1344772 - Logical loop with CPU exhaustion in MediaFormatReader::NotifyDataArrived

Status: VERIFIED FIXED

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

Description

[Honza Bambas (:mayhemer)]

Nightly based on https://hg.mozilla.org/mozilla-central/rev/34c6c2f302e7b48e3ad2cec575cbd34d423a9d32

I currently have 4 threads (a thread pool) looping calls to MediaFormatReader::NotifyDataArrived, always the same instance.  The mNotifyDataArrivedPromise.Exists() passes and the method is redispatched immediately again at [1].  This completely exhausts one or two cores of the processors.

When CPU is under a heavier load (like building the m-c tree) this renders the content process mostly useless - pages render very slowly.

I'll try to create a reduced test case to reproduce, I currently don't even have an exact STR.  Note this was opened in a private window and there is an MP4 video involved (found an MP4Decoder as this->mDecoder).  The page that was referring the video was already closed at the time this loop appeared.  The loop persists even when I close the private window (the last private tab).


The MediaFormatReader:
-		this	0x0000023f73d43000 {mPlatform={mRawPtr=0x0000023f766e3ee0 {mRefCnt={mValue={...} } mCurrentPDMs={...} ...} } ...}	mozilla::MediaFormatReader *
+		mozilla::MediaDecoderReader	{mRefCnt={mValue={...} } mAudioQueue={mReentrantMonitor={mReentrantMonitor=0x0000023f0308ac00 {...} } ...} ...}	mozilla::MediaDecoderReader
+		mPlatform	{mRawPtr=0x0000023f766e3ee0 {mRefCnt={mValue={...} } mCurrentPDMs={...} mEMEPDM={mRawPtr=0x0000000000000000 <NULL> } ...} }	RefPtr<mozilla::PDMFactory>
+		mAudio	{mPromise={mMonitor=0x0000000000000000 <NULL> mPromise={mRawPtr=0x0000000000000000 <NULL> } } mHasPromise=...}	mozilla::MediaFormatReader::DecoderDataWithPromise
+		mVideo	{mPromise={mMonitor=0x0000000000000000 <NULL> mPromise={mRawPtr=0x0000000000000000 <NULL> } } mHasPromise=...}	mozilla::MediaFormatReader::DecoderDataWithPromise
+		mDemuxer	{mTuple={...} }	mozilla::UniquePtr<mozilla::MediaFormatReader::DemuxerProxy,mozilla::DefaultDelete<mozilla::MediaFormatReader::DemuxerProxy> >
		mDemuxerInitDone	true	bool
+		mDemuxerInitRequest	{mRequest={mRawPtr=0x0000000000000000 <NULL> } }	mozilla::MozPromiseRequestHolder<mozilla::MozPromise<enum nsresult,mozilla::MediaResult,1> >
+		mNotifyDataArrivedPromise	{mRequest={mRawPtr=0x0000023f037e6aa0 {mResolveFunction={mStorage=0x0000023f037e6ae0 "" mIsSome=1 '\x1' } ...} } }	mozilla::MozPromiseRequestHolder<mozilla::MozPromise<bool,mozilla::MediaResult,1> >
+		mSkipRequest	{mRequest={mRawPtr=0x0000000000000000 <NULL> } }	mozilla::MozPromiseRequestHolder<mozilla::MozPromise<unsigned int,mozilla::MediaTrackDemuxer::SkipFailureHolder,1> >
		mLastReportedNumDecodedFrames	520	unsigned __int64
		mPreviousDecodedKeyframeTime_us	9223372036854775807	__int64
+		mKnowsCompositor	{mRawPtr=0x0000023f00506d58 {mRefCnt={mValue={...} } mShadowManager={mRawPtr=0x0000023f08297f60 {mRefCnt=...} } ...} }	RefPtr<mozilla::layers::KnowsCompositor>
		mInitDone	true	bool
+		mMetadataPromise	{mMonitor=0x0000000000000000 <NULL> mPromise={mRawPtr=0x0000000000000000 <NULL> } }	mozilla::MozPromiseHolder<mozilla::MozPromise<RefPtr<mozilla::MetadataHolder>,mozilla::MediaResult,1> >
		mTrackDemuxersMayBlock	true	bool
		mSeekScheduled	false	bool
