722183 - slow putting a few messages (or single message) into a large local folder (move, copy, archive)

Status: RESOLVED WORKSFORME

(MailNews Core :: Backend, defect)

Description

[Wayne Mery (:wsmwk)]

On laptop over several days moving messages from an imap to my local bugmail local folder was slow - timed it yesterday at 5-6 seconds. (Folder is ~35K messages/120MB - not small,  not huge.)  Slowness continued after restart of tbird and restart of PC.  tbird not looping in any way and CPU nominal.

Today I tried moving similar messages from local folder to moz-archive. Same results. Disabled gloda, same results.  Restart thunderbird into safe mode with msgdb logging (now, here it gets murky) - unfortunately tbird got updated from 20120118 build to 20120128 because of bloody test profiles which can't default to not update. but that's another story.  Anyway, problem gone in safe mode. Restart to normal mode - problem still gone.  WTH?

I wish I had tried wada's advice in bug 347837
"User can keep Db open, by keep folder open.
  Folder context menu, Open in New Tab(or Open), instead of folder switch.
As Db is kept open if folder is opened at a tab or a window, thread pane is immediately shown by tab switch or window switch. This can be a workaround by user."

current status: testcase is gone for now and I have no log. 

I have no reason to believe the problem is gone based on the list of bugs fixed since 01-18. And I can't substantiate any connection to bug 347837 (which might match this issue) because a) based on my incoming mail, workflow and list of addons there should not have been many dbs held open by tbird, and b) no log file

Comment 1

[Wayne Mery (:wsmwk)]

also ...

a) this was on every message I tried to move to moz-archive
b) I didn't get to test whether UI was responsive during the 5-6 seconds. But I can so I couldn't open another folder until the move was done .

Comment 2

[Wayne Mery (:wsmwk)]

c/But I can so /But I can say /

Comment 3

[David :Bienvenu]

Is your suspicion that we're opening and closing the target folder db on every message copy, so that the larger the db, the slower the copying?

Comment 4

[Wayne Mery (:wsmwk)]

Attachment: msgdb log

