Subject: Re: kern/35187 (Certain file operations--such as chown--take inordinate amounts of time on LFS)
To: None <kern-bug-people@netbsd.org, gnats-admin@netbsd.org,>
From: Andrew Doran <ad@netbsd.org>
List: netbsd-bugs
Date: 01/01/2007 22:40:08
The following reply was made to PR kern/35187; it has been noted by GNATS.
From: Andrew Doran <ad@netbsd.org>
To: gnats-bugs@netbsd.org
Cc:
Subject: Re: kern/35187 (Certain file operations--such as chown--take inordinate amounts of time on LFS)
Date: Mon, 1 Jan 2007 22:37:17 +0000
I have been seeing this too. Basic setup:
Filesystem 1K-blocks Used Avail Capacity iused ifree %iused Mounted on
/dev/ld0e 14535448 3111227 9969928 23% 342102 97543026 0% /local
maxvnodes ~= 128k
I did a bit of profiling, and it seems that the problem is lfs_writevnodes()
spends an unreasonable amount of time traversing the vnode list for the
mount, and in lfs_vref() -> vget().
Output from gprof is below. The numbers for Xspllower() and kernel_lock()
are a result of the activity in lfs_writevnodes().
% cumulative self self total
time seconds seconds calls ms/call ms/call name
29.29 162.03 162.03 19092 8.49 8.49 Xspllower
24.39 296.94 134.91 1122369 0.12 0.23 _kernel_lock
23.68 427.91 130.97 3948 33.17 55.33 lfs_writevnodes
7.29 468.25 40.34 176313571 0.00 0.00 vget
4.43 492.74 24.49 175754664 0.00 0.00 lfs_vref
4.06 515.21 22.47 175750428 0.00 0.00 lfs_vunref
2.01 526.34 11.13 mpidle
index % time self children called name
550 lfs_vflush <cycle 3> [740]
3398 lfs_segwrite <cycle 3> [61]
[5] 39.5 130.97 87.48 3948 lfs_writevnodes <cycle 3> [5]
24.49 40.52 175745415/175754664 lfs_vref [10]
22.47 0.00 175743764/175750428 lfs_vunref [23]
223127 lfs_writefile <cycle 3> [267]
223093 lfs_writeinode <cycle 3> [111]
12 lfs_writeseg <cycle 3> [211]
index % time self children called name
0.00 0.00 3131/175754664 lfs_mark_vnode [436]
0.00 0.00 6118/175754664 lfs_reserve [539]
24.49 40.52 175745415/175754664 lfs_writevnodes <cycle 3> [5]
[10] 11.8 24.49 40.52 175754664 lfs_vref [10]
40.21 0.31 175761681/176313571 vget [12]
index % time self children called name
0.00 0.00 16/176313571 checkalias [279]
0.00 0.00 4145/176313571 ffs_sync <cycle 3> [583]
0.00 0.00 4177/176313571 getcwd_common [114]
0.01 0.00 46692/176313571 cache_lookup [112]
0.11 0.00 496860/176313571 ufs_ihashget [125]
40.21 0.31 175761681/176313571 lfs_vref [10]
[12] 7.3 40.34 0.31 176313571 vget [12]
0.07 0.24 505279/1809247 vn_lock [69]
To repeat this:
1. Associate a large number of vnodes with the filesystem (untarring
pkgsrc.tar.gz and checking out src/sys, for example).
2. Start a few "MAKEDEV all" in the background.
3. Start a few "chown -R ... chmod -R" in the background.
4. Number of disk xfers as a result of LFS activity slows to around
10/s, and the system becomes unusable:
CPU0 states: 0.0% user, 0.0% nice, 100% system, 0.0% interrupt, 0.0% idle
CPU1 states: 0.0% user, 0.0% nice, 100% system, 0.0% interrupt, 0.0% idle
To fix, maybe alter lfs_writevnodes() to have to scan only a subset of all
vnodes which are dirty or potentially dirty. I'm not sure.