+		mOriginalSeekTarget	{mTime={mValue={mValue=67886048 mIsValid=true } } mType=Accurate (2) mVideoOnly=false }	mozilla::SeekTarget
+		mFallbackSeekTime	{mStorage=0x0000023f73d43a00 "àÛ\v\x4" mIsSome=1 '\x1' }	mozilla::Maybe<mozilla::media::TimeUnit>
+		mPendingSeekTime	{mStorage=0x0000023f73d43a18 "àÛ\v\x4" mIsSome=1 '\x1' }	mozilla::Maybe<mozilla::media::TimeUnit>
+		mSeekPromise	{mMonitor=0x0000000000000000 <NULL> mPromise={mRawPtr=0x0000023f031798b0 {mCreationSite=0x00007ffb49485fdc "Seek" ...} } }	mozilla::MozPromiseHolder<mozilla::MozPromise<mozilla::media::TimeUnit,mozilla::SeekRejectValue,1> >
+		mVideoFrameContainer	{mRawPtr=0x0000023f088969d0 {mElement=0x0000023f0369b000 {mUseScreenWakeLock=true mScreenWakeLock={mRawPtr=...} } ...} }	RefPtr<mozilla::VideoFrameContainer>
+		mCDMProxy	{mRawPtr=0x0000000000000000 <NULL> }	RefPtr<mozilla::CDMProxy>
+		mCrashHelper	{mRawPtr=0x0000023f03619180 {mElement={mRef={mRawPtr=0x0000023f03181630 {mPtr=0x0000023f0369b000 {mUseScreenWakeLock=...} } } } } }	RefPtr<mozilla::GMPCrashHelper>
+		mDecoderFactory	{mTuple={...} }	mozilla::UniquePtr<mozilla::MediaFormatReader::DecoderFactory,mozilla::DefaultDelete<mozilla::MediaFormatReader::DecoderFactory> >
+		mShutdownPromisePool	{mTuple={...} }	mozilla::UniquePtr<mozilla::MediaFormatReader::ShutdownPromisePool,mozilla::DefaultDelete<mozilla::MediaFormatReader::ShutdownPromisePool> >
+		mCompositorUpdatedListener	{mToken={mRawPtr=0x0000023f03181df0 {mRefCnt={mValue={...} } mRevoked={...} } } }	mozilla::MediaEventListener
+		mOnTrackWaitingForKeyListener	{mToken={mRawPtr=0x0000023f03181e10 {mRefCnt={mValue={...} } mRevoked={...} } } }	mozilla::MediaEventListener
+		mTags	{mTuple={...} }	mozilla::UniquePtr<nsDataHashtable<nsCStringHashKey,nsCString>,mozilla::DefaultDelete<nsDataHashtable<nsCStringHashKey,nsCString> > >
		mHasStartTime	true	bool


The code here around has been recently changed, my Nightly is few days old.  Maybe this is already fixed.


[1] https://hg.mozilla.org/mozilla-central/file/34c6c2f302e7b48e3ad2cec575cbd34d423a9d32/dom/media/MediaFormatReader.cpp#l2835

Comment 1

[Honza Bambas (:mayhemer)]

Maybe already fixed with bug 1341200?

Comment 2

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

