Closed Bug 668973 Opened 8 years ago Closed 5 years ago

Intermittent Android test_playback.html | Test timed out. (test cases seek.webm, *.ogv)

Categories

(Core :: Audio/Video, defect)

defect
Not set

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: mak, Assigned: jwwang)

References

Details

(Keywords: intermittent-failure)

Attachments

(3 files)

http://tinderbox.mozilla.org/showlog.cgi?log=Mozilla-Inbound/1309589091.1309590500.29259.gz

65434 INFO TEST-PASS | /tests/content/media/test/test_playback.html | r16000_u8_c1_list.wav duration (4.264125) should be around 4.2
65435 INFO TEST-PASS | /tests/content/media/test/test_playback.html | r16000_u8_c1_list.wav time should run forwards: p=4.249312 c=4.264125
65436 INFO TEST-PASS | /tests/content/media/test/test_playback.html | r16000_u8_c1_list.wav current time at end: 4.264125 should be: 4.2
65437 INFO TEST-PASS | /tests/content/media/test/test_playback.html | Name should match test.name #2 - "r16000_u8_c1_list.wav" should equal "r16000_u8_c1_list.wav"
65438 INFO TEST-PASS | /tests/content/media/test/test_playback.html | r16000_u8_c1_list.wav checking readyState - 2 should equal 2
65439 INFO TEST-PASS | /tests/content/media/test/test_playback.html | r16000_u8_c1_list.wav shouldn't report NETWORK_LOADED
65440 INFO TEST-PASS | /tests/content/media/test/test_playback.html | r16000_u8_c1_list.wav checking playback has ended
65441 INFO TEST-PASS | /tests/content/media/test/test_playback.html | Name should match test.name #4 - "r16000_u8_c1_list.wav" should equal "r16000_u8_c1_list.wav"
65442 INFO TEST-PASS | /tests/content/media/test/test_playback.html | r16000_u8_c1_list.wav duration (4.264125) should be around 4.2
65443 INFO TEST-PASS | /tests/content/media/test/test_playback.html | r16000_u8_c1_list.wav time should run forwards: p=4.264125 c=4.264125
65444 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_playback.html | Test timed out.
65445 INFO TEST-END | /tests/content/media/test/test_playback.html | finished in 307290ms
(In reply to comment #1)
> philor
> http://tinderbox.mozilla.org/showlog.cgi?log=Mozilla-Inbound/1309726910.
> 1309730812.7588.gz
> Rev3 MacOSX Snow Leopard 10.6.2 mozilla-inbound debug test mochitests-1/5 on
> 2011/07/03 14:01:50
> 
> s: talos-r3-snow-029
> 65580 ERROR TEST-UNEXPECTED-FAIL |
> /tests/content/media/test/test_playback.html | Test timed out.

Assertion failures in ogg seeking in the log:

65620 INFO TEST-PASS | /tests/content/media/test/test_played.html | end time shall be duration - 4 should equal 4
###!!! ASSERTION: Must get a granuletime: 'granuleTime > 0', file /builds/slave/m-in-osx64-dbg/build/content/media/ogg/nsOggReader.cpp, line 1382
nsOggReader::SeekBisection [content/media/ogg/nsOggReader.cpp:1386]
nsOggReader::SeekInBufferedRange [content/media/ogg/nsOggReader.cpp:968]
nsOggReader::Seek [content/media/ogg/nsOggReader.cpp:1099]
nsBuiltinDecoderStateMachine::Run [content/media/nsBuiltinDecoderStateMachine.cpp:1187]
nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:617]
NS_ProcessNextEvent_P [obj-firefox/xpcom/build/nsThreadUtils.cpp:245]
nsThread::ThreadFunc [xpcom/threads/nsThread.cpp:271]
_pt_root [nsprpub/pr/src/pthreads/ptthread.c:190]
libSystem.B.dylib + 0x3a536
###!!! ASSERTION: offset_start must increase: 'pageOffset > startOffset', file /builds/slave/m-in-osx64-dbg/build/content/media/ogg/nsOggReader.cpp, line 1420
nsOggReader::SeekBisection [content/media/ogg/nsOggReader.cpp:1421]
nsOggReader::SeekInBufferedRange [content/media/ogg/nsOggReader.cpp:968]
nsOggReader::Seek [content/media/ogg/nsOggReader.cpp:1099]
nsBuiltinDecoderStateMachine::Run [content/media/nsBuiltinDecoderStateMachine.cpp:1187]
nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:617]
NS_ProcessNextEvent_P [obj-firefox/xpcom/build/nsThreadUtils.cpp:245]
nsThread::ThreadFunc [xpcom/threads/nsThread.cpp:271]
_pt_root [nsprpub/pr/src/pthreads/ptthread.c:190]
libSystem.B.dylib + 0x3a536
###!!! ASSERTION: Must get a granuletime: 'granuleTime > 0', file /builds/slave/m-in-osx64-dbg/build/content/media/ogg/nsOggReader.cpp, line 1382
nsOggReader::SeekBisection [content/media/ogg/nsOggReader.cpp:1386]
nsOggReader::SeekInBufferedRange [content/media/ogg/nsOggReader.cpp:968]
nsOggReader::Seek [content/media/ogg/nsOggReader.cpp:1099]
nsBuiltinDecoderStateMachine::Run [content/media/nsBuiltinDecoderStateMachine.cpp:1187]
nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:617]
NS_ProcessNextEvent_P [obj-firefox/xpcom/build/nsThreadUtils.cpp:245]
nsThread::ThreadFunc [xpcom/threads/nsThread.cpp:271]
_pt_root [nsprpub/pr/src/pthreads/ptthread.c:190]
libSystem.B.dylib + 0x3a536
65621 INFO TEST-PASS | /tests/content/media/test/test_played.html | normal play: a.played.length must be 1 - 1 should equal 1
65622 INFO TEST-PASS | /tests/content/media/test/test_played.html | start time shall be 0 - 0 should equal 0
65623 INFO TEST-PASS | /tests/content/media/test/test_played.html | end time shall be duration - 4 should equal 4
65624 INFO TEST-PASS | /tests/content/media/test/test_played.html | normal play: a.played.length must be 1 - 1 should equal 1
65625 INFO TEST-PASS | /tests/content/media/test/test_played.html | start time shall be 0 - 0 should equal 0
65626 INFO TEST-PASS | /tests/content/media/test/test_played.html | end time shall be duration - 9.288072 should equal 9.288072
before 1187840, after 1179648, break 10a011000
before 1179648, after 1175552, break 10a011000
before 1208320, after 1187840, break 10a011000
before 1183744, after 1179648, break 10a011000
before 1183744, after 1175552, break 10a011000
before 1175552, after 1175552, break 10a011000
before 1183744, after 1171456, break 10a011000
before 1175552, after 1171456, break 10a011000
before 1179648, after 1175552, break 10a011000
before 1175552, after 1171456, break 10a011000
65627 INFO TEST-PASS | /tests/content/media/test/test_played.html | normal play: a.played.length must be 1 - 1 should equal 1
65628 INFO TEST-PASS | /tests/content/media/test/test_played.html | start time shall be 0 - 0 should equal 0
65629 INFO TEST-PASS | /tests/content/media/test/test_played.html | end time shall be duration - 3.99996 should equal 3.99996
65630 INFO TEST-PASS | /tests/content/media/test/test_played.html | normal play: a.played.length must be 1 - 1 should equal 1
65631 INFO TEST-PASS | /tests/content/media/test/test_played.html | start time shall be 0 - 0 should equal 0
65632 INFO TEST-PASS | /tests/content/media/test/test_played.html | end time shall be duration - 4 should equal 4
before 1179648, after 1175552, break 10a011000
###!!! ASSERTION: Seek target should lie inside the first audio block after seek: '!audio || (audio->mTime <= seekTime && seekTime <= audio->mTime + audio->mDuration)', file /builds/slave/m-in-osx64-dbg/build/content/media/nsBuiltinDecoderStateMachine.cpp, line 1193
nsBuiltinDecoderStateMachine::Run [content/media/nsBuiltinDecoderStateMachine.cpp:1194]
nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:617]
NS_ProcessNextEvent_P [obj-firefox/xpcom/build/nsThreadUtils.cpp:245]
nsThread::ThreadFunc [xpcom/threads/nsThread.cpp:271]
_pt_root [nsprpub/pr/src/pthreads/ptthread.c:190]
libSystem.B.dylib + 0x3a536
65633 INFO TEST-PASS | /tests/content/media/test/test_played.html | element.played.length == 2 - 2 should equal 2
65634 INFO TEST-PASS | /tests/content/media/test/test_played.html | start of first range shall be 0 - 0 should equal 0
65635 INFO TEST-PASS | /tests/content/media/test/test_played.html | we should have seeked forward by one tenth of the duration
65636 INFO TEST-PASS | /tests/content/media/test/test_played.html | end of second range shall be the total duration - 4.000124 should equal 4.000124
before 1179648, after 1175552, break 10a011000
WARNING: Should be playing: 'IsPlaying()', file /builds/slave/m-in-osx64-dbg/build/content/media/nsBuiltinDecoderStateMachine.cpp, line 619
65637 INFO TEST-PASS | /tests/content/media/test/test_played.html | element.played.length == 2 - 2 should equal 2
65638 INFO TEST-PASS | /tests/content/media/test/test_played.html | start of first range shall be 0 - 0 should equal 0
65639 INFO TEST-PASS | /tests/content/media/test/test_played.html | we should have seeked forward by one tenth of the duration
65640 INFO TEST-PASS | /tests/content/media/test/test_played.html | end of second range shall be the total duration - 9.288071 should equal 9.288071
before 1179648, after 1175552, break 10a011000
before 1179648, after 1175552, break 10a011000
65641 INFO TEST-PASS | /tests/content/media/test/test_played.html | element.played.length == 2 - 2 should equal 2
65642 INFO TEST-PASS | /tests/content/media/test/test_played.html | start of first range shall be 0 - 0 should equal 0
65643 INFO TEST-PASS | /tests/content/media/test/test_played.html | we should have seeked forward by one tenth of the duration
65644 INFO TEST-PASS | /tests/content/media/test/test_played.html | end of second range shall be the total duration - 3.99996 should equal 3.99996
65645 INFO TEST-PASS | /tests/content/media/test/test_played.html | element.played.length == 2 - 2 should equal 2
65646 INFO TEST-PASS | /tests/content/media/test/test_played.html | start of first range shall be 0 - 0 should equal 0
65647 INFO TEST-PASS | /tests/content/media/test/test_played.html | we should have seeked forward by one tenth of the duration
65648 INFO TEST-PASS | /tests/content/media/test/test_played.html | end of second range shall be the total duration - 4 should equal 4
before 1179648, after 1175552, break 10a011000
WARNING: Should be playing: 'IsPlaying()', file /builds/slave/m-in-osx64-dbg/build/content/media/nsBuiltinDecoderStateMachine.cpp, line 619
###!!! ASSERTION: Must get a granuletime: 'granuleTime > 0', file /builds/slave/m-in-osx64-dbg/build/content/media/ogg/nsOggReader.cpp, line 1382
nsOggReader::SeekBisection [content/media/ogg/nsOggReader.cpp:1386]
nsOggReader::SeekInBufferedRange [content/media/ogg/nsOggReader.cpp:968]
nsOggReader::Seek [content/media/ogg/nsOggReader.cpp:1099]
nsBuiltinDecoderStateMachine::Run [content/media/nsBuiltinDecoderStateMachine.cpp:1187]
nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:617]
NS_ProcessNextEvent_P [obj-firefox/xpcom/build/nsThreadUtils.cpp:245]
nsThread::ThreadFunc [xpcom/threads/nsThread.cpp:271]
_pt_root [nsprpub/pr/src/pthreads/ptthread.c:190]
libSystem.B.dylib + 0x3a536
###!!! ASSERTION: offset_start must increase: 'pageOffset > startOffset', file /builds/slave/m-in-osx64-dbg/build/content/media/ogg/nsOggReader.cpp, line 1420
nsOggReader::SeekBisection [content/media/ogg/nsOggReader.cpp:1421]
nsOggReader::SeekInBufferedRange [content/media/ogg/nsOggReader.cpp:968]
nsOggReader::Seek [content/media/ogg/nsOggReader.cpp:1099]
nsBuiltinDecoderStateMachine::Run [content/media/nsBuiltinDecoderStateMachine.cpp:1187]
nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:617]
NS_ProcessNextEvent_P [obj-firefox/xpcom/build/nsThreadUtils.cpp:245]
nsThread::ThreadFunc [xpcom/threads/nsThread.cpp:271]
_pt_root [nsprpub/pr/src/pthreads/ptthread.c:190]
libSystem.B.dylib + 0x3a536
###!!! ASSERTION: Must get a granuletime: 'granuleTime > 0', file /builds/slave/m-in-osx64-dbg/build/content/media/ogg/nsOggReader.cpp, line 1382
nsOggReader::SeekBisection [content/media/ogg/nsOggReader.cpp:1386]
nsOggReader::SeekInBufferedRange [content/media/ogg/nsOggReader.cpp:968]
nsOggReader::Seek [content/media/ogg/nsOggReader.cpp:1099]
nsBuiltinDecoderStateMachine::Run [content/media/nsBuiltinDecoderStateMachine.cpp:1187]
nsThread::ProcessNextEvent [xpcom/threads/nsThread.cpp:617]
NS_ProcessNextEvent_P [obj-firefox/xpcom/build/nsThreadUtils.cpp:245]
nsThread::ThreadFunc [xpcom/threads/nsThread.cpp:271]
_pt_root [nsprpub/pr/src/pthreads/ptthread.c:190]
I can reproduce this hang when I have the test looping in about 20 tabs on my mac mini. The problem is that JavaScript runs out of stack space to execute the event handlers which trigger the test to finish. This happens because we have too many nsStopThreadEvents running trying to shut down decoders' state machine threads. They're calling Shutdown() on state machine threads, and other methods are running on top of that. JS is running on top of all those running events, and it's detecting stack exhaustion and refusing to run the event handler.

This happens on Mac only (or mostly?) because thread stack sizes are smallest on Mac.

This problem will go away once bug 592833 lands, as we'll no longer be shutting down any media threads on the main thread, except the (single) shared state machine thread. The decode and audio threads will then be shutting down on the shared state machine thread, so there's won't be any extra pressure on the main thread where JS executes. There may be pressure on the state machine thread's stack, but I'd assume it would be much less.
Summary: Intermittent timeout in /tests/content/media/test/test_playback.html | Test timed out → Intermittent timeout in /tests/content/media/test/test_playback.html | Test timed out, or application timed out after 330 seconds with no output
Whiteboard: [orange]
Summary: Intermittent timeout in /tests/content/media/test/test_playback.html | Test timed out, or application timed out after 330 seconds with no output → Intermittent timeout in /tests/content/media/test/test_playback.html on Android; test cases seek.webm, *.ogv | Test timed out, or application timed out after 330 seconds with no output
"ended" event not being fired here.
See Also: → 962663
Summary: Intermittent timeout in /tests/content/media/test/test_playback.html on Android; test cases seek.webm, *.ogv | Test timed out, or application timed out after 330 seconds with no output → Intermittent Android test_playback.html | Test timed out.; test cases seek.webm, *.ogv | Test timed out, or application timed out after 330 seconds with no output
Summary: Intermittent Android test_playback.html | Test timed out.; test cases seek.webm, *.ogv | Test timed out, or application timed out after 330 seconds with no output → Intermittent Android test_playback.html | Test timed out. (test cases seek.webm, *.ogv)