1940883 - Media playback stalls when out of data without dispatching "waiting" (or transitioning to readyState < HAVE_FUTURE_DATA)

Status: RESOLVED FIXED

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

Description

[Karl Tomlinson (:karlt)]

The test for bug 1915045 times out intermittently on Linux at least for the reason described below.

The test removes data from the audio SourceBuffer after "canplay".
Logging indicates that the MediaFormatReader

1. Requests demux of more audio,
2. Sets mAudio.mReceivedNewData, in NotifyTrackDemuxers(), presumably in response to the SourceBuffer operation,
3. Triggers a drain, is response to demux failure with NS_ERROR_DOM_MEDIA_WAITING_FOR_DATA,
4. Completes the drain of the audio decoder,
5. Starts an InternalSeek(),
6. Skips rejection of the RequestAudioData() promise because mReceivedNewData is set,
7. Clears decoder.mDrainState,
8. Fails the seek from 5,
9. Clears mReceivedNewData,
10. Starts another InternalSeek() because mReceivedNewData was set,
11. Sets decoder.mWaitingForDataStartTime again in response to the seek failing with NS_ERROR_DOM_MEDIA_WAITING_FOR_DATA,
12. Skips rejection of the RequestAudioData() promise again because decoder.mDrainState has been reset.

Comment 1

[Karl Tomlinson (:karlt)]

This could be triggered when running out of data, and presumably appending data for the current playback position would trigger recovery through a successful seek, but the bug means that content is missing the notification that playback is waiting on more data.

Removal of the audio is not necessary to trigger 2. Other SourceBuffer operations would also do this.

Comment 2

[Karl Tomlinson (:karlt)]

I guess Update() would have tried to demux more samples again before needInput was changed to false when HasInternalSeekPending().

That changeset also introduced the logic to go directly to the second internal seek without another demux attempt.

Comment 3

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1269408

Comment 4

[Karl Tomlinson (:karlt)]

https://treeherder.mozilla.org/jobs?repo=try&revision=9d0a40bf97a51ec4922c72dee8458f97254b4cd0

Comment 5

[Karl Tomlinson (:karlt)]

Attachment: Bug 1940883 reject MediaData promise when waiting on resource data with no drain r?#media-playback-reviewers

Comment 6

[Karl Tomlinson (:karlt)]

Attachment: Bug 1940883 return early even when an internal seek is waiting r?#media-playback-reviewers

UpdateReceivedNewData() would have aborted Update() early on
mSeekRequest.Exists() if there were an external seek, so at this point any
seek request would be internal.

This doesn't change behavior because needInput is false when
HasInternalSeekPending(), but merely clarifies that nothing more will
happen.

Comment 7

[Karl Tomlinson (:karlt)]

Attachment: Bug 1940883 simplify waiting for data early return logic a little r?#media-playback-reviewers

No behavior change, except in logging when !decoder.HasPromise().

The mWaiting check is no longer necessary since
https://hg.mozilla.org/mozilla-central/rev/df20f438502df1a33c71aea95d3ded5b84a2d2a7#l1.34

needInput is false if an internal seek is pending and so Update() will
return before doing anything further.

If decoder.HasPromise() then this waiting for data test is not even reached
because a previous early return is taken on IsInternalSeekPending().

The behavior of continuing to demux and decode to skip frames when
mTimeThreshold->mHasSeeked is maintained.

Comment 8

[Karl Tomlinson (:karlt)]

Attachment: Bug 1940883 remove IsWaitingForData() call that always returns false r?#media-playback-reviewers

This came from
https://hg.mozilla.org/mozilla-central/rev/271a6b2de3ad4be77b1c91305f5c5a49d4924120#l1.14

IsWaitingForData() always returns false because
mWaitingForDataStartTime.reset() is called above.

Comment 9

[Karl Tomlinson (:karlt)]

Attachment: Bug 1940883 add some media resource waiting and decode error logging r?#media-playback-reviewers

Comment 10

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/6820e30c2a77
consider rejecting MediaData promise when internal seek is waiting on data r=media-playback-reviewers,padenot

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/f594e6f00208
return early even when an internal seek is waiting r=media-playback-reviewers,padenot

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/1216b45b86ea
simplify waiting for data early return logic a little r=media-playback-reviewers,padenot

Comment 13

[Serban Stanca [:SerbanS]]

https://hg.mozilla.org/mozilla-central/rev/6820e30c2a77
https://hg.mozilla.org/mozilla-central/rev/f594e6f00208
https://hg.mozilla.org/mozilla-central/rev/1216b45b86ea

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/37fadc8438b4
remove IsWaitingForData() call that always returns false r=media-playback-reviewers,padenot
https://hg.mozilla.org/integration/autoland/rev/0268263a1ef1
add some media resource waiting and decode error logging r=media-playback-reviewers,padenot

