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