On Sat Jan 1 11, Beat Gätzi wrote:
> 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
> r...@tinderbox.chruetertee.ch:/usr/obj/usr/home/beat/dev/src/head/sys/BEASTIE
> i386
no problems here.
first 'ls':
...
58144 ls 0.166961 CALL lstat(0x800c4cf08,0x800c4ce90)
58144 ls 0.166998 RET lstat 0
58144 ls 0.167019 CALL lstat(0x800c4d048,0x800c4cfd0)
58144 ls 0.167061 RET lstat 0
58144 ls 0.167066 CALL lstat(0x800c4d188,0x800c4d110)
58144 ls 0.167089 RET lstat 0
58144 ls 0.167093 CALL lstat(0x800c4d2c8,0x800c4d250)
58144 ls 0.216333 RET lstat 0
58144 ls 0.216345 CALL lstat(0x800c4d408,0x800c4d390)
58144 ls 0.216380 RET lstat 0
58144 ls 0.216385 CALL lstat(0x800c4d548,0x800c4d4d0)
58144 ls 0.216687 RET lstat 0
58144 ls 0.216695 CALL lstat(0x800c4d688,0x800c4d610)
58144 ls 0.216720 RET lstat 0
58144 ls 0.216725 CALL lstat(0x800c4d7c8,0x800c4d750)
58144 ls 0.216748 RET lstat 0
58144 ls 0.216752 CALL lstat(0x800c4d908,0x800c4d890)
58144 ls 0.216788 RET lstat 0
58144 ls 0.216793 CALL lstat(0x800c4da48,0x800c4d9d0)
58144 ls 0.216814 RET lstat 0
58144 ls 0.216818 CALL lstat(0x800c4db88,0x800c4db10)
58144 ls 0.216835 RET lstat 0
second 'ls':
...
58158 ls 0.005801 CALL lstat(0x800c4cf08,0x800c4ce90)
58158 ls 0.005817 RET lstat 0
58158 ls 0.005827 CALL lstat(0x800c4d048,0x800c4cfd0)
58158 ls 0.005844 RET lstat 0
58158 ls 0.005849 CALL lstat(0x800c4d188,0x800c4d110)
58158 ls 0.005870 RET lstat 0
58158 ls 0.005875 CALL lstat(0x800c4d2c8,0x800c4d250)
58158 ls 0.005891 RET lstat 0
58158 ls 0.005896 CALL lstat(0x800c4d408,0x800c4d390)
58158 ls 0.005912 RET lstat 0
58158 ls 0.005917 CALL lstat(0x800c4d548,0x800c4d4d0)
58158 ls 0.005933 RET lstat 0
58158 ls 0.005938 CALL lstat(0x800c4d688,0x800c4d610)
58158 ls 0.005955 RET lstat 0
58158 ls 0.005959 CALL lstat(0x800c4d7c8,0x800c4d750)
58158 ls 0.005981 RET lstat 0
58158 ls 0.005986 CALL lstat(0x800c4d908,0x800c4d890)
58158 ls 0.006002 RET lstat 0
58158 ls 0.006006 CALL lstat(0x800c4da48,0x800c4d9d0)
58158 ls 0.006023 RET lstat 0
58158 ls 0.006028 CALL lstat(0x800c4db88,0x800c4db10)
58158 ls 0.006043 RET lstat 0
...seems like the usual time improvement due to caching.
this is under:
'uname -a':
FreeBSD otaku 9.0-CURRENT FreeBSD 9.0-CURRENT #0 r216763: Thu Dec 30 00:56:03
CET 2010 root@:/usr/obj/usr/subversion-src/sys/ARUNDEL amd64
'uptime':
4:04pm up 7:17, 1 user, load averages: 1,01 1,07 1,00
'diskinfo -ct ada1':
ada1
512 # sectorsize
1000204886016 # mediasize in bytes (932G)
1953525168 # mediasize in sectors
0 # stripesize
0 # stripeoffset
1938021 # Cylinders according to firmware.
16 # Heads according to firmware.
63 # Sectors according to firmware.
S246J9EZ805506 # Disk ident.
I/O command overhead:
time to read 10MB block 0.141371 sec = 0.007 msec/sector
time to read 20480 sectors 1.585743 sec = 0.077 msec/sector
calculated command overhead = 0.071 msec/sector
Seek times:
Full stroke: 250 iter in 5.347934 sec = 21.392 msec
Half stroke: 250 iter in 4.037380 sec = 16.150 msec
Quarter stroke: 500 iter in 6.783579 sec = 13.567 msec
Short forward: 400 iter in 3.569570 sec = 8.924 msec
Short backward: 400 iter in 3.197921 sec = 7.995 msec
Seq outer: 2048 iter in 0.102532 sec = 0.050 msec
Seq inner: 2048 iter in 0.105670 sec = 0.052 msec
Transfer rates:
outside: 102400 kbytes in 0.971045 sec = 105453 kbytes/sec
middle: 102400 kbytes in 0.876063 sec = 116887 kbytes/sec
inside: 102400 kbytes in 1.426225 sec = 71798 kbytes/sec
cheers.
alex
>
> # 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
--
a13x
_______________________________________________
freebsd-current@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-current
To unsubscribe, send any mail to "freebsd-current-unsubscr...@freebsd.org"
