Debugging Latency with eBPF: bpftrace One-Liners That Find It

Debugging Latency with eBPF: bpftrace One-Liners That Find It#

A service was returning p99 responses at 800ms while p50 sat at 12ms. Classic tail latency. The application traces showed the time was spent "in the handler," which is where traces go to be useless, because the handler was blocked on something the application-level instrumentation couldn't see. bpftrace could see it, because it attaches to the kernel and watches what the process is actually doing between the lines your APM records.

If you've never used it, bpftrace is a high-level front end to eBPF. You write a short probe, it compiles to bytecode, the kernel runs it safely. No recompiling the kernel, no rebooting. You need root and a reasonably modern kernel (5.x or later is comfortable; we're on 6.8).

Where is the time actually going#

Start broad. This counts syscalls by the target process so you know what it's spending its time asking the kernel to do.

bpftrace -e 'tracepoint:raw_syscalls:sys_enter /pid == 24519/ {
  @[probe] = count();
}'

If you don't know the syscall name-to-number mapping, use the syscalls tracepoints instead, which are named:

bpftrace -e 'tracepoint:syscalls:sys_enter_* /comm == "api-server"/ {
  @[probe] = count();
}'

For our slow service the top entry was sys_enter_fdatasync, which was the tell. The handler was calling fsync somewhere we didn't expect, probably a logging library flushing to disk synchronously.

Timing a specific syscall#

Counting tells you what's frequent, not what's slow. To get latency, pair the enter and exit tracepoints and take the delta. This histogram shows how long read calls take, in microseconds bucketed by power of two:

bpftrace -e '
tracepoint:syscalls:sys_enter_read /comm == "api-server"/ { @start[tid] = nsecs; }
tracepoint:syscalls:sys_exit_read /comm == "api-server"/ {
  $d = nsecs - @start[tid];
  @us = hist($d / 1000);
  delete(@start[tid]);
}'

Output looks like this, and the shape is the whole point:

@us:
[4, 8)        18201 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[8, 16)        2100 |@@@@                                    |
...
[16K, 32K)       47 |                                        |
[32K, 64K)       31 |                                        |

Most reads finish in single-digit microseconds. But there's a second cluster up at 16-64 milliseconds. That bimodal shape is the fingerprint of tail latency. The average would have hidden it completely; the histogram shows two populations.

Was it disk, or was it scheduling#

Two of the most common hidden causes of tail latency are the disk taking too long and the process not getting CPU time when it's ready to run. eBPF sees both.

Block I/O latency, which reveals a slow or saturated disk:

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

Run-queue latency, which is how long a task waited on the run queue after becoming runnable before the scheduler gave it a CPU:

bpftrace -e '
tracepoint:sched:sched_wakeup { @qtime[args->pid] = nsecs; }
tracepoint:sched:sched_switch /@qtime[args->next_pid]/ {
  @runq_us = hist((nsecs - @qtime[args->next_pid]) / 1000);
  delete(@qtime[args->next_pid]);
}'

For us the block histogram was clean, everything under a millisecond because it was NVMe. The run-queue histogram had a fat tail past 20ms, which pointed at CPU contention. A noisy neighbor container had no CPU limit and was starving our process during its batch jobs. A cpu cgroup quota on the neighbor fixed the p99, and we never touched our own code.

The off-CPU question#

The sharpest tool for "my process is blocked and I don't know on what" is off-CPU analysis. When a thread goes off CPU, capture where it was in the stack.

bpftrace -e '
kprobe:finish_task_switch /args->prev->comm == 0/ {}
'  # simplified; in practice use the offcputime tool from bcc

Honestly, for off-CPU I reach for offcputime-bpfcc from the bcc-tools package rather than hand-rolling it, because getting the stack capture right is fiddly. offcputime -p 24519 10 gives you a flame-graph-ready breakdown of exactly what your process was blocked on for ten seconds. Ours was blocked in fdatasync, closing the loop on the very first syscall count.

The call we'd make#

When application traces bottom out at "time spent in the handler," stop staring at them and drop to eBPF. Start with a syscall count to find the suspect, then a paired enter/exit histogram to confirm it's bimodal, then decide between disk and scheduling with the block and run-queue probes. It's a fifteen-minute investigation that has replaced days of guessing for us. Keep bpftrace and bcc-tools installed on your hosts before the incident, because the worst time to learn the probe syntax is at 3am with a pager going off.