Closed Bug 1864776 Opened 5 months ago Closed 5 months ago

Display of status bar string "Looking for folders..." slowing down initial imap folder discovery. Was 6 seconds, now more than 30 seconds with 1000 folders.

Categories

(Thunderbird :: Mail Window Front End, defect)

defect

Tracking

(thunderbird_esr115 fixed, thunderbird121 fixed)

RESOLVED FIXED
122 Branch
Tracking Status
thunderbird_esr115 --- fixed
thunderbird121 --- fixed

People

(Reporter: gds, Assigned: gds)

References

Details

(Keywords: perf, regression, Whiteboard: [regression: 121, sort of])

Attachments

(2 files)

When TB starts up it always does folder discovery and, for each URL driving discovery, the status message <account name> Looking for folders... is printed to the status bar. Each print of the status message potentially steals CPU from the imap threads so it slows down the network some.
The slowdown can become noticeable if the user has the imap option to ignore subscriptions set so all folders, subscribed or not, are shown. And if you have a lot of folders in an imap account (e.g., 1000) a significant slowdown is observed. This is because instead of a single URL (discoverallboxes, or discoverchildren) as occurs when subscriptions are observed, a URL per folder occurs instead (listfolder). However, until the fix for bug 1832149 landed, versions > 110 didn't display this status message so the slowdown didn't occur. With the fix from bug 1832149 in place, for each of the 1000 folders, the string is repetitively printed to the status bar causing the discovery to now take at lease 30 seconds instead of about 6 seconds with versions <= 110 or in newer versions without the bug 1832149 fix.

In addition, while initial discovery is in progress, the status bar message <account name> Looking for folders... now flickers quickly on and off for at least 30 seconds when there are 1000 folders and TB is configured to ignore subscriptions.

This was seen and reported to me via email by user "Binarus" (info@binarus.de). Binarus also reports that sometimes the flickering status string <account name> Looking for folders... occurs during runtime and not just at startup. But I haven't yet been able to duplicate that.

I was able to verify that not printing the status string reduces the discovery time back to the <= v110 time of 6 seconds by commenting out the 3 lines pointed to here:
https://searchfox.org/comm-central/search?q=%22imapStatusLookingForMailbox%22&path=&case=false&regexp=false
My guess, without looking at the code, is that with <= 110, it didn't re-print the string until the string to print differed. Now it clears and prints the same string over and over, resulting in the flicker and the stolen cycles from an imap thread.

Note: To duplicate the problem I created 1000 folders (all are empty) in an imap account (cyrus server on localhost) and also have to set advanced imap server setting "Show only subscribed folders" to disabled (not selected).
For future reference, to create the 1000 folders I made this temporary change: https://bugzilla.mozilla.org/attachment.cgi?id=9267579

Flags: needinfo?(brendan)

The code that restores the IMAP status display
https://searchfox.org/comm-central/rev/7bbb8e5a56e688006243f0cbc0b56afe795d1842/mailnews/imap/src/nsImapService.cpp#2386-2408
is in fact from the author of the this bug here, see 1832149 comment #9. It runs in nsImapService::NewChannel(), so it wouldn't run frequently. The other code from https://hg.mozilla.org/comm-central/rev/59dc5047d862 wires up the status updates to the main window. None of this explains the flickering/flashing. Likely the frequent call to the status text update was introduced while the display itself was broken, so it went unnoticed. Likely some other part of the system resets the status display. This could best be debugged with a breakpoint/console.trace() here:
https://searchfox.org/comm-central/rev/7bbb8e5a56e688006243f0cbc0b56afe795d1842/mail/base/content/mailWindow.js#440,449

When doing the "listfolder" URL on each of my 1000 folders at startup, the call to here (based on a dump I put in it)
https://searchfox.org/comm-central/rev/7bbb8e5a56e688006243f0cbc0b56afe795d1842/mail/base/content/mailWindow.js#440
occurs with the string "Looking for folders..." and then an empty string occurs, causing the flicker I assume. If I change the code so that it returns on the empty string (!statusText) I see "Looking for folder..." continuously and no flicker. Also the time to do the 1000 "listfolder" URLs goes down from 30s to maybe 7-10 seconds (based on timestamps in IMAP:4 log). But with this change the text in the status bar never clears so "Looking for folders..." or anything else printed there remains forever, even if you open another folder.

This never seems to be called (based on a dump() call I put in it):
https://searchfox.org/comm-central/rev/7bbb8e5a56e688006243f0cbc0b56afe795d1842/mail/base/content/mailWindow.js#449

Running 102.9.1 that I have installed, I don't see the status "Looking for folders..." at all at start up. I only see it when I do a collapse/expand.at the account/server level with no flicker. The time to finish the 1000 URLs with 102 is about 5-7 seconds. (With 102 and tip, the "Looking for folders..." never clears until you click on something else.)

... and then an empty string occurs.

Where is the caller? Where does the empty string come from? Use console.trace() to see it. If it's a C++ caller, add this to the JS code:

    const ccm = Cc["@mozilla.org/charset-converter-manager;1"].getService(
      Ci.nsICharsetConverterManager
    );
    let dummy = ccm.getCharsetAlias("utf-8");

Old debugging trick from from Joshua Cranmer (who is still the mailnews module owner). Then you can break in the C++ code and get a stack.

