384360 - Message move blocks whole app, due to long re-sync time (move to not-opened, non-threaded large IMAP folder)

Status: NEW

(MailNews Core :: Backend, defect)

Description

[Ben Bucksch (:BenB)]

Reproduction:
1. Have a folder with 100000 emails
2. Move a message from any other folder into that folder
3. Watch CPU usage, and move your mouse over the toolbar buttons
4. If you have a composer folder open, try to type there

Actual result:
- CPU is used 100% for 5 seconds
- The Thunderbird UI does not react at all, button hover does not work,
  nothing.
- It is impossible to type in to the Composer to write a new mail

Expected result:
- The request to move the mail is accepted, and will be performed, but the application is immediately ready to take more commands (e.g. move more mails, open a new composer etc.) from the user.

Impact:
Highly noticable during daily usage, in the following case:
I get lots of spam. I use Thunderbird's spam filter to get them out of the way, but save them in case some ham gets wrongly marked, which does happen, so they get moved into another folder. That folder quickly (within 3-5 months) grows to over 100000 mails.
I have Thunderbird check mail every minute.
I write a lot of emails.
It means that once every minute, in the middle of me typing into the composer, Thunderbird suddenly stops accepting my keypressed, does nothing whatsoever, no reaction anymore. For 10 seconds. I have to stop and wait until it's done so that I can continue working. Disruptive. Every minute. Very annoying.

Implementation:
The obvious solution for me would be to use threads.
Whatever solution (threads or something else) is chosen, obviously it must make sure that the folders never get corrupted, even if I move several mails, once after each other, before first mail move completed.

Comment 1

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #0)
> Reproduction:
> 1. Have a folder with 100000 emails
> 2. Move a message from any other folder into that folder
(snip)
> Actual result:
> - CPU is used 100% for 5 seconds
> - The Thunderbird UI does not react at all, button hover does not work,
>   nothing.

It sounds for me "auto compaction" or "internal rebuild index", because when simply move a mail.
Try next first to see how long will it takes for "compact folder" and "rebuild index" when your "100000 mails" mail folder.
  0. Keep back up of Tb's profile directory(at least mail directory).
  1. Restart Thunderbird.
  2. Property/Rebuild Index" of the folder => How long does it take?
     (Mail count in folder pain probably becomes twice by bug.)
     ("Click other folder then click folder again" will correct count display) 
  3. Move a mail to other folder, then move back the mail again.
     "Compact Folder" => How long does it take?

> I get lots of spam. I use Thunderbird's spam filter to get them out of the way,
> but save them in case some ham gets wrongly marked, which does happen, so they get moved into another folder. 
> That folder quickly (within 3-5 months) grows to over 100000 mails.

Because "Unix Mbox" is used, too big mail folder(total mail size) causes problem when whole mail folder file process is required due to some reason or failure.
"folder splitting & virtual(search) folder" can be used to keep a big mail folder static from Tb 1.5.
Move all mails to a folder yyyy-mm every month or every two or three months, and add yyyy-mm to search target of search folder, then compact folder.
Please note that this is usable to avoid "file size limit(4GB currently)" and it is one of developer's objective of "Virtual Folder".
(Don't use special characters, at least "/", for search folder name. Otherwise,) (you'll meet bug such as Bug 286523. See dependency tree for meta Bug 124287.  )  

Comment 2

[Ben Bucksch (:BenB)]

I/O should not happen on main thread (or: ever block UI).

Comment 3

[WADA:World Anti-bad-Duping Agency]

Are you talking phenomenon of short delay in next operation?
 1. Open compose window
 2. Move a mail from large folder to large folder at mail window
 3. Try to return to compose window (click at task bar when MS Win)
I felt "sort delay" was around 1 second in my environment and my test mail folder (80000 mails).
If this is true, it possibly a result of "folder reopen after move" instead of "I/O".
When "folder reopen after move", refresh of folder pane and thread pane is also executed, and it takes longer when large mail folder than small mail folder.

Comment 4

