[Chromecast] Add metrics for logging platform A/V bitrate estimates.

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"
 #include "base/callback.h"
 #include "base/callback_helpers.h"
 #include "base/location.h"
 #include "base/logging.h"
 #include "base/single_thread_task_runner.h"
+#include "base/strings/string_piece.h"
 #include "base/thread_task_runner_handle.h"
-#include "base/time/time.h"
 #include "chromecast/base/metrics/cast_metrics_helper.h"
 #include "chromecast/media/cdm/browser_cdm_cast.h"
 #include "chromecast/media/cma/base/buffering_controller.h"
 #include "chromecast/media/cma/base/buffering_state.h"
 #include "chromecast/media/cma/base/cma_logging.h"
 #include "chromecast/media/cma/base/coded_frame_provider.h"
 #include "chromecast/media/cma/pipeline/audio_decoder_software_wrapper.h"
 #include "chromecast/media/cma/pipeline/audio_pipeline_impl.h"
 #include "chromecast/media/cma/pipeline/video_pipeline_impl.h"
 #include "chromecast/public/media/media_pipeline_backend.h"
@@ skipping 17 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;
 
+void LogEstimatedBitrate(int decoded_bytes,
+                         base::TimeDelta elapsed_time,
+                         base::StringPiece tag,
+                         base::StringPiece metric) {

[halliwell, 2016/03/11 18:12:46]

+ a nit: No need to use StringPiece here - just pass const char*?

[ejason, 2016/03/11 20:18:07]

Done.

+  int estimated_bitrate_in_kbps =
+      8 * decoded_bytes / elapsed_time.InMilliseconds();
+  if (estimated_bitrate_in_kbps > 0) {

[kmackay, 2016/03/11 17:47:40]

nit: invert logic
if (bitrate <= 0)
  return;

[ejason, 2016/03/11 20:18:07]

Done.

+    CMALOG(kLogControl) << "Estimated " << tag.as_string() << " bitrate is "
+                        << estimated_bitrate_in_kbps << " kbps";
+    metrics::CastMetricsHelper* metrics_helper =
+        metrics::CastMetricsHelper::GetInstance();
+    metrics_helper->RecordSimpleActionWithValue(metric.as_string(),
+                                                estimated_bitrate_in_kbps);
+  }
+}
+
 }  // namespace
 
 struct MediaPipelineImpl::FlushTask {
   bool audio_flushed;
   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),
       statistics_rolling_counter_(0),
