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

RESOLVED FIXED in Firefox 49

Status

()

defect
P2
normal
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: jya, Assigned: jya)

Tracking

(Blocks 1 bug, {intermittent-failure})

Trunk
mozilla49
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox49 fixed)

Details

Attachments

(1 attachment)

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
Blocks: MSE
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.
Priority: P5 → P2
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 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
Attachment #8755791 - Flags: review?(gsquelart) → review+
Hoping I nailed all the MSE intermittents now: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ffb21cfdad5e8bc3499f055e10738631b33c532b

Looks very good
https://hg.mozilla.org/mozilla-central/rev/0591ae1f3daf
Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla49
You need to log in before you can comment on or make changes to this bug.