stat() takes 54 msec in a directory with 94k files (even with a big dirhash)

[Attila Nagy]

Hello,

I have a strange error on FreeBSD 7-STABLE (compiled on 7th May, just 
few commits after the release, but an earlier kernel did the same).

I'm doing several parallel rsyncs from a machine to another (let's call 
them source and destination). The source contains maildirs, so there are 
some directories with a (relatively) lot of files.
The source runs an earlier (around 6.2) FreeBSD and plain softupdates 
mounted UFS2 file systems.
The destination has a bigger (UFS2) filesystem, on top of gjournal, 
mounted as async.

I've noticed that rsync sometimes stops moving data and the destination 
machine gets sluggish. After some testing, I could catch the effect in 
action (was not that hard, because it persists even for hours sometimes).

top shows around 20% system activity (there are two quad core CPUs) and 
0% user. The WCPU field at rsync shows 100%.

ktrace-ing the rsync process I can see this:
   31639 rsync    0.000004 CALL  lstat(0x7fffffffab70,0x7fffffffaf70)
   31639 rsync    0.000004 NAMI  
"hm33/00/16/uid/Maildir/new/1212536121.54673,S=3128"
   31639 rsync    0.054226 STRU  struct stat {dev=100, ino=136943662, 
mode=-rw------- , nlink=1, uid=999, gid=999, rdev=546942760, 
atime=1241807071, stime=1212536121, ctime=1241807071, 
birthtime=1212536121, size=3128, blksize=4096, blocks=8, flags=0x0 }
   31639 rsync    0.000013 RET   lstat 0
   31639 rsync    0.000018 CALL  lstat(0x7fffffffab70,0x7fffffffaf70)
   31639 rsync    0.000004 NAMI  
"hm33/00/16/uid/Maildir/new/1212537276.69702,S=4634"
   31639 rsync    0.054409 STRU  struct stat {dev=100, ino=136943663, 
mode=-rw------- , nlink=1, uid=999, gid=999, rdev=546942762, 
atime=1241807071, stime=1212537276, ctime=1241807071, 
birthtime=1212537276, size=4634, blksize=4096, blocks=12, flags=0x0 }
   31639 rsync    0.000013 RET   lstat 0
   31639 rsync    0.000020 CALL  lstat(0x7fffffffab70,0x7fffffffaf70)
   31639 rsync    0.000005 NAMI  
"hm33/00/16/uid/Maildir/new/1212537689.74390,S=3172"
   31639 rsync    0.054230 STRU  struct stat {dev=100, ino=136943664, 
mode=-rw------- , nlink=1, uid=999, gid=999, rdev=546942765, 
atime=1241807071, stime=1212537689, ctime=1241807071, 
birthtime=1212537689, size=3172, blksize=4096, blocks=8, flags=0x0 }
   31639 rsync    0.000013 RET   lstat 0

So according to ktrace, the stat call takes 54 milliseconds to return 
for each of the files.
I have tried with the default and a pretty much raised dirhash maxmem 
value, but I can still get these.
Currently I have:
vfs.ufs.dirhash_docheck: 0
vfs.ufs.dirhash_mem: 18589428
vfs.ufs.dirhash_maxmem: 209715200
vfs.ufs.dirhash_minsize: 2560
So dirhash has space to expand.

The directory in question contains 94493 files.

The source machine doesn't show this behaviour.

top's output on the destination machine:
CPU:  0.0% user,  0.0% nice, 22.7% system,  0.0% interrupt, 77.3% idle
Mem: 159M Active, 3032M Inact, 599M Wired, 47M Cache, 399M Buf, 102M Free
Swap: 4096M Total, 4096M Free

  PID USERNAME   THR PRI NICE   SIZE    RES STATE  C   TIME   WCPU COMMAND
31639 root         1 118    0 50648K 10512K CPU0   0   2:01 100.00% rsync
  634 root         1  -4    0  2536K   628K vlruwk 1   0:20  0.00% supervise
26760 root         1  44    0 25940K  3316K select 1   0:10  0.00% sshd
31640 root         1  75    0 87512K  8324K suspfs 4   0:10  0.00% rsync
31641 root         1  75    0 18904K  7124K suspfs 6   0:10  0.00% rsync
31637 root         1  75    0 40408K  7744K suspfs 4   0:09  0.00% rsync
31636 root         1  44    0 20952K  6288K select 2   0:09  0.00% rsync
31638 root         1  44    0   104M  8912K select 3   0:09  0.00% rsync
31635 root         1  75    0 80344K  7812K suspfs 4   0:09  0.00% rsync
31642 root         1  44    0 17940K  7624K select 1   0:04  0.00% ssh
31646 root         1  45    0 17940K  7656K select 1   0:03  0.00% ssh

All of the rsyncs use the same file system, but with different top level 
directories. During this, neither of the other rsyncs can run.

Any ideas about what could be done to work around this?

Thanks,