Closed Bug 1660672 Opened 4 years ago Closed 3 years ago

IMAP "Looking for Folders..." at startup take a very long time - long delay - ~1 minute from startup to read first email

Categories

(MailNews Core :: Networking: IMAP, defect)

defect

Tracking

(Not tracked)

RESOLVED DUPLICATE of bug 163964

People

(Reporter: richard.leger, Unassigned)

References

Details

(Keywords: perf)

Attachments

(2 files)

This is a follow up bug that blocks Bug 1649103.

Basically when starting up TB with big IMAP mailbox and high number of folders, while in online mode without caching (Keep Messages disabled), it takes a very long time before you can read the first email.

During loading time, the mention "Looking for folders..." appears for a very long time in the status bar... prior the "Loading Message..." after which the selected message body content appears in the preview pane.

This situation is aggravated if you have network calendars CalDav enabled (issue reported in Bug 1642292).

Summary: IMAP "Looking for Folders..." at startup take a very long time - long delay → IMAP "Looking for Folders..." at startup take a very long time - long delay - ~1mn from startup to read first email

If your issue isn't fundamentally caused by something in your environment, then I expect that you are probably seeing one of these https://mzl.la/3j78UZq

An imap & sync log, plus a profile, will help identify the issue.

Component: Folder and Message Lists → Networking: IMAP
Keywords: perf
Product: Thunderbird → MailNews Core

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

If your issue isn't fundamentally caused by something in your environment,

I don't believe that is the case, I would see issues with other software not just Thunderbird if that was... no?
I will try to update my machine again Windows/Drivers if any available...
Also all the test I running are run on the same machine and situation degrade as TB is upgraded so I don't think the environment is the issue.
I tried on two different Internet connections landline and 4G... same results...

then I expect that you are probably seeing one of these https://mzl.la/3j78UZq

That is quite possible so I am trying to help at least identify what the issue is or may be...
Looking at others comment in Bugzilla, I am obviously not the only one to see perf issue in TB degrading... though it may affect most heavy duty users... with very large data sets...

An imap & sync log, plus a profile, will help identify the issue.

FYI, perf profiles about this bug are available in test results 02 and 03 at Bug 1649103 Comment 15
I know how to gather the IMAP logs, but how to gather the sync log?
Which log level would be helpful?

