-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1
Hello,
in order to stress my Dovecot test installation a bit, I compiled
imaptest10.c.
Now and then I see:
Logi List Stat Sele Fetc Fet2 Copy Stor Dele Expu Appe Logo
100% 50% 50% 100% 100% 100% 33% 50% 100% 100% 100% 100%
30% 5% 5%
0 0 0 0 0 0 0 0 0 0 0 0 1/ 1
0 0 0 0 0 0 0 0 0 0 0 0 1/ 1
0 0 0 0 0 0 0 0 0 0 0 0 1/ 1
0 0 0 0 0 0 0 0 0 0 0 0 1/ 1
- 46. stalled for 1784 secs in APPEND
- 46. stalled for 1785 secs in APPEND
- 46. stalled for 1786 secs in APPEND
- 46. stalled for 1787 secs in APPEND
- 46. stalled for 1788 secs in APPEND
- 46. stalled for 1789 secs in APPEND
- 46. stalled for 1790 secs in APPEND
(Sometimes SELECT or COPY)
The maximum stalled time in APPEND is 1790s; in SELECT and COPY the
maximum time is less than 20s until now.
The only IMAP process loops around a poll():
poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=2,
events=POLLERR|POLLHUP|POLLNVAL}, {fd=0,
events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 3, 0) = 0
gettimeofday({1174389105, 882286}, {4294967236, 0}) = 0
gettimeofday({1174389105, 882339}, NULL) = 0
poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=2,
events=POLLERR|POLLHUP|POLLNVAL}, {fd=0,
events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 3, 999) = 0
gettimeofday({1174389106, 882011}, {4294967236, 0}) = 0
gettimeofday({1174389106, 882123}, NULL) = 0
poll([{fd=4, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=2,
events=POLLERR|POLLHUP|POLLNVAL}, {fd=0,
events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 3, 0) = 0
So does imaptest itself:
poll([{fd=3, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=52,
events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, 0) = 0
gettimeofday({1174389079, 93585}, {4294967236, 0}) = 0
write(1, " 0 0 0 0 0 0 "..., 68) = 68
write(2, " - 46. stalled for 1698 secs in "..., 39) = 39
gettimeofday({1174389079, 93814}, NULL) = 0
poll([{fd=3, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=52,
events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, 999) = 0
gettimeofday({1174389080, 93445}, {4294967236, 0}) = 0
gettimeofday({1174389080, 93497}, NULL) = 0
poll([{fd=3, events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}, {fd=52,
events=POLLIN|POLLPRI|POLLERR|POLLHUP|POLLNVAL}], 2, 0) = 0
gettimeofday({1174389080, 93607}, {4294967236, 0}) = 0
There are no crashes, nothing. The server is idle then.
I first assumed that it is related to an out-of-quota condition, but this
time there is no fs quota set for the user. When I played with the quota,
I ran imaptest with standard settings and without copybox=.
I used this command:
/usr/local/src/imaptest user=dvtest pass=pass clients=115
mbox=test.mbox box=box0 copybox=box1 msgs=200
./configure summary:
Install prefix ...................... : /usr/local/dovecot.rc27
File offsets ........................ : 64bit
I/O loop method ..................... : poll
File change notification method ..... : dnotify
Building with SSL support ........... : yes (OpenSSL)
Building with IPv6 support .......... : yes
Building with pop3 server ........... : yes
Building with mail delivery agent .. : yes
Building with GSSAPI support ........ : no
Building with user database modules . : static prefetch passwd passwd-file
checkpassword ldap sql (modules)
Building with password lookup modules : passwd passwd-file shadow pam
checkpassword ldap sql (modules)
Building with SQL drivers ............: pgsql
# /usr/local/dovecot.rc27/sbin/dovecot -n
# /usr/local/dovecot.rc27/etc/dovecot.conf
base_dir: /var/run/dovecot/
log_path: /var/log/dovecot/dovecot.log
protocols: imap imaps pop3 pop3s
ssl_ca_file: /etc/ssl/certs/ca.crt
ssl_cert_file(default): /etc/ssl/certs/imap.pem
ssl_cert_file(imap): /etc/ssl/certs/imap.pem
ssl_cert_file(pop3): /etc/ssl/certs/pop3.pem
ssl_key_file(default): /etc/ssl/private/imap.key
ssl_key_file(imap): /etc/ssl/private/imap.key
ssl_key_file(pop3): /etc/ssl/private/pop3.key
disable_plaintext_auth: no
verbose_ssl: yes
login_dir: /var/run/dovecot//login
login_executable(default):
/usr/local/dovecot.rc27/libexec/dovecot/imap-login
login_executable(imap): /usr/local/dovecot.rc27/libexec/dovecot/imap-login
login_executable(pop3): /usr/local/dovecot.rc27/libexec/dovecot/pop3-login
login_log_format_elements: %p: user=<%u> method=%m rip=%r lip=%l %c
verbose_proctitle: yes
first_valid_uid: 1000
mail_location:
maildir:%h/MailDir:CONTROL=/var/cache/dovecot/%i/control:INDEX=/var/cache/dovecot/%i/index
mail_debug: yes
dotlock_use_excl: yes
maildir_copy_with_hardlinks: yes
maildir_copy_preserve_filename: yes
mail_drop_priv_before_exec: yes
mail_executable(default): /usr/local/dovecot.rc27/libexec/dovecot/imap
mail_executable(imap): /usr/local/dovecot.rc27/libexec/dovecot/imap
mail_executable(pop3): /usr/local/dovecot.rc27/libexec/dovecot/pop3
mail_plugins(default): quota imap_quota mail_log zlib
mail_plugins(imap): quota imap_quota mail_log zlib
mail_plugins(pop3): quota mail_log
mail_plugin_dir(default): /usr/local/dovecot.rc27/lib/dovecot/imap
mail_plugin_dir(imap): /usr/local/dovecot.rc27/lib/dovecot/imap
mail_plugin_dir(pop3): /usr/local/dovecot.rc27/lib/dovecot/pop3
mail_log_prefix: %Us(%u) [%p]:
mail_log_max_lines_per_sec: 30
pop3_uidl_format(default):
pop3_uidl_format(imap):
pop3_uidl_format(pop3): %u
pop3_client_workarounds(default):
pop3_client_workarounds(imap):
pop3_client_workarounds(pop3): oe-ns-eoh
namespace:
type: private
separator: .
inbox: yes
hidden: yes
auth default:
mechanisms: plain login
cache_size: 10
username_chars:
abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890
verbose: yes
debug: yes
passdb:
driver: ldap
args: /usr/local/dovecot.rc26/etc/dovecot-ldap.conf
passdb:
driver: shadow
userdb:
driver: prefetch
userdb:
driver: ldap
args: /usr/local/dovecot.rc26/etc/dovecot-ldap.conf
userdb:
driver: passwd-file
args: /etc/passwd
socket:
type: listen
client:
path: /var/run/dovecot/auth-client
mode: 432
master:
path: /var/run/dovecot/auth-master
mode: 432
group: mail
plugin:
quota: fs
Bye,
- --
Steffen Kaiser
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)
iQEVAwUBRf/E3i9SORjhbDpvAQI5oQgAhOYKF9Rw0Ezz8Fn22xLjm/EtXdsRgpPx
6kcBkT+v4gLc15ORtcCrWLmU0bG+an//2wQ33cAiH2X/veZXEdXtwNultq+HPM3/
MYnjvNhL+OkkN9wAGOLTaRFJUDofEiXQzeNiVhYelmUsT4NaLzVQT4tRiYrbIAvK
sHlkZJayE3gTIc5SzAviWxPPEkcJO+0HpMrym9USYbFtWNMVEMSYl9pGTVp9YTa0
oMUGpge1H8Qw75VMuf9jHC2SU8Xe889pv9CiButE0cpkQSsQj7Gf4+rX5V3ts3xv
vw8oAZdsc3Rzms3JrWRiAsQHomXeAW0VPZSi/DjIOXT/AshXvnLDQw==FLRG
-----END PGP SIGNATURE-----
On 20.3.2007, at 13.26, Steffen Kaiser wrote:> - 46. stalled for 1784 secs in APPEND..> Install prefix ...................... : /usr/local/dovecot.rc27.. Hmm. So these hangs are with rc27? Try what happens with this patch: http://dovecot.org/patches/debug/imap-append-hang-debug.diff -------------- next part -------------- A non-text attachment was scrubbed... Name: PGP.sig Type: application/pgp-signature Size: 186 bytes Desc: This is a digitally signed message part URL: <http://dovecot.org/pipermail/dovecot/attachments/20070320/24a90bdd/attachment.bin>
On 20.3.2007, at 13.26, Steffen Kaiser wrote:> in order to stress my Dovecot test installation a bit, I compiled > imaptest10.c.Oh, and was imaptest10 also compiled against rc27 sources? Because rc27 fixed this: - If mail was sent to client with sendfile() call, we could have hanged the connection. This could happen only if mails were saved with CR+LF linefeeds. I noticed that only because imaptest kept hanging when using sendfile ().. -------------- next part -------------- A non-text attachment was scrubbed... Name: PGP.sig Type: application/pgp-signature Size: 186 bytes Desc: This is a digitally signed message part URL: <http://dovecot.org/pipermail/dovecot/attachments/20070320/bbc6a6a6/attachment.bin>
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Tue, 20 Mar 2007, Timo Sirainen wrote:> Oh, and was imaptest10 also compiled against rc27 sources? Because rc27 fixed > this:Yes. I compiled imaptest10 within rc27's source dir. I'll try the patch. Bye, - -- Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.6 (GNU/Linux) iQEVAwUBRf/uAi9SORjhbDpvAQKViQgAzBsUO5wcAFiBL4FmPP27Cx7sxCmPuIQG u8lLhY/oUVgz5ge27yJjGril4b2MGBbppPxWXbNtDVVQPtEnsKGGpUPqCarmZwK6 0mCMPOizmoATqhdbZ1kNsrgbu/eY30Fpz2ramluTGuDlOkEbpxDRHMdMvUAEwKiP UGa6BzdnTC/25yKBgZwbw9gAut5bfOr6OWtFBIp5aKpPTdYHl0I5oEBaZ+osnkfw NNYu32WPgAKUm4Qb0OxUM3YtAJvCrsl/UVGMBAO/H4bz8a0/6OT6RuAERzUo9v63 Xsqbd0MJEvPDzByVACAwDxfCQDybeqMtLJOmp49tuMJYog3YvHAApw==XEtG -----END PGP SIGNATURE-----
-----BEGIN PGP SIGNED MESSAGE----- Hash: SHA1 On Tue, 20 Mar 2007, Timo Sirainen wrote:> http://dovecot.org/patches/debug/imap-append-hang-debug.diffThe maximum "stalled" time for all three commands is 23 secs now. That's OK, I think. However, imaptest10 finished after approx. 2 houres. The last log entries of imaptest are plenty of: Error: COPY failed: Some of the requested messages no longer exist. In this time the following info had been logged 88 times: Info: dvtest: Mailbox is in inconsistent state, please relogin. There are no core dumps. The last lines of the dovecot.log file are: dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: expunged: uid=115951, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: expunged: uid=115953, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: expunged: uid=115954, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: expunged: uid=115959, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3620]: Disconnected: Mailbox is in inconsistent state, please relogin. dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3504]: expunged: uid=115924, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3530]: expunged: uid=115986, msgid=(null), box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3530]: expunged: uid=115998, msgid=<xxxxxxxx.xxxxxxx at xx-xxxx-xxxxx-xxxx.xx>, box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3530]: expunged: uid=116000, msgid=<xxxxxxxxxxxxxxxxxxxxxxxxxxxx.xxxxxxx.xxxxxxx at xx-xxxx-xxxxx-xxxx.xx>, box=box0 dovecot: Mar 20 17:55:07 Info: IMAP(dvtest) [3530]: expunged: uid=116004, msgid=<xxxxxxxx.xxxxxxx at xx-xxxx-xxxxx-xxxx.xx>, box=box0 dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3530]: expunged: uid=116008, msgid=<xxxxxxxxxxxx.xxxxxxxxxxxxxx at xx-xxxx.xxx.xx-xxxx-xxxxx-xxxx.xx>, box=box0 dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3530]: expunged: uid=116018, msgid=<xxxxxxxx.xxxxxxx at xx-xxxx-xxxxx-xxxx.xx>, box=box0 dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3530]: Disconnected dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3504]: expunged: uid=115926, msgid=(null), box=box0 [[snip 40 identical lines]] dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3461]: expunged: uid=115960, msgid=(null), box=box0 dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3461]: expunged: uid=115961, msgid=(null), box=box0 dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3504]: Disconnected: Too many invalid IMAP commands. dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3461]: expunged: uid=115981, msgid=(null), box=box0 dovecot: Mar 20 17:55:08 Info: IMAP(dvtest) [3461]: Disconnected: Mailbox is in inconsistent state, please relogin. Bye, - -- Steffen Kaiser -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.6 (GNU/Linux) iQEVAwUBRgDsXi9SORjhbDpvAQJKAwf+NqNFsXb0DWkFm7hMV03dlqONpI9cTbqS gNLCooXiyjLM8E74PjrSzKflYjq94cRwkud+vO0Nf9h8uqtJyIjIOXYT3gSoKCo2 ceRsdmoiQXmYwsywx+uWvTNKgy7wnIRd4zpkKE00R3KzAZ4UMl2Cul+oTzrzTENi rN+JX0giDLPQ73hS1pTDAaJ9fkXT3Or0obr8C8NWlquHiaq/02kpCYUnJvJUx8+h DHmZ60aj2D4sbiyxK7dUOlepuLSsmPnAA/Z/DHnGO0TRvaHVbWTN2YmCAFRJrawF DHk8N7IwWDhQYPPQl8LEohmTIyZwKSHZixGWACsqTu5Jsh7ovVYEAQ==+8ZV -----END PGP SIGNATURE-----
On Tue, 2007-03-20 at 12:26 +0100, Steffen Kaiser wrote:> - 46. stalled for 1786 secs in APPENDI started getting these also after enabling quota and using 100 clients. I guess the Maildir++ counting just slows it down so much that processes start to hang. With 10 clients there were no hangs.> maildir_copy_preserve_filename: yesThis setting also doesn't seem to work that great with stress testing, causing the "Append with UID x but next_uid is y" errors. I'll see if I can get it fixed. I also found some bugs related to saving mails with maildir when quota plugin is enabled. -------------- next part -------------- A non-text attachment was scrubbed... Name: signature.asc Type: application/pgp-signature Size: 189 bytes Desc: This is a digitally signed message part URL: <http://dovecot.org/pipermail/dovecot/attachments/20070323/849435c3/attachment.bin>