This is the mail archive of the systemtap@sourceware.org mailing list for the systemtap project.
| Index Nav: | [Date Index] [Subject Index] [Author Index] [Thread Index] | |
|---|---|---|
| Message Nav: | [Date Prev] [Date Next] | [Thread Prev] [Thread Next] |
| Other format: | [Raw text] | |
Hi,
I had been working on an ext3 tapset last month, but had to shelve it
for awhile to work on some higher-priority items. Before I did,
though, I was asked to do a quick writeup on what I had and pass it
along to some filesystem experts in the LTC. Here's what I sent to
them - I'm reposting it here now since it came up in another thread
and apparently there are people waiting for it. Anyway, I don't have
time to work on it right now but hopefully will get back to it soon...
Tom
-----------------
Hi Folks,
I've started working on a systemtap vfs/ext3 'tapset' that I'm hoping
will be useful in helping systemtap probes/script writers extract
interesting information out of a running filesystem. I've started
with ext3, and what I'm sending now is incomplete and very rough;
basically it's prototype quality at this point, but I'm sending it
anyway in the hopes of getting some early feedback before plodding on.
I'm hoping you can take a look at it and provide input such as:
- sanity check - does it basically make sense to instrument things this
way?
- special insights on where instrumentation would be useful
- special insights on how to use the data to tie things together
between subsystems e.g. vfs/io/mm
- specific examples of problems you would like to solve or data (raw
or summarized) you'd like to have at your fingertips for figuring
out whether a filesystem is working as expected or as a development
aid
I'd be especially interested in input on the final bullet item - it's
easy to instrument and brute-force trace, for instance, or even come
up with scripts that aggregate the information in simple ways, such as
the ones I've come up with so far for testing and discuss a little bit
below; it's much harder to come up with really useful scripts that
make sense of the data in powerful and non-obvious ways...
Anyway, I'm attaching a tarball that contains the current source of
the tapset, along with several example scripts. I've also provided
the complete output of a run of each of the scripts. The contents of
the tarball are as follows:
vfs-tapset/
fs/*.stp # the tapset files
*.stp # example scripts
*.out # example output (of emacs -nw junkfile; modify; sync)
I'll describe each of the scripts briefly below, along with some
sample output (full output is in the .out files), to give you some
idea of the data you can access, without having to actually run the
scripts. If you want to run the scripts, you'd use a command such as:
stap -I fs -o script.out script.stp
You might also have to add -DMAXACTION=100000 to a couple of them if
you get MAXACTION_EXCEEDED errors. My test system is a P4 x86 machine
running a git kernel, so a similar setup should work; I
had a couple of problems trying things out on an x86_64 machine, so
YMMV at this point...
Also, there's no documentation yet, but it should be pretty
straightforward to look at the tapsets and see what information is
available. For instance, for the aio_write file operation, here's the
current code:
probe ext3.fop.aio_write = kernel.function ("ext3_file_write") ?,
module("ext3").function ("ext3_file_write") ?
{
dev = $iocb->ki_filp->f_dentry->d_inode->i_sb->s_dev
devname = __find_bdevname(dev,
$iocb->ki_filp->f_dentry->d_inode->i_sb->s_bdev)
ino = $iocb->ki_filp->f_dentry->d_inode->i_ino
count = $count
pos = $pos
name = "ext3.fop.aio_write"
argstr = sprintf("%d, %d", count, pos)
size = count
units = "bytes"
}
For this probe definition, the variables that are available to the
probe handler are dev, devname, ino, count, pos, name, argstr, size,
and units (actually devname is currently broken, so will always be an
empty string). Every probe definition contains name and argstr - name
is the name of the high-level fop/aop and argstr is an ascii
representation of the important function args. These make it easy to
see basic information when tracing probes. Also, for the functions it
makes sense to do so for, size and units are available, which allows
for some simple high-level statistics to be gathered; for functions it
doesn't make sense for, size will be undefined and will resolve to 0
in the scripts. An example of using the the above probe definition in
a probe script might be something like:
probe ext3.fop.aio_write
{
printf("dev = %x, ino = %d, count %d\n", dev, ino, count)
}
So, on to some specific examples - for all of them, I started emacs on
a newly rebooted system, edited a 300k file (junkfile.txt), saved the
file, exited and then synced.
The simplest and most straightforward thing to do is a simple trace.
The ext3-trace.stp script probes all the ext3 file operation and
address space operation function entries and returns and prints a
record for each probe hit:
PROCESS OPERATION FILENAME FUNCTION
------- --------- -------- --------
bash[3763] ext3.fop.open emacs
generic_file_open(553619, emacs)
bash[3763] ext3.fop.open.ret retval = 0
bash[3763] ext3.fop.aio_read emacs
generic_file_aio_read(128, 0)
bash[3763] ext3.aop.readpages emacs ext3_readpages(4)
bash[3763] ext3.aop.mpage_readpage emacs
do_mpage_readpage(0)
bash[3763] ext3.aop.mpage_readpage.ret retval = 0xd98ea300
bash[3763] ext3.aop.mpage_readpage emacs
do_mpage_readpage(1)
bash[3763] ext3.aop.mpage_readpage.ret retval = 0xd98ea300
bash[3763] ext3.aop.mpage_readpage emacs
do_mpage_readpage(2)
bash[3763] ext3.aop.mpage_readpage.ret retval = 0xd98ea300
bash[3763] ext3.aop.mpage_readpage emacs
do_mpage_readpage(3)
bash[3763] ext3.aop.mpage_readpage.ret retval = 0xd98ea300
bash[3763] ext3.aop.readpages.ret retval = 0
bash[3763] ext3.aop.sync_page emacs
block_sync_page(0)
bash[3763] ext3.aop.sync_page.ret retval = N/A
bash[3763] ext3.fop.aio_read.ret retval = 128
bash[3763] ext3.fop.aio_read emacs
generic_file_aio_read(256, 52)
bash[3763] ext3.fop.aio_read.ret retval = 256
bash[3763] ext3.fop.aio_read emacs
generic_file_aio_read(19, 308)
bash[3763] ext3.fop.aio_read.ret retval = 19
bash[3763] ext3.fop.open ld-2.3.90.so
generic_file_open(972032, ld-2.3.90.so)
bash[3763] ext3.fop.open.ret retval = 0
bash[3763] ext3.fop.aio_read ld-2.3.90.so
generic_file_aio_read(128, 0)
bash[3763] ext3.fop.aio_read.ret retval = 128
emacs[3763] ext3.fop.mmap emacs
generic_file_mmap(0x8048000, 0x819a000, 0x1875)
emacs[3763] ext3.fop.mmap.ret retval = 0
emacs[3763] ext3.fop.mmap emacs
generic_file_mmap(0x819a000, 0x848b000, 0x101873)
emacs[3763] ext3.fop.mmap.ret retval = 0
emacs[3763] ext3.fop.aio_read ld-2.3.90.so
generic_file_aio_read(192, 52)
emacs[3763] ext3.fop.aio_read.ret retval = 192
emacs[3763] ext3.fop.mmap ld-2.3.90.so
generic_file_mmap(0xffffffffb7fdb000, 0xffffffffb7ff5000, 0x875)
emacs[3763] ext3.fop.mmap.ret retval = 0
emacs[3763] ext3.fop.mmap ld-2.3.90.so
generic_file_mmap(0xffffffffb7ff5000, 0xffffffffb7ff7000, 0x100873)
emacs[3763] ext3.fop.mmap.ret retval = 0
.
.
.
emacs[3763] ext3.fop.open junkfile.txt
generic_file_open(894470, junkfile.txt)
emacs[3763] ext3.fop.open.ret retval = 0
emacs[3763] ext3.fop.aio_read junkfile.txt
generic_file_aio_read(65536, 0)
emacs[3763] ext3.aop.readpages junkfile.txt
ext3_readpages(32)
emacs[3763] ext3.aop.mpage_readpage junkfile.txt
do_mpage_readpage(0)
emacs[3763] ext3.aop.mpage_readpage.ret retval = 0xd98ea480
emacs[3763] ext3.aop.mpage_readpage junkfile.txt
do_mpage_readpage(1)
emacs[3763] ext3.aop.mpage_readpage.ret retval = 0xd98ea480
emacs[3763] ext3.aop.mpage_readpage junkfile.txt
do_mpage_readpage(2)
emacs[3763] ext3.aop.mpage_readpage.ret retval = 0xd98ea480
emacs[3763] ext3.aop.mpage_readpage junkfile.txt
do_mpage_readpage(3)
emacs[3763] ext3.aop.mpage_readpage.ret retval = 0xd98ea480
emacs[3763] ext3.aop.mpage_readpage junkfile.txt
do_mpage_readpage(4)
emacs[3763] ext3.aop.mpage_readpage.ret retval = 0xd98ea480
emacs[3763] ext3.aop.mpage_readpage junkfile.txt
do_mpage_readpage(5)
emacs[3763] ext3.aop.mpage_readpage.ret retval = 0xd98ea480
emacs[3763] ext3.aop.mpage_readpage junkfile.txt
do_mpage_readpage(6)
emacs[3763] ext3.aop.mpage_readpage.ret retval = 0xd98ea480
.
.
.
emacs[3763] ext3.fop.open junkfile.txt
generic_file_open(893480, junkfile.txt)
emacs[3763] ext3.fop.open.ret retval = 0
emacs[3763] ext3.fop.aio_write junkfile.txt
ext3_file_write(22, 0)
emacs[3763] ext3.aop.prepare_write junkfile.txt
ext3_prepare_write(0, 22)
emacs[3763] ext3.aop.prepare_write.ret retval = 0
emacs[3763] ext3.aop.commit_write junkfile.txt
ext3_ordered_commit_write(0, 22)
emacs[3763] ext3.aop.commit_write.ret retval = 0
emacs[3763] ext3.fop.aio_write.ret retval = 22
emacs[3763] ext3.fop.aio_write junkfile.txt
ext3_file_write(16384, 22)
emacs[3763] ext3.aop.prepare_write junkfile.txt
ext3_prepare_write(22, 4096)
emacs[3763] ext3.aop.prepare_write.ret retval = 0
emacs[3763] ext3.aop.commit_write junkfile.txt
ext3_ordered_commit_write(22, 4096)
emacs[3763] ext3.aop.commit_write.ret retval = 0
emacs[3763] ext3.aop.prepare_write junkfile.txt
ext3_prepare_write(0, 4096)
emacs[3763] ext3.aop.prepare_write.ret retval = 0
emacs[3763] ext3.aop.commit_write junkfile.txt
ext3_ordered_commit_write(0, 4096)
emacs[3763] ext3.aop.commit_write.ret retval = 0
These snippets show emacs starting up, and reading and writing
junkfile.txt. Both function entry and exit are probed and the funcion
called, the associated param values (from argstr discussed above), and
the return values are displayed.
The ext3-trace-bio.stp also traces the filesystem activity, but adds
some basic block i/o tracing data to the mix, along with timestamps:
PROCESS OPERATION FILENAME TIME
FUNCTION
------- --------- -------- ----
--------
swapper[0] io.bio_endio -1 1151676488690189
sector: 58078668, done: 8
bash[3763] ext3.fop.open emacs 1151676489448969
generic_file_open(553619, emacs)
bash[3763] ext3.fop.open.ret 1151676489448983 retval = 0
bash[3763] ext3.fop.aio_read emacs 1151676489449010
generic_file_aio_read(128, 0)
bash[3763] ext3.aop.readpages emacs 1151676489449025
ext3_readpages(4)
bash[3763] vfs.add_to_page_cache emacs 1151676489449036
553619, 0, nrpages = 0
bash[3763] vfs.add_to_page_cache.ret 1151676489449045 retval
= 0
bash[3763] ext3.aop.mpage_readpage emacs 1151676489449054
do_mpage_readpage(0)
bash[3763] ext3.aop.mpage_readpage.ret 1151676489449070
retval = 0xd7db3d00
bash[3763] vfs.add_to_page_cache emacs 1151676489449076
553619, 1, nrpages = 1
bash[3763] vfs.add_to_page_cache.ret 1151676489449081 retval
= 0
bash[3763] ext3.aop.mpage_readpage emacs 1151676489449086
do_mpage_readpage(1)
bash[3763] ext3.aop.mpage_readpage.ret 1151676489449092
retval = 0xd7db3d00
bash[3763] vfs.add_to_page_cache emacs 1151676489449097
553619, 2, nrpages = 2
bash[3763] vfs.add_to_page_cache.ret 1151676489449102 retval
= 0
bash[3763] ext3.aop.mpage_readpage emacs 1151676489449107
do_mpage_readpage(2)
bash[3763] ext3.aop.mpage_readpage.ret 1151676489449112
retval = 0xd7db3d00
bash[3763] vfs.add_to_page_cache emacs 1151676489449117
553619, 3, nrpages = 3
bash[3763] vfs.add_to_page_cache.ret 1151676489449122 retval
= 0
bash[3763] ext3.aop.mpage_readpage emacs 1151676489449126
do_mpage_readpage(3)
bash[3763] ext3.aop.mpage_readpage.ret 1151676489449132
retval = 0xd7db3d00
bash[3763] io.generic_make_request emacs 1151676489449142
sector: 65373636, size: 16384, rw: R
bash[3763] ext3.aop.readpages.ret 1151676489449169 retval
= 0
bash[3763] ext3.aop.sync_page emacs 1151676489449180
block_sync_page(0)
bash[3763] ext3.aop.sync_page.ret 1151676489449225 retval
= N/A
swapper[0] io.bio_endio emacs 1151676489459331
sector: 65373636, done: 16384
bash[3763] ext3.fop.aio_read.ret 1151676489459364 retval
= 128
bash[3763] ext3.fop.aio_read emacs 1151676489459403
generic_file_aio_read(256, 52)
bash[3763] ext3.fop.aio_read.ret 1151676489459410 retval
= 256
bash[3763] ext3.fop.aio_read emacs 1151676489459417
generic_file_aio_read(19, 308)
bash[3763] ext3.fop.aio_read.ret 1151676489459423 retval
= 19
bash[3763] ext3.fop.open ld-2.3.90.so
1151676489459444 generic_file_open(972032, ld-2.3.90.so)
bash[3763] ext3.fop.open.ret 1151676489459450 retval = 0
bash[3763] ext3.fop.aio_read ld-2.3.90.so
1151676489459456 generic_file_aio_read(128, 0)
bash[3763] ext3.fop.aio_read.ret 1151676489459466 retval
= 128
emacs[3763] ext3.fop.mmap emacs 1151676489459577
generic_file_mmap(0x8048000, 0x819a000, 0x1875)
emacs[3763] ext3.fop.mmap.ret 1151676489459585 retval = 0
emacs[3763] ext3.fop.mmap emacs 1151676489459594
generic_file_mmap(0x819a000, 0x848b000, 0x101873)
emacs[3763] ext3.fop.mmap.ret 1151676489459600 retval = 0
emacs[3763] ext3.fop.aio_read ld-2.3.90.so
1151676489459607 generic_file_aio_read(192, 52)
emacs[3763] ext3.fop.aio_read.ret 1151676489459613 retval
= 192
emacs[3763] ext3.fop.mmap ld-2.3.90.so
1151676489459622 generic_file_mmap(0xffffffffb7fd3000,
0xffffffffb7fed000, 0x875)
emacs[3763] ext3.fop.mmap.ret 1151676489459627 retval = 0
emacs[3763] ext3.fop.mmap ld-2.3.90.so
1151676489459635 generic_file_mmap(0xffffffffb7fed000,
0xffffffffb7fef000, 0x100873)
emacs[3763] ext3.fop.mmap.ret
.
.
.
emacs[3763] ext3.fop.open junkfile.txt
1151676490487637 generic_file_open(893480, junkfile.txt)
emacs[3763] ext3.fop.open.ret 1151676490487648 retval = 0
emacs[3763] ext3.fop.aio_read junkfile.txt
1151676490487686 generic_file_aio_read(65536, 0)
emacs[3763] ext3.aop.readpages junkfile.txt
1151676490487705 ext3_readpages(32)
emacs[3763] vfs.add_to_page_cache junkfile.txt
1151676490487714 893480, 0, nrpages = 0
emacs[3763] vfs.add_to_page_cache.ret 1151676490487720 retval
= 0
emacs[3763] ext3.aop.mpage_readpage junkfile.txt
1151676490487728 do_mpage_readpage(0)
emacs[3763] ext3.aop.mpage_readpage.ret 1151676490487741
retval = 0xd7db3d80
emacs[3763] vfs.add_to_page_cache junkfile.txt
1151676490487746 893480, 1, nrpages = 1
emacs[3763] vfs.add_to_page_cache.ret 1151676490487751 retval
= 0
emacs[3763] ext3.aop.mpage_readpage junkfile.txt
1151676490487756 do_mpage_readpage(1)
emacs[3763] ext3.aop.mpage_readpage.ret 1151676490487762
retval = 0xd7db3d80
emacs[3763] vfs.add_to_page_cache junkfile.txt
1151676490487767 893480, 2, nrpages = 2
emacs[3763] vfs.add_to_page_cache.ret 1151676490487772 retval
= 0
emacs[3763] ext3.aop.mpage_readpage junkfile.txt
1151676490487776 do_mpage_readpage(2)
emacs[3763] ext3.aop.mpage_readpage.ret 1151676490487782
retval = 0xd7db3d80
.
.
.
emacs[3763] io.generic_make_request junkfile.txt
1151676490493816 sector: 70874404, size: 49152, rw: R
emacs[3763] ext3.aop.mpage_readpage.ret 1151676490493828
retval = 0xd7db3d00
emacs[3763] vfs.add_to_page_cache junkfile.txt
1151676490493835 893480, 13, nrpages = 13
emacs[3763] vfs.add_to_page_cache.ret 1151676490493840 retval
= 0
emacs[3763] ext3.aop.mpage_readpage junkfile.txt
1151676490493845 do_mpage_readpage(13)
emacs[3763] ext3.aop.mpage_readpage.ret 1151676490493851
retval = 0xd7db3d00
.
.
.
swapper[0] io.bio_endio junkfile.txt
1151676490502183 sector: 70874404, done: 49152
.
.
.
emacs[3763] ext3.fop.open junkfile.txt
1151676492410313 generic_file_open(894470, junkfile.txt)
emacs[3763] ext3.fop.open.ret 1151676492410325 retval = 0
emacs[3763] ext3.fop.aio_write junkfile.txt
1151676492410352 ext3_file_write(22, 0)
emacs[3763] vfs.add_to_page_cache junkfile.txt
1151676492410363 894470, 0, nrpages = 0
emacs[3763] vfs.add_to_page_cache.ret 1151676492410371 retval
= 0
emacs[3763] ext3.aop.prepare_write junkfile.txt
1151676492410380 ext3_prepare_write(0, 22)
emacs[3763] ext3.aop.prepare_write.ret 1151676492410442
retval = 0
emacs[3763] ext3.aop.commit_write junkfile.txt
1151676492410451 ext3_ordered_commit_write(0, 22)
emacs[3763] ext3.aop.commit_write.ret 1151676492410461 retval
= 0
emacs[3763] ext3.fop.aio_write.ret 1151676492410469 retval
= 22
emacs[3763] ext3.fop.aio_write junkfile.txt
1151676492410510 ext3_file_write(16384, 22)
emacs[3763] ext3.aop.prepare_write junkfile.txt
1151676492410518 ext3_prepare_write(22, 4096)
emacs[3763] ext3.aop.prepare_write.ret 1151676492410524
retval = 0
emacs[3763] ext3.aop.commit_write junkfile.txt
1151676492410532 ext3_ordered_commit_write(22, 4096)
emacs[3763] ext3.aop.commit_write.ret 1151676492410539 retval
= 0
.
.
.
sync[3765] ext3.aop.writepages junkfile.txt
1151676493910780 mpage_writepages(11920)
sync[3765] ext3.aop.writepage junkfile.txt
1151676493910788 ext3_ordered_writepage(0)
sync[3765] io.generic_make_request junkfile.txt
1151676493910798 sector: 70859044, size: 4096, rw: W
sync[3765] ext3.aop.writepage.ret 1151676493910814 retval
= 0
sync[3765] ext3.aop.writepage junkfile.txt
1151676493910820 ext3_ordered_writepage(1)
sync[3765] io.generic_make_request junkfile.txt
1151676493910827 sector: 70859052, size: 4096, rw: W
sync[3765] ext3.aop.writepage.ret 1151676493910834 retval
= 0
sync[3765] ext3.aop.writepage junkfile.txt
1151676493910839 ext3_ordered_writepage(2)
sync[3765] io.generic_make_request junkfile.txt
1151676493910847 sector: 70859692, size: 4096, rw: W
sync[3765] ext3.aop.writepage.ret 1151676493910855 retval
= 0
.
.
.
swapper[0] io.bio_endio junkfile.txt
1151676494156955 sector: 70859044, done: 4096
Using this trace data, you can track the actual sectors being read and
written by the block i/o layer in addition to the higher-level
functions causing them, and can calculate time deltas between the time
the data was submitted to the block i/o layer via generic_make_request()
and the time it was written to disk (bio_endio()).
The iotrace-addr-times.stp shows yet another trace of i/o data.
Basically this script traces time deltas between the time a bio was
activated (cfq_activate_request()) and the time it finished:
EVENT DEV FILENAME SECTOR SIZE TIME
DELTA DIRECTION
----- --- -------- ------ ---- ----
----- ---------
REQ hda6 /usr/bin/emacs 65373636 16384
1151678065659879 --- R
END hda /usr/bin/emacs 65373636 16384
1151678065667803 7847 R
REQ hda6 /usr/bin/emacs 65376212 131072
1151678065668435 --- R
END hda /usr/bin/emacs 65376212 131072
1151678065679349 10900 R
REQ hda6 /usr/X11R6/lib/libXaw3d.so.8 71255756 16384
1151678065689245 --- R
END hda /usr/X11R6/lib/libXaw3d.so.8 71255756 16384
1151678065698016 8761 R
REQ hda6 /usr/X11R6/lib/libXaw3d.so.8 71255788 32768
1151678065698660 --- R
REQ hda6 /usr/X11R6/lib/libXaw3d.so.8 71255860 253952
1151678065698686 --- R
END hda /usr/X11R6/lib/libXaw3d.so.8 71255860 253952
1151678065704248 5541 R
END hda /usr/X11R6/lib/libXaw3d.so.8 71255788 32768
1151678065704653 393 R
REQ hda6 /usr/X11R6/lib/libXmu.so.6 71245452 16384
1151678065704708 --- R
END hda /usr/X11R6/lib/libXmu.so.6 71245452 16384
1151678065710820 6101 R
REQ hda6 /usr/X11R6/lib/libXmu.so.6 71245484 32768
1151678065711458 --- R
REQ hda6 /usr/X11R6/lib/libXmu.so.6 71245556 36864
1151678065711471 --- R
END hda /usr/X11R6/lib/libXmu.so.6 71245556 36864
1151678065712087 601 R
REQ hda6 /usr/X11R6/lib/libXt.so.6 71245956 16384
1151678065712174 --- R
END hda /usr/X11R6/lib/libXmu.so.6 71245484 32768
1151678065712527 434 R
END hda /usr/X11R6/lib/libXt.so.6 71245956 16384
1151678065716449 3912 R
REQ hda6 /usr/X11R6/lib/libXt.so.6 71245988 32768
1151678065717089 --- R
REQ hda6 /usr/X11R6/lib/libXt.so.6 71246060 274432
1151678065717117 --- R
END hda /usr/X11R6/lib/libXt.so.6 71246060 274432
1151678065721766 4632 R
END hda /usr/X11R6/lib/libXt.so.6 71245988 32768
1151678065722219 443 R
REQ hda6 /usr/X11R6/lib/libSM.so.6 71239700 16384
1151678065722275 --- R
END hda /usr/X11R6/lib/libSM.so.6 71239700 16384
1151678065728016 5731 R
REQ hda6 /usr/X11R6/lib/libSM.so.6 71239732 16384
1151678065728042 --- R
END hda /usr/X11R6/lib/libSM.so.6 71239732 16384
1151678065728307 251 R
REQ hda6 /usr/X11R6/lib/libICE.so.6 71239516 16384
1151678065728359 --- R
END hda /usr/X11R6/lib/libICE.so.6 71239516 16384
1151678065728612 245 R
REQ hda6 /usr/X11R6/lib/libICE.so.6 71239548 32768
1151678065728798 --- R
REQ hda6 /usr/X11R6/lib/libICE.so.6 71239620 40960
1151678065728809 --- R
END hda /usr/X11R6/lib/libICE.so.6 71239620 40960
1151678065729340 516 R
REQ hda6 /usr/lib/libtiff.so.3 56859092 16384
1151678065729507 --- R
END hda /usr/X11R6/lib/libICE.so.6 71239548 32768
1151678065729822 475 R
END hda /usr/lib/libtiff.so.3 56859092 16384
1151678065736096 6264 R
REQ hda6 /usr/lib/libtiff.so.3 56859124 32768
1151678065736679 --- R
REQ hda6 /usr/lib/libtiff.so.3 56859196 290816
1151678065736707 --- R
END hda /usr/lib/libtiff.so.3 56859196 290816
1151678065741454 4730 R
END hda /usr/lib/libtiff.so.3 56859124 32768
1151678065744931 3466 R
REQ hda6 /usr/lib/libjpeg.so.62 56846468 16384
1151678065753362 --- R
END hda /usr/lib/libjpeg.so.62 56846468 16384
1151678065763539 10169 R
REQ hda6 /usr/lib/libjpeg.so.62 56846500 32768
1151678065764155 --- R
REQ hda6 /usr/lib/libjpeg.so.62 56846572 77824
1151678065764168 --- R
END hda /usr/lib/libjpeg.so.62 56846572 77824
1151678065765404 1221 R
REQ hda6 /usr/lib/libpng.so.3 56850860 16384
1151678065765497 --- R
END hda /usr/lib/libjpeg.so.62 56846500 32768
1151678065765876 464 R
END hda /usr/lib/libpng.so.3 56850860 16384
1151678065772169 6284 R
Tracing scripts are fine if you're willing to wade through the data to
find what you want, or need exact sequencing information; the real
power of systemtap though should be the ability to aggregate data into
higher-level summaries...
The ext3-counts.stp script makes use of the size/units fields as
described above to get a very high-level view of filesystem activity:
Counts:
ext3.aop.mpage_readpage 3242
ext3.aop.writepage 2288
ext3.aop.writepages 1460
ext3.fop.aio_read 818
ext3.aop.sync_page 428
ext3.aop.bmap 378
ext3.fop.mmap 270
ext3.aop.readpages 186
ext3.fop.aio_write 42
ext3.fop.llseek 32
ext3.aop.invalidatepage 2
Sizes:
ext3.aop.invalidatepage 2 pages
ext3.aop.mpage_readpage 3242 pages
ext3.aop.readpages 1621 pages
ext3.aop.sync_page 428 pages
ext3.aop.writepage 2288 pages
ext3.aop.writepages 541825 pages
ext3.fop.aio_read 1294201 bytes
ext3.fop.aio_write 607944 bytes
>From this we see the most-used operations, which might be useful to
identify where to drill down further.
The ext3-byexec.stp script shows the filesystem activity broken down
by executable name:
Counts:
emacs ext3.aop.mpage_readpage 3242
pdflush ext3.aop.writepage 2074
pdflush ext3.aop.writepages 1220
sync ext3.aop.writepages 1002
emacs ext3.fop.aio_read 836
kjournald ext3.aop.bmap 366
sync ext3.aop.writepage 276
sync ext3.aop.sync_page 210
emacs ext3.aop.sync_page 200
emacs ext3.aop.readpages 184
run-crons ext3.fop.aio_read 158
emacs ext3.fop.mmap 134
find ext3.fop.mmap 70
bash ext3.fop.mmap 56
on_ac_power ext3.fop.mmap 54
date ext3.fop.mmap 44
emacs ext3.fop.aio_write 42
bash ext3.fop.aio_read 40
locale ext3.fop.mmap 40
sync ext3.fop.mmap 40
on_ac_power ext3.aop.mpage_readpage 36
emacs ext3.fop.llseek 32
sh ext3.fop.mmap 30
run-crons ext3.fop.mmap 30
on_ac_power ext3.fop.aio_read 24
sh ext3.fop.aio_read 22
run-crons ext3.fop.llseek 22
touch ext3.fop.mmap 22
find ext3.fop.aio_read 20
date ext3.fop.aio_read 16
basename ext3.fop.mmap 14
mktemp ext3.fop.mmap 14
mkdir ext3.fop.mmap 14
xargs ext3.fop.mmap 14
expr ext3.fop.mmap 14
rm ext3.fop.mmap 14
run-crons ext3.aop.mpage_readpage 12
bash ext3.aop.mpage_readpage 8
locale ext3.fop.aio_read 8
cron ext3.fop.aio_read 8
on_ac_power ext3.aop.readpages 8
on_ac_power ext3.aop.sync_page 8
touch ext3.fop.aio_read 8
sync ext3.fop.aio_read 8
expr ext3.aop.mpage_readpage 6
cron ext3.fop.llseek 4
sh ext3.aop.mpage_readpage 4
basename ext3.fop.aio_read 4
mktemp ext3.fop.aio_read 4
run-crons ext3.aop.readpages 4
run-crons ext3.aop.sync_page 4
syslog-ng ext3.fop.aio_write 4
mkdir ext3.fop.aio_read 4
xargs ext3.fop.aio_read 4
expr ext3.fop.aio_read 4
rm ext3.fop.aio_read 4
bash ext3.aop.readpages 2
bash ext3.aop.sync_page 2
emacs ext3.aop.invalidatepage 2
cron ext3.fop.mmap 2
sh ext3.aop.readpages 2
sh ext3.aop.sync_page 2
run-crons ext3.fop.ioctl 2
syslog-ng ext3.aop.writepages 2
syslog-ng ext3.aop.writepage 2
syslog-ng ext3.fop.fsync 2
expr ext3.aop.readpages 2
expr ext3.aop.sync_page 2
Sizes:
sync ext3.aop.writepages 5083733 pages
emacs ext3.fop.aio_read 1278887 bytes
emacs ext3.fop.aio_write 607944 bytes
pdflush ext3.aop.writepages 382132 pages
run-crons ext3.fop.aio_read 142032 bytes
bash ext3.fop.aio_read 19474 bytes
locale ext3.fop.aio_read 12128 bytes
sync ext3.fop.aio_read 12128 bytes
on_ac_power ext3.fop.aio_read 11648 bytes
find ext3.fop.aio_read 7040 bytes
date ext3.fop.aio_read 6912 bytes
sh ext3.fop.aio_read 6886 bytes
touch ext3.fop.aio_read 3456 bytes
emacs ext3.aop.mpage_readpage 3242 pages
pdflush ext3.aop.writepage 2074 pages
emacs ext3.aop.readpages 1621 pages
basename ext3.fop.aio_read 1408 bytes
mktemp ext3.fop.aio_read 1408 bytes
mkdir ext3.fop.aio_read 1408 bytes
xargs ext3.fop.aio_read 1408 bytes
expr ext3.fop.aio_read 1408 bytes
rm ext3.fop.aio_read 1408 bytes
cron ext3.fop.aio_read 1126 bytes
syslog-ng ext3.fop.aio_write 500 bytes
sync ext3.aop.writepage 276 pages
sync ext3.aop.sync_page 210 pages
emacs ext3.aop.sync_page 200 pages
on_ac_power ext3.aop.mpage_readpage 36 pages
on_ac_power ext3.aop.readpages 18 pages
run-crons ext3.aop.mpage_readpage 12 pages
bash ext3.aop.mpage_readpage 8 pages
on_ac_power ext3.aop.sync_page 8 pages
run-crons ext3.aop.readpages 6 pages
syslog-ng ext3.aop.writepages 6 pages
expr ext3.aop.mpage_readpage 6 pages
bash ext3.aop.readpages 4 pages
sh ext3.aop.mpage_readpage 4 pages
run-crons ext3.aop.sync_page 4 pages
expr ext3.aop.readpages 3 pages
bash ext3.aop.sync_page 2 pages
emacs ext3.aop.invalidatepage 2 pages
sh ext3.aop.readpages 2 pages
sh ext3.aop.sync_page 2 pages
syslog-ng ext3.aop.writepage 2 pages
expr ext3.aop.sync_page 2 pages
This also could be used to possibly identify which programs are
causing the most activity on the system.
The ext3-bypid.stp script also shows the filesystem activity by
executable name, but adds more information by logging the pids
responsible:
Counts:
emacs[3764] ext3.aop.mpage_readpage 1628
pdflush[129] ext3.aop.writepage 1037
pdflush[129] ext3.aop.writepages 858
emacs[3764] ext3.fop.aio_read 455
sync[3766] ext3.aop.writepages 300
sync[3766] ext3.aop.writepage 175
kjournald[781] ext3.aop.bmap 140
sync[3766] ext3.aop.sync_page 123
emacs[3764] ext3.aop.sync_page 102
emacs[3764] ext3.aop.readpages 94
emacs[3764] ext3.fop.mmap 67
locale[3765] ext3.fop.mmap 48
emacs[3764] ext3.fop.aio_write 21
locale[3765] ext3.fop.aio_read 20
sync[3766] ext3.fop.mmap 20
emacs[3764] ext3.fop.llseek 16
sync[3766] ext3.fop.aio_read 8
emacs[3764] ext3.aop.invalidatepage 1
Sizes:
sync[3766] ext3.aop.writepages 3041402 pages
emacs[3764] ext3.fop.aio_read 1307239 bytes
pdflush[129] ext3.aop.writepages 634332 pages
emacs[3764] ext3.fop.aio_write 607944 bytes
locale[3765] ext3.fop.aio_read 30604 bytes
sync[3766] ext3.fop.aio_read 13190 bytes
emacs[3764] ext3.aop.mpage_readpage 3256 pages
pdflush[129] ext3.aop.writepage 2074 pages
emacs[3764] ext3.aop.readpages 1628 pages
sync[3766] ext3.aop.writepage 350 pages
sync[3766] ext3.aop.sync_page 246 pages
emacs[3764] ext3.aop.sync_page 204 pages
emacs[3764] ext3.aop.invalidatepage 2 pages
The ext3-bypidfile.stp script breaks things down even further and
shows the pids responsible, along with the files being read/written.
Note that if we can't figure out which filename corresponds to an
inode number the inode number is logged instead of the filename
(because the file was opened before the script started and we
therefore didn't catch the filename, also not addressed is the fact
that an inode may map to multiple filenames).
PROCESS FILENAME OPERATION
SIZE
------- -------- ---------
----
Sizes:
emacs[3719] junkfile.txt ext3.fop.aio_read 303924 bytes
emacs[3719] junkfile.txt ext3.fop.aio_write 303924 bytes
emacs[3719] wtmp ext3.fop.aio_read 151296 bytes
emacs[3719] locale.alias ext3.fop.aio_read 75390 bytes
sync[3721] 0 ext3.aop.writepages 33021 pages
emacs[3719] leim-list.el ext3.fop.aio_read 22199 bytes
emacs[3719] encoded-kb.elc ext3.fop.aio_read 16895 bytes
emacs[3719] resolv.conf ext3.fop.aio_read 16384
bytes
locale[3720] locale.alias ext3.fop.aio_read 16384 bytes
emacs[3719] .gnu-emacs ext3.fop.aio_read 16068
bytes
emacs[3719] rmailgen.elc ext3.fop.aio_read 12799 bytes
emacs[3719] mwheel.elc ext3.fop.aio_read 12799
bytes
emacs[3719] hosts ext3.fop.aio_read 12288 bytes
emacs[3719] locale.elc ext3.fop.aio_read 8703
bytes
emacs[3719] func-keys.elc ext3.fop.aio_read 8703 bytes
emacs[3719] locale.alias ext3.fop.aio_read 8192
bytes
emacs[3719] nsswitch.conf ext3.fop.aio_read 8192 bytes
emacs[3719] host.conf ext3.fop.aio_read 8192
bytes
sync[3721] locale.alias ext3.fop.aio_read 8192
bytes
emacs[3719] site-start.el ext3.fop.aio_read 6098 bytes
emacs[3719] utmp ext3.fop.aio_read 4608 bytes
emacs[3719] rxvt ext3.fop.aio_read 2001 bytes
emacs[3719] .emacs ext3.fop.aio_read 1637 bytes
pdflush[129] junkfile.txt ext3.aop.writepages 1077
pages
emacs[3719] emacs ext3.aop.readpages 1064 pages
emacs[3719] emacs ext3.aop.mpage_readpage 1064 pages
locale[3720] libc-2.3.90.so ext3.fop.aio_read 1024 bytes
pdflush[129] 827583 ext3.aop.writepages 1024 pages
pdflush[129] 972033 ext3.aop.writepages 1024 pages
pdflush[129] ld-2.3.90.so ext3.aop.writepages 1024
pages
pdflush[129] 486155 ext3.aop.writepages 1024 pages
pdflush[129] 488440 ext3.aop.writepages 1024 pages
pdflush[129] ld.so.cache ext3.aop.writepages 1024
pages
The iotop.stp script runs continuously, aggregating the number of
bytes sent to generic_make_request(), and dumping out the totals by
pid every few seconds. The following is the output over a couple
of minutes, mostly idle except for the emacs test:
PROCESS TOTAL (BYTES READ/WRITTEN)
------- --------------------------
kjournald[779] 3522560 (0/3522560)
PROCESS TOTAL (BYTES READ/WRITTEN)
------- --------------------------
emacs[3719] 6291456 (6291456/0)
PROCESS TOTAL (BYTES READ/WRITTEN)
------- --------------------------
emacs[3719] 761856 (761856/0)
sync[3721] 745472 (0/745472)
pdflush[129] 311296 (0/311296)
kjournald[779] 229376 (0/229376)
PROCESS TOTAL (BYTES READ/WRITTEN)
------- --------------------------
pdflush[129] 307200 (0/307200)
kjournald[779] 233472 (0/233472)
sync[3724] 221184 (0/221184)
PROCESS TOTAL (BYTES READ/WRITTEN)
------- --------------------------
PROCESS TOTAL (BYTES READ/WRITTEN)
------- --------------------------
PROCESS TOTAL (BYTES READ/WRITTEN)
------- --------------------------
PROCESS TOTAL (BYTES READ/WRITTEN)
------- --------------------------
PROCESS TOTAL (BYTES READ/WRITTEN)
------- --------------------------
PROCESS TOTAL (BYTES READ/WRITTEN)
------- --------------------------
PROCESS TOTAL (BYTES READ/WRITTEN)
------- --------------------------
kjournald[779] 532480 (0/532480)
PROCESS TOTAL (BYTES READ/WRITTEN)
------- --------------------------
This script might be useful in monitoring a system to identify where
more specific probes might be useful.
The rwpage.stp script aggregates readpage/writepage counts. Here's
output after running the emacs test after a cold start:
readpage()/writepage() counts:
EXECNAME FILE/INODE R/W PAGES
-------- ---------- --- -----
emacs[3735] emacs R 1064
pdflush[129] 827608 W 227
pdflush[129] 827603 W 216
pdflush[129] 827601 W 149
pdflush[129] 827600 W 105
emacs[3735] libtiff.so.3.8.0 R 83
emacs[3735] libXt.so.6.0 R 79
emacs[3735] junkfile.txt R 75
pdflush[129] junkfile.txt W 75
emacs[3735] libXaw3d.so.8.0 R 74
emacs[3735] libpng.so.3.1.2.8 R 63
emacs[3735] wtmp R 41
emacs[3735] libjpeg.so.62.0.0 R 31
pdflush[129] 827599 W 25
emacs[3735] libICE.so.6.4 R 22
emacs[3735] libXmu.so.6.2 R 21
emacs[3735] locale.alias R 19
emacs[3735] libXpm.so.4.11 R 16
pdflush[129] 827607 W 12
emacs[3735] libSM.so.6.0 R 8
emacs[3735] libgif.so.4.1.4 R 8
emacs[3735] libXp.so.6.2 R 7
emacs[3735] leim-list.el R 6
pdflush[129] 827605 W 5
emacs[3735] .gnu-emacs R 4
emacs[3735] encoded-kb.elc R 3
pdflush[129] 827609 W 3
emacs[3735] site-start.el R 2
emacs[3735] rmailgen.elc R 2
emacs[3735] mwheel.elc R 2
emacs[3735] subdirs.el R 1
emacs[3735] subdirs.el R 1
emacs[3735] subdirs.el R 1
emacs[3735] suse-start-po-mode.el R 1
emacs[3735] suse-start-python-mode.el R 1
emacs[3735] locale.elc R 1
emacs[3735] .emacs R 1
emacs[3735] func-keys.elc R 1
pdflush[129] 554860 W 1
pdflush[129] utmp W 1
pdflush[129] wtmp W 1
pdflush[129] 827602 W 1
pdflush[129] 846072 W 1
pdflush[129] 827604 W 1
pdflush[129] 827610 W 1
pdflush[129] 555438 W 1
sync[3737] utmp W 1
Here's the rwpage.stp output after running the test again but without
rebooting:
readpage()/writepage() counts:
EXECNAME FILE/INODE R/W PAGES
-------- ---------- --- -----
pdflush[129] 827608 W 227
pdflush[129] 827603 W 216
pdflush[129] 827601 W 149
pdflush[129] 827600 W 105
pdflush[129] junkfile.txt W 75
pdflush[129] 827599 W 25
pdflush[129] 827607 W 12
pdflush[129] 827605 W 5
pdflush[129] 827609 W 3
pdflush[129] 555438 W 1
pdflush[129] 827602 W 1
pdflush[129] 846072 W 1
pdflush[129] 827604 W 1
pdflush[129] 827610 W 1
Here, everything we need is apparently already in the page cache, as
expected, so we don't see any readpage/writepage activity related to
the emacs test (except for junkfile.txt, which was modified).
Well, that's all I have for now. If you have problems or questions,
please let me know; looking forward to your input...
Thanks,
Tom
Attachment:
vfs-tapset-0.01.tar.gz
Description: prototype ext3 tapset
| Index Nav: | [Date Index] [Subject Index] [Author Index] [Thread Index] | |
|---|---|---|
| Message Nav: | [Date Prev] [Date Next] | [Thread Prev] [Thread Next] |