(In reply to Richard Leger from comment #2)

FYI, perf profiles about this bug are available in test results 02 and 03 at Bug 1649103 Comment 15

Perf profile from test results with TB 80.0b4 (64-bit) re-posted here for convenience...

02 https://share.firefox.dev/2Ehx2tG (offline mode | ~27s delay)
03 https://share.firefox.dev/2Esd7rE (online mode | ~57s delay)

Hi Wayne,

(In reply to Richard Leger from comment #2)

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

An imap & sync log, plus a profile, will help identify the issue.

FYI, perf profiles about this bug are available in test results 02 and 03 at Bug 1649103 Comment 15
I know how to gather the IMAP logs, but how to gather the sync log?
Which log level would be helpful?

The IMAP logs are being sent to you in a private email as I don't want to publish them publicly as they may contain sensitive data.

I used the following log options to generate it as per test 03 at Bug 1649103 Comment 15:
set MOZ_LOG=IMAP:5,timestamp,sync

(In reply to Richard Leger from comment #4)

....
The IMAP logs are being sent to you in a private email as I don't want to publish them publicly as they may contain sensitive data.

I used the following log options to generate it as per test 03 at Bug 1649103 Comment 15:
set MOZ_LOG=IMAP:5,timestamp,sync

Thanks. I didn't use the full name of the sync option - it is IMAPAutoSync. But that's OK, let's see what your log shows before redoing anything.

Could this bug be related to the issues people are having with Yahoo mail?

Looking at the log received via email from Wayne, I think Richard may have more folders than I have actual messages! The log covers a period of about 50 seconds and it looks like it is mostly doing a lot of often interleaved imap list, xlist and lsub to discover the folders. Also it appears that sometimes tb only asks for list info on Inbox and the server returns info on Inbox plus all the folders under Inbox which is pretty much everything. That may be a server bug or I am not seeing it right.

I do see that the server is Cyrus and don't know if Richard has any control over it. I do see the LIST-EXTENDED XLIST capability which allows tb to do the xlist, I think. It might be interesting to see if disabling the LIST-EXTENDED XLIST capability at the server would change anything. Unfortunately, I don't see a pref in tb to cause it to be ignored.

Tb is also detecting a syntax error on the quotaroot response from the server. I don't think this causes any slowdown but we have recently "improved" the quota handling and display. Not sure if that just appeared in 78.

I may have missed it, but which old tb version was "fast enough"? 68, 60, etc? I should also ask if when it was fast enough, did you have a similar number of folders?

Looking at the list provided by Wayne above, it does appear that bug 163964 addresses the problem of lots off folders being discovered. I'll take a closer look at it and see if it might help.

Looks like the xlist is not really using that much time. It's the normal lists that are taking a lot of time. What's happening is that on startup, each connection that is made (I see two in the log, one for inbox another selected to drafts) the folder discovery sequence occurs. Each sequence per connection takes about 25 sec, so with two it takes 50 seconds. So if 5 connections occur it might take 250 sec. But this would probably only occur if 4 non-inbox folders are selected in quick succession and all 5 sequences (including inbox's) occur in parallel. Once one connection finishes the discovery, it is skipped for later new connections. It seems like once a connection starts the discovery there is no reason for the subsequent connections to also do the discovery. (This lock-out presently only occurs after a connection finishes discovery.)

Looking at the proposed fix in bug 163964 it suggests moving this https://searchfox.org/comm-central/rev/7156143da17c283114591163b3074e622484ee6e/mailnews/imap/src/nsImapProtocol.cpp#1783 down after ProcessSelectedStateURL(). Another possibility is to just not do line 1783 at all. When I remove the call to FindMailboxesIfNecessary() no time-consuming lists occur at startup. Of course, without this, any new folders that came into existence with tb shut down will not automatically appear. To see new folders the user would need to collapse/expand the account's folder tree. Doing this causes tb to run the "discoverallboxes" URL which then does the lists needed to discover and show the new folders. Also, it only occurs on one connection so, at least for Richard, it should take no more than 25 seconds and may, I'm not sure, occur in background so other UI activities can occur (hard to test since I don't have that many folders).

A possibility is to add a pref that just skips the call to FindMailboxesIfNecessary() for users like Richard with many folders. Typical users would still get the automatic folder discovery on startup.

Thanks for looking into a solution...

Yes I have a large data set after 10 years of usage... but that shall not prevent TB to scale and perform well ;-)

All I do is just click on a message in Inbox at startup to see its content.

My view on this:

  • I don't think folder discovery shall happen only at startup, but it shall not block user interaction...
  • Why not delegate this Folder Looking task to a worker (background task) so main UI not affected?
  • Could also be done at later stage (or at idle time) perhaps as you suggested...
  • Prioritise user interaction, loading new msg in Inbox list and msg content loading... maybe all those three shall happen in one separate connection not affected by other connections related to folders?

What user need at startup is usually to read new emails so the important here is for Inbox to refresh asap and allow end user access to the content of selected emails (in preview) or when opened in a tab. Message loading taking priority... over folder discovery/update...

Also why would there be multiple connections for discoverability... and why each conn takes 25s? And if multiple could they interfere with each other? Does a network socket is created for each folder check? Or the same one re-used? Also can't the process happen all at once or in batch instead of each folders as it seems in logs? Also it seems you first lookup for all folders... and then again for flags... cant both be done together within the same connection?

I do have access to IMAP Cyrus server but I am not sure if I can disable the LIST-EXTENDED XLIST but may be able to try for testing. But my view is that server options shall not impact TB.
Before doing so I can also check and compare situation with 68.11 if that can be of any help. Let me know.

With regards to quota issue, I had no quota on my mailbox, but did set one and removed again afterward as part of testing a while back for another TB bug causing it to slow down in such situation (which I still encounter in 80 branch but to less extent).
Could that have caused the quota to become unreadable for TB? Not sure why it would be "unreadable" may just need to be interpreted as "no quota" unlimited storage :-) I do effectively have no quota on my mailbox, only limited by disk space on server side ;-)

Hope that help.

(In reply to Worcester12345 from comment #6)

Could this bug be related to the issues people are having with Yahoo mail?

Bug reference?

Flags: needinfo?(worcester12345)

Here's one: bug 1606339

Here was another: bug 1615833

Flags: needinfo?(worcester12345)

I don't see how the yahoo issues are related to this bug. Maybe I'm missing something?

(In reply to Worcester12345 from comment #11)

Here's one:
https://bugzilla.mozilla.org/show_bug.cgi?id=1606339

The bug you refer to is related to authentication issues... so not related to this bug...

Here was another:
https://bugzilla.mozilla.org/show_bug.cgi?id=1615833

The bug you refer to is marked as duplicate of Bug 1595169 which itself has been marked RESOLVED INVALID
None of which appears related to this bug... while still IMAP related...

I don't think anything was missed!

Immediately after upgrade of my environment to Windows 10 2004 and TB 80.0b5 (64-bit) I noticed a slight improvement of speed... but after few days of using TB restarting it multiple times, I am now back to square one... in term of perf on this bug issue...

# PerfProfile TBVersion DelayRead1stEmail Mode
04 https://share.firefox.dev/2ZozJBd 80.0b5 (64-bit) ~1mn+ online mode (no calendar enabled)

Also noticed that more I use intensively TB during the course of the day, slower it become especially the UI interaction and the drag/drop... that freeze and go, freeze and go during dropping... which may not be related to this bug but just thought to mention it... could be related to memory usage perhaps...

I should let you know that I have no clue how to read the PerfProfile linked to. Maybe Wayne can NI someone who can interpret it.

Immediately after upgrade of my environment to Windows 10 2004 and TB 80.0b5 (64-bit) I noticed a slight improvement of speed...

Startup speed or runtime speed? Maybe both?

but after few days of using TB restarting it multiple times, I am now back to square one... in term of perf on this bug issue...

The bug issue is startup speed so I guess that's what you mean. Restarting tb or restarting windows? (I suspect "it"==TB but want to be sure.)

Also noticed that more I use intensively TB during the course of the day, slower it become especially the UI interaction and the drag/drop... that freeze and go, freeze and go during dropping... which may not be related to this bug but just thought to mention it... could be related to memory usage perhaps...

I guess this would be a separate/new bug since this bug is about startup speed. But since you mentioned it, does tb restart fix the "freeze/go" at least for while? If not, how about windows reboot?

(In reply to gene smith from comment #15)

I should let you know that I have no clue how to read the PerfProfile linked to. Maybe Wayne can NI someone who can interpret it.

Open the link https://share.firefox.dev/2ZozJBd in Firefox Desktop version on a computer is best...

Immediately after upgrade of my environment to Windows 10 2004 and TB 80.0b5 (64-bit) I noticed a slight improvement of speed...

Startup speed or runtime speed? Maybe both?

I would say both...
By startup I mean TB startup till first UI and then running time till first email read...
There is a recent tb-planining post advising dev to use lazyloading of modules instead of chrome.utils to improve TB startup so hopefully that would help speed things up at some point... I have also another bug opened for this as well.
Here I am more interested at fixing the very long Looking for folders (IMAP) issue at TB startup... that prevent/delay to load/read first msg after startup...

but after few days of using TB restarting it multiple times, I am now back to square one... in term of perf on this bug issue...

The bug issue is startup speed so I guess that's what you mean. Restarting tb or restarting windows? (I suspect "it"==TB but want to be sure.)

I meant "it"==TB

Also noticed that more I use intensively TB during the course of the day, slower it become especially the UI interaction and the drag/drop... that freeze and go, freeze and go during dropping... which may not be related to this bug but just thought to mention it... could be related to memory usage perhaps...

I guess this would be a separate/new bug since this bug is about startup speed.

Yes it should but I have already way too many bug opened at the moment with perf issues being my priority... Also there is an already opened bug somewhere about memory leakage linked to IMAP... I posted few memory report but no progress on issue so far...

But since you mentioned it, does tb restart fix the "freeze/go" at least for while? If not, how about windows reboot?

Yes restarting TB sort the drag/drop issue for a while but the calendar taking 10mn to load (dealt with already in a separate bug) I don't tend to restart more than once on a day... I do a lot of drag/drop of email in IMAP folders...

New perf profile for TB 81.0b3 (64-bit)
https://share.firefox.dev/2ZtbYYF

From start till read first emails in my IMAP account online, here are multi test results:

  • 1mn46s (while recording the perf profile which slow down the process)
  • 1m12s
  • 1m13s
  • 1m19s
  • 0m37s <-- this only happened once and don't know how or what made the difference...
  • 1m30s

On average TB takes:
~2-4 seconds to get the profile manager prompt
+18-20 second to start (till first UI - email main tab )
+40 seconds to look for folder till read first message loading - Most of this time is used for "Looking for folders"
+1-2 seconds to load the message
~1m1s-1m6s in total + some overhead...

Once it took:
~less than 2 second to get the profile manager prompt
+10 seconds to start (till first UI - email main tab)
+27 seconds to look for folder till read first message loading - Most of this time is used for "Looking for folders"
~0m39s in total + some overhead...

Attached image ChromeUtilsImportCalEvent.png (deleted) —

A per attachment in Comment 18, a lot of calls to ChromeUtils.import on ressource:///modules/CalEvent.jsm appears between 30s and 50s in the timeline...

Not sure why that is, because all my calendars are disabled so shall not be required to load such module :-)

May not make much difference on the time line as the worth issue is "Looking for Folders" but just thought to mention it!

Richard,
I went ahead and made a win64 "try" build that leaves out the call to FindMailboxesIfNecessary() that occurs on startup. Since I have no way to benchmark this with my relatively small number of folders, I'm hoping you don't mind trying this just as a test. You can download the install file from here: https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=c6fd99f40611904626de28ed805cdb34e84b18e7
I don't know if you've done this before but, if not, click the green "B" next to "Windows 2012 x64 opt" and then down below click "Artifacts". In the list select and download "target.installer.exe" (or whatever you think might be more appropriate for setting up a temporary tb installation).

Since you show version 80 as the tb you are running, not sure if you mean its a beta or a daily. Anyhow, the "try" version I just built is today's daily with a one line change.

Hi,

Thanks for looking into this...

(In reply to gene smith from comment #20)

Since you show version 80 as the tb you are running, not sure if you mean its a beta or a daily.

The b in TB 81.0b3 (64-bit) means Beta :-)

I went ahead and made a win64 "try" build that leaves out the call to FindMailboxesIfNecessary() that occurs on startup.(...) download the install file from here: https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=c6fd99f40611904626de28ed805cdb34e84b18e7

I have downloaded and installed it as suggested.

It appears to be TB Daily 82.0a1 (2020-09-11) (64-bit)

Test results:

  • creating a new profile and copy my profile content into it did not allow me to properly test and use my profile as TB stop responding shortly after opening the first main UI (without any mail folder or message list appearing)... so inconclusive... or let say broken :-)

  • creating a new profile and configuring my imap email account as a new account did not work either, see attached I can only access the Inbox folder (my mailbox root folder)! But none of its subfolders... which aren't populated... but I can access messages the Inbox :-)

Is that what you were expecting as a test result?

Regards,

What about running FindMailboxesIfNecessary() (subject that it is what causing Looking for folder issue, which seems to) into a worker process so it would do its thing separately from the main process (which would only refresh Inbox and load new emails and load message content as selected by end-user)?

This way both would happen in parallel and then you refresh the folder list view every 10s or so, or when any X number of folders have been scanned, or when main process idle, or when scan has completed?

When starting TB, end-users don't really need to wait for all folder list to be fully up-to-date prior reading new emails... they should come in immediately upon startup and be readable (message content loadable from IMAP server) immediately... as soon as end-user select a message :-)
During this time the folders can keep refreshing slowly at their own pace, in parallel without hindering the main process :-)

The b in TB 81.0b3 (64-bit) means Beta :-)