+      last_sample_time_(base::Time::FromInternalValue(0)),
+      elapsed_time_delta_(base::TimeDelta()),
+      video_bytes_for_bitrate_estimation_(0),
       weak_factory_(this) {
   CMALOG(kLogControl) << __FUNCTION__;
   weak_this_ = weak_factory_.GetWeakPtr();
   thread_checker_.DetachFromThread();
 }
 
 MediaPipelineImpl::~MediaPipelineImpl() {
   CMALOG(kLogControl) << __FUNCTION__;
   DCHECK(thread_checker_.CalledOnValidThread());
 
@@ skipping 186 matching lines @@
   pending_flush_task_->video_flushed = !video_pipeline_;
   pending_flush_task_->done_cb = flush_cb;
   if (audio_pipeline_) {
     audio_pipeline_->Flush(
         base::Bind(&MediaPipelineImpl::OnFlushDone, weak_this_, true));
   }
   if (video_pipeline_) {
     video_pipeline_->Flush(
         base::Bind(&MediaPipelineImpl::OnFlushDone, weak_this_, false));
   }
+  // 4. Invalidate bitrate statistics.
+  ResetBitrateState();

[kmackay, 2016/03/11 17:47:40]

I would rather call this on transition to the "playing" state (so, when
backend->Start() or backend->Resume() is called. Then, you can just record the
current time as last_sample_time_

[ejason, 2016/03/11 20:18:07]

Thanks this is a really good idea. Done.

 }
 
 void MediaPipelineImpl::Stop() {
   CMALOG(kLogControl) << __FUNCTION__;
   DCHECK(thread_checker_.CalledOnValidThread());
   DCHECK(audio_pipeline_ || video_pipeline_);
   if (backend_state_ != BACKEND_STATE_UNINITIALIZED)
     metrics::CastMetricsHelper::GetInstance()->RecordSimpleAction(
         "Cast.Platform.Ended");
 
   // Cancel pending flush callbacks since we are about to stop/shutdown
   // audio/video pipelines. This will ensure A/V Flush won't happen in
   // stopped state.
   pending_flush_task_.reset();
 
   // Stop both the audio and video pipeline.
   if (audio_pipeline_)
     audio_pipeline_->Stop();
   if (video_pipeline_)
     video_pipeline_->Stop();
 
   // Release hardware resources on Stop.
   audio_pipeline_ = nullptr;
   video_pipeline_ = nullptr;
   audio_decoder_.reset();
   media_pipeline_backend_.reset();
+  ResetBitrateState();
   backend_state_ = BACKEND_STATE_UNINITIALIZED;
 }
 
 void MediaPipelineImpl::SetPlaybackRate(double rate) {
   CMALOG(kLogControl) << __FUNCTION__ << " rate=" << rate;
   DCHECK(thread_checker_.CalledOnValidThread());
   DCHECK((backend_state_ == BACKEND_STATE_PLAYING) ||
          (backend_state_ == BACKEND_STATE_PAUSED));
 
   playback_rate_ = rate;
   if (buffering_controller_ && buffering_controller_->IsBuffering())
     return;
 
   if (rate != 0.0f) {
     media_pipeline_backend_->SetPlaybackRate(rate);
     if (backend_state_ == BACKEND_STATE_PAUSED) {
       media_pipeline_backend_->Resume();
       backend_state_ = BACKEND_STATE_PLAYING;
       metrics::CastMetricsHelper::GetInstance()->RecordSimpleAction(
           "Cast.Platform.Playing");
     }
   } else if (backend_state_ == BACKEND_STATE_PLAYING) {
     media_pipeline_backend_->Pause();
+    ResetBitrateState();
     backend_state_ = BACKEND_STATE_PAUSED;
     metrics::CastMetricsHelper::GetInstance()->RecordSimpleAction(
         "Cast.Platform.Pause");
   }
 }
 
 void MediaPipelineImpl::SetVolume(float volume) {
   CMALOG(kLogControl) << __FUNCTION__ << " vol=" << volume;
   DCHECK(thread_checker_.CalledOnValidThread());
   if (audio_pipeline_)
@@ skipping 51 matching lines @@
       // http://crbug.com/144683.
       LOG(WARNING) << "Ignoring buffering notification.";
     } else {
       client_.buffering_state_cb.Run(::media::BUFFERING_HAVE_ENOUGH);
     }
   }
 
   if (is_buffering && (backend_state_ == BACKEND_STATE_PLAYING)) {
     media_pipeline_backend_->Pause();
     backend_state_ = BACKEND_STATE_PAUSED;
+    ResetBitrateState();
     metrics::CastMetricsHelper::GetInstance()->RecordSimpleAction(
         "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::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_)
       video_pipeline_->UpdateStatistics();
+
+    base::Time current_time = base::Time::Now();

[kmackay, 2016/03/11 17:47:40]

Get the current time within the if statement

[ejason, 2016/03/11 20:18:07]

Done.

+    if (!last_sample_time_.is_null() &&

[kmackay, 2016/03/11 17:47:40]

If you change it to reset just when we enter the playing state, then you don't
need to check if the last sample time is null (since it will always be valid
whenever we are in the playing state).

[ejason, 2016/03/11 20:18:07]

Done.

+        backend_state_ == BACKEND_STATE_PLAYING) {
+      audio_bytes_for_bitrate_estimation_ +=
+          audio_pipeline_->bytes_decoded_since_last_update();
+      video_bytes_for_bitrate_estimation_ +=
+          video_pipeline_->bytes_decoded_since_last_update();
+      elapsed_time_delta_ += current_time - last_sample_time_;
+      if (elapsed_time_delta_.InMilliseconds() > 5000) {
+        LogEstimatedBitrate(audio_bytes_for_bitrate_estimation_,
+                            elapsed_time_delta_, "audio",
+                            "Cast.Platform.AudioBitrate");
+        LogEstimatedBitrate(video_bytes_for_bitrate_estimation_,
+                            elapsed_time_delta_, "video",
+                            "Cast.Platform.VideoBitrate");
+        ResetBitrateState();
+      }
+    }
+    if (backend_state_ == BACKEND_STATE_PLAYING) {
+      last_sample_time_ = current_time;
+    }
   }
+
   statistics_rolling_counter_ =
       (statistics_rolling_counter_ + 1) % kStatisticsUpdatePeriod;
 
   base::TimeDelta media_time = base::TimeDelta::FromMicroseconds(
       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);
@@ skipping 32 matching lines @@
   DCHECK(thread_checker_.CalledOnValidThread());
   DCHECK_NE(error, ::media::PIPELINE_OK) << "PIPELINE_OK is not an error!";
 
   metrics::CastMetricsHelper::GetInstance()->RecordSimpleAction(
       "Cast.Platform.Error");
 
   if (!client_.error_cb.is_null())
     client_.error_cb.Run(error);
 }
 
+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::Time::FromInternalValue(0);
+}
+
 }  // namespace media
 }  // namespace chromecast