(In reply to David :Bienvenu from comment #3)
> Is your suspicion that we're opening and closing the target folder db on
> every message copy

that is my suspicion, yes. But given current ideal performance (below) - one would think something else is involved than just opening the db - if that was even involved at all.

> so that the larger the db, the slower the copying?

that shouldn't be the case, right?  

what is strange of course is that safe mode or something else related to that "last" startup cleared up the problem


To give you an idea of the performance of this laptop ...
using this sequence of events:
thunderbird startup in moz-archive (local) folder (35,371 msgs)
click "filed" folder (tiny, 6 messages)
click moz-archive folder
shutdown
-- msgdb log attached.

view=all messages
every click on moz-archive takes:
-  2.5 seconds, threaded
- ~2.0 seconds, unthreaded

current performance of moves is 
- from imap (synced folders): subsecond (~0.5 sec)
- from "filed" local folder: ~instantaneous

Comment 5

[WADA:World Anti-bad-Duping Agency]

Process Monitor log for reading of all 7.4MB .msf file data(local mail folder, 16315 mails) by Tb trunk 2012/01/29 build on MS Win-XP.

> Start of read data, using 8KB buffer.
> "10761","00:00:09.5502261",C:\Mail\Big-Mbox1.sbd\Z.msf","Read","FASTIO_READ","SUCCESS","Offset: 0, Length: 8,192"
> "10762","00:00:09.5502415",C:\Mail\Big-Mbox1.sbd\Z.msf","","FASTIO_CHECK_IF_POSSIBLE","SUCCESS","Operation: Read, Offset: 0, Length: 8,192"
> "10763","00:00:09.5516746",C:\Mail\Big-Mbox1.sbd\Z.msf","Read","FASTIO_READ","SUCCESS","Offset: 8,192, Length: 8,192"
> "10764","00:00:09.5516891",C:\Mail\Big-Mbox1.sbd\Z.msf","","FASTIO_CHECK_IF_POSSIBLE","SUCCESS","Operation: Read, Offset: 8,192, Length: 8,192"
>
> Reading 8KB blocks continues
>
> EOF
> "13120","00:00:12.8898651",C:\Mail\Big-Mbox1.sbd\Z.msf","","FASTIO_CHECK_IF_POSSIBLE","SUCCESS","Operation: Read, Offset: 7,406,916, Length: 8,192","3972","1272"
> "13121","00:00:12.8900883",C:\Mail\Big-Mbox1.sbd\Z.msf","Read","FASTIO_READ","END OF FILE","Offset: 7,408,686, Length: 4,096","3972","1272"

It took 3 seconds, so, at least 3 seconds is needed to open this local mail folder.
Larger buffer such as 1MB may reduce file read time.

Because number of file handles has limitation in any system, "keep any .msf file open" can't be used as solution of issue like this. New folder option like "Keep this folder open at least NNN minutes once opened" may be required for users who loves big Unix Mbox very much.
 0  = close immediately when unselected
 -1 = never close until termination 
 -2 = never close until termination, and pre-open upon restart in background  
Virtual Folder can be used for such purpose?

"per folder thread-pane.json" like one may be a solution. Unless folder is updated by someone during the folder is unselected, actual folder open is not required to show thread pane. Actual folder open can be execute in background while showing thread pane and current message in message pane. Even if folder is updated during the folder is unselected, if modification is irrelevant to mails which are shown at thread pane, it's absolutely same as "no update" for thread pane/message pane.

Comment 6

[Wayne Mery (:wsmwk)]

Don't have process monitor info, I guess that's the next step), but I do think target db is quickly being closed. Some moves from imap to local are instant, some are slow (2-4ish sec).   I retested with thunderbird offlline, and fairly idle computer

So all moves and copies should be pretty much instant, no?   And size of the target folder .msf does't matter, right? (it's 20MB)

Ref: also bienvenu's bug 105192 comment 8 "bigger win might be to figure out a way to avoid opening and closing the same db on multiple move/copies to the same target (perhaps lazily closing db's based on an LRU scheme as Wayne suggests in bug 347837.)"

Further, I wonder if our current max# of open db (absent bugs) is still appropriate for today's computers/memory sizes and the huge volume of messages many people deal with?  Some people deal only with a few folders all day (inbox, trash, archive). But some people work with many folders in a tiny span of time - what with filters, archive, and others. And how does gmail affect the equation, including probably a majority of people not unsubscribing from the "All Mail" folder? (I wonder if we could gain that info with test pilot?)

Lastly, I need to factor in (or out) when I am being affected by Bug 505456 - move/copying multiple imap messages to local folder bypasses offline store

Comment 7

[David :Bienvenu]

(In reply to Wayne Mery (:wsmwk) from comment #6)
> 
> So all moves and copies should be pretty much instant, no?   And size of the
> target folder .msf does't matter, right? (it's 20MB)

No, that matters, if we have to re-open the .msf file for every copy.
> 
> 
> Further, I wonder if our current max# of open db (absent bugs) is still
> appropriate for today's computers/memory sizes 

There is no max # of open db's currently. We try to close them immediately, unless they're special folders (inbox, trash, etc) that we expect to copy to again soon. Once we land the dbaging patch, we can be less aggressive about closing db's immediately.

Comment 8

[Wayne Mery (:wsmwk)]

