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 at
example.com>\nE"...,
4096, 0) = 3841
17:19:31.725525 pread(11, "", 255, 3841) = 0
17:19:31.725624 pread(11, "Return-path: <dino at
example.com>\nE"...,
4096, 0) = 3841
17:19:31.725729 pread(11, "Return-path: <dino at
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 at
example.com>\nE"...,
4096, 0) = 2263
17:19:38.973282 pread(11, "", 1833, 2263) = 0
17:19:38.973382 pread(11, "Return-path: <dino at
example.com>\nE"...,
4096, 0) = 2263
17:19:38.973488 pread(11, "Return-path: <dino at
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 at
example.com>\nE"...,
4096, 0) = 3764
17:19:39.013845 pread(11, "", 332, 3764) = 0
17:19:39.013906 pread(11, "Return-path: <dino at
example.com>\nE"...,
4096, 0) = 3764
17:19:39.013999 pread(11, "Return-path: <dino at
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 at
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 at
example.com>\nE"...,
4096, 0) = 4096
17:19:39.054115 pread(11, "Return-path: <dino at
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 at
example.com>\nE"...,
4096, 0) = 2510
17:19:42.805170 pread(11, "", 1586, 2510) = 0
17:19:42.805271 pread(11, "Return-path: <dino at
example.com>\nE"...,
4096, 0) = 2510
17:19:42.805376 pread(11, "Return-path: <dino at
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
Timo Sirainen
2008-Jan-23 15:51 UTC
[Dovecot] Slow header fetching rate over nfs mailspool.
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 at example.com>\nE"..., > 4096, 0) = 2263 > 17:19:38.973282 pread(11, "", 1833, 2263) = 0Is 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. -------------- 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/20080123/e9a0d444/attachment-0002.bin>
Timo Sirainen
2008-Jan-23 17:39 UTC
[Dovecot] Slow header fetching rate over nfs mailspool.
On Thu, 2008-01-24 at 00:18 +0800, Dino Ming wrote:> open("/dap/mstorage/example.com/dino/Maildir/cur", O_RDONLY| > O_NONBLOCK|O_DIRECTORY) = 8 <0.000098>..> getdents64(8, /* 114 entries */, 8192) = 8128 <0.347680> > getdents64(8, /* 113 entries */, 8192) = 8136 <1.385329> > getdents64(8, /* 113 entries */, 8192) = 8144 <1.668419> > getdents64(8, /* 113 entries */, 8192) = 8136 <2.942874> > getdents64(8, /* 107 entries */, 8192) = 7712 <5.346971> > getdents64(8, /* 0 entries */, 8192) = 0 <0.000046>This means that a simple "ls" call on that cur directory would take about 11 seconds (when the directory entries aren't already cached). You could verify that this happens. So I can't really say anything else than that the problem is somewhere outside Dovecot.. -------------- 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/20080123/27e32952/attachment-0002.bin>
Hi Timo, I did a test with manully perform ls a hunderd times on the /dap/mstorage/example.com/dino/Maildir/cur but the response is very fast and without the strange delay like inside dovecot. With 558 emails inside the cur directory. The time to execute the ls is just real 0m0.061s user 0m0.008s sys 0m0.008s Regards, Dino On 24 Jan 2008, at 1:39 AM, Timo Sirainen wrote:> On Thu, 2008-01-24 at 00:18 +0800, Dino Ming wrote: >> open("/dap/mstorage/example.com/dino/Maildir/cur", O_RDONLY| >> O_NONBLOCK|O_DIRECTORY) = 8 <0.000098> > .. >> getdents64(8, /* 114 entries */, 8192) = 8128 <0.347680> >> getdents64(8, /* 113 entries */, 8192) = 8136 <1.385329> >> getdents64(8, /* 113 entries */, 8192) = 8144 <1.668419> >> getdents64(8, /* 113 entries */, 8192) = 8136 <2.942874> >> getdents64(8, /* 107 entries */, 8192) = 7712 <5.346971> >> getdents64(8, /* 0 entries */, 8192) = 0 <0.000046> > > This means that a simple "ls" call on that cur directory would take > about 11 seconds (when the directory entries aren't already cached). > You > could verify that this happens. > > So I can't really say anything else than that the problem is somewhere > outside Dovecot.. >