[Dovecot] Slow header fetching rate over nfs mailspool.

[Dino Ming]

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