modprobe slow linear search of /lib/modules/`uname -r`/modules.deps

[William Cohen <wcohen at redhat dot com>]

I took Daniel Barrange's bootprobe techniques
(http://people.redhat.com/berrange/systemtap/bootprobe/) for SystemTap
and wrote a little script (iotime.stp) that looked at the time spent
in the reads/write systemtcalls. One of the thing that became
apparent was the amount of data read from /lib/modules/`uname
-r`/modules.dep and the time reading the data. modprobe is not smart
at all about reading the file; it just does a linear search and stops
when it finds the first matching entry.

Wouldn't it make sense to place the modules that are actually loaded
at the beginning of the modules.dep to reduce the amount of data read
by modprobe?

I wrote a simple script to examine the modules loaded and put the
entries in modules.dep at the beginning of the file.  I then replaced
the modules.dep with this modified version. I compared the data
collected with bootchart.  The boot is a couple seconds faster for the
modified version (1:05 vs 1:07) on AMD64 rawhide machine. bootchart periodically 
samples all the entries in /proc.  Looking at the raw data from boot probe there 
are significantly fewer samples with modprobe in the modified version.

            all states    D state
            modprobe    modprobe
            samples        samples
normal    modules.dep    120        73
reordered modules.deps    63        27

The remix_modules and iotime.stp are attached.

-Will
/*
 * Copyright (C) 2006 Daniel Berrange, Red Hat Inc.
 * Copyright (C) 2007 Will Cohen, Red Hat, Inc.
 * 
 * This copyrighted material is made available to anyone wishing to use,
 * modify, copy, or redistribute it subject to the terms and conditions
 * of the GNU General Public License v.2.
 *
 * You should have received a copy of the GNU General Public License
 * along with this program; if not, write to the Free Software Foundation,
 * Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
 *
 * Print out the amount of time spent in the read and write systemcall
 * when a process closes each file is closed. Note that the systemtap 
 * script needs to be running before the open operations occur for
 * the script to record data.
 *
 * This script could be used to to find out which files are slow to load
 * on a machine. e.g.
 *
 * stap iotime.stp -c 'firefox'
 *
 * Output format is:
 * timestamp pid (executabable) info_type path ...
 *
 * 200283135 2573 (cupsd) access /etc/printcap read: 0 write: 7063
 * 200283143 2573 (cupsd) iotime /etc/printcap time: 69
 *
 */

global start
global entry_io
global fd_io
global time_io

function timestamp:long() {
  return gettimeofday_us() - start
}

function proc:string() {
  return sprintf("%d (%s)", pid(), execname())
}

probe begin {
 start = gettimeofday_us()
}

global filenames
global filehandles
global fileread
global filewrite

probe syscall.open {
  filenames[pid()] = user_string($filename)
} 

probe syscall.open.return {
  if ($return != -1) {
    filehandles[pid(), $return] = filenames[pid()]
    fileread[pid(), $return] = 0
    filewrite[pid(), $return] = 0
  } else {
    printf("%d %s access %s fail\n", timestamp(), proc(), filenames[pid()])
  }
  delete filenames[pid()]
}

probe syscall.read {
  if ($count > 0) {
    fileread[pid(), $fd] += $count
  }
  t = gettimeofday_us(); p = pid()
  entry_io[p] = t
  fd_io[p] = $fd
}

probe syscall.read.return {
  t = gettimeofday_us(); p = pid()
  fd = fd_io[p]
  time_io[p,fd] <<< t - entry_io[p]
}

probe syscall.write {
  if ($count > 0) {
    filewrite[pid(), $fd] += $count
  }
  t = gettimeofday_us(); p = pid()
  entry_io[p] = t
  fd_io[p] = $fd
}

probe syscall.write.return {
  t = gettimeofday_us(); p = pid()
  fd = fd_io[p]
  time_io[p,fd] <<< t - entry_io[p]
}

probe syscall.close {
  if (filehandles[pid(), $fd] != "") {
    printf("%d %s access %s read: %d write: %d\n",  timestamp(), proc(),
	filehandles[pid(), $fd], fileread[pid(), $fd], filewrite[pid(), $fd])
    if (@count(time_io[pid(), $fd]))
      printf("%d %s iotime %s time: %d\n",  timestamp(), proc(),
	filehandles[pid(), $fd], @sum(time_io[pid(), $fd]))
   }
  delete fileread[pid(), $fd]
  delete filewrite[pid(), $fd]
  delete filehandles[pid(), $fd]
  delete fd_io[pid()]
  delete entry_io[pid()]
  delete time_io[pid(),$fd]
}

#/bin/sh
#
# A simple little script to generate prepend the list of modules 
# dependencies to the beginning of the list. This is a simple
# attempt to speed up the modprobe on bootup.
#

MODULES_DEP=/lib/modules/`uname -r`/modules.dep

#find the list of modules currently installed
used_modules=`/sbin/lsmod|awk  '{print $1}' | tr "_" "."`

for m in $used_modules; do
	grep "$m\.ko:" $MODULES_DEP
done

cat  $MODULES_DEP