Closed Bug 975092 Opened 10 years ago Closed 9 years ago

Intermittent test_streams_autoplay.html | Test timed out.

Categories

(Core :: Audio/Video, defect)

ARM
Gonk (Firefox OS)
defect
Not set
normal

Tracking

()

RESOLVED WORKSFORME

People

(Reporter: RyanVM, Assigned: jwwang)

References

Details

(Keywords: intermittent-failure)

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

b2g_emulator_vm mozilla-inbound opt test mochitest-4 on 2014-02-20 11:13:19 PST for push cc5ce0bdff58
slave: tst-linux64-spot-145

11:28:26     INFO -  59 INFO TEST-START | /tests/content/media/test/test_streams_autoplay.html
11:28:26     INFO -  60 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_streams_autoplay.html | Test timed out.
11:28:26     INFO -  61 INFO TEST-INFO | MEMORY STAT vsize after test: 101830656
11:28:26     INFO -  62 INFO TEST-INFO | MEMORY STAT residentFast after test: 39727104
11:28:26     INFO -  63 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 15394980
11:28:26     INFO -  64 INFO TEST-END | /tests/content/media/test/test_streams_autoplay.html | finished in 327197ms
Assignee: nobody → jwwang
This is the #1 orange on trunk (having seen a tremendous spike in the last week), so any help here would be greatly appreciated :)
Flags: needinfo?(jwwang)
https://tbpl.mozilla.org/php/getParsedLog.php?id=36338427&tree=Try&full=1#error0

