1810041 - 109.0b4 long shutdown times on Mac

Status: VERIFIED DUPLICATE of bug 1788599

(MailNews Core :: Networking: IMAP, defect)

Description

[Stephen Welker]

User Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/16.2 Safari/605.1.15

Steps to reproduce:

Launch Thunderbird using this script
--- snip ---
#!/bin/sh
export MOZ_LOG=IMAP:5,IMAP_CS:5,IMAPAutoSync:5,IMAP_KW:5,IMAPCache:5,Movemail:5,MAPI:5,MailDirStore:5,negotiateauth:5,timestamp,sync
export MOZ_LOG_FILE=$HOME/Thunderbird-imap-trace
/Applications/Thunderbird.app/Contents/MacOS/thunderbird-bin &
--- snip ---
Wait 30 seconds
Quit the application (Command-Q)
Observe long shutdown time

Actual results:

TL;DR version = takes approximately 42 seconds to shutdown (7 IMAP accounts * 6 seconds)

Long version:

After Thunderbird has been told to quit, the following has been observed.

For each account, 7 in total, in the selected state, Thunderbird will:

1. Send 'DONE' for the current IDLE state
2. Send 'expunge'
3. Send 'UID fetch 3857049062:* (FLAGS)'
4. Thunderbird now creates a new thread and logs into the server
5. Send 'ENABLE CONDSTORE'
6. Send 'ID ("name" "Thunderbird" "version" "109.0")'
7. Send 'ENABLE UTF8=ACCEPT'
8. Send 'LANGUAGE en-US'
9. Send 'select "Deleted" (CONDSTORE)'
10. Send 'list "" "Deleted/*"'
11. Wait ~6 seconds

The above 11 steps are performed sequentially - totalling ~42 seconds.

Step 11 is a mystery, I do not know why it exists.

For brevity, I have opted to not include tags for the IMAP commands.

At this point, Thunderbird will quickly send a mixture of 'logout' and 'close' IMAP commands without waiting for an acknowledgment from the server. It will then close the connection.

The above behaviour has also been observed in the following:

• Thunderbird 108.0b1
• Thunderbird 107.0b1
• Thunderbird 106.0b4

Expected results:

TL;DR version = shutdown in approximately 1 second.

Long version:

After Thunderbird has been told to quit, it could:

1. Send 'DONE' for the current IDLE state
2. Send 'expunge'
3. Send 'UID fetch 3857049062:* (FLAGS)'
4. Send 'select "Deleted" (CONDSTORE)'
5. delete messages in Deleted mailbox
6. Send 'logout'

This will get rid of the delay and reduce the number of connections to the server.

Comment 1

[Wayne Mery (:wsmwk)]

In citing the list of observed versions, for example Thunderbird 106.0b4, are you suggesting that shutdown speed was better at some time prior to Thunderbird 106.0b4?

Comment 2

[Stephen Welker]

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

In citing the list of observed versions, for example Thunderbird 106.0b4, are you suggesting that shutdown speed was better at some time prior to Thunderbird 106.0b4?

I cannot recall, I have only documented the versions that I have debugging logs for, hence I can state facts not recollections. I believe that I have increased the number of IMAP accounts over some time (a few months) before 106.0b4, so I cannot make a firm claim. At the moment I only run Thunderbird Beta or Thunderbird Daily as they have independent run time directories. I have stopped using Thunderbird Release as it uses the same run time directory as Thunderbird Beta (at least in the past).

It is worth noting that the number of messages in a given mailbox does not affect the 6 second delay - 1 account has 19,300 messages in the INBOX, 1 account has just under 1000 messages in the INBOX, and the others only have less than 30 messages each INBOX.

Startup times are very fast, typically less than 10 seconds for all 7 IMAP accounts.

Comment 3

[Alfred Peters [:infofrommozilla]]

If I enable Account Settings:
[X] Clean up ("Expunge") Inbox on Exit
and
[X] Empty trash on exit
I can confirm the behavior.
Here the pause is even ~80 seconds long (just one IMAP account).

If I turn them off again, TB immediately shuts down.

Comment 4

[gene smith]

I'm seeing about a 6 or 7 second shutdown time with expunge inbox and empty trash with 1 account. I need to look closer but it appears the expunge of inbox happens fairly quick since it occurs on Inbox's existing connection. But for trash delete, tb makes a new connection, authenticates and selects trash mailbox and then deletes all unless select indicate 0 exists then it just logs out/closes.
Seems like tb could just use the existing inbox connection to empty trash and there is no need for a new connection to trash
I'm running the current daily and not a beta. FWIW, I don't see a difference with or without autosync enabled.

