Open Bug 1704637 Opened 4 years ago Updated 7 months ago

86.0b1+ have been taking a long time to shut down when exiting the program. nsMsgAccountManager::CleanupOnExit with server setting "empty trash on exit" enabled

Categories

(Thunderbird :: General, defect)

Product:
Thunderbird
Component:
General
Version:
Thunderbird 86
Platform:
x86_64
Windows 10
Type:
defect

Tracking

(Not tracked)

People

(Reporter: thee.chicago.wolf, Unassigned)

References

Details

(Keywords: perf)

I've noticed that in the past few betas---maybe since about 86?---when I File > Exit or click the close button {X] in the top right corner, it takes about 10+ seconds before TB actually exits and isn't shown as running in the Task Manager.

Any way I could help by running some kind of shutdown hang monitor/detector?

Anything in error console?

Flags: needinfo?(thee.chicago.wolf)

Just tried to see if there's anything in Error Console with 89.0b3 and not seeing anything that jumps out. Seems that between 89.0b1 (when I filed this bug) and 89.0b3 this hang behavior has decreased. I timed a shutdown and it now takes between 3-4 seconds as opposed to the 10 seconds or so it did before.

I tried a few times to close TB and immediately start it and a couple times I get the "Thunderbird is already running...." window which prompts to Close or Cancel. Only thing I saw in Error Console when I did this was:

NotFoundError: Could not open the file at C:\Users\<removed>\AppData\Local\Thunderbird\Profiles\23lp3mw9.default\startupCache\webext.sc.lz4 ExtensionParent.jsm:1758
_readData resource://gre/modules/ExtensionParent.jsm:1758
AsyncFunctionThrow self-hosted:699

So the only sort of STR I can state is:

  1. With TB closed (verify via Task Manager), launch it
  2. As soon as the TB window appears, close it via [X] immediately and quickly try to relaunch it again

This is the only way I can reliably repro (at home) the "Thunderbird is already running...." window that I would get when I closed it normally. I realize this is not the best method since no one would normally do this type of behavior but it's the best I got right now.

Flags: needinfo?(thee.chicago.wolf)

Are you still seeing this?

Flags: needinfo?(thee.chicago.wolf)
Keywords: perf

(In reply to Wayne Mery (:wsmwk) from comment #3)

Are you still seeing this?

Yes, but it's improved since the 86+ betas. I'm on 93.0b5 now. On my home PC it takes about 6-7 seconds to disappear from the Task Manager from the time I close TB. I feel like in the 60/70 TB days, it disappeared from Task Manager within a few seconds.

If I close TB and launch it immediately, Error Console shows:

mail.activity: Exception: [Exception... "Component is not available" nsresult: "0x80040111 (NS_ERROR_NOT_AVAILABLE)" location: "JS frame :: resource:///modules/ActivityManager.jsm :: getActivity :: line 135" data: no] ActivityManager.jsm:86:16
removeActivity resource:///modules/ActivityManager.jsm:86
onFolderRemovedFromQ resource:///modules/activity/autosync.jsm:247

NS_ERROR_NOT_AVAILABLE: ActivityManager.jsm:135
getActivity resource:///modules/ActivityManager.jsm:135
removeActivity resource:///modules/ActivityManager.jsm:84
onFolderRemovedFromQ resource:///modules/activity/autosync.jsm:247

And I can always tell TB didn't shut down properly yet because the little left-to-right-to-left animation beneath "File" and above "Get Messages" is going. After a proper shutdown and subsequent launch, that animation disappears after a few seconds.

Flags: needinfo?(thee.chicago.wolf)
Severity: -- → S4

Have you tested this with both WIndows and Thunderbird in safe mode?
Beyond that, it would be useful to determine the regression range using mozregression tool against nightly builds.

Flags: needinfo?(thee.chicago.wolf)

Does this still reproduce for you?

Flags: needinfo?(thee.chicago.wolf)
Summary: Last few betas (86+) have been taking a long time to shut down when exiting the program → 86.0b1+ have been taking a long time to shut down when exiting the program
See Also: → 1788599

(In reply to Wayne Mery (:wsmwk) from comment #7)

Does this still reproduce for you?

I do still see this on 110.0b4 taking around 30-60 seconds to fully shut down. When I briefly used 111.0b1, shutdown took maybe 1/2 a second or less.

For the brief moment that I was able to capture a 110.0b4 perf profile during shutdown, this is what I got: https://share.firefox.dev/3Jhx5Vc

Flags: needinfo?(thee.chicago.wolf)

(In reply to Wayne Mery (:wsmwk) from comment #9)

We have a winner - it's waiting on cleaning up trash folder https://searchfox.org/comm-central/rev/9fecf68e84150f35329821f5bfbf0af525d07999/mailnews/base/src/nsMsgAccountManager.cpp#1558

Did you glean this from the perf profile?

(In reply to Arthur K. (he/him) from comment #10)

(In reply to Wayne Mery (:wsmwk) from comment #9)

We have a winner - it's waiting on cleaning up trash folder https://searchfox.org/comm-central/rev/9fecf68e84150f35329821f5bfbf0af525d07999/mailnews/base/src/nsMsgAccountManager.cpp#1558

Did you glean this from the perf profile?

Essentially. hit * to expand all the frames, and go to nsMsgAccountManager::CleanupOnExit where it changes from 62% to 57%. The frames starting at 57% are waits.

Comments from a developer "It looks like we have some PR_Wait calls inside of that function [nsMsgAccountManager::CleanupOnExit ] that actually does nothing but to wait for 1000 microsecond in a while loop here. you can also see the same thing in the profiler source code view when you double click on the nsMsgAccountManager::CleanupOnExit frame on the call tree. looks like most of the time is spent in this line. apparently it's trying to empty the trash but it's taking longer than expected?"

(In reply to Wayne Mery (:wsmwk) from comment #11)

(In reply to Arthur K. (he/him) from comment #10)

(In reply to Wayne Mery (:wsmwk) from comment #9)

We have a winner - it's waiting on cleaning up trash folder https://searchfox.org/comm-central/rev/9fecf68e84150f35329821f5bfbf0af525d07999/mailnews/base/src/nsMsgAccountManager.cpp#1558

Did you glean this from the perf profile?

Essentially. hit * to expand all the frames, and go to nsMsgAccountManager::CleanupOnExit where it changes from 62% to 57%. The frames starting at 57% are waits.

Cool. Glad it was able to shine a light on the source/cause.

Comments from a developer "It looks like we have some PR_Wait calls inside of that function [nsMsgAccountManager::CleanupOnExit ] that actually does nothing but to wait for 1000 microsecond in a while loop here. you can also see the same thing in the profiler source code view when you double click on the nsMsgAccountManager::CleanupOnExit frame on the call tree. looks like most of the time is spent in this line. apparently it's trying to empty the trash but it's taking longer than expected?"

So, seeing as my brief experience with 111.0b1 was positive with respect to this shutdown issue, did nsMsgAccountManager.cpp#1558 get examined and fixed there already or just coincidence?

(In reply to Arthur K. (he/him) from comment #12)

So, seeing as my brief experience with 111.0b1 was positive with respect to this shutdown issue, did nsMsgAccountManager.cpp#1558 get examined and fixed there already or just coincidence?

I'd be surprised if it had gotten fixed. I would not be surprised if your problem returns.

Took me about 25 tries but I was able to capture a perf profile with 111.0b3: https://share.firefox.dev/3yiqCD1

Same story?

(In reply to Arthur K. (he/him) from comment #14)

Took me about 25 tries but I was able to capture a perf profile with 111.0b3: https://share.firefox.dev/3yiqCD1
Same story?

Yes. If you select the range in black in "parent process" at the top with your mouse, and then expand the call tree, all of the wait time is under nsMsgAccountManager::CleanupOnExit

Summary: 86.0b1+ have been taking a long time to shut down when exiting the program → 86.0b1+ have been taking a long time to shut down when exiting the program. nsMsgAccountManager::CleanupOnExit with server setting "empty trash on exit" enabled
Version: Thunderbird 88 → Thunderbird 86

Please try 115.1.0 or beta 117 (available shortly)

Flags: needinfo?(thee.chicago.wolf)

(In reply to Wayne Mery (:wsmwk) from comment #16)

Please try 115.1.0 or beta 117 (available shortly)

I tested at home with the 2nd build of 115.1.0 just this morning and it still took a while to shut down. I'm waiting on the portable 115.1.0 to get published so I can update here on my work PC.

Flags: needinfo?(thee.chicago.wolf)

(In reply to Wayne Mery (:wsmwk) from comment #16)

Please try 115.1.0 or beta 117 (available shortly)

So here's something really weird. I tested again with 115.1.0 (build 20230731171153) just now and am getting a shutdown time of +/- 1m 20sec. I repeated this test over a few times and got about the same result. Naturally, I decided to capture a per profile to see what the holdup is. As strange as it sounds, I am unable to finish a capture and upload the results because within a few seconds of ending the capture and being moments away from clicking the "Upload" button, TB shuts down gracefully. This happens with only capturing about 10 seconds of profiling info.

Ok, strike that. Somehow I was quick and lucky enough to capture two perf profiles:

https://share.firefox.dev/43QkwqO
https://share.firefox.dev/3KjnPA0

See Also: → 1869297
You need to log in before you can comment on or make changes to this bug.