03-18 08:25:25.976 I/GeckoDump( 2224): 1246 INFO TEST-START | /tests/content/media/test/test_streams_autoplay.html
03-18 08:25:26.484 E/PRLog   ( 2224): 0x6ad70060 UpdatePreloadAction mBegun=0 mIsRunningSelectResource=0 nextAction=3 mPreloadAction=0
03-18 08:25:26.484 E/PRLog   ( 2224): 0x6ad70740 UpdatePreloadAction mBegun=0 mIsRunningSelectResource=0 nextAction=3 mPreloadAction=0
03-18 08:25:26.484 E/PRLog   ( 2224): 0x6ad71ea0 CanPlayType(video/ogg) = "maybe"
03-18 08:25:26.484 E/PRLog   ( 2224): 0x6ad71ea0 CanPlayType(video/webm) = "maybe"
03-18 08:25:26.484 E/PRLog   ( 2224): 0x6ad71ea0 CanPlayType(video/webm) = "maybe"
03-18 08:25:26.484 E/PRLog   ( 2224): 0x6ad71ea0 CanPlayType(video/mp4) = ""
03-18 08:25:26.484 E/PRLog   ( 2224): 0x6ad70060 Queuing event ratechange
03-18 08:25:26.484 E/PRLog   ( 2224): 0x6ad70740 Queuing event ratechange
03-18 08:25:26.492 E/PRLog   ( 2224): 0x6ad70060 ChangeDelayLoadStatus(1) doc=0x0x6b4b4000
03-18 08:25:26.492 E/PRLog   ( 2224): 0x6ad70060 Queuing event loadstart
03-18 08:25:26.492 E/PRLog   ( 2224): 0x6ad70060 UpdatePreloadAction mBegun=0 mIsRunningSelectResource=0 nextAction=3 mPreloadAction=3
03-18 08:25:26.492 E/PRLog   ( 2224): 0x6ad70060 Trying load from src=320x240.ogv
03-18 08:25:26.492 E/PRLog   ( 2224): 0x6ad70060 Cloned decoder 0x68f8c7c0 from 0x68f8cc20
03-18 08:25:26.492 E/PRLog   ( 2224): MediaDecoderStateMachine(0x68f3f960) ctor, decoder=0x68f8c7c4
03-18 08:25:26.492 E/PRLog   ( 2224): MediaDecoderStateMachine(0x68f3f960) SetDuration, start=-1,duration=266664
03-18 08:25:26.492 E/PRLog   ( 2224): MediaDecoderStateMachine(0x68f3f960) ScheduleStateMachine 1, 0, MediaDecoder::ScheduleStateMachineThread
03-18 08:25:26.492 E/PRLog   ( 2224): MediaDecoderStateMachine(0x68f3f960) 0x68f8c7c0 Decoding Media Headers
03-18 08:25:26.507 E/PRLog   ( 2224): MediaDecoderStateMachine(0x68f3f960) 0x68f8c7c0 Media start time is 0
03-18 08:25:26.507 E/PRLog   ( 2224): 0x6ad70740 ChangeDelayLoadStatus(1) doc=0x0x6b4b4000
03-18 08:25:26.507 E/PRLog   ( 2224): 0x6ad70740 Queuing event loadstart
03-18 08:25:26.507 E/Profiler( 2224): BPUnw: [9 total] thread_register_for_profiling(me=0x1d27ac0, stacktop=0x6f7ffe0f)
03-18 08:25:26.507 E/PRLog   ( 2224): 0x6ad70740 UpdatePreloadAction mBegun=0 mIsRunningSelectResource=0 nextAction=3 mPreloadAction=3
03-18 08:25:26.507 E/PRLog   ( 2224): Media graph global underrun detected
03-18 08:25:26.507 E/PRLog   ( 2224): 0x6ad70740 ChangeDelayLoadStatus(0) doc=0x0x6b4b4000
03-18 08:25:26.507 E/PRLog   ( 2224): BlockerCount change, 0x6a9b9e40,1,1
03-18 08:25:26.507 E/PRLog   ( 2224): 0x6ad70740 Ready state changed to HAVE_METADATA, network=2
03-18 08:25:26.507 E/PRLog   ( 2224): BlockerCount change, 0x6a9c93c0,1,1
03-18 08:25:26.507 E/PRLog   ( 2224): 0x6ad70740 Queuing event durationchange
03-18 08:25:26.507 E/PRLog   ( 2224): BlockerCount change, 0x6a9b9e40,1,-1
03-18 08:25:26.507 E/PRLog   ( 2224): 0x6ad70740 Queuing event loadedmetadata
03-18 08:25:26.507 E/PRLog   ( 2224): 0x6ad70740 Queuing event suspend
03-18 08:25:26.507 E/PRLog   ( 2224): MediaDecoderStateMachine(0x68f3f960) 0x68f8c7c0 Changed state from DECODING_METADATA to DECODING
03-18 08:25:26.507 E/PRLog   ( 2224): MediaDecoderStateMachine(0x68f3f960) 0x68f8c7c0 CheckIfDecodeComplete NOT completed
03-18 08:25:26.507 E/PRLog   ( 2224): MediaDecoderStateMachine(0x68f3f960) ScheduleStateMachine 1, 0, StartDecoding
03-18 08:25:26.507 E/PRLog   ( 2224): MediaDecoderStateMachine(0x68f3f960) 0x68f8c7c0 CheckIfDecodeComplete NOT completed
03-18 08:25:26.523 E/PRLog   ( 2224): BlockerCount change, 0x6a9b9e40,33455,1
03-18 08:25:26.562 E/PRLog   ( 2224): 0x6ad70060 Dispatching event ratechange
03-18 08:25:26.562 E/PRLog   ( 2224): 0x6ad70740 Dispatching event ratechange
03-18 08:25:26.562 E/PRLog   ( 2224): 0x6ad70060 Dispatching event loadstart
03-18 08:25:26.562 E/PRLog   ( 2224): 0x6ad70060 UpdateReadyStateForData, readyState=HAVE_NOTHING, nextFrame=AVAILABLE
03-18 08:25:26.562 E/PRLog   ( 2224): 0x6ad70740 Dispatching event loadstart
03-18 08:25:26.562 E/PRLog   ( 2224): 0x6ad70740 Dispatching event durationchange
03-18 08:25:26.562 E/PRLog   ( 2224): 0x6ad70740 Dispatching event loadedmetadata
03-18 08:25:26.562 E/PRLog   ( 2224): 0x6ad70740 Dispatching event suspend
03-18 08:25:26.562 E/PRLog   ( 2224): 0x6ad70740 Ready state changed to HAVE_CURRENT_DATA, network=1
03-18 08:25:26.562 E/PRLog   ( 2224): 0x6ad70740 Queuing event loadeddata
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70740 Queuing event play
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70740 UpdateReadyStateForData, readyState=HAVE_CURRENT_DATA, nextFrame=BUFFERING
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70740 Queuing event timeupdate
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70740 Queuing event waiting
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70060 Ready state changed to HAVE_METADATA, network=2
03-18 08:25:26.570 E/PRLog   ( 2224): Media graph global underrun detected
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70060 Queuing event durationchange
03-18 08:25:26.570 E/PRLog   ( 2224): BlockerCount change, 0x6a9b9e40,48672,-1
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70060 Queuing event loadedmetadata
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70060 Ready state changed to HAVE_ENOUGH_DATA, network=2
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70060 Queuing event loadeddata
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70060 Queuing event canplay
03-18 08:25:26.570 E/PRLog   ( 2224): MediaDecoderStateMachine(0x68f3f960) ScheduleStateMachine 1, 0, MediaDecoder::ScheduleStateMachineThread
03-18 08:25:26.570 E/PRLog   ( 2224): MediaDecoderStateMachine(0x68f3f960) 0x68f8c7c0 StartPlayback()
03-18 08:25:26.570 E/PRLog   ( 2224): MediaDecoderStateMachine(0x68f3f960) AdvanceFrame 3, 33333,-1,0,0
03-18 08:25:26.570 E/PRLog   ( 2224): MediaDecoderStateMachine(0x68f3f960) ScheduleStateMachine 2, 33333, AdvanceFrame 3
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70060 Queuing event play
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70060 Queuing event playing
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70060 Queuing event canplaythrough
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70060 ChangeDelayLoadStatus(0) doc=0x0x6b4b4000
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70060 Queuing event progress
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70060 Queuing event progress
03-18 08:25:26.570 E/PRLog   ( 2224): 0x6ad70060 Queuing event suspend
03-18 08:25:26.578 E/PRLog   ( 2224): 0x6ad70060 NotifySuspendedByCache=1
03-18 08:25:26.578 E/PRLog   ( 2224): 0x6ad70060 UpdateReadyStateForData, readyState=HAVE_ENOUGH_DATA, nextFrame=AVAILABLE
03-18 08:25:26.578 E/PRLog   ( 2224): BlockerCount change, 0x6a9c93c0,82151,-1