I see the reporter is using condstore which is disabled by default. But typically it makes things faster. I keep it enabled too, usually.
Reporter, you are logging a lot of stuff. I suppose you see the same shutdown time without logging?

Also, with multiple accounts, not sure if tb does them in series or in parallel. I'm guessing in series.

(In reply to Alfred Peters from comment #3)

Here the pause is even ~80 seconds long (just one IMAP account).

If I turn them off again, TB immediately shuts down.

Don't know what's going on here. That's a lot longer then the reporter or I am seeing per account, I think.
Were there a lot of message in Trash to be deleted? Or maybe the server was being real slow in responding to imap commands or in making the new trash mailbox connection?

Comment 5

[Stephen Welker]

(In reply to gene smith from comment #4)

Reporter, you are logging a lot of stuff. I suppose you see the same shutdown time without logging?

The shutdown time is the same without logging. I only run the logging script when I need to do debugging. Normally I run Thunderbird Beta without debugging.

Comment 6

[Stephen Welker]

(In reply to gene smith from comment #4)

Also, with multiple accounts, not sure if tb does them in series or in parallel. I'm guessing in series.

Your guess is correct, the logs reveal that they are performed in series.

Comment 7

[Alfred Peters [:infofrommozilla]]

Attachment: ShutdownLog.txt

(In reply to gene smith from comment #4)

(In reply to Alfred Peters from comment #3)

Here the pause is even ~80 seconds long (just one IMAP account).

Don't know what's going on here. That's a lot longer then the reporter or I am seeing per account, I think.

I use Windows 10. Yes TB Daily and Beta behave the same.
Even with a new profile, nothing changes.

Were there a lot of message in Trash to be deleted?

No.

Or maybe the server was being real slow in responding to imap commands or in making the new trash mailbox connection?

No.

See my server log:
At 01:41:19 I selected the INBOX.
At 01:41:57 I shut down TB.
Until 01:43:20 nothing happens. Then TB finally shuts down and disappears from the process list. This also takes less than a second.

Comment 8

[Wayne Mery (:wsmwk)]

Stephen, which items of comment 3 do you have enabled?

FWIW see also

• Bug 497059 - Hang with unreliable wifi connection, either when re-connecting to email server, or on shutdown
• Bug 655357 - Auto-Expunge: mail.imap.expunge_option = 1 doesn't execute expunge immediately, but only while TB-shutdown
• Bug 401295 - Use new shutdown service to empty trash, expunge inbox, compact folders on shutdown

Comment 9

[Stephen Welker]

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

Stephen, which items of comment 3 do you have enabled?

Both (for all accounts).
[X] Clean up ("Expunge") Inbox on Exit
[X] Empty trash on exit

I have observed the server is quiet during TB shutdown.

FWIW see also

• Bug 497059 - Hang with unreliable wifi connection, either when re-connecting to email server, or on shutdown
• Bug 655357 - Auto-Expunge: mail.imap.expunge_option = 1 doesn't execute expunge immediately, but only while TB-shutdown
• Bug 401295 - Use new shutdown service to empty trash, expunge inbox, compact folders on shutdown

Also, I have:
Gigabit ethernet connection to the IMAP server.
mail.imap.expunge_option = 0 (default)

Comment 10

[Stephen Welker]

I performed a comparison with the Windows 10 (64bit) version of TB, and I observed no delay in the shutdown sequence. Same account, same server, same network, same CONDSTORE setting in preferences.

PS: the value of "mail.server.default.use_condstore" preference does NOT affect the shutdown times on either platform.

PPS: during the shutdown sequence on macOS, the beach ball cursor is present for part of the time.

Comment 11

[Wayne Mery (:wsmwk)]

So to be clear, for you, with same settings on both systems, the long shutdown is only on Mac? If so that would be quite odd.

Comment 12

[Stephen Welker]

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

So to be clear, for you, with same settings on both systems, the long shutdown is only on Mac? If so that would be quite odd.

Confirmed.

Comment 13

[Wayne Mery (:wsmwk)]

This will end up being fixed by bug 1788599 in the next couple weeks.

Comment 14

[Stephen Welker]

I have observed the issue is now resolved as of version TB 117.0 (daily and beta)

Comment 15

[Wayne Mery (:wsmwk)]

Stephen thanks for the follow up and confirmation.