Cherry pick PR #2586: Add telemetry for SourceBuffer.appendBuffer (#…

…2629) Refer to the original PR: #2586 Modifies the SourceBufferMetrics class to not be completely stubbed out in gold builds, and use it to send UMA histograms for the time spent in `SourceBuffer::PrepareAppend` and `SourceBufferAppendAlgorithm::Process`. Added basic unit tests for the `SourceBufferMetrics` class, to assert that the new code reports telemetry against the correct histograms. b/329439818 Change-Id: I7921434b02c689b645ab2a60464eee166d829135 --------- Co-authored-by: Drew Thomas <async@google.com>
youtube · Mar 19, 2024 · 0ed1dd1 · 0ed1dd1
1 parent f582ccf
commit 0ed1dd1
Show file tree

Hide file tree

Showing 7 changed files with 191 additions and 32 deletions.
diff --git a/cobalt/dom/BUILD.gn b/cobalt/dom/BUILD.gn
@@ -408,6 +408,7 @@ target(gtest_target_type, "dom_test") {
     "rule_matching_test.cc",
     "screen_test.cc",
     "serializer_test.cc",
+    "source_buffer_metrics_test.cc",
     "storage_area_test.cc",
     "text_test.cc",
     "time_ranges_test.cc",

diff --git a/cobalt/dom/source_buffer.cc b/cobalt/dom/source_buffer.cc
@@ -58,6 +58,7 @@
 #include "cobalt/dom/dom_settings.h"
 #include "cobalt/dom/media_settings.h"
 #include "cobalt/dom/media_source.h"
+#include "cobalt/dom/source_buffer_metrics.h"
 #include "cobalt/web/context.h"
 #include "cobalt/web/dom_exception.h"
 #include "cobalt/web/web_settings.h"
@@ -591,7 +592,7 @@ bool SourceBuffer::PrepareAppend(size_t new_data_size,
     return false;
   }
 
-  metrics_.StartTracking();
+  metrics_.StartTracking(SourceBufferMetricsAction::PREPARE_APPEND);
   media_source_->OpenIfInEndedState();
 
   double current_time = media_source_->GetMediaElement()->current_time(NULL);
@@ -600,11 +601,11 @@ bool SourceBuffer::PrepareAppend(size_t new_data_size,
           new_data_size + evict_extra_in_bytes_)) {
     web::DOMException::Raise(web::DOMException::kQuotaExceededErr,
                              exception_state);
-    metrics_.EndTracking(0);
+    metrics_.EndTracking(SourceBufferMetricsAction::PREPARE_APPEND, 0);
     return false;
   }
 
-  metrics_.EndTracking(0);
+  metrics_.EndTracking(SourceBufferMetricsAction::PREPARE_APPEND, 0);
   return true;
 }
 

diff --git a/cobalt/dom/source_buffer_algorithm.cc b/cobalt/dom/source_buffer_algorithm.cc
@@ -20,6 +20,7 @@
 #include "base/logging.h"
 #include "base/trace_event/trace_event.h"
 #include "cobalt/dom/media_source.h"
