[Dovecot] POP3 Slow

Mon Oct 11 17:32:35 EEST 2010

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 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