(In reply to Honza Bambas (:mayhemer) from comment #1)
> Maybe already fixed with bug 1341200?

No, I don't think so. Bug 1341200 kicks in only when it comes to decoder creation/shutdown. The symptom you described should happen during decoding.

Comment 3

[Honza Bambas (:mayhemer)]

(In reply to JW Wang [:jwwang] [:jw_wang] from comment #2)
> (In reply to Honza Bambas (:mayhemer) from comment #1)
> > Maybe already fixed with bug 1341200?
> 
> No, I don't think so. Bug 1341200 kicks in only when it comes to decoder
> creation/shutdown. The symptom you described should happen during decoding.

OK, based on that I confirm this as a likely bug.

Comment 4

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

Attachment: Bug 1344772 - set a dirty flag so we can process the notification later.

https://hg.mozilla.org/mozilla-central/file/34c6c2f302e7b48e3ad2cec575cbd34d423a9d32/dom/media/MediaFormatReader.cpp#l2835
NotifyDataArrived() is dispatched again if |mNotifyDataArrivedPromise.Exists()| which will then be dispatched again
recursively until mNotifyDataArrivedPromise is completed. This is a waste of CPU cycles.

We can use a dirty flag to note we should update buffer ranges again when the current update is done.

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

Comment 5

[Jean-Yves Avenard [:jya]]

Comment on attachment 8847469 [details]
Bug 1344772 - set a dirty flag so we can process the notification later.

https://reviewboard.mozilla.org/r/120452/#review122396

::: dom/media/MediaFormatReader.cpp:2900
(Diff revision 1)
>      ->Then(OwnerThread(), __func__,
>             [self]() {
>               self->mNotifyDataArrivedPromise.Complete();
>               self->UpdateBuffered();
>               self->NotifyTrackDemuxers();
> +             if (self->mPendingNotifyDataArrived) {

I think we could simply totally ignore pending NotifyDataArrived, but I guess better safe than sorry

Comment 6

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

Thanks!

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/8c0e4e52f376
set a dirty flag so we can process the notification later. r=jya

Comment 8

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/8c0e4e52f376

Comment 9

[Markus Stange [:mstange]]

Can we get this uplifted as far as possible? I've been seeing this for a while. (And today, when I finally wanted to file it, I found out that it was already fixed! Thanks!)

Comment 10

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

Comment on attachment 8847469 [details]
Bug 1344772 - set a dirty flag so we can process the notification later.

Approval Request Comment
[Feature/Bug causing the regression]:1319992
[User impact if declined]:CPU might be exhausted during playback.
[Is this code covered by automated tests?]:No
[Has the fix been verified in Nightly?]:No. There is no easy and reliable way to repro this bug which is a timing issue which depends on network and CPU scheduling.
[Needs manual test from QE? If yes, steps to reproduce]: No.
[List of other uplifts needed for the feature/fix]:No
[Is the change risky?]:No
[Why is the change risky/not risky?]:The change is quite simple.
[String changes made/needed]:None

Comment 11

[Gerry Chang [:gchang]]

Comment on attachment 8847469 [details]
Bug 1344772 - set a dirty flag so we can process the notification later.

Fix a CPU exhaustion issue. Aurora54+.

Comment 12

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/b23189887bfb

Comment 13

[Virtual_ManPL [:Virtual] 🇵🇱 - (please needinfo? me - so I will see your comment/reply/question/etc.)]

Requesting uplift to Firefox 53, as it's also affected looking on #bug 1319992.

Comment 14

[Virtual_ManPL [:Virtual] 🇵🇱 - (please needinfo? me - so I will see your comment/reply/question/etc.)]

Comment on attachment 8847469 [details]
Bug 1344772 - set a dirty flag so we can process the notification later.

See Comment #10

Approval Request Comment
[Feature/Bug causing the regression]:1319992
[User impact if declined]:CPU might be exhausted during playback.
[Is this code covered by automated tests?]:No
[Has the fix been verified in Nightly?]:No. There is no easy and reliable way to repro this bug which is a timing issue which depends on network and CPU scheduling.
[Needs manual test from QE? If yes, steps to reproduce]: No.
[List of other uplifts needed for the feature/fix]:No
[Is the change risky?]:No
[Why is the change risky/not risky?]:The change is quite simple.
[String changes made/needed]:None

Comment 15

[Liz Henry (:lizzard) (relman/hg->git project)]

Comment on attachment 8847469 [details]
Bug 1344772 - set a dirty flag so we can process the notification later.

Sounds like this fixes bug 1329630, a very annoying problem for users. 
Let's try uplift to beta, for the beta 7 build next week.

Comment 16

[Ryan VanderMeulen [:RyanVM]]

Needs rebasing for Beta uplift.

Comment 17

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

Bug 1319992 was landed to beta and backed out by bug 1326372 which somehow is wrong about the bug number in the commit message.

Comment 18

[Virtual_ManPL [:Virtual] 🇵🇱 - (please needinfo? me - so I will see your comment/reply/question/etc.)]

@ JW Wang [:jwwang] [:jw_wang] - Thank you very much for detailed explanation!
So per comment #17, I'm marking this bug as unaffected on Firefox 53, as patch which was causing this issue was backed out from this version.