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

2006. November 3. 13:18, Timo Sirainen:

On 3.11.2006, at 13.01, LeVA wrote:

...

...

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.

..

...

1168 pop3 1162550554.983041 CALL write(0x1,0x7f64bbeb,0x1018) 1168 pop3 1162550554.983048 RET
write -1 errno 35 Resource temporarily unavailable

OK, so this means that the receiving end isn't reading the data fast enough, so kernel starts giving EAGAIN errors to write() calls. So there simply is a network bottleneck somewhere outside Dovecot.. Understood. Thanks for the support! I am going to investigate this bottleneck.

Daniel

-- LeVA