blktrace - A block layer IO tracing utility

Posted on Edited on In , Views:

What can blktrace do?

Let’s dive into the block device layer and see how the I/O are handled in disk queues.

The following stack shows the I/O paths including the block device layer. The application can issue I/O requests directly to block device or through file systems. In the following sections, let’s dig into the block device layer with blktrace in order to understand the I/O pattern and disk queue activities.

        Applications
        |      |   |  
        V      |   | 
  File systems |   |
        |      |   |
        V      |   |
 Page Cache <--|   | 
        |          | 
        V          V
Block I/O Layer: Request Queues
        |
        V 
  SCSI Drivers
        |
        V
 Physical Devices

Don’t forget iostat

iostat is always the first place to understand the I/O characteristics before we turn to other advanced utilities like blktrace.

It provides the following information for the disk IOs.

  • Number of read/write merges per second
  • Number of reads/writes per second
  • Average I/O request size(in sectors)
  • Average request queue size
  • Average I/O wait time

If any of the above metrics indicates disk I/O performance concerns and it’s not sufficient to help us explain the performance issue, we can turn to blktrace or other tracing utilities for more insights.

blktrace and blkparse

To trace the target block device:

$ blktrace -d /dev/<sd-device-name> -D <trace-raw-data-save-dir> -w <trace-time-in-seconds>

To parse the blktrace data:

$ blkparse -i <sd-device-name> -D <trace-raw-data-save-dir> -o blkparse.<sd-device-name>.out -d blktrace.bin

blkparse output snippet:

  8,0    7        3     0.992335623  4180  A  WS 680911952 + 8 <- (8,2) 679885904
  8,0    7        4     0.992336407  4180  Q  WS 680911952 + 8 [jbd2/dm-7-8]
  8,0    7        5     0.992338784  4180  G  WS 680911952 + 8 [jbd2/dm-7-8]
  8,0    7        6     0.992339977  4180  I  WS 680911952 + 8 [jbd2/dm-7-8]
  8,0    7        7     0.992341444  4180  D  WS 680911952 + 8 [jbd2/dm-7-8]
  8,0   56        1     0.992499505     0  C  WS 680911952 + 8 [0]
  8,0   47        7     0.991930131  4180  A  WS 680911920 + 8 <- (8,2) 679885872
  8,0   47        8     0.991930522  4180  Q  WS 680911920 + 8 [jbd2/dm-7-8]
  8,0   47        9     0.991932697  4180  M  WS 680911920 + 8 [jbd2/dm-7-8]

The columns are Dev major,minor, CPU id, Sequence number, Timestamp, PID, Event, Operation, Start block + number of blocks(offset), Process name.

In the above example, The first IO starts at block 680911952 with the offset of 8 blocks. It is handled in the following sequence.

  • Remapped to a different device(8,2)
  • Handled by the request queue code
  • Get the request
  • Inserted to the request queue
  • Dispatch to device driver
  • Completion

The second IO starts at block 680911920 with the offset of 8 blocks. It’s handled in the following sequence.

  • Remapped to a different device(8,2)
  • Handled by the request queue code
  • Back merged with request on queue

blkparse output also includes a summary to explain the number of I/Os in each queuing phase. In the following example, there are 86 writes handled by request queue. 19 out of 86 writes are merged with request on queue. Thus, only 67 writes are issued to device to complete the front end requests.

Total (sda):
 Reads Queued:           0,        0KiB  Writes Queued:          86,      628KiB
 Read Dispatches:        0,        0KiB  Write Dispatches:       67,      628KiB
 Reads Requeued:         0               Writes Requeued:         0
 Reads Completed:        0,        0KiB  Writes Completed:       67,      628KiB
 Read Merges:            0,        0KiB  Write Merges:           19,       88KiB
 IO unplugs:            21               Timer unplugs:           0

btt

btt is a post-processing tool for blktrace. blktrace is capable of producing tremendous amounts of output in the form of multiple individual traces per IO executed during the traced run. It is also capable of producing some general statistics concerning IO rates and the like. btt goes further and produces a variety of overall statistics about each of the individual handling of IOs, and provides data we believe is useful to plot to provide visual comparisons for evaluation.

btt processes the binary file produced by blkparse.The major areas of output measured by btt include:

  • Q2Q : Queue-to-Queue time
  • Q2G : Queue-to-GetRequest time
  • S2G : Sleep-to-GetRequest time
  • G2I : GetRequest-to-Insert time
  • Q2M : Queue-to-Merge time
  • I2D : Insert-to-Issue time
  • M2D : Merge-to-Issue time
  • D2C : Issue-to-Complete time
  • Q2C : Queue-to-Complete time

For the D2C, it includes the driver and device time. It’s the average time from when the actual IO was issued to the driver until is completed (completion trace) back to the block IO layer. The D2C time should be greater than the actual physcial disk I/O latency which is usually measured in disk(array) side.

In the following exampl, 98.9265% of time is spent on D2C which is expected. The average IO time serviced by the disk is 1.65ms. The max IO time is 5.10ms. We may measure the I2D metric for different I/O scheduler, like noop in SSD case.

$ btt -i blktrace.bin -B offset -o btt.out

$ ls btt.*.out*
btt.sda.30s.out.avg  btt.sda.30s.out.dat  btt.sda.30s.out_dhist.dat  btt.sda.30s.out.msg  btt.sda.30s.out_qhist.dat

$ cat btt.out.avg
==================== All Devices ====================

ALL               MIN           AVG           MAX                  N
--------------- ------------- ------------- ------------- -----------

Q2Q               0.000001053   0.304967428   5.071043004          85
Q2G               0.000000338   0.000001928   0.000008143          67
G2I               0.000000161   0.000008231   0.000126276          67
Q2M               0.000000178   0.000000664   0.000002175          19
I2D               0.000000223   0.000003979   0.000024517          67
M2D               0.000002771   0.000030058   0.000116136          19
D2C               0.000089761   0.001640496   0.005096214          86
Q2C               0.000093453   0.001658297   0.005098018          86

==================== Device Overhead ====================

       DEV |       Q2G       G2I       Q2M       I2D       D2C
---------- | --------- --------- --------- --------- ---------
 (  8,  0) |   0.0906%   0.3867%   0.0088%   0.1869%  98.9265%
---------- | --------- --------- --------- --------- ---------
   Overall |   0.0906%   0.3867%   0.0088%   0.1869%  98.9265%
[..]