Intermittent test_seek.html | Test timed out.

RESOLVED WONTFIX

Status

()

defect
RESOLVED WONTFIX
5 years ago
10 months ago

People

(Reporter: KWierso, Assigned: jwwang)

Tracking

({intermittent-failure})

Trunk
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox31 disabled, firefox32 disabled, firefox33 disabled, firefox-esr24 unaffected, b2g-v2.0 disabled, b2g-v2.1 disabled)

Details

(Whiteboard: [test disabled])

Attachments

(2 attachments)

https://tbpl.mozilla.org/php/getParsedLog.php?id=35814069&tree=Mozilla-Inbound
slave: tst-linux32-spot-147



14:12:23     INFO -  4021 INFO TEST-PASS | /tests/content/media/test/test_seek.html | [finished seek.ogv-27] Length of array should match number of running tests
14:12:23     INFO -  4022 INFO TEST-PASS | /tests/content/media/test/test_seek.html | [started seek.ogv-29] Length of array should match number of running tests
14:12:23     INFO -  4023 INFO TEST-PASS | /tests/content/media/test/test_seek.html | seek.ogv seek test 3: Video currentTime should be around 1.983: 1.983
14:12:23     INFO -  4024 INFO TEST-PASS | /tests/content/media/test/test_seek.html | seek.ogv seek test 4: Video currentTime should be around 1.983: 1.983
14:12:23     INFO -  4025 INFO TEST-PASS | /tests/content/media/test/test_seek.html | seek.ogv seek test 3: Video currentTime should be around 1.983: 1.983
14:12:23     INFO -  4026 INFO TEST-PASS | /tests/content/media/test/test_seek.html | seek.ogv seek test 3: Should have got timeupdate between seeking and seekended
14:12:23     INFO -  4027 INFO TEST-PASS | /tests/content/media/test/test_seek.html | [finished seek.ogv-28] Length of array should match number of running tests
14:12:23     INFO -  4028 INFO TEST-PASS | /tests/content/media/test/test_seek.html | seek.ogv seek test 4: Video currentTime should be around 0.9915: 0.9915
14:12:23     INFO -  4029 INFO TEST-PASS | /tests/content/media/test/test_seek.html | [started seek.ogv-30] Length of array should match number of running tests
14:12:23     INFO -  4030 INFO TEST-PASS | /tests/content/media/test/test_seek.html | seek.ogv seek test 4: seek on target: 0.9915
14:12:23     INFO -  4031 INFO TEST-PASS | /tests/content/media/test/test_seek.html | [finished seek.ogv-29] Length of array should match number of running tests
14:12:23     INFO -  4032 INFO TEST-PASS | /tests/content/media/test/test_seek.html | [started seek.ogv-31] Length of array should match number of running tests
14:12:23     INFO -  4033 INFO TEST-PASS | /tests/content/media/test/test_seek.html | seek.ogv seek test 5: Video currentTime should be around 1.983: 1.983
14:12:23     INFO -  4034 INFO TEST-PASS | /tests/content/media/test/test_seek.html | seek.ogv seek test 6: Seek 1
14:12:23     INFO -  4035 INFO TEST-PASS | /tests/content/media/test/test_seek.html | seek.ogv seek test 6: Seek 2
14:12:24     INFO -  Xlib:  extension "RANDR" missing on display ":0".
14:12:24     INFO -  System JS : ERROR (null):0 - uncaught exception: 2147746065
14:12:24     INFO -  System JS : ERROR (null):0 - uncaught exception: 2147746065
14:12:25     INFO -  4036 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_seek.html | Test timed out.
14:12:25     INFO -  4037 INFO TEST-INFO | MEMORY STAT vsize after test: 901169152
14:12:25     INFO -  4038 INFO TEST-INFO | MEMORY STAT residentFast after test: 294998016
14:12:25     INFO -  4039 INFO TEST-END | /tests/content/media/test/test_seek.html | finished in 320055ms
14:12:25     INFO -  [Parent 2384] WARNING: Failed to unlock the wakelock.: '!rv.Failed()', file /builds/slave/m-in-lx-d-00000000000000000000/build/content/html/content/src/HTMLVideoElement.cpp, line 301
14:12:25     INFO -  ++DOMWINDOW == 18 (0xee05708) [pid = 2384] [serial = 4796] [outer = 0x99aa2e8]
14:12:25     INFO -  4040 INFO TEST-KNOWN-FAIL | /tests/content/media/test/test_seek.html | Assertion count 1 within expected range 0-5 assertions.
14:12:25     INFO -  4041 INFO TEST-START | /tests/content/media/test/test_seek2.html
Is it different from Bug 857424?
Flags: needinfo?(kwierso)
(In reply to JW Wang[:jwwang] from comment #26)
> Is it different from Bug 857424?

Unsure. It looks slightly different compared with 857424's comment 0 and all of the logs in that bug are expired/deleted.
Flags: needinfo?(kwierso)
(In reply to TBPL Robot from comment #61)
> KWierso
> https://tbpl.mozilla.org/php/getParsedLog.php?id=36840373&tree=Fx-Team
> Ubuntu VM 12.04 x64 fx-team pgo test mochitest-1 on 2014-03-27 16:53:24
> revision: 0df0f2fe3bbf
> slave: tst-linux64-spot-281
> 
> 5036 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_seek.html |
> Test timed out.


The log contains:

17:21:44     INFO -  5031 INFO TEST-PASS | /tests/content/media/test/test_seek.html | [started gizmo.mp4-116] Length of array should match number of running tests
17:21:44     INFO -  5032 INFO TEST-PASS | /tests/content/media/test/test_seek.html | gizmo.mp4 seek test 12: seeking should default to false
17:21:44     INFO -  5033 INFO TEST-PASS | /tests/content/media/test/test_seek.html | gizmo.mp4 seek test 12: currentTime must report seek target immediately
17:21:44     INFO -  5034 INFO TEST-PASS | /tests/content/media/test/test_seek.html | gizmo.mp4 seek test 12: seeking flag on start should be true
17:21:44     INFO -  5035 INFO TEST-PASS | /tests/content/media/test/test_seek.html | gizmo.mp4 seek test 12: seeking: currentTime must be seekTime
17:21:44     INFO -  Xlib:  extension "RANDR" missing on display ":0".
17:21:45     INFO -  TEST-INFO | screentopng: exit 0
17:21:45     INFO -  5036 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_seek.html | Test timed out.
17:21:45     INFO -  5037 INFO TEST-INFO | MEMORY STAT vsize after test: 1580392448
17:21:45     INFO -  5038 INFO TEST-INFO | MEMORY STAT residentFast after test: 325599232
17:21:45     INFO -  5039 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 179029896
17:21:45     INFO -  5040 INFO TEST-END | /tests/content/media/test/test_seek.html | finished in 310609ms
17:21:45     INFO -  5041 INFO TEST-START | /tests/content/media/test/test_seek2.html
17:21:45     INFO -  5042 INFO TEST-INFO | MEMORY STAT vsize after test: 1588961280
17:21:45     INFO -  5043 INFO TEST-INFO | MEMORY STAT residentFast after test: 326017024
17:21:45     INFO -  5044 INFO TEST-INFO | MEMORY STAT heapAllocated after test: 179224864
17:21:45     INFO -  5045 INFO TEST-END | /tests/content/media/test/test_seek2.html | finished in 81ms
17:21:45     INFO -  5046 INFO TEST-START | /tests/content/media/test/test_seekLies.html
17:21:45     INFO -  5047 INFO TEST-INFO | MEMORY STAT vsize after test: 1590009856

Specifically:

17:21:44     INFO -  5035 INFO TEST-PASS | /tests/content/media/test/test_seek.html | gizmo.mp4 seek test 12: seeking: currentTime must be seekTime
17:21:44     INFO -  Xlib:  extension "RANDR" missing on display ":0".
17:21:45     INFO -  TEST-INFO | screentopng: exit 0
17:21:45     INFO -  5036 INFO TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_seek.html | Test timed out.

That is saying that the test is producing output at 17:21:44, but times out 1 second later at 17:21:45. Is this test just to long running? What if we split the 13 cases in test_seek up into 13 separate tests?

Jwwang: What do you think?
Flags: needinfo?(jwwang)
17:16:34     INFO -  4933 INFO TEST-START | /tests/content/media/test/test_seek.html <-- test starts!

It could be the test has a really long running time and causes timeout. However, the timestamp printed by SimpleTest.info is not always reliable.

Btw, I think there might be a bug in the seeking code of MediaDecoderStateMachine. I found timeouts in test_bug465498, test_loop, and test_seek which all involves seeking.

I think it will really help to split the test to narrow down the scope to find out the bug.
Flags: needinfo?(jwwang)
This is a try push which increases the timeout for this test by 2x, and the timeouts still happen.  This is probably not due to the length of this test's runtime.

https://tbpl.mozilla.org/?tree=Try&rev=a6717375e338