Closed Bug 1198386 Opened 10 years ago Closed 10 years ago

Intermittent test_webaudioNotification.html | Test timed out, test_webaudioNotificationStopOnNavigation.html | Test timed out

Categories

(Core :: Web Audio, defect)

Product:
Core
Component:
Web Audio
Platform:
ARM
Android
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED FIXED
Milestone:
mozilla44
Tracking Flags:
Tracking Status
firefox43 --- affected
firefox44 --- fixed

People

(Reporter: RyanVM, Unassigned)

References

Details

(Keywords: intermittent-failure)

Attachments

(1 file)

Wait for the AudioContext to enter the running state before calling suspend() on it
1.18 KB, patch
karlt
: review+
Details | Diff | Splinter Review
No description provided.
Summary: Intermittent test_webaudioNotificationStopOnNavigation.html | Test timed out → Intermittent test_webaudioNotification.html | Test timed out, test_webaudioNotificationStopOnNavigation.html | Test timed out
karl, this very frequent, could you take a look? Thanks!
Flags: needinfo?(karlt)
Baku, has something changed recently ?
Flags: needinfo?(amarchesini)
This seems to be happening because of an uncaught NetworkError which is presumably coming from fetch(). Joel, can you please use your tool to see if you can narrow this down to a commit that caused it? Note that it happens quite frequently with Windows PGO builds... In the mean time I'll switch back to using XHR to stop the bleeding...
Flags: needinfo?(jmaher)
Hmm, so I tried using XHR, and it didn't fix the problem! <https://treeherder.mozilla.org/#/jobs?repo=try&revision=327d59562589> I also did another try push with logging statements everywhere in fetch that we return a network error, and we hit none of them! <https://treeherder.mozilla.org/#/jobs?repo=try&revision=d0982faabed8> I'm not sure if I can explain what's going on here...
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=b37c36475cd2 is a pgo build that doesn't seem to reproduce. The next push has the earliest incident (comment 454) after comment 1. The next pgo build reproduces frequently https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&revision=873abbd1dd23 That implies the trigger from bug 1189506: https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?changeset=052e47bcd8ac The pre-existence of bug 1196084 (and bug comment 2), with GetOrCreate() from NotifyStoppedPlaying() during AudioNode::cycleCollection::Unlink() might suggest that already notifications were at least sometimes not being sent on the suspend or close when pages were unloaded.
Blocks: 1189506
Flags: needinfo?(karlt) → needinfo?(roc)
NotifyStartedPlaying() can be triggered from the graph thread after which time a (potentially already pending) suspend may prevent triggering further notifications from that thread, but the main thread may have already sent NotifyStoppedPlaying() on the main thread when initiating the suspend. Am I missing something that prevents these getting out of order in this way?
Flags: needinfo?(ehsan)
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&fromchange=1dbf28047168&tochange=c83c2741197a&filter-searchStr=windows%20xp%20mochitest%20mochitest%20m%281%29 this indicates that bug 1204994 is the culprit. I see that that bug was landed and backed out, then landed again. While this isn't conclusive, the retriggers do point to a pattern.
Flags: needinfo?(jmaher)
I think comment 456 is on to something, but I am not sure if I still understand all of the details. Let's go through it.... (In reply to Karl Tomlinson (ni?:karlt) from comment #457) > NotifyStartedPlaying() can be triggered from the graph thread I assume you mean an InputMutedRunnable being kicked off from the graph thread, right? So far so good. > after which time > a (potentially already pending) suspend may prevent triggering further > notifications from that thread Hmm, how would that happen? AudioDestinationNode::Suspend() calls DestroyAudioChannelAgent(), but if after it has been called we receive an InputMutedRunnable, AudioDestinationNode::InputMuted() will call CreateAudioChannelAgent() if necessary, so we should be getting NotifyStartedPlaying() as expected in that case. > but the main thread may have already sent > NotifyStoppedPlaying() on the main thread when initiating the suspend. > > Am I missing something that prevents these getting out of order in this way? I am not sure if I understand the race yet. Let's look at what the test does. It loads file_webaudioLoop.html which starts an infinite loop of playback. At this time, in DestinationNodeEngine::ProcessBlock() we notice the first non-null block and dispatch InputMutedRunnable() which ends up running on the main thread and calls NotifyStartedPlayback(). This part works according to the logs. Then, the test calls Suspend() on the AudioContext object, and that apparently never calls NotifyStoppedPlayback() as the test times out waiting for that to happen. How would your theory explain this sequence?
Flags: needinfo?(ehsan) → needinfo?(karlt)
(In reply to Ehsan Akhgari (don't ask for review please) from comment #527) > (In reply to Karl Tomlinson (ni?:karlt) from comment #457) > > NotifyStartedPlaying() can be triggered from the graph thread > > I assume you mean an InputMutedRunnable being kicked off from the graph > thread, right? So far so good. That's what I mean, yes. > > after which time > > a (potentially already pending) suspend may prevent triggering further > > notifications from that thread > > Hmm, how would that happen? AudioDestinationNode::Suspend() calls > DestroyAudioChannelAgent(), but if after it has been called we receive an > InputMutedRunnable, AudioDestinationNode::InputMuted() will call > CreateAudioChannelAgent() if necessary, so we should be getting > NotifyStartedPlaying() as expected in that case. Yes, but once the stream is suspended, ProcessBlock() will not be called again and so there will be no more InputMutedRunnables dispatched to call NotifyStoppedPlaying(). The last notification is NotifyStartedPlayback, even though the stream is suspended. > Let's look at what the test does. It loads file_webaudioLoop.html which > starts an infinite loop of playback. At this time, in > DestinationNodeEngine::ProcessBlock() we notice the first non-null block and > dispatch InputMutedRunnable() which ends up running on the main thread and > calls NotifyStartedPlayback(). This part works according to the logs. > Then, the test calls Suspend() on the AudioContext object, and that > apparently never calls NotifyStoppedPlayback() as the test times out waiting > for that to happen. How would your theory explain this sequence? I think you are right that the possible race described above does not explain this failure.
Flags: needinfo?(karlt)
(In reply to Karl Tomlinson (ni?:karlt) from comment #533) > > > after which time > > > a (potentially already pending) suspend may prevent triggering further > > > notifications from that thread > > > > Hmm, how would that happen? AudioDestinationNode::Suspend() calls > > DestroyAudioChannelAgent(), but if after it has been called we receive an > > InputMutedRunnable, AudioDestinationNode::InputMuted() will call > > CreateAudioChannelAgent() if necessary, so we should be getting > > NotifyStartedPlaying() as expected in that case. > > Yes, but once the stream is suspended, ProcessBlock() will not be called > again > and so there will be no more InputMutedRunnables dispatched to call > NotifyStoppedPlaying(). The last notification is NotifyStartedPlayback, even > though the stream is suspended. Oh, I'm not sure how the stream can get suspended but that sounds wrong for sure. Do you mind filing a bug with some details on how the stream can get suspended? > > Let's look at what the test does. It loads file_webaudioLoop.html which > > starts an infinite loop of playback. At this time, in > > DestinationNodeEngine::ProcessBlock() we notice the first non-null block and > > dispatch InputMutedRunnable() which ends up running on the main thread and > > calls NotifyStartedPlayback(). This part works according to the logs. > > Then, the test calls Suspend() on the AudioContext object, and that > > apparently never calls NotifyStoppedPlayback() as the test times out waiting > > for that to happen. How would your theory explain this sequence? > > I think you are right that the possible race described above does not explain > this failure. :( I'm testing another logging patch that shows what happens under Suspend() and the NotifyStarted/StoppedPlaying calls on the try server...
Thanks for looking into this, Ehsan. (In reply to Ehsan Akhgari (don't ask for review please) from comment #547) > Do you mind filing a bug with some details on how the stream can get > suspended? I filed bug 1209408 on that.
OK, I found out what's happening. See this try push: <https://treeherder.mozilla.org/#/jobs?repo=try&revision=fb8ec7bcc7ff> If you look at the logs, you'll see that in the case where the test fails, we're bailing out here: <https://hg.mozilla.org/try/rev/c36fd31af3c7#l1.30> which means that the AudioContext is in the suspended state. As far as I can tell, this can happen in the following scenario: 1) The graph thread notices that the input is unmuted, so it dispatches an InputMutedRunnable runnable to the main thread. 2) The graph thread dispatches an StateChangeTask runnable to update the current state to Running. 3) The main thread receives the InputMutedRunnable runnable and runs NotifyStartedPlaying(). 4) The test receives the event, and does an executeSoon() to call suspend() on the AudioContext. 5) Steps 2 and 4 are racing, and if 4 wins the race, we end up calling suspend() before the main thread version of mAudioContextState has been updated, so we lose. We should probably wait for the statechange event in the test to fix this race condition. I will test a patch that does that on the try server.
Thanks again, Ehsan. Filed bug 1209598.
Depends on: 1209598
It seems like this is working! <https://treeherder.mozilla.org/#/jobs?repo=try&revision=3cf9e1f0848a> Submitting this for review while I'm waiting for more result in order to expedite landing.
Attachment #8667576 - Flags: review?(karlt)
The patch is fully green \o/
Comment on attachment 8667576 [details] [diff] [review] Wait for the AudioContext to enter the running state before calling suspend() on it I wonder whether use of resumePromise could now be replaced with runningPromise, but if suspendAC() is not called after resumeAC(), then it doesn't matter.
Attachment #8667576 - Flags: review?(karlt) → review+
Flags: needinfo?(roc)
Flags: needinfo?(amarchesini)
(In reply to Karl Tomlinson (ni?:karlt) from comment #609) > I wonder whether use of resumePromise could now be replaced with > runningPromise, but if suspendAC() is not called after resumeAC(), then it > doesn't matter. No, a promise won't resolve twice! :-)
(In reply to Ehsan Akhgari (don't ask for review please) from comment #610) > No, a promise won't resolve twice! :-) Yes, I mean the variable/reference which is updated to a new promise on each call. FWIW also merging runningPromise and suspendPromise would allow closeAC() to work in any state.
(In reply to Karl Tomlinson (ni?:karlt) from comment #613) > (In reply to Ehsan Akhgari (don't ask for review please) from comment #610) > > No, a promise won't resolve twice! :-) > > Yes, I mean the variable/reference which is updated to a new promise on each > call. > > FWIW also merging runningPromise and suspendPromise would allow closeAC() to > work in any state. Oh I see. Yeah I guess we can do that. Please file a follow-up. :-)
https://hg.mozilla.org/mozilla-central/rev/c6dfe20cbb8a
Status: NEW → RESOLVED
Closed: 10 years ago
status-firefox44: --- → fixed
Resolution: --- → FIXED
Target Milestone: --- → mozilla44
This needs to land on Aurora too.
Keywords: checkin-needed
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: