3.6.2. 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.