[Dovecot] POP3 Slow
Avinash Mishra
webbie_colt at yahoo.co.in
Fri Oct 8 07:40:40 EEST 2010
Hi,
I am running both IMAP/POP3 services. Recently, the POP3 users started complaining of slow performance.
I tried to resolve it by advising them to trim their inbox, but to no avail.
Kindly advise as I am not able to resolve this issue.
dovecot -n:
# 1.0.7: /etc/dovecot.conf
ssl_cert_file: /etc/dovecot.cert.pem
ssl_key_file: /etc/dovecot.key.pem
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
mail_location: maildir:~/Maildir
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:
mechanisms: plain login
passdb:
driver: pam
userdb:
driver: passwd
=========================================================================================
sstrace -tt -o log -p <pop3 process id>:
18:45:55.425819 gettimeofday({1286457355, 425856}, {4294966966, 0}) = 0
18:45:55.425901 write(1, "hQIKACgAoAKACgAoAKACgAoASgBaBhQI"..., 1683) = 1683
18:45:55.425987 setsockopt(1, SOL_TCP, TCP_CORK, [1], 4) = 0
18:45:55.426044 pread64(9, "UAFABQAUAFABQBR+zxT31x5qBsBcUAOu"..., 4096, 20480) = 4096
18:45:55.426137 write(1, "\r\nAUAFABQAUAFABQAUAFABQAUAFABQAU"..., 4134) = 4134
18:45:55.426204 pread64(9, "/AJ5p+VAg+zwd4k/7\n5FAB9nh/55J/3y"..., 4096, 24576) = 4096
18:45:55.426298 write(1, "\r\nAC+UmP4v++jR8gsHkp7/APfRosuwWI"..., 4134) = 4134
18:45:55.426373 pread64(9, "FA\nBQAUAFABQAUAFABQAUAFABQAUAFAB"..., 4096, 28672) = 4096
18:45:55.426466 write(1, "\r\nKBBQAUAFABQAUAFABQAUAFABQAUAFA"..., 4134) = 1729
18:45:55.426528 write(1, "rSs+4B+8/2f1oswD956r+VGow/eeq/lR"..., 2405) = -1 EAGAIN (Resource temporarily unavailable)
18:45:55.426600 setsockopt(1, SOL_TCP, TCP_CORK, [0], 4) = 0
18:45:55.426674 gettimeofday({1286457355, 426704}, NULL) = 0
18:45:55.426752
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, 4839) = 1 ([{fd=1,
revents=POLLOUT}])
18:45:55.803792 gettimeofday({1286457355, 803819}, {4294966966, 0}) = 0
18:45:55.803867 write(1, "rSs+4B+8/2f1oswD956r+VGow/eeq/lR"..., 2405) = 2405
18:45:55.803943 setsockopt(1, SOL_TCP, TCP_CORK, [1], 4) = 0
18:45:55.803998 pread64(9, "BQAUAFABQAUAFABQAUAFABQAUAFABQAU"..., 4096, 32768) = 4096
18:45:55.804091 write(1, "\r\nAFABQAUAFABQAUAFABQAUAFABQAUAF"..., 4134) = 4134
18:45:55.804158 pread64(9, "QH+Dbzj0zQBbVCrjDfIFxtx+tAD6ACgA"..., 4096, 36864) = 4096
18:45:55.804251 write(1, "\r\njQBQgtryBSqPDknJJBJJ96ALe6QXCp"..., 4134) = 2221
18:45:55.804327 write(1, "86U5IzwPagCxcQtI0BXHyOGP0waAJ6AF"..., 1913) = -1 EAGAIN (Resource temporarily unavailable)
18:45:55.804399 setsockopt(1, SOL_TCP, TCP_CORK, [0], 4) = 0
18:45:55.804449 gettimeofday({1286457355, 804466}, NULL) = 0
18:45:55.804497
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, 4461) = 1 ([{fd=1,
revents=POLLOUT}])
18:45:56.189834 gettimeofday({1286457356, 189861}, {4294966966, 0}) = 0
18:45:56.189908 write(1, "86U5IzwPagCxcQtI0BXHyOGP0waAJ6AF"..., 1913) = 1913
18:45:56.189982 setsockopt(1, SOL_TCP, TCP_CORK, [1], 4) = 0
18:45:56.190039 pread64(9, "uJ5Y9W/wC+jTC4CNf9r/vo0XC4uwep/w"..., 4096, 40960) = 4096
18:45:56.190136 write(1, "\r\nMN/e/Siwai4b+9+lKwBtb++fyosAbW"..., 4134) = 4134
18:45:56.190204 pread64(9, "0pAGBQAUALQAUAJQAtA\nBQAlAC0AFABQ"..., 4096, 45056) = 4096
18:45:56.190295 write(1, "\r\nB5Ef939aLLsGvcPs8WMbBRoGvcPs8X"..., 4134) = 1253
18:45:56.190370 write(1, "gAoAKACgAoAKACgAoAKACgAoAKACgAoA"..., 2881) = -1 EAGAIN (Resource temporarily unavailable)
18:45:56.190442 setsockopt(1, SOL_TCP, TCP_CORK, [0], 4) = 0
18:45:56.190492 gettimeofday({1286457356, 190510}, NULL) = 0
18:45:56.190540
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, 4075) = 1 ([{fd=1,
revents=POLLOUT}])
18:45:56.394306 gettimeofday({1286457356, 394338}, {4294966966, 0}) = 0
18:45:56.394394 write(1, "gAoAKACgAoAKACgAoAKACgAoAKACgAoA"..., 2881) = 2881
18:45:56.394481 setsockopt(1, SOL_TCP, TCP_CORK, [1], 4) = 0
18:45:56.394539 pread64(9, "AWgB\nKACgAoAWgBp6igBaAFoASgAoAKA"..., 4096, 49152) = 4096
18:45:56.394658 write(1, "\r\n5A2DzRYBnmtjI5GcfSnYB+XaMlcbqX"..., 4134) = 2959
18:45:56.394739 write(1, "AKACg\r\nAoAKACgAoAKACgAoAKACgAoAK"..., 1175) = -1 EAGAIN (Resource temporarily unavailable)
18:45:56.394815 setsockopt(1, SOL_TCP, TCP_CORK, [0], 4) = 0
18:45:56.394876 gettimeofday({1286457356, 394894}, NULL) = 0
18:45:56.394927
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, 3871) = 1 ([{fd=1,
revents=POLLOUT}])
18:45:56.703007 gettimeofday({1286457356, 703024}, NULL) = 0
18:45:56.703056
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, 3562) = 1 ([{fd=1,
revents=POLLOUT}])
18:45:58.344576 gettimeofday({1286457358, 344608}, {4294966966, 0}) = 0
18:45:58.344754 write(1, "gAoAKACgAoAKACgAoAKACgAoAKACgAoA"..., 3111) = 3111
18:45:58.344848 setsockopt(1, SOL_TCP, TCP_CORK, [1], 4) = 0
18:45:58.344907 pread64(9, "An8QoA\nWgAoAKACgAoAKACgAoAKACgAo"..., 4096, 69632) = 4096
18:45:58.344999 write(1, "\r\nFABQAUAFABQAUAFABQAUAFABQAUAFA"..., 4134) = 4134
18:45:58.345067 pread64(9, "oAKACgAoAKACgAoAKACgAoAKACgAoAKA"..., 4096, 73728) = 4096
18:45:58.345161 write(1, "\r\nUAFABQAUAFABQAUAFABQAUAFABQAUA"..., 4134) = 55
18:45:58.345230 write(1, "BQAUAFABQAUAFABQAUAFABQ\r\nAUAGKAC"..., 4079) = -1 EAGAIN (Resource temporarily unavailable)
18:45:58.345305 setsockopt(1, SOL_TCP, TCP_CORK, [0], 4) = 0
18:45:58.345356 gettimeofday({1286457358, 345373}, NULL) = 0
18:46:00.295062 gettimeofday({1286457360, 295092}, {4294966966, 0}) = 0
18:46:00.295146 write(1, "UAFABQAUAFABQAUAB6UA\r\nFABQAUAFAB"..., 722) = 722
18:46:00.295236 setsockopt(1, SOL_TCP, TCP_CORK, [1], 4) = 0
18:46:00.295309 pread64(9, "AFABQAUAFABQAUAFACUALQAUAFABQAUA"..., 4096, 94208) = 4096
18:46:00.295417 write(1, "\r\nFABQAUAFABQAUAFABQAUAFABQAUAFA"..., 4134) = 4134
18:46:00.295509 pread64(9, "ACgAoAKACgAoAKAEP3qAFoAWgAoAKACg"..., 4096, 98304) = 2281
18:46:00.295607 pread64(9, "", 1815, 100585) = 0
18:46:00.295686 close(9) = 0
18:46:00.295800 write(1, "\r\nAKACgAoAKAEoAWgYUCCgAoAKACgBKA"..., 2729) = 984
18:46:00.295875 setsockopt(1, SOL_TCP, TCP_CORK, [0], 4) = 0
18:46:00.295958 read(0, 0x9ad8d81, 1759) = -1 EAGAIN (Resource temporarily unavailable)
18:46:00.296019 setsockopt(1, SOL_TCP, TCP_CORK, [1], 4) = 0
18:46:00.296070 write(1, "gAoAKACgAoAKACgAoAKACgAoAKACgA\r\n"..., 1745) = -1 EAGAIN (Resource temporarily unavailable)
18:46:00.296147 setsockopt(1, SOL_TCP, TCP_CORK, [0], 4) = 0
18:46:00.296197 gettimeofday({1286457360, 296215}, NULL) = 0
18:46:00.296248
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, 9969) = 1 ([{fd=1,
revents=POLLOUT}])
===============================================================================================================
This issue started almost a week back and has been continuing since.
More information about the dovecot
mailing list