Measuring Latency & Timing

01 The pattern in one picture

Almost every "how slow is X?" question in the kernel is answered by the same four-step move. Learn it once and you can time syscalls, disk I/O, function calls, lock waits — anything that has a clear start and end.

The trick is that an eBPF program is just a tiny handler that fires when a probe is hit. You get two firings — one when the operation begins, one when it ends — and you need to carry a number from the first to the second. A map (the key/value store from Lesson 5) is the luggage that crosses that gap.

02 nsecs — reading a nanosecond clock

nsecs is a bpftrace builtin: a variable that's always available inside a probe. It returns the current time in nanoseconds since the machine booted — a steadily climbing integer. You don't set it; you just read it whenever a probe fires.

On its own it's not very interesting. Its power is relative: read it at two moments, and the difference is how much time passed between them, measured to the nanosecond.

# Print the kernel's nanosecond clock once per second
sudo bpftrace -e 'interval:s:1 { printf("now = %llu ns since boot\n", nsecs); }'

Source: bpftrace language reference — builtins.

03 Storing the start time per-thread: @start[tid] = nsecs

When the entry probe fires, we record "the operation started now" by writing the timestamp into a map. The line is exactly:

@start[tid] = nsecs;

Two things are happening. @start is a map (the @ prefix means "global map"). The part in brackets, [tid], is the key. tid is another builtin: the thread ID of whatever is running right now. So we're saying: "for this thread, remember the start time."

Why key by tid and not, say, by process?

Because many threads can be inside the same operation at the same time. Imagine ten threads all calling read() at once. If you stored a single start time in a plain variable, the tenth thread's timestamp would clobber the first nine, and every subtraction would be garbage.

A thread, though, is strictly sequential: it enters the function, then returns from it, then maybe enters again. It can't be in two places at once. So tid is the perfect key — it gives each in-flight operation its own private slot, and the return probe (running on that same thread) can look up exactly the right start time.

04 The matching RETURN probe — and computing the delta

Every kernel function you can hook on the way in with a kprobe, you can also hook on the way out with a kretprobe (the "ret" = return). They come as a pair, pointing at the same function:

At the return probe, the thread that's running is the same one that entered, so tid still points at the right slot. The latency is just:

nsecs - @start[tid]   # time-now minus time-at-entry = elapsed ns

Source: bpftrace one-liner tutorial — Lesson 7 (timing vfs_read).

05 Cleanup & guarding — don't trust a half-told story

Guard: only subtract if we actually saw the start

bpftrace may attach your probes mid-operation. A thread could be sitting inside vfs_read already when you start tracing — so the return fires, but there's no matching @start[tid]. Reading a missing key gives 0, and nsecs - 0 would record a fake latency of "billions of nanoseconds." We guard against that with a predicate — the /…/ filter after the probe — so the action runs only when a start exists:

kretprobe:vfs_read /@start[tid]/ {
    # only runs when @start[tid] is non-zero (a real start was seen)
}

Cleanup: delete the slot after you use it

Once you've computed the latency, that thread's start time is spent — leave it in the map and it just leaks memory. Remove it with delete():

delete(@start, tid);   # current syntax: delete(map, key)

Source: bpftrace standard library — delete().

06 Build the latency HISTOGRAM with hist()

Instead of printing one line per read (thousands per second — useless), we feed every delta into hist(). It builds a power-of-2 (log2) histogram entirely in the kernel: each value is dropped into a bucket like [4K, 8K), and only the bucket counts are sent up to user space. That's why it's cheap enough to leave running in production.

@ns = hist(nsecs - @start[tid]);   # bucket the elapsed time

Putting all five steps together — the complete, copy-later script that times every read() reaching the VFS layer:

#!/usr/bin/env bpftrace
# read-latency.bt — distribution of vfs_read durations, in microseconds

BEGIN {
    printf("Tracing vfs_read latency. Hit Ctrl-C to end.\n");
}

kprobe:vfs_read {
    @start[tid] = nsecs;              # ① entry: remember start, per thread
}

kretprobe:vfs_read /@start[tid]/ {       # ② guard: only if we saw the start
    @us = hist((nsecs - @start[tid]) / 1000);  # ③ delta → µs → histogram
    delete(@start, tid);              # ④ cleanup this thread's slot
}

END {
    clear(@start);                     # tidy: drop any half-finished entries
}

On Ctrl-C, bpftrace auto-prints every map. A realistic @us histogram looks like this (left = latency bucket in µs, middle = count, right = ASCII bar):

@us:
[1]                   24 |@@@                                                 |
[2, 4)               418 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[4, 8)               392 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@     |
[8, 16)              153 |@@@@@@@@@@@@@@@@@@                                  |
[16, 32)              41 |@@@@@                                               |
[32, 64)              12 |@                                                   |
[64, 128)              3 |                                                    |
[128, 256)             0 |                                                    |
[256, 512)             0 |                                                    |
[512, 1K)              2 |                                                    |
[1K, 2K)               7 |                                                    |

Source: bpftrace stdlib — hist() (log2 buckets).

07 Interpreting the histogram — read the shape

The whole point of a distribution is that its shape tells a story an average can't. Three things to look for:

08 Variants — same pattern, new questions

Once the entry/return/subtract/histogram shape is in your head, you bend it to ask sharper questions just by changing the map key or the aggregator:

Per-process latency (which program is slow?)

Add comm (the process name) as a histogram key, so you get one histogram per program:

kretprobe:vfs_read /@start[tid]/ {
    @us[comm] = hist((nsecs - @start[tid]) / 1000);  # split by process
    delete(@start, tid);
}

Count by bucket instead of a chart

Don't need the visual? Just tally how many landed in each rough band with count() keyed by a computed bucket — or keep hist() and read the count column. Same data, leaner output.

Source: bpftrace tools/biolatency.bt · Brendan Gregg — BPF Performance Tools.

09 Check yourself

10 Flashcards