916135 - Investigate webaudio mochitest timeouts on B2G

Status: RESOLVED FIXED

(Core :: Web Audio, defect, P2)

Description

[Ed Morley [:emorley]]

The webaudio tests are currently extremely unreliable on B2G (see bug 820739 comment 787).

Disabling until the failures are resolved.

Comment 1

[Ed Morley [:emorley]]

remote:   https://hg.mozilla.org/integration/mozilla-inbound/rev/7e2551feeddd

Comment 2

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/7e2551feeddd

Comment 3

[Karl Tomlinson (:karlt)]

Bug 916773 may be at least part of the problem here.

Comment 4

[(no longer active)]

(In reply to comment #3)
> Bug 916773 may be at least part of the problem here.

Should we re-enable these tests now that bug 916773 is fixed?

Comment 5

[Ryan VanderMeulen [:RyanVM]]

How about enabling them on Try with 20+ retriggers and then we can decide.

Comment 6

[(no longer active)]

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

Comment 7

[(no longer active)]

Oh shoot, this is mochitest-3, not crashtest.  :(

Comment 8

[(no longer active)]

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

Comment 9

[Ryan VanderMeulen [:RyanVM]]

(In reply to :Ehsan Akhgari (needinfo? me!) from comment #8)
> https://tbpl.mozilla.org/?tree=Try&rev=b1a2dc56e30b

lulz

Comment 10

[(no longer active)]

Alright, I give up.  jwwang, any chance you could take a look at this please?

Comment 11

[JW Wang [:jwwang] [:jw_wang]]

Sure, I am on it.

Comment 12

[JW Wang [:jwwang] [:jw_wang]]

command timed out: 1200 seconds without output, attempting to kill
Bug 820739 - Intermittent B2G emulator "command timed out: 1200 seconds without output, attempting to kill" or "command timed out: 3600 seconds without output, attempting to kill" during run-marionette or b2g_emulator_unittest step
Bug 820811 - Intermittent Android "command timed out: 1200 seconds without output, attempting to kill" during "Install App on Device" step
Bug 873053 - Intermittent B2G xpcshell command timed out: 1200 seconds without output, attempting to kill from "AttributeError: 'NoneType' object has no attribute 'pid'"

Btw, what are the lines following the "command timed out: 1200" line in the light blue box?
I don't see them in the full log. Do they even matter?

Comment 13

[Ed Morley [:emorley]]

(In reply to jwwang from comment #12)
> Btw, what are the lines following the "command timed out: 1200" line in the
> light blue box?
> I don't see them in the full log. Do they even matter?

Anything that's a link (and indented) in the TBPL blue box is a bug suggestion by TBPL, to help match up known intermittent failures with failures in automation. They are just bugzilla search results based on scraping the log for failure lines.

Comment 14

[JW Wang [:jwwang] [:jw_wang]]

https://tbpl.mozilla.org/?tree=Try&rev=1932306fae09
20 successes in a row.

As content/media/test/* tests are disabled in my test, I wonder if there are some leftovers after running content/media/test which cause deadlock or something likewise in running content/media/webaudio/test.

Btw, test_audioBufferSourceNodeLazyLoopParam.html, test_audioBufferSourceNodeLoopStartEnd.html and test_audioBufferSourceNodeLoop.html are not found in my pushlog. Are they disabled elsewhere other than testing/mochitest/b2g.json?

Is it possible to change the order of tests? I would like to see how it plays out if we run content/media/webaudio/test first and then content/media/test.

Comment 15

[(no longer active)]

(In reply to comment #14)
> https://tbpl.mozilla.org/?tree=Try&rev=1932306fae09
> 20 successes in a row.
> 
> As content/media/test/* tests are disabled in my test, I wonder if there are
> some leftovers after running content/media/test which cause deadlock or
> something likewise in running content/media/webaudio/test.

That's possible.

> Btw, test_audioBufferSourceNodeLazyLoopParam.html,
> test_audioBufferSourceNodeLoopStartEnd.html and
> test_audioBufferSourceNodeLoop.html are not found in my pushlog. Are they
> disabled elsewhere other than testing/mochitest/b2g.json?
> 
> Is it possible to change the order of tests? I would like to see how it plays
> out if we run content/media/webaudio/test first and then content/media/test.

You can try moving directories around.  AFAIK we run the tests based on the alphabetical order of their names (sub-directories first.)

Comment 16

[JW Wang [:jwwang] [:jw_wang]]

https://tbpl.mozilla.org/?tree=Try&rev=5a93c866e2d2
21 runs, each with 5 duplicates of content/media/webaudio/test (webaudio/test2~6).

2 of them timed out in convolverNode (is this a known issuue?), but none of them exhibit the same symptom as the previous command timed out.

I really suspect the command timed out is resulted from content/media/test. I will try to duplicate content/media/test and see if it will show the same results.

Comment 17

[Karl Tomlinson (:karlt)]

Looks like test_convolverNodeChannelCount.html and subsequent tests are timing out waiting for the online AudioContext, which makes that a different issue from bug 921197, but perhaps related to bug 920338 (which is also unexplained).

Comment 18

[JW Wang [:jwwang] [:jw_wang]]

https://tbpl.mozilla.org/?tree=Try&rev=24ebdb331c6d
https://tbpl.mozilla.org/?tree=Try&rev=59dbdeddd772
where content/media/test/test_timeupdate_small_files.html and content/media/test/test_video_to_canvas.html are disabled.

https://tbpl.mozilla.org/?tree=Try&rev=71c827590484
https://tbpl.mozilla.org/?tree=Try&rev=67947612ee00
where content/media/test/test_timeupdate_small_files.html and content/media/test/test_video_to_canvas.html are enabled.

It looks like disabling the 2 files would help reduce the chance of command timeout right after test_preload_actions.html. However, test_preload_actions.html is run before the 2 files. I am confused about how files run later can affect the former one.

Btw, there is no timeout in webaudio test cases in my test. Once bug 919353 is landed, we will have stack trace to give a better clue.

Comment 19

[JW Wang [:jwwang] [:jw_wang]]

https://tbpl.mozilla.org/?tree=Try&rev=e3e36c223293
66 successes in a row except 2 timeouts caused by app crashed.

There are several root causes here:
1. Only 1 omx.h264 codec available concurrently. Request for the 2nd one has to wait indefinitely until the 1st one is released. You might have to wait for a long time until GC is triggered since this is not like memory low condition.
2. Media elements not receiving loadedmetadata event in some test cases. The reason is unknown.
3. Implementation of OMXCodec::pause is broken. Calling OMXCodec::start later will return error and can't leave the paused state.

Fixes:
1. Setting the src attribute to an empty string to force releasing the underlying codec.
2. Setting the preload attribute to "auto".
3. Don't call OMXCodec::pause in OmxDecoder::Pause. However, this will break the fix for Bug 860760 and Bug 872462.

Comment 20

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Fix timeout in acquiring omx codec and waiting for loadedmetadata event.

Comment 21

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Don't call OMXCodec::pause to avoid state error.

Comment 22

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Enable tests in B2G.

Comment 23

[JW Wang [:jwwang] [:jw_wang]]

TBPL results.
https://tbpl.mozilla.org/?tree=Try&rev=73d9daec231f

Comment 24

[Paul Adenot (:padenot)]

JW, karlt is away until 3rd of January, maybe you want to redirect those review requests.

Comment 25

[Paul Adenot (:padenot)]

Comment on attachment 8348555 [details] [diff] [review]
Fix timeout in acquiring omx codec and waiting for loadedmetadata event.

Review of attachment 8348555 [details] [diff] [review]:
-----------------------------------------------------------------

I'm not sure if removing event listener matters that much. Does that keep the element alive?

::: content/media/test/manifest.js
@@ +561,5 @@
>  }
>  
> +function removeNodeAndSource(n) {
> +  if (n.parentNode) {
> +    n.parentNode.removeChild(n);

n.remove()

@@ +563,5 @@
> +function removeNodeAndSource(n) {
> +  if (n.parentNode) {
> +    n.parentNode.removeChild(n);
> +  }
> +  // force release of underlying codec

I'd rather say "decoder" than codec, here.

@@ +567,5 @@
> +  // force release of underlying codec
> +  n.src = "";
> +  while (n.firstChild) {
> +    n.removeChild(n.firstChild);
> +  }

I'm not sure why this is necessary. Even if the node has <source> children, they won't load until someone calls load() on the media element.

Also, if you remove a node, its children will get collected anyway (assuming we don't have a reference to the children, which should be fine).

::: content/media/test/reactivate_helper.html
@@ +21,5 @@
>    var test = parent.gSmallTests[i];
>    var elemType = /^audio/.test(test.type) ? "audio" : "video";
>    // Associate these elements with the subframe's document
>    var e = document.createElement(elemType);
> +  e.setAttribute("preload", "auto");

e.preload = "auto";

I see you've used this pattern a lot in this patch, please fix all occurrences.

::: content/media/test/test_bug654550.html
@@ +17,5 @@
>  
>    /* Test for Bug 654550 */
>  
> +  // Parallel test must be disabled for media.video_stats.enabled is a global setting
> +  // to prevent the setting from chaning unexpectedly in the middle of the test.

s/chaning/changing/

Comment 26

[Paul Adenot (:padenot)]

Comment on attachment 8348559 [details] [diff] [review]
Don't call OMXCodec::pause to avoid state error.

Review of attachment 8348559 [details] [diff] [review]:
-----------------------------------------------------------------

I'm not really knowledgeable on this code, can you have a look, Chris?

::: content/media/omx/OmxDecoder.cpp
@@ +461,5 @@
>    }
>    return false;
>  }
>  
> +static bool isInEmulator()

s/isInEmulator/IsInEmulator/

Comment 27

[Paul Adenot (:padenot)]

Comment on attachment 8348562 [details] [diff] [review]
Enable tests in B2G.

Review of attachment 8348562 [details] [diff] [review]:
-----------------------------------------------------------------

Looking at the try push, r+.

Comment 28

[cajbir (:cajbir)]

Comment on attachment 8348559 [details] [diff] [review]
Don't call OMXCodec::pause to avoid state error.

Review of attachment 8348559 [details] [diff] [review]:
-----------------------------------------------------------------

r+ with Paul Adenot's change.

Comment 29

[JW Wang [:jwwang] [:jw_wang]]

Comment on attachment 8348555 [details] [diff] [review]
Fix timeout in acquiring omx codec and waiting for loadedmetadata event.

Review of attachment 8348555 [details] [diff] [review]:
-----------------------------------------------------------------

::: content/media/test/manifest.js
@@ +561,5 @@
>  }
>  
> +function removeNodeAndSource(n) {
> +  if (n.parentNode) {
> +    n.parentNode.removeChild(n);

https://developer.mozilla.org/en-US/docs/Web/API/Node
I can't find the method in the DOM API. Where is it documented?

@@ +567,5 @@
> +  // force release of underlying codec
> +  n.src = "";
> +  while (n.firstChild) {
> +    n.removeChild(n.firstChild);
> +  }

The idea is to force releasing underlying decoder. So we have to clean the "src" attribute and all <source> child nodes.

Since it is not the memory low case, we might wait indefinitely for garbage collection. Therefore, I try to empty the "src" attribute and all <source> child nodes to force releasing the decoder without waiting for garbage collection to kick in.

::: content/media/test/reactivate_helper.html
@@ +21,5 @@
>    var test = parent.gSmallTests[i];
>    var elemType = /^audio/.test(test.type) ? "audio" : "video";
>    // Associate these elements with the subframe's document
>    var e = document.createElement(elemType);
> +  e.setAttribute("preload", "auto");

Will do.

Comment 30

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Fix timeout in acquiring omx codec and waiting for loadedmetadata event.

Comment 31

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Paul Adenot (:padenot) from comment #25)
> Comment on attachment 8348555 [details] [diff] [review]
> Fix timeout in acquiring omx codec and waiting for loadedmetadata event.
> 
> Review of attachment 8348555 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> I'm not sure if removing event listener matters that much. Does that keep
> the element alive?

Changing the "src" attribute will trigger events. We have to remove event listeners to prevent unexpected events that cause tests to fail.

Comment 32

[u459114]

Assign to JW since he is currently working on this fix

Comment 33

[Paul Adenot (:padenot)]

(In reply to JW Wang[:jwwang] from comment #29)
> Comment on attachment 8348555 [details] [diff] [review]
> Fix timeout in acquiring omx codec and waiting for loadedmetadata event.
> 
> Review of attachment 8348555 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: content/media/test/manifest.js
> @@ +561,5 @@
> >  }
> >  
> > +function removeNodeAndSource(n) {
> > +  if (n.parentNode) {
> > +    n.parentNode.removeChild(n);
> 
> https://developer.mozilla.org/en-US/docs/Web/API/Node
> I can't find the method in the DOM API. Where is it documented?

http://dxr.mozilla.org/mozilla-central/source/dom/interfaces/core/nsIDOMElement.idl#81
http://dom.spec.whatwg.org/#dfnReturnLink-0

Comment 34

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Fix timeout in acquiring omx codec and waiting for loadedmetadata event.

Comment 35

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/b2g-inbound/rev/69bf31cfafa1
https://hg.mozilla.org/integration/b2g-inbound/rev/91749b627a04
https://hg.mozilla.org/integration/b2g-inbound/rev/7e3a322f9fd6

Comment 36

[Ryan VanderMeulen [:RyanVM]]

Backed out for Android mochitest orange.
https://hg.mozilla.org/integration/b2g-inbound/rev/bcba9e0700e8

https://tbpl.mozilla.org/php/getParsedLog.php?id=32639777&tree=B2g-Inbound

Comment 37

[Ryan VanderMeulen [:RyanVM]]

And B2G.
https://tbpl.mozilla.org/php/getParsedLog.php?id=32643410&tree=B2g-Inbound

Comment 38

[Ryan VanderMeulen [:RyanVM]]

And every other platform.

Comment 39

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #36)
> Backed out for Android mochitest orange.
> https://hg.mozilla.org/integration/b2g-inbound/rev/bcba9e0700e8
> 
> https://tbpl.mozilla.org/php/getParsedLog.php?id=32639777&tree=B2g-Inbound

The failure is not about timeout. Should I also disable the tests to keep green?

Comment 40

[Ryan VanderMeulen [:RyanVM]]

It would be better if you understood why the test started failing before blindly disabling it. After all, tests are there to catch regressions :)

Comment 41

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Enable tests in B2G.

Comment 42

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #40)
> It would be better if you understood why the test started failing before
> blindly disabling it. After all, tests are there to catch regressions :)

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

Disable test_invalid_reject.html and test_load_same_resource.html and file bugs for them. Since this patch enables more tests than what it disables, we can still benefit from catching more regressions. For the failed tests, I would like to deal with them in other bugs.

Comment 43

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 8357044 [details] [diff] [review]
Enable tests in B2G.

The test was failing across all platforms. This will only disable it on B2G.

Paul - Are you OK with disabling these tests on all platforms so the B2G tests can be re-enabled?

Comment 44

[Paul Adenot (:padenot)]

If JW promises to fix the two disabled tests, we can land this, yes.

Comment 45

[Paul Adenot (:padenot)]

Sorry, I apparently misread comment 43. This can't land as-is, as it break tests on all platforms, whereas it should only affect b2g, which shows that we are clearly missing something here.

Comment 47

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Fix timeout in acquiring omx codec and waiting for loadedmetadata event.

Fix test failures caused by event handlers (onerror) not removed before calling removeNodeAndSource().

Comment 48

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Enable tests in B2G.

Comment 49

[JW Wang [:jwwang] [:jw_wang]]

TBPL results:
https://tbpl.mozilla.org/?tree=Try&rev=4f6739947691

Comment 50

[Ed Morley [:emorley]]

There was an intermittent failure on one of the retriggers:
https://tbpl.mozilla.org/php/getParsedLog.php?id=33141611&tree=Try

{
891 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_progress.html | Test timed out.
913 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_reactivate.html | Test timed out.
1058 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_replay_metadata.html | Test timed out.
1159 ERROR TEST-UNEXPECTED-FAIL | /tests/content/media/test/test_seek_out_of_range.html | Test timed out.
1160 ERROR TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up.
}

Comment 51

[JW Wang [:jwwang] [:jw_wang]]

I noticed that too. It was suspicious the 4 failures were temporally close to each other. There might be some other root causes for the timeouts. Given the failure was one in the hundred, I would like to check in the patches first to enable webaudio tests again and then trace other media test timeouts in other bugs so that we can make progress.

Comment 52

[Paul Adenot (:padenot)]

Comment on attachment 8361571 [details] [diff] [review]
Fix timeout in acquiring omx codec and waiting for loadedmetadata event.

Review of attachment 8361571 [details] [diff] [review]:
-----------------------------------------------------------------

r+ if you investigate the error.

Comment 53

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/b2g-inbound/rev/4272e7b529de
https://hg.mozilla.org/integration/b2g-inbound/rev/3b168ee25f38
https://hg.mozilla.org/integration/b2g-inbound/rev/d5e526257ace

Comment 54

[Ryan VanderMeulen [:RyanVM]]

Backed out for B2G mochitest-2 failures.
https://hg.mozilla.org/integration/b2g-inbound/rev/1a95ee2442c8

https://tbpl.mozilla.org/php/getParsedLog.php?id=33344919&tree=B2g-Inbound

Comment 55

[JW Wang [:jwwang] [:jw_wang]]

https://tbpl.mozilla.org/?tree=Try&rev=4f6739947691
It looks like test_mediarecorder_creation_fail.html didn't show up in my push log (Neither in mochitest-2 or 3 on B2G ICS Emulator Opt). Did I miss something to include the test?

Comment 56

[Ryan VanderMeulen [:RyanVM]]

It landed in bug 926684 on 10-Jan, so maybe your parent rev was just too old to include it?

Comment 57

[JW Wang [:jwwang] [:jw_wang]]

(In reply to Ryan VanderMeulen [:RyanVM UTC-5] from comment #54)
> Backed out for B2G mochitest-2 failures.
> https://hg.mozilla.org/integration/b2g-inbound/rev/1a95ee2442c8
> 
> https://tbpl.mozilla.org/php/getParsedLog.php?id=33344919&tree=B2g-Inbound

The failure existed on b2g without my patch. It looks like SpecialPowers.setBoolPref is async and it fails to disable Ogg in time when recorder starts.

Since the whole content/media/test/* and content/media/webaudio/test/* are disabled on b2g, there are some new tests which fail on b2g on their own not caught.

I will rebase my patch, disable the test on b2g, and run tests on try again. I would like to check in this patch as soon as possible in case there are more test failures not caught on b2g. Or is it preferred to fix the failures before this patch can check in?

Comment 58

[Ryan VanderMeulen [:RyanVM]]

I see no problem with disabling individual failing tests (on B2G *only*) in order to get the rest re-enabled.

Comment 59

[JW Wang [:jwwang] [:jw_wang]]

Attachment: Enable tests in B2G.

Disable content/media/test/test_mediarecorder_creation_fail.html which fails on B2G on its own without these patches. I will file another bug to fix the failure.

Comment 60

[JW Wang [:jwwang] [:jw_wang]]

https://tbpl.mozilla.org/?tree=Try&rev=7782e7b3b910
all green except one orange which is not related to media/webaudio.
Parent rev. = 8f4ecbf938cd on 1/21.

Hi Ryan, can you try to land the patch again? Thanks.

Comment 61

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/integration/b2g-inbound/rev/e4a5cc40929c
https://hg.mozilla.org/integration/b2g-inbound/rev/21c8ab0245dc
https://hg.mozilla.org/integration/b2g-inbound/rev/65a5026da078

Comment 62

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/e4a5cc40929c
https://hg.mozilla.org/mozilla-central/rev/21c8ab0245dc
https://hg.mozilla.org/mozilla-central/rev/65a5026da078

*cues up the Hallelujah chorus* :)

Comment 66

[Jason Smith [:jsmith]]

FYI - I filed a bunch of followups that I noticed from this bug in these bugs:

* bug 962871 - get these tests running on debug emulators
* bug 962874 - get these tests running on b2g desktop builds
* bug 962878 - fix test_mediarecord_4ch_audiocontext.html
* bug 962883 - fix test_mediarecorder_creation_fail.html