1229987 - Decoders should be drained whenever a gap is encountered playing MSE content

Status: RESOLVED FIXED

(Core :: Audio/Video: Playback, defect)

Description

[Jean-Yves Avenard [:jya]]

from bug 1194624 comment 41

"We can't at this stage be 100% compliant with the MSE buffer monitoring spec due to the underlying decoders which may hold frames.

The MSE specs define the status of readyState entirely based on the buffered range.
http://w3c.github.io/media-source/index.html#buffer-monitoring

so readyState should be HAVE_CURRENT_DATA if our source buffer contained a single frame at position 0.
this is covered by the case "If HTMLMediaElement.buffered contains a TimeRange that ends at the current playback position and does not have a range covering the time immediately after the current position"

However, decoders hold frame, the WMF h264 decoder won't output anything until at least 25 frames have been input.
So the only way for us to have readyState == HAVE_CURRENT_DATA, is by having a buffered range containing at least 25 frames.

Same with HAVE_FUTURE_DATA, the spec require that we only have one single frame *buffered* past the currentTime to have readyState = HAVE_FUTURE_DATA. But on windows this will never occur until we have at least 26 frames buffered.

All this indicates that to be compliant with the spec, the buffered range must represent frames we *can* play.

The only way to achieve this is by draining the decoders when we reach any gap in the media data range. So that every single frame contained in the buffered range is playable.
Unfortunately this is something we have considered several times in the past but decided that we wouldn't do it."

To be compliant with the MSE spec, ultimately every frames reported in the buffered range must be playable, including frames located prior a data gap.

The only way to achieve this is draining the decoder upon reaching a gap or discontinuity and when resuming seeking backward automatically and dropping frames until the previous point.

The major issue here is ensuring that the data required to perform a seek backward will never get evicted and hold them or "pinned" them somehow

Comment 1

[Jean-Yves Avenard [:jya]]

Attachment: [MSE] P1. Ensure next random access point properly calculated after seek.

When seeking, the next keyframe timet would always be set to the seek time (as the next sample to be retrieved would be a keyframe). This could lead to the next key frame logic to be activated too aggressively.

Comment 2

[Jean-Yves Avenard [:jya]]

Attachment: [MSE] P1. Ensure next random access point properly calculated after seek.

When seeking, the next keyframe time would always be set to the seek time (as the next sample to be retrieved would be a keyframe). This could lead to the next key frame logic to be activated too aggressively.

refOr() executes its argument obviously, which here is a bad thing !

Comment 3

[Jean-Yves Avenard [:jya]]

Attachment: [MSE] P1. Ensure next random access point properly calculated after seek.

When seeking, the next keyframe time would always be set to the seek time (as the next sample to be retrieved would be a keyframe). This could lead to the next key frame logic to be activated too aggressively.

Jamais deux sans trois

Comment 4

[Jean-Yves Avenard [:jya]]

Attachment: P2. Drain decoder when encountering gap.

This allows for all buffered frames to be playable.

Comment 5

[Jean-Yves Avenard [:jya]]

Attachment: P3. Update mochitests and add new one verifying behavior.

Comment 6

[Jean-Yves Avenard [:jya]]

Attachment: P3. Update mochitests and add new one verifying behavior.

Comment 7

[Jean-Yves Avenard [:jya]]

Comment on attachment 8696748 [details] [diff] [review]
P3. Update mochitests and add new one verifying behavior.

change waiting time value to be more explicit.

Interestingly, when there's an audio stream currentTime is always constanst: that is buffered.end(buffered.length-1) - 1/30

while if it's video only, it's buffered.end(buffered.length-1) - 1/30 +- 40ms

Comment 8

[Jean-Yves Avenard [:jya]]

try run:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=57009f3e6a2d

I'll submit a P4 which is a MDSM change that makes it behave with WAITING_FOR_DATA the same was  as EOS does: stop pre-roll and force displaying the frame.

Comment 9

[Jean-Yves Avenard [:jya]]

Attachment: P4. Stop pre-rolling when encountering WAITING_FOR_DATA.

