Intermittent test_FrameSelection_mp4.html | Test timed out.

RESOLVED FIXED in Firefox 49

Status

()

defect
P1
normal
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: philor, Assigned: jya)

Tracking

(Blocks 1 bug, {intermittent-failure})

unspecified
mozilla49
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox49 fixed)

Details

Attachments

(5 attachments)

Component: Audio/Video → Audio/Video: Playback
Comment hidden (Intermittent Failures Robot)
Flags: needinfo?(jyavenard)
Assignee

Updated

3 years ago
Assignee: nobody → jyavenard
Flags: needinfo?(jyavenard)
Assignee

Updated

3 years ago
Priority: P5 → P1
Comment hidden (Intermittent Failures Robot)
Assignee

Comment 3

3 years ago
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.
Assignee

Updated

3 years ago
Blocks: 1244410, 1272964
Assignee

Comment 4

3 years ago
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)
Assignee

Comment 7

3 years ago
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/
Assignee

Comment 8

3 years ago
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/
Assignee

Comment 9

3 years ago
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.
Assignee

Updated

3 years ago
See Also: → 1274933
Assignee

Updated

3 years ago
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+
Assignee

Comment 15

3 years ago
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/
Assignee

Comment 16

3 years ago
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/
Assignee

Comment 17

3 years ago
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/
Assignee

Comment 18

3 years ago
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/
Assignee

Comment 19

3 years ago
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/
Comment hidden (Intermittent Failures Robot)
You need to log in before you can comment on or make changes to this bug.