Closed Bug 1398139 Opened 2 years ago Closed 2 years ago

dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html fails on windows and mac 10.12

Categories

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

57 Branch
defect

Tracking

()

RESOLVED FIXED
mozilla57
Tracking Status
firefox-esr52 --- unaffected
firefox55 --- unaffected
firefox56 --- unaffected
firefox57 --- fixed

People

(Reporter: jmaher, Assigned: alwu)

References

()

Details

(Keywords: regression)

Attachments

(4 files)

we are moving our windows 8 tests on hardware to windows 10 hardware- same hardware, different operating system.

for the media tests, only 1 test fails:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=014799f4c401f271d60c20a3f2d5970478978599&filter-searchStr=media

here is a log file:
https://archive.mozilla.org/pub/firefox/try-builds/jmaher@mozilla.com-014799f4c401f271d60c20a3f2d5970478978599/try-win64-debug/try_win10_64-debug_test-mochitest-media-e10s-bm110-tests1-windows-build1.txt.gz


and here is a related bit from the log file:
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | fetchWithXHR load uri='bipbop/bipbop_video1.m4s' status=200 
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | fetchWithXHR load uri='bipbop/bipbop_video2.m4s' status=200 
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | fetchWithXHR load uri='bipbop/bipbop_video3.m4s' status=200 
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | fetchWithXHR load uri='bipbop/bipbop_video4.m4s' status=200 
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | fetchWithXHR load uri='bipbop/bipbop_video5.m4s' status=200 
05:34:15     INFO - Loading buffer: [0, 23860)
05:34:15     INFO - SourceBuffer buffered ranges grew from TimeRanges:  to TimeRanges: [0, 0.801666)
05:34:15     INFO - Loading buffer: [0, 21595)
05:34:15     INFO - SourceBuffer buffered ranges grew from TimeRanges: [0, 0.801666) to TimeRanges: [0, 1.601666)
05:34:15     INFO - Loading buffer: [0, 23429)
05:34:15     INFO - SourceBuffer buffered ranges grew from TimeRanges: [0, 1.601666) to TimeRanges: [0, 2.403333)
05:34:15     INFO - Loading buffer: [0, 22446)
05:34:15     INFO - SourceBuffer buffered ranges grew from TimeRanges: [0, 2.403333) to TimeRanges: [0, 3.203333)
05:34:15     INFO - Loading buffer: [0, 18191)
05:34:15     INFO - SourceBuffer buffered ranges grew from TimeRanges: [0, 3.203333) to TimeRanges: [0, 3.838344)
05:34:15     INFO - Invoking play()
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | Video playing. It should play for a bit, then fire 'waiting' 
05:34:15     INFO - Buffered messages logged at 05:34:15
05:34:15     INFO - TEST-PASS | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | Video has correct duration: 3.854512 
05:34:15     INFO - Buffered messages finished
05:34:15     INFO - TEST-UNEXPECTED-FAIL | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | Video has correct currentTime. - got 3.85452, expected 3.854512
05:34:15     INFO -     SimpleTest.is@SimpleTest/SimpleTest.js:312:5
05:34:15     INFO -     @dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html:47:7
05:34:15     INFO -     promise callback*@dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html:24:5
05:34:15     INFO -     promise callback*@dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html:16:3
05:34:15     INFO -     bootstrapTest@dom/media/mediasource/test/mediasource.js:29:5
05:34:15     INFO - GECKO(7368) | MEMORY STAT | vsize 1632MB | vsizeMaxContiguous 129993121MB | residentFast 103MB | heapAllocated 23MB
05:34:15     INFO - TEST-OK | dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html | took 5016ms
:mreavy, could you help find someone to look at this failure?  I suspect this is something easy to fix, although I didn't see anything in the test file that would indicate there is special code for windows.
Flags: needinfo?(mreavy)
Blake -- is this something that someone on your team could look at?  I'm cc'ing Anthony too.
Component: Audio/Video → Audio/Video: Playback
Flags: needinfo?(mreavy)
Flags: needinfo?(bwu)
(In reply to Maire Reavy [:mreavy] Plz needinfo? from comment #2)
> Blake -- is this something that someone on your team could look at?  I'm
> cc'ing Anthony too.
Yeah. 
From comment 0, it looks related to MSE. 
Alastor, 
Can you check this bug? It should interest you.
Flags: needinfo?(bwu) → needinfo?(alwu)
I am going to migrate these tests tomorrow to windows 10 and disable this single test- this is a friendly reminder that as of tomorrow it will be needed to enable this test in the manifest. see bug 1398244 for the patch which will be disabling this.
I can also reproduce this issue on Win7.
Flags: needinfo?(alwu)
Summary: dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html fails on windows 10 → dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html fails on windows
Assignee: nobody → alwu
thanks for working on this :alwu, please remember to enable this for win10 in the manifest!
Offline discussed with JW, it's reasonable that |me.currentTime| might be not equal with |me.duration|, but it should only have very very little difference. 

That is because every platform has different audio backend, and it would affect the audio playback duration according to different hardware resampling rate, even with the same audio samples count.

However, according to spec [1], the |me.duration| should be the last defined position on the media timeline. |me.currentTime| should not exceed the |me.duration| because it's also on the media timeline.

We should correct the |me.currentTime| and don't let it exceeds the |me.duration|.

[1] https://html.spec.whatwg.org/multipage/media.html#media-timeline
it also permanently fail on my mac box. I'm not sure the issue is what you describe (discrepency on media decoder). It's not due to windows 10 per say.

To me this is a regression, and you're seeing the same thing on windows.

First rough regression range.
https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=d942ef54fdf726840a698d2ddcaf989d2c00edbc&tochange=681a2489f6a92a09f87336c4ebfcd55030ffcda1
Keywords: regression
Summary: dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html fails on windows → dom/media/mediasource/test/test_WaitingToEndedTransition_mp4.html fails on windows and mac 10.12
Comment on attachment 8908045 [details]
Bug 1398139 - part1 : revert the changing of bug 1386478.

https://reviewboard.mozilla.org/r/179742/#review185144

::: dom/media/MediaDecoder.cpp:982
(Diff revision 1)
>    MOZ_ASSERT(NS_IsMainThread());
>    MOZ_DIAGNOSTIC_ASSERT(!IsShutdown());
>  
>    double currentPosition = CurrentPosition().ToSeconds();
> -  if (mPlayState == PLAY_STATE_ENDED) {
> -    currentPosition = std::max(currentPosition, mDuration);
> +  if (mPlayState == PLAY_STATE_ENDED ||
> +      currentPosition > mDuration) {

you're assuming you have a valid duration.

that's not always the case.

in fact plenty of media have no valid duration, and as playback goes, the duration is updated.

So why wouldn't the currentTime be different to the duration once it ends once again.

seems to me it's the duration you need to adjust, not the current position.

in any case, I'm not sure this is what the problem is
Version: 54 Branch → 57 Branch
test case to easily find a regression
I can reproduce on windows 10 by forcing the output refresh rate.
The bipbop is 22.05kHz, so the data will be resampled.

I can reproduce the issue on all platforms. That's what's going on here... I think the assessment in comment 7 is incorrect: nothing to do with the difference in decoders. it's all to do with the AudioSink

You can test by setting the pref media.resampling.enabled to true.
the default rate is 48kHz.

this will cause the test to fail.

In windows 10 try machines, the AudioStream::GetPreferredRate() returns 48000.

On linux that uses pulseaudio the default is 44.1kHz. the upsampling there is exact.
(In reply to Jean-Yves Avenard [:jya] from comment #12)
> in fact plenty of media have no valid duration, and as playback goes, the
> duration is updated.

We've considered that. Even the metadata has wrong duration, we still update it to make it correct during playback. Because of that, we can always make sure the current position is on the last position on the media time line.

> So why wouldn't the currentTime be different to the duration once it ends
> once again.
> 
> seems to me it's the duration you need to adjust, not the current position.
> 
> in any case, I'm not sure this is what the problem is

The main reason is we don't want the current position exceed the duration, it's defined in the spec.

In addition, as JW said, if the difference is unavoidable, that we don't need to expose this tiny difference to client side.

(In reply to Jean-Yves Avenard [:jya] from comment #11)
> it also permanently fail on my mac box. I'm not sure the issue is what you
> describe (discrepency on media decoder). It's not due to windows 10 per say.

Weird, no issue on my mac OSX 10.11.4.
Flags: needinfo?(jyavenard)
Even if we revert bug 1386478, will 'MediaSource.duration=x' guarantee the end time of the last audio sample equals 'x'?
(In reply to Alastor Wu [:alwu][please needinfo me][GMT+8] from comment #16)
> (In reply to Jean-Yves Avenard [:jya] from comment #12)
> > in fact plenty of media have no valid duration, and as playback goes, the
> > duration is updated.
> 
> We've considered that. Even the metadata has wrong duration, we still update
> it to make it correct during playback. Because of that, we can always make
> sure the current position is on the last position on the media time line.
> 
> > So why wouldn't the currentTime be different to the duration once it ends
> > once again.
> > 
> > seems to me it's the duration you need to adjust, not the current position.
> > 
> > in any case, I'm not sure this is what the problem is
> 
> The main reason is we don't want the current position exceed the duration,
> it's defined in the spec.
> 
> In addition, as JW said, if the difference is unavoidable, that we don't
> need to expose this tiny difference to client side.

the difference here is due to the resampling in the AudioSink, not the decoder decoding differently between platform

> 
> (In reply to Jean-Yves Avenard [:jya] from comment #11)
> > it also permanently fail on my mac box. I'm not sure the issue is what you
> > describe (discrepency on media decoder). It's not due to windows 10 per say.
> 
> Weird, no issue on my mac OSX 10.11.4.

did you try the steps I mentioned in comment 16?

what sampling rate is going to be used by the AudioSink depends on the audio device connected.
in this test, if your output supports 44.1kHz you won't have an error, if the default sampling rate is 48kHz, then you will have the error.
Flags: needinfo?(jyavenard)
(In reply to JW Wang [:jwwang] [:jw_wang] from comment #17)
> Even if we revert bug 1386478, will 'MediaSource.duration=x' guarantee the
> end time of the last audio sample equals 'x'?

that's the intent of this mochitest!

it ensure that the duration is the expected value, and that currentTime is also at the expected value (both for the waiting event and the ended event)
Fair enough. We then should fix the chained ogg issue and revert bug 1386478.
OK, got it.
I will revert the change of bug 1386478 in this bug.
(In reply to Alastor Wu [:alwu][please needinfo me][GMT+8] from comment #21)
> OK, got it.
> I will revert the change of bug 1386478 in this bug.

Not until the chained ogg bug is fixed.
Comment on attachment 8908045 [details]
Bug 1398139 - part1 : revert the changing of bug 1386478.

https://reviewboard.mozilla.org/r/179742/#review185356
Attachment #8908045 - Flags: review?(jwwang) → review+
Comment on attachment 8908046 [details]
Bug 1398139 - part2 : adjust sample's start time for chained ogg.

https://reviewboard.mozilla.org/r/179744/#review185358

::: commit-message-e56de:1
(Diff revision 2)
> +Bug 1398139 - part2 : adjust the end time of sample for chained ogg file.

this is technically not the correct description.

you're not adjusting the end time, you're adjusting the sample start time.

What about:

adjust sample's start time for chained ogg.

"For chained ogg file" -> "For chained ogg files"

s/previous/previously
Attachment #8908046 - Flags: review?(jyavenard) → review+
Comment on attachment 8908539 [details]
Bug 1398139 - part3 : check current time should be increased correctly in new chained part.

https://reviewboard.mozilla.org/r/180188/#review185360
Attachment #8908539 - Flags: review?(jyavenard) → review+
Comment on attachment 8908540 [details]
Bug 1398139 - part4 : enable test.

https://reviewboard.mozilla.org/r/180190/#review185362

can you open a new bug to remove all those windows XP tests?

we no longer supports windows xp.
Attachment #8908540 - Flags: review?(jyavenard) → review+
(In reply to Jean-Yves Avenard [:jya] from comment #30)
> Comment on attachment 8908540 [details]
> Bug 1398139 - part4 : enable test.
> 
> https://reviewboard.mozilla.org/r/180190/#review185362
> 
> can you open a new bug to remove all those windows XP tests?
> 
> we no longer supports windows xp.

Sure, will do in bug1400195.
Pushed by alwu@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/1421239eef77
part1 : revert the changing of bug 1386478. r=jwwang
https://hg.mozilla.org/integration/autoland/rev/9fe90be81abb
part2 : adjust sample's start time for chained ogg. r=jya
https://hg.mozilla.org/integration/autoland/rev/39e86cbf34d5
part3 : check current time should be increased correctly in new chained part. r=jya
https://hg.mozilla.org/integration/autoland/rev/69fec8b3a6a0
part4 : enable test. r=jya
Depends on: 1417300
You need to log in before you can comment on or make changes to this bug.