Closed Bug 762774 Opened 12 years ago Closed 9 years ago

Intermittent test_loop.html | Test timed out.

Categories

(Core :: Audio/Video, defect)

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

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla43
Tracking Flags:
Tracking Status
firefox41 --- wontfix
firefox42 --- fixed
firefox43 --- fixed
firefox-esr38 --- wontfix
b2g-v2.2 --- wontfix
b2g-master --- fixed

People

(Reporter: philor, Assigned: bechen)

References

Details

(Keywords: intermittent-failure, Whiteboard: [rr])

Attachments

(1 file, 1 obsolete file)

bug-762774-fix-v01.patch
1.67 KB, patch
jwwang
: review+
Details | Diff | Splinter Review
https://tbpl.mozilla.org/php/getParsedLog.php?id=12476024&tree=Mozilla-Inbound Rev3 Fedora 12 mozilla-inbound opt test mochitests-1/5 on 2012-06-07 20:52:24 PDT for push 274d17d6394e slave: talos-r3-fed-027 91185 INFO TEST-PASS | /tests/content/media/test/test_loop.html | Should get exactly one play event. nsBuiltinDecoderStateMachine::RunStateMachine queuing nsBuiltinDecoder::PlaybackEnded nsBuiltinDecoder::PlaybackEnded mPlayState=3 nsBuiltinDecoder::SeekingStopped, next state=3 nsBuiltinDecoderStateMachine::RunStateMachine queuing nsBuiltinDecoder::PlaybackEnded nsBuiltinDecoder::PlaybackEnded mPlayState=3 Suppressed timeupdate during seeking: currentTime=0.000000, new time=0.000000 nsBuiltinDecoder::SeekingStopped, next state=3 nsBuiltinDecoderStateMachine::RunStateMachine queuing nsBuiltinDecoder::PlaybackEnded nsBuiltinDecoder::PlaybackEnded mPlayState=3 nsBuiltinDecoder::SeekingStopped, next state=3 nsBuiltinDecoderStateMachine::RunStateMachine queuing nsBuiltinDecoder::PlaybackEnded nsBuiltinDecoder::PlaybackEnded mPlayState=3 Suppressed timeupdate during seeking: currentTime=0.000000, new time=0.000000 nsBuiltinDecoder::SeekingStopped, next state=3 nsBuiltinDecoderStateMachine::RunStateMachine queuing nsBuiltinDecoder::PlaybackEnded nsBuiltinDecoder::PlaybackEnded mPlayState=3 nsBuiltinDecoder::SeekingStopped, next state=3 91186 INFO TEST-PASS | /tests/content/media/test/test_loop.html | Expect matched pairs of seeking/seeked events. nsBuiltinDecoderStateMachine::RunStateMachine queuing nsBuiltinDecoder::PlaybackEnded nsBuiltinDecoder::PlaybackEnded mPlayState=3 91187 INFO TEST-PASS | /tests/content/media/test/test_loop.html | Shouldn't get ended event while looping. 91188 INFO TEST-PASS | /tests/content/media/test/test_loop.html | [finished seek.webm-3] Length of array should match number of running tests - 1 should equal 1 91189 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_loop.html | Test timed out. (screenshot of nothing in the iframe) 91190 INFO TEST-END | /tests/content/media/test/test_loop.html | finished in 309454ms
Whiteboard: [orange]
Please can you find an owner for this intermittent-failure - the current overall tree intermittent failure rate is spiralling out of control & the majority of bugs are unowned (see dev.platform thread).
Flags: needinfo?(roc)
Assignee: nobody → chris.double
7 month old needinfo request - think best bet just to disable the test and move on sadly...
Flags: needinfo?(roc)
The NSPR log for playing gizmo.mp4 on B2G (https://tbpl.mozilla.org/php/getParsedLog.php?id=35117045&tree=Try&full=1): 2014-02-23 15:25:52.028653 UTC - 64160[4489a380]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decoding Media Headers 2014-02-23 15:25:53.369677 UTC - 64160[4489a380]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Media start time is 0 2014-02-23 15:25:53.370117 UTC - 64160[4489a380]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decoder playing video frame 0 2014-02-23 15:25:53.380525 UTC - 64160[4489a380]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Media goes from 0 to 5568000 (duration 5568000) transportSeekable=1, mediaSeekable=1 2014-02-23 15:25:53.381528 UTC - 64160[4489a380]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Changed state from DECODING_METADATA to DECODING 2014-02-23 15:25:53.390445 UTC - 64160[4489a380]: MediaDecoderStateMachine(42fee3a0) 42ff2900 StartPlayback() 2014-02-23 15:25:53.393837 UTC - 64160[4489a380]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Start DecodeLoop() 2014-02-23 15:25:53.400775 UTC - 63760[437bd980]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decoder discarding video frame 0 2014-02-23 15:25:53.401312 UTC - 63760[437bd980]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decoder playing video frame 0 2014-02-23 15:25:53.437461 UTC - 63680[4325c300]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Begun audio thread/loop skipping many lines of logs ... 2014-02-23 15:26:19.085880 UTC - 63680[4325c300]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decoder playing 1024 frames of data to stream for AudioData at 5546666 2014-02-23 15:26:19.092742 UTC - 63760[437bd980]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decoder discarding video frame 5400000 2014-02-23 15:26:19.093236 UTC - 63760[437bd980]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decoder playing video frame 5400000 2014-02-23 15:26:19.271745 UTC - 63760[437bd980]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decoder discarding video frame 5433333 2014-02-23 15:26:19.272629 UTC - 63760[437bd980]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decoder playing video frame 5433333 2014-02-23 15:26:19.480460 UTC - 63760[437bd980]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decoder discarding video frame 5466666 2014-02-23 15:26:19.484998 UTC - 63760[437bd980]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decoder discarding video frame 5500000 2014-02-23 15:26:19.487064 UTC - 63760[437bd980]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decoder discarding video frame 5500000 (1 so far) 2014-02-23 15:26:19.488122 UTC - 63760[437bd980]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decoder playing video frame 5500000 2014-02-23 15:26:19.530536 UTC - 63680[4325c300]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Reached audio stream end. 2014-02-23 15:26:19.541957 UTC - 63680[4325c300]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Audio stream finished playing, audio thread exit 2014-02-23 15:26:19.556293 UTC - 64160[4489a380]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Exiting DecodeLoop 2014-02-23 15:26:19.556696 UTC - 64160[4489a380]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Decode thread finished 2014-02-23 15:26:19.562585 UTC - 63760[437bd980]: MediaDecoderStateMachine(42fee3a0) 42ff2900 StopPlayback() 2014-02-23 15:26:19.564293 UTC - 63760[437bd980]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Shutdown audio thread 2014-02-23 15:26:19.575871 UTC - 1074386056[40222080]: MediaDecoderStateMachine(42fee3a0) 42ff2900 Changed state to SEEKING (to 0.000000) playback time: 15:25:52 -> 15:26:19 = 27s It takes 27s for each loop of gizmo.mp4 playback, and we have 4 loops for each file. This should account for timeouts on b2g. The duration of gizmo.mp4 is 5.56s. It is suspicious for it takes about 30s each loop on B2G. Btw, I changed PARALLEL_TESTS in manifest.js to 1 so that files are played in sequence and timeouts are more likely to happen. I also checked other successful cases in https://tbpl.mozilla.org/?tree=Try&rev=79c96b770c3f. Each test_loop.html took about 260s which was close to the timeout. Even with PARALLEL_TESTS = 2, it still took about 230s in https://tbpl.mozilla.org/php/getParsedLog.php?id=35113027&tree=Try&full=1.
https://tbpl.mozilla.org/php/getParsedLog.php?id=35130069&tree=Try&full=1 Add logs to show playback time for each loop. 20:37:00 INFO - 1279 INFO TEST-START | /tests/content/media/test/test_loop.html 20:37:00 INFO - 1280 INFO TEST-INFO | /tests/content/media/test/test_loop.html | Started Sun Feb 23 2014 20:36:43 GMT+0000 (GMT) (1393187803.607s) 20:37:00 INFO - 1281 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.ogg playback time=384 20:37:00 INFO - 1282 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.ogg playback time=391 20:37:00 INFO - 1283 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.ogg playback time=370 20:37:00 INFO - 1284 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav playback time=1267 20:37:00 INFO - 1285 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.ogg playback time=370 20:37:00 INFO - 1286 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/320x240.ogv playback time=335 20:37:00 INFO - 1287 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav playback time=1304 20:37:00 INFO - 1288 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/320x240.ogv playback time=292 20:37:00 INFO - 1289 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/320x240.ogv playback time=300 20:37:00 INFO - 1290 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/320x240.ogv playback time=297 20:37:00 INFO - 1291 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav playback time=1260 20:37:00 INFO - 1292 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav playback time=1170 20:37:00 INFO - 1293 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/seek.webm playback time=4079 20:37:00 INFO - 1294 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/vp9.webm playback time=4083 20:37:00 INFO - 1295 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/seek.webm playback time=4041 20:37:00 INFO - 1296 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/vp9.webm playback time=4051 20:37:20 INFO - tests/content/media/test/big.wav 20:37:20 INFO - tests/content/media/test/320x240.ogv 20:37:20 INFO - tests/content/media/test/big.wav 20:37:20 INFO - tests/content/media/test/320x240.ogv 20:37:21 INFO - tests/content/media/test/seek.webm 20:37:21 INFO - tests/content/media/test/seek.webm 20:38:00 INFO - 1297 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/seek.webm playback time=5032 20:38:00 INFO - 1298 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/vp9.webm playback time=4072 20:38:00 INFO - 1299 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/seek.webm playback time=4040 20:38:00 INFO - 1300 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/vp9.webm playback time=4041 20:38:00 INFO - 1301 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/detodos.opus playback time=3281 20:38:00 INFO - 1302 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/detodos.opus playback time=3166 20:38:00 INFO - 1303 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/detodos.opus playback time=3165 20:38:00 INFO - 1304 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/detodos.opus playback time=3161 20:38:00 INFO - 1305 INFO TEST-INFO | /tests/content/media/test/test_loop.html | Finished at Sun Feb 23 2014 20:37:19 GMT+0000 (GMT) (1393187839.311s) 20:38:00 INFO - 1306 INFO TEST-INFO | /tests/content/media/test/test_loop.html | Running time: 35.704s 20:38:00 INFO - 1307 INFO TEST-INFO | MEMORY STAT vsize after test: 827723776 20:38:00 INFO - 1308 INFO TEST-INFO | MEMORY STAT residentFast after test: 207302656 20:38:00 INFO - 1309 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 30376708 20:38:00 INFO - 1310 INFO TEST-END | /tests/content/media/test/test_loop.html | finished in 36139ms It looks like gizmo.mp4 is not supported on Android 4 and not even played at all.
https://tbpl.mozilla.org/php/getParsedLog.php?id=35131216&tree=Try&full=1 Add logs to show playback time for each loop. 21:35:07 INFO - 1428 INFO TEST-START | /tests/content/media/test/test_loop.html 21:35:07 INFO - 1429 INFO TEST-INFO | /tests/content/media/test/test_loop.html | Started Mon Feb 24 2014 05:34:54 GMT+0000 (UTC) (1393220094.149s) 21:35:07 INFO - 1430 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.ogg playback time=931 21:35:07 INFO - 1431 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.ogg playback time=437 21:35:07 INFO - 1432 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.m4a playback time=1564 21:35:07 INFO - 1433 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.ogg playback time=391 21:35:07 INFO - 1434 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.ogg playback time=393 21:35:07 INFO - 1435 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.m4a playback time=1943 21:35:07 INFO - 1436 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.m4a playback time=999 21:35:07 INFO - 1437 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.mp3 playback time=1690 21:35:07 INFO - 1438 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.m4a playback time=725 21:35:07 INFO - 1439 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.mp3 playback time=1689 21:35:07 INFO - 1440 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.mp3 playback time=689 21:35:07 INFO - 1441 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav playback time=1560 21:35:07 INFO - 1442 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/small-shot.mp3 playback time=746 21:35:07 INFO - 1443 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav playback time=1688 21:35:07 INFO - 1444 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/320x240.ogv playback time=746 21:35:07 INFO - 1445 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/320x240.ogv playback time=795 21:35:07 INFO - 1446 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav playback time=1397 21:38:53 INFO - 1447 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/320x240.ogv playback time=828 21:38:53 INFO - 1448 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/r11025_s16_c1.wav playback time=1434 21:38:53 INFO - 1449 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/320x240.ogv playback time=1630 21:38:53 INFO - 1450 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/vp9.webm playback time=9092 21:38:53 INFO - 1451 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/vp9.webm playback time=13436 21:38:53 INFO - 1452 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/seek.webm playback time=24711 21:38:53 INFO - 1453 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/seek.webm playback time=26828 21:38:53 INFO - 1454 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/vp9.webm playback time=33372 21:38:53 INFO - 1455 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/vp9.webm playback time=11614 21:38:53 INFO - 1456 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/seek.webm playback time=19245 21:38:53 INFO - 1457 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/detodos.opus playback time=3394 21:38:53 INFO - 1458 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/detodos.opus playback time=3229 21:38:53 INFO - 1459 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/detodos.opus playback time=3464 21:38:53 INFO - 1460 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/detodos.opus playback time=3113 21:38:53 INFO - 1461 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/seek.webm playback time=18730 21:38:53 INFO - 1462 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/gizmo.mp4 playback time=28487 21:38:53 INFO - 1463 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/gizmo.mp4 playback time=27261 21:38:53 INFO - 1464 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/gizmo.mp4 playback time=27201 21:38:53 INFO - 1465 INFO TEST-INFO | /tests/content/media/test/test_loop.html | http://mochi.test:8888/tests/content/media/test/gizmo.mp4 playback time=28176 21:38:53 INFO - 1466 INFO TEST-INFO | /tests/content/media/test/test_loop.html | Finished at Mon Feb 24 2014 05:38:31 GMT+0000 (UTC) (1393220311.605s) 21:38:53 INFO - 1467 INFO TEST-INFO | /tests/content/media/test/test_loop.html | Running time: 217.456s 21:38:53 INFO - 1468 INFO TEST-INFO | MEMORY STAT vsize after test: 95858688 21:38:53 INFO - 1469 INFO TEST-INFO | MEMORY STAT residentFast after test: 48164864 21:38:53 INFO - 1470 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 20759172 21:38:53 INFO - 1471 INFO TEST-END | /tests/content/media/test/test_loop.html | finished in 218837ms As we can see the playback time of gizmo.mp4 can be as high as 28s and the test takes 218837ms in total. I think we can increase the timeout value on B2G so it has more time to complete the test. And we can also add logs to trace the playback time which will help debug timeouts on other platforms.
I may have recorded this failure, but I was off doing something else and the trace exhausted my disk space. Will try to find someone if I record it again.
Whiteboard: [rr]