[Dovecot] any idea why the mail downloading is slow?

[LeVA]

2006. November 2. 22:44, Timo Sirainen:
> On Sat, 2006-10-21 at 11:37 +0200, LeVA wrote:
> > Hi!
> >
> > I'm using rc10, but had this problem with previous releases too.
> > Not sure if this is a dovecot problem, but I can not think of
> > anything else. The mail downloading with pop3 is ~very slow,
> > approx. 20 Kbyte / sec. no matter how many mails I've got in my
> > mailbox, or how big are the mails. My ISP provides me a dedicated
> > 100mbit line, and everything else works as fast as expected eg.
> > http, ftp, scp...
> > The OS is OpenBSD 3.9-stable and the system is not under heavy load
> > at all. I've tried to turn off TLS but there was no change.
> >
> > Is the pop3 protocol this slow by design or there is something
> > wrong with my setup?
>
> There's something wrong in your setup..
>
> You could check what Dovecot is doing by tracing the process.
> http://wiki.dovecot.org/Debugging/ProcessTracing
>
> It probably shows that Dovecot spends most of its time in poll() (or
> kqueue()). But it could be either waiting to be able to send more
> data to the client, or waiting for a command from the client.
>
> With POP3 each mail is downloaded with a separate RETR command, so
> the problem could just be that the client is sending them too slowly.
> Or does this same happen even with one large mail?
Yes, it happens this one large mail too, so I followed your 
instructions, and traced the pop3 process;
Here are some lines which caught my attention:

  1168 pop3     1162550554.983008 RET   write 2048/0x800
  1168 pop3     1162550554.983041 CALL  write(0x1,0x7f64bbeb,0x1018)
  1168 pop3     1162550554.983048 RET   write -1 errno 35 Resource 
temporarily unavailable
  1168 pop3     1162550554.983053 CALL  write(0x1,0x7f64bbeb,0x1018)
  1168 pop3     1162550554.983055 RET   write -1 errno 35 Resource 
temporarily unavailable
  1168 pop3     1162550554.983062 CALL  gettimeofday(0xcfbe3330,0)
  1168 pop3     1162550554.983067 RET   gettimeofday 0
  1168 pop3     1162550554.983069 CALL  poll(0x80456000,0x4,0x235f)
  1168 pop3     1162550554.983477 RET   poll 1
  1168 pop3     1162550554.983493 CALL  
gettimeofday(0x3c012cd4,0x3c012cdc)
  1168 pop3     1162550554.983499 RET   gettimeofday 0
  1168 pop3     1162550554.983506 CALL  write(0x1,0x7f64bbeb,0x1018)
  1168 pop3     1162550554.983518 GIO   fd 1 wrote 2048 bytes
[...]
  1168 pop3     1162550554.983605 RET   pread 4096/0x1000
  1168 pop3     1162550554.983627 CALL  writev(0x1,0xcfbe3260,0x2)
  1168 pop3     1162550554.983636 RET   writev -1 errno 35 Resource 
temporarily unavailable
  1168 pop3     1162550554.983639 CALL  writev(0x1,0xcfbe3260,0x2)
  1168 pop3     1162550554.983642 RET   writev -1 errno 35 Resource 
temporarily unavailable
  1168 pop3     1162550554.983651 CALL  gettimeofday(0xcfbe3330,0)
  1168 pop3     1162550554.983655 RET   gettimeofday 0
  1168 pop3     1162550554.983657 CALL  poll(0x80456000,0x4,0x235f)
  1168 pop3     1162550554.983930 RET   poll 1
  1168 pop3     1162550554.983946 CALL  
gettimeofday(0x3c012cd4,0x3c012cdc)
  1168 pop3     1162550554.983952 RET   gettimeofday 0
  1168 pop3     1162550554.983959 CALL  writev(0x1,0xcfbe3290,0x2)
  1168 pop3     1162550554.983972 GIO   fd 1 wrote 2048 bytes


The write() failures are fishy, there are quite a lot of them :\
Is there something in dovecot which could cause this ~error?

Daniel

-- 
LeVA