321277 - Compact takes a long time - Thunderbird flushes to disk way too much, causing slow performance with pop folders

Status: RESOLVED WORKSFORME

(MailNews Core :: Database, defect)

Description

[Phillip Susi]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.0; en-US; rv:1.8) Gecko/20051111 Firefox/1.5
Build Identifier: Thunderbird version 1.5 (20051201)

It seems to me that thunderbird is allways flushing writes to the disk, which slows things down.  While downloading email, I allways hear my hard disk thrashing about from all the seeking, and as a result, downloading email seems slower than it should be. 

Also I just decided to compact my mail folders.  This process took a good 10 minutes, using virtually zero cpu the whole time.  This is utterly rediculous.  I have a gig of ram which is plenty to cache all the mail boxes entirely in ram, so the process of compacting them should be cpu bound while the messages are just moved around in ram, and the changed data flushed to disk in the background by the kernel after the compact completes.  The compact itself should only take a few seconds, not 10 minutes.  

I have about a dozen different mail folders ( one for each mailing list ) that are an average of 50 MB in size.  Thunderbird fetches the mail from a pop3 server.  

I also use thunderbird in Linux, and I believe it has the same problem.  


Reproducible: Always

Comment 1

[Tom Meyer]

I also see this on XP.  It brings my entire system to a halt about once every 8 seconds and lasts for  about 4 seconds. As you can imagine loosing 50% of your CPU time can get really anoying.

[e-mail]

Comment 2

[Wayne Mery (:wsmwk)]

what is your total memory listed for physical and commit in windows task manager?
and what logging (junk, filter) do you have turned on?

Comment 3

[Phillip Susi]

I just tried this again now using thunderbird 2.0.0.9 on a newer machine than I had when I initially filed this report.  I extracted an old archive mailbox that is about 85 MB in size and consisting of a bit over 15,000 messages.  I randomly deleted a few messages scattered around the mailbox and noted a disk flush after each delete operation, which should not occur.  I then verified that the mbox file was entirely cached in ram by copying it to NUL, which took place instantly.  Task manager shows I have 222 free and 160 MB in the system cache out of 512 mb of physical ram, with 385 mb out of 1.2 gb max commit charge.  I initiated a compact of the mailbox and this took almost exactly 3 full minutes during which time there was almost zero cpu activity.  I have not enabled any logging, or are any filters running, only a compact operation.

Comment 4

[Wayne Mery (:wsmwk)]

couple issues

1. A commit charge of 1.2GB suggests you have been severely low on memory at least once. And perhaps your page file is heavily fragmented.  defragging your disk and deleting your page file, so you can start with a new contiguous page file, might help a little.
2. Is this strictly a local folder and not a global inbox for any pop accounts?
3. I'm not sure the performance you see is unusual - almost 60 seconds for me to compact a 22MB current problem using version 2.0.0.6 (20070728) - and that's with write-through cache enabled on the disk, so I'd have to guess the performance hit is on reading of the file, not to writing.

do any of these old fixed bugs offer any insight?
bug 73833  compact local folders is deadly slow
bug 182263 Slow compact of mail folder, high HDD activity
bug 197405 Compacting folders in 1.3 takes longer than with 1.1 

Comment 5

[Phillip Susi]

1) I said the commit LIMIT was 1.2 GB, the charge was only 385, so memory pressure was not very great, and there is no indication that my page file is fragmented.

2) This is a strictly local folder.  I just extracted the mbox file to the thunderbird profile mail directory, made the .sbd directory of the same name as the file, and fired up thunderbird which recognized the mailbox and built its index the first time I opened it.

3) The performance hit isn't due to reading the file because as I said before, the entire file was cached in ram, as evidenced by the instant copy to NUL time.  Also you appear to be confirming the problem - a 22 mb mailbox should not take anywhere near 60 seconds to compact on a modern pc.  Theoretically it should take 1 second ( or less with modern disk speeds and assuming the mailbox file is not fragmented ) to read the file in, less than a second to compact it in ram, and 1 second to write it all back out.

With the file cached in ram, a compact operation should boil down to a series of memmove()s possibly followed by one large flush.  That should be a cpu bound operation for the first part, followed by a large disk write.  Given the time involved in this test it is clear that there are a great number of individual small flushes going on during the compact, resulting in a massive seek storm.

Comment 6

[Wayne Mery (:wsmwk)]

Agree, it seems slow.  Can you create some tests to determine if the time to compact is linear to # messages or message size?

Comment 7

[Roger Salmon]

I had this problem -- or something very like it -- some months ago and then it got fixed in TB 2.0

I have just switched to Gecko/20090203 Shredder/3.0b2pre and the problem is back.  The computer (Vista Home Premium SP1)churns away for an extended period. Problem may have been aggravated by a very low default in Shredder for compacting mailboxes (if it would save 1kb) but I have changed this to 2000kb and the problems persists.

Comment 8

[Wayne Mery (:wsmwk)]

Roger, did you enable vista integrated search when you installed 3.0b2pre?
I think indicated by pref mail.winsearch.enable = true

hmm, no response to comment 6

Comment 9

[Roger Salmon]

Wayne: I had mail.winsearch.enable = true, though I did not set it manually and I have no sense of which application may have changed it.  I have now reset it to the default.

The problems with TB on my machine may also have been due to interactions with Vipre (anti-virus and anti-malware), which sometimes does not play well with TB and can occupy up to 100% of CPU for extended periods.  This seems to have been sorted with the latest versions of Vipre.  But then TB has updated itself to 2.0.0.19 so currently I am not using Shredder.  Is there an easy way to stop this kind of updating -- I already set TB to "ask me what I want to do" in tools>options>update.

Comment 10

