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.