762774 - Intermittent test_loop.html | Test timed out.

Reporter

Description

•

13 years ago

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

Comment hidden (Legacy TBPL/Treeherder Robot)

Nobody; OK to take it and work on it

Updated

•

12 years ago

Keywords: intermittent-failure

Comment hidden (Legacy TBPL/Treeherder Robot)

Nobody; OK to take it and work on it

Updated

•

12 years ago

Whiteboard: [orange]

Comment hidden (Legacy TBPL/Treeherder Robot)

Ed Morley [:emorley]

Comment 145

•

12 years ago

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)

Robert O'Callahan (:roc) (email my personal email if necessary)

Updated

•

12 years ago

Assignee: nobody → chris.double

Comment hidden (Legacy TBPL/Treeherder Robot)

Ed Morley [:emorley]

Comment 204

•

11 years ago

7 month old needinfo request - think best bet just to disable the test and move on sadly...

Flags: needinfo?(roc)

Comment hidden (Legacy TBPL/Treeherder Robot)

ttaubert https://tbpl.mozilla.org/php/getParsedLog.php?id=34354480&tree=Fx-Team b2g_emulator_vm fx-team opt test mochitest-3 on 2014-02-08 09:57:31 revision: 6e77dfcf5c6e slave: tst-linux64-spot-078 1410 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_loop.html | Test timed out. 1417 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_media_sniffer.html | Test timed out. 1626 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_paused_after_ended.html | Test timed out. 1634 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_play_events.html | Test timed out. 1635 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. 1636 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 13 remaining tests. 1640 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/content/media/test/test_play_events.html finished in a non-clean fashion, probably because it didn't call SimpleTest.finish() 02-08 18:33:00.755 751 751 I GeckoDump: 1410 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_loop.html | Test timed out. 02-08 18:38:31.035 751 751 I GeckoDump: 1417 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_media_sniffer.html | Test timed out. 02-08 18:46:04.150 751 751 I GeckoDump: 1626 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_paused_after_ended.html | Test timed out. 02-08 18:51:35.197 751 751 I GeckoDump: 1634 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_play_events.html | Test timed out. 02-08 18:51:35.214 751 751 I GeckoDump: 1635 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. 02-08 18:51:35.234 751 751 I GeckoDump: 1636 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 13 remaining tests. 02-08 18:51:36.623 751 751 I GeckoDump: 1640 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/content/media/test/test_play_events.html finished in a non-clean fashion, probably because it didn't call SimpleTest.finish()

Comment hidden (Legacy TBPL/Treeherder Robot)

JW Wang [:jwwang] [:jw_wang]

Comment 249

•

11 years ago

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.

JW Wang [:jwwang] [:jw_wang]

Comment 250

•

11 years ago

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.

JW Wang [:jwwang] [:jw_wang]

Comment 251

•

11 years ago

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.

Comment hidden (Legacy TBPL/Treeherder Robot)

edmorley https://tbpl.mozilla.org/php/getParsedLog.php?id=35434821&tree=Mozilla-Inbound b2g_emulator_vm mozilla-inbound opt test mochitest-3 on 2014-02-28 09:54:38 revision: dd7286173768 slave: tst-linux64-ec2-384 1332 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_loop.html | Test timed out. 1358 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_media_sniffer.html | Test timed out. 1530 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_paused_after_ended.html | Test timed out. 1638 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_play_events.html | Test timed out. 1639 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. 1640 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 6 remaining tests. 1644 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/content/media/test/test_play_events.html finished in a non-clean fashion, probably because it didn't call SimpleTest.finish() 02-28 18:23:49.871 731 731 I GeckoDump: 1332 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_loop.html | Test timed out. 02-28 18:29:20.070 731 731 I GeckoDump: 1358 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_media_sniffer.html | Test timed out. 02-28 18:36:21.910 731 731 I GeckoDump: 1530 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_paused_after_ended.html | Test timed out. 02-28 18:41:52.851 731 731 I GeckoDump: 1638 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_play_events.html | Test timed out. 02-28 18:41:52.861 731 731 I GeckoDump: 1639 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. 02-28 18:41:52.861 731 731 I GeckoDump: 1640 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 6 remaining tests. 02-28 18:41:54.060 731 731 I GeckoDump: 1644 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/content/media/test/test_play_events.html finished in a non-clean fashion, probably because it didn't call SimpleTest.finish()