+#include "cobalt/dom/source_buffer_metrics.h"
 
 namespace cobalt {
 namespace dom {
@@ -67,12 +68,13 @@ void SourceBufferAppendAlgorithm::Process(bool* finished) {
   TRACE_EVENT1("cobalt::dom", "SourceBufferAppendAlgorithm::Process()",
                "append_size", append_size);
 
-  metrics_->StartTracking();
+  metrics_->StartTracking(SourceBufferMetricsAction::APPEND_BUFFER);
   succeeded_ = chunk_demuxer_->AppendData(
       id_, buffer_, append_size, append_window_start_, append_window_end_,
       &timestamp_offset_);
   update_timestamp_offset_cb_.Run(timestamp_offset_);
-  metrics_->EndTracking(succeeded_ ? append_size : 0);
+  metrics_->EndTracking(SourceBufferMetricsAction::APPEND_BUFFER,
+                        succeeded_ ? append_size : 0);
 
   if (succeeded_) {
     buffer_ += append_size;

diff --git a/cobalt/dom/source_buffer_metrics.cc b/cobalt/dom/source_buffer_metrics.cc
@@ -17,6 +17,8 @@
 #include <algorithm>
 
 #include "base/logging.h"
+#include "base/metrics/histogram_macros.h"
+#include "base/time/time.h"
 #include "cobalt/base/statistics.h"
 #include "starboard/common/string.h"
 #include "starboard/once.h"
@@ -26,7 +28,6 @@ namespace cobalt {
 namespace dom {
 
 #if !defined(COBALT_BUILD_TYPE_GOLD)
-
 namespace {
 
 int GetBandwidth(std::size_t size, SbTimeMonotonic duration) {
@@ -59,38 +60,57 @@ double GetWallToThreadTimeRatio(int64_t wall_time, int64_t thread_time) {
 }  // namespace
 SB_ONCE_INITIALIZE_FUNCTION(StatisticsWrapper, StatisticsWrapper::GetInstance);
 
-void SourceBufferMetrics::StartTracking() {
+#endif  // !defined(COBALT_BUILD_TYPE_GOLD)
+
+void SourceBufferMetrics::StartTracking(SourceBufferMetricsAction action) {
   if (!is_primary_video_) {
     return;
   }
 
   DCHECK(!is_tracking_);
+  DCHECK(current_action_ == SourceBufferMetricsAction::NO_ACTION);
+  DCHECK(action != SourceBufferMetricsAction::NO_ACTION);
+
   is_tracking_ = true;
-  wall_start_time_ = SbTimeGetMonotonicNow();
+  current_action_ = action;
+  wall_start_time_ = clock_->NowTicks();
+
+#if !defined(COBALT_BUILD_TYPE_GOLD)
   thread_start_time_ =
       SbTimeIsTimeThreadNowSupported() ? SbTimeGetMonotonicThreadNow() : -1;
+#endif  // !defined(COBALT_BUILD_TYPE_GOLD)
 }
 
-void SourceBufferMetrics::EndTracking(std::size_t size_appended) {
+void SourceBufferMetrics::EndTracking(SourceBufferMetricsAction action,
+                                      std::size_t size_appended) {
   if (!is_primary_video_) {
     return;
   }
 
   DCHECK(is_tracking_);
   is_tracking_ = false;
 
-  SbTimeMonotonic wall_duration = SbTimeGetMonotonicNow() - wall_start_time_;
+  DCHECK(action == current_action_);
+  current_action_ = SourceBufferMetricsAction::NO_ACTION;
+
+  base::TimeDelta wall_duration = clock_->NowTicks() - wall_start_time_;
+
+  RecordTelemetry(action, wall_duration);
+
+#if !defined(COBALT_BUILD_TYPE_GOLD)
   SbTimeMonotonic thread_duration =
       SbTimeIsTimeThreadNowSupported()
           ? SbTimeGetMonotonicThreadNow() - thread_start_time_
           : 0;
-  total_wall_time_ += wall_duration;
+
+  total_wall_time_ += wall_duration.InMicroseconds();
   total_thread_time_ += thread_duration;
 
   total_size_ += size_appended;
 
   if (size_appended > 0) {
-    int wall_bandwidth = GetBandwidth(size_appended, wall_duration);
+    int wall_bandwidth =
+        GetBandwidth(size_appended, wall_duration.InMicroseconds());
     int thread_bandwidth = SbTimeIsTimeThreadNowSupported()
                                ? GetBandwidth(size_appended, thread_duration)
                                : 0;
@@ -100,8 +120,35 @@ void SourceBufferMetrics::EndTracking(std::size_t size_appended) {
     max_thread_bandwidth_ = std::max(max_thread_bandwidth_, thread_bandwidth);
     min_thread_bandwidth_ = std::min(min_thread_bandwidth_, thread_bandwidth);
   }
+#endif  // !defined(COBALT_BUILD_TYPE_GOLD)
 }
 
+void SourceBufferMetrics::RecordTelemetry(
+    SourceBufferMetricsAction action, const base::TimeDelta& action_duration) {
+  switch (action) {
+    case SourceBufferMetricsAction::PREPARE_APPEND:
+      UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES(
+          "Cobalt.Media.SourceBuffer.PrepareAppend.Timing", action_duration,
+          base::TimeDelta::FromMicroseconds(1),
+          base::TimeDelta::FromMilliseconds(25), 50);
+      break;
+    case SourceBufferMetricsAction::APPEND_BUFFER:
+      UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES(
+          "Cobalt.Media.SourceBuffer.AppendBuffer.Timing", action_duration,
+          base::TimeDelta::FromMicroseconds(1),
+          base::TimeDelta::FromMilliseconds(25), 50);
+      break;
+    default:
+      UMA_HISTOGRAM_CUSTOM_MICROSECONDS_TIMES(
+          "Cobalt.Media.SourceBuffer.Other.Timing", action_duration,
+          base::TimeDelta::FromMicroseconds(1),
+          base::TimeDelta::FromMilliseconds(25), 50);
+      break;
+  }
+}
+
+#if !defined(COBALT_BUILD_TYPE_GOLD)
+
 void SourceBufferMetrics::PrintCurrentMetricsAndUpdateAccumulatedMetrics() {
   if (!is_primary_video_) {
     return;

diff --git a/cobalt/dom/source_buffer_metrics.h b/cobalt/dom/source_buffer_metrics.h
@@ -15,58 +15,66 @@
 #ifndef COBALT_DOM_SOURCE_BUFFER_METRICS_H_
 #define COBALT_DOM_SOURCE_BUFFER_METRICS_H_
 
+#include "base/time/default_tick_clock.h"
+#include "base/time/tick_clock.h"
+#include "base/time/time.h"
 #include "starboard/time.h"
 
 namespace cobalt {
 namespace dom {
 
-#if defined(COBALT_BUILD_TYPE_GOLD)
+enum class SourceBufferMetricsAction : uint8_t {
+  NO_ACTION,
+  PREPARE_APPEND,
+  APPEND_BUFFER,
+};
 
 class SourceBufferMetrics {
  public:
-  explicit SourceBufferMetrics(bool is_primary_video) {}
+  SourceBufferMetrics(
+      bool is_primary_video,
+      const base::TickClock* clock = base::DefaultTickClock::GetInstance())
+      : is_primary_video_(is_primary_video), clock_(clock) {}
   ~SourceBufferMetrics() = default;
 
-  void StartTracking() {}
-  void EndTracking(size_t size_appended) {}
+  void StartTracking(SourceBufferMetricsAction action);
+  void EndTracking(SourceBufferMetricsAction action, size_t size_appended);
+
+#if defined(COBALT_BUILD_TYPE_GOLD)
   void PrintCurrentMetricsAndUpdateAccumulatedMetrics() {}
   void PrintAccumulatedMetrics() {}
-};
-
-#else  // defined(COBALT_BUILD_TYPE_GOLD)
-
-class SourceBufferMetrics {
- public:
-  explicit SourceBufferMetrics(bool is_primary_video)
-      : is_primary_video_(is_primary_video) {}
-  ~SourceBufferMetrics() = default;
-
-  void StartTracking();
-  void EndTracking(size_t size_appended);
+#else   // defined(COBALT_BUILD_TYPE_GOLD)
   void PrintCurrentMetricsAndUpdateAccumulatedMetrics();
   void PrintAccumulatedMetrics();
+#endif  // defined(COBALT_BUILD_TYPE_GOLD)
 
  private:
   SourceBufferMetrics(const SourceBufferMetrics&) = delete;
   SourceBufferMetrics& operator=(const SourceBufferMetrics&) = delete;
 
-  SbTimeMonotonic wall_start_time_ = 0;
-  SbTimeMonotonic thread_start_time_ = 0;
+  void RecordTelemetry(SourceBufferMetricsAction action,
+                       const base::TimeDelta& action_duration);
+
+  base::TimeTicks wall_start_time_;
 
   const bool is_primary_video_;
   bool is_tracking_ = false;
+  SourceBufferMetricsAction current_action_ =
+      SourceBufferMetricsAction::NO_ACTION;
+  const base::TickClock* clock_;
 
+#if !defined(COBALT_BUILD_TYPE_GOLD)
+  SbTimeMonotonic thread_start_time_ = 0;
   size_t total_size_ = 0;
   SbTime total_thread_time_ = 0;
   SbTime total_wall_time_ = 0;
   int max_thread_bandwidth_ = 0;
   int min_thread_bandwidth_ = INT_MAX;
   int max_wall_bandwidth_ = 0;
   int min_wall_bandwidth_ = INT_MAX;
+#endif  // !defined(COBALT_BUILD_TYPE_GOLD)
 };
 
-#endif  // defined(COBALT_BUILD_TYPE_GOLD)
-
 }  // namespace dom
 }  // namespace cobalt
 

diff --git a/cobalt/dom/source_buffer_metrics_test.cc b/cobalt/dom/source_buffer_metrics_test.cc
@@ -0,0 +1,66 @@
+// Copyright 2024 The Cobalt Authors. All Rights Reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#include "cobalt/dom/source_buffer_metrics.h"
+
+#include <memory>
+#include <string>
+
+#include "base/test/metrics/histogram_tester.h"
+#include "base/test/simple_test_tick_clock.h"
+#include "base/time/time.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace cobalt {
+namespace dom {
+namespace {
+constexpr char kUmaPrefix[] = "Cobalt.Media.SourceBuffer.";
+
+class SourceBufferMetricsTest : public ::testing::Test {
+ protected:
+  SourceBufferMetricsTest()
+      : metrics_(std::make_unique<SourceBufferMetrics>(
+            /*is_primary_video=*/true, &clock_)) {}
+
+  void SetUp() override { clock_.SetNowTicks(base::TimeTicks()); }
+
+  base::HistogramTester histogram_tester_;
+  base::SimpleTestTickClock clock_;
+
+  std::unique_ptr<SourceBufferMetrics> metrics_;
+};
+
+TEST_F(SourceBufferMetricsTest, RecordsPrepareAppendTelemetry) {
+  metrics_->StartTracking(SourceBufferMetricsAction::PREPARE_APPEND);
+
+  clock_.Advance(base::TimeDelta::FromMicroseconds(100));
+  metrics_->EndTracking(SourceBufferMetricsAction::PREPARE_APPEND, 1234);
+
+  histogram_tester_.ExpectUniqueSample(
+      std::string(kUmaPrefix) + "PrepareAppend.Timing", 100, 1);
+}
+
+TEST_F(SourceBufferMetricsTest, RecordsAppendBufferTelemetry) {
+  metrics_->StartTracking(SourceBufferMetricsAction::APPEND_BUFFER);
+
+  clock_.Advance(base::TimeDelta::FromMicroseconds(100));
+  metrics_->EndTracking(SourceBufferMetricsAction::APPEND_BUFFER, 1234);
+
+  histogram_tester_.ExpectUniqueSample(
+      std::string(kUmaPrefix) + "AppendBuffer.Timing", 100, 1);
+}
+
+}  // namespace
+}  // namespace dom
+}  // namespace cobalt
diff --git a/tools/metrics/histograms/metadata/cobalt/histograms.xml b/tools/metrics/histograms/metadata/cobalt/histograms.xml
@@ -151,6 +151,40 @@ Always run the pretty print utility on this file after editing:
   </summary>
 </histogram>
 
+<histogram name="Cobalt.Media.SourceBuffer.AppendBuffer.Timing"
+    units="microseconds" expires_after="never">
+<!-- expires-never: Needed for long-term tracking of SourceBuffer latency. -->
+
+  <owner>async@google.com</owner>
+  <owner>cobalt-team@google.com</owner>
+  <summary>
+    Timing data for the main action of the `SourceBuffer.appendBuffer` call.
+  </summary>
+</histogram>
+
+<histogram name="Cobalt.Media.SourceBuffer.PrepareAppend.Timing"
+    units="microseconds" expires_after="never">
+<!-- expires-never: Needed for long-term tracking of SourceBuffer latency. -->
+
+  <owner>async@google.com</owner>
+  <owner>cobalt-team@google.com</owner>
+  <summary>
+    Timing data for preparation of `SourceBuffer.appendBuffer` calls.
+  </summary>
+</histogram>
+
+<histogram name="Cobalt.Media.SourceBuffer.Other.Timing"
+    units="microseconds" expires_after="never">
+<!-- expires-never: Needed for long-term tracking of SourceBuffer latency. -->
+
+  <owner>async@google.com</owner>
+  <owner>cobalt-team@google.com</owner>
+  <summary>
+    Catch-all for timing data for `SourceBuffer.appendBuffer` calls. This
+    histogram is not expected to receive data normally.
+  </summary>
+</histogram>
+
 <histogram name="Cobalt.MediaDevices.MicCreationSucceeded" enum="Boolean"
     expires_after="never">
 <!-- expires-never: Needed for long-term tracking of device mic support. -->