Add Seek Latency Telemetry (#2735)

Added the ability to track the latency of `WebMediaPlayer` actions to
the existing `MediaMetricsProvider` class, and instrumented `Seek` as
the first action.

Added basic unit tests for the new code.

b/329439521

Change-Id: Icbbfd0da148e48d2137da7662b91e6e2d52de590
(cherry picked from commit a712047)

cobalt/media/BUILD.gn

@@ -120,6 +120,11 @@ target(gtest_target_type, "media_test") {
   sources = [
     "base/cval_stats_test.cc",
     "base/decoder_buffer_cache_test.cc",
+<<<<<<< HEAD
+=======
+    "base/metrics_provider_test.cc",
+    "bidirectional_fit_reuse_allocator_test.cc",
+>>>>>>> a712047ec57 (Add Seek Latency Telemetry (#2735))
     "file_data_source_test.cc",
     "progressive/demuxer_extension_wrapper_test.cc",
     "progressive/mock_data_source_reader.h",

cobalt/media/base/metrics_provider.cc

@@ -16,6 +16,8 @@
 
 #include "base/logging.h"
 #include "base/metrics/histogram_functions.h"
+#include "base/metrics/histogram_macros.h"
+#include "base/time/time.h"
 
 namespace cobalt {
 namespace media {
@@ -122,5 +124,44 @@ bool MediaMetricsProvider::IsInitialized() const {
   return media_info_.has_value();
 }
 
+void MediaMetricsProvider::StartTrackingAction(WebMediaPlayerAction action) {
+  DCHECK(IsInitialized());
+  DCHECK(!IsActionCurrentlyTracked(action));
+  ScopedLock scoped_lock(mutex_);
+
+  tracked_actions_start_times_[action] = clock_->NowTicks();
+}
+
+void MediaMetricsProvider::EndTrackingAction(WebMediaPlayerAction action) {
+  DCHECK(IsInitialized());
+  DCHECK(IsActionCurrentlyTracked(action));
+  ScopedLock scoped_lock(mutex_);
+
+  auto duration = clock_->NowTicks() - tracked_actions_start_times_[action];
+  ReportActionLatencyUMA(action, duration);
+  tracked_actions_start_times_.erase(action);
+}
+
+bool MediaMetricsProvider::IsActionCurrentlyTracked(
+    WebMediaPlayerAction action) {
+  DCHECK(IsInitialized());
+  ScopedLock scoped_lock(mutex_);
+  return tracked_actions_start_times_.find(action) !=
+         tracked_actions_start_times_.end();
+}
+
+void MediaMetricsProvider::ReportActionLatencyUMA(
+    WebMediaPlayerAction action, const base::TimeDelta& action_duration) {
+  switch (action) {
+    case WebMediaPlayerAction::SEEK:
+      UMA_HISTOGRAM_TIMES("Cobalt.Media.WebMediaPlayer.Seek.Timing",
+                          action_duration);
+      break;
+    case WebMediaPlayerAction::UNKNOWN_ACTION:
+    default:
+      break;
+  }
+}
+
 }  // namespace media
 }  // namespace cobalt

cobalt/media/base/metrics_provider.h

@@ -15,14 +15,29 @@
 #ifndef COBALT_MEDIA_BASE_METRICS_PROVIDER_H_
 #define COBALT_MEDIA_BASE_METRICS_PROVIDER_H_
 
+#include <map>
 #include <string>
 
+<<<<<<< HEAD
 #include "starboard/common/mutex.h"
 #include "third_party/chromium/media/base/audio_codecs.h"
 #include "third_party/chromium/media/base/container_names.h"
 #include "third_party/chromium/media/base/pipeline_status.h"
 #include "third_party/chromium/media/base/timestamp_constants.h"
 #include "third_party/chromium/media/base/video_codecs.h"
+=======
+#include "base/containers/small_map.h"
+#include "base/time/default_tick_clock.h"
+#include "base/time/tick_clock.h"
+#include "base/time/time.h"
+#include "media/base/audio_codecs.h"
+#include "media/base/container_names.h"
+#include "media/base/pipeline_status.h"
+#include "media/base/timestamp_constants.h"
+#include "media/base/video_codecs.h"
+#include "starboard/common/mutex.h"
+#include "starboard/types.h"
+>>>>>>> a712047ec57 (Add Seek Latency Telemetry (#2735))
 
 namespace cobalt {
 namespace media {
@@ -32,9 +47,16 @@ using VideoCodec = ::media::VideoCodec;
 using PipelineStatus = ::media::PipelineStatus;
 using VideoDecoderType = ::media::VideoDecoderType;
 
+enum class WebMediaPlayerAction : uint8_t {
+  UNKNOWN_ACTION,
+  SEEK,
+};
+
 class MediaMetricsProvider {
  public:
-  MediaMetricsProvider() = default;
+  MediaMetricsProvider(
+      const base::TickClock* clock = base::DefaultTickClock::GetInstance())
+      : clock_(clock) {}
   ~MediaMetricsProvider();
 
  private:
@@ -71,11 +93,24 @@ class MediaMetricsProvider {
 
   void ReportPipelineUMA();
 
+  // Used to record the latency of an action in the WebMediaPlayer.
+  void StartTrackingAction(WebMediaPlayerAction action);
+  void EndTrackingAction(WebMediaPlayerAction action);
+  bool IsActionCurrentlyTracked(WebMediaPlayerAction action);
+
  private:
   std::string GetUMANameForAVStream(const PipelineInfo& player_info) const;
   bool IsInitialized() const;
 
+  void ReportActionLatencyUMA(WebMediaPlayerAction action,
+                              const base::TimeDelta& action_duration);
+
  private:
+  // Media player action latency data.
+  const base::TickClock* clock_;
+  base::small_map<std::map<WebMediaPlayerAction, base::TimeTicks>, 2>
+      tracked_actions_start_times_;
+
   // UMA pipeline packaged data
   PipelineInfo uma_info_;
 

cobalt/media/base/metrics_provider_test.cc

@@ -0,0 +1,70 @@
+// 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/media/base/metrics_provider.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 media {
+namespace {
+constexpr char kUmaPrefix[] = "Cobalt.Media.";
+
+class MediaMetricsProviderTest : public ::testing::Test {
+ protected:
+  MediaMetricsProviderTest() : metrics_(&clock_) {}
+
+  void SetUp() override { clock_.SetNowTicks(base::TimeTicks()); }
+
+  base::HistogramTester histogram_tester_;
+  base::SimpleTestTickClock clock_;
+
+  MediaMetricsProvider metrics_;
+};
+
+TEST_F(MediaMetricsProviderTest, ReportsSeekLatency) {
+  metrics_.Initialize(true);
+  metrics_.StartTrackingAction(WebMediaPlayerAction::SEEK);
+
+  clock_.Advance(base::TimeDelta::FromMilliseconds(100));
+  metrics_.EndTrackingAction(WebMediaPlayerAction::SEEK);
+
+  histogram_tester_.ExpectUniqueSample(
+      std::string(kUmaPrefix) + "WebMediaPlayer.Seek.Timing", 100, 1);
+}
+
+TEST_F(MediaMetricsProviderTest, SupportsTrackingMultipleActions) {
+  metrics_.Initialize(true);
+  metrics_.StartTrackingAction(WebMediaPlayerAction::SEEK);
+  metrics_.StartTrackingAction(WebMediaPlayerAction::UNKNOWN_ACTION);
+
+  clock_.Advance(base::TimeDelta::FromMilliseconds(100));
+  metrics_.EndTrackingAction(WebMediaPlayerAction::UNKNOWN_ACTION);
+
+  clock_.Advance(base::TimeDelta::FromMilliseconds(1000));
+  metrics_.EndTrackingAction(WebMediaPlayerAction::SEEK);
+
+  histogram_tester_.ExpectUniqueSample(
+      std::string(kUmaPrefix) + "WebMediaPlayer.Seek.Timing", 1100, 1);
+}
+
+}  // namespace
+}  // namespace media
+}  // namespace cobalt

cobalt/media/player/web_media_player_impl.cc

@@ -22,6 +22,7 @@
 #include "base/trace_event/trace_event.h"
 #include "cobalt/base/instance_counter.h"
 #include "cobalt/media/base/drm_system.h"
+#include "cobalt/media/base/metrics_provider.h"
 #include "cobalt/media/base/sbplayer_pipeline.h"
 #include "cobalt/media/player/web_media_player_proxy.h"
 #include "cobalt/media/progressive/data_source_reader.h"
@@ -362,6 +363,7 @@ void WebMediaPlayerImpl::Seek(float seconds) {
     return;
   }
 
+  media_metrics_provider_.StartTrackingAction(WebMediaPlayerAction::SEEK);
   media_log_->AddEvent<::media::MediaLogEvent::kSeek>(seconds);
 
   base::TimeDelta seek_time = ConvertSecondsToTimestamp(seconds);
@@ -637,6 +639,14 @@ void WebMediaPlayerImpl::OnPipelineSeek(::media::PipelineStatus status,
     const bool kEosPlayed = false;
     GetClient()->TimeChanged(kEosPlayed);
   }
+
+  // WebMediaPlayerImpl::OnPipelineSeek() is called frequently, more than just
+  // when WebMediaPlayerImpl::Seek() is called. This helps to filter out when
+  // the pipeline seeks without being initiated by WebMediaPlayerImpl.
+  if (media_metrics_provider_.IsActionCurrentlyTracked(
+          WebMediaPlayerAction::SEEK)) {
+    media_metrics_provider_.EndTrackingAction(WebMediaPlayerAction::SEEK);
+  }
 }
 
 void WebMediaPlayerImpl::OnPipelineEnded(::media::PipelineStatus status) {

tools/metrics/histograms/metadata/cobalt/histograms.xml

@@ -185,6 +185,17 @@ Always run the pretty print utility on this file after editing:
   </summary>
 </histogram>
 
+<histogram name="Cobalt.Media.WebMediaPlayer.Seek.Timing"
+    units="milliseconds" expires_after="never">
+<!-- expires-never: Needed for long-term tracking of Seek latency. -->
+
+  <owner>[email protected]</owner>
+  <owner>[email protected]</owner>
+  <summary>
+    Timing data for the seek latency of WebMediaPlayer.
+  </summary>
+</histogram>
+
 <histogram name="Cobalt.MediaDevices.MicCreationSucceeded" enum="Boolean"
     expires_after="never">
 <!-- expires-never: Needed for long-term tracking of device mic support. -->