Suddenly slow lstat syscalls on CURRENT from Juli

From: Beat Gätzi <beat_at_chruetertee.ch>
Date: Sat, 01 Jan 2011 13:15:36 +0100
Hi,

Since a couple of days commands like ls(1) are very slow on one of my
tinderboxes. Checking with ktrace/kdump I see that the lstat syscall
takes about one second:

 70559 ls       0.004644 CALL  lstat(0x284472f8,0x28447298)
 70559 ls       0.004651 NAMI  "Mk"
 70559 ls       0.004664 STRU  struct stat {... }
 70559 ls       0.004672 RET   lstat 0
 70559 ls       0.004688 CALL  lstat(0x2844a1b8,0x2844a158)
 70559 ls       0.004696 NAMI  "README,v"
 70559 ls       1.004245 STRU  struct stat {...}
 70559 ls       1.004263 RET   lstat 0
 70559 ls       1.004277 CALL  lstat(0x2844a2b8,0x2844a258)
 70559 ls       1.004286 NAMI  ".cvsignore,v"
 70559 ls       2.004282 STRU  struct stat {...}
 70559 ls       2.004302 RET   lstat 0
 70559 ls       2.004316 CALL  lstat(0x2844a3b8,0x2844a358)
 70559 ls       2.004325 NAMI  "CHANGES,v"
 70559 ls       3.004275 STRU  struct stat {...}
 70559 ls       3.004296 RET   lstat 0
 70559 ls       3.004310 CALL  lstat(0x2844a4b8,0x2844a458)
 70559 ls       3.004318 NAMI  "COPYRIGHT,v"
 70559 ls       4.004300 STRU  struct stat {...}
 70559 ls       4.004318 RET   lstat 0

When i immediately re-execute the command in the same directory it looks
normal:

 78007 ls       0.004665 CALL  lstat(0x284472f8,0x28447298)
 78007 ls       0.004673 NAMI  "Mk"
 78007 ls       0.004686 STRU  struct stat {...}
 78007 ls       0.004693 RET   lstat 0
 78007 ls       0.004708 CALL  lstat(0x2844a1b8,0x2844a158)
 78007 ls       0.004715 NAMI  "README,v"
 78007 ls       0.004728 STRU  struct stat {...}
 78007 ls       0.004735 RET   lstat 0
 78007 ls       0.004742 CALL  lstat(0x2844a2b8,0x2844a258)
 78007 ls       0.004749 NAMI  ".cvsignore,v"
 78007 ls       0.004761 STRU  struct stat {...}
 78007 ls       0.004768 RET   lstat 0
 78007 ls       0.004775 CALL  lstat(0x2844a3b8,0x2844a358)
 78007 ls       0.004782 NAMI  "CHANGES,v"
 78007 ls       0.004795 STRU  struct stat {...}
 78007 ls       0.004802 RET   lstat 0
 78007 ls       0.004809 CALL  lstat(0x2844a4b8,0x2844a458)
 78007 ls       0.004817 NAMI  "COPYRIGHT,v"
 78007 ls       0.004828 STRU  struct stat {...}
 78007 ls       0.004835 RET   lstat 0

System is a HP DL360 G3 with a Compaq Smart Array 5i controller. There
is no evidence of a RAID controller or hard disk problem in the system
logs. Also writing to a file and reading from a file looks normal.
The running kernel is a GENERIC kernel from Juli without debugging options:

# uname -a
FreeBSD tinderbox.chruetertee.ch 9.0-CURRENT FreeBSD 9.0-CURRENT #5
r209980: Tue Jul 13 11:25:50 CEST 2010
root_at_tinderbox.chruetertee.ch:/usr/obj/usr/home/beat/dev/src/head/sys/BEASTIE
 i386

# uptime
12:22pm  up 170 days, 20:13, 2 users, load averages: 0.00, 0.00, 0.00

Does anybody knows what could cause such a behavior or how to track this
down?

Thanks,
Beat
Received on Sat Jan 01 2011 - 11:15:34 UTC

This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:40:10 UTC