[Wayne Mery (:wsmwk)]

(In reply to comment #9)
> Wayne: I had mail.winsearch.enable = true, though I did not set it manually and
> I have no sense of which application may have changed it.  I have now reset it
> to the default.

after you installed shredder, the first startup would have prompted you about indexing, and set mail.winsearch.enable accordingly.  But this setting has no effect when you are running 2.x

 
> The problems with TB on my machine may also have been due to interactions with
> Vipre (anti-virus and anti-malware), which sometimes does not play well with TB
> and can occupy up to 100% of CPU for extended periods.  This seems to have been
> sorted with the latest versions of Vipre.  But then TB has updated itself to
> 2.0.0.19 so currently I am not using Shredder.  Is there an easy way to stop
> this kind of updating -- I already set TB to "ask me what I want to do" in
> tools>options>update.

Why would you want to turn off update? Because Vipre doesn't detect the update?

Comment 11

[Roger Salmon]

Thanks Wayne.

All my comment meant was that I would prefer TB not to "update" from 3.0.x to 2.0.0.y.  I agree that automatic updating is good news, except at least for the way extensions then get temporarily disabled.

Comment 12

[Wayne Mery (:wsmwk)]

Tom Meyer wrote he no longer sees the problem using Thunderbird 2.0.0.14 (Windows/20080421)

so we are left with  Phillip Susi's issue.  Again, it would be useful for  Phillip to quantify some examples per comment 6.  And, if you can do it with a beta release that would be much better. 
 http://www.mozillamessaging.com/en-US/thunderbird/early_releases/

Comment 13

[WADA:World Anti-bad-Duping Agency]

To Phillip Susi(bug opener):

"Compact folder" is roughly (1) mail folder file copy + (2) rebuild index.

(Q1) How long does "copy of all mails to other mail folder" take?
It's roughly same operation as "copy to nstmp" in "compact folder".
1. To avoid issues due to non-opened .msf, click(==open) copy target folder
   at folder pane before start of copy.
2. To avoid delay by view refresh, don't open copy target folder at other window.
3. Open copy source folder, select all, then copy to target folder
(Q1) How long does "rebuild-index" take?
(Q3) Which process does take long in your "compact folder"?
     (delete a mail of largest "Order Receievd" column value, )
     (then copy back the mail => Tb have to copy all mail data)
    (1) Copy to new mail folder file (copied to file named "nstmp")
    (2) msf creation(nearly equals to rebuild-index)
        Check time from "end of file size increase of nstmp"
        to "compact completion"(nstmp.msf/nstmp is deleted).
    How longer is the time for (1) than "copy of file by Windows Explorer"?

There are already known issues due to "long/deep mail thread".
  (a) Bug 452221 : It takes long to update .msf after mail delete
  (b) Rebuild Index takes long
  (c) Change to View/Thread takes long
Please confirm that problem like (b) is irrelevant to your problem.

(In reply to comment #0)
> so the process of compacting them should be cpu bound while the messages are just moved around in ram,
> and the changed data flushed to disk in the background by the kernel after the compact completes.
> The compact itself should only take a few seconds, not 10 minutes.  
(In reply to comment #5)
> With the file cached in ram, a compact operation should boil down to a series of memmove()s possibly followed by one large flush.

Wrong guess or wrong conclusion, isn't it?
  Tb's file related action in "compact folder" are roughly:
  (1) Copy of data for other than deleted-but-not-removed-yet-mail to nstmp.
      This is done by "write requests of buffer data to a new file".
  (2) Replace of old mail folder file by nstmp.
  (3) Rewrite or replace of .msf file.
MS Window always/forever(forever for started Tb) holds whole written file data in real memory and MS Window always doesn't issue "disk flush" untile file close by application?

AFAIK, Tb uses relatively large buffer in "copy of non-deleted(active) mail data to nstmp", and file open/close(write mode) of nstmp is done only once for writing data to nstmp. "All written file data is cached in real memory until close of file, or not" depends on OS.
Did you really see "many disk flush by Tb himself instead of OS"?
Did Tb(not OS) really request "disk flush" after each(or some) write request(s) of buffer?
(If my memory is not corrupted, Tb has logic to request disk flush during multiple mail data manipulation...)
If yes, is it main/root cause of your "compact folder takes long" problem?

By the way, please separate (a) "seek upon download" and (b) "flush upon a few message delete" from main "compact folder" of this bug.
  (a) relates to disk fragmentation. (b) relates to auto-compact.

Comment 14

[Phillip Susi]

I have tested the new Thunderbird 3 beta 2 build and the issue seems to be resolved.  I pulled out the 100 meg mailbox I used last time and deleted a dozen or so messages from random locations within it and then ran a compact and it took less than 10 seconds.

Comment 15

[[:Aureliano Buendía]]

Close as Workforme per comment #14 (it works on TB 3.x)

Feel free to reopen it if I'm wrong.

Comment 16

[Wayne Mery (:wsmwk)]

Phillip Susi, 

Sorry to ask another question but I'd like to try to understand why your problem went away. I can't think of any patches that would have improved compact speed between comment 14 2009-07-08 and 2008-01-23 comment 5. And comment 3, 3 minutes for an 85MB folder, really make no sense even if you were on a heavily loaded slowish laptop.

Were you running any antivirus software?
Can you think of anything else that may have changed between comment 14 2009-07-08 and 2008-01-23 comment 5?

Comment 17

[Phillip Susi]

No antivirus software or other activity, and it was a desktop, though not with a particularly fast hard disk.  The 3 minutes was indeed far longer than it should have taken, which is why I filed the bug.  As I said before, I could verify with disk IO traces that thunderbird was issuing many flush requests, and this would cause the long delay.