Add a better underflow metric: Media.MeanTimeBetweenRebuffers.

This is equivalent to YouTube's MTBR metric in that it corresponds to the
total watch time for a session divided by the number of underflow events
that occur during that session.

The metric is recorded by having the WatchTimeReporter count the number
of underflow events that occur and pass them along to MediaInternals
during each watch time reporting interval. At finalization MTBR is
calculated for AudioVideo.MSE, AudioVideo.SRC, AudioVideo.EME,
Audio.MSE, Audio.SRC, and Audio.EME.

This is nicer than the existing Media.UnderflowDuration metric since it
is not as susceptible to scaling issues due to more playbacks and has no
automatic zero weighting.

BUG=648710, 727862
TEST=new unittests

Change-Id: I144333e6e25cc599bfc89ee2be9a25bac476d156
Reviewed-on: https://chromium-review.googlesource.com/516528
Reviewed-by: Xiaohan Wang <xhwang@chromium.org>
Reviewed-by: Ilya Sherman <isherman@chromium.org>
Commit-Queue: Dale Curtis <dalecurtis@chromium.org>
Cr-Commit-Position: refs/heads/master@{#476124}

content/browser/media/media_internals.cc

@@ -333,6 +333,7 @@ class MediaInternals::MediaInternalsUMAHandler {
     std::string video_decoder;
     GURL origin_url;
     WatchTimeInfo watch_time_info;
+    int underflow_count = 0;
   };
 
   // Helper function to report PipelineStatus associated with a player to UMA.
@@ -346,17 +347,29 @@ class MediaInternals::MediaInternalsUMAHandler {
     return !key.ends_with("EmbeddedExperience");
   }
 
-  void RecordWatchTime(base::StringPiece key, base::TimeDelta value) {
+  void RecordWatchTime(base::StringPiece key,
+                       base::TimeDelta value,
+                       bool is_mtbr = false) {
     base::Histogram::FactoryTimeGet(
-        key.as_string(), base::TimeDelta::FromSeconds(7),
+        key.as_string(),
+        // There are a maximum of 5 underflow events possible in a given 7s
+        // watch time period, so the minimum value is 1.4s.
+        is_mtbr ? base::TimeDelta::FromSecondsD(1.4)
+                : base::TimeDelta::FromSeconds(7),
         base::TimeDelta::FromHours(10), 50,
         base::HistogramBase::kUmaTargetedHistogramFlag)
         ->AddTime(value);
   }
 
+  void RecordMeanTimeBetweenRebuffers(base::StringPiece key,
+                                      base::TimeDelta value) {
+    RecordWatchTime(key, value, true);
+  }
+
   enum class FinalizeType { EVERYTHING, POWER_ONLY };
   void FinalizeWatchTime(bool has_video,
                          const GURL& url,
+                         int* underflow_count,
                          WatchTimeInfo* watch_time_info,
                          FinalizeType finalize_type) {
     // |url| may come from an untrusted source, so ensure it's valid before
@@ -369,6 +382,20 @@ class MediaInternals::MediaInternalsUMAHandler {
     const bool has_ukm = !!ukm::UkmRecorder::Get();
 
     if (finalize_type == FinalizeType::EVERYTHING) {
+      if (*underflow_count) {
+        // Check for watch times entries that have corresponding MTBR entries
+        // and report the MTBR value using watch_time / |underflow_count|
+        for (auto& kv : mtbr_keys_) {
+          auto it = watch_time_info->find(kv.first);
+          if (it == watch_time_info->end())
+            continue;
+          RecordMeanTimeBetweenRebuffers(kv.second,
+                                         it->second / *underflow_count);
+        }
+
+        *underflow_count = 0;
+      }
+
       std::unique_ptr<ukm::UkmEntryBuilder> builder;
       for (auto& kv : *watch_time_info) {
         RecordWatchTime(kv.first, kv.second);
@@ -420,8 +447,15 @@ class MediaInternals::MediaInternalsUMAHandler {
   // Stores player information per renderer.
   RendererPlayerMap renderer_info_;
 
+  // Set of all possible watch time keys.
   const base::flat_set<base::StringPiece> watch_time_keys_;
+
+  // Set of only the power related watch time keys.
   const base::flat_set<base::StringPiece> watch_time_power_keys_;
+
+  // Mapping of WatchTime metric keys to MeanTimeBetweenRebuffers (MTBR) keys.
+  const base::flat_map<base::StringPiece, base::StringPiece> mtbr_keys_;
+
   content::MediaInternals* const media_internals_;
 
   DISALLOW_COPY_AND_ASSIGN(MediaInternalsUMAHandler);
@@ -431,6 +465,19 @@ MediaInternals::MediaInternalsUMAHandler::MediaInternalsUMAHandler(
     content::MediaInternals* media_internals)
     : watch_time_keys_(media::MediaLog::GetWatchTimeKeys()),
       watch_time_power_keys_(media::MediaLog::GetWatchTimePowerKeys()),
+      mtbr_keys_({{media::MediaLog::kWatchTimeAudioSrc,
+                   media::MediaLog::kMeanTimeBetweenRebuffersAudioSrc},
+                  {media::MediaLog::kWatchTimeAudioMse,
+                   media::MediaLog::kMeanTimeBetweenRebuffersAudioMse},
+                  {media::MediaLog::kWatchTimeAudioEme,
+                   media::MediaLog::kMeanTimeBetweenRebuffersAudioEme},
+                  {media::MediaLog::kWatchTimeAudioVideoSrc,
+                   media::MediaLog::kMeanTimeBetweenRebuffersAudioVideoSrc},
+                  {media::MediaLog::kWatchTimeAudioVideoMse,
+                   media::MediaLog::kMeanTimeBetweenRebuffersAudioVideoMse},
+                  {media::MediaLog::kWatchTimeAudioVideoEme,
+                   media::MediaLog::kMeanTimeBetweenRebuffersAudioVideoEme}},
+                 base::KEEP_FIRST_OF_DUPES),
       media_internals_(media_internals) {}
 
 void MediaInternals::MediaInternalsUMAHandler::SavePlayerState(
@@ -527,12 +574,18 @@ void MediaInternals::MediaInternalsUMAHandler::SavePlayerState(
             base::TimeDelta::FromSecondsD(it.value().GetDouble());
       }
 
+      if (event.params.HasKey(media::MediaLog::kUnderflowCount)) {
+        event.params.GetInteger(media::MediaLog::kUnderflowCount,
+                                &player_info.underflow_count);
+      }
+
       if (event.params.HasKey(media::MediaLog::kWatchTimeFinalize)) {
         bool should_finalize;
         DCHECK(event.params.GetBoolean(media::MediaLog::kWatchTimeFinalize,
                                        &should_finalize) &&
                should_finalize);
         FinalizeWatchTime(player_info.has_video, player_info.origin_url,
+                          &player_info.underflow_count,
                           &player_info.watch_time_info,
                           FinalizeType::EVERYTHING);
       } else if (event.params.HasKey(
@@ -542,6 +595,7 @@ void MediaInternals::MediaInternalsUMAHandler::SavePlayerState(
                                        &should_finalize) &&
                should_finalize);
         FinalizeWatchTime(player_info.has_video, player_info.origin_url,
+                          &player_info.underflow_count,
                           &player_info.watch_time_info,
                           FinalizeType::POWER_ONLY);
       }
@@ -556,6 +610,7 @@ void MediaInternals::MediaInternalsUMAHandler::SavePlayerState(
 
       ReportUMAForPipelineStatus(it->second);
       FinalizeWatchTime(it->second.has_video, it->second.origin_url,
+                        &it->second.underflow_count,
                         &(it->second.watch_time_info),
                         FinalizeType::EVERYTHING);
       player_info_map.erase(it);
@@ -662,6 +717,7 @@ void MediaInternals::MediaInternalsUMAHandler::OnProcessTerminated(
   while (it != players_it->second.end()) {
     ReportUMAForPipelineStatus(it->second);
     FinalizeWatchTime(it->second.has_video, it->second.origin_url,
+                      &it->second.underflow_count,
                       &(it->second.watch_time_info), FinalizeType::EVERYTHING);
     players_it->second.erase(it++);
   }

content/browser/media/media_internals_unittest.cc

@@ -381,6 +381,14 @@ class MediaInternalsWatchTimeTest : public testing::Test,
     }
   }
 
+  void ExpectMtbrTime(const std::vector<base::StringPiece>& keys,
+                      base::TimeDelta value) {
+    for (auto key : keys) {
+      histogram_tester_->ExpectUniqueSample(key.as_string(),
+                                            value.InMilliseconds(), 1);
+    }
+  }
+
   void ExpectUkmWatchTime(size_t entry, size_t size, base::TimeDelta value) {
     ASSERT_LT(entry, test_recorder_->entries_count());
 
@@ -425,6 +433,8 @@ TEST_F(MediaInternalsWatchTimeTest, BasicAudio) {
   CycleWatchTimeReporter();
   ExpectWatchTime(std::vector<base::StringPiece>(), base::TimeDelta());
 
+  wtr_->OnUnderflow();
+  wtr_->OnUnderflow();
   CycleWatchTimeReporter();
   wtr_.reset();
 
@@ -433,6 +443,9 @@ TEST_F(MediaInternalsWatchTimeTest, BasicAudio) {
        media::MediaLog::kWatchTimeAudioEme, media::MediaLog::kWatchTimeAudioAc,
        media::MediaLog::kWatchTimeAudioEmbeddedExperience},
       kWatchTimeLate);
+  ExpectMtbrTime({media::MediaLog::kMeanTimeBetweenRebuffersAudioMse,
+                  media::MediaLog::kMeanTimeBetweenRebuffersAudioEme},
+                 kWatchTimeLate / 2);
 
   ASSERT_EQ(1U, test_recorder_->sources_count());
   ExpectUkmWatchTime(0, 4, kWatchTimeLate);
@@ -454,6 +467,8 @@ TEST_F(MediaInternalsWatchTimeTest, BasicVideo) {
   CycleWatchTimeReporter();
   ExpectWatchTime(std::vector<base::StringPiece>(), base::TimeDelta());
 
+  wtr_->OnUnderflow();
+  wtr_->OnUnderflow();
   CycleWatchTimeReporter();
   wtr_.reset();
 
@@ -463,6 +478,9 @@ TEST_F(MediaInternalsWatchTimeTest, BasicVideo) {
                    media::MediaLog::kWatchTimeAudioVideoAc,
                    media::MediaLog::kWatchTimeAudioVideoEmbeddedExperience},
                   kWatchTimeLate);
+  ExpectMtbrTime({media::MediaLog::kMeanTimeBetweenRebuffersAudioVideoSrc,
+                  media::MediaLog::kMeanTimeBetweenRebuffersAudioVideoEme},
+                 kWatchTimeLate / 2);
 
   ASSERT_EQ(1U, test_recorder_->sources_count());
   ExpectUkmWatchTime(0, 4, kWatchTimeLate);

media/base/media_log.cc

@@ -61,6 +61,21 @@ const char MediaLog::kWatchTimeAudioVideoBackgroundEmbeddedExperience[] =
 const char MediaLog::kWatchTimeFinalize[] = "FinalizeWatchTime";
 const char MediaLog::kWatchTimeFinalizePower[] = "FinalizePowerWatchTime";
 
+const char MediaLog::kUnderflowCount[] = "UnderflowCount";
+
+const char MediaLog::kMeanTimeBetweenRebuffersAudioSrc[] =
+    "Media.MeanTimeBetweenRebuffers.Audio.SRC";
+const char MediaLog::kMeanTimeBetweenRebuffersAudioMse[] =
+    "Media.MeanTimeBetweenRebuffers.Audio.MSE";
+const char MediaLog::kMeanTimeBetweenRebuffersAudioEme[] =
+    "Media.MeanTimeBetweenRebuffers.Audio.EME";
+const char MediaLog::kMeanTimeBetweenRebuffersAudioVideoSrc[] =
+    "Media.MeanTimeBetweenRebuffers.AudioVideo.SRC";
+const char MediaLog::kMeanTimeBetweenRebuffersAudioVideoMse[] =
+    "Media.MeanTimeBetweenRebuffers.AudioVideo.MSE";
+const char MediaLog::kMeanTimeBetweenRebuffersAudioVideoEme[] =
+    "Media.MeanTimeBetweenRebuffers.AudioVideo.EME";
+
 base::flat_set<base::StringPiece> MediaLog::GetWatchTimeKeys() {
   return base::flat_set<base::StringPiece>(
       {kWatchTimeAudioAll,

media/base/media_log.h

@@ -136,6 +136,17 @@ class MEDIA_EXPORT MediaLog {
   static const char kWatchTimeFinalize[];
   static const char kWatchTimeFinalizePower[];
 
+  // Count of the number of underflow events during a media session.
+  static const char kUnderflowCount[];
+
+  // UMA keys for MTBR samples.
+  static const char kMeanTimeBetweenRebuffersAudioSrc[];
+  static const char kMeanTimeBetweenRebuffersAudioMse[];
+  static const char kMeanTimeBetweenRebuffersAudioEme[];
+  static const char kMeanTimeBetweenRebuffersAudioVideoSrc[];
+  static const char kMeanTimeBetweenRebuffersAudioVideoMse[];
+  static const char kMeanTimeBetweenRebuffersAudioVideoEme[];
+
   static base::flat_set<base::StringPiece> GetWatchTimeKeys();
   static base::flat_set<base::StringPiece> GetWatchTimePowerKeys();
 

media/blink/watch_time_reporter.cc

@@ -167,6 +167,16 @@ bool WatchTimeReporter::IsSizeLargeEnoughToReportWatchTime() const {
          initial_video_size_.width() >= kMinimumVideoSize.width();
 }
 
+void WatchTimeReporter::OnUnderflow() {
+  if (!reporting_timer_.IsRunning())
+    return;
+
+  // In the event of a pending finalize, we don't want to count underflow events
+  // that occurred after the finalize time. Yet if the finalize is canceled we
+  // want to ensure they are all recorded.
+  pending_underflow_events_.push_back(get_media_time_cb_.Run());
+}
+
 void WatchTimeReporter::OnPowerStateChange(bool on_battery_power) {
   if (!reporting_timer_.IsRunning())
     return;
@@ -216,6 +226,7 @@ void WatchTimeReporter::MaybeStartReportingTimer(
   if (reporting_timer_.IsRunning())
     return;
 
+  underflow_count_ = 0;
   last_media_timestamp_ = last_media_power_timestamp_ =
       end_timestamp_for_power_ = kNoTimestamp;
   is_on_battery_power_ = IsOnBatteryPower();
@@ -315,6 +326,23 @@ void WatchTimeReporter::UpdateWatchTime() {
   }
 #undef RECORD_WATCH_TIME
 
+  // Pass along any underflow events which have occurred since the last report.
+  if (!pending_underflow_events_.empty()) {
+    if (!is_finalizing) {
+      // The maximum value here per period is ~5 events, so int cast is okay.
+      underflow_count_ += static_cast<int>(pending_underflow_events_.size());
+    } else {
+      // Only count underflow events prior to finalize.
+      for (auto& ts : pending_underflow_events_) {
+        if (ts <= end_timestamp_)
+          underflow_count_++;
+      }
+    }
+
+    log_event->params.SetInteger(MediaLog::kUnderflowCount, underflow_count_);
+    pending_underflow_events_.clear();
+  }
+
   // Always send finalize, even if we don't currently have any data, it's
   // harmless to send since nothing will be logged if we've already finalized.
   if (is_finalizing)
@@ -337,6 +365,7 @@ void WatchTimeReporter::UpdateWatchTime() {
   // Stop the timer if this is supposed to be our last tick.
   if (is_finalizing) {
     end_timestamp_ = kNoTimestamp;
+    underflow_count_ = 0;
     reporting_timer_.Stop();
   }
 }

media/blink/watch_time_reporter.h

@@ -5,6 +5,8 @@
 #ifndef MEDIA_BLINK_WATCH_TIME_REPORTER_H_
 #define MEDIA_BLINK_WATCH_TIME_REPORTER_H_
 
+#include <vector>
+
 #include "base/callback.h"
 #include "base/power_monitor/power_observer.h"
 #include "base/time/time.h"
@@ -107,6 +109,11 @@ class MEDIA_BLINK_EXPORT WatchTimeReporter : base::PowerObserver {
   // recorded for playback.
   bool IsSizeLargeEnoughToReportWatchTime() const;
 
+  // Indicates a rebuffering event occurred during playback. When watch time is
+  // finalized the total watch time for a given category will be divided by the
+  // number of rebuffering events. Reset to zero after a finalize event.
+  void OnUnderflow();
+
   // Setup the reporting interval to be immediate to avoid spinning real time
   // within the unit test.
   void set_reporting_interval_for_testing() {
@@ -171,6 +178,8 @@ class MEDIA_BLINK_EXPORT WatchTimeReporter : base::PowerObserver {
   bool is_playing_ = false;
   bool is_visible_ = true;
   double volume_ = 1.0;
+  int underflow_count_ = 0;
+  std::vector<base::TimeDelta> pending_underflow_events_;
 
   // The last media timestamp seen by UpdateWatchTime().
   base::TimeDelta last_media_timestamp_ = kNoTimestamp;

media/blink/watch_time_reporter_unittest.cc

@@ -66,6 +66,12 @@ class WatchTimeReporterTest : public testing::TestWithParam<bool> {
           continue;
         }
 
+        int underflow_count;
+        if (it.value().GetAsInteger(&underflow_count)) {
+          OnUnderflowUpdate(underflow_count);
+          continue;
+        }
+
         double in_seconds;
         ASSERT_TRUE(it.value().GetAsDouble(&in_seconds));
         OnWatchTimeUpdate(it.key(), base::TimeDelta::FromSecondsD(in_seconds));
@@ -75,6 +81,7 @@ class WatchTimeReporterTest : public testing::TestWithParam<bool> {
     MOCK_METHOD0(OnWatchTimeFinalized, void(void));
     MOCK_METHOD0(OnPowerWatchTimeFinalized, void(void));
     MOCK_METHOD2(OnWatchTimeUpdate, void(const std::string&, base::TimeDelta));
+    MOCK_METHOD1(OnUnderflowUpdate, void(int));
 
    protected:
     ~WatchTimeLogMonitor() override {}
@@ -340,16 +347,55 @@ TEST_P(WatchTimeReporterTest, WatchTimeReporterBasic) {
   // any chance to pump.
   CycleReportingTimer();
 
+  wtr_->OnUnderflow();
+  wtr_->OnUnderflow();
   EXPECT_WATCH_TIME(Ac, kWatchTimeLate);
   EXPECT_WATCH_TIME(All, kWatchTimeLate);
   EXPECT_WATCH_TIME(Eme, kWatchTimeLate);
   EXPECT_WATCH_TIME(Mse, kWatchTimeLate);
+  EXPECT_CALL(media_log_, OnUnderflowUpdate(2));
   CycleReportingTimer();
 
   EXPECT_WATCH_TIME_FINALIZED();
   wtr_.reset();
 }
 
+TEST_P(WatchTimeReporterTest, WatchTimeReporterUnderflow) {
+  constexpr base::TimeDelta kWatchTimeEarly = base::TimeDelta::FromSeconds(10);
+  constexpr base::TimeDelta kWatchTimeLate = base::TimeDelta::FromSeconds(15);
+  EXPECT_CALL(*this, GetCurrentMediaTime())
+      .WillOnce(testing::Return(base::TimeDelta()))
+      .WillOnce(testing::Return(base::TimeDelta::FromSeconds(5)))
+      .WillOnce(testing::Return(kWatchTimeEarly))
+      .WillOnce(testing::Return(kWatchTimeEarly))
+      .WillRepeatedly(testing::Return(kWatchTimeLate));
+  Initialize(true, true, true, kSizeJustRight);
+  wtr_->OnPlaying();
+  EXPECT_TRUE(IsMonitoring());
+
+  // No log should have been generated yet since the message loop has not had
+  // any chance to pump.
+  CycleReportingTimer();
+
+  wtr_->OnUnderflow();
+  wtr_->OnVolumeChange(0);
+
+  // This underflow call should be ignored since it happens after the finalize.
+  // Note: We use a muted call above to trigger finalize instead of say a pause
+  // since media time will be the same in the event of a pause and no underflow
+  // should trigger after a pause in any case.
+  wtr_->OnUnderflow();
+
+  EXPECT_WATCH_TIME(Ac, kWatchTimeEarly);
+  EXPECT_WATCH_TIME(All, kWatchTimeEarly);
+  EXPECT_WATCH_TIME(Eme, kWatchTimeEarly);
+  EXPECT_WATCH_TIME(Mse, kWatchTimeEarly);
+  EXPECT_CALL(media_log_, OnUnderflowUpdate(1));
+  EXPECT_WATCH_TIME_FINALIZED();
+  CycleReportingTimer();
+  wtr_.reset();
+}
+
 TEST_P(WatchTimeReporterTest, WatchTimeReporterShownHidden) {
   constexpr base::TimeDelta kWatchTimeEarly = base::TimeDelta::FromSeconds(8);
   constexpr base::TimeDelta kWatchTimeLate = base::TimeDelta::FromSeconds(25);