1900172 - Compact doesn't show reasonable result: Done compacting (approx. 0 KB saved).

Status: RESOLVED FIXED

(MailNews Core :: General, defect)

Description

[Francesco]

As noted in bug 1898780 comment #8, compacting doesn't correctly report on the space saved. I deleted a few messages from an IMAP folder selected for offline use, then compacted. On disk, the raw messages file went from 7 MB to zero, however, the message displayed was: Done compacting (approx. 0 KB saved).

Comment 1

[Ben Campbell]

(In reply to Francesco from comment #0)

As noted in bug 1898780 comment #8, compacting doesn't correctly report on the space saved. I deleted a few messages from an IMAP folder selected for offline use, then compacted. On disk, the raw messages file went from 7 MB to zero, however, the message displayed was: Done compacting (approx. 0 KB saved).

How did you start the compaction? Did you:

• right-click on the folder and pick "Compact"
• right-click on the account and pick "Compact" (or was it "Compact All"? I think it might have changed)
• use file menu-> "Compact Folders"
• something else?

Comment 2

[Francesco]

Right-click on the folder and pick "Compact".

Comment 3

[Ben Campbell]

Thanks!

I can get the message to display, but only by right-clicking "Compact" on a folder that doesn't have any messages to expunge (ie with messages that have been deleted).
Which is what you'd expect: you start an un-needed compaction and it finishes, saying it save 0 bytes. (better still would be disabling the menu item if the folder doesn't need compacting).

I can't seem to get it to happen on a folder that does have messages to compact. I wonder if somehow the operation is being run twice?

Could I get you to trigger the bug again, but with the compaction logging active, ie with the environment var MOZ_LOG="compact:3", and see what the log output is?

For me, an actual compaction produces log output like this (after manually deleting all the messages my INBOX):

[Parent 4964: Main Thread]: I/compact AsyncCompactFolders() starting compaction of 1 folders
[Parent 4964: Main Thread]: I/compact BeginCompacting() folder='imap://bob@localhost/INBOX'
[Parent 4964: Main Thread]: I/compact OnCompactionComplete(status=0x0 oldSize=30016 newSize=0)
[Parent 4964: Main Thread]: I/compact AsyncCompactFolders() finished. TotalBytesRecovered=30016

