How much time are the read/write system calls taking

[William Cohen]

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
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: process-files4.stap
URL: <http://sourceware.org/pipermail/systemtap/attachments/20070108/5004fc9e/attachment.ksh>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: fc6_firefox_20070108.log.gz
Type: application/x-tar
Size: 19636 bytes
Desc: not available
URL: <http://sourceware.org/pipermail/systemtap/attachments/20070108/5004fc9e/attachment.tar>