On Fri, Nov 02, 2007 at 12:12:05PM -0400, Adam McDougall wrote:
On Fri, Nov 02, 2007 at 06:04:12PM +0200, Timo Sirainen wrote:
On Mon, 2007-10-29 at 17:15 -0400, Adam McDougall wrote:
> Sometimes when I login to dovecot and read a message from an imap maildir folder,
> the message contents do not load for at least 10 seconds, sometimes closer to a
> minute, but after that first message loads, the rest seem fine in that mailbox.
> The time seems to vary some, usually longer rather than shorter.
Getting a strace from what the imap process is doing at the time would
be useful. It sounds a bit like a stale dotlock, although Dovecot waits
for two minutes for that. http://hg.dovecot.org/dovecot/rev/6dd5df1c1ec9
fixes a stale dotlock overriding issue.Agreed, I've wanted to get a trace since the first time I saw it, but I've been using dovecot 1.1 all week and hardly seen it. Its possible a patch improved it or there was some other cause, so its just something I'll watch out for and try to tackle as soon as it becomes reproducable. After some further preparation this weekend I plan to expand my testing of 1.1 beyond just myself and one server, since I've been very happy with the current state of 1.1 this week versus 1.0.
I noticed some sluggish message body fetches today that I don't think I've seen before. Each time I fetch a message from this particular mailbox (network/2007/01-Jan for my own record) it takes a few seconds, and mutt makes it look like the fetch was "slow". So did thunderbird. I didn't waste any time and tried to grab a truss and kdump of the action asap (attached). Apparently strace is only available on i386 for FreeBSD, but truss and kdump should be similar, depends what details you are looking for.
It looks like the message fetch actually reads in from disk fairly promptly (you can see the whole spam message in the kdump output) but then it churns away for a while with something like the below:
fstat(13,{mode=-rw------- ,inode=5656735,size=817368,blksize=4096}) = 0 (0x0) fchown(0xd,0x5321,0xffffffff) = 0 (0x0) madvise(0x10649000,0x82000,0x4) = 0 (0x0) fstat(13,{mode=-rw------- ,inode=5656735,size=817368,blksize=4096}) = 0 (0x0) fchown(0xd,0x5321,0xffffffff) = 0 (0x0) madvise(0x10649000,0x82000,0x4) = 0 (0x0) fstat(13,{mode=-rw------- ,inode=5656735,size=817368,blksize=4096}) = 0 (0x0) fchown(0xd,0x5321,0xffffffff) = 0 (0x0) madvise(0x10649000,0x82000,0x4) = 0 (0x0) fstat(13,{mode=-rw------- ,inode=5656735,size=817368,blksize=4096}) = 0 (0x0) fchown(0xd,0x5321,0xffffffff) = 0 (0x0) madvise(0x10649000,0x82000,0x4) = 0 (0x0) fstat(13,{mode=-rw------- ,inode=5656735,size=817368,blksize=4096}) = 0 (0x0) fchown(0xd,0x5321,0xffffffff) = 0 (0x0) madvise(0x10649000,0x82000,0x4) = 0 (0x0) fstat(13,{mode=-rw------- ,inode=5656735,size=817368,blksize=4096}) = 0 (0x0) fchown(0xd,0x5321,0xffffffff) = 0 (0x0) madvise(0x10649000,0x82000,0x4) = 0 (0x0)
For now I plan to leave mutt with the current folder selected, incase something I do makes the behavior go away.