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.
Have you tried the suggestions on improving performance in the wiki? http://wiki.dovecot.org/PerformanceTuning You will need to upgrade to take advantage of several of them..
Ken
On 10/7/2010 11:40 PM, Avinash Mishra wrote:
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: pamuserdb:
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.
-- Ken Anderson Pacific Internet - http://www.pacific.net
Hi
I have tried out the Performance Tuning measures, I do not think that an
upgrade is going to help as most of the features can be incorporated
with the current version itself. ( already done that btw )
I am unable to find any anomalies in the trace, or am I missing something ?
The only part that seems to be not ok, is the EAGAIN -1 return from the write() function.
I did run a protocol analyzer trace on the TCP transaction, when the POP3
clients were connecting and discovered a lot of Re-Transmissions and Duplicate
ACK packets.
--- On Fri, 8/10/10, Ken A ka@pacific.net wrote:
From: Ken A ka@pacific.net Subject: Re: [Dovecot] POP3 Slow To: dovecot@dovecot.org Date: Friday, 8 October, 2010, 7:24 PM
Have you tried the suggestions on improving performance in the wiki? http://wiki.dovecot.org/PerformanceTuning You will need to upgrade to take advantage of several of them..
Ken
On 10/7/2010 11:40 PM, Avinash Mishra wrote:
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.
-- Ken Anderson Pacific Internet - http://www.pacific.net
On Sat, 2010-10-09 at 09:34 +0530, Avinash Mishra wrote:
Hi
I have tried out the Performance Tuning measures, I do not think that an
upgrade is going to help as most of the features can be incorporated
with the current version itself. ( already done that btw )
The problem is, you are asking for support for a version that is no longer supported, just because it is "current" in debians eyes, does not mean it is so, 1.0 is deprecated, some time ago now.
But, apart from other obvious things, have your checked your disks for problems. Your config looks fine anyway, if you have not changed anything, no other OS packaged updated recently, have restarted dovecot etc, checked messages kernel and daemon logs as well, maybe, late at night issue a 'shutdown -F now ' to force checks. Upgrading to at least v1.2 (.15 is current) will give you some performance boost with pop3 over 1.0x
I did run a protocol analyzer trace on the TCP transaction, when the POP3
clients were connecting and discovered a lot of Re-Transmissions and Duplicate
ACK packets.
Then the first thing I would do is check the network connection. Maybe you have a wrecked network card, switch port ot et cetera. Try running another protocol, like FTP, over the same connection. If you get similar errors you can rule out dovecot.
JC
On 10/8/2010 11:04 PM, Avinash Mishra wrote:
Hi
I have tried out the Performance Tuning measures, I do not think that an
upgrade is going to help as most of the features can be incorporated
with the current version itself. ( already done that btw )
Well, to keep us from wasting our time, and to get relevant answers efficiently, it's good practice to outline your hardware, and what you have already tried in your first post. What does your hardware utilization look like?
Ken
I am unable to find any anomalies in the trace, or am I missing something ?
The only part that seems to be not ok, is the EAGAIN -1 return from the write() function.
I did run a protocol analyzer trace on the TCP transaction, when the POP3
clients were connecting and discovered a lot of Re-Transmissions and Duplicate
ACK packets.
--- On Fri, 8/10/10, Ken Aka@pacific.net wrote:
From: Ken Aka@pacific.net Subject: Re: [Dovecot] POP3 Slow To: dovecot@dovecot.org Date: Friday, 8 October, 2010, 7:24 PM
Have you tried the suggestions on improving performance in the wiki? http://wiki.dovecot.org/PerformanceTuning You will need to upgrade to take advantage of several of them..
Ken
On 10/7/2010 11:40 PM, Avinash Mishra wrote:
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.
-- Ken Anderson Pacific Internet - http://www.pacific.net
On Mon, 11 Oct 2010 09:32:35 -0500 Ken A ka@pacific.net articulated:
Well, to keep us from wasting our time, and to get relevant answers efficiently, it's good practice to outline your hardware, and what you have already tried in your first post. What does your hardware utilization look like?
In the future, could we also please trim the superfluous material from these posts.
To the OP, the output of "uname -a", "dovecot -n" as well as the configuration files of other pertinent applications in addition to what modifications you have made and all pertinent log entries would prove extremely useful. Listing your hardware, as previously mentioned, is also invaluable in some situations. Some of these you have obviously all ready supplied and, or been requested to supply.
-- Jerry ✌ Dovecot.user@seibercom.net
Disclaimer: off-list followups get on-list replies or get ignored. Please do not ignore the Reply-To header.
One big pile is better than two little piles.
Arlo GuthrieOn Mon, 11 Oct 2010 11:56:38 -0400 Charles Marcus CMarcus@Media-Brokers.com articulated:
Actually, doveconf -n output should include similar output as uname -a (as well as dovecot version) at the top...
It was meant as a semi all inclusive listings. I could have included tcpdump, etc.; however, I just wanted to convey the general idea to the OP. Obviously, 'dovecot -n' would not be required for say a Postfix specific problem.
As you are probably aware, most posters supply either too little or too much info. When in doubt, I would favor the "too much" scenario though. It saves asking for further info and greatly facilitates diagnosing the problem.
-- Jerry ✌ Dovecot.user@seibercom.net
Disclaimer: off-list followups get on-list replies or get ignored. Please do not ignore the Reply-To header.
She was good at playing abstract confusion in the same way a midget is good at being short.
Clive James, on Marilyn MonroeOn 2010-10-11 12:15 PM, Jerry wrote:
As you are probably aware, most posters supply either too little or too much info. When in doubt, I would favor the "too much" scenario though. It saves asking for further info and greatly facilitates diagnosing the problem.
I agree, but you miss my point...
Providing 'uname -a' output is *redundant* (except for old/outdated versions that do not include this info) when doveconf -n output is provided...
--
Best regards,
Charles
Hi,
Thanks to everybody for your contributions to my issue. The hardware usage
is minimal. I was actually thinking that I have missed something major in the
strace output, that I had posted and that would be pointed out.
Beyond that I have looked into every possible angle, and I did run a further network
analysis of TCP connections ( ftp ), as suggested, and found out that there
were retransmissions and duplicate acks.
The problems are extraneous to dovecot, which in my opinion is the best
IMAP/POP3 server out there. This issue can be considered closed. .
--- On Mon, 11/10/10, Charles Marcus CMarcus@Media-Brokers.com wrote:
From: Charles Marcus CMarcus@Media-Brokers.com Subject: Re: [Dovecot] POP3 Slow To: dovecot@dovecot.org Date: Monday, 11 October, 2010, 11:06 PM
On 2010-10-11 12:15 PM, Jerry wrote:
As you are probably aware, most posters supply either too little or too much info. When in doubt, I would favor the "too much" scenario though. It saves asking for further info and greatly facilitates diagnosing the problem.
I agree, but you miss my point...
Providing 'uname -a' output is *redundant* (except for old/outdated versions that do not include this info) when doveconf -n output is provided...
--
Best regards,
Charles
participants (6)
-
Avinash Mishra
-
Charles Marcus
-
Jakob Curdes
-
Jerry
-
Ken A
-
Noel Butler