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] | |
Well, maybe not 101 things, but 5 at least, as described below...
Attached is a small tarball containing a 'blktrace tapset' which makes
blktrace event data available to systemtap scripts; also included are
several demo scripts that make use of the tapset in various ways.
Aside from being yet another data source available to systemtap users
in general, this tapset might also be useful to blktrace users and
developers - scripts running alongside a blktrace trace can allow
'patterns' in the data to be detected and pointed out as they happen,
with enough detail noted to allow the corresponding and complete set of
events to be located in the full blktrace trace (see the 'speculative
tracing' example described below). It might also be useful for quickly
prototyping new additions to analysis tools such as btt.
The way the blktrace tapset itself is implemented and used is a little
strange - all blktrace events are dispatched through a common function,
__blk_add_trace(), and this is the only function that's probed by the
tapset. The probe handler for that function basically demultiplexes the
event data and dispatches it to systemtap handler functions defined for
each event type. These functions are 'overridden' by the end-user
script and the event data is available as params in the overridden
callback. Please see the blktrace documentation for a full description
of all the available event types.
Things works fine this way, if you're careful - for some reason, if you
don't define overrides for *all* the callback functions, *none* of them
get called. The same thing is apparently true wrt optimization - if any
one of the callback functions gets optimized out, they all do. So in
your script, you need to define handler functions for every event type
whether you use it or not, and furthermore the bodies of the unused
handlers need to contain code that won't be optimized out - for now I
just use printf("") for that purpose. This should probably be filed as
a bug - I'm sure tapsets weren't meant to written in this way, but
still, it should probably work without these workarounds.
Note that blktrace needs to be running in order for these scripts to
have any effect - __blk_add_trace() and therefore the tapset probe
isn't actually called unless tracing is active. Of course, that means
that you need to enable CONFIG_BLK_DEV_IO_TRACE in the kernel.
Besides the blktrace tapset, there's also a 'poor man's speculative
tracing' tapset, spectrace.stp, included in the tapsets directory. It
implements a simple ring containing the n most recent events, where
'events' are nothing more than application-defined strings. Its
purpose is to enable the script to keep a continuously cycling
representation of its most recent context which it can then dump out
in case it detects 'interesting' patterns in the data; in the case of
the blktrace script, this 'context data' is a close approximation of
the last 'n' blktrace events, which are used to locate the actual
events in the real trace stream saved by blktrace. The spectrace code
is really too simple to merit its own tapset, but it doesn't belong in
the blktrace tapset, and I thought it might be useful for other
applications, so put it in a separate tapset.
I'm using a recent git kernel, and needed to apply these patches to
systemtap in order to run the scripts:
http://sources.redhat.com/ml/systemtap/2007-q1/msg00341.html
http://sourceware.org/ml/systemtap/2006-q4/msg00469.html
I've included a handful of demo scripts with the tapsets; all are
briefly describe below. Here's a summary of those:
countall.stp - display counts of all blktrace events
spectest.stp - test 'speculative tracing' support
iotop.stp - periodically display top I/O producers
topfile.stp - display read/write I/O accumulated by file
traceread.stp - trace read I/O for all or selected file
For all the scripts, you basically just run the script while running
blktrace in another shell (the blktrace and spectrace tapsets are
contained in the ./tapsets directory which needs to be included on the
stap commandline e.g.
# stap -I tapsets countall.stp
# btrace /dev/hda
Note that the meanings of the blktrace event types can be inferred from
the tapset or by reading the blktrace documentation. Briefly, though,
for the purpose of making sense of these examples, here are basically
what the most common events mean:
Q - I/O request submitted to block layer
M - request merged with previous request
D - request issued to device
C - request completed
So on to the demo scripts...
---------
countall - display counts of all blktrace events
This script just keeps a running count of all blktrace events that
have occurred over the run, broken down by event type and R/W
direction. Here are the stats collected during a kernel compile:
MAJ MIN ACTION RW(*) COUNT KiB
--- --- --------------- ----- -------- --------
3 0 backmerge R 4600 21748
3 0 backmerge W 65545 262180
3 0 backmerge RM 4 16
3 0 complete R 8537 104580
3 0 complete W 13209 316868
3 0 frontmerge W 36 144
3 0 frontmerge R 12 52
3 0 get request R 7620 79096
3 0 get request W 13636 54544
3 0 get request RM 916 3664
3 0 insert R 8536 82760
3 0 insert W 13636 54544
3 0 issue R 8536 104576
3 0 issue W 13209 316868
3 0 plug R 8621 0
3 0 queue R 12232 100896
3 0 queue W 79217 316868
3 0 queue RM 920 3680
3 0 unplug R 10031 0
3 0 unplug timer R 20 0
(*) R=Read, W=Write, A=readAhead, M=Meta, S=Sync, B=Barrier
---------
spectest - test 'speculative tracing'
This script demonstrates how systemtap scripts can be run alongside
blktrace tracing sessions, searching for patterns in the trace data
and notifying the user when they occur.
It also implements a primitive kind of 'speculative tracing' via the
included 'spectrace' tapset; basically all this means is that the
systemtap script continously records, but doesn't save to disk, the
most recent events, which are then always available to the script
whenever a certain condition is detected; in this case the events are
displayed to the user and allow the actual events in the blktrace
stream to be located for further analysis.
This script continuously tracks the blktrace event stream, calculating
for each I/O the time it took between the time it was submitted to the
block layer (q) and the time the I/O completed (c) (the 'd' in the
calculation refers to the time it was dispatched to the driver).
For this particular script, if the total time for any I/O ever goes
above 1 second, the script prints the last 15 blktrace events and
exits. The systemtap event output can then be used to locate the
actual data in the blktrace trace.
To make it easier to locate the data, it's useful to start the script
first, then start blktrace. That way, since the script won't actually
start recording data until blktrace starts tracing, the timestamps
should be similar, making it easier to locate the actual events.
Here's the output after running a kernel compile. About 6 minutes
into the compile, we detected an I/O that took more than 1 second:
q2c time > 1 second detected, dumping and exiting...
q2c ( 1.009127993) = q2d ( 0.995869990) + d2c ( 0.013258003)
Last 15 records of trace (locate complete data run in blktrace output):
3,0 0 376.050241410 9954 D W 141509292 + 16 [cc1]
3,0 0 376.063755312 9954 C W 141509292 + 16 [0]
3,0 0 376.063817162 9954 D W 141509412 + 8 [cc1]
3,0 0 376.067128381 9954 C W 141509412 + 8 [0]
3,0 0 376.067182275 9954 D W 141509436 + 8 [cc1]
3,0 0 376.070480022 9954 C W 141509436 + 8 [0]
3,0 0 376.070531315 9954 D W 141509484 + 8 [cc1]
3,0 0 376.072908834 9954 C W 141509484 + 8 [0]
3,0 0 376.072961535 9954 D W 141509540 + 8 [cc1]
3,0 0 376.073211216 9954 C W 141509540 + 8 [0]
3,0 0 376.073240432 9954 D W 141509604 + 8 [cc1]
3,0 0 376.073502322 9954 C W 141509604 + 8 [0]
3,0 0 376.073531807 9954 D W 141509700 + 8 [cc1]
3,0 0 376.077646354 9954 C W 141509700 + 8 [0]
3,0 0 376.077702407 9954 D W 141509716 + 8 [cc1]
3,0 0 376.090960410 9954 C W 141509716 + 8 [0]
Using the sector number, 141509716, we locate the actual data run in
the blktrace output. Here, we see that the I/O was queued at
374.955475225 seconds and completed at 375.964310872 seconds:
3,0 0 65269 374.955475225 99 Q W 141509716 + 8 [pdflush]
<--
3,0 0 65270 374.955488164 99 G W 141509716 + 8 [pdflush]
3,0 0 65271 374.955500263 99 I W 141509716 + 8 [pdflush]
3,0 0 65272 374.955515043 99 Q W 141509740 + 8 [pdflush]
3,0 0 65273 374.955528048 99 G W 141509740 + 8 [pdflush]
3,0 0 65274 374.955539776 99 I W 141509740 + 8 [pdflush]
3,0 0 65275 374.955554727 99 Q W 141509772 + 8 [pdflush]
3,0 0 65276 374.955567763 99 G W 141509772 + 8 [pdflush]
3,0 0 65277 374.955579546 99 I W 141509772 + 8 [pdflush]
3,0 0 65278 374.955594174 99 Q W 141509844 + 8 [pdflush]
3,0 0 65279 374.955607400 99 G W 141509844 + 8 [pdflush]
3,0 0 65280 374.955619115 99 I W 141509844 + 8 [pdflush]
3,0 0 65281 374.955633856 99 Q W 141509852 + 8 [pdflush]
3,0 0 65282 374.955646622 99 M W 141509852 + 8 [pdflush]
3,0 0 65283 374.955661292 99 Q W 141509892 + 8 [pdflush]
3,0 0 65284 374.955674590 99 G W 141509892 + 8 [pdflush]
3,0 0 65285 374.955686848 99 I W 141509892 + 8 [pdflush]
3,0 0 65286 374.955701666 99 Q W 141509900 + 8 [pdflush]
3,0 0 65287 374.955714355 99 M W 141509900 + 8 [pdflush]
3,0 0 65288 374.955729005 99 Q W 141509908 + 8 [pdflush]
3,0 0 65289 374.955741464 99 M W 141509908 + 8 [pdflush]
3,0 0 65290 374.955756111 99 Q W 141689364 + 8 [pdflush]
3,0 0 65291 374.955769133 99 G W 141689364 + 8 [pdflush]
3,0 0 65292 374.955781503 99 I W 141689364 + 8 [pdflush]
3,0 0 65293 374.964514171 9934 C W 118702868 + 24 [0]
3,0 0 65294 374.964560077 9934 D W 118752860 + 8 [cc1]
3,0 0 65295 374.969101508 9934 C W 118752860 + 8 [0]
3,0 0 65296 374.969140913 9934 D W 120539684 + 8 [cc1]
3,0 0 65297 374.972196049 9934 C W 120539684 + 8 [0]
.
.
.
3,0 0 65522 375.946551319 9954 D W 141509604 + 8 [cc1]
3,0 0 65523 375.946818577 9954 C W 141509604 + 8 [0]
3,0 0 65524 375.946842707 9954 D W 141509700 + 8 [cc1]
3,0 0 65525 375.950973348 9954 C W 141509700 + 8 [0]
3,0 0 65526 375.951013258 9954 D W 141509716 + 8 [cc1]
3,0 0 65527 375.964310872 9954 C W 141509716 + 8 [0]
<--
3,0 0 65528 375.964338113 9954 D W 141509740 + 8 [cc1]
3,0 0 65529 375.964564957 9954 C W 141509740 + 8 [0]
3,0 0 65530 375.964572025 9954 D W 141509772 + 8 [cc1]
3,0 0 65531 375.966179354 9954 C W 141509772 + 8 [0]
3,0 0 65532 375.966211534 9954 D W 141509844 + 16 [cc1]
3,0 0 65533 375.968021537 9954 C W 141509844 + 16 [0]
3,0 0 65534 375.968043594 9954 D W 141509892 + 24 [cc1]
3,0 0 65535 375.981376041 9960 C W 141509892 + 24 [0]
3,0 0 65536 375.981410612 9960 D W 141689364 + 8 [stap]
3,0 0 65537 375.985204933 9960 U R [stap] 1
3,0 0 65538 375.993949353 9954 C W 141689364 + 8 [0]
3,0 0 65539 378.707409807 1901 Q W 136659148 + 8
[kjournald]
3,0 0 65540 378.707416342 1901 G W 136659148 + 8
[kjournald]
Having access to the full trace data saved by blktrace should be
useful in analyzing why there was a lag and/or whether it was unusual.
If the blktrace data alone doesn't provide sufficient data, additional
probes and tracing/analysis code can be added to the script to provide
augmented data that could help.
---------
iotop - periodically display top I/O producers
This script displays top I/O producing processes as measured by actual
I/O queued to the device. Since most writes are deferred, if we just
directly account the write I/O to the process queing the I/O, we end
up with almost all of it accounted to pdfush and kjournald, which
isn't all that useful if we're trying to figure out exactly who's
responsible for write I/O. To make it more useful, this script tracks
dirty pages, and when the I/O is actually queued, it retrieves the
dirtying pid associated with page in the bio and accounts it to that
pid instead of e.g. pdflush.
If after looking at the iotop output, you see a process that looks
like it's doing a lot of I/O, you can use the topfile.stp script below
to see which files that process is reading/writing.
Below is part of the output of running the script while doing a kernel
compile and cold-starting firefox:
This script needs a couple extra changes to the normal commandline, so
it doesn't choke on some default systemtap limits:
# stap -I tapsets -DMAXMAPENTRIES=10000 -DMAXACTION=10000 iotop.stp
Displaying top 20 I/O producing processes every 5 seconds...
PID EXECNAME TOTAL(k) QR(k) QW(k)
-------- -------- -------- -------- --------
5356 cc1 72 72 0
5379 cc1 72 72 0
5435 cc1 52 52 0
5471 cc1 40 40 0
5491 cc1 32 32 0
5389 cc1 20 20 0
5425 cc1 20 20 0
5357 as 16 16 0
5405 cc1 16 16 0
5371 ar 12 12 0
5375 ar 12 12 0
5445 cc1 12 12 0
5455 cc1 12 12 0
5353 make 8 8 0
5368 make 8 8 0
5372 make 8 8 0
5376 make 8 8 0
5380 as 8 8 0
5367 ld 4 4 0
5366 sh 4 4 0
PID EXECNAME TOTAL(k) QR(k) QW(k)
-------- -------- -------- -------- --------
5649 firefox-bin 6388 6388 0
1900 kjournald 400 0 400
5641 cc1 200 200 0
5708 cc1 44 44 0
5617 make 24 24 0
5662 cc1 24 24 0
5472 as 20 0 20
5476 fixdep 20 0 20
5620 cc1 20 20 0
5346 fixdep 16 0 16
5361 fixdep 16 0 16
5384 fixdep 16 0 16
5400 fixdep 16 0 16
5420 fixdep 16 0 16
5430 fixdep 16 0 16
5440 fixdep 16 0 16
5450 fixdep 16 0 16
5466 fixdep 16 0 16
4543 bash 16 16 0
5350 ld 12 0 12
PID EXECNAME TOTAL(k) QR(k) QW(k)
-------- -------- -------- -------- --------
5649 firefox-bin 11392 11392 0
5727 gconfd-2 3040 3040 0
1900 kjournald 864 0 864
5546 ld 60 0 60
5548 ld 60 0 60
5798 cc1 44 44 0
5779 cc1 28 28 0
5657 fixdep 20 0 20
5667 fixdep 20 0 20
5719 cc1 20 20 0
5811 cc1 20 20 0
5496 fixdep 16 0 16
5506 fixdep 16 0 16
5522 fixdep 16 0 16
5532 fixdep 16 0 16
5542 fixdep 16 0 16
5629 fixdep 16 0 16
5677 fixdep 16 0 16
5687 fixdep 16 0 16
5703 fixdep 16 0 16
.
.
.
PID EXECNAME TOTAL(k) QR(k) QW(k)
-------- -------- -------- -------- --------
1900 kjournald 1012 0 1012
6151 ld 604 0 604
5649 firefox-bin 292 12 280
6364 cc1 284 284 0
6245 cc1 44 44 0
6236 ld 40 0 40
6360 ld 40 0 40
6273 cc1 32 32 0
6221 cc1 24 24 0
6259 cc1 24 24 0
6303 cc1 20 20 0
6313 cc1 20 20 0
6337 cc1 20 20 0
6232 fixdep 20 0 20
6147 fixdep 16 0 16
6170 fixdep 16 0 16
6180 fixdep 16 0 16
6193 fixdep 16 0 16
6206 fixdep 16 0 16
6216 fixdep 16 0 16
PID EXECNAME TOTAL(k) QR(k) QW(k)
-------- -------- -------- -------- --------
1900 kjournald 424 0 424
6380 cc1 344 344 0
6455 ld 84 0 84
6459 cc1 64 64 0
6381 as 44 0 44
6396 cc1 40 36 4
6416 cc1 28 28 0
6427 fixdep 24 8 16
6365 as 24 0 24
6375 fixdep 24 0 24
6391 fixdep 24 0 24
6397 as 20 0 20
6437 fixdep 20 0 20
5649 firefox-bin 16 0 16
6401 fixdep 16 0 16
6411 fixdep 16 0 16
6451 fixdep 16 0 16
6464 fixdep 16 0 16
6406 cc1 12 12 0
6407 as 12 8 4
---------
topfile.stp - display read/write I/O accumulated by file
This script displays read/write I/O total by file. It can either
watch I/O for all files, or just the files read and written by a
specific program. The default is all files; to have it track only
files for a single program, uncomment and change the 'watchme' global
in the script.
Below is the output from running the script while starting up firefox
and browsing a couple pages ('watchme = firefox-bin'):
This script needs a couple extra changes to the normal commandline, so
it doesn't choke on some default systemtap limits:
stap -I tapsets -DMAXMAPENTRIES=10000 -DMAXACTION=10000 topfile.stp
watching read/write file I/O for program firefox-bin
INO FILENAME TOTAL(k) QR(k) QW(k)
-------- -------- -------- -------- --------
458901 XUL.mfasl 896 896 0
1540368 nsExtensionManager.js 268 268 0
1540370 nsUpdateService.js 228 228 0
1655550 _CACHE_002_ 160 88 72
1655549 _CACHE_001_ 156 96 60
1753153 bookmarks.properties 148 148 0
475249 compreg.dat 144 144 0
1986358 forms.css 124 124 0
1986359 ua.css 116 116 0
1655551 _CACHE_003_ 100 48 52
458904 xpti.dat 96 96 0
1540393 nsBrowserContentHandler.js 96 96 0
1986338 charsetData.properties 96 96 0
475299 bookmarks-1.html 96 48 48
1999555 left_ptr_watch 88 88 0
1785948 tabbrowser.xml 84 84 0
1622275 necko.properties 80 80 0
1986326 all.js 72 72 0
475236 bookmarks.bak 48 0 48
37786 Toolbar.png 44 44 0
1828559 locale.alias 40 40 0
1785953 tree.xml 40 40 0
1785924 browser.xml 40 40 0
1986360 html.css 32 32 0
527417 2DABA7F0d01 32 0 32
37767 browser.css 28 28 0
1785923 autocomplete.xml 28 28 0
1655548 _CACHE_MAP_ 28 12 16
458907 bookmarks.html 28 4 24
1037545 default.xpm 24 24 0
2071470 extensions.cache 24 24 0
874245 intl.properties 24 24 0
1622311 xul.css 24 24 0
1785937 popup.xml 24 24 0
1785947 tabbox.xml 24 24 0
1986323 firefox.js 20 20 0
1540294 dom_html.xpt 20 20 0
1540305 dom_svg.xpt 20 20 0
884848 search.xml 20 20 0
1968257 libmozjs.so 16 16 0
1523939 libxpcom_core.so 16 16 0
1523932 libplc4.so 16 16 0
1523929 libnspr4.so 16 16 0
1826476 libjpeg.so.62.0.0 16 16 0
1523934 libsmime3.so 16 16 0
1523936 libssl3.so 16 16 0
1523930 libnss3.so 16 16 0
1821028 libXt.so.6.0.0 16 16 0
1829920 libXp.so.6.2.0 16 16 0
1820654 libXft.so.2.1.2 16 16 0
1523938 libxpcom_compat.so 16 16 0
1523935 libsoftokn3.so 16 16 0
1819411 libSM.so.6.0.0 16 16 0
1820225 libICE.so.6.3.0 16 16 0
1819117 libgconf-2.so.4.1.0 16 16 0
1826325 libORBit-2.so.0.1.0 16 16 0
1820026 libgthread-2.0.so.0.1200.4 16 16 0
1902252 libpixbufloader-xpm.so 16 16 0
1902647 gconfd-2 16 16 0
1826754 libgnome-2.so.0.1600.0 16 16 0
1826705 libgnomevfs-2.so.0.1400.2 16 16 0
1827485 libbonobo-2.so.0.0.0 16 16 0
1827486 libbonobo-activation.so.4.0.0 16 16 0
1826618 libesd.so.0.2.36 16 16 0
1826616 libaudiofile.so.0.0.2 16 16 0
1826502 libavahi-common.so.3.4.3 16 16 0
1826506 libavahi-client.so.3.2.1 16 16 0
1826327 libORBitCosNaming-2.so.0.1.0 16 16 0
1540265 necko.xpt 16 16 0
475233 localstore.rdf 16 8 8
1785949 text.xml 16 16 0
1785931 general.xml 16 16 0
1785951 toolbar.xml 16 16 0
1540246 libnkgnomevfs.so 16 16 0
1507650 browser.properties 16 16 0
458905 cookies.txt 16 16 0
1969603 libmozgnome.so 16 16 0
1902205 pango-indic-fc.so 16 16 0
1523937 libxpcom.so 12 12 0
1523933 libplds4.so 12 12 0
1986324 channel-prefs.js 12 12 0
1540251 xpcom_ds.xpt 12 12 0
1826508 libavahi-glib.so.1.0.1 12 12 0
1540291 dom_base.xpt 12 12 0
1540298 dom_css.xpt 12 12 0
884846 sanitize.js 12 12 0
213463 quirk.css 12 12 0
1605907 xulscrollbars.css 12 12 0
1540341 accessibility.xpt 12 12 0
1605915 tree.css 12 12 0
1540322 docshell.xpt 12 12 0
1785925 button.xml 12 12 0
1605881 button.css 12 12 0
1785950 textbox.xml 12 12 0
1986337 charsetalias.properties 12 12 0
475258 history.dat 12 4 8
1902201 pango-hangul-fc.so 12 12 0
1902204 pango-hebrew-fc.so 12 12 0
1902197 pango-arabic-fc.so 12 12 0
1540258 xpconnect.xpt 8 8 0
1540252 xpcom_io.xpt 8 8 0
1540394 nsBrowserGlue.js 8 8 0
1540286 rdf.xpt 8 8 0
459757 prefs.js 8 8 0
1986319 prefcalls.js 8 8 0
33467 ssl-modules.conf 8 8 0
1540293 dom_core.xpt 8 8 0
1540295 dom_events.xpt 8 8 0
1540308 content_base.xpt 8 8 0
1540304 dom_xul.xpt 8 8 0
1540354 jsconsole-clhandler.js 8 8 0
874208 css.properties 8 8 0
1540364 nsDefaultCLH.js 8 8 0
1986344 pangoFontEncoding.properties 8 8 0
1605891 global.css 8 8 0
1605890 formatting.css 8 8 0
1605879 autocomplete.css 8 8 0
1785934 menu.xml 8 8 0
1605896 menu.css 8 8 0
1605911 tabbox.css 8 8 0
1605914 toolbarbutton.css 8 8 0
1622276 platformHTMLBindings.xml 8 8 0
1540333 webBrowser_core.xpt 8 8 0
1540307 widget.xpt 8 8 0
1902208 pango-indic-lang.so 8 8 0
1540363 nsCloseAllWindows.js 8 8 0
475231 profiles.ini 4 4 0
475243 compatibility.ini 4 4 0
2071469 extensions.ini 4 4 0
1986327 xpinstall.js 4 4 0
1986325 security-prefs.js 4 4 0
1986322 vendor.js 4 4 0
1986321 reporter.js 4 4 0
33675 firefox.js 4 4 0
874206 browser.manifest 4 4 0
874207 comm.manifest 4 4 0
874279 en-US.manifest 4 4 0
874282 toolkit.manifest 4 4 0
874283 pippki.manifest 4 4 0
874284 reporter.manifest 4 4 0
874297 classic.manifest 4 4 0
1589270 gtkrc 4 4 0
1540250 xpcom_base.xpt 4 4 0
1540253 xpcom_components.xpt 4 4 0
1540366 xulapp.xpt 4 4 0
1540284 pref.xpt 4 4 0
1540367 extensions.xpt 4 4 0
1986320 platform.js 4 4 0
1523943 firefox.cfg 4 4 0
1540254 xpcom_threads.xpt 4 4 0
1540369 update.xpt 4 4 0
34157 gdk-pixbuf.loaders 4 4 0
33587 theme-method.conf 4 4 0
33588 font-method.conf 4 4 0
33715 smb-module.conf 4 4 0
33716 mapping-modules.conf 4 4 0
33466 default-modules.conf 4 4 0
1986354 hiddenWindow.html 4 4 0
1540383 xmlextras.xpt 4 4 0
1540314 content_xslt.xpt 4 4 0
1540296 dom_stylesheets.xpt 4 4 0
1540300 dom_range.xpt 4 4 0
1540312 xuldoc.xpt 4 4 0
1540318 layout_xul.xpt 4 4 0
1540319 layout_xul_tree.xpt 4 4 0
1540299 dom_traversal.xpt 4 4 0
1540310 content_htmldoc.xpt 4 4 0
1540313 xultmpl.xpt 4 4 0
1540292 dom_canvas.xpt 4 4 0
1540297 dom_views.xpt 4 4 0
1540361 commandlines.xpt 4 4 0
49159 intl.properties 4 4 0
1540277 necko_http.xpt 4 4 0
1540325 windowwatcher.xpt 4 4 0
1785942 scrollbar.xml 4 4 0
1540301 dom_xbl.xpt 4 4 0
1540302 dom_xpath.xpt 4 4 0
1037544 slider.gif 4 4 0
2067966 arrow-lft.gif 4 4 0
2067971 arrow-rit.gif 4 4 0
2067976 arrow-up.gif 4 4 0
2067961 arrow-dn.gif 4 4 0
874244 intl.css 4 4 0
884830 browser.css 4 4 0
1605889 findBar.css 4 4 0
1540392 browsercompsbase.xpt 4 4 0
1638946 browserOverlay.css 4 4 0
1605899 popup.css 4 4 0
1785946 stringbundle.xml 4 4 0
1540355 autocomplete.xpt 4 4 0
874263 tree.dtd 4 4 0
1605913 toolbar.css 4 4 0
874215 global.dtd 4 4 0
49158 platformKeys.properties 4 4 0
1785944 splitter.xml 4 4 0
1605910 splitter.css 4 4 0
874261 tabbrowser.dtd 4 4 0
1605880 browser.css 4 4 0
1507697 tabstrip-bottom.png 4 4 0
1507689 folder-item.png 4 4 0
1785952 toolbarbutton.xml 4 4 0
1507686 close.png 4 4 0
874240 findbar.dtd 4 4 0
1785939 progressmeter.xml 4 4 0
1605903 progressmeter.css 4 4 0
1589360 chevron.gif 4 4 0
2067962 arrow-dn-dis.gif 4 4 0
874264 textcontext.dtd 4 4 0
1605912 textbox.css 4 4 0
37768 browser.xml 4 4 0
37769 Go.png 4 4 0
884852 searchbarBindings.css 4 4 0
37777 searchbar.css 4 4 0
37779 Search-bar.png 4 4 0
37778 search-arrow.gif 4 4 0
1936767 amazondotcom.src 4 4 0
1936765 google.src 4 4 0
1936770 creativecommons.src 4 4 0
1936768 eBay.src 4 4 0
1936769 yahoo.src 4 4 0
1936771 answers.src 4 4 0
1936778 debsearch.src 4 4 0
1936780 wikipedia.src 4 4 0
481680 region.properties 4 4 0
475234 search.rdf 4 4 0
37784 Throbber-small.png 4 4 0
2067977 arrow-up-dis.gif 4 4 0
2067967 arrow-lft-dis.gif 4 4 0
2067972 arrow-rit-dis.gif 4 4 0
1540358 satchel.xpt 4 4 0
1936764 google.gif 4 4 0
1540262 intl.xpt 4 4 0
1540261 locale.xpt 4 4 0
1507662 searchbar.properties 4 4 0
1540281 uriloader.xpt 4 4 0
1540344 mozbrwsr.xpt 4 4 0
1007337 security.properties 4 4 0
1540338 appshell.xpt 4 4 0
1540321 shistory.xpt 4 4 0
874262 tabbrowser.properties 4 4 0
1540388 bookmarks.xpt 4 4 0
1540359 fastfind.xpt 4 4 0
1540260 uconv.xpt 4 4 0
37775 livemark-item.png 4 4 0
1540371 shellservice.xpt 4 4 0
1507701 Throbber-small.gif 4 4 0
213468 loading-image.gif 4 4 0
213467 broken-image.gif 4 4 0
1540272 necko_cache.xpt 4 4 0
1999583 hand2 4 4 0
37773 page-livemarks.png 4 4 0
213465 arrow.gif 4 4 0
1902198 pango-arabic-lang.so 4 4 0
1540362 appstartup.xpt 4 4 0
480177 prefs-1.js 4 0 4
---------
traceread - trace read I/O for all or selected file
This script attempts to show the detailed sequence of events
(including timings) that occurs, from a block-layer perspective, when
a file is read via vfs_read(). It puts probes on sys_read() entry and
exit, which print some details about each read call, and in-between
prints the intervening blktrace event data.
The script takes a command-line argument saying whether to trace only
the read of a given file, or to trace all reads. Specify 'all' for
all files, the individual filename otherwise.
The output below shows the results of tracing:
# cat linux-2.6/kernel/module.c
which is about a 64k file.
The leftmost column shows the time since the start of the script in
seconds, the second column shows the time elapsed since the beginning
of the previous read() entry, the third column shows the event type,
the rest should be self-explanatory.
This script needs a couple extra changes to the normal commandline, so
it doesn't choke on some default systemtap limits:
stap -I tapsets -DMAXMAPENTRIES=10000 -DMAXACTION=10000 traceread.stp
module.c
tracking file module.c
3.358570676 0.000000000 T R
tracking file module.c, ino 548922
11.192565429 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 0 count 4096
11.192612604 0.000047175 Q R sector 120456092, bytes 16384
11.192639507 0.000026903 G R sector 120456092, bytes 16384
11.192654697 0.000015190 P R
11.192666705 0.000012008 I R sector 120456092, bytes 16384
11.192685104 0.000018399 U R
11.192701796 0.000016692 D R sector 120456092, bytes 16384
11.197560999 0.004859203 C R sector 120456092, bytes
16384, q2d 0.000089192, d2c 0.004859203, q2c 0.004948395
11.197612869 0.000051870 vfs_read.exit cat(4932) file module.c
retval 4096
11.198286672 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 4096 count 4096
11.198311506 0.000024834 Q R sector 120456124, bytes 4096
11.198326747 0.000015241 G R sector 120456124, bytes 4096
11.198339793 0.000013046 P R
11.198349240 0.000009447 I R sector 120456124, bytes 4096
11.198370808 0.000021568 Q R sector 120456132, bytes 4096
11.198381908 0.000011100 M R sector 120456132, bytes 4096
11.198394319 0.000012411 Q R sector 120456140, bytes 4096
11.198404331 0.000010012 M R sector 120456140, bytes 4096
11.198414968 0.000010637 Q R sector 120456148, bytes 4096
11.198424554 0.000009586 M R sector 120456148, bytes 4096
11.198435146 0.000010592 Q R sector 120456156, bytes 4096
11.198445158 0.000010012 M R sector 120456156, bytes 4096
11.198455498 0.000010340 Q R sector 120456164, bytes 4096
11.198465149 0.000009651 M R sector 120456164, bytes 4096
11.198475409 0.000010260 Q R sector 120456172, bytes 4096
11.198485294 0.000009885 M R sector 120456172, bytes 4096
11.198496223 0.000010929 Q R sector 120456180, bytes 4096
11.198505800 0.000009577 M R sector 120456180, bytes 4096
11.198520161 0.000014361 vfs_read.exit cat(4932) file module.c
retval 4096
11.199417764 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 8192 count 4096
11.199430012 0.000012248 vfs_read.exit cat(4932) file module.c
retval 4096
11.200308850 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 12288 count 4096
11.200319449 0.000010599 vfs_read.exit cat(4932) file module.c
retval 4096
11.200367998 0.000000000 T R
11.200995102 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 16384 count 4096
11.201021906 0.000026804 Q R sector 120456188, bytes 4096
11.201035815 0.000013909 M R sector 120456188, bytes 4096
11.201047730 0.000011915 U R
11.201062188 0.000014458 D R sector 120456124, bytes 36864
11.201535192 0.000473004 C R sector 120456124, bytes
36864, q2d 0.002750682, d2c 0.000473004, q2c 0.003223686
11.201578313 0.000043121 Q R sector 120456196, bytes 16384
11.201590126 0.000011813 G R sector 120456196, bytes 16384
11.201601350 0.000011224 P R
11.201610690 0.000009340 I R sector 120456196, bytes 16384
11.201625092 0.000014402 vfs_read.exit cat(4932) file module.c
retval 4096
11.202486288 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 20480 count 4096
11.202498689 0.000012401 vfs_read.exit cat(4932) file module.c
retval 4096
11.203312312 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 24576 count 4096
11.203322829 0.000010517 vfs_read.exit cat(4932) file module.c
retval 4096
11.204227629 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 28672 count 4096
11.204240782 0.000013153 vfs_read.exit cat(4932) file module.c
retval 4096
11.204365075 0.000000000 T R
11.205072430 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 32768 count 4096
11.205084716 0.000012286 vfs_read.exit cat(4932) file module.c
retval 4096
11.206034244 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 36864 count 4096
11.206045473 0.000011229 vfs_read.exit cat(4932) file module.c
retval 4096
11.206904137 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 40960 count 4096
11.206915239 0.000011102 vfs_read.exit cat(4932) file module.c
retval 4096
11.207528133 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 45056 count 4096
11.207539952 0.000011819 vfs_read.exit cat(4932) file module.c
retval 4096
11.208232199 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 49152 count 4096
11.208245536 0.000013337 U R
11.208264744 0.000019208 D R sector 120456196, bytes 16384
11.208781142 0.000516398 C R sector 120456196, bytes
16384, q2d 0.006686431, d2c 0.000516398, q2c 0.007202829
11.208812506 0.000031364 vfs_read.exit cat(4932) file module.c
retval 4096
11.209518661 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 53248 count 4096
11.209530107 0.000011446 vfs_read.exit cat(4932) file module.c
retval 4096
11.210028947 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 57344 count 4096
11.210039547 0.000010600 vfs_read.exit cat(4932) file module.c
retval 4096
11.309701774 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 61440 count 4096
11.309726162 0.000024388 vfs_read.exit cat(4932) file module.c
retval 2793
11.310370936 0.000000000 vfs_read.entry cat(4932) file module.c,
pos 64233 count 4096
11.310379344 0.000008408 vfs_read.exit cat(4932) file module.c
retval 0
Well, that's all for now. Hopefully someone will find this tapset
and/or examples of some use...
Enjoy!
Tom
Attachment:
blktap.0.tar.gz
Description: application/compressed-tar
| Index Nav: | [Date Index] [Subject Index] [Author Index] [Thread Index] | |
|---|---|---|
| Message Nav: | [Date Prev] [Date Next] | [Thread Prev] [Thread Next] |