1276184 - Assertion failure: (track[i-1]->mTrackInfo->GetID() == track[i]->mTrackInfo->GetID() && track[i-1]->mTimecode <= track[i]->mTimecode) || track[i]->mKeyframe, at TrackBuffersManager.cpp:12

Status: RESOLVED FIXED

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

Description

[Carsten Book [:Tomcat]]

Attachment: bughunter stack

Found via bughunter and reproduced on a windows 7 trunk debug build based on m-c tip

Steps to reproduce:
-> Load https://www.youtube.com/watch?v=DirSXIoL_sE
--> Assertion Failure

Assertion failure: (track[i-1]->mTrackInfo->GetID() == track[i]->mTrackInfo->GetID() && track[i-1]->mTimecode <= track[i]->mTimecode) || track[i]->mKeyframe, at c:/Users/mozilla/debug-builds/mozilla-central/dom/media/mediasource/TrackBuffersManager.cpp:1230

#01: mozilla::TrackBuffersManager::DoDemuxAudio[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0x3c7852a]
#02: mozilla::TrackBuffersManager::OnVideoDemuxCompleted[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0x3c84399]
#03: mozilla::MozPromise<RefPtr<mozilla::MediaTrackDemuxer::SamplesHolder>,enum mozilla::DemuxerFailureReason,1>::InvokeCallbackMethod<mozilla::TrackBuffersManager,void (__thiscall mozilla::TrackBuffersManager::*)(RefPtr<mozilla::MediaTrackDemuxer::SamplesHold[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0x3c5e51a]
#04: mozilla::MozPromise<RefPtr<mozilla::MediaTrackDemuxer::SamplesHolder>,enum mozilla::DemuxerFailureReason,1>::MethodThenValue<mozilla::TrackBuffersManager,void (__thiscall mozilla::TrackBuffersManager::*)(RefPtr<mozilla::MediaTrackDemuxer::SamplesHolder>),[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0x3c79ab5]
#05: mozilla::MozPromise<RefPtr<mozilla::MediaTrackDemuxer::SamplesHolder>,enum mozilla::DemuxerFailureReason,1>::ThenValueBase::DoResolveOrReject[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0x3a4ac03]
#06: mozilla::MozPromise<RefPtr<mozilla::MediaTrackDemuxer::SamplesHolder>,enum mozilla::DemuxerFailureReason,1>::ThenValueBase::ResolveOrRejectRunnable::Run[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0x3a60536]
#07: mozilla::TaskQueue::Runner::Run[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0x77d6c3]
#08: nsThreadPool::Run[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0x77e5af]
#09: nsThread::ProcessNextEvent[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0x777b6b]
#10: NS_ProcessNextEvent[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0x7e31b2]
#11: mozilla::ipc::MessagePumpForNonMainThreads::Run[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0xff47ac]
#12: MessageLoop::RunInternal[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0xf9291d]
#13: MessageLoop::RunHandler[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0xf92892]
#14: MessageLoop::Run[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0xf9248d]
#15: nsThread::ThreadFunc[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\xul.dll +0x782b33]
#16: _PR_NativeRunThread[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\nss3.dll +0x2fb02b]
#17: _PR_MD_YIELD[c:\Users\mozilla\debug-builds\mozilla-central\firefox-debug\dist\bin\nss3.dll +0x2e01f9]
#18: crt_at_quick_exit[C:\Windows\system32\ucrtbase.DLL +0x7f794]
#19: BaseThreadInitThunk[C:\Windows\system32\kernel32.dll +0x4ef1c]
#20: RtlInitializeExceptionChain[C:\Windows\SYSTEM32\ntdll.dll +0x63648]

Comment 1

[Carsten Book [:Tomcat]]

jean-yves also tested on beta with a build based on https://hg.mozilla.org/releases/mozilla-beta/rev/2ee4473c729acb2ba7dc723e7affe79ce14bff85 and also shows this assertion. So i can confirm its a regression

Comment 2

[Jean-Yves Avenard [:jya]]

Thanks.. Any chances you can see if it reproduces in 46?

Comment 3

[Carsten Book [:Tomcat]]

found a 46 tinderbox debug build based on https://hg.mozilla.org/releases/mozilla-beta/rev/f51382b3b967a684813ed6f6aa4be0aaab766d6f

and in 46 the assertion is 