Comment 15

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/37fadc8438b4
https://hg.mozilla.org/mozilla-central/rev/0268263a1ef1

Comment 16

[Cristina Horotan [:chorotan]]

Backed out changeset f594e6f00208 (Bug 1940883) for causing crashes in Bug 1941164

Backout: https://hg.mozilla.org/integration/autoland/rev/abc92a41910764a2dc98aea04074bc746fa2c194

Comment 17

[Sandor Molnar[:smolnar]]

Backout merged to central: https://hg.mozilla.org/mozilla-central/rev/abc92a41910764a2dc98aea04074bc746fa2c194

Comment 18

[Karl Tomlinson (:karlt)]

Still intending to fix this, once Bug 1941164 is understood.

Comment 19

[amarc]

Backout merged to mozilla-central: https://hg.mozilla.org/mozilla-central/rev/45f68751c2a6677f127f1d1125aea72adce108af

Comment 20

[Karl Tomlinson (:karlt)]

The crash state of bug 1941164 could be reached via this sequence of events:

1. An internal seek successfully seeks to the preceding random access point.
2. Demux of samples is requested while decoder output is less than the seek target time.
3. The demux fails with NS_ERROR_DOM_MEDIA_WAITING_FOR_DATA, requests a drain and calls NotifyWaitingForData(), which sets decoder.mTimeThreshold->mWaiting.
4. HasInternalSeekWaiting() now returns true even though HasInternalSeekPending() is false.
5. mDrainState is cleared even though not complete.
6. Another demux is requested and fails, which triggers another drain.

Comment 21

[amarc]

Backed out changeset 1216b45b86ea (Bug 1940883) due to risk of unproductive cpu usage : https://hg.mozilla.org/integration/autoland/rev/5ee87c6b2828c6f7d32fd939fe19f8d0e02fd68d

Comment 22

[Karl Tomlinson (:karlt)]

What I missed in writing https://hg.mozilla.org/mozilla-central/rev/1216b45b86ea also was that mWaiting can be set even when the MediaTrackDemuxer::Seek() has completed the seek to a random access point, but a demux has failed while Update() is trying to advance through dependent frames before the target. HasInternalSeekPending() is false, but Update() should not (repeatedly) schedule another demux until mReceivedNewData is set.

Comment 23

[Karl Tomlinson (:karlt)]

Attachment: Bug 1940883 add comments and assertions to MediaFormatReader r?#media-playback-reviewers

Comment 24

[Karl Tomlinson (:karlt)]

Attachment: Bug 1940883 set mWaitingForDataStartTime only if not already set r?#media-playback-reviewers

Comment 25

[Karl Tomlinson (:karlt)]

Attachment: Bug 1940883 skip an array allocation and clarify that demux happens only when mQueuedSamples is empty r?#media-playback-reviewers

Comment 26

[Karl Tomlinson (:karlt)]

Attachment: Bug 1940883 reset mPreviousDecodedKeyframeTime_us after dropping frames only for video tracks r?#media-playback-reviewers

Comment 27

[Serban Stanca [:SerbanS]]

Backout merged to mozilla-central: https://hg.mozilla.org/mozilla-central/rev/5ee87c6b2828c6f7d32fd939fe19f8d0e02fd68d

Comment 28

[Karl Tomlinson (:karlt)]

Attachment: Bug 1940883 add a state diagram for MediaFormatReader::Update() r?#media-playback-reviewers

Comment 29

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/01b46c4c797f
add comments and assertions to MediaFormatReader r=media-playback-reviewers,padenot

Comment 30

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/069caa4d0484
reset mPreviousDecodedKeyframeTime_us after dropping frames only for video tracks r=media-playback-reviewers,padenot

Comment 31

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/ff56d620f395
skip an array allocation and clarify that demux happens only when mQueuedSamples is empty r=media-playback-reviewers,padenot

Comment 32

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/080623fd072c
set mWaitingForDataStartTime only if not already set r=media-playback-reviewers,padenot

Comment 33

[Norisz Fay [:noriszfay]]

https://hg.mozilla.org/mozilla-central/rev/01b46c4c797f
https://hg.mozilla.org/mozilla-central/rev/069caa4d0484
https://hg.mozilla.org/mozilla-central/rev/ff56d620f395
https://hg.mozilla.org/mozilla-central/rev/080623fd072c

Comment 34

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/742de48395f3
add a state diagram for MediaFormatReader::Update() r=media-playback-reviewers,padenot

Comment 35

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/a47c8e651937
reject MediaData promise when waiting on resource data with no drain r=media-playback-reviewers,padenot

Comment 36

[Serban Stanca [:SerbanS]]

https://hg.mozilla.org/mozilla-central/rev/742de48395f3
https://hg.mozilla.org/mozilla-central/rev/a47c8e651937