From 842e3b83c2e091614ad07a1e31e81dbc8449c1cf Mon Sep 17 00:00:00 2001 From: Scott Rifenbark Date: Fri, 18 Jan 2013 15:37:23 -0800 Subject: profile-manual: Added blktrace section. No re-writing at all. (From yocto-docs rev: c18bd94ac0e6fc3a23139ec8d1ef7b04518746de) Signed-off-by: Scott Rifenbark Signed-off-by: Richard Purdie --- .../profile-manual/profile-manual-usage.xml | 404 +++++++++++++++++++++ 1 file changed, 404 insertions(+) (limited to 'documentation/profile-manual') diff --git a/documentation/profile-manual/profile-manual-usage.xml b/documentation/profile-manual/profile-manual-usage.xml index a777b4212a..68ea68507b 100644 --- a/documentation/profile-manual/profile-manual-usage.xml +++ b/documentation/profile-manual/profile-manual-usage.xml @@ -3279,8 +3279,412 @@ + + +
+ blktrace + + + blktrace is a tool for tracing and reporting low-level disk I/O. + blktrace provides the tracing half of the equation; its output can + be piped into the blkparse program, which renders the data in a + human-readable form and does some basic analysis: + + +
+ Setup + + + For this section, we'll assume you've already performed the + basic setup outlined in the + "General Setup" + section. + + + + blktrace is an application that runs on the target system. + You can run the entire blktrace and blkparse pipeline on the + target, or you can run blktrace in 'listen' mode on the target + and have blktrace and blkparse collect and analyze the data on + the host (see the + "Using blktrace Remotely" + section below). + For the rest of this section we assume you've ssh'ed to the + host and will be running blkrace on the target. + +
+ +
+ Basic Usage + + + To record a trace, simply run the 'blktrace' command, giving it + the name of the block device you want to trace activity on: + + root@crownbay:~# blktrace /dev/sdc + + In another shell, execute a workload you want to trace. + + root@crownbay:/media/sdc# rm linux-2.6.19.2.tar.bz2; wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2; sync + Connecting to downloads.yoctoproject.org (140.211.169.59:80) + linux-2.6.19.2.tar.b 100% |*******************************| 41727k 0:00:00 ETA + + Press Ctrl-C in the blktrace shell to stop the trace. It will + display how many events were logged, along with the per-cpu file + sizes (blktrace records traces in per-cpu kernel buffers and + simply dumps them to userspace for blkparse to merge and sort + later). + + ^C=== sdc === + CPU 0: 7082 events, 332 KiB data + CPU 1: 1578 events, 74 KiB data + Total: 8660 events (dropped 0), 406 KiB data + + If you examine the files saved to disk, you see multiple files, + one per CPU and with the device name as the first part of the + filename: + + root@crownbay:~# ls -al + drwxr-xr-x 6 root root 1024 Oct 27 22:39 . + drwxr-sr-x 4 root root 1024 Oct 26 18:24 .. + -rw-r--r-- 1 root root 339938 Oct 27 22:40 sdc.blktrace.0 + -rw-r--r-- 1 root root 75753 Oct 27 22:40 sdc.blktrace.1 + + To view the trace events, simply invoke 'blkparse' in the + directory containing the trace files, giving it the device name + that forms the first part of the filenames: + + root@crownbay:~# blkparse sdc + + 8,32 1 1 0.000000000 1225 Q WS 3417048 + 8 [jbd2/sdc-8] + 8,32 1 2 0.000025213 1225 G WS 3417048 + 8 [jbd2/sdc-8] + 8,32 1 3 0.000033384 1225 P N [jbd2/sdc-8] + 8,32 1 4 0.000043301 1225 I WS 3417048 + 8 [jbd2/sdc-8] + 8,32 1 0 0.000057270 0 m N cfq1225 insert_request + 8,32 1 0 0.000064813 0 m N cfq1225 add_to_rr + 8,32 1 5 0.000076336 1225 U N [jbd2/sdc-8] 1 + 8,32 1 0 0.000088559 0 m N cfq workload slice:150 + 8,32 1 0 0.000097359 0 m N cfq1225 set_active wl_prio:0 wl_type:1 + 8,32 1 0 0.000104063 0 m N cfq1225 Not idling. st->count:1 + 8,32 1 0 0.000112584 0 m N cfq1225 fifo= (null) + 8,32 1 0 0.000118730 0 m N cfq1225 dispatch_insert + 8,32 1 0 0.000127390 0 m N cfq1225 dispatched a request + 8,32 1 0 0.000133536 0 m N cfq1225 activate rq, drv=1 + 8,32 1 6 0.000136889 1225 D WS 3417048 + 8 [jbd2/sdc-8] + 8,32 1 7 0.000360381 1225 Q WS 3417056 + 8 [jbd2/sdc-8] + 8,32 1 8 0.000377422 1225 G WS 3417056 + 8 [jbd2/sdc-8] + 8,32 1 9 0.000388876 1225 P N [jbd2/sdc-8] + 8,32 1 10 0.000397886 1225 Q WS 3417064 + 8 [jbd2/sdc-8] + 8,32 1 11 0.000404800 1225 M WS 3417064 + 8 [jbd2/sdc-8] + 8,32 1 12 0.000412343 1225 Q WS 3417072 + 8 [jbd2/sdc-8] + 8,32 1 13 0.000416533 1225 M WS 3417072 + 8 [jbd2/sdc-8] + 8,32 1 14 0.000422121 1225 Q WS 3417080 + 8 [jbd2/sdc-8] + 8,32 1 15 0.000425194 1225 M WS 3417080 + 8 [jbd2/sdc-8] + 8,32 1 16 0.000431968 1225 Q WS 3417088 + 8 [jbd2/sdc-8] + 8,32 1 17 0.000435251 1225 M WS 3417088 + 8 [jbd2/sdc-8] + 8,32 1 18 0.000440279 1225 Q WS 3417096 + 8 [jbd2/sdc-8] + 8,32 1 19 0.000443911 1225 M WS 3417096 + 8 [jbd2/sdc-8] + 8,32 1 20 0.000450336 1225 Q WS 3417104 + 8 [jbd2/sdc-8] + 8,32 1 21 0.000454038 1225 M WS 3417104 + 8 [jbd2/sdc-8] + 8,32 1 22 0.000462070 1225 Q WS 3417112 + 8 [jbd2/sdc-8] + 8,32 1 23 0.000465422 1225 M WS 3417112 + 8 [jbd2/sdc-8] + 8,32 1 24 0.000474222 1225 I WS 3417056 + 64 [jbd2/sdc-8] + 8,32 1 0 0.000483022 0 m N cfq1225 insert_request + 8,32 1 25 0.000489727 1225 U N [jbd2/sdc-8] 1 + 8,32 1 0 0.000498457 0 m N cfq1225 Not idling. st->count:1 + 8,32 1 0 0.000503765 0 m N cfq1225 dispatch_insert + 8,32 1 0 0.000512914 0 m N cfq1225 dispatched a request + 8,32 1 0 0.000518851 0 m N cfq1225 activate rq, drv=2 + . + . + . + 8,32 0 0 58.515006138 0 m N cfq3551 complete rqnoidle 1 + 8,32 0 2024 58.516603269 3 C WS 3156992 + 16 [0] + 8,32 0 0 58.516626736 0 m N cfq3551 complete rqnoidle 1 + 8,32 0 0 58.516634558 0 m N cfq3551 arm_idle: 8 group_idle: 0 + 8,32 0 0 58.516636933 0 m N cfq schedule dispatch + 8,32 1 0 58.516971613 0 m N cfq3551 slice expired t=0 + 8,32 1 0 58.516982089 0 m N cfq3551 sl_used=13 disp=6 charge=13 iops=0 sect=80 + 8,32 1 0 58.516985511 0 m N cfq3551 del_from_rr + 8,32 1 0 58.516990819 0 m N cfq3551 put_queue + + CPU0 (sdc): + Reads Queued: 0, 0KiB Writes Queued: 331, 26,284KiB + Read Dispatches: 0, 0KiB Write Dispatches: 485, 40,484KiB + Reads Requeued: 0 Writes Requeued: 0 + Reads Completed: 0, 0KiB Writes Completed: 511, 41,000KiB + Read Merges: 0, 0KiB Write Merges: 13, 160KiB + Read depth: 0 Write depth: 2 + IO unplugs: 23 Timer unplugs: 0 + CPU1 (sdc): + Reads Queued: 0, 0KiB Writes Queued: 249, 15,800KiB + Read Dispatches: 0, 0KiB Write Dispatches: 42, 1,600KiB + Reads Requeued: 0 Writes Requeued: 0 + Reads Completed: 0, 0KiB Writes Completed: 16, 1,084KiB + Read Merges: 0, 0KiB Write Merges: 40, 276KiB + Read depth: 0 Write depth: 2 + IO unplugs: 30 Timer unplugs: 1 + + Total (sdc): + Reads Queued: 0, 0KiB Writes Queued: 580, 42,084KiB + Read Dispatches: 0, 0KiB Write Dispatches: 527, 42,084KiB + Reads Requeued: 0 Writes Requeued: 0 + Reads Completed: 0, 0KiB Writes Completed: 527, 42,084KiB + Read Merges: 0, 0KiB Write Merges: 53, 436KiB + IO unplugs: 53 Timer unplugs: 1 + + Throughput (R/W): 0KiB/s / 719KiB/s + Events (sdc): 6,592 entries + Skips: 0 forward (0 - 0.0%) + Input file sdc.blktrace.0 added + Input file sdc.blktrace.1 added + + The report shows each event that was found in the blktrace data, + along with a summary of the overall block I/O traffic during + the run. You can look at the + blkparse + manpage to learn the + meaning of each field displayed in the trace listing. + + +
+ Live Mode + + + blktrace and blkparse are designed from the ground up to + be able to operate together in a 'pipe mode' where the + stdout of blktrace can be fed directly into the stdin of + blkparse: + + root@crownbay:~# blktrace /dev/sdc -o - | blkparse -i - + + This enables long-lived tracing sessions to run without + writing anything to disk, and allows the user to look for + certain conditions in the trace data in 'real-time' by + viewing the trace output as it scrolls by on the screen or + by passing it along to yet another program in the pipeline + such as grep which can be used to identify and capture + conditions of interest. + + + + There's actually another blktrace command that implements + the above pipeline as a single command, so the user doesn't + have to bother typing in the above command sequence: + + root@crownbay:~# btrace /dev/sdc + + +
+ +
+ Using blktrace Remotely + + + Because blktrace traces block I/O and at the same time + normally writes its trace data to a block device, and + in general because it's not really a great idea to make + the device being traced the same as the device the tracer + writes to, blktrace provides a way to trace without + perturbing the traced device at all by providing native + support for sending all trace data over the network. + + + + To have blktrace operate in this mode, start blktrace on + the target system being traced with the -l option, along with + the device to trace: + + root@crownbay:~# blktrace -l /dev/sdc + server: waiting for connections... + + On the host system, use the -h option to connect to the + target system, also passing it the device to trace: + + $ blktrace -d /dev/sdc -h 192.168.1.43 + blktrace: connecting to 192.168.1.43 + blktrace: connected! + + On the target system, you should see this: + + server: connection from 192.168.1.43 + + In another shell, execute a workload you want to trace. + + root@crownbay:/media/sdc# rm linux-2.6.19.2.tar.bz2; wget http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2; sync + Connecting to downloads.yoctoproject.org (140.211.169.59:80) + linux-2.6.19.2.tar.b 100% |*******************************| 41727k 0:00:00 ETA + + When it's done, do a Ctrl-C on the host system to + stop the trace: + + ^C=== sdc === + CPU 0: 7691 events, 361 KiB data + CPU 1: 4109 events, 193 KiB data + Total: 11800 events (dropped 0), 554 KiB data + + On the target system, you should also see a trace + summary for the trace just ended: + + server: end of run for 192.168.1.43:sdc + === sdc === + CPU 0: 7691 events, 361 KiB data + CPU 1: 4109 events, 193 KiB data + Total: 11800 events (dropped 0), 554 KiB data + + The blktrace instance on the host will save the target + output inside a hostname-timestamp directory: + + $ ls -al + drwxr-xr-x 10 root root 1024 Oct 28 02:40 . + drwxr-sr-x 4 root root 1024 Oct 26 18:24 .. + drwxr-xr-x 2 root root 1024 Oct 28 02:40 192.168.1.43-2012-10-28-02:40:56 + + cd into that directory to see the output files: + + $ ls -l + -rw-r--r-- 1 root root 369193 Oct 28 02:44 sdc.blktrace.0 + -rw-r--r-- 1 root root 197278 Oct 28 02:44 sdc.blktrace.1 + + And run blkparse on the host system using the device name: + + $ blkparse sdc + + 8,32 1 1 0.000000000 1263 Q RM 6016 + 8 [ls] + 8,32 1 0 0.000036038 0 m N cfq1263 alloced + 8,32 1 2 0.000039390 1263 G RM 6016 + 8 [ls] + 8,32 1 3 0.000049168 1263 I RM 6016 + 8 [ls] + 8,32 1 0 0.000056152 0 m N cfq1263 insert_request + 8,32 1 0 0.000061600 0 m N cfq1263 add_to_rr + 8,32 1 0 0.000075498 0 m N cfq workload slice:300 + . + . + . + 8,32 0 0 177.266385696 0 m N cfq1267 arm_idle: 8 group_idle: 0 + 8,32 0 0 177.266388140 0 m N cfq schedule dispatch + 8,32 1 0 177.266679239 0 m N cfq1267 slice expired t=0 + 8,32 1 0 177.266689297 0 m N cfq1267 sl_used=9 disp=6 charge=9 iops=0 sect=56 + 8,32 1 0 177.266692649 0 m N cfq1267 del_from_rr + 8,32 1 0 177.266696560 0 m N cfq1267 put_queue + + CPU0 (sdc): + Reads Queued: 0, 0KiB Writes Queued: 270, 21,708KiB + Read Dispatches: 59, 2,628KiB Write Dispatches: 495, 39,964KiB + Reads Requeued: 0 Writes Requeued: 0 + Reads Completed: 90, 2,752KiB Writes Completed: 543, 41,596KiB + Read Merges: 0, 0KiB Write Merges: 9, 344KiB + Read depth: 2 Write depth: 2 + IO unplugs: 20 Timer unplugs: 1 + CPU1 (sdc): + Reads Queued: 688, 2,752KiB Writes Queued: 381, 20,652KiB + Read Dispatches: 31, 124KiB Write Dispatches: 59, 2,396KiB + Reads Requeued: 0 Writes Requeued: 0 + Reads Completed: 0, 0KiB Writes Completed: 11, 764KiB + Read Merges: 598, 2,392KiB Write Merges: 88, 448KiB + Read depth: 2 Write depth: 2 + IO unplugs: 52 Timer unplugs: 0 + + Total (sdc): + Reads Queued: 688, 2,752KiB Writes Queued: 651, 42,360KiB + Read Dispatches: 90, 2,752KiB Write Dispatches: 554, 42,360KiB + Reads Requeued: 0 Writes Requeued: 0 + Reads Completed: 90, 2,752KiB Writes Completed: 554, 42,360KiB + Read Merges: 598, 2,392KiB Write Merges: 97, 792KiB + IO unplugs: 72 Timer unplugs: 1 + + Throughput (R/W): 15KiB/s / 238KiB/s + Events (sdc): 9,301 entries + Skips: 0 forward (0 - 0.0%) + + You should see the trace events and summary just as + you would have if you'd run the same command on the target. + +
+ +
+ Tracing Block I/O via 'ftrace' + + + It's also possible to trace block I/O using only + trace events subsystem, + which can be useful for casual tracing + if you don't want bother dealing with the userspace tools. + + + + To enable tracing for a given device, use + /sys/block/xxx/trace/enable, where xxx is the device name. + This for example enables tracing for /dev/sdc: + + root@crownbay:/sys/kernel/debug/tracing# echo 1 > /sys/block/sdc/trace/enable + + Once you've selected the device(s) you want to trace, + selecting the 'blk' tracer will turn the blk tracer on: + + root@crownbay:/sys/kernel/debug/tracing# cat available_tracers + blk function_graph function nop + root@crownbay:/sys/kernel/debug/tracing# echo blk > current_tracer + + Execute the workload you're interested in: + + root@crownbay:/sys/kernel/debug/tracing# cat /media/sdc/testfile.txt + + And look at the output (note here that we're using + 'trace_pipe' instead of trace to capture this trace - + this allows us to wait around on the pipe for data to + appear): + + root@crownbay:/sys/kernel/debug/tracing# cat trace_pipe + cat-3587 [001] d..1 3023.276361: 8,32 Q R 1699848 + 8 [cat] + cat-3587 [001] d..1 3023.276410: 8,32 m N cfq3587 alloced + cat-3587 [001] d..1 3023.276415: 8,32 G R 1699848 + 8 [cat] + cat-3587 [001] d..1 3023.276424: 8,32 P N [cat] + cat-3587 [001] d..2 3023.276432: 8,32 I R 1699848 + 8 [cat] + cat-3587 [001] d..1 3023.276439: 8,32 m N cfq3587 insert_request + cat-3587 [001] d..1 3023.276445: 8,32 m N cfq3587 add_to_rr + cat-3587 [001] d..2 3023.276454: 8,32 U N [cat] 1 + cat-3587 [001] d..1 3023.276464: 8,32 m N cfq workload slice:150 + cat-3587 [001] d..1 3023.276471: 8,32 m N cfq3587 set_active wl_prio:0 wl_type:2 + cat-3587 [001] d..1 3023.276478: 8,32 m N cfq3587 fifo= (null) + cat-3587 [001] d..1 3023.276483: 8,32 m N cfq3587 dispatch_insert + cat-3587 [001] d..1 3023.276490: 8,32 m N cfq3587 dispatched a request + cat-3587 [001] d..1 3023.276497: 8,32 m N cfq3587 activate rq, drv=1 + cat-3587 [001] d..2 3023.276500: 8,32 D R 1699848 + 8 [cat] + + And this turns off tracing for the specified device: + + root@crownbay:/sys/kernel/debug/tracing# echo 0 > /sys/block/sdc/trace/enable + + +
+
+
+ Documentation + + + Online versions of the man pages for the commands discussed + in this section can be found here: + + http://linux.die.net/man/8/blktrace + + http://linux.die.net/man/1/blkparse + + http://linux.die.net/man/8/btrace + + + + + + The above manpages, along with manpages for the other + blktrace utilities (btt, blkiomon, etc) can be found in the + /doc directory of the blktrace tools git repo: + + $ git clone git://git.kernel.dk/blktrace.git + + +