Reland: "Add underflow duration to our media UKM reporting."

This associates a completed underflow count and total underflow duration
with each segment of watch time reported to UKM.

Generally the completion will always fall within a given segment of
watch time, however it is possible that a completion can happen after a
resolution change or other secondary property update and thus end up in
a subsequent segment.

We impose impose a maximum value of 1 minute for rebuffer durations to
avoid noise from rebuffers which may cross a suspend/resume boundary.

BUG=994021
TEST=new unittests
TBR=meacer,sandersd,holte

Change-Id: I7359d329259ce2cc2c6643c61741cb7ca8473b0f
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1879847Reviewed-by: Dale Curtis <dalecurtis@chromium.org>
Reviewed-by: Dan Sanders <sandersd@chromium.org>
Reviewed-by: Mustafa Emre Acer <meacer@chromium.org>
Commit-Queue: Dale Curtis <dalecurtis@chromium.org>
Cr-Commit-Position: refs/heads/master@{#709191}

media/blink/watch_time_component_unittest.cc

@@ -22,6 +22,7 @@ class WatchTimeInterceptor : public mojom::WatchTimeRecorder {
   MOCK_METHOD1(FinalizeWatchTime, void(const std::vector<WatchTimeKey>&));
   MOCK_METHOD1(OnError, void(PipelineStatus));
   MOCK_METHOD1(UpdateUnderflowCount, void(int32_t count));
+  MOCK_METHOD2(UpdateUnderflowDuration, void(int32_t, base::TimeDelta));
   MOCK_METHOD1(
       UpdateSecondaryProperties,
       void(mojom::SecondaryPlaybackPropertiesPtr secondary_properties));

media/blink/watch_time_reporter.cc

@@ -4,8 +4,12 @@
 
 #include "media/blink/watch_time_reporter.h"
 
+#include <numeric>
+
 #include "base/bind.h"
 #include "base/power_monitor/power_monitor.h"
+#include "base/time/time.h"
+#include "media/base/timestamp_constants.h"
 #include "media/base/watch_time_keys.h"
 
 namespace media {
@@ -236,10 +240,35 @@ void WatchTimeReporter::OnUnderflow() {
   if (!reporting_timer_.IsRunning())
     return;
 
+  if (!pending_underflow_events_.empty())
+    DCHECK_NE(pending_underflow_events_.back().duration, kNoTimestamp);
+
   // 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());
+  pending_underflow_events_.push_back(
+      {false, get_media_time_cb_.Run(), kNoTimestamp});
+}
+
+void WatchTimeReporter::OnUnderflowComplete(base::TimeDelta elapsed) {
+  if (background_reporter_)
+    background_reporter_->OnUnderflowComplete(elapsed);
+  if (muted_reporter_)
+    muted_reporter_->OnUnderflowComplete(elapsed);
+
+  if (!reporting_timer_.IsRunning())
+    return;
+
+  // Drop this underflow completion if we don't have a corresponding underflow
+  // start event; this can happen if a finalize occurs between the underflow and
+  // the completion.
+  if (pending_underflow_events_.empty())
+    return;
+
+  // There should only ever be one outstanding underflow, so stick the duration
+  // in the last underflow event.
+  DCHECK_EQ(pending_underflow_events_.back().duration, kNoTimestamp);
+  pending_underflow_events_.back().duration = elapsed;
 }
 
 void WatchTimeReporter::OnNativeControlsEnabled() {
@@ -375,9 +404,7 @@ void WatchTimeReporter::MaybeStartReportingTimer(
   if (!should_start)
     return;
 
-  underflow_count_ = 0;
-  pending_underflow_events_.clear();
-
+  ResetUnderflowState();
   base_component_->OnReportingStarted(start_timestamp);
   power_component_->OnReportingStarted(start_timestamp);
 
@@ -423,19 +450,46 @@ void WatchTimeReporter::RecordWatchTime() {
 
   // Pass along any underflow events which have occurred since the last report.
   if (!pending_underflow_events_.empty()) {
-    if (!base_component_->NeedsFinalize()) {
-      // 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 <= base_component_->end_timestamp())
-          underflow_count_++;
+    const int last_underflow_count = total_underflow_count_;
+    const int last_completed_underflow_count = total_completed_underflow_count_;
+
+    for (auto& ufe : pending_underflow_events_) {
+      // Since the underflow occurred after finalize, ignore the event and mark
+      // it for deletion.
+      if (ufe.timestamp > current_timestamp) {
+        ufe.reported = true;
+        ufe.duration = base::TimeDelta();
+        continue;
+      }
+
+      if (!ufe.reported) {
+        ufe.reported = true;
+        ++total_underflow_count_;
+      }
+
+      // Drop any rebuffer completions that took more than a minute. For our
+      // purposes these are considered as timeouts. We want a maximum since
+      // rebuffer duration is in real time and not media time, which means if
+      // the rebuffer spans a suspend/resume the time can be arbitrarily long.
+      constexpr base::TimeDelta kMaximumRebufferDuration =
+          base::TimeDelta::FromMinutes(1);
+      if (ufe.duration != kNoTimestamp &&
+          ufe.duration <= kMaximumRebufferDuration) {
+        ++total_completed_underflow_count_;
+        total_underflow_duration_ += ufe.duration;
       }
     }
 
-    recorder_->UpdateUnderflowCount(underflow_count_);
-    pending_underflow_events_.clear();
+    base::EraseIf(pending_underflow_events_, [](const UnderflowEvent& ufe) {
+      return ufe.reported && ufe.duration != kNoTimestamp;
+    });
+
+    if (last_underflow_count != total_underflow_count_)
+      recorder_->UpdateUnderflowCount(total_underflow_count_);
+    if (last_completed_underflow_count != total_completed_underflow_count_) {
+      recorder_->UpdateUnderflowDuration(total_completed_underflow_count_,
+                                         total_underflow_duration_);
+    }
   }
 
   // Record watch time for all components.
@@ -473,10 +527,16 @@ void WatchTimeReporter::UpdateWatchTime() {
   recorder_->FinalizeWatchTime({});
 
   // Stop the timer if this is supposed to be our last tick.
-  underflow_count_ = 0;
+  ResetUnderflowState();
   reporting_timer_.Stop();
 }
 
+void WatchTimeReporter::ResetUnderflowState() {
+  total_underflow_count_ = total_completed_underflow_count_ = 0;
+  total_underflow_duration_ = base::TimeDelta();
+  pending_underflow_events_.clear();
+}
+
 #define NORMAL_KEY(key)                                                     \
   ((properties_->has_video && properties_->has_audio)                       \
        ? (is_background_ ? WatchTimeKey::kAudioVideoBackground##key         \

media/blink/watch_time_reporter.h

@@ -121,6 +121,7 @@ class MEDIA_BLINK_EXPORT WatchTimeReporter : base::PowerObserver {
   // 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();
+  void OnUnderflowComplete(base::TimeDelta elapsed);
 
   // These methods are used to ensure that the watch time is reported relative
   // to whether the media is using native controls.
@@ -183,6 +184,8 @@ class MEDIA_BLINK_EXPORT WatchTimeReporter : base::PowerObserver {
   void RecordWatchTime();
   void UpdateWatchTime();
 
+  void ResetUnderflowState();
+
   // Helper methods for creating the components that make up the watch time
   // report. All components except the base component require a creation method
   // and a conversion method to get the correct WatchTimeKey.
@@ -220,8 +223,15 @@ class MEDIA_BLINK_EXPORT WatchTimeReporter : base::PowerObserver {
   // transitioning above/below kMinimumVideoSize.
   gfx::Size natural_size_;
 
-  int underflow_count_ = 0;
-  std::vector<base::TimeDelta> pending_underflow_events_;
+  int total_underflow_count_ = 0;
+  int total_completed_underflow_count_ = 0;
+  base::TimeDelta total_underflow_duration_;
+  struct UnderflowEvent {
+    bool reported = false;
+    base::TimeDelta timestamp = kNoTimestamp;
+    base::TimeDelta duration = kNoTimestamp;
+  };
+  std::vector<UnderflowEvent> pending_underflow_events_;
 
   // The various components making up WatchTime. If the |base_component_| is
   // finalized, all reporting will be stopped and finalized using its ending

media/blink/webmediaplayer_impl.cc

@@ -2102,7 +2102,9 @@ void WebMediaPlayerImpl::OnBufferingStateChangeInternal(
 
     // Report the amount of time it took to leave the underflow state.
     if (underflow_timer_) {
-      RecordUnderflowDuration(underflow_timer_->Elapsed());
+      auto elapsed = underflow_timer_->Elapsed();
+      RecordUnderflowDuration(elapsed);
+      watch_time_reporter_->OnUnderflowComplete(elapsed);
       underflow_timer_.reset();
     }
   } else {

media/mojo/mojom/watch_time_recorder.mojom

@@ -86,5 +86,7 @@ interface WatchTimeRecorder {
   // Indicates that an underflow event has occurred while collecting watch time.
   // Used to report mean values for rebuffering metrics. As with watch time,
   // this is an absolute count and not relative since the last call.
-  UpdateUnderflowCount(int32 count);
+  UpdateUnderflowCount(int32 total_count);
+  UpdateUnderflowDuration(int32 total_completed_count,
+                          mojo_base.mojom.TimeDelta total_duration);
 };

media/mojo/services/watch_time_recorder.cc

@@ -238,9 +238,15 @@ void WatchTimeRecorder::FinalizeWatchTime(
   }
 
   // Ensure values are cleared in case the reporter is reused.
-  if (!ukm_records_.empty())
-    ukm_records_.back().total_underflow_count += underflow_count_;
-  underflow_count_ = 0;
+  if (!ukm_records_.empty()) {
+    auto& last_record = ukm_records_.back();
+    last_record.total_underflow_count += underflow_count_;
+    last_record.total_completed_underflow_count += completed_underflow_count_;
+    last_record.total_underflow_duration += underflow_duration_;
+  }
+
+  underflow_count_ = completed_underflow_count_ = 0;
+  underflow_duration_ = base::TimeDelta();
   watch_time_info_.clear();
 }
 
@@ -298,11 +304,15 @@ void WatchTimeRecorder::UpdateSecondaryProperties(
     for (auto& kv : watch_time_info_)
       last_record.aggregate_watch_time_info[kv.first] += kv.second;
     last_record.total_underflow_count += underflow_count_;
+    last_record.total_completed_underflow_count += completed_underflow_count_;
+    last_record.total_underflow_duration += underflow_duration_;
 
     // If we flushed any watch time or underflow counts which hadn't been
     // finalized we'll need to ensure the eventual Finalize() correctly accounts
     // for those values at the time of the secondary property update.
-    last_record_was_unfinalized = !watch_time_info_.empty() || underflow_count_;
+    last_record_was_unfinalized =
+        !watch_time_info_.empty() || underflow_count_ ||
+        completed_underflow_count_ || !underflow_duration_.is_zero();
   }
   ukm_records_.emplace_back(std::move(secondary_properties));
 
@@ -324,6 +334,8 @@ void WatchTimeRecorder::UpdateSecondaryProperties(
   if (last_record_was_unfinalized) {
     auto& last_record = ukm_records_.back();
     last_record.total_underflow_count = -underflow_count_;
+    last_record.total_completed_underflow_count = -completed_underflow_count_;
+    last_record.total_underflow_duration = -underflow_duration_;
     for (auto& kv : watch_time_info_)
       last_record.aggregate_watch_time_info[kv.first] = -kv.second;
   }
@@ -338,8 +350,15 @@ void WatchTimeRecorder::OnDurationChanged(base::TimeDelta duration) {
   duration_ = duration;
 }
 
-void WatchTimeRecorder::UpdateUnderflowCount(int32_t count) {
-  underflow_count_ = count;
+void WatchTimeRecorder::UpdateUnderflowCount(int32_t total_count) {
+  underflow_count_ = total_count;
+}
+
+void WatchTimeRecorder::UpdateUnderflowDuration(
+    int32_t total_completed_count,
+    base::TimeDelta total_duration) {
+  completed_underflow_count_ = total_completed_count;
+  underflow_duration_ = total_duration;
 }
 
 void WatchTimeRecorder::RecordUkmPlaybackData() {
@@ -473,6 +492,10 @@ void WatchTimeRecorder::RecordUkmPlaybackData() {
     builder.SetIsMSE(properties_->is_mse);
     builder.SetLastPipelineStatus(pipeline_status_);
     builder.SetRebuffersCount(ukm_record.total_underflow_count);
+    builder.SetCompletedRebuffersCount(
+        ukm_record.total_completed_underflow_count);
+    builder.SetCompletedRebuffersDuration(
+        ukm_record.total_underflow_duration.InMilliseconds());
     builder.SetVideoNaturalWidth(
         ukm_record.secondary_properties->natural_size.width());
     builder.SetVideoNaturalHeight(

media/mojo/services/watch_time_recorder.h

@@ -38,7 +38,9 @@ class MEDIA_MOJO_EXPORT WatchTimeRecorder : public mojom::WatchTimeRecorder {
       mojom::SecondaryPlaybackPropertiesPtr secondary_properties) override;
   void SetAutoplayInitiated(bool value) override;
   void OnDurationChanged(base::TimeDelta duration) override;
-  void UpdateUnderflowCount(int32_t count) override;
+  void UpdateUnderflowCount(int32_t total_count) override;
+  void UpdateUnderflowDuration(int32_t total_completed_count,
+                               base::TimeDelta total_duration) override;
 
  private:
   // Records a UKM event based on |aggregate_watch_time_info_|; only recorded
@@ -89,8 +91,10 @@ class MEDIA_MOJO_EXPORT WatchTimeRecorder : public mojom::WatchTimeRecorder {
     // Sum of all watch time data since the last complete finalize.
     WatchTimeInfo aggregate_watch_time_info;
 
-    // Total underflow count for this segment of UKM watch time.
+    // Total underflow count and duration for this segment of UKM watch time.
     int total_underflow_count = 0;
+    int total_completed_underflow_count = 0;
+    base::TimeDelta total_underflow_duration;
   };
 
   // List of all watch time segments. A new entry is added for every secondary
@@ -98,6 +102,9 @@ class MEDIA_MOJO_EXPORT WatchTimeRecorder : public mojom::WatchTimeRecorder {
   std::vector<WatchTimeUkmRecord> ukm_records_;
 
   int underflow_count_ = 0;
+  int completed_underflow_count_ = 0;
+  base::TimeDelta underflow_duration_;
+
   PipelineStatus pipeline_status_ = PIPELINE_OK;
   base::TimeDelta duration_ = kNoTimestamp;
 

tools/metrics/ukm/ukm.xml

@@ -3712,6 +3712,18 @@ be describing additional metrics about the same event.
       activation on the page or without a user initiated same-domain navigation.
     </summary>
   </metric>
+  <metric name="CompletedRebuffersCount">
+    <summary>
+      Integer count of the number of times a previous rebuffer succeeded and
+      playback continued.
+    </summary>
+  </metric>
+  <metric name="CompletedRebuffersDuration">
+    <summary>
+      Sum in milliseconds of all completed rebuffering events. Only reported if
+      a rebuffering completion occurred.
+    </summary>
+  </metric>
   <metric name="Duration">
     <summary>
       Duration in milliseconds, rounded to the most significant digit, of the