does it only repro when the playback is played > 1 hour? or is it repro on any minute of a long video? 

Anton, do you have everything set up to look at this?

> does it only repro when the playback is played > 1 hour? or is it repro on any minute of a long video? 

I mean if you select a long video (duration > 1 hour) and play it, the playback may stop at around 10 minutes.

Can you repro with a plain video tag? YouTube may be doing something in JS.

What happens if you listen to the same video on Chrome or Safari iOS?

> Can you repro with a plain video tag? YouTube may be doing something in JS.

Tried another two sites and can't repro the bug. Could be YT-only.

> What happens if you listen to the same video on Chrome or Safari iOS?

I tried and found:
* Safari does not support background video playback.
* Cannot repro with YT on Chrome Desktop.

Safari iOS has background playback, you have to resume from the system media centre. I've been playing a YouTube video for more than 10 minutes so it seems to work.

Did the same on Chrome iOS. I have a video running for ~20 minutes.

Some additional testing on Nexus 5 with Android L.

YouTube pauses both with and without Spitzer. With Spitzer there's nothing showing up in media-internals (the player is in kPlaying state). The media element ready state goes from have enough data to have current data. currentTime stops updating.

Other MSE videos seem to pause too, even faster: go to http://shaka-player-demo.appspot.com/demo/, allow device identification, select Sintel 4k video and play it - it stops before 3 minutes pass for me.

mp4 videos like https://vimeo.com/34665210 seem to work past 10 minutes fine.

Audio like https://soundcloud.com/theguardianlongread is not affected as well (do they use Web Audio? I failed to find and <audio> element on the page).

Seems like the issue is Android and adaptive video specific, not YouTube specific though. Could it be some form of  Issue 489789  ?

Shouldn't be in this case since that signal is now plumbed for Android. It's possible the render thread is getting starved and thus can't append any more data within MSE.

avayvod@, do you see the same behaviour if you run chrome without your feature and disable media suspend? I might have a look myself today and will let you know if I find something.

I have a similar issue if I disable media suspend and get background playback without your feature Anton. As others, it did cut just before 10 minutes.

The 10 minutes mark make me wonder if this could be related to script throttling.

Maybe Ross or Sami know something then? :)

Timer throttling kicks in after 5 minutes, and shouldn't affect tabs playing audio.

If you want to try turning it off, make this function return false: https://cs.chromium.org/chromium/src/chrome/renderer/chrome_content_renderer_client.cc?rcl=0&l=1059

I've been investigating with `adb lolcat` and nothing interesting there. Giving it a shot with timer throttling disabled now. I love Nian cat videos! :)

