536447 - Compact folder triggers the process of fetching a lot of data from the imap mail server (related to Mark as Deleted?)

Status: RESOLVED WORKSFORME

(MailNews Core :: Backend, defect)

Description

[Brett Leber]

User-Agent:       Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US) AppleWebKit/532.0 (KHTML, like Gecko) Chrome/3.0.195.38 Safari/532.0
Build Identifier: Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.1.5) Gecko/20091216 Shredder/3.0.1pre

Compaction appears to trigger a process of fetching a lot of information from the server. Thunderbird 2 did not do this: clicking compact for the Inbox just expunged the marked-as-deleted messages, it didn't do this long process with the server.

Reproducible: Always

Steps to Reproduce:
1. Mark some messages as deleted for an IMAP account.
2. Click "Compact" button or right-click Inbox and choose compact.
Actual Results:  
Compaction occurs and communication with the server goes on while Thunderbird retrieves something like information on each message (not sure it does this, but the wait time is proportional to the number of the messages in the folder).

Expected Results:  
Compaction occurs and communication with the server stops shortly thereafter.

See attachment of IMAP log to bug 509748:
https://bugzilla.mozilla.org/attachment.cgi?id=395331

Comment 1

[Wayne Mery (:wsmwk)]

Dan is seeing this (I don't). Dan uses "mark as deleted model" (I don't). We use the same server.  This is not a folder size problem - Dan's inbox is only 200MB. Dan:

1. deleted 2 messages
2. compact
3. in activity mgr we see "Bringing folder Inbox up to date"

results:
* gloda goes crazy indexing
* folder size on disk doubles 

server capabilities
 * OK [CAPABILITY IMAP4REV1 I18NLEVEL=1 LITERAL+ SASL-IR LOGIN-REFERRALS AUTH=PLAIN AUTH=LOGIN] rain Panda IMAP 

Xref
 Bug 532403 -  IMAP 4 messages retrieved every time compacting is done
 Bug 476516 -  IMAP repeated re-download of entire Inbox headers

Comment 2

[Wayne Mery (:wsmwk)]

xref also gerv's  Bug 444343 -  "Compact Folders" corrupts indexes; regular index rebuild needed

gerv also was using "mark as deleted"

Comment 3

[Dan Schwartz]

I'm running TB 3.0.1 (Mozilla/5.0 (Windows; U; Windows NT 6.1; en-US; rv:1.9.1.7) Gecko/20100111 Thunderbird/3.0.1)

Comment 4

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #1)
> Dan uses "mark as deleted model" (I don't).
> This is not a folder size problem - Dan's inbox is only 200MB. Dan:
>(snip)
> results:
>(snip)
> * gloda goes crazy indexing
> * folder size on disk doubles 

Even if mail folder size is less than offlin-store size limit, offline-store file size can exceeds size limit, and once offline-store size exceeds the limit, re-download can happen. Read bug 537498, and check size of offline-store file size, please.

Once something wrong is generated in .msf and/or offline-store, it'll not be cleared by compact usually. Please start from clean status by Rebuild-Index.

Comment 5

[Wayne Mery (:wsmwk)]

wada san, you're quite right, the folder size was less than the file size - folder size was ~280MB, file size ~1.5GB iirc (Dan may have a better memory). Don't know if inbox file (or folder) ever exceeded 4gb.

However, before posting comment 2 we *deleted* the inbox file with thunderbird shut down. Dan, had we also deleted inbox.msf?   

wada, what would happen if we deleted Inbox but not .msf file?

Comment 6

[WADA:World Anti-bad-Duping Agency]

(In reply to comment #5)
> wada, what would happen if we deleted Inbox but not .msf file?

I dont't know what happens if something wrong exists in .msf.
But I generated next phenomenon by manual corruption of .msf during test for thread pane column change.
1. Change column selection of a blank local mail folder,
   copy some mails to the local mail folder. 
2. Close the mail folder, reduce entry size for column using text editor. 
>  ={"threadCol":{"visible":false},"attachmentCol":{"visible":true},"flaggedCo\
=> ={"threadCol":{"visible":true},"attachmentCol":{"visible":true},"flaggedCo\
(if a column is changed false to true, change of another column from true to false is required to keep the entry length, in order to keep offset value in other entries)
3. Re-open the mail folder
   => All mail is lost, due to manual offset value corruption. 
   => Compact can't recover lost mails. Rebuild-Index was needed to recover.

Comment 7

[Brett Leber]

FWIW, I see a large number of nstmp-* files in my profile as a result of compacting. These exist in profile\ImapMail\[server-host], and are created regularly even if the compact process appears to finish without interruption.

In the past the stats were:

profile\ImapMail\imap.server\
18GB of 184 nstmp files

profile\ImapMail\imap.server\Inbox.sbd
4GB of 29 nstmp files 

I cleaned up recently (01/27/2010), and these are the stats:

profile\ImapMail\imap.server\
1.34GB of 13 nstmp files

profile\ImapMail\imap.server\Inbox.sbd
1GB of 5 nstmp files

Comment 8

[Wayne Mery (:wsmwk)]

Brett, do you see this in version 3.1?  If you do, we can try to move this along.

Comment 9

[Brett Leber]

Wayne: the original issue? Yes, definitely. The progress bar works it's way up after compacting. The profile folder size doesn't change much if at all, at least in a quick test of a single compacting.

The proliferation of nstmp files? Not really, no, but I've been using 3.1 and 3.2 (trunk) and I may have cleared the files out a few months ago.

Comment 10

[Wayne Mery (:wsmwk)]

Bug 218075 also covers performance issue for mark as deleted model.
But, did the issue just get worse in version 3?

Comment 11

[Brett Leber]

I believe the issue got worse in version 3. It still exists in version 5, but I'm actually running on the nightly update channel so I have 8.0a. I'm basing this mostly on the progress/status bar and not on the logs as I don't have logs from version 2. I suppose I could create v2 logs with relatively little work if that would be helpful.

I just did a compact on my inbox and it immediately compacted but then the progress bar at the bottom took ~11 seconds to fill up. There are 1175 messages in my inbox, I had marked 1 as deleted, and the IMAP server is here at CMU where I am. I also ran a compact on a folder with 10,452 messages, same server, marked 1 as deleted, and the status bar took ~40 seconds to fill up, so it seems related to the size of the folder, not the number of messages marked as deleted.

Comment 12

[Wayne Mery (:wsmwk)]

Gerv, were you also using mark as deleted in the v2 to v3 transition?  And if so, did you experience the performance hit Brett describes?

bienvenu, 
Any theory of what performance hit entered in version 3, right, that might account for Brett seeing anything worse than just bug 218075? And would it still manifest itself?

Comment 13

[Gervase Markham [:gerv]]

wsmwk: I'm afraid I can't remember if I was using Mark as Deleted then, or whether I saw a performance hit. v3 was a long time ago!

Gerv

Comment 14

[Wayne Mery (:wsmwk)]

(In reply to Gervase Markham [:gerv] from comment #13)
> wsmwk: I'm afraid I can't remember if I was using Mark as Deleted then, or
> whether I saw a performance hit. v3 was a long time ago!
> 
> Gerv

Ah, let me clarify then. You said in bug 444343 you *were* using MAD. But I fully understand if you don't remember v3.0.

Comment 15

[Gervase Markham [:gerv]]

wsmwk: if I said it, and the timeframes match, then I guess I was :-)

Gerv

Comment 16

[Wayne Mery (:wsmwk)]

(Dan no longer uses Thunderbird)

Brett, are you still using Thunderbird?

Comment 17

[rsx11m]

(In reply to Brett Leber from comment #11)
> I just did a compact on my inbox and it immediately compacted but then the
> progress bar at the bottom took ~11 seconds to fill up. There are 1175
> messages in my inbox, I had marked 1 as deleted, and the IMAP server is here
> at CMU where I am. I also ran a compact on a folder with 10,452 messages,
> same server, marked 1 as deleted, and the status bar took ~40 seconds to
> fill up, so it seems related to the size of the folder, not the number of
> messages marked as deleted.

Are you sure that this is actual communication with the server? I'm using IMAP from different locations, some of them are synchronized and others are not. I'm using the mark-as-deleted model.

Where I don't have synchronization enabled, compacting the folder is instantaneous; when synchronization is enabled, I see what you see, the messages disappearing and the status bar showing activity for several seconds after that. However, this is related to local activity on the disk, compacting the synchronized copy of the folder held locally, and shouldn't be different from compacting a local folder. Since the full folder is copied during compacting, with the deleted messages removed, then replacing the original (uncompacted) folder, it is linearly dependent on the size of the folder.

Comment 18

[Brett Leber]

I'm still using Thunderbird. Comments below.

(In reply to rsx11m from comment #17)
> (In reply to Brett Leber from comment #11)
> > I just did a compact on my inbox and it immediately compacted but then the
> > progress bar at the bottom took ~11 seconds to fill up. There are 1175
> > messages in my inbox, I had marked 1 as deleted, and the IMAP server is here
> > at CMU where I am. I also ran a compact on a folder with 10,452 messages,
> > same server, marked 1 as deleted, and the status bar took ~40 seconds to
> > fill up, so it seems related to the size of the folder, not the number of
> > messages marked as deleted.
> 
> Are you sure that this is actual communication with the server? I'm using
> IMAP from different locations, some of them are synchronized and others are
> not. I'm using the mark-as-deleted model.

No, I'm not sure that this is actual communication with the server. Maybe that was a bad assumption on my part. Does the protocol log linked above not identify whether the server is being contacted? Is it worth confirming that server communication is not going on?

> Where I don't have synchronization enabled, compacting the folder is
> instantaneous; when synchronization is enabled, I see what you see, the
> messages disappearing and the status bar showing activity for several
> seconds after that. However, this is related to local activity on the disk,
> compacting the synchronized copy of the folder held locally, and shouldn't
> be different from compacting a local folder. Since the full folder is copied
> during compacting, with the deleted messages removed, then replacing the
> original (uncompacted) folder, it is linearly dependent on the size of the
> folder.

I can confirm that compacting a large local folder also takes a similarly noticeable amount of time (although subsequent compacting appears to be much faster, both locally and with IMAP). My IMAP inbox and all folders are indeed synchronized.

So if it's not actual communication with the server, is this still a performance regression? Comparisons with Thunderbird 2 (c. 2007), in which compacting was very fast, don't seem to be valid at this point. Maybe so much has changed (better indexing, search) that it's not even a valid comparison. A user can turn off synchronization on a folder, although knowing that that's related to compacting speed is not obvious, and turning it off affects what is indexed for search, right?

Comment 19

[Wayne Mery (:wsmwk)]

duplicate of bug 218075?

Comment 20

[Wayne Mery (:wsmwk)]

(In reply to Wayne Mery (:wsmwk) from comment #19)
> duplicate of bug 218075?

hmm, if this bug is a regression, it couldn't be a pure duplicate of bug 218075 because of the age of 218075

Comment 21

[Wayne Mery (:wsmwk)]

(In reply to rsx11m from comment #17)
> Where I don't have synchronization enabled, compacting the folder is
> instantaneous; when synchronization is enabled, I see what you see, the
> messages disappearing and the status bar showing activity for several
> seconds after that. However, this is related to local activity on the disk,
> compacting the synchronized copy of the folder held locally, and shouldn't
> be different from compacting a local folder. Since the full folder is copied
> during compacting, with the deleted messages removed, then replacing the
> original (uncompacted) folder, it is linearly dependent on the size of the
> folder.

Is this reproducible on trunk?

Comment 22

[rsx11m]

Using a current release build, I still see the progress bar moving for a while when compacting the synchronized local copies. I don't think this can be changed without changing the compaction code to not create a copy of the folder during compacting (and even then a substantial amount of data would need to be rewritten if an early message was deleted and the rest needs to move up). This issue may be resolved with switching to the maildir backend, I don't know.

As for the IMAP log, there is an individual server response for each message expunged after the "mark as deleted" model was applied (which is what bug 218075 is about). For example, deleting three messages with position x/y/z, then expunging them results in the following log:

> SendData: nnn expunge
> CreateNewLineFromSocket: * x EXPUNGE
> CreateNewLineFromSocket: * y-1 EXPUNGE (offset by 1 after expunging x?)
> CreateNewLineFromSocket: * z-2 EXPUNGE (offset by 2 after expunging x and y?)
> CreateNewLineFromSocket: * www EXISTS  (last selected message?)
> CreateNewLineFromSocket: * 0 RECENT
> CreateNewLineFromSocket: nnn OK Expunged 3 messages

The next operation indicated in the log is checking the quota and then fetching message www, but I don't see any of the extensive communication shown in bug 509748 attachment 395331 [details]. That log essentially shows the same activity as observed by me during the expunge operation, but then the IMAP connection is closed and reopened from scratch. So, this may be a different issue, where the communication following the reset of the connection looks normal to me (and indeed, it's checking for each message whether or not its status has been changed, thus if any updates are needed for a specific message, that's normal behavior as well).

Thus, the only question here is why the connection is broken and needs to be reestablished after an expunge has taken place (and a corruption like bug 444343 would certainly trigger that, but didn't happen for me).

BTW: I'm not using Gloda, in case it contributes to this issue in some way.

Comment 23

[Wayne Mery (:wsmwk)]

On 2009-10-07 on trunk, for version 3.0, bug 519801 "fixed" something in this area. Perhaps it also broke something, or didn't completely fix it?

Curiously, bug 519801 isn't marked as a regression. But it's duplicate bug 510330 states the issue is a regression. On 2009-08-13 Magnus says "it happen in the last two weeks".

Comment 24

[Wayne Mery (:wsmwk)]

If this happens on compact it potentially affects large % of users, so > critical

Comment 25

[gene smith]

Sniffing with wireshark, I only see the imap expunge happen when I "compact" a folder. But I'll watch for this.

Comment 26

[Wayne Mery (:wsmwk)]

So, we have the origins in bug 218075. Keeping this bug open because it has so much information.

And bug 1697116 is likely a current example.