1293646 - mediasource-duration.html intermittently failing when decode ahead is set to high values

Status: RESOLVED FIXED

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

Description

[Jean-Yves Avenard [:jya]]

Attachment: mediasource-duration.log

noticed while debugging an intermittent in the web-platform-test mediasource-duration.html and attempting to find why we've had report for the "ended" event to never be fired.

something isn't quite right.

Set media.video-decode-ahead to 30.

We have reached the end of the data, and the decoder has been drained. There are now 27 frames pending to be returned to the MDSM.
The last frame returned to the MDSM had a time of 365200.

duration was set to 0.510839. The ended event is never fired.

[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(139d53000)::NotifyNewOutput: Received new Video sample time:1294800 duration:33200
[MediaPlayback #1]: D/MediaFormatReader MediaFormatReader(139d53000)::NotifyDrainComplete: Video
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(139d53000)::Update: Processing update for Video
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(139d53000)::Update: Update(Video) ni=0 no=0 ie=1, in:38 out:38 qs=27 pending:27 waiting:1 ahead:1 sid:0
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(139d53000)::Update: Still waiting for data.
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(139d53000)::Update: Processing update for Audio
[MediaPlayback #1]: D/MediaFormatReader MediaFormatReader(139d53000)::Update: Rejecting Audio promise: WAITING_FOR_DATA
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(139d53000)::Update: Update(Audio) ni=0 no=1 ie=1, in:29 out:29 qs=0 pending:0 waiting:1 ahead:1 sid:0
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(139d53000)::Update: Still waiting for data.
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(139d53000)::ScheduleUpdate: SchedulingUpdate(Audio)
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(139d53000)::Update: Processing update for Audio
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(139d53000)::Update: Update(Audio) ni=0 no=0 ie=1, in:29 out:29 qs=0 pending:0 waiting:1 ahead:1 sid:0
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(139d53000)::Update: Still waiting for data.
[Main Thread]: D/MediaSource SourceBuffer(139d3ad00:video/mp4)::DispatchSimpleEvent: Dispatch event 'updatestart'
[Main Thread]: D/MediaSource SourceBuffer(139d3ad00:video/mp4)::QueueAsyncSimpleEvent: Queuing event 'update'
[Main Thread]: D/MediaSource SourceBuffer(139d3ad00:video/mp4)::QueueAsyncSimpleEvent: Queuing event 'updateend'
[Main Thread]: D/MediaSource SourceBuffer(139d3ad00:video/mp4)::DispatchSimpleEvent: Dispatch event 'update'
[Main Thread]: D/MediaSource SourceBuffer(139d3ad00:video/mp4)::DispatchSimpleEvent: Dispatch event 'updateend'
[Main Thread]: D/MediaSource MediaSource(12fbe6040)::SetDuration: SetDuration(aDuration=0.500000, ErrorResult)
[Main Thread]: D/MediaSource MediaSource(12fbe6040)::DurationChange: DurationChange(aNewDuration=0.500000)
[Main Thread]: D/MediaSource TrackBuffersManager(12ea0b000:video/mp4)::Buffered: 
[Main Thread]: V/MediaSource SourceBuffer(139d3ad00:video/mp4)::GetBuffered: intersection=[(0.033200, 0.510839)]
[Main Thread]: D/MediaSource MediaSourceResource(12fbd5180:)::GetLength: UNIMPLEMENTED FUNCTION at /Users/jyavenard/Work/Mozilla/mozilla-central/dom/media/mediasource/MediaSourceResource.h:43
[Main Thread]: D/MediaSource MediaSourceResource(12fbd5180:)::SetPlaybackRate: UNIMPLEMENTED FUNCTION at /Users/jyavenard/Work/Mozilla/mozilla-central/dom/media/mediasource/MediaSourceResource.h:37
[Main Thread]: D/MediaSource MediaSource(12fbe6040)::SetDuration: SetDuration(aDuration=0.510839, ErrorResult)
[Main Thread]: D/MediaSource MediaSource(12fbe6040)::DurationChange: DurationChange(aNewDuration=0.510839)
[Main Thread]: D/MediaSource MediaSource(12fbe6040)::EndOfStream: EndOfStream(aError=0)
[Main Thread]: D/MediaSource MediaSource(12fbe6040)::SetReadyState: SetReadyState(aState=2) mReadyState=1

The problem here is that remove was called with (0.5, Infinity) ; however the MFR has already decoded everything there was to decode in the sourcebuffer.
Once we've reached the end of the queued buffer.
We stay in waiting mode.

we also don't seek back to the duration as it should if currentTime was > duration.

Comment 1

[Jean-Yves Avenard [:jya]]

Attachment: Bug 1293646: [MSE] P1. Reject seeking attempt with EOS when the mediasource is ended.

Otherwise, the ended event would never be fired should the decoder have reached the end of the stream prior endOfStream being called.

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

Comment 2

[Jean-Yves Avenard [:jya]]

Attachment: Bug 1293646: [MSE] P2. Only reject a seek request with EOS if it's passed the explicit duration.

With MSE, the actual duration is always exact as it is amended when data is added. We do not want to fire ended when we attempt to seek to unbuffered data once endOfStream has been called. Instead we will fire the waiting event.

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

Comment 3

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

Comment on attachment 8779622 [details]
Bug 1293646: [MSE] P1. Reject seeking attempt with EOS when the mediasource is ended.

https://reviewboard.mozilla.org/r/70574/#review67948

r+ with nits:

In commit description: "prior" -> "prior to".

::: dom/media/mediasource/MediaSourceDemuxer.cpp:390
(Diff revision 1)
> -      return SeekPromise::CreateAndReject(DemuxerFailureReason::WAITING_FOR_DATA,
> -                                          __func__);
> +      return SeekPromise::CreateAndReject(
> +        mManager->IsEnded() ? DemuxerFailureReason::END_OF_STREAM :
> +                              DemuxerFailureReason::WAITING_FOR_DATA, __func__);

The style is a bit strange here, I'd put ", __func__" on a separate line, left-aligned with mManager.

Comment 4

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

Comment on attachment 8779623 [details]
Bug 1293646: [MSE] P2. Only reject a seek request with EOS if it's passed the explicit duration.

https://reviewboard.mozilla.org/r/70576/#review67950

r+ with nits:

In commit description: "passed" -> "past".

::: dom/media/MediaFormatReader.h:14
(Diff revision 1)
>  #include "mozilla/Atomics.h"
>  #include "mozilla/Maybe.h"
> -#include "mozilla/TaskQueue.h"
>  #include "mozilla/Monitor.h"
> +#include "mozilla/StateMirroring.h"
> +#include "mozilla/TaskQueue.h"

Praise: Thank you for reordering the #includes! :-)

::: dom/media/MediaFormatReader.cpp:80
(Diff revision 1)
>    , mIsEncrypted(false)
>    , mTrackDemuxersMayBlock(false)
>    , mDemuxOnly(false)
>    , mSeekScheduled(false)
>    , mVideoFrameContainer(aVideoFrameContainer)
> +  , mExplicitDuration(mTaskQueue, Maybe<double>(), "MediaFormatReader::mExplicitDuration(Mirror)")

Tip: You can use 'Nothing()' to initialize any Maybe<T> with nothing.

::: dom/media/MediaFormatReader.cpp:1088
(Diff revision 1)
> +                        // We want to enter EOS when performing an
> +                        // internal seek only if we're attempting to seek past
> +                        // the explicit duration to avoid unwanted ended
> +                        // event to be fired.
> +                        if (self->mExplicitDuration.Ref().isSome() &&
> +                            decoder.mTimeThreshold.ref().Time() < TimeUnit::FromSeconds(self->mExplicitDuration.Ref().ref())) {

Style: Line is too long.

::: dom/media/MediaFormatReader.cpp:1742
(Diff revision 1)
>      mVideo.mSeekRequest.Complete();
>    } else {
>      mAudio.mSeekRequest.Complete();
>    }
>  
> +  // We want to enter EOS when performing aseek only if we're attempting to

Typo: 'aseek' -> 'a seek'.

Comment 5

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

Comment on attachment 8779623 [details]
Bug 1293646: [MSE] P2. Only reject a seek request with EOS if it's passed the explicit duration.

https://reviewboard.mozilla.org/r/70576/#review67952

::: dom/media/MediaFormatReader.cpp:259
(Diff revision 1)
>      metadata->mInfo = mInfo;
>      metadata->mTags = nullptr;
>      return MetadataPromise::CreateAndResolve(metadata, __func__);
>    }
>  
> +  mExplicitDuration.Connect(static_cast<MediaDecoder*>(mDecoder)->CanonicalExplicitDuration());

Move CanonicalExplicitDuration up the class hierarchy so we don't need this tricky static_cast.

Comment 6

[Jean-Yves Avenard [:jya]]

Comment on attachment 8779622 [details]
Bug 1293646: [MSE] P1. Reject seeking attempt with EOS when the mediasource is ended.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/70574/diff/1-2/

Comment 7

[Jean-Yves Avenard [:jya]]

Comment on attachment 8779623 [details]
Bug 1293646: [MSE] P2. Only reject a seek request with EOS if it's passed the explicit duration.

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/70576/diff/1-2/

Comment 8

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/35f12e09005a
[MSE] P1. Reject seeking attempt with EOS when the mediasource is ended. r=gerald
https://hg.mozilla.org/integration/autoland/rev/5a949eb358e2
[MSE] P2. Only reject a seek request with EOS if it's passed the explicit duration. r=gerald

Comment 9

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/35f12e09005a
https://hg.mozilla.org/mozilla-central/rev/5a949eb358e2

Comment 10

[Maire Reavy [:mreavy]]

@jya -- Can you request uplift to Aurora & Beta?  Thanks.

Comment 11

[Jean-Yves Avenard [:jya]]

Comment on attachment 8779622 [details]
Bug 1293646: [MSE] P1. Reject seeking attempt with EOS when the mediasource is ended.

Request is for both patches.

2nd patches may need rebasing with beta.

Approval Request Comment
[Feature/regressing bug #]: MSE
[User impact if declined]: Video stalling or playback never finishing which with youtube would prevent going to the next video.
[Describe test coverage new/current, TreeHerder]: Manual test, in central.
[Risks and why]: Low. We handle seeking in the same fashion as the other mode, properly detecting when the mediasource is ended.
[String/UUID change made/needed]: none

Comment 12

[Ritu Kothari (:ritu) (Inactive, please n-i to RyanVM, jcristau, or pascal)]

Comment on attachment 8779622 [details]
Bug 1293646: [MSE] P1. Reject seeking attempt with EOS when the mediasource is ended.

Fixes a regression (which would make end-user experience when watching a youtube playlist less than ideal), Aurora50+, Beta49+

Comment 13

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/252ceee6fee8
https://hg.mozilla.org/releases/mozilla-aurora/rev/da5b828c39ce

Comment 14

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-beta/rev/202cbd5602d5
https://hg.mozilla.org/releases/mozilla-beta/rev/77701a10e980