[Dovecot] Performance problem with STATUS after upgrade (1.0.15 -> 1.2.2)
Hello list,
after upgrading dovecot from 1.0.15 to 1.2.2 (and carefully reading through the upgrading notes in the wiki), I got sieve, quota and fts up and running, but I'm now suffering some kind of performance problem with the STATUS command.
Symptoms: Reading mail on the IMAP server itself with "mutt", no TLS/SSL, connected through loopback interface. Whenever I idle a bit and then hit any key thereafter, for example to change into another mailbox, mutt will send a number of "STATUS" commands:
#
T 127.0.0.1:53604 -> 127.0.0.1:143 [AP]
DONE..a0070 STATUS "postfix-buch" (UIDNEXT UIDVALIDITY UNSEEN RECENT)..a0071 STATUS "postfix-users" (UIDNEXT UIDVALIDITY UNSEEN RECENT)..a0072 STATUS "Trash" (UIDNEXT UIDVALIDITY UNSEEN RECENT)..a0073 STATUS "Sent" (UIDNEXT UIDVALID
ITY UNSEEN RECENT)..a0074 STATUS "mailman-users" (UIDNEXT UIDVALIDITY UNSEEN RECENT)..a0075 STATUS "mailman-developers" (UIDNEXT UIDVALIDITY UNSEEN RECENT)..a0076 STATUS "de-postfix-users" (UIDNEXT UIDVALIDITY UNSEEN RECENT)..a0077
STATUS "amavis-users" (UIDNEXT UIDVALIDITY UNSEEN RECENT)..a0078 STATUS "spam" (UIDNEXT UIDVALIDITY UNSEEN RECENT)..a0079 STATUS "localreports" (UIDNEXT UIDVALIDITY UNSEEN RECENT)..a0080 STATUS "Drafts" (UIDNEXT UIDVALIDITY UNSEEN R
ECENT)..a0081 STATUS "exim-users" (UIDNEXT UIDVALIDITY UNSEEN RECENT)..
#
(The whole conversation is available as: http://www.incertum.net/~cite/dovecot-snoop.log)
Those commands take almost one(!) second to complete. I've used strace to capture what happens and made the results available at http://www.incertum.net/~cite/imap.log.
With 1.0.15, I never noticed this kind of delay, and reading mail feels really sluggish at the moment. Is there any way to improve performance?
Configuration data:
Filesystem mounted to /export/vmailboxes is an ext3:
# tune2fs -l /dev/rootvg/mailhome_lv | grep "^Filesystem features" Filesystem features: has_journal resize_inode dir_index filetype needs_recovery sparse_super large_file
(needs_recovery is set because the filesystem is mounted, I umounted it, did fsck -Dfy and it didn't display that "feature" when unmounted).
dovecot -n (also available as: http://www.incertum.net/~cite/dovecot-n.log): # 1.2.2: /etc/dovecot/dovecot.conf # OS: Linux 2.6.26-2-amd64 x86_64 Debian 5.0.2 log_timestamp: %Y-%m-%d %H:%M:%S protocols: imap imaps managesieve listen(default): *:143 listen(imap): *:143 listen(managesieve): * ssl_listen(default): *:993 ssl_listen(imap): *:993 ssl_listen(managesieve): ssl_cert_file: /etc/ssl/owncerts/mail_incertum_net.crt ssl_key_file: /etc/ssl/private/mail_incertum_net.key login_dir: /var/run/dovecot/login login_executable(default): /usr/lib/dovecot/imap-login login_executable(imap): /usr/lib/dovecot/imap-login login_executable(managesieve): /usr/lib/dovecot/managesieve-login verbose_proctitle: yes mail_privileged_group: vmail mail_location: maildir:~/Maildir mbox_write_locks: fcntl dotlock mail_executable(default): /usr/lib/dovecot/imap mail_executable(imap): /usr/lib/dovecot/imap mail_executable(managesieve): /usr/lib/dovecot/managesieve mail_process_size: 1024 mail_plugins(default): quota imap_quota fts fts_squat mail_plugins(imap): quota imap_quota fts fts_squat mail_plugins(managesieve): mail_plugin_dir(default): /usr/lib/dovecot/modules/imap mail_plugin_dir(imap): /usr/lib/dovecot/modules/imap mail_plugin_dir(managesieve): /usr/lib/dovecot/modules/managesieve lda: postmaster_address: postmaster@incertum.net hostname: mail.incertum.net mail_plugins: quota sieve auth_socket_path: /var/run/dovecot/auth-master auth default: mechanisms: plain login cram-md5 passdb: driver: sql args: /etc/dovecot/dovecot-sql.conf userdb: driver: sql args: /etc/dovecot/dovecot-sql.conf socket: type: listen client: path: /var/spool/postfix/private/auth mode: 432 user: postfix group: sasl master: path: /var/run/dovecot/auth-master mode: 384 user: vmail group: vmail plugin: quota: maildir:User quota quota_warning: storage=80%% /usr/local/bin/quota-warning.sh 80 quota_warning: storage=95%% /usr/local/bin/quota-warning.sh 95 sieve: ~/.dovecot.sieve sieve_storage: ~/sieve sieve_extensions: +imapflags fts: squat fts_squat: partial=4 full=10
SQL-Configuration:
# grep -v '^ *\(#.*\)\?$' dovecot-sql.conf driver = pgsql connect = hostaddr=333.33.33.3 port=5432 dbname=secret user=secret password=secret sslmode=require default_pass_scheme = PLAIN password_query = SELECT login AS user, password FROM virtual_user_maps WHERE login IN ('%u', '%n') user_query = SELECT vum.uid, vum.gid, ('*:storage=' || vum.quota_kbytes || 'k') AS quota_rule, ('/export/vmailboxes/' || SUBSTR(vum.login, 1, 1) || '/' || vum.login) AS home FROM virtual_mailbox_domains AS vmd LEFT JOIN virtual_mailbox_maps AS vmm ON (vmd.id = vmm.domain) LEFT JOIN virtual_user_maps AS vum ON (vmm.login = vum.id) WHERE ((vmm.localpart = '%n' AND vmd.name='%d') OR (vum.login = '%u')) AND vum.active
Memory:
# free -m total used free shared buffers cached Mem: 3952 3003 949 0 226 1036 -/+ buffers/cache: 1740 2211 Swap: 7812 5 7807
The version is Debian/unstable's 1.2.2, available at http://packages.debian.org/sid/dovecot-common, I've made a backport to Debian/stable. Any help/insights are really appreciated.
Cheers Stefan
Quick follwup to myself:
- Stefan Förster cite+dovecot-users@incertum.net:
(The whole conversation is available as: http://www.incertum.net/~cite/dovecot-snoop.log) [...] dovecot -n (also available as: http://www.incertum.net/~cite/dovecot-n.log):
I've noticed some people trying to access this URLs with the enclosing ")" still in place. Of course, the URLs are:
http://www.incertum.net/~cite/dovecot-snoop.log http://www.incertum.net/~cite/dovecot-n.log
And in case that it wasn't clear: This...
http://www.incertum.net/~cite/imap.log
...is the "strace" output.
Any help/insights are really appreciated.
Cheers Stefan
Another follow-up on my first posting:
- Stefan Förster cite+dovecot-users@incertum.net:
Those commands take almost one(!) second to complete. I've used strace to capture what happens and made the results available at http://www.incertum.net/~cite/imap.log.
Comaring this to a 1.0.15, the main difference seems to be that the "dovecot-uidlist" file is rewritten every time I issue a "STATUS" command. Here's what 1.0.15 does:
read(0, "a0071 STATUS \"postfix-users\" (UID"..., 4072) = 66
setsockopt(1, SOL_TCP, TCP_CORK, [1], 4) = 0
stat("/export/vmailboxes/c/cite/Maildir/.postfix-users", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
stat("/export/vmailboxes/c/cite/Maildir/.postfix-users/cur", {st_mode=S_IFDIR|0700, st_size=1650688, ...}) = 0
stat("/export/vmailboxes/c/cite/Maildir/.postfix-users/new", {st_mode=S_IFDIR|0700, st_size=36864, ...}) = 0
stat("/export/vmailboxes/c/cite/Maildir/.postfix-users/tmp", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
stat("/export/vmailboxes/c/cite/Maildir/.postfix-users", {st_mode=S_IFDIR|0700, st_size=4096, ...}) = 0
stat("/export/vmailboxes/c/cite/Maildir/.postfix-users/dovecot-shared", 0x7fff35082530) = -1 ENOENT (No such file or directory)
brk(0x8b0000) = 0x8b0000
gettimeofday({1249300019, 466489}, NULL) = 0
open("/export/vmailboxes/c/cite/Maildir/.postfix-users/dovecot.index", O_RDWR) = 7
alarm(120) = 0
fcntl(7, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0
alarm(0) = 120
fstat(7, {st_mode=S_IFREG|0600, st_size=289344, ...}) = 0
mmap(NULL, 289344, PROT_READ|PROT_WRITE, MAP_SHARED, 7, 0) = 0x7fde2d02c000
open("/export/vmailboxes/c/cite/Maildir/.postfix-users/dovecot.index.log", O_RDWR) = 8
fstat(8, {st_mode=S_IFREG|0600, st_size=296440, ...}) = 0
pread(8, "\1\0\30\0Y\315vJ\1\0\0\0\0\0\0\0\0\0\0\0Y\315vJ"..., 24, 0) = 24
fcntl(7, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
access("/export/vmailboxes/c/cite/Maildir/.postfix-users/cur", W_OK) = 0
stat("/export/vmailboxes/c/cite/Maildir/.postfix-users/new", {st_mode=S_IFDIR|0700, st_size=36864, ...}) = 0
stat("/export/vmailboxes/c/cite/Maildir/.postfix-users/cur", {st_mode=S_IFDIR|0700, st_size=1650688, ...}) = 0
fstat(7, {st_mode=S_IFREG|0600, st_size=289344, ...}) = 0
stat("/export/vmailboxes/c/cite/Maildir/.postfix-users/dovecot.index", {st_mode=S_IFREG|0600, st_size=289344, ...}) = 0
alarm(120) = 0
fcntl(7, F_SETLKW, {type=F_RDLCK, whence=SEEK_SET, start=0, len=0}) = 0
alarm(0) = 120
fstat(8, {st_mode=S_IFREG|0600, st_size=296440, ...}) = 0
mmap(NULL, 296440, PROT_READ, MAP_SHARED, 8, 0) = 0x7fde2cfe3000
madvise(0x7fde2cfe3000, 296440, MADV_SEQUENTIAL) = 0
fcntl(7, F_SETLK, {type=F_UNLCK, whence=SEEK_SET, start=0, len=0}) = 0
gettimeofday({1249300019, 471527}, NULL) = 0
write(1, "* STATUS \"postfix-users\" (RECENT "..., 111) = 111
setsockopt(1, SOL_TCP, TCP_CORK, [0], 4) = 0
gettimeofday({1249300019, 471961}, NULL) = 0
epoll_wait(4,
As you can see, dovecot-uidlist istn recreated.
Is this intended behaviour, some unfortunate side effect of mounting the partition with "relatime" or something completely different, perhaps something about my plugin (quota, sieve, fts)?
Ciao Stefan
Stefan Förster http://www.incertum.net/ Public Key: 0xBBE2A9E9 UNIX *is* user-friendly; it's just picky about its friends."
On Mon, 2009-08-03 at 10:01 +0200, Stefan Förster wrote:
after upgrading dovecot from 1.0.15 to 1.2.2 (and carefully reading through the upgrading notes in the wiki), I got sieve, quota and fts up and running, but I'm now suffering some kind of performance problem with the STATUS command.
Thanks, fixed: http://hg.dovecot.org/dovecot-1.2/rev/25c9df95fda6
I guess this could also explain the other v1.2 performance complaint I remember hearing about. Probably time for v1.2.3.
participants (2)
-
Stefan Förster
-
Timo Sirainen