The I/O stack - which layer is adding the latency

“The disk is slow” is a claim about one layer of a stack with at least five. A write() that takes 200 ms might have spent that time waiting for dirty-page throttling, for a journal commit, in a block-layer queue, or in the device - and the remedy differs completely in each case.

iostat measures exactly one of those layers. Knowing which one is the difference between fixing the problem and replacing a healthy disk.

The layers

  application         write(), read(), fsync()
       |
  ---------------------------------------------  syscall boundary
  page cache          dirty pages, writeback throttling
       |
  filesystem          allocation, journal, barriers
       |
  block layer         scheduler queue, merging, nr_requests   <-- iostat measures HERE
       |
  driver / HBA        hardware queue, command timeouts
       |
  device              media, controller cache, garbage collection

iostat reads /proc/diskstats, which the block layer maintains. Everything above that line is invisible to it, and everything above that line is where a surprising share of real latency lives.

Two consequences follow immediately.

A buffered write returns before iostat sees anything. A write() to a normal file copies into the page cache and returns. The device I/O happens later, during writeback, and may be merged with others or never happen at all if the file is deleted first. Application-observed write latency and w_await are measuring different events.

A slow application with an idle-looking disk is common and normal. If iostat shows await of 0.3 ms and %util of 4% while the application reports 200 ms writes, the disk is not lying. The time is being spent above the block layer.

What each layer’s tool is

The gap between the application number and the iostat number is the budget spent in the layers between them. Measuring both ends and subtracting is the whole technique.

Reading the extended iostat columns

Modern iostat -x reports four operation classes, not two:

iostat -x 1 2

Device  r/s  rkB/s  r_await rareq-sz  w/s  wkB/s  w_await wareq-sz  d/s  dkB/s  d_await  f/s  f_await  aqu-sz  %util
sda    2.10  48.20     0.41    22.95  118.4 4210.8    1.82    35.57  0.00   0.00     0.00 41.2    8.94    1.31   22.40

• r/s, r_await - reads and their latency.
• w/s, w_await - writes and their latency.
• d/s, d_await - discards (TRIM). Usually zero unless fstrim is running or the filesystem is mounted with discard.
• f/s, f_await - flushes. This is the durability path: cache-flush commands the kernel issues on fsync() and on journal commits.

f_await is the column almost nobody reads and it is often the answer. Above, writes complete in 1.82 ms but flushes take 8.94 ms, and there are 41 of them per second. That is 366 ms of flush latency per second of wall clock, and every one of them is a transaction commit that some application thread is waiting on.

The raw counters

/sys/block/DEV/stat is the same data iostat derives from, in one line:

cat /sys/block/sda/stat

310477 77460 16511483 58877 1558346 3764651 117940386 2570268 0 1255743 3143057 32859 0 151804424 674 242514 513237

The 17 fields, in order:

Two of these are worth knowing by heart.

Field 9, in flight, is an instantaneous gauge rather than a counter - the only one in the line. It is also available on its own:

cat /sys/block/sda/inflight

       0        0

Reads and writes currently in flight. Sampling this in a loop gives you queue occupancy without waiting for an iostat interval, which is useful when you need to catch a short spike.

Fields 16 and 17 give average flush latency directly:

awk '{ if ($16 > 0) printf "flush ops=%d  avg=%.2f ms\n", $16, $17/$16;
       else print "no flush operations recorded" }' /sys/block/sda/stat

flush ops=242514  avg=2.12 ms

That is a since-boot average, so it is a baseline rather than a live signal - but a host where the since-boot average flush is 20 ms has a durability-path problem that predates today.

Sectors are always 512 bytes in these fields regardless of the device’s real sector size, so field 7 divided by 2 is kilobytes written.

Splitting the layers with bpftrace

When the gap between application latency and iostat latency needs attributing, trace both ends. The block layer has stable tracepoints, so this needs no kernel symbols, and bpftrace ships a tool that does exactly this:

sudo /usr/sbin/biolatency.bt

The core of that tool is worth reading, because it is the pattern for timing any pair of kernel events:

tracepoint:block:block_bio_queue
{
  @start[args.sector] = nsecs;
}

tracepoint:block:block_rq_complete,
tracepoint:block:block_bio_complete
/@start[args.sector]/
{
  @usecs = hist((nsecs - @start[args.sector]) / 1000);
  delete(@start, args.sector);
}

Start timestamp into a map on the first event, subtract on the second, aggregate into a histogram in the kernel. Output looks like this:

@device_us:
[64, 128)          1204 |@@@@@@@@@@@@                                        |
[128, 256)         5102 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[256, 512)         2244 |@@@@@@@@@@@@@@@@@@@@@@                              |
[512, 1K)           418 |@@@@                                                |
[1K, 2K)             22 |                                                    |

That histogram is device-and-below latency, in microseconds. If it is tight and the application is slow, the time is above the block layer, and the next probe is the syscall:

sudo bpftrace -e 'tracepoint:syscalls:sys_enter_fsync { @s[tid] = nsecs; }
tracepoint:syscalls:sys_exit_fsync /@s[tid]/ {
  @fsync_ms = hist((nsecs - @s[tid]) / 1000000);
  delete(@s, tid);
}'

Two histograms, one subtraction, and the layer is named.

The bcc collection ships equivalents, though the packaged names differ by distribution - on Debian and Ubuntu every tool carries a -bpfcc suffix, so it is biolatency-bpfcc and ext4slower-bpfcc rather than the upstream names:

ls /usr/sbin/*-bpfcc | head -5

The eBPF part of this course covers the cost, the permissions and the kernel requirements of these tools in detail. For now: block tracepoints are among the cheapest probes available, and every one of these one-liners needs root.

Knowledge check