Once you have gathered the tracing data, you can process it with blkparse as follows:
# blkparse mmcblk2
This provides an stdout output for all the gathered data, and a final summary, as follows:
Input file mmcblk2.blktrace.0 added
Input file mmcblk2.blktrace.1 added
Input file mmcblk2.blktrace.2 added
179,0 0 1 0.000000000 645 A WS 1056768 + 24 <- (179,1) 1048576
179,0 0 2 0.000005667 645 Q WS 1056768 + 24 [dd]
179,0 0 3 0.000021667 645 G WS 1056768 + 24 [dd]
179,0 0 4 0.000029000 645 P N [dd]
179,0 0 5 0.000047334 645 I WS 1056768 + 24 [dd]
179,0 0 6 0.000054667 645 U N [dd] 1
179,0 0 7 0.000104667 95 D WS 1056768 + 24 [mmcqd/2]
179,0 0 8 0.711890667 95 C WS 1056768 + 24 [0]
179,0 0 9 0.712024667 645 A WSM 25184 + 8 <- (179,1) 16992
179,0 0 10 0.712027334 645 Q WSM 25184 + 8 [dd]
179,0 0 11 0.712036334 645 G WSM 25184 + 8 [dd]
179,0 0 12 0.712044667 645 I WSM 25184 + 8 [dd]
179,0 0 13 0.712073667 95 D WSM 25184 + 8 [mmcqd/2]
179,0 0 14 1.428851001 95 C WSM 25184 + 8 [0]
179,0 0 15 1.428936334 645 A WSM 170024 + 8 <- (179,1) 161832
179,0 0 16 1.428938667 645 Q WSM 170024 + 8 [dd]
179,0 0 17 1.428946001 645 G WSM 170024 + 8 [dd]
179,0 0 18 1.428950667 645 P N [dd]
179,0 0 19 1.428959001 645 I WSM 170024 + 8 [dd]
179,0 0 20 1.428964667 645 U N [dd] 1
179,0 0 21 1.428993667 95 D WSM 170024 + 8 [mmcqd/2]
179,0 0 22 2.135076667 95 C WSM 170024 + 8 [0]
.........
CPU0 (mmcblk2):
Reads Queued: 0, 0KiB Writes Queued: 3, 20KiB
Read Dispatches: 0, 0KiB Write Dispatches: 5, 28KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 0, 0KiB Writes Completed: 7, 36KiB
Read Merges: 0, 0KiB Write Merges: 0, 0KiB
Read depth: 0 Write depth: 2
IO unplugs: 2 Timer unplugs: 0
CPU2 (mmcblk2):
Reads Queued: 0, 0KiB Writes Queued: 4, 16KiB
Read Dispatches: 0, 0KiB Write Dispatches: 2, 8KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 0, 0KiB Writes Completed: 0, 0KiB
Read Merges: 0, 0KiB Write Merges: 0, 0KiB
Read depth: 0 Write depth: 2
IO unplugs: 1 Timer unplugs: 0
Total (mmcblk2):
Reads Queued: 0, 0KiB Writes Queued: 7, 36KiB
Read Dispatches: 0, 0KiB Write Dispatches: 7, 36KiB
Reads Requeued: 0 Writes Requeued: 0
Reads Completed: 0, 0KiB Writes Completed: 7, 36KiB
Read Merges: 0, 0KiB Write Merges: 0, 0KiB
IO unplugs: 3 Timer unplugs: 0
Throughput (R/W): 0KiB/s / 1KiB/s
Events (mmcblk2): 48 entries
Skips: 0 forward (0 - 0.0%)
The output format from blkparse is as follows:
179,0 0 7 0.000181333 83 D W 1138688 + 8 [mmcqd/2]
This corresponds to the following:
<mayor,minor> <cpu> <seq_nr> <timestamp> <pid> <actions> <rwbs>
<start block> + <nr of blocks> <command>
The actions column corresponds to:
- A: I/O remapped to a different device
- B: I/O bounced
- C: I/O completed
- D: I/O issued to driver
- F: I/O front merged with request on queue
- G: Get request
- I: I/O inserted into request queue
- M: I/O back merged with request on queue
- P: Plug request
- Q: I/O handled by request queue code
- S: Sleep request
- T: Unplug due to timeout
- U: Unplug request
- X: Split
The RWBS field corresponds to:
- R: Read
- W: Write
- B: Barrier
- S: Synchronous
Another way of tracing non-disruptively is using live monitoring, that is, piping the output of blktrace to blkparse directly without writing anything to disk, as follows:
# blktrace /dev/mmcblk2 -o - | blkparse -i -
This can also be done in just one line:
# btrace /dev/mmcblk2