This allows to start displaying frames even when we have less than 5 frames.

Comment 10

[Jean-Yves Avenard [:jya]]

Attachment: P5. Update mochitest to use only 3 frames.

Comment 11

[Jean-Yves Avenard [:jya]]

try run with P4 and P5:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=8b11f2e04bd0

Comment 12

[Jean-Yves Avenard [:jya]]

Comment on attachment 8696961 [details] [diff] [review]
P5. Update mochitest to use only 3 frames.

on win7 try run, the currentTime varies to greatly to be meaningfull when you have only 3 frames. so no point testing it

Comment 13

[Jean-Yves Avenard [:jya]]

Attachment: P3. Update mochitests and add new one verifying behavior.

Comment 14

[Jean-Yves Avenard [:jya]]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=0de8d00d29d5

All green even with the now re-enabled win7 tests.

Comment 15

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8696747 [details] [diff] [review]
P2. Drain decoder when encountering gap.

Review of attachment 8696747 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/media/MediaFormatReader.cpp
@@ +1046,5 @@
>        }
>        while (decoder.mOutput.Length()) {
>          RefPtr<MediaData> output = decoder.mOutput[0];
>          decoder.mOutput.RemoveElementAt(0);
>          decoder.mSizeOfQueue -= 1;

Just as an aside, can you use decoder.mOutput.size() instead of maintaining decoder.mSizeOfQueue?

@@ +1066,5 @@
> +    }
> +  }
> +  if (decoder.HasPromise() && decoder.mOutput.IsEmpty()) {
> +    if (decoder.mDrainComplete) {
> +      bool wasdraining = decoder.mDraining;

Nit: wasDraining

Comment 16

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8697157 [details] [diff] [review]
P3. Update mochitests and add new one verifying behavior.

Review of attachment 8697157 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/media/mediasource/test/test_DrainOnMissingData_mp4.html
@@ +27,5 @@
> +      info("Invoking play()");
> +      var promises = [];
> +      promises.push(once(el, 'playing'));
> +      el.play();
> +      return Promise.all(promises);

Can't you just "return once(el, 'playing')" here instead of creating an array of 1 element and calling Promises.all() on it?

Comment 17

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8696960 [details] [diff] [review]
P4. Stop pre-rolling when encountering WAITING_FOR_DATA.

Review of attachment 8696960 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/media/MediaDecoderStateMachine.cpp
@@ +782,5 @@
>               [self] (WaitForDataRejectValue aRejection) -> void {
>                 self->WaitRequestRef(aRejection.mType).Complete();
>               }));
>  
> +    if (isAudio) {

You need a comment explaining *why* we're doing this.

Comment 18

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/42ca05d8546d
https://hg.mozilla.org/integration/mozilla-inbound/rev/c8f4e1eaf884
https://hg.mozilla.org/integration/mozilla-inbound/rev/37003d495f20
https://hg.mozilla.org/integration/mozilla-inbound/rev/707a87454058

Comment 19

[Phil Ringnalda (:philor)]

Turns out that a relatively slow day when one person is sheriffing for 17 hours is not the time to slip in a patch that causes intermittent failures. Backed out in https://hg.mozilla.org/integration/mozilla-inbound/rev/672a8b656e19 for ASan e10s timeouts in test_playback.html, https://treeherder.mozilla.org/logviewer.html#?job_id=18481272&repo=mozilla-inbound, Mac timeouts in test_BufferingWait_mp4.html, https://treeherder.mozilla.org/logviewer.html#?job_id=18482084&repo=mozilla-inbound, and Win8 failures in test_WaitingToEndedTransition_mp4.html, https://treeherder.mozilla.org/logviewer.html#?job_id=18481386&repo=mozilla-inbound

Comment 20

[Jean-Yves Avenard [:jya]]

All green try was posted above. 

there can't be any relation to the timeout in test_playback.html as all changes are limited to MSE

Comment 21

[Phil Ringnalda (:philor)]

Yeah, given the frequency of the Mac and Win8 failures while I was retriggering, I wouldn't have expected you to see them on try - they're both probably around 5%, an awkward rate that's too much when you are looking at a day worth of m-i runs, but is hard to hit without extreme triggering on a try push.

Since I'm not burdened with even the knowledge of what MSE *is*, all I know about test_playback.html is what I saw: https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=5d377d84fbc0b4d3e08a614ad9db7bd2b86ae82f&tochange=707a87454058&fromchange=b4a141cbb454&selectedJob=18481272 had 6 instances in 77 runs on your push, and none in 51 on the push below, but I'm happy to try another 49 on that push to make it an even hundred.

Comment 22

[Jean-Yves Avenard [:jya]]

I believe that I've found the cause.
Asan builds are particularly slow, it may happen that NotifyDataArrived was being called after we had entered mDemuxEOS which would reset the mDemuxEOS flag ; causing the internal seek to kick in and we wouldn't then resolve the data promise with EOS => time out

Comment 23

[Jean-Yves Avenard [:jya]]

JW, something I'm trying to get my head around is this.

From time to time, the test dom/media/mediasource/test/test_BufferingWait_mp4.html will timeout.
The reason for this is that it's waiting for the waiting event to be fired a 2.41s - 1/30. The logic for that value is that buffered range ends at 2.41s, less the duration of a video frame.
That particular MSE has an audio and video track.
The last audio sample has a start time of 2.368435s
The last video sample has a start time of 2.465000s

Locally, I managed to reproduce it (albeit after about 300 runs). Yet the waiting event was fired at 2.368434s. That value has been consistent across all try failures where that mochitest failed:
like:
https://treeherder.mozilla.org/logviewer.html#?job_id=14640333&repo=try (OSX)
https://treeherder.mozilla.org/logviewer.html#?job_id=14640159&repo=try (win10)

always 2.368434s.

Why not 2.368435s, and actually seeing that we have audio until 2.414875s, why isn't the waiting event fired at 2.414875s?

Comment 24

[JW Wang [:jwwang] [:jw_wang]]

MediaDecoderStateMachine::MaybeStartBuffering() is called when a sample is popped, not when the sample is consumed by the underlying audio engine. So it is possible for 'waiting' to fire before the last sample is drained.

Why does waitUntilTime() need to check |v.currentTime >= targetTime|? It appear to me that the promise should be resolved once 'waiting' is received.

Comment 25

[Jean-Yves Avenard [:jya]]

(In reply to JW Wang [:jwwang] from comment #24)
> Why does waitUntilTime() need to check |v.currentTime >= targetTime|? It
> appear to me that the promise should be resolved once 'waiting' is received.

This is mostly to deal with multiple waiting being fired. Like if play() starts before any data is buffered, a waiting event will be fired immediately.

So waiting for a particular waiting event at a given time threshold was the most convenient way to ignore the waiting events we do not care about.

Comment 26

[Jean-Yves Avenard [:jya]]

JW, looking at this try run:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=e836e5141d9d

The win8 error, are all about "###!!! ASSERTION: We should have got duration already: 'mState > DECODER_STATE_DECODING_METADATA', file c:/builds/moz2_slave/try-w64-d-00000000000000000000/build/src/dom/media/MediaDecoderStateMachine.cpp, line 1497 "

This seems to happen when seek starts there: https://hg.mozilla.org/try/file/ec29b0d44aab/dom/media/mediasource/test/test_PlayEvents.html#l129

I can't explain how this could ever happen, seeing that loadedmetadata has already been fired.

Got any ideas on what's going on?

Comment 27

[JW Wang [:jwwang] [:jw_wang]]

I guess the state machine went dormant and mState became DECODER_STATE_DECODING_NONE.

Comment 28

[Jean-Yves Avenard [:jya]]

hmmm.. isn't dormant enabled after at least 60s idle and if the video is not visible?

If we can't seek on a video that is dormant simply because it's been idle for a short time, how come we aren't seeing that bug more often ???

Comment 29

[Jean-Yves Avenard [:jya]]

the MediaDecoder does appear to turn off dormant when seeking
https://dxr.mozilla.org/mozilla-central/source/dom/media/MediaDecoder.cpp#791

However, it seems that MediaDecoder::UpdateDormantState() will have no effect if the video element considers it as inactive.

Still dormant shouldn't have kicked in before 60s...

Comment 30

[Jean-Yves Avenard [:jya]]

ok.. can reproduce... if I set media.decoder.heuristic.dormant.timeout to 1ms only , seeks never complete.

Will take this in a separate bug

Comment 31

[Jean-Yves Avenard [:jya]]

actually, no.. was a one off.. damn

Comment 32

[JW Wang [:jwwang] [:jw_wang]]

https://treeherder.mozilla.org/logviewer.html#?job_id=14645629&repo=try

I noticed the test case timed out before hitting the assertion. I guess the media element went dormant while the test runner was removing the page and our test script was still running. (INFO TEST-UNEXPECTED-FAIL | dom/media/mediasource/test/test_PlayEvents.html | got canplaythrough event - Result logged after SimpleTest.finish())

Comment 33

[Jean-Yves Avenard [:jya]]

ah ok.. so it is a red herring then..

so I need to find out what's causing the timeout there... oh joy...

Comment 34

[Jean-Yves Avenard [:jya]]

JW, you can obviously read the logs better than I do.

Can you tell what's causing the timeout? which step of the script?

I'm starting to think I'll just temporarily disable it because I don't want this to get in the way of this work.

Comment 35

[JW Wang [:jwwang] [:jw_wang]]

These are the messages before timeout:
02:08:13     INFO -  82 INFO SourceBuffer buffered ranges grew from TimeRanges: [0, 3.203333)[6, 6.801666) to TimeRanges: [0, 3.203333)[6, 7.601666)
02:08:13     INFO -  83 INFO TEST-PASS | dom/media/mediasource/test/test_PlayEvents.html | got seeked and canplay event
02:08:13     INFO -  84 INFO TEST-PASS | dom/media/mediasource/test/test_PlayEvents.html | seeked to 6s
02:08:13     INFO -  85 INFO TEST-PASS | dom/media/mediasource/test/test_PlayEvents.html | readyState is HAVE_FUTURE_DATA
02:08:13     INFO -  86 INFO TEST-PASS | dom/media/mediasource/test/test_PlayEvents.html | fetchWithXHR load uri='bipbop/bipbop_video3.m4s' status=200
02:08:13     INFO -  87 INFO TEST-PASS | dom/media/mediasource/test/test_PlayEvents.html | fetchWithXHR load uri='bipbop/bipbop_video4.m4s' status=200
02:08:13     INFO -  88 INFO Loading buffer: [0, 23429)
02:08:13     INFO -  89 INFO SourceBuffer buffered ranges grew from TimeRanges: [0, 3.203333)[6, 7.601666) to TimeRanges: [0, 3.203333)[6, 8.403333)
02:08:13     INFO -  90 INFO Loading buffer: [0, 22446)
02:08:13     INFO -  91 INFO SourceBuffer buffered ranges grew from TimeRanges: [0, 3.203333)[6, 8.403333) to TimeRanges: [0, 3.203333)[6, 9.203333)
02:08:13     INFO -  92 INFO got stalled event
02:08:13     INFO -  93 INFO TEST-UNEXPECTED-FAIL | dom/media/mediasource/test/test_PlayEvents.html | Test timed out.

corresponding to
https://hg.mozilla.org/mozilla-central/file/0babaa3edcf908c393b68a3dc2d1c2a2450c31ed/dom/media/mediasource/test/test_PlayEvents.html#l90

It looks like 'canplaythrough' didn't come.

Comment 36

[Jean-Yves Avenard [:jya]]

I've managed to reproduce it consistently in a win8 VM with high core count and lots of RAM (8 cores, 24GB)

Comment 37

[Jean-Yves Avenard [:jya]]

I'm still puzzled on why canplaythrough arrives but only after timing out

Comment 38

[Jean-Yves Avenard [:jya]]

it does appear to be dormant related though:
dormant disabled:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=f59438f86fdc : all green
with dormant enabled:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=faf7b79f9655 : timeouts

Comment 39

[Jean-Yves Avenard [:jya]]

Attachment: P2. Drain decoder when encountering gap.

This allows for all buffered frames to be playable.

This is a significant rewrite from the first patch.

Comment 40

[Jean-Yves Avenard [:jya]]

The current patches actually exposed a race problem that was there all along, because the patch delayed some actions, the consequence of the race was more obvious.

It could be the cause of a few intermittent in particular on slow machines.

The asan intermittent timeout was due to NotifyDataArrived being called well after we had detected an end of stream. So seeing that new data is available (the buffered range got extended) it clears the EOS flag and is waiting on the MDSM to call Request*Data again, call that will never come.

The other intermittent error (particularly obvious on windows 8) was due that under some circumstances the cached buffered range wouldn't be immediately refreshed. The MediaDecoder, right after calling NotifyDataArrived will query the buffered range. If the buffered range has changed then the HTMLMediaElement is signaled to refresh the readyState value. It was possible that the buffered range wasn't updated in time; so GetBuffered() would get an old time ranges which would prevent the StateMirror to kick in. And as such readyState wouldn't be modified and no event (canplay/canplaythrough) would be fired.

Finally, I also noticed a case where the MediaFormatReader could attempt to decode continuously in a loop even if WAITING_FOR_DATA was encountered.

Comment 41

[Jean-Yves Avenard [:jya]]

Attachment: P5. Drop frames during internal seeking early.

We would only start to drop frames once we had a request for data. On platforms such as windows WMF, following a drain we would typically hold over 33 decoded frames which would have been held resulting in unnecessarily high memory usage.
This also results in a simplified logic for the following steps.

Comment 42

[Chris Pearce [:cpearce (Not reading bugmail)]]

Comment on attachment 8699647 [details] [diff] [review]
P5. Drop frames during internal seeking early.

Review of attachment 8699647 [details] [diff] [review]:
-----------------------------------------------------------------

::: dom/media/MediaFormatReader.cpp
@@ +1042,5 @@
>    AbstractMediaDecoder::AutoNotifyDecoded a(mDecoder);
>  
> +  // Drop any frames found prior our internal seek target.
> +  while (decoder.mTimeThreshold && decoder.mOutput.Length()) {
> +    auto& output = decoder.mOutput[0];

Your code would be easier (and faster!) to read and review if you used the actual type for your variables here instead of 'auto'. For example, you're assigning target = decoder.mTimeThreshold.ref(), so does that mean target is a reference to mTimeThreshold?

Please only use 'auto' where it improves readability; for example in heavily templated code. Then it'd be easier for me to r+ it faster.

Comment 43

[Jean-Yves Avenard [:jya]]

Ok.. I see why we timeout like on run like this:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=cafb2714a9a3

When playback encounters the end of the data (but mediasource isn't ended, so we're just supposed to stall), we drain the decoder and then the MDSM calls RequestVideoData repetitively which are almost immediately resolved.
28 frames were returned when the decoder was drained. We get 28 RequestVideoData. The 29th one that should be coming to reject the promise with: WAITING_FOR_DATA never comes.

Here are the log
http://mozilla-releng-blobs.s3.amazonaws.com/blobs/try/sha512/ca659e95bc3a1a814ce1eddd8e2947cdcc7814ad9bb0dadc1434f9e3408b66bc0a1e335996a1721297bf506fbdc87095832cb0eac8ae1b6fbebdcddfc9b92f6a

JW, what do you think? do you have an explanation on why the MDSM stops requesting video ?

The only thing I can think of is that the audio track is 3.900952s long while the video track is 4.005s long and from time to time, depending on how currentTime progress it doesn't attempt to decode past the audio stream.

The difference with before is that we would have returned WAITING_FOR_DATA for the video track at 3.136666s (4.05 - 28 frames) so the MDSM would have always required more data.

Comment 44

[JW Wang [:jwwang] [:jw_wang]]

Video frames are popped when current playback position (which is report by audio sink) passes the time of video frames. So MDSM stops requesting video when video queue is ample.

Comment 45

[Jean-Yves Avenard [:jya]]

Isn't that a bug though?

It means that depending on timing we will never fire ended if the video track is slightly longer than the audio track (which can be rather common)

Comment 46

[JW Wang [:jwwang] [:jw_wang]]

No, it is already handled by audio sink. When audio track reaches the end, audio sink will report system time instead which will keep advancing.

Comment 47

[Jean-Yves Avenard [:jya]]

well, it doesn't appear that way (I opened bug 1233639)

Comment 48

[JW Wang [:jwwang] [:jw_wang]]

The current problem happens when there is a gap in the stream, right? It is not about EOS.

Comment 49

[Jean-Yves Avenard [:jya]]

not quite.

The gap is temporary and the MediaFormatReader will return WAITING_FOR_DATA once the MDSM request more than what's available.

Unfortunately, the MDSM never requests more data.

If you look at the log you see that it calls RequestAudioData -> which is rejected with WAITING_FOR_DATA
it then calls RequestVideoData until it's right pass the audio and stop there.
I then end the mediasource which causes the MediaFormatReader to resolve the audio waiting promise and the MDSM calls RequestAudioData which is now rejected with EOS.

But the request for more video never resumes (it's neither in WAITING_FOR_DATA mode nor END_OF_STREAM)

Comment 50

[Jean-Yves Avenard [:jya]]

it seems that the MDSM doesn't properly handle the transition buffering -> completed

Comment 51

[Jean-Yves Avenard [:jya]]

try run:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=e1ee8e2a9049

that's with the  dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html mochitest modified to ensure the video track is slightly smaller than the audio track so it never triggers bug 1233639

Comment 52

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/1efca40406f1
https://hg.mozilla.org/integration/mozilla-inbound/rev/cb3d56df0a47
https://hg.mozilla.org/integration/mozilla-inbound/rev/aca5c93b342e
https://hg.mozilla.org/integration/mozilla-inbound/rev/37e78e0926ff
https://hg.mozilla.org/integration/mozilla-inbound/rev/289faf063a57

Comment 53

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/1efca40406f1
https://hg.mozilla.org/mozilla-central/rev/cb3d56df0a47
https://hg.mozilla.org/mozilla-central/rev/aca5c93b342e
https://hg.mozilla.org/mozilla-central/rev/37e78e0926ff
https://hg.mozilla.org/mozilla-central/rev/289faf063a57

Comment 54

[Jean-Yves Avenard [:jya]]

[Tracking Requested - why for this release]:
Two side bugs were discovered in the process of implementing this feature. All fixed. Worth spreading I believe

Comment 55

[Sylvestre Ledru [:Sylvestre]]

Jean-Yves, are you planning to fill an uplift request to 45? If you do, could you do that asap? Thanks

Comment 56

[Jean-Yves Avenard [:jya]]

Comment on attachment 8696345 [details] [diff] [review]
[MSE] P1. Ensure next random access point properly calculated after seek.

Approval is for all patches

Approval Request Comment
[Feature/regressing bug #]: 1229987
[User impact if declined]: YouTube stalls, some events not fired, intermittent mochitest timeout
[Describe test coverage new/current, TreeHerder]: In central for over a week, extra mochitest added
[Risks and why]: Low. We're doing what we used to do before the new MSE was introduced in 42.
[String/UUID change made/needed]: None

Comment 57

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/c1a3159224ae
https://hg.mozilla.org/releases/mozilla-aurora/rev/bab2c729fe29
https://hg.mozilla.org/releases/mozilla-aurora/rev/9fa906dfe06d
https://hg.mozilla.org/releases/mozilla-aurora/rev/50de8c9efef8
https://hg.mozilla.org/releases/mozilla-aurora/rev/aa47aa5c7a22