[WADA:World Anti-bad-Duping Agency]

> "CPU 100% of 5 second"
How long will it take when step-2 of next operations?
 1. Restart Tb. 2. Click the large mail folder (first open after restart)

Comment 5

[Ben Bucksch (:BenB)]

Thanks for the tips, they were helpful.
Inbox: 5000 msgs
Spam folder: 300000 msgs
Computer: Athlon 3500+, 2 GB fast RAM

1. Restart Thunderbird.
2. Move mail from Inbox to spam folder.
   Takes 7-8 seconds on 100% CPU, blocked UI.
3. Repeat several times. Takes 7-8 seconds every time.
4. Click on spam folder (to open in threadpane).
   Takes 7-8 seconds on 100% CPU, blocked UI.
   Then, the threadpane shows messages from the spam folder
   Then, another 3-4 seconds 100% CPU, I think downloading
   a few (24) new headers.
5. Go back to Inbox (Click on Inbox for it to show in threadpane)
6. Move mail from Inbox to spam folder.
   Takes 1-2 seconds on 100% CPU.
3. Repeat several times. Takes 1-2 seconds every time.

Comment 6

[Ben Bucksch (:BenB)]

Note that even the 1.2 seconds are too much, anything more than 20ms is, but I think it gives a hint at where at least one part of the problem is.
Seems like Thunderbird "opens" the folder every time a message is moved, but caches something when I open it in UI

Comment 7

[WADA:World Anti-bad-Duping Agency]

FYI.
Bug 347837 is for phenomeon of db re-open when folder re-open, because of delayed-db-close as a result of "null out the cached db pointer in the folder".

Comment 8

[Ben Bucksch (:BenB)]

Problem is gone now for me, interesting. Marking as Junk and moving to the junk folder is now takes only 1s.

Somehow, my local folder header cache (folder is IMAP) for the spam folder was gone - when I clicked on the folder, all 320000 headers had to be downloaded. Afterwards, move msg was still fast, but when I restarted Thunderbird, it was slow again.

So, the problem is gone when Mozilla had no data in the folder and thus does not try to update it. Consequently, that could also be a fix for this bug: If the folder had not been opened in this session and a msg is moved there, do *not* open it, but treat it as if you had never opened it and as if you had no local header cache. There should be no cache consistency/update problem, because mails can be moved to a folder at any time from any client or server.

Comment 9

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #8)
> when I clicked on the folder, all 320000 headers had to be downloaded.

Oh IMAP, and 320,000 mails in a folder, 3 x (over 100,000).

> Somehow ... (snip) when I clicked on the folder, all 320000 headers had to be downloaded.
> Afterwards, move msg was still fast, but when I restarted Thunderbird, it was slow again.

Is "it was slow again" also applicable to IMAP mail folder of 320,000 mails which you opened manually by clicking the folder, after restart of Thunderbird?

Comment 10

[Ben Bucksch (:BenB)]

"over 100,000" for me includes in some cases over 1 million.