Chris Jones [:cjones] inactive; ni?/f?/r? if you need me

Comment 258

•

11 years ago

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]

Comment hidden (Legacy TBPL/Treeherder Robot)

RyanVM https://tbpl.mozilla.org/php/getParsedLog.php?id=35727792&tree=B2g-Inbound b2g_emulator_vm b2g-inbound opt test mochitest-3 on 2014-03-06 07:39:50 revision: 45a7ba51f378 slave: tst-linux64-spot-441 1297 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_loop.html | Test timed out. 1323 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_media_sniffer.html | Test timed out. 1495 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_paused_after_ended.html | Test timed out. 1603 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_play_events.html | Test timed out. 1604 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. 1605 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 20 remaining tests. 1609 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/content/media/test/test_play_events.html finished in a non-clean fashion, probably because it didn't call SimpleTest.finish() 03-06 16:13:58.032 737 737 I GeckoDump: 1297 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_loop.html | Test timed out. 03-06 16:19:28.282 737 737 I GeckoDump: 1323 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_media_sniffer.html | Test timed out. 03-06 16:26:32.352 737 737 I GeckoDump: 1495 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_paused_after_ended.html | Test timed out. 03-06 16:32:03.482 737 737 I GeckoDump: 1603 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_play_events.html | Test timed out. 03-06 16:32:03.482 737 737 I GeckoDump: 1604 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. 03-06 16:32:03.493 737 737 I GeckoDump: 1605 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 20 remaining tests. 03-06 16:32:04.722 737 737 I GeckoDump: 1609 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/content/media/test/test_play_events.html finished in a non-clean fashion, probably because it didn't call SimpleTest.finish()

Comment hidden (Legacy TBPL/Treeherder Robot)

Tomcat https://tbpl.mozilla.org/php/getParsedLog.php?id=36714396&tree=Mozilla-Aurora b2g_emulator_vm mozilla-aurora opt test mochitest-3 on 2014-03-25 23:16:46 revision: 849084164ca7 slave: tst-linux64-spot-595 1311 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_loop.html | Test timed out. 1337 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_media_sniffer.html | Test timed out. 1509 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_paused_after_ended.html | Test timed out. 1588 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_play_events.html | Test timed out. 1589 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. 1590 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 22 remaining tests. 1594 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/content/media/test/test_play_events.html finished in a non-clean fashion, probably because it didn't call SimpleTest.finish() 03-26 06:51:14.039 718 718 I GeckoDump: 1311 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_loop.html | Test timed out. 03-26 06:56:44.280 718 718 I GeckoDump: 1337 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_media_sniffer.html | Test timed out. 03-26 07:04:47.990 718 718 I GeckoDump: 1509 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_paused_after_ended.html | Test timed out. 03-26 07:10:19.550 718 718 I GeckoDump: 1588 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_play_events.html | Test timed out. 03-26 07:10:19.550 718 718 I GeckoDump: 1589 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. 03-26 07:10:19.560 718 718 I GeckoDump: 1590 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 22 remaining tests. 03-26 07:10:20.789 718 718 I GeckoDump: 1594 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/content/media/test/test_play_events.html finished in a non-clean fashion, probably because it didn't call SimpleTest.finish()

Comment hidden (Legacy TBPL/Treeherder Robot)

edmorley https://tbpl.mozilla.org/php/getParsedLog.php?id=39349936&tree=Fx-Team b2g_emulator_vm fx-team opt test mochitest-3 on 2014-05-09 03:10:48 revision: 6ebcd2ebbed4 slave: tst-linux64-spot-930 1306 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_loop.html | Test timed out. 1317 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_media_sniffer.html | Test timed out. 1357 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_mediarecorder_record_immediate_stop.html | Test timed out. 1367 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_mediarecorder_record_no_timeslice.html | Test timed out. 1368 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. 1369 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 44 remaining tests. 1373 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/content/media/test/test_mediarecorder_record_no_timeslice.html finished in a non-clean fashion, probably because it didn't call SimpleTest.finish() 05-09 10:50:23.173 759 759 I GeckoDump: 1306 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_loop.html | Test timed out. 05-09 10:55:53.293 759 759 I GeckoDump: 1317 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_media_sniffer.html | Test timed out. 05-09 11:01:54.723 759 759 I GeckoDump: 1357 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_mediarecorder_record_immediate_stop.html | Test timed out. 05-09 11:07:24.863 759 759 I GeckoDump: 1367 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_mediarecorder_record_no_timeslice.html | Test timed out. 05-09 11:07:24.883 759 759 I GeckoDump: 1368 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. 05-09 11:07:24.893 759 759 I GeckoDump: 1369 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 44 remaining tests. 05-09 11:07:26.523 759 759 I GeckoDump: 1373 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/content/media/test/test_mediarecorder_record_no_timeslice.html finished in a non-clean fashion, probably because it didn't call SimpleTest.finish()

