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