[Chromecast] Log playback stall event.

chromecast/media/cma/pipeline/media_pipeline_impl.cc

 // Copyright 2014 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "chromecast/media/cma/pipeline/media_pipeline_impl.h"
 
 #include <algorithm>
 #include <utility>
 
 #include "base/bind.h"
@@ skipping 33 matching lines @@
     base::TimeDelta::FromMilliseconds(300));
 
 // Interval between two updates of the media time.
 const base::TimeDelta kTimeUpdateInterval(
     base::TimeDelta::FromMilliseconds(250));
 
 // Interval between two updates of the statistics is equal to:
 // kTimeUpdateInterval * kStatisticsUpdatePeriod.
 const int kStatisticsUpdatePeriod = 4;
 
+// Stall duration threshold that triggers a playback stall event.
+constexpr int kPlaybackStallEventThreshold = 2500;
+
 void LogEstimatedBitrate(int decoded_bytes,
                          base::TimeDelta elapsed_time,
                          const char* tag,
                          const char* metric) {
   int estimated_bitrate_in_kbps =
       8 * decoded_bytes / elapsed_time.InMilliseconds();
 
   if (estimated_bitrate_in_kbps <= 0)
     return;
 
@@ skipping 12 matching lines @@
   bool video_flushed;
   base::Closure done_cb;
 };
 
 MediaPipelineImpl::MediaPipelineImpl()
     : cdm_(nullptr),
       backend_state_(BACKEND_STATE_UNINITIALIZED),
       playback_rate_(1.0f),
       audio_decoder_(nullptr),
       video_decoder_(nullptr),
       pending_time_update_task_(false),

[kmackay, 2016/06/03 17:37:05]

initialize last_media_time_ to kNoTimestamp

[ejason, 2016/06/03 19:20:15]

Done.

       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();
   thread_checker_.DetachFromThread();
 }
 
 MediaPipelineImpl::~MediaPipelineImpl() {
   CMALOG(kLogControl) << __FUNCTION__;
   DCHECK(thread_checker_.CalledOnValidThread());
 
@@ skipping 316 matching lines @@
     metrics::CastMetricsHelper::GetInstance()->RecordApplicationEvent(
         "Cast.Platform.Pause");
   } else if (!is_buffering && (backend_state_ == BACKEND_STATE_PAUSED)) {
     // Once we finish buffering, we need to honour the desired playback rate
     // (rather than just resuming). This way, if playback was paused while
     // buffering, it will remain paused rather than incorrectly resuming.
     SetPlaybackRate(playback_rate_);
   }
 }
 
+void MediaPipelineImpl::CheckForPlaybackStall(base::TimeDelta media_time,
+                                              base::TimeTicks current_stc) {

[kmackay, 2016/06/03 17:37:05]

what does 'stc' stand for?

[ejason, 2016/06/03 19:20:15]

System time clock. I simply re-used the existing nomenclature from
UpdateMediaTime() (line 528). I'm open to changing this if you want, I don't
feel strongly one way or the other. 

+  DCHECK(media_time != ::media::kNoTimestamp());
+
+  // A playback stall is defined as a scenario where the underlying media
+  // pipeline has unexpectedly stopped making forward progress. The pipeline is
+  // NOT stalled if:
+  //
+  // 1. Media time is progressing
+  // 2. The backend is paused
+  // 3. We are currently buffering (this is captured in a separate event)
+  if (media_time != last_media_time_ ||
+      backend_state_ != BACKEND_STATE_PLAYING ||
+      (buffering_controller_ && buffering_controller_->IsBuffering())) {
+    if (playback_stalled_) {
+      // Transition out of the stalled condition.
+      base::TimeDelta stall_duration = current_stc - playback_stalled_time_;
+      CMALOG(kLogControl)
+          << "Transitioning out of stalled state. Stall duration was "
+          << 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() >=
+        kPlaybackStallEventThreshold) {
+      CMALOG(kLogControl) << "Playback stalled";
+      metrics::CastMetricsHelper::GetInstance()->RecordApplicationEvent(
+          "Cast.Platform.PlaybackStall");
+      playback_stalled_notification_sent_ = true;
+    }
+    return;
+  }
+}
+
 void MediaPipelineImpl::UpdateMediaTime() {
   pending_time_update_task_ = false;
   if ((backend_state_ != BACKEND_STATE_PLAYING) &&
       (backend_state_ != BACKEND_STATE_PAUSED))
     return;
 
   if (statistics_rolling_counter_ == 0) {
     if (audio_pipeline_)
       audio_pipeline_->UpdateStatistics();
     if (video_pipeline_)
@@ skipping 30 matching lines @@
       media_pipeline_backend_->GetCurrentPts());
   if (media_time == ::media::kNoTimestamp()) {
     pending_time_update_task_ = true;
     base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
         FROM_HERE, base::Bind(&MediaPipelineImpl::UpdateMediaTime, weak_this_),
         kTimeUpdateInterval);
     return;
   }
   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);
 
     // Receiving the same time twice in a row means playback isn't moving,
     // so don't interpolate ahead.
     if (media_time != last_media_time_) {
       max_rendering_time = buffering_controller_->GetMaxRenderingTime();
       if (max_rendering_time == ::media::kNoTimestamp())
         max_rendering_time = media_time;
@@ skipping 27 matching lines @@
 
 void MediaPipelineImpl::ResetBitrateState() {
   elapsed_time_delta_ = base::TimeDelta::FromSeconds(0);
   audio_bytes_for_bitrate_estimation_ = 0;
   video_bytes_for_bitrate_estimation_ = 0;
   last_sample_time_ = base::TimeTicks::Now();
 }
 
 }  // namespace media
 }  // namespace chromecast