Comment hidden (Legacy TBPL/Treeherder Robot)

Tomcat https://tbpl.mozilla.org/php/getParsedLog.php?id=40542714&tree=B2g-Inbound b2g_emulator_vm b2g-inbound opt test mochitest-3 on 2014-05-28 05:35:50 revision: 307154329504 slave: tst-linux64-spot-040 1326 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_loop.html | Test timed out. 1337 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_media_sniffer.html | Test timed out. 1377 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_mediarecorder_record_immediate_stop.html | Test timed out. 1387 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_mediarecorder_record_no_timeslice.html | Test timed out. 1388 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. 1389 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 44 remaining tests. 1393 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/content/media/test/test_mediarecorder_record_no_timeslice.html finished in a non-clean fashion, probably because it didn't call SimpleTest.finish() 05-28 13:15:22.654 760 760 I GeckoDump: 1326 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_loop.html | Test timed out. 05-28 13:20:52.765 760 760 I GeckoDump: 1337 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_media_sniffer.html | Test timed out. 05-28 13:26:53.434 760 760 I GeckoDump: 1377 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_mediarecorder_record_immediate_stop.html | Test timed out. 05-28 13:32:23.544 760 760 I GeckoDump: 1387 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_mediarecorder_record_no_timeslice.html | Test timed out. 05-28 13:32:23.584 760 760 I GeckoDump: 1388 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. 05-28 13:32:23.594 760 760 I GeckoDump: 1389 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 44 remaining tests. 05-28 13:32:25.214 760 760 I GeckoDump: 1393 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | /tests/content/media/test/test_mediarecorder_record_no_timeslice.html finished in a non-clean fashion, probably because it didn't call SimpleTest.finish()

Comment hidden (Legacy TBPL/Treeherder Robot)

JW Wang [:jwwang] [:jw_wang]

Comment 465

•

10 years ago

