[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) {
+  int estimated_bitrate_in_kbps =
+      8 * decoded_bytes / elapsed_time.InMilliseconds();
+  if (estimated_bitrate_in_kbps > 0) {
+    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();
 }
 
 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();
+    if (!last_sample_time_.is_null() &&
+        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