Video freeze after exiting sleep mode on Mac |
||||||||||
Issue descriptionVersion: M51 OS: Mac What steps will reproduce the problem? (1) Play any HTML5 video in Chrome on Macbook. (2) Close the lid. (3) Wait for a few minutes (so that the device enters sleep mode). (4) Open the lid (and login if necessary). What is the expected output? Both audio and video resume to play immediately. What do you see instead? Audio resumes immediately. Caption is working fine. But video keeps freezing. The screen recording is at: https://youtu.be/R493r1NdnWQ Please use labels and text to provide additional information. 1. Video sometimes resume playback after a while. The timing varies from time to time. In the worst case, it doesn't resume playback until the end of the video. In the best case, it resumes playback after a few seconds. 2. This also happens for encrypted content, e.g. on shaka demo player. 3. This is similar to issue 605828. But in that case, even audio doesn't resume either.
,
Jun 15 2016
If audio is playing it shouldn't be suspend/resume related. Have you checked to see if we're getting compositor callbacks to VideoFrameCompositor?
,
Jun 15 2016
Does it only happen with h264 or just vp9?
,
Jun 15 2016
BTW, this is the page I was testing on: http://www.html5rocks.com/en/tutorials/video/basics/
,
Jun 15 2016
I don't have a mac debug build working right now so I haven't checked anything. The test video above is vp8. The shaka demo player is using h264. I don't really feel this is codec related.
,
Jun 15 2016
I lied; I actually have a debug build chrome sitting on my Mac. I added logs in VideoFrameCompositor. We actually called BackgroundRender() after we exit sleep mode. ProcessNewFrame() and CallRender() are called as normal after it. [16297:18695:0615/160541:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame [16297:18695:0615/160541:VERBOSE1:video_frame_compositor.cc(217)] CallRender [16297:18695:0615/160541:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame [16297:18695:0615/160541:VERBOSE1:video_frame_compositor.cc(217)] CallRender [16297:18695:0615/160541:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame [16297:18695:0615/160541:VERBOSE1:video_frame_compositor.cc(217)] CallRender [16297:18695:0615/160541:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame [16297:18695:0615/160541:VERBOSE1:video_frame_compositor.cc(217)] CallRender [16297:18695:0615/160541:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame [16297:18695:0615/160541:VERBOSE1:video_frame_compositor.cc(217)] CallRender [16297:18695:0615/160541:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame ----------------- sleeping, no logs here, just a separate line --------------- [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(205)] BackgroundRender [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(217)] CallRender [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(217)] CallRender [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(217)] CallRender [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(217)] CallRender [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(217)] CallRender [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(217)] CallRender [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(217)] CallRender [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(217)] CallRender [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame [16297:18695:0615/161739:VERBOSE1:video_frame_compositor.cc(217)] CallRender
,
Jun 15 2016
Seems like a compositing issue then. We're telling the compositor that we have a new frame, but it's not doing anything with it. +ccamereon, compositing folk. Just to be sure, is ProcessNewFrame() returning true? I.e. we have a new frame for painting? This should percolate up to a call in VideoFrameProviderClientImpl::DidReceiveFrame().
,
Jun 16 2016
ProcessNewFrame() starts to return false after exiting sleep mode. In this case VideoFrameProviderClientImpl::DidReceiveFrame() is not called. ProcessNewFrame() always returns the same frame. This time I didn't see BackgroundRender() though around the waking point. [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame0x7f96041fb920 [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(203)] ProcessNewFrame: true [19005:19719:0615/164954:ERROR:video_frame_provider_client_impl.cc(148)] DidReceiveFrame [19005:19719:0615/164954:ERROR:video_frame_provider_client_impl.cc(152)] DidReceiveFrame [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(220)] CallRender [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame0x7f96041fb920 [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(194)] ProcessNewFrame: false [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(220)] CallRender [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame0x7f960466c1e0 [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(203)] ProcessNewFrame: true [19005:19719:0615/164954:ERROR:video_frame_provider_client_impl.cc(148)] DidReceiveFrame [19005:19719:0615/164954:ERROR:video_frame_provider_client_impl.cc(152)] DidReceiveFrame [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(220)] CallRender [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame0x7f960466c1e0 [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(194)] ProcessNewFrame: false [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(220)] CallRender [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame0x7f960466c1e0 [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(194)] ProcessNewFrame: false [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(220)] CallRender [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame0x7f9604594f70 [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(203)] ProcessNewFrame: true [19005:19719:0615/164954:ERROR:video_frame_provider_client_impl.cc(148)] DidReceiveFrame [19005:19719:0615/164954:ERROR:video_frame_provider_client_impl.cc(152)] DidReceiveFrame [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(220)] CallRender [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame0x7f9604594f70 [19005:19719:0615/164954:VERBOSE1:video_frame_compositor.cc(194)] ProcessNewFrame: false ------------------------------------------------------------------- [19005:19719:0615/165701:VERBOSE1:video_frame_compositor.cc(220)] CallRender [19005:19719:0615/165701:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame0x7f96041f7b60 [19005:19719:0615/165701:VERBOSE1:video_frame_compositor.cc(203)] ProcessNewFrame: true [19005:19719:0615/165701:ERROR:video_frame_provider_client_impl.cc(148)] DidReceiveFrame [19005:19719:0615/165701:ERROR:video_frame_provider_client_impl.cc(152)] DidReceiveFrame [19005:19719:0615/165701:VERBOSE1:video_frame_compositor.cc(220)] CallRender [19005:19719:0615/165701:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame0x7f96041fb420 [19005:19719:0615/165701:VERBOSE1:video_frame_compositor.cc(203)] ProcessNewFrame: true [19005:19719:0615/165701:ERROR:video_frame_provider_client_impl.cc(148)] DidReceiveFrame [19005:19719:0615/165701:ERROR:video_frame_provider_client_impl.cc(152)] DidReceiveFrame [19005:19719:0615/165701:VERBOSE1:video_frame_compositor.cc(220)] CallRender [19005:19719:0615/165701:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame0x7f96041fb420 [19005:19719:0615/165701:VERBOSE1:video_frame_compositor.cc(194)] ProcessNewFrame: false [19005:19719:0615/165701:VERBOSE1:video_frame_compositor.cc(220)] CallRender [19005:19719:0615/165701:VERBOSE1:video_frame_compositor.cc(190)] ProcessNewFrame0x7f96041fb420 [19005:19719:0615/165701:VERBOSE1:video_frame_compositor.cc(194)] ProcessNewFrame: false (then this pattern repeats forever)
,
Jun 16 2016
It's not compositing then. I suspect the time jump is messing with our audio clock and we're overflowing or pinning to an old time somewhere. The next place to look is VideoRendererAlgorithm + VideoRendererImpl. We'll want to print the delta from TimeTicks::Now() and the the times returned by the WallClockTimeCB in relation to CurrentMediaTime() and the frames we have in the queue. I'd turn on all the DVLOG(2)'s in VideoRendererAlgorithm. I can help take a look at this tomorrow.
,
Jun 16 2016
-compositing.
,
Jun 16 2016
I won't have time to look at this today or tomorrow. Assign to dalecurtis@ for now for investigation.
,
Jun 16 2016
,
Jun 16 2016
,
Jun 16 2016
Thanks for the fix! I verified that this also fixes issue 605828.
,
Jun 17 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/e3fb958aa538c5b146afea7f9df498a579d3e5a4 commit e3fb958aa538c5b146afea7f9df498a579d3e5a4 Author: dalecurtis <dalecurtis@chromium.org> Date: Fri Jun 17 18:03:16 2016 Freeze media time and audio rendering when the system suspends. Allows us to avoid unexpected differences between what the audio renderer and video renderer think the current time is. Causes the wall clock time calculations to return false for "is time moving." With this information the video renderer (and other callers) can accurately act upon frozen moments and not expire frames due to a difference of opinion on what the current time is (audio only updates its base every Render() call). BUG= 620478 TEST=new unittests Review-Url: https://codereview.chromium.org/2072843002 Cr-Commit-Position: refs/heads/master@{#400454} [modify] https://crrev.com/e3fb958aa538c5b146afea7f9df498a579d3e5a4/media/renderers/audio_renderer_impl.cc [modify] https://crrev.com/e3fb958aa538c5b146afea7f9df498a579d3e5a4/media/renderers/audio_renderer_impl.h [modify] https://crrev.com/e3fb958aa538c5b146afea7f9df498a579d3e5a4/media/renderers/audio_renderer_impl_unittest.cc
,
Jun 20 2016
Thanks for the fix. Do you want to merge the fix to M52?
,
Jun 20 2016
Issue 605828 has been merged into this issue.
,
Jun 20 2016
Yup, just wanted to make sure it soaked over the weekend without issue.
,
Jun 20 2016
Your change meets the bar and is auto-approved for M52 (branch: 2743)
,
Jun 20 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/190fbd2f4ce6ff7617a4b60b22723dee6b5ec4ce commit 190fbd2f4ce6ff7617a4b60b22723dee6b5ec4ce Author: Dale Curtis <dalecurtis@chromium.org> Date: Mon Jun 20 23:04:55 2016 Merge M52: "Freeze media time and audio rendering when the system suspends." Allows us to avoid unexpected differences between what the audio renderer and video renderer think the current time is. Causes the wall clock time calculations to return false for "is time moving." With this information the video renderer (and other callers) can accurately act upon frozen moments and not expire frames due to a difference of opinion on what the current time is (audio only updates its base every Render() call). BUG= 620478 TEST=new unittests Review-Url: https://codereview.chromium.org/2072843002 Cr-Commit-Position: refs/heads/master@{#400454} (cherry picked from commit e3fb958aa538c5b146afea7f9df498a579d3e5a4) Review URL: https://codereview.chromium.org/2089503002 . Cr-Commit-Position: refs/branch-heads/2743@{#419} Cr-Branched-From: 2b3ae3b8090361f8af5a611712fc1a5ab2de53cb-refs/heads/master@{#394939} [modify] https://crrev.com/190fbd2f4ce6ff7617a4b60b22723dee6b5ec4ce/media/renderers/audio_renderer_impl.cc [modify] https://crrev.com/190fbd2f4ce6ff7617a4b60b22723dee6b5ec4ce/media/renderers/audio_renderer_impl.h [modify] https://crrev.com/190fbd2f4ce6ff7617a4b60b22723dee6b5ec4ce/media/renderers/audio_renderer_impl_unittest.cc
,
Jun 21 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/2e3f39cf2b1486771f9296ecab2551bae06a5b19 commit 2e3f39cf2b1486771f9296ecab2551bae06a5b19 Author: Dale Curtis <dalecurtis@chromium.org> Date: Tue Jun 21 00:55:28 2016 Fix broken merge for M52 branch. New code missed non-merged refactoring. BUG=621737, 620478 (cherry picked from commit ce790c6362b892134ca51a76cf7a7f365f627b47) Review URL: https://codereview.chromium.org/2085843002 . Cr-Commit-Position: refs/branch-heads/2743@{#422} Cr-Branched-From: 2b3ae3b8090361f8af5a611712fc1a5ab2de53cb-refs/heads/master@{#394939} [modify] https://crrev.com/2e3f39cf2b1486771f9296ecab2551bae06a5b19/media/renderers/audio_renderer_impl_unittest.cc
,
Jun 22 2016
We may want to merge to M51 if possible given the long cycle and partner impact. WDYT xhwang? Please mark it if so.
,
Jun 22 2016
IMHO I don't feel this issue is critical enough for a stable channel merge. After all it only affects one particular use case (keep watching movie after exiting sleep mode) and there's a workaround for it (user can resume playback by seeking to any point). |
||||||||||
►
Sign in to add a comment |
||||||||||
Comment 1 by xhw...@chromium.org
, Jun 15 2016