It seems that disallowing timer suspension has no effect :( Looking at network traffic with console now.

The network timeline is interesting: YT stops hitting the network at some point. Whether they do it on purpose or Chrome prevents them for doing it, there is clearly something odd. Note that the video I used is 10 hours long so there is no way it stopped downloading because it was buffered.

Deleted: yt-background-network-timeline.png 11.0 KB

	yt-background-network-timeline.png 11.0 KB View Download

disable-media-suspend and timer throttling off, Shaka player demo still pauses after ~2 minutes

Deleted: Screenshot from 2016-08-18 11:53:45.png 43.8 KB

	Screenshot from 2016-08-18 11:53:45.png 43.8 KB View Download

Pauses the same way in 53 Beta as well, with --disable-media-suspend flag.

Deleted: Screenshot from 2016-08-18 12:02:24.png 69.6 KB

	Screenshot from 2016-08-18 12:02:24.png 69.6 KB View Download

+wolenetz@, any idea why this could happen?

It'll be a bit tricky since the trace buffers are likely to get full, but if you start adb_profile_chrome --trace-scheduler a bit before you think it's going to hang, the trace might tell us something.

Here's a trace I've captured with the Shaka Player Demo, tracing from the start as continuous, the playback stopped at about 2 minutes past.

Deleted: traceEvents.html 2.3 MB

traceEvents.html 2.3 MB View Download

Hmm, there's just one renderer in that trace with the title "About Version". Is that the Shaka page? In any case, it doesn't seem to be doing much for the whole duration so it's probably something else.

Could it be that Android killed the backgrounded renderer? Or maybe the renderer is stuck in an infinite loop and we're not getting trace data out of it because of that? adb_gdb could be used to check the latter.

Ok, how about this trace? https://drive.google.com/a/google.com/file/d/0B44CKnXso82GZFlxUFlrNHk0Qm8/view?usp=sharing

Yeah, that looks better.

It seems like things just stop at the 130s mark. The renderer main thread is happily executing stuff after that so this doesn't look like a scheduling bug. Could the network connection be somehow dying? Nothing obvious jumped out from the trace but the net log is the first thing that stops.

Got a log from chrome://net-internals

Deleted: net-internals-log.json 9.3 MB

net-internals-log.json 9.3 MB View Download

@#21: I've no idea other than the avenues searched already. I haven't looked into the traces nor net-internals log.

Emailed chrome-network-stack for help.

Looking at the trace from https://bugs.chromium.org/p/chromium/issues/detail?id=637327#c26, I wonder:
1) VpxOffloadThread stops doing stuff around 130.2 seconds. A repro with extra logging enabled (and perhaps added to vpx_video_decoder, if missing) might help understand. cmdline args like the following, used on a debug build, may help produce an adb log which might investigate if media paths are responsible for the bg playback stall:
--v=3 --vmodule=MediaSource*=3,HTMLMediaSource*=3,SourceBuffer*=3,HTMLMediaElement*=3,chunk*=3,source*=3,media*=3,webmed*=3,websou*=3,frame_pro*=3,webm*=3,mp4*=3,mp3*=3,box_*=3,avc*=3,aac*=3,es_*=3,track_*=3,cenc*=3,vpx*=3,audio*=3,video*=3,renderer_imp*=3,*=0 --blink-platform-log-channels=Media'