(In reply to TBPL Robot from comment #464) Found this in logcat: 09-15 17:34:12.554 E/libOpenSLES( 2252): Encountered unknown AudioTrack event 5 for CAudioPlayer 0x2428830

Depends on: 1015870

Comment hidden (Legacy TBPL/Treeherder Robot)

cajbir (:cajbir)

Updated

•

10 years ago

Assignee: cajbir.bugzilla → nobody

Comment hidden (Legacy TBPL/Treeherder Robot)

JW Wang [:jwwang] [:jw_wang]

Updated

•

9 years ago

Depends on: 1183955

Comment hidden (Legacy TBPL/Treeherder Robot)

JW Wang [:jwwang] [:jw_wang]

Comment 709

•

9 years ago

(In reply to Treeherder Robot from comment #672) The timeout becomes suddenly much more frequent since 8/7. I wonder if recent changes regress it. Hi Chris, Do you know is there a way to ask QA for a regression window for such intermittent timeouts?

Flags: needinfo?(cpearce)

Comment hidden (Legacy TBPL/Treeherder Robot)

Chris Pearce [:cpearce (Not reading bugmail)]

Comment 722

•

9 years ago

(In reply to JW Wang [:jwwang] from comment #709) > (In reply to Treeherder Robot from comment #672) > The timeout becomes suddenly much more frequent since 8/7. I wonder if > recent changes regress it. > > Hi Chris, > Do you know is there a way to ask QA for a regression window for such > intermittent timeouts? OrangeFactor seems to indicate something around August 6: https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=762774&endday=2015-08-11&startday=2014-12-31&tree=trunk I don't know if there's a way to get a more accurate regression window.

Flags: needinfo?(cpearce)

Comment hidden (Legacy TBPL/Treeherder Robot)

Ryan VanderMeulen [:RyanVM]

Comment 741

•

9 years ago

Spiking badly on B2G lately.

Flags: needinfo?(jwwang)

Comment hidden (Legacy TBPL/Treeherder Robot)

JW Wang [:jwwang] [:jw_wang]

Comment 749

•

9 years ago

Almost sure bug 1185792 is the cause for recent timeouts of test_loop.html. https://treeherder.mozilla.org/#/jobs?repo=try&revision=8df7716bc812 Try logs before bug 1185792 is landed. No timeouts in test_loop.html within 59 runs. https://treeherder.mozilla.org/#/jobs?repo=try&revision=b75814e240fa Try logs after bug 1185792 is landed. 17 timeouts in test_loop.html out of 59 runs. And the orange rate is much higher than before.

Flags: needinfo?(jwwang) → needinfo?(jyavenard)

Comment hidden (Legacy TBPL/Treeherder Robot)

Jean-Yves Avenard [:jya]

Comment 751

•

9 years ago

JW, It would be more useful to check with a current tree, with the webm pref on vs webm off. Something that could explain the difference, is that should the GONK decoder states that it supports VP8/VP9 ; then it will be used rather than the software based decoder based on libvpx. Does the gonk decoders supports that? Jan could you also have a look?

Flags: needinfo?(jyavenard)

Flags: needinfo?(jwwang)

Flags: needinfo?(j)

Comment hidden (Legacy TBPL/Treeherder Robot)

Jean-Yves Avenard [:jya]

Comment 764

•

9 years ago

https://treeherder.mozilla.org/#/jobs?repo=try&revision=ceb5c6e409cc This is with the rework of MediaResource that caused bug 1184429 and bug 1186804 there's no media related error in that try, that's with 30 repeat of every single test. M6 on gonk is pretty slow, but so far with 12 runs, no error

JW Wang [:jwwang] [:jw_wang]

Comment 765

•

9 years ago

https://treeherder.mozilla.org/logviewer.html#?job_id=10380518&repo=try One timeout in test_loop.html so far. Hi Benjamin, We have frequent timeout in test_loop.html on B2G recently. Can you help check if software or hardware decoders are used to decode webm files before and after bug 1185792 is landed? I doubt if software decoders which are slow and make the test case more timeout-prone.

Flags: needinfo?(jwwang) → needinfo?(bechen)

Benjamin Chen [:bechen]

Assignee

Comment 766

•

9 years ago

(In reply to JW Wang [:jwwang] from comment #765) > https://treeherder.mozilla.org/logviewer.html#?job_id=10380518&repo=try > One timeout in test_loop.html so far. > > Hi Benjamin, > We have frequent timeout in test_loop.html on B2G recently. Can you help > check if software or hardware decoders are used to decode webm files before > and after bug 1185792 is landed? I doubt if software decoders which are slow > and make the test case more timeout-prone. Sure, I'll check soon.

Flags: needinfo?(bechen)

Jean-Yves Avenard [:jya]

Comment 767

•

9 years ago

JW, the pref switched from the WebMReader to WebMDemuxer+MediaFormatReader. WebMReader was always software only except on windows with an intel 5000+ (and the HW acceleration is disabled by default) The new WebmDemuxer+MFR could do hardware, but on gonk, that codec isn't reported as being supported in HW (it reports supporting only: return aMimeType.EqualsLiteral("audio/mp4a-latm") || aMimeType.EqualsLiteral("audio/3gpp") || aMimeType.EqualsLiteral("audio/amr-wb") || aMimeType.EqualsLiteral("audio/mpeg") || aMimeType.EqualsLiteral("video/mp4") || aMimeType.EqualsLiteral("video/mp4v-es") || aMimeType.EqualsLiteral("video/avc") || aMimeType.EqualsLiteral("video/3gpp"); none of the codec would you find in a webm container

JW Wang [:jwwang] [:jw_wang]

Comment 768

•

9 years ago

So both of them use software decoders on B2G. There is no reason for WebMDemuxer+MediaFormatReader to run slower than WebMReader... weird...

Comment hidden (Legacy TBPL/Treeherder Robot)

Benjamin Chen [:bechen]

Assignee

Comment 779

•

9 years ago

https://dxr.mozilla.org/mozilla-central/source/dom/media/DecoderTraits.cpp#744 On b2g-emulator, the webm playback is still MediaOmxReader.

Benjamin Chen [:bechen]

Assignee

Comment 780

•

9 years ago

(In reply to Benjamin Chen [:bechen] from comment #779) > https://dxr.mozilla.org/mozilla-central/source/dom/media/DecoderTraits. > cpp#744 > > On b2g-emulator, the webm playback is still MediaOmxReader. https://dxr.mozilla.org/mozilla-central/source/dom/media/omx/moz.build#115 emulator-ICS is pure software...

Comment hidden (Legacy TBPL/Treeherder Robot)

Benjamin Chen [:bechen]

Assignee

Comment 784

•

9 years ago

On my desktop build, log for seek.webm: Decoder=7f48ae606d70 playing video frame 3333000 (id=51) (queued=70, state-machine=10, decoder-queued=60) It shows that there are 60 decoded samples in the queue. And now I'm trying to trace the |decoder.mSizeOfQueue| in MediaFormatReader, found the number of decoder.mSizeOfQueue always |add 2 -> dec 1 -> add 2 -> dec 1| so make the number to 60.

Comment hidden (Legacy TBPL/Treeherder Robot)

Jean-Yves Avenard [:jya]

Comment 792

•

9 years ago

without the new webm: https://treeherder.mozilla.org/#/jobs?repo=try&revision=38356b56ad3d with the new webm: https://treeherder.mozilla.org/#/jobs?repo=try&revision=573e44472313 80 runs each, no error at all. Unless the emulator doesn't show as OMX, the new code isn't used.

Flags: needinfo?(j)

Jean-Yves Avenard [:jya]

Comment 793

•

9 years ago

(In reply to Benjamin Chen [:bechen] from comment #784) > On my desktop build, log for seek.webm: > Decoder=7f48ae606d70 playing video frame 3333000 (id=51) (queued=70, > state-machine=10, decoder-queued=60) > > It shows that there are 60 decoded samples in the queue. > And now I'm trying to trace the |decoder.mSizeOfQueue| in MediaFormatReader, > found the number of decoder.mSizeOfQueue always |add 2 -> dec 1 -> add 2 -> > dec 1| so make the number to 60. sounds like bug 1194884

Comment hidden (Legacy TBPL/Treeherder Robot)

Benjamin Chen [:bechen]

Assignee

Comment 826

•

9 years ago

(In reply to Treeherder Robot from comment #825) > log: > https://treeherder.mozilla.org/logviewer.html#?repo=mozilla- > inbound&job_id=13024669 > repository: mozilla-inbound > start_time: 2015-08-18T19:34:25 > who: philringnalda[at]gmail[dot]com > machine: tst-linux64-spot-1991 > buildname: b2g_emulator_vm mozilla-inbound opt test mochitest-6 > revision: 67e660dfdd37 > > 433 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_loop.html | Test timed > out. > 08-19 05:42:00.896 F/libc ( 778): Fatal signal 11 (SIGSEGV) at > 0x00000000 (code=1) > This usually indicates the B2G process has crashed > Return code: 1 Some clues. From the log: 503 INFO TEST-OK | dom/media/test/test_play_events.html | took 147782ms 435 INFO TEST-OK | dom/media/test/test_loop.html | took 454152ms These two testcases run the same files |gSmallTests|. test_play_events plays the files once and test_loop plays the files three times in order to verify the loop attribute. 147s * 3 = 441s is almost equal to 454s. So we can exclude the seek operation.

Comment hidden (Legacy TBPL/Treeherder Robot)

Benjamin Chen [:bechen]

Assignee

Comment 830

•

9 years ago

Finally get some useful information from log. I insert some log at test_play_events to detect the system time we play a webm file. Without the new webm, vp9.webm-1 spends only 1.715s, but the duration of this file is 4s. After apply the new webm, the system time look like normal, usually spends 5s to play it. Apparently, there is something wrong for vp9.webm at the old code path.

JW Wang [:jwwang] [:jw_wang]

Comment 831

•

9 years ago

I wonder if the duration problem with vp9.webm happens on B2G only or also on other platforms.

Comment hidden (Legacy TBPL/Treeherder Robot)

Benjamin Chen [:bechen]

Assignee

Comment 833

•

9 years ago

The root cause is that the |isKeyFrame| is not consistent between |NesteggPacketHolder| and |vpx_codec_peek_stream_info|. ex1: without new webm https://dxr.mozilla.org/mozilla-central/source/dom/media/webm/SoftwareWebMVideoDecoder.cpp?case=true&from=SoftwareWebMVideoDecoder.cpp&offset=0#151 The |is_kf| is not equal to |holder->IsKeyframe()|, holder->IsKeyframe() always return true. ex2: use new webm https://dxr.mozilla.org/mozilla-central/source/dom/media/webm/WebMDemuxer.cpp#524 The |is_kf| is not equal to |holder->IsKeyframe()| at the first frame. Because here https://dxr.mozilla.org/mozilla-central/source/dom/media/webm/WebMDemuxer.cpp#612 Hi jya: Any idea about the this? Looks like the WebMReader::DemuxPacket() and WebMDemuxer::DemuxPacket() both have keyframe issue here. Solution for this bug: increase the testcase execution time.

Flags: needinfo?(jyavenard)

Jean-Yves Avenard [:jya]

Comment 834

•

9 years ago

(In reply to Benjamin Chen [:bechen] from comment #833) > The root cause is that the |isKeyFrame| is not consistent between > |NesteggPacketHolder| and |vpx_codec_peek_stream_info|. > > ex1: without new webm > https://dxr.mozilla.org/mozilla-central/source/dom/media/webm/ > SoftwareWebMVideoDecoder.cpp?case=true&from=SoftwareWebMVideoDecoder. > cpp&offset=0#151 > The |is_kf| is not equal to |holder->IsKeyframe()|, holder->IsKeyframe() > always return true. > > ex2: use new webm > https://dxr.mozilla.org/mozilla-central/source/dom/media/webm/WebMDemuxer. > cpp#524 > The |is_kf| is not equal to |holder->IsKeyframe()| at the first frame. > Because here > https://dxr.mozilla.org/mozilla-central/source/dom/media/webm/WebMDemuxer. > cpp#612 > > Hi jya: > Any idea about the this? Looks like the WebMReader::DemuxPacket() and > WebMDemuxer::DemuxPacket() > both have keyframe issue here. That value set in the NesteggPacketHolder constructor isn't used in the WebMDemuxer. And neither is NesteggPacketHolder::IsKeyframe() it's only used by WebMReader which will construct the holders differently. In the WebMDemuxer, the NesteggPacketHolder is retrieved via NextPacket, which will initialize the value of mIsKeyFrame to false via the constructor ; only to be calculated just after in the same manner as done in WebMReader: switch (mVideoCodec) { case NESTEGG_CODEC_VP8: vpx_codec_peek_stream_info(vpx_codec_vp8_dx(), data, length, &si); break; case NESTEGG_CODEC_VP9: vpx_codec_peek_stream_info(vpx_codec_vp9_dx(), data, length, &si); break; } isKeyframe = si.is_kf; I don't think any differences here between the two. Code appears fine to me.

Flags: needinfo?(jyavenard)

Jan Gerber

Comment 835

•

9 years ago

Attached patch Bug-762774-media-test_loop-Increase-timeout-for-slow-platforms.patch (obsolete) (deleted) — Details — Splinter Review

(In reply to Benjamin Chen [:bechen] from comment #833) > Solution for this bug: increase the testcase execution time. currently it has a factor of 1.5, would 2 be enough or should we go higher?

Attachment #8650450 - Flags: review?(jyavenard)

Comment hidden (Legacy TBPL/Treeherder Robot)

Jean-Yves Avenard [:jya]

Comment 841

•

9 years ago

(In reply to Jan Gerber from comment #835) > Created attachment 8650450 [details] [diff] [review] > Bug-762774-media-test_loop-Increase-timeout-for-slow-platforms.patch > > (In reply to Benjamin Chen [:bechen] from comment #833) > > Solution for this bug: increase the testcase execution time. > > currently it has a factor of 1.5, would 2 be enough or should we go higher? default timeout is 300s .. surely it doesn't take that long to read a webm video !

Jean-Yves Avenard [:jya]

Comment 842

•

9 years ago

(In reply to Benjamin Chen [:bechen] from comment #833) > The root cause is that the |isKeyFrame| is not consistent between > |NesteggPacketHolder| and |vpx_codec_peek_stream_info|. > What makes you think that this is the "root cause"? the value returned by NesteggPacketHolder is only used by the old WebMReader. What makes you believe that the keyframe state is incorrectly calculated?

Flags: needinfo?(bechen)

Benjamin Chen [:bechen]

Assignee

Comment 843

•

9 years ago

(In reply to Jean-Yves Avenard [:jya] from comment #841) > (In reply to Jan Gerber from comment #835) > > Created attachment 8650450 [details] [diff] [review] > > Bug-762774-media-test_loop-Increase-timeout-for-slow-platforms.patch > > > > (In reply to Benjamin Chen [:bechen] from comment #833) > > > Solution for this bug: increase the testcase execution time. > > > > currently it has a factor of 1.5, would 2 be enough or should we go higher? > > default timeout is 300s .. surely it doesn't take that long to read a webm > video ! I suggest that we can also reduce the test from 3 times to 2. https://dxr.mozilla.org/mozilla-central/source/dom/media/test/test_loop.html?offset=0#41 Because from the failed log, I saw the machine spends 170~240s for test_play_events. So now the test_loop will spend about 3*(170~240) seconds.

Comment hidden (Legacy TBPL/Treeherder Robot)

Benjamin Chen [:bechen]

Assignee

Comment 845

•

9 years ago

(In reply to Jean-Yves Avenard [:jya] from comment #842) > (In reply to Benjamin Chen [:bechen] from comment #833) > > The root cause is that the |isKeyFrame| is not consistent between > > |NesteggPacketHolder| and |vpx_codec_peek_stream_info|. > > > > What makes you think that this is the "root cause"? > > the value returned by NesteggPacketHolder is only used by the old WebMReader. > > What makes you believe that the keyframe state is incorrectly calculated? Print log in WebMReader::DemuxPacket(), every frames of vp9.webm are keyFrame. Apparently it is not correct, so I print log in SoftwareWebMVideoDecoder::DecodeVideoFrame again and found that only the first frame is keyFrame, others are not keyFrame.

Flags: needinfo?(bechen)

Jean-Yves Avenard [:jya]

Comment 846

•

9 years ago

Right so thats a likely bug in WebMReader, but its not used anymore.

Jean-Yves Avenard [:jya]

Comment 847

•

9 years ago

That only the first frame is a keyframe is fairly normal. It will take a whilr before you see another keyframe. And the flag is only used in seeking

Comment hidden (Legacy TBPL/Treeherder Robot)

Benjamin Chen [:bechen]

Assignee

Comment 878

•

9 years ago

Attached patch bug-762774-fix-v01.patch (deleted) — Details — Splinter Review

See comment 843, increase the timeout and also reduce the testcase repeat times.

Attachment #8652117 - Flags: review?(jwwang)

JW Wang [:jwwang] [:jw_wang]

Updated

•

9 years ago

Attachment #8652117 - Flags: review?(jwwang) → review+

Comment hidden (Legacy TBPL/Treeherder Robot)

Benjamin Chen [:bechen]

Assignee

Updated

•

9 years ago

Attachment #8650450 - Attachment is obsolete: true

Attachment #8650450 - Flags: review?(jyavenard)

Benjamin Chen [:bechen]

Assignee

Updated

•

9 years ago

Keywords: checkin-needed

Pulsebot

Comment 882

•

9 years ago

https://hg.mozilla.org/integration/mozilla-inbound/rev/06ce1f332adc

Keywords: checkin-needed

Comment hidden (Legacy TBPL/Treeherder Robot)

Ryan VanderMeulen [:RyanVM]

Comment 891

•

9 years ago

https://hg.mozilla.org/mozilla-central/rev/06ce1f332adc

Assignee: nobody → bechen

Status: NEW → RESOLVED

Closed: 9 years ago

status-firefox43: --- → fixed

Resolution: --- → FIXED

Target Milestone: --- → mozilla43

Comment hidden (Legacy TBPL/Treeherder Robot)

Ryan VanderMeulen [:RyanVM]

Updated

•

9 years ago

status-b2g-v2.2: --- → wontfix

status-b2g-master: --- → fixed

status-firefox41: --- → wontfix

status-firefox42: --- → affected

status-firefox-esr38: --- → wontfix

Ryan VanderMeulen [:RyanVM]

Comment 895

•

9 years ago

https://hg.mozilla.org/releases/mozilla-aurora/rev/b6af21a35119

status-firefox42: affected → fixed

Flags: in-testsuite+

Bug-762774-media-test_loop-Increase-timeout-for-slow-platforms.patch 9 years ago Jan Gerber (deleted), patch		Details \| Diff \| Splinter Review
bug-762774-fix-v01.patch 9 years ago Benjamin Chen [:bechen] (deleted), patch	jwwang : review+	Details \| Diff \| Splinter Review