[Dovecot] very slow pop3 downloads

[Kae Verens]

Hi all,

I have a dovecot installation which very suddenly decided to slow to a crawl yesterday after being totally fine for months.

IMAP is fine, but POP3 is very painful to use, and frequently times out.

here's my config:
# 1.0.7: /etc/dovecot.conf
log_path: /var/log/dovecot_errors
info_log_path: /var/log/dovecot_informational
ssl_ca_file: /etc/postfix/ssl/cacert.pem
ssl_cert_file: /etc/postfix/ssl/postfix.webworks.ie.crt
ssl_key_file: /etc/postfix/ssl/postfix.webworks.ie.key
login_dir: /var/run/dovecot/login
login_executable(default): /usr/libexec/dovecot/imap-login
login_executable(imap): /usr/libexec/dovecot/imap-login
login_executable(pop3): /usr/libexec/dovecot/pop3-login
login_process_per_connection: no
login_processes_count: 6
first_valid_uid: 89
mail_location: maildir:/home/vmail/%d/%n
mail_executable(default): /usr/libexec/dovecot/imap
mail_executable(imap): /usr/libexec/dovecot/imap
mail_executable(pop3): /usr/libexec/dovecot/pop3
mail_plugin_dir(default): /usr/lib/dovecot/imap
mail_plugin_dir(imap): /usr/lib/dovecot/imap
mail_plugin_dir(pop3): /usr/lib/dovecot/pop3
pop3_client_workarounds(default):
pop3_client_workarounds(imap):
pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh
auth default:
   passdb:
     driver: pam
   passdb:
     driver: sql
     args: /etc/dovecot-mysql.conf
   userdb:
     driver: sql
     args: /etc/dovecot-mysql.conf

I tried an strace as suggested by some other people. didn't know exactly what to attach it to, so did a "ps aux" (Centos 
5.2, btw) and chose the first "pop3" process:

[root at postfix cur]# strace -p 1697
Process 1697 attached - interrupt to quit
gettimeofday({1238146840, 724484}, {0, 0}) = 0
gettimeofday({1238146840, 724542}, NULL) = 0
poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=2, events=POLLERR|POLLHUP|POLLNVAL}, {fd=0, 
events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=1, events=POLLOUT|POLLERR|POLLHUP|POLLNVAL}], 4, 3123) = 0
gettimeofday({1238146843, 847540}, {0, 0}) = 0
gettimeofday({1238146843, 847590}, NULL) = 0
poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=2, events=POLLERR|POLLHUP|POLLNVAL}, {fd=0, 
events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=1, events=POLLOUT|POLLERR|POLLHUP|POLLNVAL, revents=POLLOUT}], 4, 
10000) = 1
gettimeofday({1238146847, 807077}, {0, 0}) = 0
write(1, "6DEDK02J5VXFQtloRQ/JPgdcCrSmSRXj"..., 2171) = 2171
setsockopt(1, SOL_TCP, TCP_CORK, [1], 4) = 0
pread64(9, "7P8JZloV9g/oYWdnm\nnZ9f+xzkO3fVXr"..., 4096, 102400) = 4096
write(1, "\r\nLhQoxZy+rq1TZXl2ZtrKrZH15dE2PK"..., 4134) = 3669
write(1, "uv69IdP6FDbO0lztPh2sA6Z/wBqIdP9Y"..., 465) = -1 EAGAIN (Resource temporarily unavailable)
setsockopt(1, SOL_TCP, TCP_CORK, [0], 4) = 0
gettimeofday({1238146847, 807691}, NULL) = 0
poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=2, events=POLLERR|POLLHUP|POLLNVAL}, {fd=0, 
events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=1, events=POLLOUT|POLLERR|POLLHUP|POLLNVAL}], 4, 6040) = 0
gettimeofday({1238146853, 847046}, {0, 0}) = 0
gettimeofday({1238146853, 847095}, NULL) = 0
poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=2, events=POLLERR|POLLHUP|POLLNVAL}, {fd=0, 
events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=1, events=POLLOUT|POLLERR|POLLHUP|POLLNVAL, revents=POLLOUT}], 4, 
10000) = 1
gettimeofday({1238146856, 546780}, {0, 0}) = 0
write(1, "uv69IdP6FDbO0lztPh2sA6Z/wBqIdP9Y"..., 465) = 465
setsockopt(1, SOL_TCP, TCP_CORK, [1], 4) = 0
pread64(9, "24\nekSIYgeKr5kpQwrk4iWMqC2+/uvwf"..., 4096, 106496) = 4096
write(1, "\r\nIHaoJDSPFqr4jw9SP8S2yLsWOt2RVx"..., 4134) = 4134
pread64(9, "DUJvKTRdVNxs3JTdRQYqD61EYbg22DLb"..., 4096, 110592) = 4096
write(1, "\r\nbDlx3+0LszvjOrD5+04T8PF39frFpQ"..., 4134) = 1241
write(1, "9Zc/wAr\r\nF1bI22U8dNTIKBc423KFJSO"..., 2893) = -1 EAGAIN (Resource temporarily unavailable)
setsockopt(1, SOL_TCP, TCP_CORK, [0], 4) = 0
gettimeofday({1238146856, 547406}, NULL) = 0
poll( <unfinished ...>
Process 1697 detached

looking forward to you all saving my sanity!
thanks,
kae