(And I'll see "Done compacting (Approx. 30 KB saved)").

And if I compact the same folder again:

[Parent 4964: Main Thread]: I/compact AsyncCompactFolders() ignoring folder 'imap://bob@localhost/INBOX' (expungedBytes is 0)
[Parent 4964: Main Thread]: I/compact AsyncCompactFolders() starting compaction of 0 folders
[Parent 4964: Main Thread]: I/compact AsyncCompactFolders() finished. TotalBytesRecovered=0

(I'll see "Done compacting (Approx. 0 KB saved)").

Comment 4

[Francesco]

I'm using Windows. Something is wrong with the setting you suggested, nothing is logged. Just to make sure the logging setup is correct, I then used set MOZ_LOG=compact:5,IMAP:5. Surprisingly then compact also gets logged. Maybe the last buffer isn't flushed.

Here is what I do:
Have a folder "test2" which is empty, 0 KB size on disk. Move a message to it. Size on disk: 4.3 KB according to TB, 5 KB according to Windows. Delete the message. Size on disk according to TB: 0 KB, size on disk according to Windows: 5 KB. compact. Size on disk 0 KB, also according to Windows. Here's the log:

[Parent 14492: Main Thread]: I/compact AsyncCompactFolders() starting compaction of 1 folders
[Parent 14492: Main Thread]: I/compact BeginCompacting() folder='imap://[...]/INBOX/test2'
[Parent 14492: Main Thread]: V/compact OnCompactionBegin()
[Parent 14492: Main Thread]: D/compact OnRetentionQuery(storeToken='0')? => No
[Parent 14492: Main Thread]: I/compact OnCompactionComplete(status=0x0 oldSize=4448 newSize=4448)
[Parent 14492: Main Thread]: I/compact AsyncCompactFolders() finished. TotalBytesRecovered=0

Looks like newSize isn't right.

Comment 5

[Ben Campbell]

(In reply to Francesco from comment #4)

I'm using Windows. Something is wrong with the setting you suggested, nothing is logged. Just to make sure the logging setup is correct, I then used set MOZ_LOG=compact:5,IMAP:5. Surprisingly then compact also gets logged. Maybe the last buffer isn't flushed.

Hmm. That is odd... the compact log is using the same log routines as everything else. Maybe it just wasn't outputting enough data on it's own to cause a console flush under windows?

[snip]

Here's the log:

[Parent 14492: Main Thread]: I/compact AsyncCompactFolders() starting compaction of 1 folders
[Parent 14492: Main Thread]: I/compact BeginCompacting() folder='imap://[...]/INBOX/test2'
[Parent 14492: Main Thread]: V/compact OnCompactionBegin()
[Parent 14492: Main Thread]: D/compact OnRetentionQuery(storeToken='0')? => No
[Parent 14492: Main Thread]: I/compact OnCompactionComplete(status=0x0 oldSize=4448 newSize=4448)
[Parent 14492: Main Thread]: I/compact AsyncCompactFolders() finished. TotalBytesRecovered=0

Looks like newSize isn't right.

Yup. It's correctly deciding not to retain the single message in the mbox, yet the final reported file size is unchanged.

I think the compaction is working fine, just that final filesize check is borked. And I think it's a windows-only issue.

At the beginning of the compaction, I store the path for the mbox as an nsIFile object and check the filesize before and after the compaction to get those sizes.
But looking through the nsIFile.fileSize implementation for windows, it looks like the data is cached.
Since the nsIFile object has no way of knowing that the file at the path it holds has now been overwritten, it continues to use the now-incorrect cached size. Sigh.

I've got a workaround, but I don't have easy access to a windows box right now, so could I get someone to try it out?

There's a build running here which you can get binaries from:
https://treeherder.mozilla.org/jobs?repo=try-comm-central&revision=3e7236855265631d09cf1441505b777c1714a220

You can get the windows binary by clicking the "B" icon beside an appropriate job (one of the windows ones, but I'm not quite sure what they all are!), then selecting the "Artifacts and Debugging Tools" tab below to list the available files (again, I'm not quite sure which one you need!).

Wayne: Could you fill out some details on my rather vague instructions on how to get a windows build from treeherder please?

Comment 6

[Ben Campbell]

Attachment: Bug 1900172 - Workaround nsIFile.fileSize stat cache after folder compaction. r=#thunderbird-reviewers

Comment 7

[Francesco]

There's a build running here which you can get binaries from

Looks like it failed.

Comment 8

[Ben Campbell]

Gah. That was the second attempt too...
Just kicking off another one now (fingers crossed):
https://treeherder.mozilla.org/jobs?repo=try-comm-central&revision=6e2c116ccd376cc5def459b33f0273bb7a01e596

Comment 9

[Francesco]

The try build works and shows the correct space saved in the status bar. Just out of curiosity: Why is this an issue now? If the old implementation also checked the file size after compaction, it would have had the same issue on Windows.

Comment 10

[Ben Campbell]

(In reply to Francesco from comment #9)

The try build works and shows the correct space saved in the status bar.

Great - thank you for that!

Just out of curiosity: Why is this an issue now? If the old implementation also checked the file size after compaction, it would have had the same issue on Windows.

The new implementation starts by getting the mbox path from the folder (folder->GetFilePath()) as an nsIFile object, and holds onto that object for the duration:

https://searchfox.org/comm-central/search?q=mMboxPath&path=&case=false&regexp=false

It calls nsIFile::GetFileSize() before it starts, then again after it ends. The problem was that the windows implementation of nsIFile::GetFileSize() caches the result and had no way of knowing that the file had been overwritten, so the second call just returned the same value!

The workaround is to clone the nsIFile object before the second GetFileSize() call. The cloned object has those cached values cleared.

I've seen a few places in the code where nsIFile objects were being cloned for no obvious reason, and I always thought it was odd, but maybe this is the reason! I'll write it up as a separate bug for m-c.

Comment 11

[Ben Campbell]

(In reply to Ben Campbell from comment #10)

I'll write it up as a separate bug for m-c.

Ahh. No need. Bug 307815, Bug 456603, Bug 1022704

Comment 12

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/434347757157
Workaround nsIFile.fileSize stat cache after folder compaction. r=babolivier

Comment 13

[Wayne Mery (:wsmwk)]

Ben, want this for Monday's beta?

Comment 14

[Ben Campbell]

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

Ben, want this for Monday's beta?

Yes please!

Comment 15

[Wayne Mery (:wsmwk)]

Comment on attachment 9405628 [details]
Bug 1900172 - Workaround nsIFile.fileSize stat cache after folder compaction. r=#thunderbird-reviewers

[Triage Comment]
Approved for beta

Comment 16

[Rob Lemley [:rjl]]

Thunderbird 128.0b4:
https://hg.mozilla.org/releases/comm-beta/rev/2da8c4a2cba4

Comment 17

[Ramona Gavrilescu]

Confirming this issue as verified fixed for 128.0b4(20240624182435) with Win10&11 .