Assertion failure: (track[i-1]->mTrackInfo->GetID() == track[i]->mTrackInfo->GetID() && track[i-1]->mTimecode <= track[i]->mTimecode) || track[i]->mKeyframe, at c:/builds/moz2_slave/m-beta-w32-d-00000000000000000/build/src/dom/media/mediasource/TrackBuffersManager.cpp:1224
#01: JS::ubi::DominatorTree::root[xul +0x188062e]
#02: JS::ubi::DominatorTree::root[xul +0x1886e59]
#03: JS::ubi::DominatorTree::root[xul +0x187564d]
#04: JS::ubi::DominatorTree::root[xul +0x1881266]
#05: JS::ubi::DominatorTree::root[xul +0x1795504]
#06: JS::ubi::DominatorTree::root[xul +0x179d457]
#07: XRE_AddStaticComponent[xul +0x113b34]
#08: XRE_AddStaticComponent[xul +0x114413]
#09: XRE_AddStaticComponent[xul +0x1114ce]
#10: NS_StringSetIsVoid[xul +0x13ee6b]
#11: mozilla::SandboxTarget::Instance[xul +0x407be1]
#12: mozilla::LoadInfo::TriggeringPrincipal[xul +0x3d6712]
#13: mozilla::LoadInfo::TriggeringPrincipal[xul +0x3d66ca]
#14: mozilla::LoadInfo::TriggeringPrincipal[xul +0x3d6443]
#15: XRE_AddStaticComponent[xul +0x1168e4]
#16: PR_NativeCreateThread[nss3 +0x207698]
#17: PR_MD_WAIT_CV[nss3 +0x1f82ef]
#18: _get_flsindex[MSVCR120 +0x2c01d]
#19: _get_flsindex[MSVCR120 +0x2c001]
#20: BaseThreadInitThunk[kernel32 +0x4ef1c]
#21: RtlInitializeExceptionChain[ntdll +0x63648]
#22: RtlInitializeExceptionChain[ntdll +0x6361b]

Comment 4

[Jean-Yves Avenard [:jya]]

Can't reproduce it :(

