815107 - Intermittent test_playback_rate.html | application timed out after 330 seconds with no output (after: "ASSERTION: Should have positive clock time.: 'clock_time >= mStartTime', file ..../build/content/media/MediaDecoderStateMachine.cpp, line 2277")

Status: RESOLVED FIXED

(Core :: Audio/Video, defect)

Description

[Ed Morley [:emorley]]

Rev3 WINNT 6.1 mozilla-inbound debug test mochitest-1 on 2012-11-25 15:20:21 PST for push 4b816b309e52

slave: talos-r3-w7-088

https://tbpl.mozilla.org/php/getParsedLog.php?id=17335446&tree=Mozilla-Inbound

{
...
...
...

[Parent 3480] ###!!! ASSERTION: Should have positive clock time.: 'clock_time >= mStartTime', file e:/builds/moz2_slave/m-in-w32-dbg/build/content/media/MediaDecoderStateMachine.cpp, line 2277
130379 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | playbackRate should be initially 1.0
130380 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | defaultPlaybackRate should be initially 1.0
130381 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | PlaybackRate should be clamped to 0.25.
130382 INFO TEST-PASS | /tests/content/media/test/test_playback_rate.html | playbackRate should be reset to 1.0 on play() call
xul!JSD_AttemptUCScriptInStackFrame+0x0000000000AC3EBA
xul!JSD_AttemptUCScriptInStackFrame+0x0000000000AC4112
xul!JSD_AttemptUCScriptInStackFrame+0x000000000136FABF
xul!JSD_AttemptUCScriptInStackFrame+0x000000000136FCF1
xul!JSD_AttemptUCScriptInStackFrame+0x000000000136A8F8
xul!JSD_AttemptUCScriptInStackFrame+0x0000000001317FF0
xul!JSD_AttemptUCScriptInStackFrame+0x0000000001369F00
nspr4!PRP_TryLock+0x000000000000062B
MSVCR100D!beginthreadex+0x00000000000001D4
kernel32!BaseThreadInitThunk+0x0000000000000012
ntdll!RtlInitializeExceptionChain+0x0000000000000063
ntdll!RtlInitializeExceptionChain+0x0000000000000036
[Parent 3480] ###!!! ASSERTION: Should have positive clock time.: 'clock_time >= mStartTime', file e:/builds/moz2_slave/m-in-w32-dbg/build/content/media/MediaDecoderStateMachine.cpp, line 2277
TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_playback_rate.html | application timed out after 330 seconds with no output
}

Comment 1

[Legacy TBPL/Treeherder Robot]

edmorley
https://tbpl.mozilla.org/php/getParsedLog.php?id=17376118&tree=Mozilla-Inbound
Rev3 WINNT 6.1 mozilla-inbound debug test mochitest-1 on 2012-11-27 07:42:40
slave: talos-r3-w7-064

TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_playback_rate.html | application timed out after 330 seconds with no output
remoteFailed: [Failure instance: Traceback from remote host -- Traceback (most recent call last):

Comment 2

[Chris Pearce [:cpearce (Not reading bugmail)]]

Paul, are you looking into this? I get a horrendous amount of assertion failure spam when I run this test on Windows, I haven't tried other platforms.

It looks like AudioClock::GetPosition() is returning a bogus value because AudioClock::mBasePosition is bogus.

Comment 3

[Chris Pearce [:cpearce (Not reading bugmail)]]

OK, I looked into this because it was causing tests to fail for me with my WMF backend...

The problem is that AudioClock::GetPosition() uses mOldOutRate to calculate the "position" variable [1], that gets stored in mPreviousPosition, which then later is stored in mBasePosition [2].

mOldOutRate is initialized by the constructor to 0, and it's set to mOutRate in one but not all code paths in AudioClock::SetPlaybackRate(). So I guess we're taking the path in SetPlaybackRate() that doesn't set mOldOutRate, and so mOldOutRate is then 0 when we come to all AudioClock::GetPosition(), which poisons all future calculations. We don't appear to be crashing, despite the fact that we're dividing by 0.

I'd guess the fix is to initialize mOldOutRate to mOutRate in AudioClock::Init().


[1] http://mxr.mozilla.org/mozilla-central/source/content/media/AudioStream.cpp#1088
[2] http://mxr.mozilla.org/mozilla-central/source/content/media/AudioStream.cpp#1096

Comment 4

[Chris Pearce [:cpearce (Not reading bugmail)]]

Attachment: Patch v1

Initialize mOldOutRate to mOutRate, and initialize mOldBasePosition to 0.

This seems like the right thing to do, and it stops the assertion spam and the current playback position now advances for me when playing MP4 videos using the Windows Media Foundation backend I'm working on.

Comment 5

[Paul Adenot (:padenot)]

Comment on attachment 690157 [details] [diff] [review]
Patch v1

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

Funnily enough, I've came to the same conclusion and was about to upload the same patch. Thanks!

Comment 6

[Chris Pearce [:cpearce (Not reading bugmail)]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/4bd1cc9d98c5

Comment 7

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/4bd1cc9d98c5