[Dovecot] some mail accesses in dovecot 1.1 stall for a bit (in progress)

[Adam McDougall]

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.