Closed
Bug 1270323
Opened 9 years ago
Closed 8 years ago
Intermittent test_FrameSelection_mp4.html | Test timed out.
Categories
(Core :: Audio/Video: Playback, defect, P1)
Core
Audio/Video: Playback
Tracking
()
RESOLVED
FIXED
mozilla49
Tracking | Status | |
---|---|---|
firefox49 | --- | fixed |
People
(Reporter: philor, Assigned: jya)
References
(Blocks 1 open bug)
Details
(Keywords: intermittent-failure)
Attachments
(5 files)
58 bytes,
text/x-review-board-request
|
cpearce
:
review+
|
Details |
58 bytes,
text/x-review-board-request
|
cpearce
:
review+
|
Details |
58 bytes,
text/x-review-board-request
|
cpearce
:
review+
|
Details |
58 bytes,
text/x-review-board-request
|
cpearce
:
review+
|
Details |
58 bytes,
text/x-review-board-request
|
cpearce
:
review+
|
Details |
Updated•9 years ago
|
Component: Audio/Video → Audio/Video: Playback
Comment hidden (Intermittent Failures Robot) |
Updated•8 years ago
|
Flags: needinfo?(jyavenard)
Updated•8 years ago
|
Priority: -- → P5
Assignee | ||
Updated•8 years ago
|
Assignee: nobody → jyavenard
Flags: needinfo?(jyavenard)
Assignee | ||
Updated•8 years ago
|
Priority: P5 → P1
Comment hidden (Intermittent Failures Robot) |
Assignee | ||
Comment 3•8 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•8 years ago
|
Assignee | ||
Comment 4•8 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 5•8 years ago
|
||
Followup from bug 1272964 P4.
Review commit: https://reviewboard.mozilla.org/r/54526/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/54526/
Assignee | ||
Comment 6•8 years ago
|
||
Amendment to bug 1244410. If no frames had been output yet, last dts would have been INT64_MIN.
Review commit: https://reviewboard.mozilla.org/r/54528/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/54528/
Assignee | ||
Comment 7•8 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•8 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•8 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.
Comment 10•8 years ago
|
||
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 11•8 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
https://reviewboard.mozilla.org/r/54526/#review51352
Attachment #8755309 -
Flags: review?(cpearce) → review+
Updated•8 years ago
|
Attachment #8755310 -
Flags: review?(cpearce) → review+
Comment 12•8 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
https://reviewboard.mozilla.org/r/54528/#review51354
Updated•8 years ago
|
Attachment #8755311 -
Flags: review?(cpearce) → review+
Comment 13•8 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
https://reviewboard.mozilla.org/r/54530/#review51356
Comment 14•8 years ago
|
||
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•8 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•8 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•8 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•8 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•8 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 20•8 years ago
|
||
https://hg.mozilla.org/integration/mozilla-inbound/rev/f17f688f419c
https://hg.mozilla.org/integration/mozilla-inbound/rev/adc18bf4eac2
https://hg.mozilla.org/integration/mozilla-inbound/rev/f4b4c6f24fc3
https://hg.mozilla.org/integration/mozilla-inbound/rev/c39eb78d3600
https://hg.mozilla.org/integration/mozilla-inbound/rev/5613020111ba
Comment 21•8 years ago
|
||
bugherder |
https://hg.mozilla.org/mozilla-central/rev/f17f688f419c
https://hg.mozilla.org/mozilla-central/rev/adc18bf4eac2
https://hg.mozilla.org/mozilla-central/rev/f4b4c6f24fc3
https://hg.mozilla.org/mozilla-central/rev/c39eb78d3600
https://hg.mozilla.org/mozilla-central/rev/5613020111ba
Status: NEW → RESOLVED
Closed: 8 years ago
status-firefox49:
--- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla49
Comment hidden (Intermittent Failures Robot) |
You need to log in
before you can comment on or make changes to this bug.
Description
•