After examining the logs, it looks like the same cause as Bug 907162 (https://bugzilla.mozilla.org/show_bug.cgi?id=907162#c34). Let's wait and see if Bug 907162 fixes the timeout here.
Flags: needinfo?(jwwang)
Forget about comment 394. I just found out i pasted the wrong logs.

https://tbpl.mozilla.org/php/getParsedLog.php?id=36338708&tree=Try&full=1#error0

03-18 08:29:56.835 I/GeckoDump( 2248): 1246 INFO TEST-START | /tests/content/media/test/test_streams_autoplay.html
03-18 08:29:57.062 E/PRLog   ( 2248): 0x66bf1460 UpdatePreloadAction mBegun=0 mIsRunningSelectResource=0 nextAction=3 mPreloadAction=0
03-18 08:29:57.062 E/PRLog   ( 2248): 0x66bf1b40 UpdatePreloadAction mBegun=0 mIsRunningSelectResource=0 nextAction=3 mPreloadAction=0
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf3980 CanPlayType(video/ogg) = "maybe"
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf3980 CanPlayType(video/webm) = "maybe"
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf3980 CanPlayType(video/webm) = "maybe"
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf3980 CanPlayType(video/mp4) = ""
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1460 Queuing event ratechange
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1b40 Queuing event ratechange
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1460 ChangeDelayLoadStatus(1) doc=0x0x6b3c4800
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1460 Queuing event loadstart
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1460 UpdatePreloadAction mBegun=0 mIsRunningSelectResource=0 nextAction=3 mPreloadAction=3
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1460 Trying load from src=320x240.ogv
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1460 Cloned decoder 0x6b22b080 from 0x5be5c740
03-18 08:29:57.070 E/PRLog   ( 2248): MediaDecoderStateMachine(0x6ae8d090) ctor, decoder=0x6b22b084
03-18 08:29:57.070 E/PRLog   ( 2248): MediaDecoderStateMachine(0x6ae8d090) SetDuration, start=-1,duration=266664
03-18 08:29:57.070 E/PRLog   ( 2248): MediaDecoderStateMachine(0x6ae8d090) ScheduleStateMachine 1, 0, MediaDecoder::ScheduleStateMachineThread
03-18 08:29:57.070 E/PRLog   ( 2248): MediaDecoderStateMachine(0x6ae8d090) 0x6b22b080 Decoding Media Headers
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1b40 ChangeDelayLoadStatus(1) doc=0x0x6b3c4800
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1b40 Queuing event loadstart
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1b40 UpdatePreloadAction mBegun=0 mIsRunningSelectResource=0 nextAction=3 mPreloadAction=3
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1b40 ChangeDelayLoadStatus(0) doc=0x0x6b3c4800
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1b40 Ready state changed to HAVE_METADATA, network=2
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1b40 Queuing event durationchange
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1b40 Queuing event loadedmetadata
03-18 08:29:57.070 E/PRLog   ( 2248): 0x66bf1b40 Queuing event suspend
03-18 08:29:57.078 E/Profiler( 2248): BPUnw: [9 total] thread_register_for_profiling(me=0xca0048, stacktop=0x6e6ffe0f)
03-18 08:29:57.078 E/PRLog   ( 2248): Media graph global underrun detected
03-18 08:29:57.078 E/PRLog   ( 2248): BlockerCount change, 0x6b3e24c0,1,1
03-18 08:29:57.078 E/PRLog   ( 2248): BlockerCount change, 0x6b3e2600,1,1
03-18 08:29:57.078 E/PRLog   ( 2248): BlockerCount change, 0x6b3e24c0,1,-1
03-18 08:29:57.078 E/PRLog   ( 2248): BlockerCount change, 0x6b3e24c0,1,1
03-18 08:29:57.085 E/PRLog   ( 2248): MediaDecoderStateMachine(0x6ae8d090) 0x6b22b080 Media start time is 0
03-18 08:29:57.085 E/PRLog   ( 2248): MediaDecoderStateMachine(0x6ae8d090) 0x6b22b080 Changed state from DECODING_METADATA to DECODING
03-18 08:29:57.085 E/PRLog   ( 2248): MediaDecoderStateMachine(0x6ae8d090) 0x6b22b080 CheckIfDecodeComplete NOT completed
03-18 08:29:57.085 E/PRLog   ( 2248): MediaDecoderStateMachine(0x6ae8d090) ScheduleStateMachine 1, 0, StartDecoding
03-18 08:29:57.085 E/PRLog   ( 2248): MediaDecoderStateMachine(0x6ae8d090) 0x6b22b080 CheckIfDecodeComplete NOT completed
03-18 08:29:57.093 E/PRLog   ( 2248): endBlockingDecisions not advance, 45629!!! <-- bug 934794 (https://bugzilla.mozilla.org/show_bug.cgi?id=934794#c10)

Let's wait and see if Bug 934794 fixes the timeout here.
Depends on: 934794
Inactive; closing (see bug 1180138).
Status: NEW → RESOLVED
Closed: 9 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.