No, as established before, when I click on the folder, it's mostly OK afterwards (not good, but down from 10s to 1-2s).
What I found out was that it's *also* OK when the .msf file for that folder is gone/not there and I don't click on the folder.
So, workaround: delete the .msf file of that folder and never click on it.
(Or click on it after every restart, but that's worse, for user time and RAM.)

Comment 11

[Ben Bucksch (:BenB)]

> "over 100,000" for me includes in some cases over 1 million.

(All test above have been made with my "Spam 10" folder with about 300,000 mails, though, see comment 5)

Comment 12

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #10)
> "over 100,000" for me includes in some cases over 1 million.
It's always true for every body : Finite "grater than one" < ∞(=+Infinity) ;-)
> No.
I see. (It's answer I expected)

I don't know well about IMAP, but IMAP has at least "mechanism of re-synchronization", which may take long when 320,000 mails, and it may occur when folder open. "When re-synchronization is executed" possibly depends on option of "offline use" (not "offline mode"). Can you check difference between "move to not-opened non-offline-use folder" and "move to not-opened offline-use folder? (See 385502. David is trying to change "offline use" to default.)
I think checking of IMAP protocol log is first step of analysis.
  http://kb.mozillazine.org/Session_logging_for_mail/news
  http://www.mozilla.org/quality/mailnews/mail-troubleshoot.html#imap
Because elapsed time of an operation(move a mail) is to be measured, log with time stamp will be helpful in analysis. IMAP protocol log(NSPR log,"imap:5") with time stamp can be easily obtained if MS Win. See Bug 86396 Comment #7, if you use MS Win.

 

Comment 13

[Ben Bucksch (:BenB)]

"offline use" (= download and store all bodies locally) is of course not checked for my spam folders, and should not be checked.
I think we already have a way to fix this bug which is IMHO the right approach and may fix other problems as well: When moving a mail, and the target folder has not been "open"ed (manually), do *not* "open" the folder (temporarily), but treat it as if you never downloaded any headers for it. Don't try to sync local data in that case.

Comment 15

[WADA:World Anti-bad-Duping Agency]

FYI.
You can see David's explanation about current behavior when IMAP in Bug 358595 Comment #10. 

Comment 16

[WADA:World Anti-bad-Duping Agency]

To Ben Bucksch:
Can you increase number of cached connection? Will it change situation?
I also think following can be a solution.
 - When move/copy of some mails in manually opened IMAP folder to not-opened
   IMAP folder, append only, no re-sync.
But isn't it dangerous? No bad affect on other simultaneous access?

Comment 17

[WADA:World Anti-bad-Duping Agency]

Adding IMAP & re-sync in summary for ease of search.

Comment 18

[Wayne Mery (:wsmwk)]

(In reply to comment #16)
> To Ben Bucksch:
> Can you increase number of cached connection? Will it change situation?

Ben, was that of any help?

Comment 19

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #8)
> If the folder had not been opened in this session and a msg is moved there,
> do *not* open it

As seen in IMAP log of Bug 402468 Comment #1, "move of mail to other folder of same account" consists of;
 1. FETCH (from original folder)
 2. COPY  (to target folder)
 3. Flag as \Deleted (mail in original folder), and EXPUNGE if required
It indicates that there is no need to re-synchronize move target folder if the target folder is not opened yet, as you say, at least when the target folder is owned by same account.

Comment 20

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #8)
> If the folder had not been opened in this session and a msg is moved there,
> do *not* open it

"do *not* open" is not easily applicable when fall back to FECTH/APPEND is required because COPY is not usable.
See Bug 403101. In this case, I think "internal mail DB open" is required to APPEND , even when copy/move target folder is on same IMAP server. Isolation of "(internal) mail DB open" and "re-synchronization of IMAP mail folder" will be required for universal/general solution of this bug.
What do you think?

Comment 21

[Wayne Mery (:wsmwk)]

Ben, iirc you no longer have the same big folder.  But do you have a sense of whether this is still happening for you in TB 3 nightlies?  
STM this is more about just opening the db, and not related to bug 347665 nor bug 347837.

Comment 22

[Wayne Mery (:wsmwk)]

bienvenu, is there a potential strategy for this issue?

(xref, but I assume of no use in this case, is Bug 588952 - autosync should use new async folder)

Comment 23

[David :Bienvenu]

I believe there are two issues here - see bug 693659 comment 4 - I think those issues are much more relevant to the hang than the ones discussed in this bug.

Comment 24

[Wayne Mery (:wsmwk)]

(In reply to David :Bienvenu from comment #23)
> I believe there are two issues here - see bug 693659 comment 4 - I think those
> issues are much more relevant to the hang than the ones discussed in this bug.

"bug 538378 is the biggest issue; bug 644333 is the other main issue."

both of these are now fixed. So perhaps Ben's issue is fixed?

Comment 25

[Ben Bucksch (:BenB)]

I just tested again. The bug is still there.

1. When I select 15000 emails, it takes 5-10 seconds until they are selected (blue), during which TB UI is frozen.
2. When I try to drag them, the UI freezes again (in the middle of the drag action, while I hold the mouse button !) for 45 seconds. The "stop script" dialog appears several times. Luckily, I can release the mouse button and the drag action still continues.
3. When move the emails on another folder, the UI freezes again for several minutes (!).

That's with just 15000 emails. I have folders with >100000 emails.

Comment 26

[WADA:World Anti-bad-Duping Agency]

(In reply to Ben Bucksch (:BenB) from comment #25)
> I just tested again. The bug is still there.

"Selection of mails" and "Dragging multiple mails" were involved in your operation.

> 1. When I select 15000 emails, it takes 5-10 seconds until they are selected
> (blue), during which TB UI is frozen.

After "summary view", "multiple mails selection" takes longer. See bug 778907.
Do you see severe delay with following?
  mail.operate_on_msgs_in_collapsed_threads = false 

> 2. When I try to drag them, the UI freezes again (in the middle of the drag
> action, while I hold the mouse button !) for 45 seconds.
> The "stop script" dialog appears several times.

When drag operation is started, DragStart event is invoked at thread pane. To support "Dra&Drop multiple mails to Desktop folder for saving mails", Tb tries to generate file name of "part of subject" + "suffix of -NN if same part of subject" for each mail. In this prcess, duplication check/uniqueness check of geerated files is O(n^2) process instead of O(n+*log[n]) or O(n).
This is bug 812923(FIXED in Tb 24, but it's workaround by generating one file name only)

> Luckily, I can release the mouse button and the drag action still continues.

It may depend on your mouse driver setting.

> 3. When move the emails on another folder, the UI freezes again for several
> minutes (!).
> That's with just 15000 emails. I have folders with >100000 emails.

Upon Drop event of move target folder at folder pane, "move mails" starts.
"Move mails" = "Copy mails" + "Delete mails", and performance issue in "delete mails" is known(bug 452221 and relevant bugs), and, further, your case is IMAP.
As seen in Bug 693659, "UI freeze while moving/deleting many mails" is already known issue and is pretty ordinal phenomenon in Tb, because IMAP task is currently executed under main thread for UI process.

Because of performance issue, data such as relation between "number of moved mails" and "time to move the mails" is usually needed for problem analysis.

Comment 27

[WADA:World Anti-bad-Duping Agency]

Major cause of bug 452221 is "thread data update according to removal of MsgDBHdr by mail delete". In IMAP, if iMAP and IMAP delete model of "Just mark is as deleted", "removal of MsgDBHdr" doesn't occur by "delete mails" operation.
Do you see long UI freeze with IMAP delete model of "Just mark is as deleted"?

Note:
When IMAP delete model of "Just mark is as deleted", "removal of MsgDBHdr" is executed upon EXPUNGE by "Compact this folder". Severe performance issue by "Compact this folder when many mails have \Deleted flag" is known problem and bug for it already exists.

If IMAP, performance issue exists in "Copy many mails between Mbox of same IMAP account" phase too. See bug 846123, please.

Comment 28

[Ben Bucksch (:BenB)]

> Do you see severe delay with following?
>   mail.operate_on_msgs_in_collapsed_threads = false

I'm not in threaded view. Yes, it's from and to IMAP folders, on the same server.

Wayne and WADA, thank you for your efforts, but please stop asking me questions, here and in the other bugs. It's not helpful. If you want to investigate the bug, please try it yourself. It's not hard to reproduce. If you can't, leave it alone. I'm willing to answer specific questions from developer only.

You are welcome to cross-reference closely related bugs. Thanks for that. But please keep the text and number of comments short.

It's pretty clear that TB has severe problems with any operation operating on many emails. The number of seconds *each* step in comment 25 takes alone suggests that, so there are several points in the code to fix here. It's also clear from the age of the bug that this is a long-standing problem.

Comment 29

[Wayne Mery (:wsmwk)]

(Hopefully will go away with the new backend)