I tried other ways to fix this but this seems, on average, to be optimum.
In addition to fixing the flicker/readability issues, this reduces the time to
complete the folder discovery imap background process at startup for 3000 folders
from about 10 minutes to 2 minutes when subscriptions are ignored.
Taken directly from https://github.com/Betterbird/thunderbird-patches/blob/main/115/bugs/1864776-status-display-less-busy.patch

Assignee: nobody → gds
Status: NEW → ASSIGNED

This may not be a direct regression caused by changes made in bug 1832149, just that the problem is not noticeable without those changes which now allow the status bar to display the "Looking for folders..." string. So probably most likely this is the result of the many SN changes (but I'll leave the regression flag set until we are sure).
The code that the patch of comment 5 above is applied to (mailWindow.js) appears to be mostly the same as 102 which doesn't have the problems described here.
Also, for some reason, when 102 starts, it never displays the "Looking for folders..." message repeatedly. It only displays it on collapse/expand at the account top level. Daily, with the bug 1832149 fixes, shows it repeatedly at both times. ("Looking for folders..." status string is only displayed repeatedly when you have a lot of folders and you are configured to ignore subscriptions and is the result of running "listfolder" URLs repeatedly.)

Attachment #9364394 - Attachment description: Bug 1864776 - Reduce flicker and improve readability of status bar text. r=mkmelin,babolivier → Bug 1864776 - Reduce flicker and improve readability of status bar text. r=babolivier
Flags: needinfo?(brendan)

A similar issue appears when performing a "Repair Folder" with the "Downloading message xxx of yyy in <folder>" messages.

Do we need a new bug for that, or would that be covered here?

(In reply to Calum Mackay from comment #7)

A similar issue appears when performing a "Repair Folder" with the "Downloading message xxx of yyy in <folder>" messages.

Do we need a new bug for that, or would that be covered here?

Yes, it should keep the "Downloading..." strings from slowing down the downloads. The patch doesn't care what the string is. Of course, you may not see each xxx value but you probably couldn't before this patch either since, for small messages, they went by too fast.

great, thanks Gene. I'll double check that when the fix is out.

Still calling this a regression but not a regression specifically caused by bug 1832149.
Also, set checkin-needed-tb keyword.

No longer regressed by: 1832149
See Also: → 1832149
Target Milestone: --- → 122 Branch

Pushed by ikey@thunderbird.net:
https://hg.mozilla.org/comm-central/rev/2d7e8092cbc4
Reduce flicker and improve readability of status bar text. r=babolivier

Status: ASSIGNED → RESOLVED
Closed: 5 months ago
Resolution: --- → FIXED

This is breaking comm/mail/base/test/browser/browser_searchMessages.js

Flags: needinfo?(gds)
Regressions: 1859526

Now that status changes occur on 500 ms time base, the test was expecting
to instantly see the status display change from "No matches found" to
"10 matches found". So the test now allows up to 1 second for the status text
change to occur before a failure is logged.

Pushed by mkmelin@iki.fi:
https://hg.mozilla.org/comm-central/rev/6c5b81e0b2dd
Follow-up: Fixes failing test browser_searchMessages.js. r=mkmelin

Gene, good for uplift to beta?

And, if we take bug 1832149 on 115 we will also need to take this.

Keywords: perf
Whiteboard: [regression: 121, sort of]

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

Gene, good for uplift to beta?

And, if we take bug 1832149 on 115 we will also need to take this.

Yes, if bug 1832149 by itself it tends to slow down network activity when there are a lot of status messages displaying.
My only mild concern is that since status display is reduced down to two per second by this (bug 1864776) and those in between are thrown away, so maybe there will be a status not displayed that a user is expecting to see in some situations. So maybe having bug 1832149 and this on beta for a while would be best rather than going immediately into 115 with both.

Flags: needinfo?(gds)
Duplicate of this bug: 1859526

Comment on attachment 9364394 [details]
Bug 1864776 - Reduce flicker and improve readability of status bar text. r=babolivier

[Triage Comment]
Approved for beta

Attachment #9364394 - Flags: approval-comm-beta+

Comment on attachment 9365298 [details]
Bug 1864776 -- Fixes failing test reported at bug 1859526 caused by patch for this bug. r=mkmelin

[Triage Comment]
Approved for beta

Attachment #9365298 - Flags: approval-comm-beta+

Good for 115?

Flags: needinfo?(gds)

Looks like it's only been on beta for about 6 days. Don't know how many users have tried it. Before this and bug 1832149 on 115 we had no status for the most part. So even though maybe a lot of user haven't used it yet, it's better than no status. So I would say go ahead and put this and bug 1832149 both on 115..

Flags: needinfo?(gds)
Attachment #9365298 - Flags: approval-comm-esr115?

Comment on attachment 9364394 [details]
Bug 1864776 - Reduce flicker and improve readability of status bar text. r=babolivier

[Triage Comment]
Approved for esr115

Attachment #9364394 - Flags: approval-comm-esr115+

Comment on attachment 9365298 [details]
Bug 1864776 -- Fixes failing test reported at bug 1859526 caused by patch for this bug. r=mkmelin

[Triage Comment]
Approved for esr115

Attachment #9365298 - Flags: approval-comm-esr115? → approval-comm-esr115+
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: