Closed Bug 494420 Opened 15 years ago Closed 14 years ago

sporadic reftest timeout in ogg-video tests -- "timed out waiting for onload to fire" [e.g. aspect-ratio-1-ref.html, object-aspect-ratio-*, offset-1.xhtml, zoomed-1.xhtml]

Categories

(Core :: Audio/Video, defect)

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

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: dholbert, Unassigned)

References

(
URL
)

Details

(Keywords: intermittent-failure) 

REFTEST TEST-UNEXPECTED-FAIL | http://localhost:4444/89/ogg-video/object-aspect-ratio-2b.xhtml | timed out waiting for onload to fire

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1242998612.1243003408.17023.gz
OS X 10.5.2 mozilla-1.9.1 unit test on 2009/05/22 06:23:32

Appears to be a sporadic failure -- the two previous cycles were built from the same changeset, and neither of them had this failure.
Whiteboard: [orange]
mozilla-central had the same test-failure plus a few other similar ones this morning:

REFTEST TEST-UNEXPECTED-FAIL | http://localhost:4444/1242997920998/90/ogg-video/aspect-ratio-1-ref.html | timed out waiting for onload to fire
REFTEST TEST-UNEXPECTED-FAIL | http://localhost:4444/1242997920999/91/ogg-video/aspect-ratio-1-ref.html | timed out waiting for onload to fire
REFTEST TEST-UNEXPECTED-FAIL | http://localhost:4444/1242997921001/94/ogg-video/object-aspect-ratio-2b.xhtml | timed out waiting for onload to fire
REFTEST TEST-UNEXPECTED-FAIL | http://localhost:4444/1242997921002/95/ogg-video/zoomed-1.xhtml | timed out waiting for onload to fire

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1242996699.1243001825.10343.gz
OS X 10.5.2 mozilla-central unit test on 2009/05/22 05:51:39
OS: Linux → Mac OS X
Summary: ogg-video/object-aspect-ratio-2b.xhtml | timed out waiting for onload to fire → sporadic reftest failure in ogg-video tests -- "timed out waiting for onload to fire" [aspect-ratio-1-ref.html, object-aspect-ratio-2b.xhtml, zoomed-1.xhtml]
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1243016248.1243021173.21952.gz
OS X 10.5.2 mozilla-1.9.1 unit test on 2009/05/22 11:17:28
Timeouts in object-aspect-ratio-2a.xhtml and offset-1.xhtml
Summary: sporadic reftest failure in ogg-video tests -- "timed out waiting for onload to fire" [aspect-ratio-1-ref.html, object-aspect-ratio-2b.xhtml, zoomed-1.xhtml] → sporadic reftest failure in ogg-video tests -- "timed out waiting for onload to fire" [e.g. aspect-ratio-1-ref.html, object-aspect-ratio-2*, offset-1.xhtml, zoomed-1.xhtml]
This just happened on object-aspect-ratio-1b.xhtm and object-aspect-ratio-2a.xhtml
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1243021273.1243026327.1235.gz#err0
OS X 10.5.2 mozilla-1.9.1 unit test on 2009/05/22 12:41:13
Summary: sporadic reftest failure in ogg-video tests -- "timed out waiting for onload to fire" [e.g. aspect-ratio-1-ref.html, object-aspect-ratio-2*, offset-1.xhtml, zoomed-1.xhtml] → sporadic reftest failure in ogg-video tests -- "timed out waiting for onload to fire" [e.g. aspect-ratio-1-ref.html, object-aspect-ratio-*, offset-1.xhtml, zoomed-1.xhtml]
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox3.5/1243031731.1243036793.21752.gz
OS X 10.5.2 mozilla-1.9.1 unit test on 2009/05/22 15:35:31
REFTEST TEST-UNEXPECTED-FAIL | http://localhost:4444/1243189061085/92/ogg-video/offset-1.xhtml | timed out waiting for onload to fire
REFTEST TEST-UNEXPECTED-FAIL | http://localhost:4444/1243189061086/94/ogg-video/object-aspect-ratio-2b.xhtml | timed out waiting for onload to fire

http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1243187188.1243192976.7733.gz
OS X 10.5.2 mozilla-central unit test on 2009/05/24 10:46:28
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1243222356.1243231703.4915.gz
OS X 10.5.2 mozilla-central unit test on 2009/05/24 20:32:36
I can reproduce some failures like this by running the video reftests several hundred times. Here's an interesting bit of log:

2009-04-28 19:50:08.839549 UTC - -1608607968[70a6c0]: b9f8db0 ChangeDelayLoadStatus(1) doc=0x254f8a00
2009-04-28 19:50:08.897944 UTC - -1608607968[70a6c0]: b9f8db0 Queuing progress event loadstart
2009-04-28 19:50:08.898009 UTC - -1608607968[70a6c0]: b9f8db0 Trying load from src=black140x100.ogv
2009-04-28 19:50:08.898939 UTC - -1608607968[70a6c0]: b9f8db0 Dispatching progress event loadstart at time 1243540208898938
2009-04-28 19:50:08.910607 UTC - -1608607968[70a6c0]: b9f8db0 Created decoder f30d240 for type video/ogg
2009-04-28 19:50:08.910812 UTC - -1608607968[70a6c0]: b9f8db0 Queuing progress event progress
2009-04-28 19:50:08.914241 UTC - -1608607968[70a6c0]: b9f8db0 Dispatching progress event progress at time 1243540208914240
2009-04-28 19:50:08.916687 UTC - -1608607968[70a6c0]: b9f8db0 Ready state changed to HAVE_METADATA
2009-04-28 19:50:08.916704 UTC - -1608607968[70a6c0]: b9f8db0 Queuing simple event durationchange
2009-04-28 19:50:08.916714 UTC - -1608607968[70a6c0]: b9f8db0 Queuing simple event loadedmetadata
2009-04-28 19:50:08.916734 UTC - -1608607968[70a6c0]: b9f8db0 Ready state changed to HAVE_CURRENT_DATA
2009-04-28 19:50:08.916741 UTC - -1608607968[70a6c0]: b9f8db0 Queuing simple event loadeddata
2009-04-28 19:50:08.916751 UTC - -1608607968[70a6c0]: b9f8db0 ChangeDelayLoadStatus(0) doc=0x254f8a00
2009-04-28 19:50:08.916856 UTC - -1608607968[70a6c0]: b9f8db0 Queuing progress event progress
2009-04-28 19:50:08.916870 UTC - -1608607968[70a6c0]: b9f8db0 Ready state changed to HAVE_ENOUGH_DATA
2009-04-28 19:50:08.916877 UTC - -1608607968[70a6c0]: b9f8db0 Queuing simple event canplay
2009-04-28 19:50:08.916890 UTC - -1608607968[70a6c0]: b9f8db0 Queuing simple event canplaythrough
2009-04-28 19:50:08.916899 UTC - -1608607968[70a6c0]: b9f8db0 Queuing progress event load
2009-04-28 19:50:08.917214 UTC - -1608607968[70a6c0]: b9f8db0 Dispatching simple event durationchange at time 1243540208917213
2009-04-28 19:50:08.917649 UTC - -1608607968[70a6c0]: b9f8db0 Dispatching simple event loadedmetadata at time 1243540208917648
2009-04-28 19:50:08.917745 UTC - -1608607968[70a6c0]: b9f8db0 Dispatching simple event loadeddata at time 1243540208917745
2009-04-28 19:50:25.653601 UTC - -1608607968[70a6c0]: b9f8db0 Dispatching progress event progress at time 1243540225653599
2009-04-28 19:50:25.653967 UTC - -1608607968[70a6c0]: b9f8db0 Dispatching simple event canplay at time 1243540225653967
2009-04-28 19:50:25.654159 UTC - -1608607968[70a6c0]: b9f8db0 Dispatching simple event canplaythrough at time 1243540225654159
2009-04-28 19:50:25.654265 UTC - -1608607968[70a6c0]: b9f8db0 Dispatching progress event load at time 1243540225654264
REFTEST TEST-UNEXPECTED-FAIL | http://localhost:4444/1243513913634/172/ogg-video/basic-1.xhtml | timed out waiting for onload to fire@1243540225654000

The reftest timeout is set to 10 seconds, so it should have fired at around 19:50:18, so it looks like we were away from the main thread event loop for about 7 seconds. Whether the Firefox process was just not running, or we were actually doing something during that time, I can't tell.

Something similar here:

2009-04-28 21:13:07.184273 UTC - -1608607968[70a6c0]: f3b0500 Dispatching simple event durationchange at time 1243545187184272
2009-04-28 21:13:07.184627 UTC - -1608607968[70a6c0]: f3b0500 Dispatching simple event loadedmetadata at time 1243545187184627
2009-04-28 21:13:07.184719 UTC - -1608607968[70a6c0]: f3b0500 Dispatching simple event loadeddata at time 1243545187184718
2009-04-28 21:13:17.269709 UTC - -1608607968[70a6c0]: f3b0500 Dispatching progress event progress at time 1243545197269708
2009-04-28 21:13:17.270254 UTC - -1608607968[70a6c0]: f3b0500 Dispatching simple event canplay at time 1243545197270253
2009-04-28 21:13:17.270543 UTC - -1608607968[70a6c0]: f3b0500 Dispatching simple event canplaythrough at time 1243545197270542
2009-04-28 21:13:17.280967 UTC - -1608607968[70a6c0]: f3b0500 Dispatching progress event load at time 1243545197280965
REFTEST TEST-UNEXPECTED-FAIL | http://localhost:4444/1243513917497/5645/ogg-video/aspect-ratio-3a.xhtml | timed out waiting for onload to fire@1243545197281000
http://tinderbox.mozilla.org/showlog.cgi?log=Firefox/1244953275.1244959444.18069.gz
OS X 10.5.2 mozilla-central unit test on 2009/06/13 21:21:15
Comments 21 through 23 are *not* this bug -- this bug is about reftest timeouts, not reftest failures.

There's been no new reports here for 10 months, actually (up to comment 21) -- the original bug here is probably fixed.
Filed Bug 561385 on the new issue for comment 21-23.

Resolving this bug as WFM, since it was originally pretty frequent, and now there have been no reports since last June.
Status: NEW → RESOLVED
Closed: 14 years ago
Resolution: --- → WORKSFORME
Summary: sporadic reftest failure in ogg-video tests -- "timed out waiting for onload to fire" [e.g. aspect-ratio-1-ref.html, object-aspect-ratio-*, offset-1.xhtml, zoomed-1.xhtml] → sporadic reftest timeout in ogg-video tests -- "timed out waiting for onload to fire" [e.g. aspect-ratio-1-ref.html, object-aspect-ratio-*, offset-1.xhtml, zoomed-1.xhtml]
Whiteboard: [orange]
You need to log in before you can comment on or make changes to this bug.