Closed Bug 1234742 Opened 8 years ago Closed 7 years ago

Intermittent test_WaitingToEndedTransition_mp4.html | Video has correct currentTime. - got 3.900907, expected 3.854512

Categories

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

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

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: philor, Assigned: jya)

References

Details

(Keywords: intermittent-failure)

Component: Audio/Video → Audio/Video: Playback
Assignee: nobody → jyavenard
JW, how can it be possible for currentTime to be > video.duration ? (intermittently) doesn't happen often. but it does :(

The video track last frame end at 3.838344 and the audio track ends at 3.854512. (per spec, when a mediasource is end of stream, the duration is set to the "set to the highest end time reported by the buffered attribute across all SourceBuffer objects in sourceBuffers.")

Getting a currentTime of 3.900907 is very puzzling.
Flags: needinfo?(jwwang)
this started shortly after bug 1229987 went in
Depends on: 1229987
https://hg.mozilla.org/mozilla-central/file/0771c5eab32f0cee4f7d12bc382298a81e0eabb2/dom/media/MediaDecoderStateMachine.cpp#l2490

The current time is capped to the maximum of audio and video end time. You can check the end time of each audio/video sample to see if there is anything wrong.

According to your logs, the end time of each video frame should be smaller than 3.838344.
Flags: needinfo?(jwwang)
You're not telling me anything new. Did you read my comment? :)

As mentioned no frame (audio or video) has an end time greater than 3.85. So how can currentTime ever be 3.90 (and in particular here also greater than duration!)
That is my question!
You talked about the end time of last audio/video frame. However, I suspect if there are any abnormal frames in the middle which have incorrect end times. I think that should be impossible though.

Another possibility I can think of is  MediaDecoder::mExplicitDuration is set to an abnormal value.
This is MSE, and in this case we control the input. All frames are in strict order.
now this seems to have only happened on windows, maybe it's the windows decoder that from time to time returns rubbish timestamp.

Chris, do you think this could be a possibility?

But having said that, if one of the frame had an invalid time, then duration would have been updated too and we should still have currentTime == duration when the video is ended.
(In reply to Jean-Yves Avenard [:jya] from comment #7)
> This is MSE, and in this case we control the input. All frames are in strict
> order.
> now this seems to have only happened on windows, maybe it's the windows
> decoder that from time to time returns rubbish timestamp.
> 
> Chris, do you think this could be a possibility?

cpearce: see Jean-Yves' question in comment 7.
Flags: needinfo?(cpearce)
Priority: -- → P5
Priority: P5 → P2
(In reply to Chris Peterson [:cpeterson] from comment #8)
> (In reply to Jean-Yves Avenard [:jya] from comment #7)
> > This is MSE, and in this case we control the input. All frames are in strict
> > order.
> > now this seems to have only happened on windows, maybe it's the windows
> > decoder that from time to time returns rubbish timestamp.
> > 
> > Chris, do you think this could be a possibility?
> 
> cpearce: see Jean-Yves' question in comment 7.

I've seen the WMF decoder output with negative timestamps at the start of an AAC stream. That's about the only thing I can think of.

Bryce was just able repro currentTime being after the duration with his patches to make WebM without Cues seekable. If he plays through no-cues.webm, when he hits the end of stream we end up calling RecomputeDuration(), which changes the duration. I'm guessing the last frame in no-cues.webm is damaged and/or has a bogus end time, and we're moving the duration to match the last frame's end time.

Something similar could be happening for this MSE/MP4 case.
Flags: needinfo?(cpearce)
I've opened a bug about that (currentTime being past duration).. To me this is a bug in the MediaDecoder/MDSM
bug 1233639

The MDSM stops sometime requesting new frames, so the MediaFormatReader never get the chance to report EOS.

Re: negative timestamp, shouldn't happen here as the timestamps in the container are always >= 0
(In reply to Jean-Yves Avenard [:jya] from comment #10)
> The MDSM stops sometime requesting new frames, so the MediaFormatReader
> never get the chance to report EOS.
Maybe this is already fixed by reccent prerolling bugs.
(In reply to Chris Pearce (:cpearce) from comment #9)
> I've seen the WMF decoder output with negative timestamps at the start of an
> AAC stream. That's about the only thing I can think of.
Negative timestamps with non-zero frame numbers? This could be a problme to DecodedAudioDataSink which doens't drop frames starting before mStartTime.
(In reply to Jean-Yves Avenard [:jya] from comment #10)
> I've opened a bug about that (currentTime being past duration).. To me this
> is a bug in the MediaDecoder/MDSM
> bug 1233639

We see this in seek.webm too, i.e. the one with Cues. This happens in videos without an audio stream, but it seems bug 1233639 is related to something that only happens when a file has an audio stream?

> Re: negative timestamp, shouldn't happen here as the timestamps in the
> container are always >= 0

The WMF decoder outputs samples with negative timestamps. It's independent of the container.

This is an example of a file for which the WMF AAC decoder outputs a sample with a negative timestamp as the first audio sample:
http://people.mozilla.org/~jyavenard/tests/mse_mp4/facebook-paper.mp4

(In reply to JW Wang [:jwwang] from comment #12)
> Negative timestamps with non-zero frame numbers?

Yes.
(In reply to Chris Pearce (:cpearce) from comment #13)
> (In reply to Jean-Yves Avenard [:jya] from comment #10)
> > I've opened a bug about that (currentTime being past duration).. To me this
> > is a bug in the MediaDecoder/MDSM
> > bug 1233639
> 
> We see this in seek.webm too, i.e. the one with Cues. This happens in videos
> without an audio stream, but it seems bug 1233639 is related to something
> that only happens when a file has an audio stream?
> 
> > Re: negative timestamp, shouldn't happen here as the timestamps in the
> > container are always >= 0
> 
> The WMF decoder outputs samples with negative timestamps. It's independent
> of the container.
> 
> This is an example of a file for which the WMF AAC decoder outputs a sample
> with a negative timestamp as the first audio sample:
> http://people.mozilla.org/~jyavenard/tests/mse_mp4/facebook-paper.mp4

Nothing abnormal there.
The first audio frame *is* negative
from ffprobe:
[PACKET]
stream_index=1
pts_time=-0.021333
duration_time=N/A
[/PACKET]
[PACKET]
stream_index=1
pts_time=0.000000
duration_time=0.021333
[/PACKET]

So I would expect the WMF to output a negative timestamp for the first frame; it has to.
I was able to reproduce this bug after looping dom/media/mediasource/test 28 times on my Win7 laptop.
I tried to print the audio samples when |audio->mTime >= 3854512 which is the duration| and found out:
[MediaPlayback #8]: D/MediaDecoder Decoder=b3b2f20 OnAudioDecoded [3854512,3900951] disc=0

This is what resulted in |el.currentTime > el.duration| and failed the test.

I wonder why the timestamps of audio samples are not deterministic? We should have fixed values for each playback.
Flags: needinfo?(jyavenard)
They should. The duration and timestamps stored in the MSE track buffer certainly are.

I can't foresee a case where MSE would have a different buffered range.

The WMF decoder appears to create its own timestamps from time to time by the look of things
Flags: needinfo?(jyavenard)
Following the changes that could cause the audio being played to be resampled, this is now a permafail. 
https://treeherder.mozilla.org/#/jobs?repo=try&revision=4de04ad1ad0263e1ab7b918d7f3b948c91e43751

This indicates to me that the currentTime is being adjusted according to what goes in the AudioSink which could be wrong. For example, if for whatever reason audio decoding was late and we underrun, or if all audio frames got popped while the AudioStream is still goin, silence would be played by the DecodedAudioDataSink which would increase the amount of frames written regardless of the real time.

This would affect the value of DecodedAudioDataSink::GetEndTime. This could be an explanation on why sometimes we finish later than duration: we have a race between MediaSink:Shutdown and AudioStream/cubeb actually stopping to request new frames.
(In reply to Jean-Yves Avenard [:jya] from comment #23)
> For example, if for
> whatever reason audio decoding was late and we underrun, or if all audio
> frames got popped while the AudioStream is still goin, silence would be
> played by the DecodedAudioDataSink which would increase the amount of frames
> written regardless of the real time.

Can you point me at the code where DecodedAudioDataSink inserts silence?
This would have been fixed in bug 1264199, P9.
Status: NEW → RESOLVED
Closed: 8 years ago
Resolution: --- → WORKSFORME
Still happening on trunk per OrangeFactor.
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Mass change P2 -> P3
Priority: P2 → P3
I'm back working on my mac after two weeks spent on windows.

This code now permafails on my mac running 10.12.6

TEST-UNEXPECTED-FAIL | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | Video has correct currentTime. - got 3.85452, expected 3.854512

JW, Are you aware of any recent changes that could cause this problem?

trying to find a regression range.
Flags: needinfo?(jwwang)
didn't happen in a year.
issue with the test failing is discussed in bug 1398139
Status: REOPENED → RESOLVED
Closed: 8 years ago → 7 years ago
Flags: needinfo?(jwwang)
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.