thr3ads.net - dovecot - [Dovecot] POP3 Slow [Oct 2010]

If this information is useful, please help other people find it:
Share via:

Avinash Mishra

2010-Oct-08 04:40 UTC

[Dovecot] POP3 Slow

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 A

2010-Oct-08 13:54 UTC

head link

[Dovecot] POP3 Slow

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

Avinash Mishra

2010-Oct-09 04:04 UTC

head link

[Dovecot] POP3 Slow

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

Jakob Curdes

2010-Oct-09 20:23 UTC

head link

[Dovecot] POP3 Slow

> 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

dovecot - Oct 2010 - POP3 Slow

[Dovecot] POP3 Slow

[Dovecot] POP3 Slow

[Dovecot] POP3 Slow

[Dovecot] POP3 Slow