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

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 73dc9ad1eb0e06779348f1bac45204c45842168c..687645dbb3c61742f45113ddd27f0522f1c49f0b 100644
--- a/chromecast/media/cma/pipeline/media_pipeline_impl.cc
+++ b/chromecast/media/cma/pipeline/media_pipeline_impl.cc
@@ -13,8 +13,8 @@
 #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"
@@ -52,6 +52,22 @@ const base::TimeDelta kTimeUpdateInterval(
 // 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 {
@@ -68,6 +84,9 @@ MediaPipelineImpl::MediaPipelineImpl()
       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();
@@ -274,6 +293,8 @@ void MediaPipelineImpl::Flush(const base::Closure& flush_cb) {
     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() {
@@ -300,6 +321,7 @@ void MediaPipelineImpl::Stop() {
   video_pipeline_ = nullptr;
   audio_decoder_.reset();
   media_pipeline_backend_.reset();
+  ResetBitrateState();
   backend_state_ = BACKEND_STATE_UNINITIALIZED;
 }
 
@@ -323,6 +345,7 @@ void MediaPipelineImpl::SetPlaybackRate(double rate) {
     }
   } else if (backend_state_ == BACKEND_STATE_PLAYING) {
     media_pipeline_backend_->Pause();
+    ResetBitrateState();
     backend_state_ = BACKEND_STATE_PAUSED;
     metrics::CastMetricsHelper::GetInstance()->RecordSimpleAction(
         "Cast.Platform.Pause");
@@ -394,6 +417,7 @@ void MediaPipelineImpl::OnBufferingNotification(bool is_buffering) {
   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)) {
@@ -415,7 +439,30 @@ void MediaPipelineImpl::UpdateMediaTime() {
       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;
 
@@ -468,5 +515,12 @@ void MediaPipelineImpl::OnError(::media::PipelineStatus error) {
     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