[Media] Record time it takes to start rendering audio and video

media/renderers/renderer_impl.cc

Index: media/renderers/renderer_impl.cc
diff --git a/media/renderers/renderer_impl.cc b/media/renderers/renderer_impl.cc
index 87212d8214423f6ed38b7cd4344feca1ae16476e..c74724372e8436b0bb6c3bc95293a7f91b7f46da 100644
--- a/media/renderers/renderer_impl.cc
+++ b/media/renderers/renderer_impl.cc
@@ -12,6 +12,7 @@
 #include "base/command_line.h"
 #include "base/compiler_specific.h"
 #include "base/location.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/single_thread_task_runner.h"
 #include "base/strings/string_number_conversions.h"
 #include "media/base/audio_decoder_config.h"
@@ -65,6 +66,7 @@ class RendererImpl::RendererClientInternal : public RendererClient {
     // the DemuxerHost interface.
     NOTREACHED();
   }
+  void OnFirstFrameRender() override { renderer_->OnFirstFrameRender(type_); }
 
  private:
   DemuxerStream::Type type_;
@@ -236,6 +238,10 @@ void RendererImpl::RestartStreamPlayback(DemuxerStream* stream,
     if (restarting_video_)
       return;
     restarting_video_ = true;
+
+    if (stream->enabled() && video_preroll_start_time_.is_null())
+      video_preroll_start_time_ = base::TimeTicks::Now();
+
     video_renderer_->Flush(
         base::Bind(&RendererImpl::RestartVideoRenderer, weak_this_, time));
   } else if (stream->type() == DemuxerStream::AUDIO) {
@@ -244,6 +250,10 @@ void RendererImpl::RestartStreamPlayback(DemuxerStream* stream,
     if (restarting_audio_)
       return;
     restarting_audio_ = true;
+
+    if (stream->enabled() && audio_preroll_start_time_.is_null())
+      audio_preroll_start_time_ = base::TimeTicks::Now();
+
     // Stop ticking (transition into paused state) in audio renderer before
     // calling Flush, since after Flush we are going to restart playback by
     // calling audio renderer StartPlaying which would fail in playing state.
@@ -642,8 +652,9 @@ void RendererImpl::OnBufferingStateChange(DemuxerStream::Type type,
   bool was_waiting_for_enough_data = WaitingForEnoughData();
 
   if (restarting_audio_ || restarting_video_) {
-    if (HandleRestartedStreamBufferingChanges(type, new_buffering_state))
+    if (HandleRestartedStreamBufferingChanges(type, new_buffering_state)) {
       return;
+    }
   }
 
   // When audio is present and has enough data, defer video underflow callbacks
@@ -655,7 +666,7 @@ void RendererImpl::OnBufferingStateChange(DemuxerStream::Type type,
         audio_buffering_state_ == BUFFERING_HAVE_ENOUGH &&
         new_buffering_state == BUFFERING_HAVE_NOTHING &&
         deferred_video_underflow_cb_.IsCancelled()) {
-      DVLOG(4) << __func__ << " Deferring HAVE_NOTHING for video stream.";
+      DVLOG(1) << __func__ << " Deferring HAVE_NOTHING for video stream.";

[servolk, 2016/12/13 19:46:28]

Nit: why? this could be noisy in logs. Let's keep it P4.

[whywhat, 2016/12/13 21:44:10]

Oops, uploaded accidental change after debug logging.

       deferred_video_underflow_cb_.Reset(
           base::Bind(&RendererImpl::OnBufferingStateChange,
                      weak_factory_.GetWeakPtr(), type, new_buffering_state));
@@ -665,7 +676,6 @@ void RendererImpl::OnBufferingStateChange(DemuxerStream::Type type,
       return;
     }
 
-    DVLOG(4) << "deferred_video_underflow_cb_.Cancel()";

[servolk, 2016/12/13 19:46:28]

Also: why?

[whywhat, 2016/12/13 21:44:10]

ditto

     deferred_video_underflow_cb_.Cancel();
   } else if (!deferred_video_underflow_cb_.IsCancelled() &&
              type == DemuxerStream::AUDIO &&
@@ -845,4 +855,20 @@ void RendererImpl::OnVideoOpacityChange(bool opaque) {
   client_->OnVideoOpacityChange(opaque);
 }
 
+void RendererImpl::OnFirstFrameRender(DemuxerStream::Type type) {
+  DCHECK(task_runner_->BelongsToCurrentThread());
+  if (type == DemuxerStream::AUDIO && !audio_preroll_start_time_.is_null()) {
+    UMA_HISTOGRAM_MEDIUM_TIMES(
+        "Media.Audio.PrerollTime",
+        base::TimeTicks::Now() - audio_preroll_start_time_);
+    audio_preroll_start_time_ = base::TimeTicks();
+  } else if (type == DemuxerStream::VIDEO &&
+             !video_preroll_start_time_.is_null()) {
+    UMA_HISTOGRAM_MEDIUM_TIMES(
+        "Media.Video.PrerollTime",
+        base::TimeTicks::Now() - video_preroll_start_time_);
+    video_preroll_start_time_ = base::TimeTicks();
+  }
+}
+
 }  // namespace media