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

media/renderers/video_renderer_impl.cc

Index: media/renderers/video_renderer_impl.cc
diff --git a/media/renderers/video_renderer_impl.cc b/media/renderers/video_renderer_impl.cc
index 2c13377bd0519218571104f9a3559dbc8932ca14..be64506762d8743b4ae2beab0569d10b8f29ca9b 100644
--- a/media/renderers/video_renderer_impl.cc
+++ b/media/renderers/video_renderer_impl.cc
@@ -210,6 +210,10 @@ scoped_refptr<VideoFrame> VideoRendererImpl::Render(
   if (!background_rendering && !was_background_rendering_)
     frames_dropped_ += frames_dropped;
   UpdateStats_Locked();
+
+  if (was_background_rendering_ && !background_rendering)
+    shown_timestamp_ = tick_clock_->NowTicks();

[DaleCurtis, 2016/12/03 01:26:34]

Does this actually capture what you want? When video track is disabled this
stream will end. I think instead you want the time from SetMediaTime() -> First
frame.

[whywhat, 2016/12/06 22:01:12]

That seems to be the right place to detect when the video is being shown, no? Is
it called to late after the video element is actually visible?

SetMediaTime calls StartPlayingFrom in this class but it has no idea whether
it's after being shown or user seeked to a new position or hit play. Should I
somehow pass a flag from OnShown in WMPI here then (I don't know exactly how
would I plumb it through yet)?

VideoRendererImpl::StartPlayingFrom() {
  ...
  if (record_show_timestamp_) {
    record_show_timestamp_ = false;
    show_timestamp_ = NowTicks();
  }
  ...
}

I should also probably check for the case when the video is paused when it
changes visibility.

[DaleCurtis, 2016/12/06 23:26:58]

This isn't called until playback starts. It's okay if you don't know if you're
hidden or not. We're essentially looking for the time between SetMediaTime ->
PaintSingleFrame() (or HAVE_ENOUGH if we want to wait for enough frames to start
playback). This will yield some value that we expect to see an upward trend in
when background-disable optimization is enabled.

We can compare this value in finch alongside different key-frame lengths and see
how it's affected. It's possible instead of adding this UMA here we should add
it in media::RendererImpl and have one for audio and one for video. I.e.
something like AudioPrerollTime, VideoPrerollTime.

[whywhat, 2016/12/08 00:23:17]

Hm, seems like we'd be better off using the time_clocks_ in video and audio
renderers separately though (renderer_impl_ doesn't have a time clock, only time
source which is for media time IIUC.

Seems like last_rendered_timestamp_ is what's tracking the time for an analogue
of video frame being painted in audio_renderer_impl.cc?

[DaleCurtis, 2016/12/08 19:04:46]

I don't follow your suggestion? Are you suggesting to use the video/audio
timeline clocks? Those may be scaled by playback rate and aren't running at this
point. I think we just want preroll time from SetMediaTime->HaveEnough using
base::TimeTicks:Now() deltas.

This should be easy enough to test locally. Add such things, turn on your
feature and see if the average time is higher (it should be) for videos with
long keyframe gaps.

+
   was_background_rendering_ = background_rendering;
 
   // Always post this task, it will acquire new frames if necessary and since it
@@ -422,6 +426,12 @@ void VideoRendererImpl::FrameReady(VideoFrameStream::Status status,
                               first_frame->natural_size());
       sink_->PaintSingleFrame(first_frame);
       painted_first_frame_ = true;
+
+      if (!shown_timestamp_.is_null()) {
+        UMA_HISTOGRAM_MEDIUM_TIMES("Media.Video.TimeFromShownToFirstFrame",
+                                   tick_clock_->NowTicks() - shown_timestamp_);
+        shown_timestamp_ = base::TimeTicks();
+      }
     }
   }