I was just looking at the 80 under "Category" at the top and didn't see the exact version several comments below.

creating a new profile and copy my profile content into it did not allow me to properly test and use my profile as TB stop responding shortly after opening the first main UI (without any mail folder or message list appearing)... so inconclusive... or let say broken :-)

Not sure if this will work, but I haven't tried it.

creating a new profile and configuring my imap email account as a new account did not work either, see attached I can only access the Inbox folder (my mailbox root folder)! But none of its subfolders... which aren't populated... but I can access messages the Inbox :-)

I was thinking you would just use the existing profile with all the folders already "discovered" rather than make a new one. When I did that it worked OK with existing profile. But I understand you may not want to possibly corrupt you existing profile with unreleased code.

Anyhow, using the new profile with only Inbox working, collapse and then expand the "richard@..." account widget. This will force a folder discovery on the new profile. Then after all the folders appear (as they should, but may take a while), restart tb, select the new profile and see if the startup speed improves.

For now, I just want to see if this is contributing a lot to the slow startup. I'm not suggesting this as the ultimate solution.

(In reply to gene smith from comment #23)

Anyhow, using the new profile with only Inbox working, collapse and then expand the "richard@..." account widget. This will force a folder discovery on the new profile.

Manual collapse and then expand the "richard@..." account widget did trigger Looking for Folders and all folders started to appear.

Then after all the folders appear (as they should, but may take a while), restart tb, select the new profile and see if the startup speed improves.

Once Looking for Folders was completed, I restarted TB and selected the new profile created for the test.
I can confirm that it is now much faster as it is no longer Looking for Folders. It took me few seconds for selected message to load content in preview pane. In overall it took me about 20s from startup over all which majority of time was to wait for the main UI to appear :-)

