How much time are the read/write system calls taking

[William Cohen <wcohen at redhat dot com>]

Hi all,

I was curious about where time was being spent when the machine started up. I 
started with the bootprobe and process-file probes in 
http://people.redhat.com/berrange/systemtap/. The bootprobe provides describes 
how to set up a script to run when the machine boots. The process-file shows 
file accesses.

In particular I modified Daniel's process-files.stap to accumulate the amount of 
time spent in the read and write systemcalls. The script is just looking at wall 
clock time. It is going to be very useful for the writes because those 
operations are going to be buffered up and flushed to the disk at some other 
time. However, I expect that there might be some useful information for the 
reads. If the file has to be accessed off disk the read is not going to complete 
until the data has been fetched. Looking at the trace gives some clue which 
processes/files require a lot time.

The script is attached, process-files4.stap. I modified the script for to avoid 
using the 0/"" as delete operations.

I ran a simple experiment booting up a FC6 machine running a locally built FC6 
kernel, but this script could be just as easily used look at starting up a task, 
e.g. (stap -g process-files4.stap -c "firefox"). The compressed log for firefox 
startup is attached.

Below is looking at the things that have the largest accumulations of IO times 
for bootup on the machine; the log file is a bit large to attach. The 
modules.dep and various .ko files are towards the top of the list.

I was thinking it would be nice to have instrumentation to look at which 
processes are sleeping or waiting for other events and then use this information 
to find critical paths in the code. Then have something that looks through the 
log file to identify processes and operations that are holding things up.

-Will


$ grep iotime fc6iotimes_20070108.log |sort -nrk 7|head -n 20
10049986 785 (pcmcia-socket-s) iotime 
/sys/class/pcmcia_socket/pcmcia_socket0/available_resources_io time: 816284
8682689 640 (udev_run_hotplu) iotime /lib/libc.so.6 time: 698020
8759101 662 (modprobe) iotime 
/lib/modules/2.6.18-stock/kernel/sound/core/snd-pcm.ko time: 606052
3386002 1 (init) iotime /selinux//load time: 528235
10875046 1143 (vol_id) iotime /dev/.tmp-3-1 time: 368101
9608302 563 (modprobe) iotime 
/lib/modules/2.6.18-stock/kernel/drivers/net/wireless/airo.ko time: 344454
10345087 974 (vol_id) iotime /dev/.tmp-3-5 time: 334310
31556034 2091 (dbus-daemon) iotime /etc/dbus-1/system.d/gnome-power-manager.conf 
time: 292526
8797613 506 (modprobe) iotime 
/lib/modules/2.6.18-stock/kernel/drivers/cdrom/cdrom.ko time: 289193
10774901 1135 (vol_id) iotime /dev/.tmp-3-3 time: 279866
18288883 1514 (modprobe) iotime 
/lib/modules/2.6.18-stock/kernel/net/ipv6/ipv6.ko time: 273499
8948958 671 (modprobe) iotime 
/lib/modules/2.6.18-stock/kernel/drivers/block/floppy.ko time: 250969
8768580 679 (modprobe) iotime 
/lib/modules/2.6.18-stock/kernel/sound/core/snd-pcm.ko time: 245145
7996631 582 (modprobe) iotime /lib/modules/2.6.18-stock/modules.dep time: 240950
7905347 565 (modprobe) iotime /lib/modules/2.6.18-stock/modules.dep time: 239156
36776828 2201 (automount) iotime /usr/lib/autofs/lookup_nisplus.so time: 234972
7892458 581 (modprobe) iotime /lib/modules/2.6.18-stock/modules.dep time: 229659
35273156 2174 (S26hidd) iotime /etc/sysconfig/hidd time: 222505
7868487 564 (modprobe) iotime /lib/modules/2.6.18-stock/modules.dep time: 207937
10708476 1139 (vol_id) iotime /dev/.tmp-3-2 time: 207539
/*
 * Copyright (C) 2006 Daniel Berrange, 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
 *
*/

global start
global entry_io
global fd_io
global time_io


function get_usertime:long() %{
  THIS->__retvalue = current->utime + current->signal->utime;
%}

function get_systime:long() %{
  THIS->__retvalue = current->stime + current->signal->stime;
%}

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

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

probe begin {
 start = gettimeofday_us()
}

probe syscall.fork.return {
  printf("%d %s fork %d\n", timestamp(), proc(), $return)
}

probe syscall.execve {
  printf("%d %s exec %s\n", timestamp(), proc(), kernel_string($filename))
}

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]
}

probe syscall.exit {
  printf("%d %s exit user: %d sys: %d\n", timestamp(), proc(), get_usertime(), get_systime())
}

Attachment: fc6_firefox_20070108.log.gz
Description: Unix tar archive