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

media/renderers/video_renderer_impl.cc

 // Copyright 2013 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/video_renderer_impl.h"
 
 #include <utility>
 
 #include "base/bind.h"
 #include "base/callback.h"
@@ skipping 192 matching lines @@
   }
 
   // We don't count dropped frames in the background to avoid skewing the count
   // and impacting JavaScript visible metrics used by web developers.
   //
   // Just after resuming from background rendering, we also don't count the
   // dropped frames since they are likely just dropped due to being too old.
   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
   // happens on another thread, even if we don't have room in the queue now, by
   // the time it runs (may be delayed up to 50ms for complex decodes!) we might.
   task_runner_->PostTask(
       FROM_HERE,
       base::Bind(&VideoRendererImpl::AttemptReadAndCheckForMetadataChanges,
                  weak_factory_.GetWeakPtr(), result->format(),
                  result->natural_size()));
@@ skipping 192 matching lines @@
     // prerolling frames before the actual start time that will be dropped.
     if (algorithm_->frames_queued() > 1 || received_end_of_stream_ ||
         frame->timestamp() >= start_timestamp_ || low_delay_ ||
         !video_frame_stream_->CanReadWithoutStalling()) {
       scoped_refptr<VideoFrame> first_frame =
           algorithm_->Render(base::TimeTicks(), base::TimeTicks(), nullptr);
       CheckForMetadataChanges(first_frame->format(),
                               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();
+      }
     }
   }
 
   // Signal buffering state if we've met our conditions.
   if (buffering_state_ == BUFFERING_HAVE_NOTHING && HaveEnoughData_Locked())
     TransitionToHaveEnough_Locked();
 
   // Always request more decoded video if we have capacity.
   AttemptRead_Locked();
 }
@@ skipping 275 matching lines @@
 
 void VideoRendererImpl::AttemptReadAndCheckForMetadataChanges(
     VideoPixelFormat pixel_format,
     const gfx::Size& natural_size) {
   base::AutoLock auto_lock(lock_);
   CheckForMetadataChanges(pixel_format, natural_size);
   AttemptRead_Locked();
 }
 
 }  // namespace media