1864776 - 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.

Status: RESOLVED FIXED

(Thunderbird :: Mail Window Front End, defect)

Description

[gene smith]

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" ([e-mail]). 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

Comment 1

[betterbird.project+12]

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

Comment 2

[gene smith]

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.)

Comment 3

[betterbird.project+12]

... 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.

Comment 4

[betterbird.project+13]

This should stop the flickering:
https://github.com/Betterbird/thunderbird-patches/blob/main/115/bugs/1864776-status-display-less-busy.patch

Comment 5

[gene smith]

Attachment: Bug 1864776 - Reduce flicker and improve readability of status bar text. r=babolivier

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

Comment 6

[gene smith]

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.)

Comment 7

[Calum Mackay]

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?

Comment 8

[gene smith]

(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.

Comment 9

[Calum Mackay]

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

Comment 10

[gene smith]

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

Comment 11

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/2d7e8092cbc4
Reduce flicker and improve readability of status bar text. r=babolivier

Comment 12

[Magnus Melin [:mkmelin]]

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

Comment 13

[gene smith]

Attachment: Bug 1864776 -- Fixes failing test reported at bug 1859526 caused by patch for this bug. r=mkmelin

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.

Comment 14

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/6c5b81e0b2dd
Follow-up: Fixes failing test browser_searchMessages.js. r=mkmelin

Comment 15

[Wayne Mery (:wsmwk)]

Gene, good for uplift to beta?

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

Comment 16

[gene smith]

(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.

Comment 18

[Wayne Mery (:wsmwk)]

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

[Triage Comment]
Approved for beta

Comment 19

[Wayne Mery (:wsmwk)]

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

Comment 20

[Rob Lemley [:rjl]]

Thunderbird 121.0b3:
https://hg.mozilla.org/releases/comm-beta/rev/9ae69d00af62
https://hg.mozilla.org/releases/comm-beta/rev/a001c1f3e82d

Comment 21

[Wayne Mery (:wsmwk)]

Good for 115?

Comment 22

[gene smith]

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..

Comment 23

[Wayne Mery (:wsmwk)]

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

[Triage Comment]
Approved for esr115

Comment 24

[Wayne Mery (:wsmwk)]

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

Comment 25

[Rob Lemley [:rjl]]

Thunderbird 115.5.2:
https://hg.mozilla.org/releases/comm-esr115/rev/6da21983e840
https://hg.mozilla.org/releases/comm-esr115/rev/fe1f9f922675

Comment 26

[Intermittent Failures Robot]

3 failures in 3671 pushes (0.001 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• comm-central: 3

Platform and build breakdown:

• macosx1015-64-qr: 3
  • debug: 3

For more details, see:
https://treeherder.mozilla.org/intermittent-failures/bugdetails?bug=1864776&startday=2023-12-04&endday=2023-12-10&tree=all