Closed Bug 668973 Opened 14 years ago Closed 11 years ago

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

Categories

(Core :: Audio/Video, defect)

Product:
Core
Component:
Audio/Video
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: mak, Assigned: jwwang)

References

Details

(Keywords: intermittent-failure)

Attachments

(3 files)

668973_enable_test_playback.patch
2.74 KB, patch
cpearce
: review+
Details | Diff | Splinter Review
668973_part1_remove_flooding_logs.patch
3.31 KB, patch
cpearce
: review+
Details | Diff | Splinter Review
668973_part2_make_timeout_reason_obvious.patch
3.49 KB, patch
cpearce
: review+
Details | Diff | Splinter Review
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)
This intermittent failure is #3 on OrangeFactor, and as such worthy of escalation due to https://wiki.mozilla.org/Sheriffing/Test_Disabling_Policy Needinfo'ing an appropriate person (in this case: the last person to touch the test) for estimation of next steps & timeframe. The policy requires that I state that after two working days a needinfo on the module owner will be added, and failing that - the test disabled 2 working days after that. But that's an absolutely last resort :-) Note this test also has many other bugs filed against it: https://bugzilla.mozilla.org/buglist.cgi?quicksearch=test_playback.html
Flags: needinfo?(jwwang)
I am looking at this bug. However, I don't think it can be fixed in a short time. I would suggest to disable this bug on Android only.
Assignee: nobody → jwwang
Flags: needinfo?(jwwang)
Thanks, JW. Disabled on Android. https://hg.mozilla.org/integration/b2g-inbound/rev/52b9baee3402
Whiteboard: [test disabled on Android][leave open]
Depends on: 1033121
Since test_playback tests the fundamental functionality of our media stack, I would like to enable this test as soon as possible. However, there is bug 1039901 which will cause failure in checking MP3 duration. Therefore I skip the MP3 duration test on B2G so we can enable this test. Once bug 1039901 is fixed, we can remove the workaround to increase the test coverage. Try on Android and B2G: https://tbpl.mozilla.org/?tree=Try&rev=3916e403bc84 https://tbpl.mozilla.org/?tree=Try&rev=a3e56f54102a No failures in test_playback.html. So far so good.
Attachment #8458381 - Flags: review?(cpearce)
Attachment #8458381 - Flags: review?(cpearce) → review+
Keywords: checkin-needed
Recent timeouts are due to bug 1076691 comment 0. Once bug 1076691 is fixed, I will modify test_playback.html to prevent timeouts for different reasons fall into the same bug which makes it hard to track the bug status and progress.
Depends on: 1076691
No longer depends on: 943189
Remove flooding logs in 'timeupdate' event handler which makes debugging hard.
Attachment #8501488 - Flags: review?(cpearce)
Per comment 382, rewrite the test case to show the timeout reasons for easier debugging.
Attachment #8501489 - Flags: review?(cpearce)
Try: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=9005a1edfa5c The oranges on B2G are either about graphics or related to media recorder which is a known issue.
Attachment #8501488 - Flags: review?(cpearce) → review+
Comment on attachment 8501489 [details] [diff] [review] 668973_part2_make_timeout_reason_obvious.patch Review of attachment 8501489 [details] [diff] [review]: ----------------------------------------------------------------- ::: content/media/test/test_playback.html @@ +68,5 @@ > + > + // Check if we time out in waiting for some events. > + var registerTimer = function() { > + cancelTimer(); > + timer = setTimeout(onTimeout, 30000); Is 30s enough in debug b2g emulator builds? I'd hope so...
Attachment #8501489 - Flags: review?(cpearce) → review+
Comment on attachment 8501489 [details] [diff] [review] 668973_part2_make_timeout_reason_obvious.patch Review of attachment 8501489 [details] [diff] [review]: ----------------------------------------------------------------- ::: content/media/test/test_playback.html @@ +68,5 @@ > + > + // Check if we time out in waiting for some events. > + var registerTimer = function() { > + cancelTimer(); > + timer = setTimeout(onTimeout, 30000); The timer is re-scheduled in 'timeupdate' which should work for a file longer than 30s as long as 'tmeupdate' fires regualarly.
Please check in 668973_part1_remove_flooding_logs.patch and 668973_part2_make_timeout_reason_obvious.patch only and close this bug after verified. It is hard to track the bug status when timeouts come from various causes.
Keywords: checkin-needed
Hi KWierso, Can we close this bug? It is hard to track the bug status in the same bug when timeouts come from various causes. I would like to open a new bug when timeouts pop up again.
Flags: needinfo?(kwierso)
Sounds good to me.
Status: NEW → RESOLVED
Closed: 11 years ago
Flags: needinfo?(kwierso)
Resolution: --- → FIXED
Let's call this incomplete since AFAICT we never landed any fixes here.
Resolution: FIXED → INCOMPLETE
Whiteboard: [test disabled on Android][leave open]
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #395) > Let's call this incomplete since AFAICT we never landed any fixes here. What about the two mozila-central changesets in comment #392? Aren't they the patches mentioned in comment #390? Or don't they count as fixes? (Sorry if the question makes me look stupid.)
Those were debugging patches.
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: