Closed Bug 707777 Opened 13 years ago Closed 11 years ago

Intermittent test_bug493187.html | Test timed out

Categories

(Core :: Audio/Video, defect)

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

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla35
Tracking Flags:
Tracking Status
firefox32 --- wontfix
firefox33 --- wontfix
firefox34 --- fixed
firefox35 --- fixed
firefox-esr31 --- wontfix
b2g-v1.4 --- wontfix
b2g-v2.0 --- wontfix
b2g-v2.1 --- fixed
b2g-v2.2 --- fixed

People

(Reporter: philor, Assigned: jwwang)

References

Details

(Keywords: intermittent-failure)

Attachments

(3 files, 1 obsolete file)

screenshot
596.88 KB, image/png
Details
media logging of timeout
619.05 KB, text/plain
Details
707777_fix_test_bug493187_html-v2.patch
4.34 KB, patch
roc
: review+
Details | Diff | Splinter Review
Attached image screenshot —
https://tbpl.mozilla.org/php/getParsedLog.php?id=7737262&tree=Mozilla-Inbound Rev3 Fedora 12 mozilla-inbound debug test mochitests-1/5 on 2011-12-04 05:15:37 PST for push 3d2eac7dcf66 73391 INFO TEST-PASS | /tests/content/media/test/test_bug493187.html | [finished split.webm-6] Length of array should match number of running tests - 1 should equal 1 --DOMWINDOW == 628 (0xd6c8648) [serial = 2558] [outer = (nil)] [url = http://mochi.test:8888/tests/content/media/test/test_bug465498.html] 73392 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_bug493187.html | Test timed out. XScreenSaver state: Disabled User input has been idle for 7258 seconds args: ['/home/cltbld/talos-slave/test/build/bin/screentopng'] ... 73393 INFO TEST-END | /tests/content/media/test/test_bug493187.html | finished in 300980ms
Attached file media logging of timeout —
Caught this locally with media logging on. No threads were active. From the logs it looks like seek.webm-4 started but didn't dispatch a canplaythrough event so didn't finish.
Whiteboard: [orange]
This is basically failing exclusively on the Win8 slaves these days, and with pretty high frequency. The spike is very recently (within the last day or two). Chris, can you help out possibly?
Flags: needinfo?(chris.double)
Chris Pearce might have an idea - maybe related to the Windows media changes?
Flags: needinfo?(chris.double) → needinfo?(cpearce)
The landing of bug 786539 may have caused this.
Flags: needinfo?(cpearce)
(In reply to Chris Pearce (:cpearce) from comment #19) > Created attachment 587234 [details] > media logging of timeout > > Caught this locally with media logging on. No threads were active. From the > logs it looks like seek.webm-4 started but didn't dispatch a canplaythrough > event so didn't finish. (In reply to Ryan VanderMeulen [:RyanVM] from comment #386) > This is basically failing exclusively on the Win8 slaves these days, and > with pretty high frequency. The spike is very recently (within the last day > or two). Chris, can you help out possibly? (In reply to Chris Pearce (:cpearce) from comment #392) > The landing of bug 786539 may have caused this. Roc, would you be able to take a look at this? :-)
Flags: needinfo?(roc)
I am not endowed with Windows 8, but Chris P is.
Assignee: nobody → cpearce
Flags: needinfo?(roc)
Appears to run OK now after a lot of Try runs. Re-enabled.
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → WORKSFORME
I think this is still there... Hit this on try (improbable to be caused by the patch) exactly as in comment 767. https://tbpl.mozilla.org/php/getParsedLog.php?id=41358168&tree=Try
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
(In reply to TBPL Robot from comment #851) 22:25:08 INFO - 1680 INFO [320x240.ogv] start 22:25:08 INFO - 1681 INFO [320x240.ogv] canPlayThrough 22:25:08 INFO - 1682 INFO [320x240.ogv] seeking 22:25:08 INFO - 1683 INFO [320x240.ogv] seeked When canPlayThrough event comes before seeked event, |v._seeked| will false [1] and manager.finished() won't be called and result in timeout. canPlayThrough event is just an estimation. When we receive the event, it doesn't necessarily mean all the data is already buffered. Furthermore, it could never come if download speed is poor. After reading bug 493187, I think we can re-write the test as follows: 1. play the media file 2. wait for some moments for enough data buffered 3. seek within the buffered range 4. check readyState >= HAVE_FUTURE_DATA [1] http://hg.mozilla.org/mozilla-central/file/acbdce59da2f/content/media/test/test_bug493187.html#l37
Flags: needinfo?(roc)
Sounds fine
Flags: needinfo?(roc)
Hi Chris, I will take this bug from you and rewrite the test as described in comment 852.
Assignee: cpearce → jwwang
OS: Linux → All
Hardware: x86 → All
Attached patch 707777_fix_test_bug493187_html-v1.patch (obsolete) — — Splinter Review
Rewrite the test as described in comment 852.
Attachment #8487054 - Flags: review?(roc)
Comment on attachment 8487054 [details] [diff] [review] 707777_fix_test_bug493187_html-v1.patch Cancel the review for it has one failure on b2g emulator. https://tbpl.mozilla.org/?tree=Try&rev=a1375bf8865e
Attachment #8487054 - Flags: review?(roc)
There are several problems found in the test (https://tbpl.mozilla.org/?tree=Try&rev=a1375bf8865e). 1. When "oncanplay" is received, there is no guarantee readyState will be at least HAVE_FUTURE_DATA. Since "oncanplay" is dispatched asynchronously, readyState can change before the event is received. Should we enforce readyState >= HAVE_FUTURE_DATA when "oncanplay" is received? I can't find such a statement on the spec. though. 2. Even if we change the criteria to pass the test when "oncanplay" is received, there is no guarantee we can pass the tests reliably on B2G emulator. Since readyState is calculated based on the amount of decoded data, on a slow decoding platform like B2G emulator, it is possible that decoded data is never enough to reach HAVE_FUTURE_DATA for the entire duration of the playback even though all data is already buffered. 3. Following (2), it is possible to enter buffering state when decoding is slow even though all data is already buffered. This is kinda weird. I can set PARALLEL_TESTS to 1 in order not to thrash the poor CPU on B2G emulator which should increase the pass rate on B2G emulator. Or should we just disable the test on B2G emulator?
Flags: needinfo?(roc)
(In reply to JW Wang [:jwwang] from comment #866) > 1. When "oncanplay" is received, there is no guarantee readyState will be at > least HAVE_FUTURE_DATA. Since "oncanplay" is dispatched asynchronously, > readyState can change before the event is received. Should we enforce > readyState >= HAVE_FUTURE_DATA when "oncanplay" is received? I can't find > such a statement on the spec. though. We can't do that. The spec effectively prevents it. When we were writing the spec, I argued that it should work the way you expect, but I lost the argument. > 2. Even if we change the criteria to pass the test when "oncanplay" is > received, there is no guarantee we can pass the tests reliably on B2G > emulator. Since readyState is calculated based on the amount of decoded > data, on a slow decoding platform like B2G emulator, it is possible that > decoded data is never enough to reach HAVE_FUTURE_DATA for the entire > duration of the playback even though all data is already buffered. OK. > 3. Following (2), it is possible to enter buffering state when decoding is > slow even though all data is already buffered. This is kinda weird. Maybe we can fix this. > I can set PARALLEL_TESTS to 1 in order not to thrash the poor CPU on B2G > emulator which should increase the pass rate on B2G emulator. Or should we > just disable the test on B2G emulator? I'd rather disable the test on B2G.
Flags: needinfo?(roc)
The test seems to run well on B2G emulator after setting PARALLEL_TESTS to 1. https://tbpl.mozilla.org/?tree=Try&rev=7a883a65dad9 No failures within 50 runs on opt and debug respectively. I also request faster VM (see Bug 994920) for media tests on B2G so that this test can pass reliably.
Attachment #8487054 - Attachment is obsolete: true
Attachment #8487753 - Flags: review?(roc)
Keywords: checkin-needed
https://hg.mozilla.org/integration/mozilla-inbound/rev/64383668cf94
Flags: in-testsuite+
Keywords: checkin-needed
Whiteboard: [test disabled][leave open]
https://hg.mozilla.org/mozilla-central/rev/64383668cf94
Status: REOPENED → RESOLVED
Closed: 11 years ago → 11 years ago
Resolution: --- → FIXED
Target Milestone: --- → mozilla35
(In reply to TBPL Robot from comment #880) > edmorley > https://tbpl.mozilla.org/php/getParsedLog.php?id=48660075&tree=Fx-Team > Ubuntu VM 12.04 fx-team debug test mochitest-1 on 2014-09-23 00:24:43 > revision: 1e0d3035de88 > slave: tst-linux32-spot-758 I notice something wrong which is not about this bug though... 01:03:27 INFO - 1739 INFO [split.webm] buffered start=-1999998 end=-1999996.199 01:03:27 INFO - 1740 INFO [split.webm] seeking to -1999997.0995 01:03:27 INFO - 1741 INFO [split.webm] seeked currentTime=0 readyState=4 The buffered range seems wrong. Hi Jean, Do you have any idea about it? Could it be related to recent changes in webm?
Flags: needinfo?(jyavenard)
Flags: needinfo?(karlt)
Flags: needinfo?(jyavenard) → needinfo?(kinetik)
Looks like the same thing I'm investigating in bug 1072483.
Flags: needinfo?(kinetik)
See Also: → 1072483
Flags: needinfo?(karlt)
(In reply to JW Wang [:jwwang] from comment #882) > 01:03:27 INFO - 1739 INFO [split.webm] buffered start=-1999998 > end=-1999996.199 Should be fixed by the landing of bug 1072483 and bug 739094.
(In reply to Matthew Gregan [:kinetik] from comment #884) > (In reply to JW Wang [:jwwang] from comment #882) > > 01:03:27 INFO - 1739 INFO [split.webm] buffered start=-1999998 > > end=-1999996.199 > > Should be fixed by the landing of bug 1072483 and bug 739094. Do we have a test case for that? Or we can modify test_playback.html [1] to check buffered range in the timeupdate handler. [1] http://hg.mozilla.org/mozilla-central/file/5e704397529b/content/media/test/test_playback.html#l66
(In reply to JW Wang [:jwwang] from comment #885) > Do we have a test case for that? Or we can modify test_playback.html [1] to > check buffered range in the timeupdate handler. Not yet. I'm working on a gtest to give the WebM buffered parser some coverage now. We've traditionally had fairly poor @buffered coverage (see bug 600724) because it's hard to test with mochitests. We could certainly add simple tests to catch insane values like the ones you pointed out here. Also, now we can use MSE to control exactly what data is available to the media code, we can add precise @buffered tests pretty easily.
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: