Closed Bug 1270323 Opened 8 years ago Closed 8 years ago

Intermittent test_FrameSelection_mp4.html | Test timed out.

Categories

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

Product:
Core
Component:
Audio/Video: Playback
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla49
Tracking Flags:
Tracking Status
firefox49 --- fixed

People

(Reporter: philor, Assigned: jya)

References

(Blocks 1 open bug)

Details

(Keywords: intermittent-failure)

Attachments

(5 files)

MozReview Request: Bug 1270323: P1. Don't reset flag indicating that new data was received. r?cpearce
58 bytes, text/x-review-board-request
cpearce
: review+
Details
MozReview Request: Bug 1270323: P2. Don't process new incoming data while a skip to next keyframe is pending. r?cpearce
58 bytes, text/x-review-board-request
cpearce
: review+
Details
MozReview Request: Bug 1270323: [ffmpeg] P3. Use the dts of the last sample input, not the dts of the last decoded sample. r?cpearce
58 bytes, text/x-review-board-request
cpearce
: review+
Details
MozReview Request: Bug 1270323: P4. Don't drain decoder if we're already waiting for new data. r?cpearce
58 bytes, text/x-review-board-request
cpearce
: review+
Details
MozReview Request: Bug 1270323: P5. Prevent potential null deref. r?cpearce
58 bytes, text/x-review-board-request
cpearce
: review+
Details
Component: Audio/Video → Audio/Video: Playback
Flags: needinfo?(jyavenard)
Assignee: nobody → jyavenard
Flags: needinfo?(jyavenard)
Priority: P5 → P1
While the try error is only showing up on Linux, I don't think it's linux only. It just happens to fail with ASAN because it's particularly slow.

I've managed to reproduce it on Windows 10 with debug/non-optimised.

The issue occurs when a waiting promise isn't resolved even when we are received new data. (same issue as what's still causing dom/media/mediasource/test/test_BufferingWait_mp4.html to timeout intermittently)

Adding some logging I see:
 05:23:10     INFO -  video state: ni=0 no=0 ie=0 demuxr:0 demuxq:0 decoder:1 tt:-1.000000 tths:-1 in:3 out:3 qs=1 pending:1 waiting:1 rnewdata:1 sid:13

So we have a pending frames, ready to be output, yet we are in waiting mode and mReceivedNewData is true. That's bad.

