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.