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]
(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
Assignee: cajbir.bugzilla → nobody
Depends on: 1183955
(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)
(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)
Spiking badly on B2G lately.
Flags: needinfo?(jwwang)
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)
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)
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
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)
(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)
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
So both of them use software decoders on B2G. There is no reason for WebMDemuxer+MediaFormatReader to run slower than WebMReader... weird...
https://dxr.mozilla.org/mozilla-central/source/dom/media/DecoderTraits.cpp#744

On b2g-emulator, the webm playback is still MediaOmxReader.
(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...
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.
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)
(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
(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.
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.
I wonder if the duration problem with vp9.webm happens on B2G only or also on other platforms.
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)
(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)
(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)
(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 !
(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)
(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.
(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)
Right so thats a likely bug in WebMReader, but its not used anymore.
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
See comment 843, increase the timeout and also reduce the testcase repeat times.
Attachment #8652117 - Flags: review?(jwwang)
Attachment #8652117 - Flags: review?(jwwang) → review+
Attachment #8650450 - Attachment is obsolete: true
Attachment #8650450 - Flags: review?(jyavenard)
Keywords: checkin-needed
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
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: