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.. >