summaryrefslogtreecommitdiffstats
path: root/documentation/profile-manual
diff options
context:
space:
mode:
authorScott Rifenbark <scott.m.rifenbark@intel.com>2013-01-18 23:37:23 (GMT)
committerRichard Purdie <richard.purdie@linuxfoundation.org>2013-01-27 13:56:03 (GMT)
commit842e3b83c2e091614ad07a1e31e81dbc8449c1cf (patch)
treef0b76389b8f4576be1a625a258af3298936b34af /documentation/profile-manual
parente4746a55e43b0ddde0b4b6070017ad7a5a002760 (diff)
downloadpoky-842e3b83c2e091614ad07a1e31e81dbc8449c1cf.tar.gz
profile-manual: Added blktrace section.
No re-writing at all. (From yocto-docs rev: c18bd94ac0e6fc3a23139ec8d1ef7b04518746de) Signed-off-by: Scott Rifenbark <scott.m.rifenbark@intel.com> Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org>
Diffstat (limited to 'documentation/profile-manual')
-rw-r--r--documentation/profile-manual/profile-manual-usage.xml404
1 files changed, 404 insertions, 0 deletions
diff --git a/documentation/profile-manual/profile-manual-usage.xml b/documentation/profile-manual/profile-manual-usage.xml
index a777b42..68ea685 100644
--- a/documentation/profile-manual/profile-manual-usage.xml
+++ b/documentation/profile-manual/profile-manual-usage.xml
@@ -3279,8 +3279,412 @@
3279 </literallayout> 3279 </literallayout>
3280 </para> 3280 </para>
3281 </section> 3281 </section>
3282</section>
3283
3284<section id='profile-manual-blktrace'>
3285 <title>blktrace</title>
3286
3287 <para>
3288 blktrace is a tool for tracing and reporting low-level disk I/O.
3289 blktrace provides the tracing half of the equation; its output can
3290 be piped into the blkparse program, which renders the data in a
3291 human-readable form and does some basic analysis:
3292 </para>
3293
3294 <section id='blktrace-setup'>
3295 <title>Setup</title>
3296
3297 <para>
3298 For this section, we'll assume you've already performed the
3299 basic setup outlined in the
3300 "<link linkend='profile-manual-general-setup'>General Setup</link>"
3301 section.
3302 </para>
3303
3304 <para>
3305 blktrace is an application that runs on the target system.
3306 You can run the entire blktrace and blkparse pipeline on the
3307 target, or you can run blktrace in 'listen' mode on the target
3308 and have blktrace and blkparse collect and analyze the data on
3309 the host (see the
3310 "<link linkend='using-blktrace-remotely'>Using blktrace Remotely</link>"
3311 section below).
3312 For the rest of this section we assume you've ssh'ed to the
3313 host and will be running blkrace on the target.
3314 </para>
3315 </section>
3316
3317 <section id='blktrace-basic-usage'>
3318 <title>Basic Usage</title>
3319
3320 <para>
3321 To record a trace, simply run the 'blktrace' command, giving it
3322 the name of the block device you want to trace activity on:
3323 <literallayout class='monospaced'>
3324 root@crownbay:~# blktrace /dev/sdc
3325 </literallayout>
3326 In another shell, execute a workload you want to trace.
3327 <literallayout class='monospaced'>
3328 root@crownbay:/media/sdc# rm linux-2.6.19.2.tar.bz2; wget <ulink url='http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2'>http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2</ulink>; sync
3329 Connecting to downloads.yoctoproject.org (140.211.169.59:80)
3330 linux-2.6.19.2.tar.b 100% |*******************************| 41727k 0:00:00 ETA
3331 </literallayout>
3332 Press Ctrl-C in the blktrace shell to stop the trace. It will
3333 display how many events were logged, along with the per-cpu file
3334 sizes (blktrace records traces in per-cpu kernel buffers and
3335 simply dumps them to userspace for blkparse to merge and sort
3336 later).
3337 <literallayout class='monospaced'>
3338 ^C=== sdc ===
3339 CPU 0: 7082 events, 332 KiB data
3340 CPU 1: 1578 events, 74 KiB data
3341 Total: 8660 events (dropped 0), 406 KiB data
3342 </literallayout>
3343 If you examine the files saved to disk, you see multiple files,
3344 one per CPU and with the device name as the first part of the
3345 filename:
3346 <literallayout class='monospaced'>
3347 root@crownbay:~# ls -al
3348 drwxr-xr-x 6 root root 1024 Oct 27 22:39 .
3349 drwxr-sr-x 4 root root 1024 Oct 26 18:24 ..
3350 -rw-r--r-- 1 root root 339938 Oct 27 22:40 sdc.blktrace.0
3351 -rw-r--r-- 1 root root 75753 Oct 27 22:40 sdc.blktrace.1
3352 </literallayout>
3353 To view the trace events, simply invoke 'blkparse' in the
3354 directory containing the trace files, giving it the device name
3355 that forms the first part of the filenames:
3356 <literallayout class='monospaced'>
3357 root@crownbay:~# blkparse sdc
3358
3359 8,32 1 1 0.000000000 1225 Q WS 3417048 + 8 [jbd2/sdc-8]
3360 8,32 1 2 0.000025213 1225 G WS 3417048 + 8 [jbd2/sdc-8]
3361 8,32 1 3 0.000033384 1225 P N [jbd2/sdc-8]
3362 8,32 1 4 0.000043301 1225 I WS 3417048 + 8 [jbd2/sdc-8]
3363 8,32 1 0 0.000057270 0 m N cfq1225 insert_request
3364 8,32 1 0 0.000064813 0 m N cfq1225 add_to_rr
3365 8,32 1 5 0.000076336 1225 U N [jbd2/sdc-8] 1
3366 8,32 1 0 0.000088559 0 m N cfq workload slice:150
3367 8,32 1 0 0.000097359 0 m N cfq1225 set_active wl_prio:0 wl_type:1
3368 8,32 1 0 0.000104063 0 m N cfq1225 Not idling. st->count:1
3369 8,32 1 0 0.000112584 0 m N cfq1225 fifo= (null)
3370 8,32 1 0 0.000118730 0 m N cfq1225 dispatch_insert
3371 8,32 1 0 0.000127390 0 m N cfq1225 dispatched a request
3372 8,32 1 0 0.000133536 0 m N cfq1225 activate rq, drv=1
3373 8,32 1 6 0.000136889 1225 D WS 3417048 + 8 [jbd2/sdc-8]
3374 8,32 1 7 0.000360381 1225 Q WS 3417056 + 8 [jbd2/sdc-8]
3375 8,32 1 8 0.000377422 1225 G WS 3417056 + 8 [jbd2/sdc-8]
3376 8,32 1 9 0.000388876 1225 P N [jbd2/sdc-8]
3377 8,32 1 10 0.000397886 1225 Q WS 3417064 + 8 [jbd2/sdc-8]
3378 8,32 1 11 0.000404800 1225 M WS 3417064 + 8 [jbd2/sdc-8]
3379 8,32 1 12 0.000412343 1225 Q WS 3417072 + 8 [jbd2/sdc-8]
3380 8,32 1 13 0.000416533 1225 M WS 3417072 + 8 [jbd2/sdc-8]
3381 8,32 1 14 0.000422121 1225 Q WS 3417080 + 8 [jbd2/sdc-8]
3382 8,32 1 15 0.000425194 1225 M WS 3417080 + 8 [jbd2/sdc-8]
3383 8,32 1 16 0.000431968 1225 Q WS 3417088 + 8 [jbd2/sdc-8]
3384 8,32 1 17 0.000435251 1225 M WS 3417088 + 8 [jbd2/sdc-8]
3385 8,32 1 18 0.000440279 1225 Q WS 3417096 + 8 [jbd2/sdc-8]
3386 8,32 1 19 0.000443911 1225 M WS 3417096 + 8 [jbd2/sdc-8]
3387 8,32 1 20 0.000450336 1225 Q WS 3417104 + 8 [jbd2/sdc-8]
3388 8,32 1 21 0.000454038 1225 M WS 3417104 + 8 [jbd2/sdc-8]
3389 8,32 1 22 0.000462070 1225 Q WS 3417112 + 8 [jbd2/sdc-8]
3390 8,32 1 23 0.000465422 1225 M WS 3417112 + 8 [jbd2/sdc-8]
3391 8,32 1 24 0.000474222 1225 I WS 3417056 + 64 [jbd2/sdc-8]
3392 8,32 1 0 0.000483022 0 m N cfq1225 insert_request
3393 8,32 1 25 0.000489727 1225 U N [jbd2/sdc-8] 1
3394 8,32 1 0 0.000498457 0 m N cfq1225 Not idling. st->count:1
3395 8,32 1 0 0.000503765 0 m N cfq1225 dispatch_insert
3396 8,32 1 0 0.000512914 0 m N cfq1225 dispatched a request
3397 8,32 1 0 0.000518851 0 m N cfq1225 activate rq, drv=2
3398 .
3399 .
3400 .
3401 8,32 0 0 58.515006138 0 m N cfq3551 complete rqnoidle 1
3402 8,32 0 2024 58.516603269 3 C WS 3156992 + 16 [0]
3403 8,32 0 0 58.516626736 0 m N cfq3551 complete rqnoidle 1
3404 8,32 0 0 58.516634558 0 m N cfq3551 arm_idle: 8 group_idle: 0
3405 8,32 0 0 58.516636933 0 m N cfq schedule dispatch
3406 8,32 1 0 58.516971613 0 m N cfq3551 slice expired t=0
3407 8,32 1 0 58.516982089 0 m N cfq3551 sl_used=13 disp=6 charge=13 iops=0 sect=80
3408 8,32 1 0 58.516985511 0 m N cfq3551 del_from_rr
3409 8,32 1 0 58.516990819 0 m N cfq3551 put_queue
3410
3411 CPU0 (sdc):
3412 Reads Queued: 0, 0KiB Writes Queued: 331, 26,284KiB
3413 Read Dispatches: 0, 0KiB Write Dispatches: 485, 40,484KiB
3414 Reads Requeued: 0 Writes Requeued: 0
3415 Reads Completed: 0, 0KiB Writes Completed: 511, 41,000KiB
3416 Read Merges: 0, 0KiB Write Merges: 13, 160KiB
3417 Read depth: 0 Write depth: 2
3418 IO unplugs: 23 Timer unplugs: 0
3419 CPU1 (sdc):
3420 Reads Queued: 0, 0KiB Writes Queued: 249, 15,800KiB
3421 Read Dispatches: 0, 0KiB Write Dispatches: 42, 1,600KiB
3422 Reads Requeued: 0 Writes Requeued: 0
3423 Reads Completed: 0, 0KiB Writes Completed: 16, 1,084KiB
3424 Read Merges: 0, 0KiB Write Merges: 40, 276KiB
3425 Read depth: 0 Write depth: 2
3426 IO unplugs: 30 Timer unplugs: 1
3427
3428 Total (sdc):
3429 Reads Queued: 0, 0KiB Writes Queued: 580, 42,084KiB
3430 Read Dispatches: 0, 0KiB Write Dispatches: 527, 42,084KiB
3431 Reads Requeued: 0 Writes Requeued: 0
3432 Reads Completed: 0, 0KiB Writes Completed: 527, 42,084KiB
3433 Read Merges: 0, 0KiB Write Merges: 53, 436KiB
3434 IO unplugs: 53 Timer unplugs: 1
3435
3436 Throughput (R/W): 0KiB/s / 719KiB/s
3437 Events (sdc): 6,592 entries
3438 Skips: 0 forward (0 - 0.0%)
3439 Input file sdc.blktrace.0 added
3440 Input file sdc.blktrace.1 added
3441 </literallayout>
3442 The report shows each event that was found in the blktrace data,
3443 along with a summary of the overall block I/O traffic during
3444 the run. You can look at the
3445 <ulink url='http://linux.die.net/man/1/blkparse'>blkparse</ulink>
3446 manpage to learn the
3447 meaning of each field displayed in the trace listing.
3448 </para>
3449
3450 <section id='blktrace-live-mode'>
3451 <title>Live Mode</title>
3452
3453 <para>
3454 blktrace and blkparse are designed from the ground up to
3455 be able to operate together in a 'pipe mode' where the
3456 stdout of blktrace can be fed directly into the stdin of
3457 blkparse:
3458 <literallayout class='monospaced'>
3459 root@crownbay:~# blktrace /dev/sdc -o - | blkparse -i -
3460 </literallayout>
3461 This enables long-lived tracing sessions to run without
3462 writing anything to disk, and allows the user to look for
3463 certain conditions in the trace data in 'real-time' by
3464 viewing the trace output as it scrolls by on the screen or
3465 by passing it along to yet another program in the pipeline
3466 such as grep which can be used to identify and capture
3467 conditions of interest.
3468 </para>
3469
3470 <para>
3471 There's actually another blktrace command that implements
3472 the above pipeline as a single command, so the user doesn't
3473 have to bother typing in the above command sequence:
3474 <literallayout class='monospaced'>
3475 root@crownbay:~# btrace /dev/sdc
3476 </literallayout>
3477 </para>
3478 </section>
3479
3480 <section id='using-blktrace-remotely'>
3481 <title>Using blktrace Remotely</title>
3482
3483 <para>
3484 Because blktrace traces block I/O and at the same time
3485 normally writes its trace data to a block device, and
3486 in general because it's not really a great idea to make
3487 the device being traced the same as the device the tracer
3488 writes to, blktrace provides a way to trace without
3489 perturbing the traced device at all by providing native
3490 support for sending all trace data over the network.
3491 </para>
3492
3493 <para>
3494 To have blktrace operate in this mode, start blktrace on
3495 the target system being traced with the -l option, along with
3496 the device to trace:
3497 <literallayout class='monospaced'>
3498 root@crownbay:~# blktrace -l /dev/sdc
3499 server: waiting for connections...
3500 </literallayout>
3501 On the host system, use the -h option to connect to the
3502 target system, also passing it the device to trace:
3503 <literallayout class='monospaced'>
3504 $ blktrace -d /dev/sdc -h 192.168.1.43
3505 blktrace: connecting to 192.168.1.43
3506 blktrace: connected!
3507 </literallayout>
3508 On the target system, you should see this:
3509 <literallayout class='monospaced'>
3510 server: connection from 192.168.1.43
3511 </literallayout>
3512 In another shell, execute a workload you want to trace.
3513 <literallayout class='monospaced'>
3514 root@crownbay:/media/sdc# rm linux-2.6.19.2.tar.bz2; wget <ulink url='http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2'>http://downloads.yoctoproject.org/mirror/sources/linux-2.6.19.2.tar.bz2</ulink>; sync
3515 Connecting to downloads.yoctoproject.org (140.211.169.59:80)
3516 linux-2.6.19.2.tar.b 100% |*******************************| 41727k 0:00:00 ETA
3517 </literallayout>
3518 When it's done, do a Ctrl-C on the host system to
3519 stop the trace:
3520 <literallayout class='monospaced'>
3521 ^C=== sdc ===
3522 CPU 0: 7691 events, 361 KiB data
3523 CPU 1: 4109 events, 193 KiB data
3524 Total: 11800 events (dropped 0), 554 KiB data
3525 </literallayout>
3526 On the target system, you should also see a trace
3527 summary for the trace just ended:
3528 <literallayout class='monospaced'>
3529 server: end of run for 192.168.1.43:sdc
3530 === sdc ===
3531 CPU 0: 7691 events, 361 KiB data
3532 CPU 1: 4109 events, 193 KiB data
3533 Total: 11800 events (dropped 0), 554 KiB data
3534 </literallayout>
3535 The blktrace instance on the host will save the target
3536 output inside a hostname-timestamp directory:
3537 <literallayout class='monospaced'>
3538 $ ls -al
3539 drwxr-xr-x 10 root root 1024 Oct 28 02:40 .
3540 drwxr-sr-x 4 root root 1024 Oct 26 18:24 ..
3541 drwxr-xr-x 2 root root 1024 Oct 28 02:40 192.168.1.43-2012-10-28-02:40:56
3542 </literallayout>
3543 cd into that directory to see the output files:
3544 <literallayout class='monospaced'>
3545 $ ls -l
3546 -rw-r--r-- 1 root root 369193 Oct 28 02:44 sdc.blktrace.0
3547 -rw-r--r-- 1 root root 197278 Oct 28 02:44 sdc.blktrace.1
3548 </literallayout>
3549 And run blkparse on the host system using the device name:
3550 <literallayout class='monospaced'>
3551 $ blkparse sdc
3552
3553 8,32 1 1 0.000000000 1263 Q RM 6016 + 8 [ls]
3554 8,32 1 0 0.000036038 0 m N cfq1263 alloced
3555 8,32 1 2 0.000039390 1263 G RM 6016 + 8 [ls]
3556 8,32 1 3 0.000049168 1263 I RM 6016 + 8 [ls]
3557 8,32 1 0 0.000056152 0 m N cfq1263 insert_request
3558 8,32 1 0 0.000061600 0 m N cfq1263 add_to_rr
3559 8,32 1 0 0.000075498 0 m N cfq workload slice:300
3560 .
3561 .
3562 .
3563 8,32 0 0 177.266385696 0 m N cfq1267 arm_idle: 8 group_idle: 0
3564 8,32 0 0 177.266388140 0 m N cfq schedule dispatch
3565 8,32 1 0 177.266679239 0 m N cfq1267 slice expired t=0
3566 8,32 1 0 177.266689297 0 m N cfq1267 sl_used=9 disp=6 charge=9 iops=0 sect=56
3567 8,32 1 0 177.266692649 0 m N cfq1267 del_from_rr
3568 8,32 1 0 177.266696560 0 m N cfq1267 put_queue
3569
3570 CPU0 (sdc):
3571 Reads Queued: 0, 0KiB Writes Queued: 270, 21,708KiB
3572 Read Dispatches: 59, 2,628KiB Write Dispatches: 495, 39,964KiB
3573 Reads Requeued: 0 Writes Requeued: 0
3574 Reads Completed: 90, 2,752KiB Writes Completed: 543, 41,596KiB
3575 Read Merges: 0, 0KiB Write Merges: 9, 344KiB
3576 Read depth: 2 Write depth: 2
3577 IO unplugs: 20 Timer unplugs: 1
3578 CPU1 (sdc):
3579 Reads Queued: 688, 2,752KiB Writes Queued: 381, 20,652KiB
3580 Read Dispatches: 31, 124KiB Write Dispatches: 59, 2,396KiB
3581 Reads Requeued: 0 Writes Requeued: 0
3582 Reads Completed: 0, 0KiB Writes Completed: 11, 764KiB
3583 Read Merges: 598, 2,392KiB Write Merges: 88, 448KiB
3584 Read depth: 2 Write depth: 2
3585 IO unplugs: 52 Timer unplugs: 0
3586
3587 Total (sdc):
3588 Reads Queued: 688, 2,752KiB Writes Queued: 651, 42,360KiB
3589 Read Dispatches: 90, 2,752KiB Write Dispatches: 554, 42,360KiB
3590 Reads Requeued: 0 Writes Requeued: 0
3591 Reads Completed: 90, 2,752KiB Writes Completed: 554, 42,360KiB
3592 Read Merges: 598, 2,392KiB Write Merges: 97, 792KiB
3593 IO unplugs: 72 Timer unplugs: 1
3594
3595 Throughput (R/W): 15KiB/s / 238KiB/s
3596 Events (sdc): 9,301 entries
3597 Skips: 0 forward (0 - 0.0%)
3598 </literallayout>
3599 You should see the trace events and summary just as
3600 you would have if you'd run the same command on the target.
3601 </para>
3602 </section>
3603
3604 <section id='tracing-block-io-via-ftrace'>
3605 <title>Tracing Block I/O via 'ftrace'</title>
3606
3607 <para>
3608 It's also possible to trace block I/O using only
3609 <link linkend='the-trace-events-subsystem'>trace events subsystem</link>,
3610 which can be useful for casual tracing
3611 if you don't want bother dealing with the userspace tools.
3612 </para>
3613
3614 <para>
3615 To enable tracing for a given device, use
3616 /sys/block/xxx/trace/enable, where xxx is the device name.
3617 This for example enables tracing for /dev/sdc:
3618 <literallayout class='monospaced'>
3619 root@crownbay:/sys/kernel/debug/tracing# echo 1 > /sys/block/sdc/trace/enable
3620 </literallayout>
3621 Once you've selected the device(s) you want to trace,
3622 selecting the 'blk' tracer will turn the blk tracer on:
3623 <literallayout class='monospaced'>
3624 root@crownbay:/sys/kernel/debug/tracing# cat available_tracers
3625 blk function_graph function nop
3282 3626
3627 root@crownbay:/sys/kernel/debug/tracing# echo blk > current_tracer
3628 </literallayout>
3629 Execute the workload you're interested in:
3630 <literallayout class='monospaced'>
3631 root@crownbay:/sys/kernel/debug/tracing# cat /media/sdc/testfile.txt
3632 </literallayout>
3633 And look at the output (note here that we're using
3634 'trace_pipe' instead of trace to capture this trace -
3635 this allows us to wait around on the pipe for data to
3636 appear):
3637 <literallayout class='monospaced'>
3638 root@crownbay:/sys/kernel/debug/tracing# cat trace_pipe
3639 cat-3587 [001] d..1 3023.276361: 8,32 Q R 1699848 + 8 [cat]
3640 cat-3587 [001] d..1 3023.276410: 8,32 m N cfq3587 alloced
3641 cat-3587 [001] d..1 3023.276415: 8,32 G R 1699848 + 8 [cat]
3642 cat-3587 [001] d..1 3023.276424: 8,32 P N [cat]
3643 cat-3587 [001] d..2 3023.276432: 8,32 I R 1699848 + 8 [cat]
3644 cat-3587 [001] d..1 3023.276439: 8,32 m N cfq3587 insert_request
3645 cat-3587 [001] d..1 3023.276445: 8,32 m N cfq3587 add_to_rr
3646 cat-3587 [001] d..2 3023.276454: 8,32 U N [cat] 1
3647 cat-3587 [001] d..1 3023.276464: 8,32 m N cfq workload slice:150
3648 cat-3587 [001] d..1 3023.276471: 8,32 m N cfq3587 set_active wl_prio:0 wl_type:2
3649 cat-3587 [001] d..1 3023.276478: 8,32 m N cfq3587 fifo= (null)
3650 cat-3587 [001] d..1 3023.276483: 8,32 m N cfq3587 dispatch_insert
3651 cat-3587 [001] d..1 3023.276490: 8,32 m N cfq3587 dispatched a request
3652 cat-3587 [001] d..1 3023.276497: 8,32 m N cfq3587 activate rq, drv=1
3653 cat-3587 [001] d..2 3023.276500: 8,32 D R 1699848 + 8 [cat]
3654 </literallayout>
3655 And this turns off tracing for the specified device:
3656 <literallayout class='monospaced'>
3657 root@crownbay:/sys/kernel/debug/tracing# echo 0 > /sys/block/sdc/trace/enable
3658 </literallayout>
3659 </para>
3660 </section>
3661 </section>
3283 3662
3663 <section id='blktrace-documentation'>
3664 <title>Documentation</title>
3665
3666 <para>
3667 Online versions of the man pages for the commands discussed
3668 in this section can be found here:
3669 <itemizedlist>
3670 <listitem><para><ulink url='http://linux.die.net/man/8/blktrace'>http://linux.die.net/man/8/blktrace</ulink>
3671 </para></listitem>
3672 <listitem><para><ulink url='http://linux.die.net/man/1/blkparse'>http://linux.die.net/man/1/blkparse</ulink>
3673 </para></listitem>
3674 <listitem><para><ulink url='http://linux.die.net/man/8/btrace'>http://linux.die.net/man/8/btrace</ulink>
3675 </para></listitem>
3676 </itemizedlist>
3677 </para>
3678
3679 <para>
3680 The above manpages, along with manpages for the other
3681 blktrace utilities (btt, blkiomon, etc) can be found in the
3682 /doc directory of the blktrace tools git repo:
3683 <literallayout class='monospaced'>
3684 $ git clone git://git.kernel.dk/blktrace.git
3685 </literallayout>
3686 </para>
3687 </section>
3284</section> 3688</section>
3285</chapter> 3689</chapter>
3286<!-- 3690<!--