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

media/renderers/renderer_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 "media/renderers/renderer_impl.h"
 
 #include <utility>
 
 #include "base/bind.h"
 #include "base/callback.h"
 #include "base/callback_helpers.h"
 #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"
 #include "media/base/audio_renderer.h"
 #include "media/base/bind_to_current_loop.h"
 #include "media/base/demuxer_stream_provider.h"
 #include "media/base/media_switches.h"
 #include "media/base/renderer_client.h"
 #include "media/base/time_source.h"
 #include "media/base/video_decoder_config.h"
@@ skipping 33 matching lines @@
     DCHECK(type_ == DemuxerStream::VIDEO);
     renderer_->OnVideoOpacityChange(opaque);
   }
   void OnDurationChange(base::TimeDelta duration) override {
     // RendererClients should only be notified of duration changes in certain
     // scenarios, none of which should arise for RendererClientInternal.
     // Duration changes should be sent to the pipeline by the DemuxerStream, via
     // the DemuxerHost interface.
     NOTREACHED();
   }
+  void OnFirstFrameRender() override { renderer_->OnFirstFrameRender(type_); }
 
  private:
   DemuxerStream::Type type_;
   RendererImpl* renderer_;
 };
 
 RendererImpl::RendererImpl(
     const scoped_refptr<base::SingleThreadTaskRunner>& task_runner,
     std::unique_ptr<AudioRenderer> audio_renderer,
     std::unique_ptr<VideoRenderer> video_renderer)
@@ skipping 151 matching lines @@
   bool video = (stream->type() == DemuxerStream::VIDEO);
   DVLOG(1) << __func__ << (video ? " video" : " audio") << " stream=" << stream
            << " enabled=" << stream->enabled() << " time=" << time.InSecondsF();
   if ((state_ != STATE_PLAYING) || (audio_ended_ && video_ended_))
     return;
   if (stream->type() == DemuxerStream::VIDEO) {
     DCHECK(video_renderer_);
     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) {
     DCHECK(audio_renderer_);
     DCHECK(time_source_);
     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.
     if (time_ticking_) {
       time_ticking_ = false;
       time_source_->StopTicking();
     }
     audio_renderer_->Flush(
         base::Bind(&RendererImpl::RestartAudioRenderer, weak_this_, time));
   }
@@ skipping 378 matching lines @@
                                         : &video_buffering_state_;
 
   DVLOG(1) << __func__ << (type == DemuxerStream::AUDIO ? " audio " : " video ")
            << BufferingStateStr(*buffering_state) << " -> "
            << BufferingStateStr(new_buffering_state);
   DCHECK(task_runner_->BelongsToCurrentThread());
 
   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
   // for some time to avoid unnecessary glitches in audio; see
   // http://crbug.com/144683#c53.
   if (audio_renderer_ && type == DemuxerStream::VIDEO &&
       state_ == STATE_PLAYING) {
     if (video_buffering_state_ == BUFFERING_HAVE_ENOUGH &&
         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));
       task_runner_->PostDelayedTask(FROM_HERE,
                                     deferred_video_underflow_cb_.callback(),
                                     video_underflow_threshold_);
       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 &&
              new_buffering_state == BUFFERING_HAVE_NOTHING) {
     // If audio underflows while we have a deferred video underflow in progress
     // we want to mark video as underflowed immediately and cancel the deferral.
     deferred_video_underflow_cb_.Cancel();
     video_buffering_state_ = BUFFERING_HAVE_NOTHING;
   }
 
@@ skipping 159 matching lines @@
 void RendererImpl::OnVideoNaturalSizeChange(const gfx::Size& size) {
   DCHECK(task_runner_->BelongsToCurrentThread());
   client_->OnVideoNaturalSizeChange(size);
 }
 
 void RendererImpl::OnVideoOpacityChange(bool opaque) {
   DCHECK(task_runner_->BelongsToCurrentThread());
   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