1986372 - Android fragmented-mp4-end.html timeout due to stalled decoder drain

Status: RESOLVED FIXED

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

Description

[Karl Tomlinson (:karlt)]

When the test times out, the RemoteDataDecoder returns the first available output sample when available after Drain() and receives all remaining 7 remaining output samples, except an empty EOS frame, before MediaFormatReader calls Drain() again.

RemoteDataDecoder does not return the available samples on the second Drain() call.

https://treeherder.mozilla.org/jobs?repo=try&selectedTaskRun=C1xq2sfuTYCAcaYwD9Ljaw.0&revision=7f6e9f1f29cb33c480ee3dfb8fd64f0aa4d804a8

[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::SetState: 2
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ReturnDecodedData: have decode promise=0, have drain promise=1, state=2
:.h264.decoder] setting dataspace on output surface to #103
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ProcessOutput: flags=0 size=3110400 presentationTimeUs=1750000
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ReturnDecodedData: have decode promise=0, have drain promise=1, state=2
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ProcessOutput: flags=0 size=3110400 presentationTimeUs=1791666
[MediaSupervisor #1]: V/MediaFormatReader MediaFormatReader[7fe775bd0e00] ::NotifyNewOutput: Received new Video sample time:1750000 duration:41666
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ReturnDecodedData: have decode promise=0, have drain promise=0, state=2
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ProcessOutput: flags=0 size=3110400 presentationTimeUs=1833333
[MediaSupervisor #1]: D/MediaFormatReader MediaFormatReader[7fe775bd0e00] ::NotifyNewOutput: Done processing new Video samples
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ReturnDecodedData: have decode promise=0, have drain promise=0, state=2
[MediaSupervisor #1]: V/MediaFormatReader MediaFormatReader[7fe775bd0e00] ::ScheduleUpdate: SchedulingUpdate(Video)
[MediaSupervisor #1]: V/MediaFormatReader MediaFormatReader[7fe775bd0e00] ::Update: Processing update for Video
[MediaSupervisor #1]: V/MediaFormatReader MediaFormatReader[7fe775bd0e00] ::UpdateReceivedNewData: !decoder.mReceivedNewData
[MediaSupervisor #1]: D/MediaFormatReader MediaFormatReader[7fe775bd0e00] ::ReturnOutput: Resolved data promise for Video [1750000, 1791666]
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ProcessOutput: flags=0 size=3110400 presentationTimeUs=1875000
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ReturnDecodedData: have decode promise=0, have drain promise=0, state=2
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ProcessOutput: flags=0 size=3110400 presentationTimeUs=1916666
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ReturnDecodedData: have decode promise=0, have drain promise=0, state=2
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ProcessOutput: flags=0 size=3110400 presentationTimeUs=1958333
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ReturnDecodedData: have decode promise=0, have drain promise=0, state=2
[MediaSupervisor #1]: D/MediaFormatReader MediaFormatReader[7fe775bd0e00] ::DrainDecoder: Requesting Video decoder to drain
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ProcessOutput: flags=0 size=3110400 presentationTimeUs=2000000
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ReturnDecodedData: have decode promise=0, have drain promise=0, state=2
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ProcessOutput: flags=0 size=3110400 presentationTimeUs=2041666
[MediaDecoderStateMachine #1]: D/MediaDecoder MediaDecoderStateMachine[7fe776264c00] state=SEEKING_ACCURATE DropVideoUpToSeekTarget() frame [1666667, 1708333]
[MediaDecoderStateMachine #1]: D/MediaDecoder MediaDecoderStateMachine[7fe776264c00] state=SEEKING_ACCURATE DropVideoUpToSeekTarget() pop video frame [1666667, 1708333] target=1900000
[MediaPDecoder #1]: D/AndroidDecoderModule RemoteDataDecoder(7fe772d14200)::ReturnDecodedData: have decode promise=0, have drain promise=0, state=2
[MediaSupervisor #1]: V/MediaFormatReader MediaFormatReader[7fe775bd0e00] ::RequestVideoData: RequestVideoData(0), requestNextKeyFrame=0
[MediaSupervisor #1]: V/MediaFormatReader MediaFormatReader[7fe775bd0e00] ::ScheduleUpdate: SchedulingUpdate(Video)
[MediaSupervisor #1]: V/MediaFormatReader MediaFormatReader[7fe775bd0e00] ::Update: Processing update for Video
[MediaSupervisor #1]: V/MediaFormatReader MediaFormatReader[7fe775bd0e00] ::UpdateReceivedNewData: !decoder.mReceivedNewData
[MediaSupervisor #1]: V/MediaFormatReader MediaFormatReader[7fe775bd0e00] ::Update: Update(Video) ni=0 no=1 in:8 out:1 qs=7 decoding:0 flushing:0 desc:android decoder (remote) pending:0 waiting:0 eos:1 ds:2 sid:4294967295 waitcdm:0
[MediaSupervisor #1]: V/MediaFormatReader MediaFormatReader[7fe775bd0e00] ::Update: No need for additional input (pending:0)

Holding the output buffers has been observed to prevent the decoder from advancing to notify end of stream.
The same problem would occur though even if EOS were received before the second Drain() call.

There is a similar issue with errors, which are not reported if there is no promise pending at the time they are discovered.

Comment 1

[Karl Tomlinson (:karlt)]

The drain flaw comes from https://hg-edge.mozilla.org/mozilla-central/rev/fb0a390994d73d1029f111df8cc1950790ded48b#l1.113, though attempting to collect all drained frames in one batch may have had similar problems prior to that.

The similar flaw in error reporting comes from https://hg-edge.mozilla.org/mozilla-central/diff/b2171e3e8b6971c434a1c1424fac1484fe322351/dom/media/platforms/android/RemoteDataDecoder.cpp#l1.841

Comment 2

[Karl Tomlinson (:karlt)]

S2 because this would cause playback stalls.

Comment 3

[Karl Tomlinson (:karlt)]

Attachment: Bug 1986372 add Android RemoteDataDecoder state and video output and drain logging r?jolin

Comment 4

[Karl Tomlinson (:karlt)]

Attachment: Bug 1986372 Settle DecodePromises with drained samples or errors even when these arrive before the promise is created r?jolin

Comment 5

[Pulsebot]

Pushed by [e-mail]:
https://github.com/mozilla-firefox/firefox/commit/8f2533e3dae7
https://hg.mozilla.org/integration/autoland/rev/791982eaaf25
add Android RemoteDataDecoder state and video output and drain logging r=jolin

Comment 6

[Pulsebot]

Pushed by [e-mail]:
https://github.com/mozilla-firefox/firefox/commit/d6d3da73311c
https://hg.mozilla.org/integration/autoland/rev/1278aa8f8fcb
Settle DecodePromises with drained samples or errors even when these arrive before the promise is created r=jolin

Comment 7

[agoloman]

https://hg.mozilla.org/mozilla-central/rev/791982eaaf25

Comment 8

[Narcis Beleuzu [:NarcisB]]

https://hg.mozilla.org/mozilla-central/rev/1278aa8f8fcb

Comment 9

[Ryan VanderMeulen [:RyanVM]]

Do we need fragmented-mp4-end.html.ini now?

Comment 10

[Karl Tomlinson (:karlt)]

Ah, we don't, thanks. This run shows that resolving issue identified here with draining resolved the timeouts.
It was from before the fragmented-mp4-end.html.ini with timeout expectations existed.

Comment 11

[Karl Tomlinson (:karlt)]

Attachment: Bug 1986372 Remove intermittent fragmented-mp4-end.html timeout expectations r?#media-playback-reviewers

now that the cause of the stall during drain is addressed.

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://github.com/mozilla-firefox/firefox/commit/e2163bfee118
https://hg.mozilla.org/integration/autoland/rev/b0d1ce792b76
Remove intermittent fragmented-mp4-end.html timeout expectations r=media-playback-reviewers,aosmond

Comment 13

[pstanciu]

https://hg.mozilla.org/mozilla-central/rev/b0d1ce792b76