[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Video)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Video
[MediaPlayback #1]: D/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Seeking to last sample time: 1763332
[MediaPlayback #1]: D/MediaFormatReader MediaFormatReader(61e0000f9c80)::InternalSeek: Video internal seek to 1.763332
[MediaPlayback #1]: D/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Rejecting Video promise: WAITING_FOR_DATA
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Nothing more to do
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Video)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Video
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Update(Video) ni=1 no=0 ie=0, in:0 out:0 qs=0 pending:0 waiting:1 ahead:1 sid:13
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::RequestDemuxSamples: Requesting extra demux Video
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::OnVideoDemuxCompleted: 1 video samples demuxed (sid:13)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Video)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Video
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Update(Video) ni=1 no=0 ie=0, in:0 out:0 qs=0 pending:0 waiting:1 ahead:1 sid:13
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::HandleDemuxedSamples: Giving Video input to decoder
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::HandleDemuxedSamples: Input:1696666 (dts:1696666 kf:1)
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::NotifyInputExhausted: Decoder has requested more Video data
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Video)
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Video
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Update(Video) ni=1 no=0 ie=1, in:1 out:0 qs=1 pending:0 waiting:1 ahead:1 sid:13
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::RequestDemuxSamples: Requesting extra demux Video
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::OnVideoDemuxCompleted: 1 video samples demuxed (sid:13)
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Video)
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Video
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Update(Video) ni=1 no=0 ie=1, in:1 out:0 qs=1 pending:0 waiting:1 ahead:1 sid:13
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::HandleDemuxedSamples: Giving Video input to decoder
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::HandleDemuxedSamples: Input:1763332 (dts:1728623 kf:0)
[MediaPDecoder #2]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Output: Decoded Video sample time=1696666 timecode=-1 kf=1 dur=33345
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::NotifyNewOutput: Received new Video sample time:1696666 duration:33345
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Video)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Video
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Internal Seeking: Dropping Video frame time:1.696666 wanted:1.763332 (kf:1)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Update(Video) ni=1 no=0 ie=0, in:2 out:1 qs=1 pending:0 waiting:1 ahead:1 sid:13
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::RequestDemuxSamples: Requesting extra demux Video
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::OnVideoDemuxCompleted: 1 video samples demuxed (sid:13)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Video)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Video
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Update(Video) ni=1 no=0 ie=0, in:2 out:1 qs=1 pending:0 waiting:1 ahead:1 sid:13
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::HandleDemuxedSamples: Giving Video input to decoder
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::HandleDemuxedSamples: Input:1730010 (dts:1760582 kf:0)
[MediaPDecoder #2]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Output: Decoded Video sample time=1730010 timecode=-1 kf=0 dur=33322
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::NotifyNewOutput: Received new Video sample time:1730010 duration:33322
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Video)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Video
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Internal Seeking: Dropping Video frame time:1.730010 wanted:1.763332 (kf:0)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Update(Video) ni=1 no=0 ie=0, in:3 out:2 qs=1 pending:0 waiting:1 ahead:1 sid:13
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::RequestDemuxSamples: Requesting extra demux Video
[MediaPlayback #1]: D/MediaFormatReader MediaFormatReader(61e0000f9c80)::OnDemuxFailed: Failed to demux video, failure:1
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Video)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Video
[MediaPlayback #1]: D/MediaFormatReader MediaFormatReader(61e0000f9c80)::DrainDecoder: Requesting Video decoder to drain
[MediaPDecoder #2]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Output: Decoded Video sample time= timecode=-1 kf=0 dur=0
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::NotifyDemuxer: 
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Video)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Audio)
[MediaPlayback #1]: D/MediaFormatReader MediaFormatReader(61e0000f9c80)::UpdateReceivedNewData: We have new data. Resolving WaitingPromise
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Video
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Update(Video) ni=0 no=0 ie=0, in:3 out:2 qs=1 pending:0 waiting:1 ahead:1 sid:13
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: No need for additional input (pending:0)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Audio
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Update(Audio) ni=0 no=0 ie=1, in:4 out:4 qs=0 pending:0 waiting:0 ahead:1 sid:13
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: No need for additional input (pending:0)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::RequestAudioData: 
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Audio)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Audio
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Update(Audio) ni=1 no=1 ie=1, in:4 out:4 qs=0 pending:0 waiting:0 ahead:0 sid:13
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::RequestDemuxSamples: Requesting extra demux Audio
[MediaPlayback #1]: D/MediaFormatReader MediaFormatReader(61e0000f9c80)::OnDemuxFailed: Failed to demux audio, failure:1
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Audio)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Audio
[MediaPlayback #1]: D/MediaFormatReader MediaFormatReader(61e0000f9c80)::NotifyDrainComplete: Audio
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Audio)
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Audio
[MediaPlayback #1]: D/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Rejecting Audio promise: EOS
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Update(Audio) ni=0 no=1 ie=1, in:4 out:4 qs=0 pending:0 waiting:0 ahead:1 sid:13
[MediaPlayback #1]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: No need for additional input (pending:0)
[Main Thread]: D/MediaFormatReader MediaFormatReader(61e0000f9c80)::operator(): Reporting telemetry DROPPED_FRAMES_IN_VIDEO_PLAYBACK
[MediaPlayback #4]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::NotifyNewOutput: Received new Video sample time:1763332 duration:0
[MediaPlayback #4]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Video)
[MediaPlayback #4]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Video
[MediaPlayback #4]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Update(Video) ni=0 no=0 ie=0, in:3 out:3 qs=1 pending:1 waiting:1 ahead:1 sid:13
[MediaPlayback #4]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Still waiting for data.
[MediaPlayback #3]: D/MediaFormatReader MediaFormatReader(61e0000f9c80)::NotifyDrainComplete: Video
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::ScheduleUpdate: SchedulingUpdate(Video)
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Processing update for Video
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Update(Video) ni=0 no=0 ie=0, in:3 out:3 qs=1 pending:1 waiting:1 ahead:1 sid:13
[MediaPlayback #3]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Update: Still waiting for data.


We can see here that right after draining the decoder as a demux failed with WAITING_FOR_DATA, while we are doing the internal seeking, we get a failure this time as EOS as mediasource.endOfStream() was called.

And immediately after we get the notification that data was added.

However, when receiving the EOS we signal to drain the decoder again. By this time, we have already rejected the video promise with WAITING_FOR_DATA and we have a waiting promise waiting.

When UpdateReceivedNewData is sees that we're in the middle of draining and does nothing.

However MediaFormatReader::Update() expects that the only time we could be draining is when we have a pending media data promise; and as such, the waiting promise isn't resolved.

result? stall.
Blocks: 1244410, 1272964
A bit of a shot in the dark, but it is possible that data got received but that information got lost as reset was called.

Review commit: https://reviewboard.mozilla.org/r/54524/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/54524/
Attachment #8755308 - Flags: review?(cpearce)
Attachment #8755309 - Flags: review?(cpearce)
Attachment #8755310 - Flags: review?(cpearce)
Attachment #8755311 - Flags: review?(cpearce)
Attachment #8755312 - Flags: review?(cpearce)
If we're in waiting for data mode, the decoder must have already been drained and we want the waiting promise to be resolved upon the next run of UpdateReceivedNewData.

Review commit: https://reviewboard.mozilla.org/r/54530/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/54530/
This currently can't happen as no MediaDataDecoder ever return a null sample.

Review commit: https://reviewboard.mozilla.org/r/54532/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/54532/
Another issue seen, but only on linux and I suspect would only happen with an old version of LibAV like what try is using:

[MediaPlayback #1]: D/MediaFormatReader MediaFormatReader(61e0000f9c80)::DrainDecoder: Requesting Video decoder to drain
[MediaPDecoder #2]: V/MediaFormatReader MediaFormatReader(61e0000f9c80)::Output: Decoded Video sample time= timecode=-1 kf=0 dur=0

Sometimes, when asking the decoder to drain we get a crap output, this appears to be the empty sample we pass to the ffmpeg decoder to drain. for some reason it's being output.
See Also: → 1274933
Blocks: MSE
Comment on attachment 8755308 [details]
MozReview Request: Bug 1270323: P1. Don't reset flag indicating that new data was received. r?cpearce

https://reviewboard.mozilla.org/r/54524/#review51350
Attachment #8755308 - Flags: review?(cpearce) → review+
Comment on attachment 8755309 [details]
MozReview Request: Bug 1270323: P2. Don't process new incoming data while a skip to next keyframe is pending. r?cpearce

https://reviewboard.mozilla.org/r/54526/#review51352
Attachment #8755309 - Flags: review?(cpearce) → review+
Attachment #8755310 - Flags: review?(cpearce) → review+
Comment on attachment 8755310 [details]
MozReview Request: Bug 1270323: [ffmpeg] P3. Use the dts of the last sample input, not the dts of the last decoded sample. r?cpearce

https://reviewboard.mozilla.org/r/54528/#review51354
Attachment #8755311 - Flags: review?(cpearce) → review+
Comment on attachment 8755311 [details]
MozReview Request: Bug 1270323: P4. Don't drain decoder if we're already waiting for new data. r?cpearce

https://reviewboard.mozilla.org/r/54530/#review51356
Comment on attachment 8755312 [details]
MozReview Request: Bug 1270323: P5. Prevent potential null deref. r?cpearce

https://reviewboard.mozilla.org/r/54532/#review51358
Attachment #8755312 - Flags: review?(cpearce) → review+
Comment on attachment 8755308 [details]
MozReview Request: Bug 1270323: P1. Don't reset flag indicating that new data was received. r?cpearce

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/54524/diff/1-2/
Comment on attachment 8755309 [details]
MozReview Request: Bug 1270323: P2. Don't process new incoming data while a skip to next keyframe is pending. r?cpearce

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/54526/diff/1-2/
Comment on attachment 8755310 [details]
MozReview Request: Bug 1270323: [ffmpeg] P3. Use the dts of the last sample input, not the dts of the last decoded sample. r?cpearce

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/54528/diff/1-2/
Comment on attachment 8755311 [details]
MozReview Request: Bug 1270323: P4. Don't drain decoder if we're already waiting for new data. r?cpearce

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/54530/diff/1-2/
Comment on attachment 8755312 [details]
MozReview Request: Bug 1270323: P5. Prevent potential null deref. r?cpearce

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/54532/diff/1-2/
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: