1142229 - Debug emulator shutdown timeout caused by dom/ipc/test_NuwaProcessCreation.html and dom/ipc/test_NuwaProcessDeadlock.html

Status: RESOLVED FIXED

(Core :: IPC, defect)

Description

[Andrew Halberstadt [:ahal]]

All debug emulator mochitest-11 jobs have a shutdown timeout in them (e.g search for TEST-UNEXPECTED-FAIL in [1]). These are green because of a special hack in mozharness just for this issue.

RyanVM and I recently figured out test_NuwaProcessCreation.html and test_NuwaProcessDeadlock.html are somehow causing it. Interestingly, disabling either of those tests fixes the issue. It's only when both are run together that the timeout occurs:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=0019c0ba19fd
https://treeherder.mozilla.org/#/jobs?repo=try&revision=698c547cf90d


[1] http://ftp.mozilla.org/pub/mozilla.org/b2g/try-builds/[e-mail]-e035ba199aec/try-emulator-debug/try_ubuntu64_vm-b2g-emulator-debug_test-mochitest-debug-11-bm122-tests1-linux64-build72.txt.gz

Comment 1

[Ryan VanderMeulen [:RyanVM]]

Just so it's clear here, we're very likely to be disabling these tests in short order as they're blocking other patches from landing and are causing a legitimate permafail at the moment.

Comment 2

[Cervantes Yu [:cyu] [:cervantes]]

Just to be sure, are we closing both test cases or just one to make it green? We need at least one test case as a guard for breakage of Nuwa functionality.

Comment 3

[Ryan VanderMeulen [:RyanVM]]

Ideally we'd disable neither :-). That said, happy to defer to your preference if it comes to that.

Comment 4

[Cervantes Yu [:cyu] [:cervantes]]

I can look into it, but the problem was only seen on the try server as I remember. Debugging is really painful as I could only printf and push to try to see the output. If there is debuggable environment for such cases, we can save lots of time on similar bugs. Do you have any suggestion?

Comment 5

[Ryan VanderMeulen [:RyanVM]]

Loaner slave?
https://wiki.mozilla.org/ReleaseEngineering/How_To/Request_a_slave

Comment 6

[Cervantes Yu [:cyu] [:cervantes]]

(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #5)
> Loaner slave?
> https://wiki.mozilla.org/ReleaseEngineering/How_To/Request_a_slave

That looks pretty delicious. I'll try that.

Comment 7

[Ryan VanderMeulen [:RyanVM]]

What do you think about disabling test_NuwaProcessDeadlock.html so we can fix this and bug 1132368 in one shot?

Comment 8

[Cervantes Yu [:cyu] [:cervantes]]

We still need the test case to guard against new stuff added to the Nuwa process that creates a deadlock as the original bug did. I agree that we disable the test case temporarily, rinse, and then reenable the test case.

Comment 9

[Cervantes Yu [:cyu] [:cervantes]]

This can be reproduced locally so no need for loaner slave.

Comment 10

[Cervantes Yu [:cyu] [:cervantes]]

Hooking the Nuwa test cases under ProcessPriorityManager turns out to be a bad idea. Setting process priorities is an indirect signal that can subject to timing problems easily. I think it's better to redesign the test cases that use more direct signals from where the Nuwa process are created/shutdown.

Comment 11

[Cervantes Yu [:cyu] [:cervantes]]

Attachment: Fix the test cases (WIP)

This should not block and timeout: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ce95abcb1760

The root cause of this timeout is:
1. We shut down the Nuwa process.
1.1 The run loop of the main thread exits.
1.2 The Nuwa process shuts down XPCOM
1.3 Some observer of xpcom-shutdown fires a Timer to the Timer thread, which is frozen.
1.4 The Nuwa process deadlocks.
2. The b2g process starts to shut down.
2.1 The compositor thread shuts down, which cannot complete because the compositor thread is ref-counted.
2.2 The b2g process deadlocks.

The patch contains rework of the test cases and adds logic to shut down the Nuwa process. Ideally we can thaw the threads to let them shut down correctly. But it's still not functioning. I use _exit() to force shutting down the process, but it leads to abort() crashes in the b2g process. I need to figure out how to fix it. At least, with this patch we should not see timeouts anymore.

Comment 12

[Cervantes Yu [:cyu] [:cervantes]]

Attachment: Part 1: refactor the test cases.

This cleans up the test case and remove the use of flaky timeouts. Also we use a dedicated pref value 'dom.ipc.preallocatedProcessManager.testMode' only for Nuwa test cases.

Comment 13

[Cervantes Yu [:cyu] [:cervantes]]

Attachment: Part 2: Shut down the Nuwa process with QuickExit()

Comment 14

[Cervantes Yu [:cyu] [:cervantes]]

Try push log: https://treeherder.mozilla.org/#/jobs?repo=try&revision=ddfdabe232b8

Comment 15

[Ryan VanderMeulen [:RyanVM]]

Comment on attachment 8586642 [details] [diff] [review]
Part 1: refactor the test cases.

I'm not a peer. Wish I could help here, but way out of my jurisdiction :)

Comment 16

[Cervantes Yu [:cyu] [:cervantes]]

Comment on attachment 8586642 [details] [diff] [review]
Part 1: refactor the test cases.

Request review from :mrbkap.

Blake, since Kyle is on vacation, would you review the test cases? Thanks.

Comment 17

[Blake Kaplan (:mrbkap) (inactive)]

Comment on attachment 8586642 [details] [diff] [review]
Part 1: refactor the test cases.

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

Clearing this request until my question about the second pushPrefEnv calls is resolved.

::: dom/ipc/tests/test_NuwaProcessCreation.html
@@ +39,5 @@
>      cpmm.removeMessageListener("TEST-ONLY:nuwa-add-new-process", msgHandler);
> +
> +
> +    SpecialPowers.pushPrefEnv({
> +      'clear': [

This shouldn't be necessary. The initial pushPrefEnv knows that it has to clear the prefs if they don't exist to begin with. This just creates an extra round-trip that doesn't do anything.

::: dom/ipc/tests/test_NuwaProcessDeadlock.html
@@ +39,5 @@
>      cpmm.removeMessageListener("TEST-ONLY:nuwa-add-new-process", msgHandler);
> +
> +
> +    SpecialPowers.pushPrefEnv({
> +      'clear': [

Same here.

Comment 18

[Cervantes Yu [:cyu] [:cervantes]]

Attachment: Part 1: refactor the test cases (v2),

Update to the previous revision: remove the unnecessary SpecialPowers.pushPrefEnv() call to clear the pref values on test case shutdown.

Comment 19

[Blake Kaplan (:mrbkap) (inactive)]

Comment on attachment 8589569 [details] [diff] [review]
Part 1: refactor the test cases (v2),

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

Looks good. Thanks!

Comment 20

[Cervantes Yu [:cyu] [:cervantes]]

https://hg.mozilla.org/integration/b2g-inbound/rev/a255a2f9d4f3
https://hg.mozilla.org/integration/b2g-inbound/rev/6b67bc79ec2d

Comment 21

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/a255a2f9d4f3
https://hg.mozilla.org/mozilla-central/rev/6b67bc79ec2d

Comment 22

[Ryan VanderMeulen [:RyanVM]]

Nice, I've confirmed that this actually fixes some permafails we recently began to encounter on the older release branches as well after the chunking boundaries changed. Please can we nominate these patches for b2g32/34/37 approval? I've already done the rebases and verified green on Try.

Comment 23

[Ryan VanderMeulen [:RyanVM]]

The alternative to approval being that I disable the Nuwa tests on the release branches, but that doesn't seem like an ideal outcome when we have a relatively small, simple patch that can fix them instead.

Comment 24

[Cervantes Yu [:cyu] [:cervantes]]

It's pretty safe change so we should uplift to release branches. Part 2 contains a change in IPC, but no one is ever going to Close() the Nuwa process except in test cases that changes the pref "dom.ipc.processPrelaunch.enabled" dynamically.

Comment 25

[Cervantes Yu [:cyu] [:cervantes]]

Comment on attachment 8586644 [details] [diff] [review]
Part 2: Shut down the Nuwa process with QuickExit()

NOTE: Please see https://wiki.mozilla.org/Release_Management/B2G_Landing to better understand the B2G approval process and landings.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 922465
User impact if declined: None. This is a test case fix.
Testing completed: Automatic tests on try and locally.
Risk to taking this patch (and alternatives if risky): Pretty low. This is a fix in test case. Also the change is only reachable in debug build, it's never seen in release build.

Comment 26

[Cervantes Yu [:cyu] [:cervantes]]

Comment on attachment 8589569 [details] [diff] [review]
Part 1: refactor the test cases (v2),

NOTE: Please see https://wiki.mozilla.org/Release_Management/B2G_Landing to better understand the B2G approval process and landings.

[Approval Request Comment]
Bug caused by (feature/regressing bug #): bug 922465
User impact if declined: None. This is a test case fix.
Testing completed: Automatic tests on try and locally.
Risk to taking this patch (and alternatives if risky): Pretty low. This is a fix in test case.

Comment 27

[bhavana bajaj [:bajaj]]

Comment on attachment 8589569 [details] [diff] [review]
Part 1: refactor the test cases (v2),

Spoke offline with Ryan and he gave me context and we feel its better to uplift this to help with permafails else we would have to end up disabling nuwa tests. Please note, these are deemed low risk as well, hence the a+

Comment 28

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/a3286b24ae86
https://hg.mozilla.org/releases/mozilla-b2g37_v2_2/rev/ba89756104b0

https://hg.mozilla.org/releases/mozilla-b2g34_v2_1/rev/d6a5a21e289f
https://hg.mozilla.org/releases/mozilla-b2g34_v2_1/rev/24860a5e6c84

https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/068cd1b55d7d
https://hg.mozilla.org/releases/mozilla-b2g32_v2_0/rev/29d943c277ab

https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/b8551dbe2a77
https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/3b992f316710

Comment 29

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g34_v2_1s/rev/d6a5a21e289f
https://hg.mozilla.org/releases/mozilla-b2g34_v2_1s/rev/24860a5e6c84

https://hg.mozilla.org/releases/mozilla-b2g32_v2_0m/rev/068cd1b55d7d
https://hg.mozilla.org/releases/mozilla-b2g32_v2_0m/rev/29d943c277ab

Comment 31

[Ting-Yu Chou [:ting] (away)]

There's one thing I noticed today. SpecialPower.exactGC() does two iterations of full GC and CC like this:

  #1 full GC
  #2 CC
  #3 full GC
  #4 CC

At #2, it's possible that NeedsGCAfterCC() returns true because sCCollectedWaitingForGC is larger than the threashold and nsJSContext::EndCycleCollectionCallback() then poke a delayed GC with reason CC_WAITING.

This delayed GC will always happen after #4, even there's a full GC #3 and the NeedsGCAfterCC() check at #4 returns false. I think this is redundant, GC really takes time in DEBUG build.

Kyle, I am not sure whom to ask, but since this is triggered from EndCycleCollectionCallback(), do you think it is reasonable to cancel the delayed GC timer if there's a full GC happened before it? Or do you know whom should I ask for this? Thank you.

Comment 32

[Ting-Yu Chou [:ting] (away)]

Ouch, I meant to leave comment 31 in bug 1099195. Wrong tab. Sorry about that.