Tried with mp4 MSE and webm (this video only has a webm/vorbis stream) ; at every resolutions available. I never hit this assert :(

Carsten, can you reproduce doing the following?

Pause the video
Seek to 0
In the settings -> Quality, go through each available resolution (144, 240, 360, 480, 720, 1080p). When changing resolution let it buffer to the end

Does it crash?

Can you manually reproduce it? when you right click on the playback window and select "stats for nerds" what does it show (hoping this would be available prior the assert)

Side note, that bird look like an australian tawny frogmouth, though I've never heard those make any noise.

Comment 5

[Jean-Yves Avenard [:jya]]

and what's the result of youtube.com/html5 ?

Comment 6

[Carsten Book [:Tomcat]]

Attachment: youtube debug info

Comment 7

[Carsten Book [:Tomcat]]

Attachment: screenshot from the settings

can still reproduce the crash. Seems this crash only at this special resolution and somehow i was also not able to crash with mozregression. 

So this win7 debug build based on m-c shows the assertion but it seems builds like from mozregression not.

Comment 8

[Carsten Book [:Tomcat]]

Attachment: youtube/html5

Comment 9

[Carsten Book [:Tomcat]]

jya: tried your debug patch and does not crash anymore :( but i still keep trying, maybe this is something that happen only like on europe's mornings or so :(

Comment 10

[Carsten Book [:Tomcat]]

Attachment: mediasource.zip

media source files when the crash happened

Comment 11

[Carsten Book [:Tomcat]]

It seems this crash depend a lot on your connection speed - 
high speed internet connection -> no crash
slower internet connection (and so the resolution changes) or a connection that use several things like streams etc at once -> assertion

i was not able to reproduce in a normal environment anymore (using the 1280 x 720 resolution) but using a tool in the vm that force-reduce my connection speed worked to reproduce (had to load other tabs and webradio also to produce some load).

Comment 12

[Jean-Yves Avenard [:jya]]

https://people.mozilla.org/~jyavenard/tests/mse_webm/youtube-assert2.html will reproduce the problem consistently

Comment 13

[Jean-Yves Avenard [:jya]]

The error occurs because the last sample of a packet has the same start time at the sample of the next packet:
[MediaPlayback #3]: D/MediaSourceSamples TrackBuffersManager(1343ed000:video/webm)::ProcessFrames: Processing video/webm; codecs=vp9 frame(pts:25025000 end:25092000, dts:25025000, duration:67000, kf:0)

[MediaPlayback #3]: D/MediaSourceSamples TrackBuffersManager(1343ed000:video/webm)::ProcessFrames: Processing video/webm; codecs=vp9 frame(pts:25025000 end:25092000, dts:25025000, duration:67000, kf:1)

for some reason that duplicate frame isn't removed when it should be.

While playing this file, I found a few times that the playback would jump straight at the end even though we were continuously adding data; it should have stopped and waited for more data to be added. But for some reasons it didn't.
This is likely what is causing some error such as:
28 INFO TEST-UNEXPECTED-FAIL | dom/media/mediasource/test/test_DrainOnMissingData_mp4.html | Video has correct currentTime. - got 9.977, expected 0.801666
https://treeherder.mozilla.org/logviewer.html#?job_id=29270782&repo=mozilla-inbound

Comment 14

[Jean-Yves Avenard [:jya]]

Attachment: MozReview Request: Bug 1276184: [MSE] P1. Scan where to start removing frames from the start if new block added starts with a keyframe. r?kamidphish

We keep the next position on where to add frames so that we do not break the current coded frame group. However, when the new group of added frames starts with a keyframe we do not have to worry about breaking the previous coded frame group.

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

Comment 15

[Jean-Yves Avenard [:jya]]

Attachment: MozReview Request: Bug 1276184: [MSE] P2. Remove the need to scan the track buffer when frames are being removed. r?kamidphish

The index at which we are removing frames is always the one where we will be inserting the next ones.

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

Comment 16

[Jean-Yves Avenard [:jya]]

Attachment: MozReview Request: Bug 1276184: [MSE] P3. Be consistent with types when accessing track buffer. r?kamidphish

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

Comment 17

[u480271]

Comment on attachment 8759056 [details]
MozReview Request: Bug 1276184: [MSE] P1. Scan where to start removing frames from the start if new block added starts with a keyframe. r?kamidphish

https://reviewboard.mozilla.org/r/57144/#review54234

Comment 18

[u480271]

Comment on attachment 8759057 [details]
MozReview Request: Bug 1276184: [MSE] P2. Remove the need to scan the track buffer when frames are being removed. r?kamidphish

https://reviewboard.mozilla.org/r/57146/#review54236

Comment 19

[u480271]

Comment on attachment 8759058 [details]
MozReview Request: Bug 1276184: [MSE] P3. Be consistent with types when accessing track buffer. r?kamidphish

https://reviewboard.mozilla.org/r/57148/#review54240

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/fa6a1c27983f
[MSE] P1. Scan where to start removing frames from the start if new block added starts with a keyframe. r=kamidphish
https://hg.mozilla.org/integration/mozilla-inbound/rev/0567d1267d23
[MSE] P2. Remove the need to scan the track buffer when frames are being removed. r=kamidphish
https://hg.mozilla.org/integration/mozilla-inbound/rev/71a44348d3b7
[MSE] P3. Be consistent with types when accessing track buffer. r=kamidphish

Comment 21

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/fa6a1c27983f
https://hg.mozilla.org/mozilla-central/rev/0567d1267d23
https://hg.mozilla.org/mozilla-central/rev/71a44348d3b7

Comment 22

[Jean-Yves Avenard [:jya]]

Comment on attachment 8759056 [details]
MozReview Request: Bug 1276184: [MSE] P1. Scan where to start removing frames from the start if new block added starts with a keyframe. r?kamidphish

Approval Request Comment
[Feature/regressing bug #]: MSE
[User impact if declined]: Potential stalls with some YouTube videos
[Describe test coverage new/current, TreeHerder]: In central for a few weeks.
[Risks and why]: Low. Special case for some of the webm youtube videos. Not the best fix, but will do for now. 
[String/UUID change made/needed]: None

Comment 23

[Sylvestre Ledru [:Sylvestre]]

I guess this uplift is for the three patches?

Comment 24

[Liz Henry (:lizzard Please n-i to RyanVM, jcristau, or pascal)]

Dan, can you answer since jya is on PTO? Also I'm hoping you can be around if we end up having to back this out or if there are problems.

Comment 25

[Liz Henry (:lizzard Please n-i to RyanVM, jcristau, or pascal)]

Comment on attachment 8759056 [details]
MozReview Request: Bug 1276184: [MSE] P1. Scan where to start removing frames from the start if new block added starts with a keyframe. r?kamidphish

Let's try this in aurora, all 3 patches.

Since this isn't fixing a known reported issue maybe it would be best to keep this change on aurora without uplifting further.

Comment 26

[u480271]

(In reply to Liz Henry (:lizzard) (needinfo? me) from comment #24)
> Dan, can you answer since jya is on PTO? Also I'm hoping you can be around
> if we end up having to back this out or if there are problems.

Yes, uplift needs to be three patches. I'll be around.

Comment 27

[Gerry Chang [:gchang]]

Comment on attachment 8759056 [details]
MozReview Request: Bug 1276184: [MSE] P1. Scan where to start removing frames from the start if new block added starts with a keyframe. r?kamidphish

It's a possible fix. Let's take it in 48 beta 6 and keep monitoring the result.

Comment 28

[Gerry Chang [:gchang]]

Tracking this and see if any regressions happen.

Comment 29

[Carsten Book [:Tomcat]]

(In reply to Liz Henry (:lizzard) (needinfo? me) from comment #25)
> Comment on attachment 8759056 [details]
> MozReview Request: Bug 1276184: [MSE] P1. Scan where to start removing
> frames from the start if new block added starts with a keyframe. r?kamidphish
> 
> Let's try this in aurora, all 3 patches.
> 
> Since this isn't fixing a known reported issue maybe it would be best to
> keep this change on aurora without uplifting further.

its already on aurora with the mergeday in june

Comment 30

[Carsten Book [:Tomcat]]

remote:   https://hg.mozilla.org/releases/mozilla-beta/rev/aa702c6e60ea
remote:   https://hg.mozilla.org/releases/mozilla-beta/rev/3c50c8027389
remote:   https://hg.mozilla.org/releases/mozilla-beta/rev/3e04c4853a8b