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 > root_at_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_at_:/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 -- a13xReceived on Sat Jan 01 2011 - 14:10:08 UTC
This archive was generated by hypermail 2.4.0 : Wed May 19 2021 - 11:40:10 UTC