Chromium Code Reviews
|
|
Chromium Code Reviews
Issue
2552493002:
[Media] Record time it takes to start rendering audio and video (Closed)
Description[Media] Record time it takes to start rendering audio and video
BUG=670150
TEST=manually with and without the background video track optimization flag.
Record time between the play or seek and when the player has enough
data for both audio and video renderers.
Review-Url: https://codereview.chromium.org/2552493002
Cr-Commit-Position: refs/heads/master@{#441860}
Committed: https://chromium.googlesource.com/chromium/src/+/ac607d65a37cba23db6690580fd78068f9b9fde0
Patch Set 1 #
Total comments: 5
Patch Set 2 : Audio and video first render times #
Total comments: 2
Patch Set 3 : Compute preroll time for both audio and video renderers #
Total comments: 6
Patch Set 4 : Addressed nits in histograms.xml #Patch Set 5 : Use RestartPlaybackStream and OnFirstFrameRender #
Total comments: 4
Patch Set 6 : Reverted accidental changes to logs #Patch Set 7 : Changed to PS4 but resetting the time in RestartStreamPlayback #Patch Set 8 : Tracking the time between being shown and the first frame being composited #Patch Set 9 : Reverted to RestartStreamPlayback #Patch Set 10 : Accessing VFC directly from WMPI #
Total comments: 3
Patch Set 11 : visible->shown,timestamp->time #Patch Set 12 : Shown->Foreground #
Messages
Total messages: 66 (19 generated)
avayvod@chromium.org changed reviewers: + dalecurtis@chromium.org
PTaL Took a stab at the timing between the video being shown and the first frame painted.
https://codereview.chromium.org/2552493002/diff/1/media/renderers/video_rende... File media/renderers/video_renderer_impl.cc (right): https://codereview.chromium.org/2552493002/diff/1/media/renderers/video_rende... media/renderers/video_renderer_impl.cc:215: shown_timestamp_ = tick_clock_->NowTicks(); 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.
https://codereview.chromium.org/2552493002/diff/1/media/renderers/video_rende... File media/renderers/video_renderer_impl.cc (right): https://codereview.chromium.org/2552493002/diff/1/media/renderers/video_rende... media/renderers/video_renderer_impl.cc:215: shown_timestamp_ = tick_clock_->NowTicks(); On 2016/12/03 at 01:26:34, DaleCurtis wrote: > 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. 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.
https://codereview.chromium.org/2552493002/diff/1/media/renderers/video_rende... File media/renderers/video_renderer_impl.cc (right): https://codereview.chromium.org/2552493002/diff/1/media/renderers/video_rende... media/renderers/video_renderer_impl.cc:215: shown_timestamp_ = tick_clock_->NowTicks(); On 2016/12/06 at 22:01:12, whywhat_OOO_till_Mon_Nov_28 wrote: > On 2016/12/03 at 01:26:34, DaleCurtis wrote: > > 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. > > 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. 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.
Audio and video first render times
https://codereview.chromium.org/2552493002/diff/1/media/renderers/video_rende... File media/renderers/video_renderer_impl.cc (right): https://codereview.chromium.org/2552493002/diff/1/media/renderers/video_rende... media/renderers/video_renderer_impl.cc:215: shown_timestamp_ = tick_clock_->NowTicks(); On 2016/12/06 at 23:26:58, DaleCurtis wrote: > On 2016/12/06 at 22:01:12, whywhat_OOO_till_Mon_Nov_28 wrote: > > On 2016/12/03 at 01:26:34, DaleCurtis wrote: > > > 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. > > > > 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. > > 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. 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?
The CQ bit was checked by avayvod@chromium.org to run a CQ dry run
Dry run: CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
The CQ bit was unchecked by commit-bot@chromium.org
Dry run: Try jobs failed on following builders: android_n5x_swarming_rel on master.tryserver.chromium.android (JOB_FAILED, https://build.chromium.org/p/tryserver.chromium.android/builders/android_n5x_...)
https://codereview.chromium.org/2552493002/diff/1/media/renderers/video_rende... File media/renderers/video_renderer_impl.cc (right): https://codereview.chromium.org/2552493002/diff/1/media/renderers/video_rende... media/renderers/video_renderer_impl.cc:215: shown_timestamp_ = tick_clock_->NowTicks(); On 2016/12/08 at 00:23:17, whywhat wrote: > On 2016/12/06 at 23:26:58, DaleCurtis wrote: > > On 2016/12/06 at 22:01:12, whywhat_OOO_till_Mon_Nov_28 wrote: > > > On 2016/12/03 at 01:26:34, DaleCurtis wrote: > > > > 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. > > > > > > 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. > > > > 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. > > 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? 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.
mlamouri@chromium.org changed reviewers: + mlamouri@chromium.org
Should we have something specific for videos that are back from background? How is this data help with the background decoding work? https://codereview.chromium.org/2552493002/diff/20001/tools/metrics/histogram... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2552493002/diff/20001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:23645: + after playback start is initiated (on initial play or after seekeing). nit: seeking https://codereview.chromium.org/2552493002/diff/20001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:25466: + start is initiated (on initial play or after seekeing). nit: ditto
On 2016/12/09 at 18:58:01, mlamouri wrote: > Should we have something specific for videos that are back from background? How is this data help with the background decoding work? See Dale's comment above: "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." > > https://codereview.chromium.org/2552493002/diff/20001/tools/metrics/histogram... > File tools/metrics/histograms/histograms.xml (right): > > https://codereview.chromium.org/2552493002/diff/20001/tools/metrics/histogram... > tools/metrics/histograms/histograms.xml:23645: + after playback start is initiated (on initial play or after seekeing). > nit: seeking > > https://codereview.chromium.org/2552493002/diff/20001/tools/metrics/histogram... > tools/metrics/histograms/histograms.xml:25466: + start is initiated (on initial play or after seekeing). > nit: ditto
Compute preroll time for both audio and video renderers
avayvod@chromium.org changed reviewers: + isherman@chromium.org - mlamouri@chromium.org
PTAL +isherman for histograms.xml
Description was changed from
==========
[Video] Record time between video shown and the first paint
BUG=670150
TEST=None
==========
to
==========
[Media] Record time it takes to start rendering audio and video
BUG=670150
TEST=manually with and without the background video track optimization flag.
Record time between the play or seek and when the player has enough
data for both audio and video renderers.
==========
The CQ bit was checked by avayvod@chromium.org to run a CQ dry run
Dry run: CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
Have you confirmed that you can see a difference in these values locally with your optimization enabled/disabled? This is the right idea I had, but you'll still need to verify it actually works since I haven't been following how the track switches work. If each track switch ends up hitting this path, we should see an average increase here with the optimization enabled. This is something you should be able to verify locally with videos that have long keyframe distances.
Metrics LGTM % nits: https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:23820: + Records the time between moment when the audio is requested to start from a nit: s/between moment/between the moment https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:23822: + every time the enough data is buffered after playback is initiated (on nit: s/the enough data is/there's enough data or /enough data is https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:25512: + Records the time between moment when the video is requested to start from a nit: s/between moment/between the moment
Addressed nits in histograms.xml
avayvod@chromium.org changed reviewers: + servolk@chromium.org
Thanks for the review isherman@! Dale, I tested it manually and see the increase in time at about 10ms mean for audio (from 12ms to 22ms) and similar for video (from ~20ms to ~30ms). However, I'd say this is a pretty anecdotal evidence since I didn't do much testing. +servolk who should be able to confirm from the track switching point of view. https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... File tools/metrics/histograms/histograms.xml (right): https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:23820: + Records the time between moment when the audio is requested to start from a On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > nit: s/between moment/between the moment Done. https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:23822: + every time the enough data is buffered after playback is initiated (on On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > nit: s/the enough data is/there's enough data or /enough data is Done. https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... tools/metrics/histograms/histograms.xml:25512: + Records the time between moment when the video is requested to start from a On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > nit: s/between moment/between the moment Done.
On 2016/12/10 at 02:26:09, whywhat wrote: > Thanks for the review isherman@! > > Dale, I tested it manually and see the increase in time at about 10ms mean for audio (from 12ms to 22ms) and similar for video (from ~20ms to ~30ms). However, I'd say this is a pretty anecdotal evidence since I didn't do much testing. +servolk who should be able to confirm from the track switching point of view. TBH, it seems like this CL would not catch the case when we have the data buffered and disable / enabled video track - we'd have enough data already but there's still a delay before the video is rendered (e.g. when playing the BBB video on http://avayvod.github.io/mediaplaybacktest.html I see a visible delay when I switch back to the tab even in Release build on my machine, but I only get one report in histogram that doesn't differ from the one in the case when the flag is disabled). > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > File tools/metrics/histograms/histograms.xml (right): > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > tools/metrics/histograms/histograms.xml:23820: + Records the time between moment when the audio is requested to start from a > On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > > nit: s/between moment/between the moment > > Done. > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > tools/metrics/histograms/histograms.xml:23822: + every time the enough data is buffered after playback is initiated (on > On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > > nit: s/the enough data is/there's enough data or /enough data is > > Done. > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > tools/metrics/histograms/histograms.xml:25512: + Records the time between moment when the video is requested to start from a > On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > > nit: s/between moment/between the moment > > Done.
On 2016/12/10 02:34:58, whywhat wrote: > On 2016/12/10 at 02:26:09, whywhat wrote: > > Thanks for the review isherman@! > > > > Dale, I tested it manually and see the increase in time at about 10ms mean for > audio (from 12ms to 22ms) and similar for video (from ~20ms to ~30ms). However, > I'd say this is a pretty anecdotal evidence since I didn't do much testing. > +servolk who should be able to confirm from the track switching point of view. > > TBH, it seems like this CL would not catch the case when we have the data > buffered and disable / enabled video track - we'd have enough data already but > there's still a delay before the video is rendered (e.g. when playing the BBB > video on http://avayvod.github.io/mediaplaybacktest.html I see a visible delay > when I switch back to the tab even in Release build on my machine, but I only > get one report in histogram that doesn't differ from the one in the case when > the flag is disabled). > > > > > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > > File tools/metrics/histograms/histograms.xml (right): > > > > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > > tools/metrics/histograms/histograms.xml:23820: + Records the time between > moment when the audio is requested to start from a > > On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > > > nit: s/between moment/between the moment > > > > Done. > > > > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > > tools/metrics/histograms/histograms.xml:23822: + every time the enough data > is buffered after playback is initiated (on > > On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > > > nit: s/the enough data is/there's enough data or /enough data is > > > > Done. > > > > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > > tools/metrics/histograms/histograms.xml:25512: + Records the time between > moment when the video is requested to start from a > > On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > > > nit: s/between moment/between the moment > > > > Done. Yes, it also seems to me that this CL in it's current form will not report correctly the preroll delay associated with enabling/disabling track, because RendererImpl::StartPlayingFrom is not called when a media track is re-enabled. If you do want to catch a/v preroll delay when a media track is re-enabled, you should probably also reset audio/video_preroll_start_time_ in RendererImpl::RestartStreamPlayback (or, perhaps in RendererImpl::RestartAudio/VideoRenderer, depending on what you are trying to measure).
On 2016/12/12 at 19:08:20, servolk wrote: > On 2016/12/10 02:34:58, whywhat wrote: > > On 2016/12/10 at 02:26:09, whywhat wrote: > > > Thanks for the review isherman@! > > > > > > Dale, I tested it manually and see the increase in time at about 10ms mean for > > audio (from 12ms to 22ms) and similar for video (from ~20ms to ~30ms). However, > > I'd say this is a pretty anecdotal evidence since I didn't do much testing. > > +servolk who should be able to confirm from the track switching point of view. > > > > TBH, it seems like this CL would not catch the case when we have the data > > buffered and disable / enabled video track - we'd have enough data already but > > there's still a delay before the video is rendered (e.g. when playing the BBB > > video on http://avayvod.github.io/mediaplaybacktest.html I see a visible delay > > when I switch back to the tab even in Release build on my machine, but I only > > get one report in histogram that doesn't differ from the one in the case when > > the flag is disabled). > > > > > > > > > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > > > File tools/metrics/histograms/histograms.xml (right): > > > > > > > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > > > tools/metrics/histograms/histograms.xml:23820: + Records the time between > > moment when the audio is requested to start from a > > > On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > > > > nit: s/between moment/between the moment > > > > > > Done. > > > > > > > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > > > tools/metrics/histograms/histograms.xml:23822: + every time the enough data > > is buffered after playback is initiated (on > > > On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > > > > nit: s/the enough data is/there's enough data or /enough data is > > > > > > Done. > > > > > > > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > > > tools/metrics/histograms/histograms.xml:25512: + Records the time between > > moment when the video is requested to start from a > > > On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > > > > nit: s/between moment/between the moment > > > > > > Done. > > Yes, it also seems to me that this CL in it's current form will not report correctly the preroll delay associated with enabling/disabling track, because RendererImpl::StartPlayingFrom is not called when a media track is re-enabled. > If you do want to catch a/v preroll delay when a media track is re-enabled, you should probably also reset audio/video_preroll_start_time_ in RendererImpl::RestartStreamPlayback (or, perhaps in RendererImpl::RestartAudio/VideoRenderer, depending on what you are trying to measure). Thanks, I figured that out too. What would be the place to measure when the video/audio frame actually leaves the pipeline to be rendered (or something close to that)?
On 2016/12/12 22:23:13, whywhat wrote: > On 2016/12/12 at 19:08:20, servolk wrote: > > On 2016/12/10 02:34:58, whywhat wrote: > > > On 2016/12/10 at 02:26:09, whywhat wrote: > > > > Thanks for the review isherman@! > > > > > > > > Dale, I tested it manually and see the increase in time at about 10ms mean > for > > > audio (from 12ms to 22ms) and similar for video (from ~20ms to ~30ms). > However, > > > I'd say this is a pretty anecdotal evidence since I didn't do much testing. > > > +servolk who should be able to confirm from the track switching point of > view. > > > > > > TBH, it seems like this CL would not catch the case when we have the data > > > buffered and disable / enabled video track - we'd have enough data already > but > > > there's still a delay before the video is rendered (e.g. when playing the > BBB > > > video on http://avayvod.github.io/mediaplaybacktest.html I see a visible > delay > > > when I switch back to the tab even in Release build on my machine, but I > only > > > get one report in histogram that doesn't differ from the one in the case > when > > > the flag is disabled). > > > > > > > > > > > > > > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > > > > File tools/metrics/histograms/histograms.xml (right): > > > > > > > > > > > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > > > > tools/metrics/histograms/histograms.xml:23820: + Records the time > between > > > moment when the audio is requested to start from a > > > > On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > > > > > nit: s/between moment/between the moment > > > > > > > > Done. > > > > > > > > > > > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > > > > tools/metrics/histograms/histograms.xml:23822: + every time the enough > data > > > is buffered after playback is initiated (on > > > > On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > > > > > nit: s/the enough data is/there's enough data or /enough data is > > > > > > > > Done. > > > > > > > > > > > > https://codereview.chromium.org/2552493002/diff/40001/tools/metrics/histogram... > > > > tools/metrics/histograms/histograms.xml:25512: + Records the time > between > > > moment when the video is requested to start from a > > > > On 2016/12/10 at 01:55:35, Ilya Sherman wrote: > > > > > nit: s/between moment/between the moment > > > > > > > > Done. > > > > Yes, it also seems to me that this CL in it's current form will not report > correctly the preroll delay associated with enabling/disabling track, because > RendererImpl::StartPlayingFrom is not called when a media track is re-enabled. > > If you do want to catch a/v preroll delay when a media track is re-enabled, > you should probably also reset audio/video_preroll_start_time_ in > RendererImpl::RestartStreamPlayback (or, perhaps in > RendererImpl::RestartAudio/VideoRenderer, depending on what you are trying to > measure). > > Thanks, I figured that out too. What would be the place to measure when the > video/audio frame actually leaves the pipeline to be rendered (or something > close to that)? For VideoRenderer I believe it would be at https://cs.chromium.org/chromium/src/media/renderers/video_renderer_impl.cc?r..., but that's probably not easily accessible from RendererImpl.
Use RestartPlaybackStream and OnFirstFrameRender
PTAL I think we're closer to measuring the time between reinitiating playback between audio/video track enabled and the first render (hopefully the one in the audio renderer is correct, the video renderer has a helpful bool already). However, I think this becomes useless for the feature in question: - measuring audio doesn't help at all as we don't deselect audio track - measuring video won't trigger when the feature is disabled Therefore I think we need to start the timing when the video (frame) becomes visible and stop when the first frame is painted. Seems like I can propagate OnFirstFrameRendered up to the PipelineImpl from VideoRenderer and maybe propagate OnShown from WMPI to PipelineImpl as well and record the time there. Or I could propagate the first render time all the way to WMPI via pipeline_statistics. WDYT?
https://codereview.chromium.org/2552493002/diff/70001/media/renderers/rendere... File media/renderers/renderer_impl.cc (left): https://codereview.chromium.org/2552493002/diff/70001/media/renderers/rendere... media/renderers/renderer_impl.cc:668: DVLOG(4) << "deferred_video_underflow_cb_.Cancel()"; Also: why? https://codereview.chromium.org/2552493002/diff/70001/media/renderers/rendere... File media/renderers/renderer_impl.cc (right): https://codereview.chromium.org/2552493002/diff/70001/media/renderers/rendere... media/renderers/renderer_impl.cc:669: DVLOG(1) << __func__ << " Deferring HAVE_NOTHING for video stream."; Nit: why? this could be noisy in logs. Let's keep it P4.
Reverted accidental changes to logs
https://codereview.chromium.org/2552493002/diff/70001/media/renderers/rendere... File media/renderers/renderer_impl.cc (left): https://codereview.chromium.org/2552493002/diff/70001/media/renderers/rendere... media/renderers/renderer_impl.cc:668: DVLOG(4) << "deferred_video_underflow_cb_.Cancel()"; On 2016/12/13 at 19:46:28, servolk wrote: > Also: why? ditto https://codereview.chromium.org/2552493002/diff/70001/media/renderers/rendere... File media/renderers/renderer_impl.cc (right): https://codereview.chromium.org/2552493002/diff/70001/media/renderers/rendere... media/renderers/renderer_impl.cc:669: DVLOG(1) << __func__ << " Deferring HAVE_NOTHING for video stream."; On 2016/12/13 at 19:46:28, servolk wrote: > Nit: why? this could be noisy in logs. Let's keep it P4. Oops, uploaded accidental change after debug logging.
This isn't going to measure what you think it is since the frame may sit in the compositor for some time w/o rendering; especially when transitioning to the foreground, see http://crbug.com/659207. What you had in PS#4 was correct; RestartStreamPlayback() is going to trigger a rebuffering cycle so we'll run the transition from HAVE_NOTHING -> HAVE_ENOUGH again.
On 2016/12/14 at 00:39:11, DaleCurtis wrote: > This isn't going to measure what you think it is since the frame may sit in the compositor for some time w/o rendering; especially when transitioning to the foreground, see http://crbug.com/659207. What you had in PS#4 was correct; RestartStreamPlayback() is going to trigger a rebuffering cycle so we'll run the transition from HAVE_NOTHING -> HAVE_ENOUGH again. Well, almost correct, you need to set your measurement marker again (or possibly only in this case) in RestartStreamPlayback().
On 2016/12/14 at 00:40:11, dalecurtis wrote: > On 2016/12/14 at 00:39:11, DaleCurtis wrote: > > This isn't going to measure what you think it is since the frame may sit in the compositor for some time w/o rendering; especially when transitioning to the foreground, see http://crbug.com/659207. What you had in PS#4 was correct; RestartStreamPlayback() is going to trigger a rebuffering cycle so we'll run the transition from HAVE_NOTHING -> HAVE_ENOUGH again. When the flag enabled, yes, but how do we compare it with the times where the track is not enabled - the rebuffering will not happen when video becomes visible - we will only have the time for when the video is preloaded mostly, no? > > Well, almost correct, you need to set your measurement marker again (or possibly only in this case) in RestartStreamPlayback().
On 2016/12/14 at 01:56:58, avayvod wrote: > On 2016/12/14 at 00:40:11, dalecurtis wrote: > > On 2016/12/14 at 00:39:11, DaleCurtis wrote: > > > This isn't going to measure what you think it is since the frame may sit in the compositor for some time w/o rendering; especially when transitioning to the foreground, see http://crbug.com/659207. What you had in PS#4 was correct; RestartStreamPlayback() is going to trigger a rebuffering cycle so we'll run the transition from HAVE_NOTHING -> HAVE_ENOUGH again. > > When the flag enabled, yes, but how do we compare it with the times where the track is not enabled - the rebuffering will not happen when video becomes visible - we will only have the time for when the video is preloaded mostly, no? > > > > > Well, almost correct, you need to set your measurement marker again (or possibly only in this case) in RestartStreamPlayback(). The time when the feature is not enabled is zero :) so just always recording this value gives us an idea of the average lag time for enabling a track. With a Finch flag we can directly correlate which parts of this value are from your feature versus the general track changes
On 2016/12/14 at 01:56:58, whywhat wrote: > On 2016/12/14 at 00:40:11, dalecurtis wrote: > > On 2016/12/14 at 00:39:11, DaleCurtis wrote: > > > This isn't going to measure what you think it is since the frame may sit in the compositor for some time w/o rendering; especially when transitioning to the foreground, see http://crbug.com/659207. What you had in PS#4 was correct; RestartStreamPlayback() is going to trigger a rebuffering cycle so we'll run the transition from HAVE_NOTHING -> HAVE_ENOUGH again. > > When the flag enabled, yes, but how do we compare it with the times where the track is not enabled - the rebuffering will not happen when video becomes visible - we will only have the time for when the video is preloaded mostly, no? > > > > > Well, almost correct, you need to set your measurement marker again (or possibly only in this case) in RestartStreamPlayback(). Actually even with the flag enabled, preroll as in PS4 never happens to me in my testing - we usually always have enough data.
Changed to PS4 but resetting the time in RestartStreamPlayback
Tracking the time between being shown and the first frame being composited
PTAL at another approach (which works with both flag enabled and disabled). It's rather rough and I suspect might be inefficient in a sense that a callback is called for each frame composited and it causes two locks and two thread jumps (from cc to media to main). Perhaps, it's better to pass the visible state along with the timestamp all the way to the VFC that would update the starting timestamp and record the time delta in PutCurrentFrame?
Sorry, this is too invasive. Please stick with one of the approaches we've discussed. Either: - In RendererImpl, Start ElapsedTimer in RestartXXX() and record in OnBuffering(HAVE_ENOUGH). - In WMPI, set current time flag in VFC, record time on next painted frame.
On 2016/12/14 at 19:35:59, dalecurtis wrote: > Sorry, this is too invasive. I guessed so :) > Please stick with one of the approaches we've discussed. Either: > - In RendererImpl, Start ElapsedTimer in RestartXXX() and record in OnBuffering(HAVE_ENOUGH). So this won't work for the following reasons: 1. RestartXXX doesn't get called without the feature enabled - we can't compare the metric for experiments; same for HAVE_NOTHING -> HAVE_ENOUGH cycle; it doesn't happen if we don't stop video decoder when in the background - we will not get a baseline 2. I think media tracks defer HAVE_NOTHING for smooth playback - HAVE_NOTHING to HAVE_ENOUGH doesn't happen in my testing, see https://cs.chromium.org/chromium/src/media/renderers/renderer_impl.cc?rcl=0&l... -- I tried adding recording the histogram there but then HAVE_ENOUGH happens too soon and the logic is again media track specific... > - In WMPI, set current time flag in VFC, By VFC you mean VideoFrameCompositor, right? So basically what I did in the last patch but inversed? 1. WMPI calls PipelineImpl calls RendererImpl calls VideoRendererImpl calls VideoFrameCompositor with the timestamp of WMPI::OnShown 2. VFC::PutCurrentFrame checks if the flag is set and records the UMA with the current timestamp, unsets the flag. Note that PutCurrentFrame is still not after the frame has actually been painted but rather queued to the compositor - it could be the decoding will stall the compositor so it will paint the frame later and our metric won't catch it fully; however I've no idea atm how I would incorporate that into the metric without making the change even more invasive -- I just hope that if we don't regress on this time interval too much, we don't regress too much on the full time interval the user will perceive. > record time on next painted frame. Thanks for coping with me! :)
On 2016/12/14 at 20:22:47, avayvod wrote: > On 2016/12/14 at 19:35:59, dalecurtis wrote: > > Sorry, this is too invasive. > > I guessed so :) > > > Please stick with one of the approaches we've discussed. Either: > > - In RendererImpl, Start ElapsedTimer in RestartXXX() and record in OnBuffering(HAVE_ENOUGH). > > So this won't work for the following reasons: > 1. RestartXXX doesn't get called without the feature enabled - we can't compare the metric for experiments; same for HAVE_NOTHING -> HAVE_ENOUGH cycle; it doesn't happen if we don't stop video decoder when in the background - we will not get a baseline Don't have time to reply to rest, but this isn't true, we know it won't be called, because the value is zero in the non-experiment case. So any value above zero is the average it takes for a user to see video again. > 2. I think media tracks defer HAVE_NOTHING for smooth playback - HAVE_NOTHING to HAVE_ENOUGH doesn't happen in my testing, see https://cs.chromium.org/chromium/src/media/renderers/renderer_impl.cc?rcl=0&l... -- I tried adding recording the histogram there but then HAVE_ENOUGH happens too soon and the logic is again media track specific... > > > - In WMPI, set current time flag in VFC, > > By VFC you mean VideoFrameCompositor, right? So basically what I did in the last patch but inversed? > 1. WMPI calls PipelineImpl calls RendererImpl calls VideoRendererImpl calls VideoFrameCompositor with the timestamp of WMPI::OnShown > 2. VFC::PutCurrentFrame checks if the flag is set and records the UMA with the current timestamp, unsets the flag. > > Note that PutCurrentFrame is still not after the frame has actually been painted but rather queued to the compositor - it could be the decoding will stall the compositor so it will paint the frame later and our metric won't catch it fully; however I've no idea atm how I would incorporate that into the metric without making the change even more invasive -- I just hope that if we don't regress on this time interval too much, we don't regress too much on the full time interval the user will perceive. > > > record time on next painted frame. > > Thanks for coping with me! :)
Reverted to RestartStreamPlayback
avayvod@chromium.org changed reviewers: + xhwang@chromium.org
PTAL +Xiaohan since Dale's OOO I don't think HAVE_ENOUGH is late enough to catch problems with decoding late. I tried logging the times with a YouTube video (https://www.youtube.com/watch?v=l42U5Cwn1Y0) and with a downloadable video (http://avayvod.github.io/media/single-video.html). For the latter I can clearly see a few seconds of delay before the video frame updates after being shown, however, the data is there long before that and the timing doesn't catch it. I've uploaded a screen recording of that (shared for chromium.org accounts): https://drive.google.com/open?id=0BwikUGjiZQ-0TkVkVEpyUHZ5aUk One can see that even though the delay between restarting the stream and getting enough data for YouTube is bigger and close to 0.1 s while the delay for the Sintel video is at least a half of that, the Sintel video seems stalled for a couple of seconds before resuming playback and the YouTube video is smooth. The previous patchset showed delay time much closer to what I see :)
On 2016/12/16 at 00:28:15, avayvod wrote: > PTAL > > +Xiaohan since Dale's OOO > > I don't think HAVE_ENOUGH is late enough to catch problems with decoding late. I tried logging the times with a YouTube video (https://www.youtube.com/watch?v=l42U5Cwn1Y0) and with a downloadable video (http://avayvod.github.io/media/single-video.html). For the latter I can clearly see a few seconds of delay before the video frame updates after being shown, however, the data is there long before that and the timing doesn't catch it. > > I've uploaded a screen recording of that (shared for chromium.org accounts): https://drive.google.com/open?id=0BwikUGjiZQ-0TkVkVEpyUHZ5aUk > > One can see that even though the delay between restarting the stream and getting enough data for YouTube is bigger and close to 0.1 s while the delay for the Sintel video is at least a half of that, the Sintel video seems stalled for a couple of seconds before resuming playback and the YouTube video is smooth. > > The previous patchset showed delay time much closer to what I see :) Something does seem weird there. HAVE_ENOUGH is delivered after we issue PaintSingleFrame() so it's odd that there is no new frame in the Sintel case before the screen updated. This might be a result of the compositor bug xhwang@ filed.
On 2016/12/14 at 20:22:47, avayvod wrote: > On 2016/12/14 at 19:35:59, dalecurtis wrote: > > Sorry, this is too invasive. > > I guessed so :) > > > Please stick with one of the approaches we've discussed. Either: > > - In RendererImpl, Start ElapsedTimer in RestartXXX() and record in OnBuffering(HAVE_ENOUGH). > > So this won't work for the following reasons: > 1. RestartXXX doesn't get called without the feature enabled - we can't compare the metric for experiments; same for HAVE_NOTHING -> HAVE_ENOUGH cycle; it doesn't happen if we don't stop video decoder when in the background - we will not get a baseline > 2. I think media tracks defer HAVE_NOTHING for smooth playback - HAVE_NOTHING to HAVE_ENOUGH doesn't happen in my testing, see https://cs.chromium.org/chromium/src/media/renderers/renderer_impl.cc?rcl=0&l... -- I tried adding recording the histogram there but then HAVE_ENOUGH happens too soon and the logic is again media track specific... > > > - In WMPI, set current time flag in VFC, > > By VFC you mean VideoFrameCompositor, right? So basically what I did in the last patch but inversed? > 1. WMPI calls PipelineImpl calls RendererImpl calls VideoRendererImpl calls VideoFrameCompositor with the timestamp of WMPI::OnShown > 2. VFC::PutCurrentFrame checks if the flag is set and records the UMA with the current timestamp, unsets the flag. > Not quite. There's no reason to touch PipelineImpl at all. WMPI knows if the playback is suspended and when it will be resumed. So it can just talk to VFC directly without needing to go through the Pipeline or RendererImpl. VFC::PutCurrentFrame() is called after compositor is done compositing, so it's not quite what you want. What you want instead is the first call to GetCurrentFrame(), though even that is probably excessive. Just recording the delta when ProcessNewFrame() is fired is probably sufficient. > Note that PutCurrentFrame is still not after the frame has actually been painted but rather queued to the compositor - it could be the decoding will stall the compositor so it will paint the frame later and our metric won't catch it fully; however I've no idea atm how I would incorporate that into the metric without making the change even more invasive -- I just hope that if we don't regress on this time interval too much, we don't regress too much on the full time interval the user will perceive. > > > record time on next painted frame. > > Thanks for coping with me! :)
Accessing VFC directly from WMPI
Dale, WDYT? I kind of missed the fact that VFC is accessible directly from WMPI in #ps8 :) This seems to give higher numbers on Linux when the optimization is on although still is recorded way before I actually see updated frames on screen.
lgtm % some naming and comment nits. Your histogram comment is the most accurate and how I would change the method names and UMA names. I.e. use foregrounded instead of shown. https://codereview.chromium.org/2552493002/diff/170001/media/blink/video_fram... File media/blink/video_frame_compositor.h (right): https://codereview.chromium.org/2552493002/diff/170001/media/blink/video_fram... media/blink/video_frame_compositor.h:106: // Called when the video becomes visible with the timestamp. visible is a bit confusing in this context; instead you should write this in terms of a background to foreground transition. Maybe something like SetForegroundTime(). Per our typical lexicon Timestamp is only used for TimeDelta's, so this should just be XXXTime().
Thanks for the review. A couple of thoughts on Shown vs Foreground. https://codereview.chromium.org/2552493002/diff/170001/media/blink/video_fram... File media/blink/video_frame_compositor.h (right): https://codereview.chromium.org/2552493002/diff/170001/media/blink/video_fram... media/blink/video_frame_compositor.h:106: // Called when the video becomes visible with the timestamp. On 2017/01/05 at 22:38:43, DaleCurtis wrote: > visible is a bit confusing in this context; instead you should write this in terms of a background to foreground transition. Maybe something like SetForegroundTime(). Per our typical lexicon Timestamp is only used for TimeDelta's, so this should just be XXXTime(). s/Timestamp/Time sgtm Re: s/shown/foreground: 1) there's another "background" term used here w.r.t. the background thread being used for rendering IIUC -- I already used |is_background_rendering_| in some patchset here incorrectly because of the term reuse. 2) I hope in the future the term shown will suit these transitions better as we'll reuse the media remoting work that detects when the media elements is in the viewport and not (so visible/shown == tab is in foreground _and_ the element is in the viewport) Therefore I used Shown/Hidden to be consistent with OnHidden/OnShown in WMPI and not to be confused with background render in VFC.
The CQ bit was checked by avayvod@chromium.org to run a CQ dry run
Dry run: CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
https://codereview.chromium.org/2552493002/diff/170001/media/blink/video_fram... File media/blink/video_frame_compositor.h (right): https://codereview.chromium.org/2552493002/diff/170001/media/blink/video_fram... media/blink/video_frame_compositor.h:106: // Called when the video becomes visible with the timestamp. On 2017/01/05 at 23:15:44, whywhat wrote: > On 2017/01/05 at 22:38:43, DaleCurtis wrote: > > visible is a bit confusing in this context; instead you should write this in terms of a background to foreground transition. Maybe something like SetForegroundTime(). Per our typical lexicon Timestamp is only used for TimeDelta's, so this should just be XXXTime(). > > s/Timestamp/Time sgtm > > Re: s/shown/foreground: > 1) there's another "background" term used here w.r.t. the background thread being used for rendering IIUC -- I already used |is_background_rendering_| in some patchset here incorrectly because of the term reuse. > 2) I hope in the future the term shown will suit these transitions better as we'll reuse the media remoting work that detects when the media elements is in the viewport and not (so visible/shown == tab is in foreground _and_ the element is in the viewport) > > Therefore I used Shown/Hidden to be consistent with OnHidden/OnShown in WMPI and not to be confused with background render in VFC. Background rendering and SetForegroundTime() would be fine, they are both effectively triggered by the inverse of the other.
The CQ bit was unchecked by avayvod@chromium.org
Shown->Foreground
The CQ bit was checked by avayvod@chromium.org
The patchset sent to the CQ was uploaded after l-g-t-m from isherman@chromium.org, dalecurtis@chromium.org Link to the patchset: https://codereview.chromium.org/2552493002/#ps210001 (title: "Shown->Foreground")
CQ is trying da patch. Follow status at https://chromium-cq-status.appspot.com/v2/patch-status/codereview.chromium.or...
CQ is committing da patch.
Bot data: {"patchset_id": 210001, "attempt_start_ts": 1483664816102050,
"parent_rev": "f8e75174463273c99caae55d988ebcf935582f5c", "commit_rev":
"ac607d65a37cba23db6690580fd78068f9b9fde0"}
Message was sent while issue was closed.
Description was changed from
==========
[Media] Record time it takes to start rendering audio and video
BUG=670150
TEST=manually with and without the background video track optimization flag.
Record time between the play or seek and when the player has enough
data for both audio and video renderers.
==========
to
==========
[Media] Record time it takes to start rendering audio and video
BUG=670150
TEST=manually with and without the background video track optimization flag.
Record time between the play or seek and when the player has enough
data for both audio and video renderers.
Review-Url: https://codereview.chromium.org/2552493002
Cr-Commit-Position: refs/heads/master@{#441860}
Committed:
https://chromium.googlesource.com/chromium/src/+/ac607d65a37cba23db6690580fd7...
==========
Message was sent while issue was closed.
Committed patchset #12 (id:210001) as https://chromium.googlesource.com/chromium/src/+/ac607d65a37cba23db6690580fd7... |
||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||||