2) mlamouri@, does this issue still repro if we disable background video decode (using servolk@'s currently experimental video track {de,}select functionality)?

Another vector for investigation would be to use a simple repro page that logs to console periodically the currentTime, buffered, and readyState attributes of the <video>. It could simply be that the stall occurs due to media buffering exhaustion (perhaps something in the JS or network stack would thus be stopping the fetching).

Hm, the command line doesn't affect the amount of logging output at all.
Paul, you could reproduce on trunk by loading the shaka player demo link from https://bugs.chromium.org/p/chromium/issues/detail?id=637327#c10, selecting Sintel 4k video and playing it with a gesture. It takes about 2-3 minutes to stall.

@#33: Did you try on a debug build? Those options expose DVLOGs, which of course aren't in a release build.

@#33: Who is Paul? I don't see a Paul on cc:

@#35 s/Paul/Matt
@#34 trying the debug build

I've attached the logs. I've also modified the Shaka demo page to log the currentTime, buffered and readyState every second (hosted at https://avayvod.github.io/demo.html)

Deleted: output.txt 3.2 MB

output.txt 3.2 MB View Download

Disabling the video track helps to delay the issue - I was now able to listen for the Sintel video using my page for about twice longer. Output attached. The logging seems to keep working so JS is there.

Deleted: output.txt 28.8 MB

output.txt 28.8 MB Download

Can we try to test the following behaviour:
1. src= with H264 video (or anything hw supported)
2. src= with VP8/9 video
3. MSE with H264 video
4. MSE with VP8/9 video

My understanding is that YouTube is #4. Did we try #1-3? It think it might help narrow down the issue. WDYT?

Matt, are you able to follow up based on #c27 and #c38?
If that's indeed media buffer exhaustion, what would be a fix/workaround? Why would it exhaust in the background more than in the foreground (I assume Clank can play a Youtube video for 10 minutes without stalling when in foreground or we have a problem).

Assigning to Matt for his attention :)

This has my attention. I'm quite busy today but will try to get to this later today.

@#c40 From log in c#38, it looks indeed like buffered audio was exhausted. The last frames demuxed (during append operation by javascript) for the audio stream were:
V/chromium(12746): [VERBOSE1:source_buffer_stream.cc(389)] Append AUDIO: done. ranges_=[270.997;340.16(340.181)]

Note that the VIDEO SourceBuffer had frames appended until time 345:V/chromium(12746): [VERBOSE1:source_buffer_stream.cc(389)] Append VIDEO: done. ranges_=[275;344.958(345)]

The last frame decoded was the audio frame with timestamp 340.16. Subsequent attempts to read more audio stalled since there was nothing further buffered.

There is nothing else I see in the log from c#38 indicating *why* the app stopped appending audio and video. Is there something in the network stack which might pause background javascript network fetches after some time?

----

In the log from c#37 (which doesn't disable the video track), it appears that the video decoder is running very slow: reads from the audio demuxer stream get well ahead of reads from the video demuxer stream, for example:
14231 V/chromium(15160): [VERBOSE2:source_buffer_stream.cc(1159)] GetNextBuffer VIDEO: no pending buffer, returning status 0
14232 V/chromium(15160): [VERBOSE2:chunk_demuxer.cc(358)] CompletePendingReadIfPossible_Locked: returning kOk, type 2, dts 40.292,       pts 40.292, dur 0.041, key 0
14233 V/chromium(15160): [VERBOSE2:source_buffer_stream.cc(1154)] GetNextBuffer AUDIO
14234 V/chromium(15160): [VERBOSE2:source_buffer_stream.cc(1159)] GetNextBuffer AUDIO: no pending buffer, returning status 0
14235 V/chromium(15160): [VERBOSE2:chunk_demuxer.cc(358)] CompletePendingReadIfPossible_Locked: returning kOk, type 1, dts 69.4187,       pts 69.4187, dur 0.021333, key 1

In this case, the "coded frame eviction algorithm", which is based partly on "current media time" evicts the range including the last video frame read (timestamp 47.125) when media time (according to the clock driven by the audio clock, which isn't underflowing the decoder) is 81.06s. Subsequent appends to the video SourceBuffer do not unblock reads on the video demuxer stream since they are not adjacent to the last buffer read. 

----

Two routes I suggest for further investigation:
w.r.t. #38 log: why does app stop appending more media? network stack folks?
w.r.t. #37 log: why do we intermittently transition to HAVE_NOTHING by video_renderer_impl when background rendering (line 7727 in the log, for example)? And why do the reads from the audio and video streams diverge so much (is the s/w vpx decoder throttled when in BG)? --> dalecurtis@, any ideas here?

Assigning to dalecurtis@ for attention on the general case (#37 log). For the eventual "disable the video stream if in background" represented in #38, network stack folks might be able to help us understand why the appends to SourceBuffer stop.

We'll transition to have nothing even in background rendering if no frames have been decoded between Render() intervals. Probably resources are throttled in the background but I'm not sure. I don't know off hand what might be going wrong here, avayvod@ you'll have to do more digging.

Network stack team is not aware of any throttling taking place on Android when in the background. Will keep digging.

HLS seems to play fine (tried with https://m.vidio.com/videos/119306/playlist.m3u8).

It seems to be using MP4. Can HLS use VP9?

HLS uses a different media path on Chrome for Android than normal src= or MSE. Underneath it all, it uses the Android MediaPlayer API for playback IIUC.

Indeed, did not think about this. No need to test more I guess :)

I've made a small MSE demo with a 130Mb mp4 video (Sintel-1024) at https://project-1912052061267295165.firebaseapp.com/

I've prepared fragmented video with ffmpeg and got segment sizes from MP4Box to make the video compliant. It plays fine while in the foreground in both desktop and Android Chromes. It still stops appending data when in the background.

It appends the next chunk of the video only if the current time is greater than what's buffered or once the current time reaches the middle of the interval between the latest buffered time and the current time. It also handles the exception when the buffer is full (happened to me too soon given we should have 150Mb size cap, no?) by removing what's already played or again, waiting until half the buffer can be removed.

In both cases, it uses setTimeout to prevent appending too much. The console logs show that at some point setTimeout simply stops working. I'm trying the Chromium build with throttling disabled per #15 and with HackTimer.js (that claims to overcome the throttling by using WebWorker-based implementation of setTimer and so on).

Sami, any idea why setTimeout might stop firing even with AllowTimerSuspensionWhenProcessBackgrounded returning false on Android?

https://project-1912052061267295165.firebaseapp.com/without-set-timer.html hangs waiting for FileReader.onload to happen in Chrome Dev (crashes with memory access on Debug build).

Assigning to Sami to take a look.

I believe I see the same behavior even without playing any video or using MediaSource API. After about 30 times setTimeout stops working in the background, you can use https://project-1912052061267295165.firebaseapp.com/just-downloads.html to reproduce (each timeout is about 10s so about 5m to reproduce).

I have traced the setTimeout implementation to the task_queue_impl that's using ThrottledTimeDomain but still have no idea why the task is never run. Hope Sami has a better knowledge on how these work.

I've hardcoded throttling disabled and even HasActiveAudio to true just in case (my local patch with logging is attached for verification).

m.youtube.com demonstrated similar logs although it fetches and appends far smaller chunks with smaller timeouts -- I'm trying to make sure I'm not investigating a problem with my test site.

Raising the priority since M54 is in Beta now.

Deleted: patch.txt 12.0 KB

patch.txt 12.0 KB View Download

I tried disabling the ThrottledHelper by hardcoding virtual_time_ to be true and used a very simple page that just logs a ping in the console every 10 seconds while playing a src= mp4 video (so that HasActiveAudio is true). It still stopped after ~5 minutes (31 pings).

The page I used: https://project-1912052061267295165.firebaseapp.com/just-timeouts-with-audio.html

I think I found the issue. There's this long-forgotten code in the Chrome activity that *also* suspends timers after 5 minutes. I've got a patch to remove it since it's completely redundant with the code we have in the scheduler:

https://codereview.chromium.org/2303733002

The remaining bug is that on Android we somehow send the OnRendererBackgrounded message even if the renderer is playing audio. That doesn't seem to happen on desktop. Probably some bit of plumbing needs to be added for Android.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/31abb5e88e0dc5df1788e75d5096d3a9d4ad1e0c

commit 31abb5e88e0dc5df1788e75d5096d3a9d4ad1e0c
Author: skyostil <skyostil@chromium.org>
Date: Thu Sep 01 14:32:11 2016

android: Remove redundant code to suspend timers in the background

This patch removes the Activity-side code for suspending renderer timers
after 5 minutes in the background. This code is redundant because the
Blink scheduler also implements this timer suspension in the renderer.

BUG= 637327 , 379158 

Review-Url: https://codereview.chromium.org/2303733002
Cr-Commit-Position: refs/heads/master@{#415951}

[modify] https://crrev.com/31abb5e88e0dc5df1788e75d5096d3a9d4ad1e0c/chrome/android/java/src/org/chromium/chrome/browser/ChromeApplication.java

Thanks Sami!!!

Re #c54 Dale, would you know if OnRendererBackgrounded is intended on Android for when media is playing?

IIRC, the scheduler is not supposed to send those messages due to this code:

https://cs.chromium.org/chromium/src/content/browser/renderer_host/media/audio_renderer_host.cc?l=760

On 52+ that should be firing accurately for everything but HLS content. There's a 10 second "hysteresis" on the output device shutting down last I looked, so it shouldn't be hitting an idle state.

I'd trace the code from there and make sure the scheduler is actually obeying the result of the notification.

Oh actually, maybe there's nothing that needs to be done here. I think this may be WAI -- or at least WAI from a media perspective. If the scheduler skips sending this message we'll leave video+audio playing in the background which is not what we want by default.

skyostil@ do you mean the backgrounded message is continuously sent or just sent once on background? We expect it to be sent once and suspend media initially based on it.

The OnRendererBackgrounded message is sent once when going to the home screen, causing the scheduler to suspend timers after 5 minutes. It sounds we should instead not send the message at all if the tab is playing audio. At least that seems to happen on desktop.

So there's a related bug: https://bugs.chromium.org/p/chromium/issues/detail?id=537671 On Android, the message is sent again if the process is already backgrounded/foregrounded.

However, the main issue I think is that unlike audio, we do suspend video when going to the background initially, so there's no active audio at the time this message is sent and |should_background| is true here: https://cs.chromium.org/chromium/src/content/browser/renderer_host/render_process_host_impl.cc?rcl=0&l=2694

Seems like either we need to add "has suspended video waiting to be resumed" to HasActiveAudio definition or have an extra signal once the video is resumed.

The former would be more reliable probably because if the user resumes the video with a delay and the scripts are suspended, it might be the page won't recover and the video will not play.

I was able to play a video for 20+ minutes so far. Requesting merge for Sami's patch.

Your change meets the bar and is auto-approved for M54 (branch: 2840)

Regardless of this feature, wouldn't the same bug happen if someone was listening to some audio (like music or podcast), pauses it, backgrounds Chrome and later resumes the audio playback?

Re #64. Might be if it relies on timeouts and events to fire. I'd suspect that even MSE audio is often buffered ahead of time altogether so there's not much to do except to resume the media pipeline. MSE video (in my short experience) requires cleaning up the source buffers before appending new data and that might require timers to check when the video passed the buffered frames so you can discard them (would be nice to have a media element / media source event for that maybe?).

I actually thought the buffers were about 150Mb for videos but Chrome threw an exception to me much much earlier.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/282419b6cde6ee55cc5ead9af5824f0e20b379b3

commit 282419b6cde6ee55cc5ead9af5824f0e20b379b3
Author: Anton Vayvod <avayvod@google.com>
Date: Thu Sep 01 19:27:30 2016

android: Remove redundant code to suspend timers in the background

This patch removes the Activity-side code for suspending renderer timers
after 5 minutes in the background. This code is redundant because the
Blink scheduler also implements this timer suspension in the renderer.

BUG= 637327 , 379158 

Review-Url: https://codereview.chromium.org/2303733002
Cr-Commit-Position: refs/heads/master@{#415951}
(cherry picked from commit 31abb5e88e0dc5df1788e75d5096d3a9d4ad1e0c)

Review URL: https://codereview.chromium.org/2302593004 .

Cr-Commit-Position: refs/branch-heads/2840@{#101}
Cr-Branched-From: 1ae106dbab4bddd85132d5b75c670794311f4c57-refs/heads/master@{#414607}

[modify] https://crrev.com/282419b6cde6ee55cc5ead9af5824f0e20b379b3/chrome/android/java/src/org/chromium/chrome/browser/ChromeApplication.java

I see that OnRendererForegrounded is called already as soon as video resumes in the background. Will confirm what happens if the video/audio is not resumed in 5 minutes.

I didn't observe any issues when resuming the video from the notification after the timers suspension happens (in ~5 minutes after the video is paused in the background). I found/remembered another issue ( crbug.com/643383 ) but it probably has a different cause. Closing this one for now.

Thanks all and esp. Sami for a quick turnaround!

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/282419b6cde6ee55cc5ead9af5824f0e20b379b3

commit 282419b6cde6ee55cc5ead9af5824f0e20b379b3
Author: Anton Vayvod <avayvod@google.com>
Date: Thu Sep 01 19:27:30 2016

android: Remove redundant code to suspend timers in the background

This patch removes the Activity-side code for suspending renderer timers
after 5 minutes in the background. This code is redundant because the
Blink scheduler also implements this timer suspension in the renderer.

BUG= 637327 , 379158 

Review-Url: https://codereview.chromium.org/2303733002
Cr-Commit-Position: refs/heads/master@{#415951}
(cherry picked from commit 31abb5e88e0dc5df1788e75d5096d3a9d4ad1e0c)

Review URL: https://codereview.chromium.org/2302593004 .

Cr-Commit-Position: refs/branch-heads/2840@{#101}
Cr-Branched-From: 1ae106dbab4bddd85132d5b75c670794311f4c57-refs/heads/master@{#414607}

[modify] https://crrev.com/282419b6cde6ee55cc5ead9af5824f0e20b379b3/chrome/android/java/src/org/chromium/chrome/browser/ChromeApplication.java