For now, I just want to see if this is contributing a lot to the slow startup. I'm not suggesting this as the ultimate solution.

While not an ultimate solution it seems to confirm your suspicion I believe, so a possible way forward...

As suggested maybe the FindMailboxesIfNecessary() which trigger the Looking for Folders could still be run automatically at startup or upon account add but in a worker process separately from the main process? But you may have a better idea solution... this is just a thought...

Obviously the folders would still need to auto-update at startup but without hindering the overall performance...

Two potentially related issues

  • Bug 163964 - speedup imap startup by skipping folder discovery and other niceties, for many hundreds to thousands of folders
  • Bug 588952 - autosync should use new async folder opening to avoid extremely bad performance at startup or when reading messages with very big IMAP folders (like gmail All Mail)
Flags: needinfo?(gds)

Yes, the first one is relevant to this bug and was pointed out in an earlier comment. I don't think the 2nd one is relevant to this bug since it involves a lot of messages in a folder and not folder "discovery".

Flags: needinfo?(gds)
Depends on: 163964

Some tests and results available in Bug 163964 Comment 30 for reference...

Promising improvements upcoming... more details in Bug 163964 Comment 46... stay tuned!

(In reply to Richard Leger from comment #28)

Promising improvements upcoming... more details in Bug 163964 Comment 46... stay tuned!

That one is done. Did it fix this?

Flags: needinfo?(richard.leger)
Summary: IMAP "Looking for Folders..." at startup take a very long time - long delay - ~1mn from startup to read first email → IMAP "Looking for Folders..." at startup take a very long time - long delay - ~1 minute from startup to read first email

This is fixed in bug 163964 so I'm marking this bug as a duplicate of that bug.
Richard reported that the primary issue of this bug is fixed. But I'll leave his NI set and let him confirm the fix. He will have to run a Daily to 100% confirm. Not sure if this is in a beta yet.

Status: NEW → RESOLVED
Closed: 3 years ago
Resolution: --- → DUPLICATE

(In reply to gene smith from comment #30)

Not sure if this is in a beta yet.

It seems to have landed in 93.x branch according to Bug 163964 Comment 77.

I am currently testing 91.x ESR branch but shortly after automatic update would have been enabled for all languages, I'll resume working on 93.x aka beta branch to test further since the landing of the patch.

(In reply to Richard Leger from comment #31)

(In reply to gene smith from comment #30)

Not sure if this is in a beta yet.

It seems to have landed in 93.x branch according to Bug 163964 Comment 77.

I am currently testing 91.x ESR branch but shortly after automatic update would have been enabled for all languages, I'll resume working on 93.x aka beta branch to test further since the landing of the patch.

As tested in TB 93.0b5 (64-bit), I can now quickly access emails upon TB startup... while working with on online IMAP account (no downloaded messages). Looking for folders does no longer prevent downloading of email content when one is selected in the Inbox folder list.

Flags: needinfo?(richard.leger)

Glad that's working OK for you now!

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: