1020538 - Fix and re-enable test_playback_rate.html

Status: RESOLVED FIXED

Description

[Ryan VanderMeulen [:RyanVM]]

With bug 921622 fixed, I took a look at re-enabling test_playback_rate.html. It looks pretty green on opt builds, but debug builds still assert like crazy.

Android 4.0 Panda try debug test mochitest-3 on 2014-06-04 11:26:20 PDT for push 2fb25f5fc810

06-04 11:52:12.125 I/Gecko   ( 2250): [2250] ###!!! ASSERTION: Should be on state machine or decode thread.: 'OnStateMachineThread() || OnDecodeThread()', file /builds/slave/try-and-d-00000000000000000000/build/content/media/MediaDecoderStateMachine.cpp, line 559
06-04 11:52:16.203 I/Gecko   ( 2250): [2250] ###!!! ASSERTION: Clock should go forwards if the playback rate is > 0.: 'mCurrentFrameTime <= clock_time || mPlaybackRate <= 0', file /builds/slave/try-and-d-00000000000000000000/build/content/media/MediaDecoderStateMachine.cpp, line 2379

06-04 11:52:26.851 E/GeckoConsole( 2250): [JavaScript Warning: "Invalid URI. Load of media resource  failed." {file: "http://mochi.test:8888/tests/content/media/test/test_playback_rate.html" line: 0}]

I'm feeling inclined to re-enable test_playback_rate.html on opt builds once I get some more green retriggers, but debug builds are still going to need some help.

Comment 1

[Ryan VanderMeulen [:RyanVM]]

Windows 7/8 opt builds still hit bug 814533 as well.

Comment 2

[Ryan VanderMeulen [:RyanVM]]

The "Should be on state machine or decode thread" asserts happen on all platforms. Linux also hits the "Clock should go forwards if the playback rate is > 0" assert.

However, the test was already annotated on all platforms for assertions before, so maybe we just need to bump the allowed number (assuming it's the same asserts as before, just firing more often).

Comment 3

[Ryan VanderMeulen [:RyanVM]]

Occasional Android timeouts, but hard to say it's any worse than any other test in content/media in that respect...
https://tbpl.mozilla.org/php/getParsedLog.php?id=41054576&tree=Try

Comment 4

[Ryan VanderMeulen [:RyanVM]]

Pretty flaky on B2G emulator with the following happening frequently:

1453 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_playback_rate.html | Current time should not change when playbackRate is null (5.207732 4.88848).
1468 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_playback_rate.html | Current time should not change when playbackRate is null (3.233 2.8).
1522 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_playback_rate.html | The element should not be in paused state.

https://tbpl.mozilla.org/php/getParsedLog.php?id=41056722&tree=Try

Comment 5

[Ryan VanderMeulen [:RyanVM]]

Ouch, Android debug hit anywhere from 3-94 assertions. That's too wide for me to comfortably annotate it away.

Comment 6

[Ryan VanderMeulen [:RyanVM]]

I filed bug 1020707 for the Android timeouts. They're infrequent enough that they'd be tolerable IMO (given Android's already crappy orange rate for media tests).

Comment 7

[Ryan VanderMeulen [:RyanVM]]

Attachment: partial re-enabling and updates to assertion annotations

Definitely not intended to be the final fix for this bug, but it gets the ball rolling anyway.

This patch re-enables test_playback_rate.html on Linux, OSX, and Android opt. It also updates the assertion annotations for all desktop platforms. Due to the aforementioned issues in this bug, Windows, B2G, and Android debug remain disabled.

Try runs:
https://tbpl.mozilla.org/?tree=Try&rev=588f84523a36
https://tbpl.mozilla.org/?tree=Try&rev=f9ae9b880cb0

Comment 8

[JW Wang [:jwwang] [:jw_wang]]

I got this assertion when running on my local Linux box.

#0  0x00007ffff2169597 in mozilla::MediaDecoderStateMachine::NeedToDecodeAudio (this=0x7fffbfc97840) at /home/jwwang/codebase/mozilla-central2/content/media/MediaDecoderStateMachine.cpp:685
#1  0x00007ffff21697ba in mozilla::MediaDecoderStateMachine::DispatchDecodeTasksIfNeeded (this=this@entry=0x7fffbfc97840)
    at /home/jwwang/codebase/mozilla-central2/content/media/MediaDecoderStateMachine.cpp:1580
#2  0x00007ffff2169b82 in mozilla::MediaDecoderStateMachine::StopPlayback (this=this@entry=0x7fffbfc97840) at /home/jwwang/codebase/mozilla-central2/content/media/MediaDecoderStateMachine.cpp:1107
#3  0x00007ffff2169c8d in mozilla::MediaDecoderStateMachine::StartBuffering (this=0x7fffbfc97840) at /home/jwwang/codebase/mozilla-central2/content/media/MediaDecoderStateMachine.cpp:2684
#4  0x00007ffff2162bbf in mozilla::MediaDecoder::Resume (this=0x7fffc452d4e0, aForceBuffering=<optimized out>) at /home/jwwang/codebase/mozilla-central2/content/media/MediaDecoder.cpp:1373
#5  0x00007ffff20c6974 in mozilla::dom::HTMLMediaElement::Play (this=0x7fffbfeb5400, aRv=...) at /home/jwwang/codebase/mozilla-central2/content/html/content/src/HTMLMediaElement.cpp:2124
#6  0x00007ffff1840412 in mozilla::dom::HTMLMediaElementBinding::play (cx=0x7fffcd0176a0, obj=..., self=<optimized out>, args=...)
    at /home/jwwang/codebase/mozilla-central2/obj-x86_64-unknown-linux-gnu/dom/bindings/HTMLMediaElementBinding.cpp:930


I don't understand why MediaDecoderStateMachine::NeedToDecodeVideo|NeedToDecodeAudio should only be called on state or decode threads.

Comment 9

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/12e8837e166a

Comment 10

[Chris Pearce [:cpearce (GMT+13)]]

(In reply to JW Wang [:jwwang] from comment #8)
> I don't understand why
> MediaDecoderStateMachine::NeedToDecodeVideo|NeedToDecodeAudio should only be
> called on state or decode threads.

Given that the decoder monitor should be held here, I agree, these functions should be safe to call on any thread.

Comment 11

[Wes Kocher (:KWierso)]

https://hg.mozilla.org/mozilla-central/rev/12e8837e166a

Comment 12

[Ryan VanderMeulen [:RyanVM]]

FYI, we see the "Clock should go forwards if the playback rate is > 0" asserts quite a bit in test_playback_rate_playpause.html.

Comment 13

[JW Wang [:jwwang] [:jw_wang]]

I've fixed all failures on all platforms except the B2G emualtor.

https://tbpl.mozilla.org/php/getParsedLog.php?id=42030206&tree=Try&full=1#error2
TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_playback_rate.html | Current time should not change when playbackRate is null (2.681958 2.058891).

MediaDecoder::PlaybackPositionChanged() updates the official playback position (mCurrentTime) and dispatches 'timeupdate' event asynchronously. It is possible for the current playback position to change again before 'timeupdate' is fired.

It is observed on B2G emulator that the official playback position is 2.058891 and current playback position is 2.667270 when 'timeupdate' is fired. The check fails at http://hg.mozilla.org/mozilla-central/file/f78e532e8a10/content/media/test/test_playback_rate.html#l96  for the difference is over 0.3 sec.

It is also observed on B2G emulator that the latency between 'timeupdate' is dispatched and fired could go as high as 2.46867 sec for B2G emulator sometimes is very slow.

I think we could either have a higher tolerance on B2G or update the official playback position again before 'timeupdate' is fired to minimize the difference between current/official playback position.

Comment 14

[Chris Pearce [:cpearce (GMT+13)]]

I'd suggest we increase the latency tolerance on B2G. Timeupdate isn't supposed to be highly accurate.

'timeupdate' is defined to fire loosely, approx 4 times per second during playback. MediaDecoder::PlaybackPositionChanged() passes "true" to MediaDecoderOwner::FireTimeUpdate to signal a "periodic" time update, i.e. to only fire a 'timeupdate' if one hasn't fired in the last ~250ms. We could be hitting that, and then our task to dispatch the 'timeupdate' event to HTML could be getting delayed in the event queues.

Comment 15

[JW Wang [:jwwang] [:jw_wang]]

Attachment: 1020538_fix_test_playback_rate_part1-v1.patch

Fix the position calculation algorithm in MediaDecoderStateMachine::GetVideoStreamPosition().

Comment 16

[JW Wang [:jwwang] [:jw_wang]]

Attachment: 1020538_fix_test_playback_rate_part2-v1.patch

Fix frame position adjustment algorithm in AudioStream.

Comment 17

[JW Wang [:jwwang] [:jw_wang]]

Attachment: 1020538_fix_test_playback_rate_enable_test-v1.patch

Enable test_playback_rate.html.

Comment 18

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8444918 [details] [diff] [review]
1020538_fix_test_playback_rate_part2-v1.patch

Review of attachment 8444918 [details] [diff] [review]:
-----------------------------------------------------------------

::: content/media/AudioStream.cpp
@@ +979,5 @@
>    }
>  
>    uint8_t* wpos = reinterpret_cast<uint8_t*>(aBuffer);
>    double playbackRate = static_cast<double>(mInRate) / mOutRate;
> +  uint32_t toPopBytes = FramesToBytes(ceil(aFrames * playbackRate));

When playback rate is 0.5, libSoundTouch will turn 100 frames into 200 frames. Therefore we should only pop 200 * 0.5 = 100 frames. However it doesn't really matter for the while loop below will ensure we've process enough frames.

Comment 19

[Matthew Gregan [:kinetik]]

Comment on attachment 8444918 [details] [diff] [review]
1020538_fix_test_playback_rate_part2-v1.patch

Review of attachment 8444918 [details] [diff] [review]:
-----------------------------------------------------------------

This is much nicer than the existing code.

Comment 20

[Matthew Gregan [:kinetik]]

Note that the following assertion count needs to be corrected before these patches can land:

22:46:51     INFO -  5130 ERROR TEST-UNEXPECTED-PASS | /tests/content/media/test/test_playback_rate_playpause.html | Assertion count 0 is less than expected range 2-7 assertions.

Comment 21

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Matthew Gregan [:kinetik] from comment #20)
> Note that the following assertion count needs to be corrected before these
> patches can land:
> 
> 22:46:51     INFO -  5130 ERROR TEST-UNEXPECTED-PASS |
> /tests/content/media/test/test_playback_rate_playpause.html | Assertion
> count 0 is less than expected range 2-7 assertions.

They will be removed in bug 897108.

Comment 22

[Matthew Gregan [:kinetik]]

Okay, then this can't land until after bug 897108.

Comment 23

[JW Wang [:jwwang] [:jw_wang]]

Bug 1020538 and bug 897108 should be landed at the same time.
If we land bug 1020538 first, we will hit comment 20. If we land bug 897108 first, test_playback_rate_playpause.html will fail from assertions count > 0. Is there any way to tell Sheriff to land these patches altogether?

Comment 24

[Matthew Gregan [:kinetik]]

Oh, the dependency is circular? In that case, it's better to post all the patches in a single bug (or perhaps even roll the fixes together, otherwise bisect becomes painful).  There's probably some way to signal this in the whiteboard for needs-landing too, but I don't know what it is.  I'll land them now, anyway.

Comment 25

[Matthew Gregan [:kinetik]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/a896fedd7cec
https://hg.mozilla.org/integration/mozilla-inbound/rev/3d78475581e2
https://hg.mozilla.org/integration/mozilla-inbound/rev/614bfb13a731

Comment 26

[JW Wang [:jwwang] [:jw_wang]]

Thanks, Matthew. 1020538_fix_test_playback_rate_enable_test-v1.patch and 897108_fix_test_playback_rate_playpause_html_timeout-v1.patch were originally one patch which was split for easier review. Next time I should take both review and check-in into account when merge/split patches.

Comment 27

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/a896fedd7cec
https://hg.mozilla.org/mozilla-central/rev/3d78475581e2
https://hg.mozilla.org/mozilla-central/rev/614bfb13a731

Comment 28

[Ryan VanderMeulen [:RyanVM]]

Not sure what the backport situation is here. Please request approval on whatever branches you feel this is safe for.

Comment 29

[JW Wang [:jwwang] [:jw_wang]]

The patches can't apply cleanly. The code changed quite a bit even since then. Since this bug fixes the problem in playback rate changes which most user will not encounter, I guess we are fine with not uplifting to aurora/beta.