[Dovecot] POP3 Slow

Sat Oct 9 07:04:18 EEST 2010

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 at pacific.net> wrote:

From: Ken A <ka at pacific.net>
Subject: Re: [Dovecot] POP3 Slow
To: dovecot at 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