Re: [Dovecot] POP3 Slow

Ken A Mon, 11 Oct 2010 07:33:26 -0700


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 answersefficiently, it's good practice to outline your hardware, and what youhave already tried in your first post. What does your hardwareutilization 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 A<k...@pacific.net>  wrote:

From: Ken A<k...@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

Re: [Dovecot] POP3 Slow

Reply via email to