898910 - GStreamer backend sometimes times out running test_seek case 13 on owl.mp3

Status: RESOLVED DUPLICATE of bug 912854

(Core :: Audio/Video, defect)

Description

[Chris Pearce [:cpearce (Not reading bugmail)]]

The GStreamer backend sometimes times out running test_seek case 13

See this log:

https://tbpl.mozilla.org/php/getParsedLog.php?id=25432727&tree=Mozilla-Central

Ubuntu VM 12.04 x64 mozilla-central pgo test mochitest-1 on 2013-07-18 06:29:12 PDT for push f26e4c26ce4a

grep out the "TEST-SEEK" lines makes the failure clear:

06:50:58     INFO -  SEEK-TEST: Started owl.mp3 seek test 1
06:50:58     INFO -  SEEK-TEST: Finished gizmo.mp4 seek test 13
06:50:59     INFO -  SEEK-TEST: Started owl.mp3 seek test 2
06:51:01     INFO -  SEEK-TEST: Finished owl.mp3 seek test 1
06:51:01     INFO -  SEEK-TEST: Started owl.mp3 seek test 3
06:51:01     INFO -  SEEK-TEST: Finished owl.mp3 seek test 2
06:51:01     INFO -  SEEK-TEST: Started owl.mp3 seek test 4
06:51:01     INFO -  SEEK-TEST: Finished owl.mp3 seek test 3
06:51:01     INFO -  SEEK-TEST: Started owl.mp3 seek test 5
06:51:01     INFO -  SEEK-TEST: Finished owl.mp3 seek test 4
06:51:01     INFO -  SEEK-TEST: Started owl.mp3 seek test 6
06:51:01     INFO -  SEEK-TEST: Finished owl.mp3 seek test 6
06:51:02     INFO -  SEEK-TEST: Started owl.mp3 seek test 7
06:51:02     INFO -  SEEK-TEST: Finished owl.mp3 seek test 7
06:51:02     INFO -  SEEK-TEST: Started owl.mp3 seek test 8
06:51:02     INFO -  SEEK-TEST: Finished owl.mp3 seek test 8
06:51:02     INFO -  SEEK-TEST: Started owl.mp3 seek test 9
06:51:02     INFO -  SEEK-TEST: Finished owl.mp3 seek test 9
06:51:02     INFO -  SEEK-TEST: Started owl.mp3 seek test 10
06:51:02     INFO -  SEEK-TEST: Finished owl.mp3 seek test 10
06:51:02     INFO -  SEEK-TEST: Started owl.mp3 seek test 11
06:51:02     INFO -  SEEK-TEST: Finished owl.mp3 seek test 11
06:51:02     INFO -  SEEK-TEST: Started owl.mp3 seek test 12
06:51:03     INFO -  SEEK-TEST: Finished owl.mp3 seek test 12
06:51:03     INFO -  SEEK-TEST: Started owl.mp3 seek test 13
06:51:03     INFO -  SEEK-TEST: Finished owl.mp3 seek test 5


We started owl.mp3 seek test 13, but don't finish it.

I also saw an assertion failure when looping on test_seek on Linux when running on owl.mp3, which may be related:

NS_ASSERTION(!audio || (audio->mTime <= seekTime &&
                        seekTime <= audio->mTime + audio->mDuration),
              "Seek target should lie inside the first audio block after seek");
MediaDecoderStateMachine.cpp:2023.

Comment 1

[Chris Pearce [:cpearce (Not reading bugmail)]]

I also see seeking failing on Linux for gizmo.mp4 in test_bug465498.html

For example this log:
https://tbpl.mozilla.org/php/getParsedLog.php?id=25227353&tree=Mozilla-Inbound

10:41:52     INFO -  143308 INFO TEST-PASS | /tests/content/media/test/test_bug465498.html | [started gizmo.mp4-7] Length of array should match number of running tests
10:41:52     INFO -  143309 INFO TEST-PASS | /tests/content/media/test/test_bug465498.html | Checking currentTime at end: 4 for seek.webm
10:41:52     INFO -  143310 INFO TEST-PASS | /tests/content/media/test/test_bug465498.html | Checking playback has ended for seek.webm
10:41:52     INFO -  143311 INFO TEST-PASS | /tests/content/media/test/test_bug465498.html | Checking ended is no longer true for seek.webm
10:41:52     INFO -  143312 INFO TEST-PASS | /tests/content/media/test/test_bug465498.html | Checking currentTime after seek: 0 for seek.webm
10:41:52     INFO -  143313 INFO TEST-PASS | /tests/content/media/test/test_bug465498.html | Checking ended is false for seek.webm
10:41:52     INFO -  143314 INFO TEST-PASS | /tests/content/media/test/test_bug465498.html | [finished seek.webm-5] Length of array should match number of running tests
10:41:55     INFO -  143315 INFO TEST-PASS | /tests/content/media/test/test_bug465498.html | Checking currentTime at end: 5.568 for gizmo.mp4
10:41:55     INFO -  143316 INFO TEST-PASS | /tests/content/media/test/test_bug465498.html | Checking playback has ended for gizmo.mp4
10:41:55     INFO -  143317 INFO TEST-PASS | /tests/content/media/test/test_bug465498.html | Checking ended is no longer true for gizmo.mp4
10:46:57     INFO -  143318 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_bug465498.html | Test timed out.

So here we can see that we run the "ended" event handler, which seeks, but the "seeked" event handler never runs, and so the test times out.

Comment 2

[Chris Pearce [:cpearce (Not reading bugmail)]]

Attachment: Stack trace when hang occurs on test_bug465498

I looped on test_bug465498, since that also seems to be a very common failure on Linux. I changed gSmallTests to contain 2 instaces of gizmo.mp4, with a ?1 ?2 after the filename to enure they don't share cache. I observed a timeout, and that's in this attached file.

I also saw the same I/O failure I reported in bug 898252, I'm not sure if it's coincidence, or causative here:
System JS : ERROR /home/cpearce/src/mozilla/orange/objdir/_tests/testing/mochitest/httpd.js:2854
                     NS_ERROR_UNEXPECTED: Component returned failure code: 0x8000ffff (NS_ERROR_UNEXPECTED) [nsIBinaryOutputStream.writeByteArray]


From the stacks above, it looks like DecodeToTarget() is timing out waiting for more audio samples after seeking.

Comment 3

[Edwin Flores [inactive from 2016-12-01] [:eflores] [:edwin]]

Should have been fixed with bug 912854.