Get a real disk latency histogram in one line of bpftrace

iostat -x 1 tells you await is 8ms. Fine. Is that eight thousand requests at 8ms, or seven thousand at 1ms and a thousand at 55ms? Those are completely different problems and the average is identical. The second one is why your p99 is garbage and the first one isn’t a problem at all.

You need the distribution. It takes one command.

The program

bpftrace -e '
tracepoint:block:block_rq_issue    { @start[args->dev, args->sector] = nsecs; }
tracepoint:block:block_rq_complete /@start[args->dev, args->sector]/ {
    @usecs[args->dev] = hist((nsecs - @start[args->dev, args->sector]) / 1000);
    delete(@start[args->dev, args->sector]);
}'

Ctrl-C when you’ve seen enough:

@usecs[271581184]:
[64, 128)         1834 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[128, 256)         912 |@@@@@@@@@@@@@@@@@@@@@@@@@@@                       |
[256, 512)         203 |@@@@@                                             |
[512, 1K)           41 |@                                                 |
[1K, 2K)             8 |                                                  |
[8K, 16K)           94 |@@                                                |
[16K, 32K)          31 |                                                  |

There it is. A clean cluster around 100µs — that’s the device doing its job — and a second mode at 8–32ms that has nothing to do with the first. Ninety-four requests took a hundred times longer than the median. That bimodality is the whole story, and await averaged it into a single number that described neither population.

Two humps means two different things are happening. Cache hits and cache misses. Reads and writes. Requests that got queued behind something and requests that didn’t. Now you have a question worth asking instead of a number to stare at.

Making it answer the next question

Split by operation — reads and writes have completely different characteristics and mixing them is how you lose an afternoon:

bpftrace -e '
tracepoint:block:block_rq_issue { @start[args->dev, args->sector] = nsecs; }
tracepoint:block:block_rq_complete /@start[args->dev, args->sector]/ {
    @[args->rwbs] = hist((nsecs - @start[args->dev, args->sector]) / 1000);
    delete(@start[args->dev, args->sector]);
}'

rwbs is the kernel’s flag string — R, W, WS for sync writes, FF for flushes. If your slow mode is all WS or FF, you’re watching fsync latency, and that’s a durability-versus-speed conversation, not a broken disk.

Or attribute it to a process:

bpftrace -e '
tracepoint:block:block_rq_issue { @c[args->dev, args->sector] = comm; @s[args->dev, args->sector] = nsecs; }
tracepoint:block:block_rq_complete /@s[args->dev, args->sector]/ {
    @[@c[args->dev, args->sector]] = hist((nsecs - @s[args->dev, args->sector]) / 1000);
    delete(@s[args->dev, args->sector]); delete(@c[args->dev, args->sector]);
}'

Careful reading that one: comm at issue time is whichever process was on-CPU when the request was submitted, which for buffered writes is a kernel flush thread, not the application that wrote the data. It’s exactly right for direct and sync I/O and misleading for everything else. Know which you’re looking at.

Why this and not bcc’s biolatency

biolatency from bcc does this and does it well — if it’s installed, use it. The reason to know the bpftrace version is that it’s four lines you can modify. Nobody ships a pre-built tool for “latency histogram, reads only, on this one device, only for requests larger than 128KB, grouped by process.” You write that in thirty seconds if you know the shape above, and never if you only know the tool names.

The shape is always the same, and it generalizes far past disks:

1. Stash a timestamp on the “start” probe, keyed by whatever identifies the request.
2. On the “end” probe, subtract and feed it to hist().
3. delete() the key, or your map grows without bound and bpftrace starts dropping entries.

That last step is not optional. Any request that starts and never completes leaks a map entry. On a box with heavy I/O and an unbounded map you’ll see Map full; can't update element in a few minutes, and your histogram quietly stops being true.

Cost, honestly

Two tracepoints and a hash map. On a busy database server this is low single-digit percent overhead, and tracepoints are the cheap kind of probe — stable ABI, no instruction patching, no kprobe on a function that might get inlined out of existence next kernel. I run this on production without a maintenance window and without asking. Kprobes on hot internal functions deserve more caution; tracepoints in the block layer do not.

What you can’t do is leave it running forever as monitoring. It’s a scalpel: attach, get the distribution, detach, now you know which of the two problems you have. That’s the value — iostat told you there was a number. This tells you there are two populations, and only one of them is worth your afternoon.