Disk I/O profiling with eBPF

Coroot's node-agent has had an eBPF CPU profiler for a long time. When something burns CPU, you open the flame graph and see which function. When something waits for the disk, you have nothing: the CPU profile is flat, because waiting does not consume CPU.

The metrics for disk problems are always the same. Latency on a volume goes up, utilization hits 100%, queries slow down. Every chart agrees the disk is the bottleneck, none of them says what the database was doing while it waited. Flushing pages? Syncing the journal? Reading data that fell out of the cache?

We wanted the same flame graph as for CPU, where the value is time spent waiting for the disk.

What we wanted #

• Stack traces of the application, so the answer is a function, not a device name.
• Asynchronous I/O too. Databases use libaio and io_uring, and they fsync from one thread while a hundred others wait on a lock.
• Cheap enough to be on by default. If it needs a flag, nobody turns it on before the incident.
• No new storage. Profiles live in ClickHouse, and we did not want to double the volume.

Why not off-CPU profiling #

A CPU profiler only sees threads while they run. Off-CPU profiling is the mirror image: it measures the time threads spend not running, which is where all the waiting is. Disk reads, lock contention, network round trips, sleeping on a timer.

The usual way to get it is to hook the scheduler. Every time a thread is switched out, record a timestamp and its stack. When it is switched back in, add the time it was away to that stack. You get a flame graph where frame width is wait time instead of CPU time. We tried it first and dropped it.

It records every sleep. Locks, sockets, timers, idle workers waiting for work. A database with 500 connections spends almost all of its off-CPU time doing nothing in particular, and the disk waits are buried in that.

It costs the most where it matters the most. A busy node does tens of thousands of context switches per second per core, and sched_switch is the hottest path in the kernel. A stack walk on each one is not an "on by default" kind of cost.

And it answers the wrong question for async I/O. A thread that submits through io_uring never sleeps for the request. A thread waiting on a lock held by the thread doing the fsync is recorded as a lock wait, which is true and useless.

What we actually wanted was narrower: for every block request, how long it took and which code path issued it. That is a question for the block layer, not for the scheduler.

Hooking the block layer #

Every request to a block device passes through submit_bio() on the way in and bio_endio() on the way out. The first runs in the context of the task that issued the request, which is exactly the stack we want. The second runs when the device is done, and we only need to match it with the first.

So: a kprobe on each, and a map keyed by the bio pointer.

SEC("kprobe/submit_bio")
int submit_bio_enter(struct pt_regs *ctx, struct bio *bio) {
    struct io_state state = {
        .key.pid = tgid,
        .key.user_stack = bpf_get_stackid(ctx, &stacks, USER_STACKID_FLAGS),
        .start = bpf_ktime_get_ns(),
    };
    bpf_map_update_elem(&io_reqs, &bio, &state, BPF_ANY);
    return 0;
}

SEC("kprobe/bio_endio")
int bio_endio_enter(struct pt_regs *ctx, struct bio *bio) {
    struct io_state *state = bpf_map_lookup_elem(&io_reqs, &bio);
    if (!state) return 0;
    u64 delta = bpf_ktime_get_ns() - state->start;
    bpf_map_delete_elem(&io_reqs, &bio);
    struct sample_value *val = sample_value(&state->key);
    if (val) val->io_time_ns += delta;
    return 0;
}

The value is the same struct the CPU profiler uses for its sample counts, with three more fields: I/O time, bytes read, bytes written. Same stacks, same map, same upload. One pprof per container with four sample types sharing one location table.

That was the "no new storage" requirement, solved for free. Storing profiles in ClickHouse is already very cheap: a process has a limited set of distinct stacks, so they are stored once and the per-minute rows only reference them by hash, and the columnar format compresses those rows by an order of magnitude. Three more numbers per row are almost invisible. See how Coroot stores profiles in ClickHouse for the details.

Two details that cost us time:

• Bytes have to be read at submission. bi_iter.bi_size is the remaining size, and by completion it is zero.
• Only reads and writes count as bytes. A discard bio carries the discarded range as its size, so an fstrim run would look like gigabytes written by whoever deleted a file.

And one dead end. Our first version used the block tracepoints, block_bio_queue and block_bio_complete. It worked on the dev machine and recorded nothing on the test cluster. block_bio_complete only fires for bio-based devices like md and dm. For every blk-mq device, which is every NVMe, virtio and SCSI disk today, completion is traced at the request level and the bio tracepoint is skipped.

Time, bytes read, bytes written #

Three values per stack, because they answer three different questions.

• I/O time: who waited, and for how long. Grows when the disk gets slower even if the application does the same work.
• Bytes read: who misses the cache. A scan of a collection larger than the cache, a database warming up after a restart, a backup, a compaction.
• Bytes written: who pushes data out. Mostly background machinery: checkpoints, page flushing, the redo log or WAL and its fdatasync on every commit, compactions, temp files for sorts.

Time up with bytes flat means the device got slower. Bytes up with time up means the application does more I/O. Bytes alone cannot tell whether anyone waited: a compaction nobody waits for and a journal write every transaction waits for look alike in bytes.

What it sees #

Everything the application does to reach the disk itself: O_DIRECT reads and writes, page cache misses, memory mapped file faults, fsync, libaio, io_uring. Async works because we never cared who sleeps, only who submits.

What it does not see is I/O that kernel threads submit on the application's behalf. Buffered writes are flushed later by the writeback threads, so an application that writes a lot and never syncs shows little I/O time. Its fsync calls, which are what it actually waits for, are attributed correctly.

Sampling #

A single NVMe device does several hundred thousand requests per second. A user stack walk per request is out of the question, and the stack walk is the expensive part: the map update is cheap, bpf_get_stackid with frame pointer unwinding of a deep MongoDB stack is not.

The CPU profiler samples at a fixed rate and multiplies each sample by the period. We do the same, per CPU: at most one bio per millisecond gets a stack, and it carries the number of bios that CPU has seen since the previous sample as its weight.

struct io_sampler {
    u64 next;        // when the next sample may be taken
    u64 count;       // bios seen since the last sample
    u64 read_bytes;  // and their bytes, by direction
    u64 write_bytes;
};

sampler->count++;
sampler->read_bytes += size;   // or write_bytes
if (now < sampler->next)
    return 0;                  // skipped: no stack, nothing stored
weight = sampler->count;       // this bio stands for all of them
...
sampler->count = 0;
sampler->next = now + 1000000; // 1ms

At completion, the sampled request's latency is multiplied by its weight. The bytes of the skipped requests are charged to the sampled stack in the same way.

Totals come out exact. A node doing 10,000 requests per second at 1ms shows 10 seconds of I/O time per second, the way the CPU profile shows busy cores. What is approximate is the attribution between stacks: a 1MB readahead bio sampled next to a run of 4KB journal writes gets their bytes, and the other way round. Over a minute of profiling this averages out, as with any sampling profiler.

The sampler is per CPU rather than global so that there is no contention on it, and a skipped request costs about 100ns: a counter update at submission and a map miss at completion. The map of in-flight requests is an LRU hash keyed by the bio pointer, so a bio that never completes, or completes on a path we do not see, ages out instead of leaking.

Overhead #

12-core machine, PostgreSQL under pgbench, runs alternated with and without I/O profiling. Then fio with io_uring at the device limit.

Workload	Baseline	With I/O profiling
pgbench select-only	74,000 TPS	0 to 1.6% lower
pgbench TPC-B	1,600 TPS	within run-to-run noise
fio io_uring, 4k random reads	700,000 IOPS	within run-to-run noise

bpf_stats reports about 100ns per request at submission and 70ns at completion, which is 1.6% of one core at 700,000 IOPS. The agent's memory grew by about 1MB. So it is on by default.

In Coroot #

The profiles show up in the Profiling tab under the I/O category, with the volumes' I/O load or bandwidth charted above the flame graph. Comparison mode works as for CPU: select the incident on the chart, get a diff against the period before it.

The Storage tab links to them: the I/O load charts open the I/O time profile, the bandwidth charts open the read or write bytes profile, whichever moved more data on that volume.

A retention job #

To try it on something real we used rca-lab, our Kubernetes cluster with a microservice stack and real databases behind it. We did not have to break anything: the lab has a retention CronJob that runs every four hours and deletes orders older than seven days from a three-node Percona XtraDB Cluster, in small batches, pacing itself on Galera flow control. It is the kind of job every production database has, and nobody looks at.

Here is what it does to the disks. Reads on all three nodes go from near zero to 7MB/s, writes from 2MB/s to 30MB/s, and the I/O load from 0.5 to 5 seconds per second. Query latency on the writer doubles, from 4ms to 9ms, order-service gets about 20% slower. Not an outage, just a cluster that spends ten minutes every four hours mostly talking to its disks.

The read bytes profile, comparing the run with the period before it, splits the reads between two kinds of threads. On the left, red, the client connection that runs the DELETE. On the right, the Galera replication appliers on the other two nodes. Zooming into the writer:

Sql_cmd_delete::delete_from_single_table is up 83%, and it reads in two places: IndexRangeScanIterator::Read walks the range of rows to delete, and ha_delete_row updates the secondary indexes of each one. Both end in buf_read_page and pread64. The rows being deleted are the oldest in the table, so their pages are the coldest, long evicted from the buffer pool, and every one of them has to come back from disk just to be deleted. On the replicas the same work shows up as Rows_log_event::do_index_scan_and_update → rnd_pos: the appliers look up each deleted row by primary key, and hit the same cold pages.

The writes are not the DELETE itself. They are the page cleaner and the doublewrite buffer flushing the pages the deletes dirtied, through the native AIO path, on all three nodes at once. One job, three nodes, 30MB/s of writes each.

None of this is visible from the query. The job issues small, well-indexed deletes. The profile shows that each one costs a random read on every node and a page flush behind it, which is why the sensible fix is not a faster disk but partitioning the table by day and dropping partitions.

I/O profiles in root cause analysis #

Coroot's AI root cause analysis already pulls CPU profiles when CPU usage correlates with an anomaly, and heap profiles when memory does. It now does the same for disk: when a volume's latency correlates with the incident, or a database reports buffer pool misses or cache pressure, the investigation fetches the I/O profile whose code paths changed the most and reads it like an engineer would.

Here is the retention run as the RCA saw it, investigating the latency of the services behind the database:

It found the DELETE workload in the query statistics, and used the disk read profile to explain how a job that deletes rows in small batches slows the whole cluster: the replication apply path on the other nodes went from 6% to 56% of all disk reads. That is the part no metric shows, and the part that turns "MySQL got slow at 17:27" into something you can act on.

Summary #

Disk I/O profiling is on by default in coroot-node-agent, for every process on the node, with no instrumentation and without significant overhead. "The disk is busy" becomes "this is the code that keeps it busy, and here is the stack".

It is available in both Coroot Community and Enterprise Edition. Check the documentation, give us a ⭐ on GitHub if you find it useful, and join the conversation on Slack.