[Chromecast] Log playback stall event.

chromecast/media/cma/pipeline/media_pipeline_impl.cc

Index: chromecast/media/cma/pipeline/media_pipeline_impl.cc
diff --git a/chromecast/media/cma/pipeline/media_pipeline_impl.cc b/chromecast/media/cma/pipeline/media_pipeline_impl.cc
index 68fcaa72e67c5834f50f1e1f40019f885e26603d..6b6e4b9f67788ced81b70825499b2cdc54f07509 100644
--- a/chromecast/media/cma/pipeline/media_pipeline_impl.cc
+++ b/chromecast/media/cma/pipeline/media_pipeline_impl.cc
@@ -87,6 +87,8 @@ MediaPipelineImpl::MediaPipelineImpl()
       statistics_rolling_counter_(0),
       audio_bytes_for_bitrate_estimation_(0),
       video_bytes_for_bitrate_estimation_(0),
+      playback_stalled_(false),
+      playback_stalled_notification_sent_(false),
       weak_factory_(this) {
   CMALOG(kLogControl) << __FUNCTION__;
   weak_this_ = weak_factory_.GetWeakPtr();
@@ -423,6 +425,44 @@ void MediaPipelineImpl::OnBufferingNotification(bool is_buffering) {
   }
 }
 
+void MediaPipelineImpl::CheckForPlaybackStall(base::TimeDelta media_time,
+                                              base::TimeTicks current_stc) {

[alokp, 2016/06/02 00:09:33]

DCHECK(media_time >= last_media_time)

[ejason, 2016/06/03 16:48:47]

I added this DCHECK but during my local longevity tests it appears that this
assumption doesn't hold (i.e., I hit the DCHECK). I didn't debug further. 

While I wouldn't expect this condition either, I think the initial if-condition
that checks that media_time != last_media_time should handle this gracefully (it
either no-ops or resets stall state and returns). Further, we only use the stc
value for calculations. 

I did add a DCHECK for media_time != ::media::kNoTimestamp as the code as
written should only be called with a valid media_time. 

+  // Check to see if a stall condition exists. If not, check to see if we need
+  // to transition out of the previous stall condition.
+  if (media_time != last_media_time_) {
+    if (playback_stalled_) {
+      // Transition out of the stalled condition.
+      base::TimeDelta stall_duration = current_stc - playback_stalled_time_;
+      LOG(INFO) << "Transitioning out of stalled state. Stall duration was "

[alokp, 2016/06/02 00:09:33]

LOG(INFO) -> CMALOG

[ejason, 2016/06/03 16:48:47]

Done.

+                << stall_duration.InMilliseconds() << " ms";
+      playback_stalled_ = false;
+      playback_stalled_notification_sent_ = false;
+    }
+    return;
+  }
+
+  // Check to see if this is a new stall condition.
+  if (!playback_stalled_) {
+    playback_stalled_ = true;
+    playback_stalled_time_ = current_stc;
+    return;
+  }
+
+  // If we are in an existing stall, check to see if we've been stalled for more
+  // than 2.5 s. If so, send a single notification of the stall event.
+  if (!playback_stalled_notification_sent_) {
+    base::TimeDelta current_stall_duration =
+        current_stc - playback_stalled_time_;
+    if (current_stall_duration.InMilliseconds() >= 2500) {

[alokp, 2016/06/02 00:09:33]

move 2500 into a constant.

[ejason, 2016/06/03 16:48:47]

Done.

+      LOG(INFO) << "Playback stalled";
+      metrics::CastMetricsHelper::GetInstance()->RecordApplicationEvent(
+          "Cast.Platform.PlaybackStall");
+      playback_stalled_notification_sent_ = true;
+    }
+    return;
+  }
+}
+
 void MediaPipelineImpl::UpdateMediaTime() {

[alokp, 2016/06/02 00:09:33]

verify that this is not scheduled when playback_rate = 0. Otherwise you will log
false stall events.

[ejason, 2016/06/03 16:48:47]

I reviewed the code and it appears to be the case. That said, I added explicit
checks to CheckForPlaybackStall() for this case and the case where we are
buffering, as we have another metric for the buffering_controller case. 

   pending_time_update_task_ = false;
   if ((backend_state_ != BACKEND_STATE_PLAYING) &&
@@ -473,6 +513,8 @@ void MediaPipelineImpl::UpdateMediaTime() {
   }
   base::TimeTicks stc = base::TimeTicks::Now();
 
+  CheckForPlaybackStall(media_time, stc);
+
   base::TimeDelta max_rendering_time = media_time;
   if (buffering_controller_) {
     buffering_controller_->SetMediaTime(media_time);