This is a spinoff of bug 1050026. On my flame, I see: > 2563 >adb shell b2g-ps > APPLICATION SEC USER PID PPID VSIZE RSS WCHAN PC NAME > b2g 0 root 306 1 170820 84144 ffffffff 00000000 S /system/b2g/b2g > b2g 0 root 457 306 55680 5536 ffffffff 00000000 S /system/b2g/b2g > Built-in Keyboa 2 u0_a943 943 306 88824 33688 ffffffff 00000000 S /system/b2g/plugin-container > Homescreen 2 u0_a945 945 306 85348 38480 ffffffff 00000000 S /system/b2g/plugin-container pid 457 is the Nuwa process and should be showing up as (Nuwa)

I coludn't repro this on my Flame v2.1. gecko: bf91c751284b35831b2ed54b1a56909b9052a672 gaia: 353a0e233247a26e43302463368dfaca47cd7953 firmware: v123

(In reply to Ting-Yu Chou [:ting] from comment #1) > I coludn't repro this on my Flame v2.1. > > gecko: bf91c751284b35831b2ed54b1a56909b9052a672 > gaia: 353a0e233247a26e43302463368dfaca47cd7953 > firmware: v123 Interesting. I built using the exact same hashes, and the same base image, and the problem repros for me. I did a full-flash (./flash.sh) > shell@flame:/ $ b2g-ps > APPLICATION SEC USER PID PPID VSIZE RSS WCHAN PC NAME > b2g 0 root 311 1 169020 84012 ffffffff 00000000 S /system/b2g/b2g > b2g 0 root 462 311 55664 5516 ffffffff 00000000 S /system/b2g/b2g > Built-in Keyboa 2 u0_a956 956 311 88808 32932 ffffffff 00000000 S /system/b2g/plugin-container > Homescreen 2 u0_a958 958 311 85344 38460 ffffffff 00000000 S /system/b2g/plugin-container

I have those in .userconfig: export MOZ_PROFILING=1 export ENABLE_MARIONETTE=1 Did full flash as well, tried |adb reboot| 10 times but no luck.

This is my .userconfig: https://gist.github.com/dhylands/80885ac73cfefd279444 Probably the most significant differences: export B2G_DEBUG=1 export NOFTU=1 (although my money would be on B2G_DEBUG=1) I've just fired up a non-DEBUG build to see how it behaves.

With B2G_DEBUG=0 then I see the Nuwa process: > APPLICATION SEC USER PID PPID VSIZE RSS WCHAN PC NAME > b2g 0 root 304 1 161148 75764 ffffffff 00000000 S /system/b2g/b2g > (Nuwa) 0 root 351 304 53576 13912 ffffffff 00000000 S /system/b2g/b2g > Built-in Keyboa 2 u0_a901 901 351 69976 22120 ffffffff 00000000 S /system/b2g/b2g > (Preallocated a 2 u0_a983 983 351 59476 18800 ffffffff 00000000 S /system/b2g/b2g > Homescreen 2 u0_a987 987 304 75160 32804 ffffffff 00000000 S /system/b2g/plugin-container and with B2G_DEBUG=1, I don't (see comment 2)

I wonder if the real issue here is that we're starting up the Nuwa process and then not using it on debug builds.

Kyle is right, because of this: #ifndef DEBUG // Enable pre-launching content processes for improved startup time // (hiding latency). pref("dom.ipc.processPrelaunch.enabled", true); ... Nuwa is forked from B2GLoader RunProcesses(), but not used. Should this be resolved with wontfix?

Oops, I forgot to clear status changing.

I think that we should either detect the pref and not do the fork (this may not be possible given how early this occurs), or do the fork and the Nuwa process should exit once it gets far enough along that it can query the pref.

In that case, we won't be able to fork it later when dom.ipc.processPrelaunch.enabled set to true. I'll talk to Thinker about this, see if keeping Nuwa process is intended.

I think we should turn on Nuwa in debug builds, and not support changing the preference at runtime.

Just talked to Thinker, the preference was a workaround for launch time testing, he couldn't remember the details. I will check around, if it can be removed we can do what Kyle suggested in comment 11.

From blame, cjones added "#ifndef DEBUG" for easier debuggability, seems not related to launch time testing. Not sure whom to ask, tried asking in #fxos-perf on IRC.

(In reply to Ting-Yu Chou [:ting] from comment #13) > From blame, cjones added "#ifndef DEBUG" for easier debuggability, seems not > related to launch time testing. Not sure whom to ask, tried asking in > #fxos-perf on IRC. Yeah - originally, we only had the preallocated app, and trying to debug an app, especially the startup code, was much trickier when the preallocated app was being launched. So we decided not to launch the preallocated app at all when DEBUG was enabled.

If there is any perf test depends on the preference for startup time testing, as Kyle stated in the email I sent offline, it can be work around by set "dom.ipc.processPrelaunch.delayMs" larger, and then launch an app before the one test case is measuring, which preallocated process won't have a chance to be forked for the latter one. I am working on a patch, since do_GetService(NS_PREFSERVICE_CINTRACTID) in B2GLoader returns NULL, I will try the 2nd option of comment 9. For comment 11, is it using LockPref() to prevent changing at runtime (but it can be unlocked)? Also, following test cases set the preference value, any suggestions how should I update the them if the preference can't be changed at runtime? ./gecko/dom/ipc/tests/test_NuwaProcessCreation.html ./gecko/dom/ipc/tests/test_NuwaProcessDeadlock.html ./gecko/dom/browser-element/mochitest/priority/test_Preallocated.html

(In reply to Ting-Yu Chou [:ting] from comment #12) > Just talked to Thinker, the preference was a workaround for launch time > testing, he couldn't remember the details. Received confirmation from Hub and :davehunt the preference is not used. So I guess we need to deal with only the test cases in comment 15 for the changes in comment 11.

- Nuwa exits if the preference is false - Turn on Nuwa in debug builds Done in WIP. One thing to note is after Nuwa exits, it becomes a zombie process, but it goes away once b2g process is terminated (no zombine if ignore SIGCHLD). Is observing the preference in PreallocatedProcessManagerImpl::Init() still needed then? - Not support changing the preference at runtime I am still not sure how to make this, one idea is to declare the change only takes effect after restart. - Existed test cases I guess they are already failed after landing B2GLoader as they all expect Nuwa process to be created by setting the preference false and then true, no ideas how to fix them.

Added code to reap zombie Nuwa process.

Comment on attachment 8472177 [details] [diff] [review] wip Review of attachment 8472177 [details] [diff] [review]: ----------------------------------------------------------------- ::: b2g/app/B2GLoader.cpp @@ +220,5 @@ > + sa.sa_handler = SIG_IGN; > + sigemptyset(&sa.sa_mask); > + sa.sa_flags = 0; > + sigaction(SIGCHLD, &sa, nullptr); > + Is this necessary? Since the b2g process itself would set a handler for SIGCHLD, it should move the dead b2g loader processor out of the zombie state. Does it not work?

(In reply to Thinker Li [:sinker] from comment #19) > Is this necessary? Since the b2g process itself would set a handler for > SIGCHLD, it should move the dead b2g loader processor out of the zombie > state. Does it not work? No, I can see zombie Nuwa process. Could you point me out where the code is?

Keep an eye on bug 1048011 which terminating ProcLoaderChild may need update.

Simply kill() Nuwa if the preference is false seems more straightforward, not to depend on IPC.

(In reply to Ting-Yu Chou [:ting] from comment #20) > (In reply to Thinker Li [:sinker] from comment #19) > > Is this necessary? Since the b2g process itself would set a handler for > > SIGCHLD, it should move the dead b2g loader processor out of the zombie > > state. Does it not work? > > No, I can see zombie Nuwa process. Could you point me out where the code is? The code Thinker mentioned handling SIGCHLD is pr_SigchldHandler(), but it is installed for PR_CreateProcess().

(In reply to Ting-Yu Chou [:ting] from comment #10) > we won't be able to fork it later when dom.ipc.processPrelaunch.enabled set to true. I was wrong. It will fallback to original path to fork Nuwa. So currently test_NuwaProcessCreation.html and test_NuwaProcessDeadlock.html are still passed.

kill() instead.

(In reply to Kyle Huey [:khuey] (khuey@mozilla.com) from comment #11) > I think we should turn on Nuwa in debug builds, and not support changing the > preference at runtime. How about turning on Nuwa at build time? Since we have shipped Nuwa on several devices for months, it has been a default mechanism and basically works fine. We can keep the perf, but it only for preallocated process. If the perf is turned off, Nuwa doesn't fork automatically, and vice versa.

I second the idea of decoupling Nuwa from the preference so the device will behave the same w/wo Nuwa.

What if we handle the preference changing in a different bug?

ok, I'll file a bug for that.

see bug 1054233 for enabling Nuwa on debug build.

I didn't state clearly. I meant to handle how the preference is used, and how could it be changed at runtime in a different bug. Removing "#ifndef DEBUG" to enable Nuwa on debug builds has been included in WIP here.

Okay. I updated the bug.

Comment on attachment 8472918 [details] [diff] [review] patch Enable Nuwa on debug builds, and kill unused Nuwa process when it is disabled.

Comment on attachment 8472918 [details] [diff] [review] patch Review of attachment 8472918 [details] [diff] [review]: ----------------------------------------------------------------- r=me

This also fixes the leak of PProcLoaderParent.

Update commit message, carry r+ from comment 34.

Try looks good: https://tbpl.mozilla.org/?tree=Try&rev=9ac570eeacb8

khuey backed this out for apparently causing B2G debug mochitest perma-timeouts in most chunks. https://hg.mozilla.org/mozilla-central/rev/372ce1f36116

Kyle, do you know where can I find the failed test cases, since the try at comment 37 seems good? Or did I miss some tests?

If you look at the logs for the debug tests you'll see that we timed out on a bunch of tests. TBPL just isn't marking things orange ...

I see, will check that after entering office. (I thought only orange/red are failed...)

Yeah, me too :/ This is a bug in TBPL. I'll get it fixed.

Still struglling running mochitest on my Flame, note search "timed out after 450.0 seconds" on bugzilla found 24 bugs.

Filed bug 1062237 for can't running mochitest on device.

The test is finished since SimpleTest.finish() does not invoke TestRunner.testFinished() because its |parentRunner| is null. It is null because |window.parent == window| and |window.opener == null|. I will keep checking what is this about.

Correction: (In reply to Ting-Yu Chou [:ting] from comment #47) > The test is finished since SimpleTest.finish() does not invoke ^^ The test is not finished

Not sure why, but I can hardly repro the timed out on emulator...

(In reply to Ting-Yu Chou [:ting] from comment #47) > The test is finished since SimpleTest.finish() does not invoke > TestRunner.testFinished() because its |parentRunner| is null. It is null > because |window.parent == window| and |window.opener == null|. I will keep > checking what is this about. This is true when I run mochitest locally: ./mach mochitest-remote content/base/test/test_bug894874.html but not the case on TBPL.

Finally found where it is stocked, it's right in ShutdownXPCOM(): gfxPlatform::ShutdownLayersIPC(); I will try to figure out why.

Somehow sCompositorThreadHolder is leaked, and CompositorParent::ShutDown never end.

The ContentParent of Nuwa opens PCompositor and PImageBridge, it is the corresponding CrossProcessCompositorParent and ImageBridgeParent leaking sCompositorThreadHolder.

I've been building with this patch in my tree for a while but after updating my tree today it doesn't appear to work anymore :/

Got it, I'll take a look when I have time, I'm currently working on bug 1064800.

Yeah, that's definitely higher priority than this.

I tried with the latest trunk, the Nuwa process gets killed on opt/debug builds when I have "dom.ipc.processPrelaunch.enabled" false, though the patch needs rebase. I saw some crashes when launch app or swith to homescreen, is this what you saw? If not, could you please elaborate more on "doesn't apper to work anymore"?

Running xpcshell test crashes since ProcLoaderClientGeckoInit() is not called from XRE_XPCShellMain(), which ProcLoaderLoad() reutrns false and the MOZ_ASSERT does its work in debug build.

(In reply to Ting-Yu Chou [:ting] from comment #57) > I saw some crashes when launch app or swith to homescreen, is this what you > saw? The crash still happens without the patch here, filed bug 1076748.

(In reply to Ting-Yu Chou [:ting] from comment #58) > Running xpcshell test crashes since ProcLoaderClientGeckoInit() is not > called from XRE_XPCShellMain(), which ProcLoaderLoad() reutrns false and the > MOZ_ASSERT does its work in debug build. I am not sure whether xpcshell needs Nuwa process, am trying to figure out the stack creating it.

Just for bookkeeping: I couldn't find bug 1087464 on DEBUG builds because Nuwa is disabled here.

(In reply to Ting-Yu Chou [:ting] from comment #58) > Running xpcshell test crashes since ProcLoaderClientGeckoInit() is not > called from XRE_XPCShellMain(), which ProcLoaderLoad() reutrns false and the > MOZ_ASSERT does its work in debug build. Couldn't repro locally, XRE_XPCShellMain() is called on Try but not on my local build...

(In reply to Ting-Yu Chou [:ting] from comment #62) > (In reply to Ting-Yu Chou [:ting] from comment #58) > > Running xpcshell test crashes since ProcLoaderClientGeckoInit() is not > > called from XRE_XPCShellMain(), which ProcLoaderLoad() reutrns false and the > > MOZ_ASSERT does its work in debug build. > > Couldn't repro locally, XRE_XPCShellMain() is called on Try but not on my > local build... Can repro now, the test arguments I passed were incorrect.

Updated commit message, carry r+ from comment 34.

Avoid LaunchAppProcLoader() when proc loader is not initialized (xpcshell), otherwise the assertion will be failed on debug build. Try: https://treeherder.mozilla.org/ui/#/jobs?repo=try&revision=40f95a54a028

Comment on attachment 8514896 [details] [diff] [review] part2: disable preallocate if proc loader is not initialized Review of attachment 8514896 [details] [diff] [review]: ----------------------------------------------------------------- ::: dom/ipc/PreallocatedProcessManager.cpp @@ +134,5 @@ > os->AddObserver(this, NS_XPCOM_SHUTDOWN_OBSERVER_ID, > /* weakRef = */ false); > } > +#ifdef MOZ_B2G_LOADER > + if (!mozilla::ipc::ProcLoaderIsInitialized()) Brace single line ifs, please.

(In reply to Kyle Huey [:khuey] (khuey@mozilla.com) from comment #66) > Comment on attachment 8514896 [details] [diff] [review] > part2: disable preallocate if proc loader is not initialized > > Review of attachment 8514896 [details] [diff] [review]: > ----------------------------------------------------------------- > > ::: dom/ipc/PreallocatedProcessManager.cpp > @@ +134,5 @@ > > os->AddObserver(this, NS_XPCOM_SHUTDOWN_OBSERVER_ID, > > /* weakRef = */ false); > > } > > +#ifdef MOZ_B2G_LOADER > > + if (!mozilla::ipc::ProcLoaderIsInitialized()) > > Brace single line ifs, please. Fixed, will always do in future.

https://hg.mozilla.org/integration/mozilla-inbound/rev/773b27cd166b https://hg.mozilla.org/integration/mozilla-inbound/rev/bc3b048b416d

https://hg.mozilla.org/mozilla-central/rev/773b27cd166b https://hg.mozilla.org/mozilla-central/rev/bc3b048b416d

This dramatically regressed debug mochitest run time (M12 went from ~90min to hitting the 120min timeout frequently). The Try run shows similar regressions. I see a lot of assertion spew in the logs like this too: 02:05:40 INFO - [Parent 730] ###!!! ASSERTION: Wrong size for this Shmem!: 'Error', file ../../../gecko/ipc/glue/Shmem.cpp, line 459 Which I assume is related. Backed out. https://hg.mozilla.org/integration/mozilla-inbound/rev/2ab425b4c278

Merge of backout: https://hg.mozilla.org/mozilla-central/rev/2ab425b4c278

(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #70) > regressions. I see a lot of assertion spew in the logs like this too: > 02:05:40 INFO - [Parent 730] ###!!! ASSERTION: Wrong size for this > Shmem!: 'Error', file ../../../gecko/ipc/glue/Shmem.cpp, line 459 I also see a lot of: 04:29:10 INFO - [Child 796] WARNING: Failed to retarget HTML data delivery to the parser thread.: file ../../../gecko/parser/html/nsHtml5StreamParser.cpp, line 947

(In reply to Ting-Yu Chou [:ting] from comment #72) > (In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #70) > > regressions. I see a lot of assertion spew in the logs like this too: > > 02:05:40 INFO - [Parent 730] ###!!! ASSERTION: Wrong size for this > > Shmem!: 'Error', file ../../../gecko/ipc/glue/Shmem.cpp, line 459 > > I also see a lot of: > > 04:29:10 INFO - [Child 796] WARNING: Failed to retarget HTML data > delivery to the parser thread.: file > ../../../gecko/parser/html/nsHtml5StreamParser.cpp, line 947 That's normal. See bug 1055728.

Thanks for the information, Kyle.

(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #70) > regressions. I see a lot of assertion spew in the logs like this too: > 02:05:40 INFO - [Parent 730] ###!!! ASSERTION: Wrong size for this > Shmem!: 'Error', file ../../../gecko/ipc/glue/Shmem.cpp, line 459 I found the same message from recent try runs (M12), so this is not caused by the patches here: http://ftp.mozilla.org/pub/mozilla.org/b2g/try-builds/mvujovic@adobe.com-8a0096da6d01/try-emulator-debug/try_ubuntu64_vm-b2g-emulator-debug_test-mochitest-debug-12-bm117-tests1-linux64-build402.txt.gz http://ftp.mozilla.org/pub/mozilla.org/b2g/try-builds/bzbarsky@mozilla.com-ce20aaf0ed67/try-emulator-debug/try_ubuntu64_vm-b2g-emulator-debug_test-mochitest-debug-12-bm117-tests1-linux64-build401.txt.gz

(In reply to Ting-Yu Chou [:ting] from comment #75) > (In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #70) > > regressions. I see a lot of assertion spew in the logs like this too: > > 02:05:40 INFO - [Parent 730] ###!!! ASSERTION: Wrong size for this > > Shmem!: 'Error', file ../../../gecko/ipc/glue/Shmem.cpp, line 459 > > I found the same message from recent try runs (M12), so this is not caused > by the patches here: There's a bug 1065892 for the shmem above. BTW, I couldn't repro bug 1093040 either locally or on Try. I'll try to figure out why M12 takes longer with the patches.

The test case /tests/dom/media/test/test_mediarecorder_record_immediate_stop.html takes 51181ms with the patch [1], 20226ms without the patch [2]. Both does not contain the shmem warnning. I'll take a look at this. [1] https://tbpl.mozilla.org/php/getParsedLog.php?id=53471408&tree=Try&full=1 [2] https://tbpl.mozilla.org/php/getParsedLog.php?id=53721100&tree=Try&full=1

Later I will try the patch again, as bug 1142229 may fix the timeout.

M12 is timeout often currently and is ignored, see bug 1099195 and bug 1148843.

Even worse now, M12 is now always timed out because of following test cases: 2482 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_canvas_blocked.html | Test timed out. - expected PASS 2502 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_persistent_sessions.html | Test timed out. - expected PASS 2519 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_playback.html | Test timed out. - expected PASS 2574 INFO TEST-UNEXPECTED-FAIL | dom/media/test/test_eme_stream_capture_blocked.html | Test timed out. - expected PASS 2575 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | 4 test timeouts, giving up. - expected PASS 2576 INFO TEST-UNEXPECTED-FAIL | (SimpleTest/TestRunner.js) | Skipping 52 remaining tests. - expected PASS https://treeherder.mozilla.org/#/jobs?repo=try&revision=675fe3e2b2c4&exclusion_profile=false https://treeherder.mozilla.org/#/jobs?repo=try&revision=a98fd211f2d7&exclusion_profile=false

Bug 1155533 has been created to deal with the timed out EME cases, I asked JW for the patch and initiated another run: https://treeherder.mozilla.org/#/jobs?repo=try&revision=235c637b628f&exclusion_profile=false https://treeherder.mozilla.org/#/jobs?repo=try&revision=dcc87ea6ad9d&exclusion_profile=false I will check the log after they finish.

Tested tests/dom/media/test/test_mediarecorder_record_immediate_stop.html 5 times on Try with [1] and without [2] the patches, and it took: With Without ------- ------- 1. 62799ms* 33893ms 2. 25215ms 33654ms 3. 18876ms* 28859ms 4. 30534ms 26179ms 5. 25870ms 33712ms I compared the logs of 1st [3] and 3rd [4] run with the patch (the ones with the star), here're the periods which are most different: ReallyStartLoadinInternal ~ SimpleTest.js loading 8821ms / 4959ms manifest.js loading ~ manifest.js > requestFlakyTimeout 1934ms / 540ms manifest.js loaded ~ manifest.js > nextTest 5066ms / 1571ms ondataavailabe ~ onstop 2066ms / 644ms PreciseGCRunnable > GCForReason ~ Callback 16519ms / 3109ms PreciseGCRunnable > Callback ~ GCForReason 12005ms / 1350ms I haven't figured out what of Nuwa could cause it, but the duration of precise GC is quite vary. For the other periods, I wonder are there unnecessary GCs. [1] https://treeherder.mozilla.org/#/jobs?repo=try&revision=dcc87ea6ad9d&exclusion_profile=false [2] https://treeherder.mozilla.org/#/jobs?repo=try&revision=235c637b628f&exclusion_profile=false [3] http://ftp.mozilla.org/pub/mozilla.org/b2g/try-builds/tchou@mozilla.com-dcc87ea6ad9d/try-emulator-debug/try_ubuntu64_vm-b2g-emulator-debug_test-mochitest-debug-12-bm113-tests1-linux64-build88.txt.gz [4] http://ftp.mozilla.org/pub/mozilla.org/b2g/try-builds/tchou@mozilla.com-dcc87ea6ad9d/try-emulator-debug/try_ubuntu64_vm-b2g-emulator-debug_test-mochitest-debug-12-bm68-tests1-linux64-build286.txt.gz

Since M12 is always timed out now, I'd like to extend the 7200s timeout to check whether the patches here make the test chunk takes longer to finish, but I don't know where to configure it... Checking a specfic test case doesn't seem helpful as it does not take long consistently, I should concentrate on the whole chunk.

Due to bug 1151672, Mochitest process is now forked from B2G process instead of Nuwa.

Bug 1099195 is landed. Push to Try to see if the patches still makes M12 taking longer: With patch: https://treeherder.mozilla.org/#/jobs?repo=try&revision=7b585c376588&exclusion_profile=false Without patch: https://treeherder.mozilla.org/#/jobs?repo=try&revision=53a2c69d84c0&exclusion_profile=false

(In reply to Ting-Yu Chou [:ting] from comment #85) > Bug 1099195 is landed. Push to Try to see if the patches still makes M12 > taking longer: > > With patch: > > https://treeherder.mozilla.org/#/ > jobs?repo=try&revision=7b585c376588&exclusion_profile=false > Without patch: > > https://treeherder.mozilla.org/#/ > jobs?repo=try&revision=53a2c69d84c0&exclusion_profile=false I ran debug M12 10 times (count only complete ones), the numbers are in minutes: MIN MAX MED AVG STD Without patch 146 187 177 168.8 17.11919001 With patch 151 186 160 163.8 12.22747362 The issue of comment 70 is not observed, I'd like to reland the patches.

https://hg.mozilla.org/integration/b2g-inbound/rev/6f9f9778a54c https://hg.mozilla.org/integration/b2g-inbound/rev/d00eb233eb9a

https://hg.mozilla.org/mozilla-central/rev/6f9f9778a54c https://hg.mozilla.org/mozilla-central/rev/d00eb233eb9a

Thanks ting!