1274933 - Intermittent dom/media/mediasource/test/test_ResumeAfterClearing_mp4.html | Test timed out.

Status: RESOLVED FIXED

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

Description

[Jean-Yves Avenard [:jya]]

Likely very similar to bug 1270323, symptoms are similar but somehow the fix of bug 1270323 doesn't fix it.

Logs show that: audio state: ni=0 no=0 ie=1 demuxr:0 demuxq:0 decoder:1 tt:-1.000000 tths:-1 in:1 out:1 qs=0 pending:0 waiting:1 rnewdata:1 sid:27 

So we are in waiting mode, it is marked as having new data received, yet the waiting promise wasn't resolved:
[3340] WARNING: Decoder=110d2e80 GetMediaTime=1623945 GetClock=1623945 mState=DECODING mPlayState=3 mDecodingFirstFrame=0 IsPlaying=1 mAudioStatus=waiting mVideoStatus=idle mDecodedAudioEndTime=1625395 mDecodedVideoEndTime=1963333 mIsAudioPrerolling=0 mIsVideoPrerolling=0:

Unfortunately, I've only seen it happening twice, going to be hard to reproduce

Comment 1

[Jean-Yves Avenard [:jya]]

Actually looking at the log, this is potentially very troublesome.

It shows that if decoding is fast and we get to the end of the trackbuffer while we're in the middle of processing an appendBuffer and between two media segments: we will stall and playback will not recover.

example:
 04:50:01     INFO -  audio state: ni=0 no=0 ie=1 demuxr:0 demuxq:0 decoder:1 tt:-1.000000 tths:-1 in:1 out:1 qs=0 pending:0 waiting:1 rnewdata:1 sid:28
 04:50:01     INFO -  video decoder: wmf software video decoder
 04:50:01     INFO -  hardware video decoding: disabled
 04:50:01     INFO -  video frames decoded: 71 (skipped:0)
 04:50:01     INFO -  video state: ni=0 no=0 ie=1 demuxr:0 demuxq:0 decoder:1 tt:-1.000000 tths:-1 in:72 out:72 qs=1 pending:1 waiting:0 rnewdata:0 sid:29
 04:50:01     INFO -  mDemuxEOS=1 mOutputRequested=1 mNeedDraining=0 mDraining=1 mDrainComplete=1Dumping data for demuxer eba2220:
 04:50:01     INFO -  	Dumping Audio Track Buffer(audio/mp4a-latm): - mLastAudioTime: 6.826666
 04:50:01     INFO -  		NumSamples:84 Size:17668 NextGetSampleIndex:4294967295 NextInsertionIndex:84
 04:50:01     INFO -  		Buffered: ranges=[(3.900952, 7.801904)]
 04:50:01     INFO -  	Dumping Video Track Buffer(video/avc) - mLastVideoTime: 7.208333
 04:50:01     INFO -  		NumSamples:96 Size:107347 NextGetSampleIndex:96 NextInsertionIndex:96
 04:50:01     INFO -  		Buffered: ranges=[(4.005000, 7.208333)]

so here we have audio stuck at 6.826666s. 6.826666 is the end time of the 3rd media segment being processed

It's a very narrow gap during which the error can occur as a new task is immediately dispatched to process the next media segment (the appendBuffer adds 2 media segments at once).

So I'm marking this as P2 because that needs to be tackled asap.

Comment 2

[Jean-Yves Avenard [:jya]]

just seen with mochitest dom/media/mediasource/test/test_SeekNoData_mp4.html | Test timed out. 

same observed behaviour, stall occurs with data in the middle of an append buffer.

Comment 3

[Jean-Yves Avenard [:jya]]

Attachment: MozReview Request: Bug 1274933: Reject data promise when EOS is encountered following waiting for data. r?gerald

Review commit: https://reviewboard.mozilla.org/r/54814/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/54814/

Comment 4

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Comment on attachment 8755791 [details]
MozReview Request: Bug 1274933: Reject data promise when EOS is encountered following waiting for data. r?gerald

https://reviewboard.mozilla.org/r/54814/#review51476

Comment 5

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/0591ae1f3daf

Comment 6

[Jean-Yves Avenard [:jya]]

Hoping I nailed all the MSE intermittents now: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ffb21cfdad5e8bc3499f055e10738631b33c532b

Looks very good

Comment 7

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/0591ae1f3daf

Comment 8

[Intermittent Failures Robot]

24 automation job failures were associated with this bug yesterday.

Repository breakdown:
* mozilla-inbound: 24

Platform breakdown:
* windows7-32: 11
* windows7-32-vm: 8
* windows8-64: 5

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1274933&startday=2016-06-28&endday=2016-06-28&tree=all

Comment 9

[Intermittent Failures Robot]

24 automation job failures were associated with this bug in the last 7 days.

Repository breakdown:
* mozilla-inbound: 24

Platform breakdown:
* windows7-32: 11
* windows7-32-vm: 8
* windows8-64: 5

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1274933&startday=2016-06-27&endday=2016-07-03&tree=all