[Dovecot] Slow header fetching rate over nfs mailspool.
We are setting up a Dovecot over a pair of NFS which mirrored with DRBD +Heartbeat, under Debian Etch AMD64 with Kernel 2.6.22-5.
The problem was slow header downloading rate. We had tried to use
postal to inject 500 emails which are under 5KB each,
but when ever we start up Mail.app, Thunderbird or even OE6, the
header download rate is terrible slow.
Its look like a few sec for just 1 header download from the strace of
the dovecot process, sometime, it maybe longer
and this leading to the MUA hang.
We had tried dove 1.0.rc15-2etch3, 1.1beta13... and the following
configuration is for 1.1beta13.
Mount options on Dovecot frontend
nfs4 rsize=8192,wsize=8192,hard,fg,proto=tcp,retrans=0,noatime
Export option on NFS backend
/dap/mail
192.168.2.0
/24(rw,no_subtree_check,no_root_squash,no_all_squash,sync,fsid=0)
/dap/mail/mstorage
192.168.2.0/24(rw,no_subtree_check,no_root_squash,no_all_squash,sync)
Dovecot Config dump.
base_dir = /var/run/dovecot/
protocols = pop3 imap
disable_plaintext_auth = no
log_path = /var/log/dovecot.log
info_log_path = /var/log/dovecot-info.log
log_timestamp = "%Y-%m-%d %H:%M:%S "
ssl_disable = yes
login_dir = /var/run/dovecot/login
login_chroot = yes
login_user = dovecot
login_processes_count = 10
login_max_processes_count = 20
login_process_per_connection = yes
mail_debug = yes
max_mail_processes = 1024
mail_process_size = 256
mail_location = maildir:~/Maildir:INDEX=/var/indexes/%u (Indexes is
putting on local disk, but same with no luck)
auth_process_size = 128
auth_cache_size = 32
auth_cache_ttl = 3600
auth_verbose = yes
auth_debug = no
auth_debug_passwords = no
auth_worker_max_count = 50
namespace private { separator = / prefix = INBOX/ inbox = yes }
mail_extra_groups = mail mmap_disable = no lock_method = fcntl mail_nfs_storage = yes mail_nfs_index = no dotlock_use_excl = no fsync_disable = no
Strace Log file of dovecot during thunderbird download those headers.
17:19:27.670428 open("/dap/mstorage/example.com/dino/Maildir/cur/
1201079181.H112920P11724.mx01.example.com,S=3841:2,", O_RDONLY) = 11
17:19:27.670631 fstat(11, {st_mode=S_IFREG|0600, st_size=3841, ...}) = 0
17:19:27.670691 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 3841
17:19:31.725525 pread(11, "", 255, 3841) = 0
17:19:31.725624 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 3841
17:19:31.725729 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 3841
17:19:31.725798 close(11) = 0
17:19:31.725887 open("/dap/mstorage/example.com/dino/Maildir/cur/
1201079181.H210436P11742.mx01.example.com,S=2263:2,", O_RDONLY) = 11
17:19:31.726127 fstat(11, {st_mode=S_IFREG|0600, st_size=2263, ...}) = 0
17:19:31.726193 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 2263
17:19:38.973282 pread(11, "", 1833, 2263) = 0
17:19:38.973382 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 2263
17:19:38.973488 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 2263
17:19:38.973559 close(11) = 0
17:19:38.973645 open("/dap/mstorage/example.com/dino/Maildir/cur/
1201079181.H210590P11751.mx01.example.com,S=3764:2,", O_RDONLY) = 11
17:19:38.973900 fstat(11, {st_mode=S_IFREG|0600, st_size=3764, ...}) = 0
17:19:38.973967 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 3764
17:19:39.013845 pread(11, "", 332, 3764) = 0
17:19:39.013906 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 3764
17:19:39.013999 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 3764
17:19:39.014066 close(11) = 0
17:19:39.014129 open("/dap/mstorage/example.com/dino/Maildir/cur/
1201079181.H297801P11758.mx01.example.com,S=6890:2,", O_RDONLY) = 11
17:19:39.014331 fstat(11, {st_mode=S_IFREG|0600, st_size=6890, ...}) = 0
17:19:39.014391 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 4096
17:19:39.053878 pread(11, "~b_])!5b\'8rIwz/mmG31A}yr*9\'uC!$<"...,
4095, 4096) = 2794
17:19:39.053963 pread(11, "", 1301, 6890) = 0
17:19:39.054022 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 4096
17:19:39.054115 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 4096
17:19:39.054182 close(11) = 0
17:19:39.054245 open("/dap/mstorage/example.com/dino/Maildir/cur/
1201079181.H308343P11761.mx01.example.com,S=2510:2,", O_RDONLY) = 11
17:19:39.054448 fstat(11, {st_mode=S_IFREG|0600, st_size=2510, ...}) = 0
17:19:39.054508 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 2510
17:19:42.805170 pread(11, "", 1586, 2510) = 0
17:19:42.805271 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 2510
17:19:42.805376 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 2510
17:19:42.805441 write(1, "* 272 FETCH (UID 3838 RFC822.SIZ"..., 2146)
= 2146
17:19:42.805503 close(11) = 0
On Wed, 2008-01-23 at 17:39 +0800, Dino Ming wrote:
17:19:31.726127 fstat(11, {st_mode=S_IFREG|0600, st_size=2263, ...}) = 0 17:19:31.726193 pread(11, "Return-path: dino@example.com\nE"...,
4096, 0) = 2263 17:19:38.973282 pread(11, "", 1833, 2263) = 0
Is it spending 7 seconds trying to do the second pread(), or is Dovecot doing something else for 7 seconds? What does strace -T show as the time spent in syscalls?
To me this looks like a problem with your network or your NFS server.
participants (2)
-
Dino Ming
-
Timo Sirainen