1244118 - slow-shutdown, process cleanup takes a long period in task manager

Status: RESOLVED FIXED

(Core :: Graphics, defect)

Description

[Alice0775 White]

Build Identifier:
https://hg.mozilla.org/mozilla-central/rev/0ecd7d72f232304da046b352c457e039e35ceed7
Mozilla/5.0 (Windows NT 6.1; WOW64; rv:47.0) Gecko/20100101 Firefox/47.0 ID:20160128030208

When I close browser after normal browsing, process cleanup takes a long period in task manager.

Reproducible: sometimes

Steps To Reproduce:
at least the following STR cause the problem in 50% probability.

1. Start Aurora with new profile and close Aurora.
2. Start Nightly with the profile. When "Default Browser" dialog pops up, choose [Not now].
3. Restore Previous Session from history menu.
4. Open url[1] in new tab (i.e., paste the url[1] in locationbar and then press Alt+Enter.
   [1] https://addons.mozilla.org/en-US/firefox/?utm_source=snippet&utm_medium=snippet&utm_campaign=addons
5. Close Nightly.
6. Repeat from step 1, if any.

Actual Results:
Process cleanup takes a long period in task manager.
In this case, about:telemetry "Simple Measurements" shows 'shutdownDuration 28233'.
Usually shutdownDuration is ～1000.

Expected Results:
It should be few seconds

Comment 1

[Alice0775 White]

Another Steps To Reproduce:
The following STR also cause the problem in almost 100% probability.

1. Start Nightly with new profile and close Nightly.
2. Start Nightly with the profile. When "Default Browser" dialog pops up, choose [Not now].
3. Open url[1] in new tab (i.e., paste the url[1] in locationbar and then press Alt+Enter.
   [1] https://addons.mozilla.org/en-US/firefox/?utm_source=snippet&utm_medium=snippet&utm_campaign=addons
4. Close Nightly.
5. Repeat from step 1, if any.

Comment 2

[Alice0775 White]

[Tracking Requested - why for this release]: shutdown hang


Regression window (using STR in Comment 1):
https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=d244738428700a2f8d85b17161c42a0444af6ca0&tochange=c347dd2df979ab54dd05370c6a1f548f0c2b4aeb

Suspect: Bug 1172796 , Bug 1215438 , Bug 1215005


And I confirmed that Aurora46.0a2 is also affected.

Comment 3

[Alice0775 White]

Attachment: about:support

Comment 4

[Olli Pettay [:smaug][[e-mail]]]

Morris, could you investigate this.

So far I haven't managed to reproduce on Linux. The only case I've see a bit longer shutdown was when the newly created profile ended up trying to look for a new update I think.

Comment 5

[Morris Tseng [:mtseng] [:Morris] (Inactive)]

(In reply to Olli Pettay [:smaug] from comment #4)
> Morris, could you investigate this.
> 
> So far I haven't managed to reproduce on Linux. The only case I've see a bit
> longer shutdown was when the newly created profile ended up trying to look
> for a new update I think.
Sure.

Comment 6

[Alice0775 White]

(In reply to Olli Pettay [:smaug] from comment #4)
> Morris, could you investigate this.
> 
> So far I haven't managed to reproduce on Linux. The only case I've see a bit
> longer shutdown was when the newly created profile ended up trying to look
> for a new update I think.

Even if I disable auto update, the long hang occurs.

Comment 7

[Morris Tseng [:mtseng] [:Morris] (Inactive)]

I can reproduce with STR described on comment 1 on my local build. Keep investigating it.

Comment 8

[Morris Tseng [:mtseng] [:Morris] (Inactive)]

The root cause is:

[1] set idle thread timeout to 30 seconds. So when ShutdownXPCOM() shuts all threads in [2], it will wait this idle thread timeout. I think we should call ThreadPool::Shutdown() before [2].

[1]: https://dxr.mozilla.org/mozilla-central/source/dom/base/ImageEncoder.cpp?from=ImageEncoder.cpp#511
[2]: https://dxr.mozilla.org/mozilla-central/source/xpcom/build/XPCOMInit.cpp#879

Comment 9

[Morris Tseng [:mtseng] [:Morris] (Inactive)]

Attachment: Shutdown threadpool when xpcom-shutdown-threads happened.

Comment 10

[jcpereira]

In my case this happened to me at work after +-8 hours open almost every day(i´m using 30/12/2015 nightly build -32bits noE10).

Sometimes i had to kill the process.

After testing for a while, closing nightly using the menu command, this situation doesn´t happen.

Comment 12

[Jim Mathies [:jimm]]

There's some debug log output over in bug 1234531 that might be useful.

Comment 13

[Jim Mathies [:jimm]]

(In reply to Morris Tseng [:mtseng] from comment #9)
> Created attachment 8714670 [details] [diff] [review]
> Shutdown threadpool when xpcom-shutdown-threads happened.

I can confirm this patch fixes the problem.

Comment 14

[Nathan Froyd [:froydnj]]

Comment on attachment 8714670 [details] [diff] [review]
Shutdown threadpool when xpcom-shutdown-threads happened.

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

::: dom/base/ImageEncoder.cpp
@@ +522,5 @@
> +    nsCOMPtr<nsIObserverService> os = mozilla::services::GetObserverService();
> +    NS_ASSERTION(os, "do_GetService failed");
> +    os->AddObserver(new EncoderThreadPoolTerminator(),
> +                    "xpcom-shutdown-threads",
> +                    false);

You need to make sure you're doing this all on the main thread; getting the observer service and manipulating it is not safe to do on a non-main thread.

Comment 15

[Jim Mathies [:jimm]]

Attachment: example dialog

this is the dialog you get when you try to open the browser. Selecting "Close Firefox" doesn't seem to do anything.

Comment 16

[Morris Tseng [:mtseng] [:Morris] (Inactive)]

Attachment: Shutdown threadpool when xpcom-shutdown-threads happened v2.

Addressed froydnj's comment.

Comment 17

[Morris Tseng [:mtseng] [:Morris] (Inactive)]

https://treeherder.mozilla.org/#/jobs?repo=try&revision=48633d375d9f&selectedJob=16726002

Try is good.

Comment 18

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/de3cd971372c

Comment 19

[Morris Tseng [:mtseng] [:Morris] (Inactive)]

Comment on attachment 8719362 [details] [diff] [review]
Shutdown threadpool when xpcom-shutdown-threads happened v2.

Approval Request Comment
[Feature/regressing bug #]: 1172796
[User impact if declined]: Firefox may freeze 30 seconds when shutdown.
[Describe test coverage new/current, TreeHerder]: Tested locally.
[Risks and why]: Low risk, only call ThreadPool::Shutdown during shutdown process.
[String/UUID change made/needed]: n/a

Comment 20

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/de3cd971372c

Comment 22

[Liz Henry (:lizzard) (relman/hg->git project)]

Tracking since this is a recent regression.

Comment 23

[Liz Henry (:lizzard) (relman/hg->git project)]

Comment on attachment 8719362 [details] [diff] [review]
Shutdown threadpool when xpcom-shutdown-threads happened v2.

Fix for recent shutdown hang regression. 
Please uplift to aurora.

Comment 24

[Morris Tseng [:mtseng] [:Morris] (Inactive)]

Please land the patch to aurora. Thanks.

Comment 25

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/6beee365d4f2

Comment 26

[Brian Mastenbrook]

This significantly improves the very long shutdown times I've been seeing for a while. Even with this patch, shutdown under OS X still takes 2-5s longer than before the changeset containing Bug 1172796, Bug 1215438, and Bug 1215005. Is this expected? Should I file a separate issue for this?