(In reply to David :Bienvenu from comment #7)
> (In reply to Wayne Mery (:wsmwk) from comment #6)
> > 
> > So all moves and copies should be pretty much instant, no?   And size of the
> > target folder .msf does't matter, right? (it's 20MB)
> 
> No, that matters, if we have to re-open the .msf file for every copy.

I understand the need to open. But do we read in the entire db even just to add a message, and viewing any in the target folder?

> > 
> > 
> > Further, I wonder if our current max# of open db (absent bugs) is still
> > appropriate for today's computers/memory sizes 
> 
> There is no max # of open db's currently. We try to close them immediately,
> unless they're special folders (inbox, trash, etc) that we expect to copy to
> again soon. Once we land the dbaging patch, we can be less aggressive about
> closing db's immediately.

thanks for clearing up my misunderstanding. Guess I should look at my msgdb as well

Comment 9

[Wayne Mery (:wsmwk)]

[correction] and no views open to the target folder?

Comment 10

[David :Bienvenu]

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

> I understand the need to open. But do we read in the entire db even just to
> add a message, and viewing any in the target folder?
Yes, that's a drawback of an all-in-memory database like Mork.

Comment 11

[Wayne Mery (:wsmwk)]

(In reply to David :Bienvenu from comment #10)
> (In reply to Wayne Mery (:wsmwk) from comment #8)
> 
> > I understand the need to open. But do we read in the entire db even just to
> > add a message, and viewing any in the target folder?
> Yes, that's a drawback of an all-in-memory database like Mork.

yeah, smaller target folder makes a world of difference.

Comment 12

[[:Aleksej]]

I am using Icedove 17 Linux x86_64 in a per-file encrypted directory, and moving 2000 messages between folders is about 10 per second.

Comment 15

[Wayne Mery (:wsmwk)]

Aleksej, note, this bug is NOT about bulk move of messages. (eg bug 847285, bug 846123)

bug 384360 comment 0 may be the same issue as this bug.
(That is, if Ben's comment is correct about moving a *single* message or just a few messages. It seems to me the focus digressed after comment 0)

Comment 16

[[:Aleksej]]

(In reply to Wayne Mery (:wsmwk) from comment #15)
> Aleksej, note, this bug is NOT about bulk move of messages. (eg bug 847285,
> bug 846123)
> 
> bug 384360 comment 0 may be the same issue as this bug.

Both non-meta bugs mention IMAP, which I don't use.

Comment 17

[WADA:World Anti-bad-Duping Agency]

(In reply to Wayne Mery (:wsmwk) from comment #6)
> And size of the target folder .msf does't matter, right? (it's 20MB)

If your problem is actually caused by (a) long time for "required full read of 20MB .msf file", following is simplest workaround.
  delete.msf of target folder, do Copy or Move to Target folder.
As known by bug like bug 261419, bug 495760, bug 905576, DoCopy doesn't care for "error in MsgDatabase open". So, DoCopy appends mail data to target msgStore file without correct update of .msf.
So, required time is (b) "read data from source msgStore file" + (c) "append mail data to target msgStore file" only. Time consuming "Rebuild-Index" is executed upon next folder open. i.e. "time consuming" part is transfered to other people. So your objective of "fast copy/move" is easily acieved? :-)

Cause of your roblem actually long (a)? "3 second for read full .msf" is major part of your bug for performance problem? IIRC, "one write request per one line of mail data in (c)" is already known issue, and is not resolved yet(once resolved, but quickly revived). 

> Don't have process monitor info, I guess that's the next step), but I do
> think target db is quickly being closed.

"process monitor info" is to measure "full .msf file read for folder open" time, "write all data to target msgStore file" time etc.
Even though bug report at B.M.O for performane problem, why data such as timestamp,MSGDB:5,MsgCopyService:5 is not provided by bug opener nor "me too" comment posters yet?

IIRC, problem like next existed in the past; even though idle time setting is millisecond, "value in second" was set as default...
Bug opener, do you see your problem in recent Tb?
  default in Tb 24 : 
    mail.db.idle_limit=300000  == 300sec, 5 minutes.
    mail.db.max_open = 30      Too small? or 30 means 30*1000 folders?

Comment 20

[Wayne Mery (:wsmwk)]

I no longer have that laptop (was either a dell or a thinkpad w520).
I haven't seen this in a long time