Off-CPU Flame Graphs: Where Your Linux Service Waits

Your API takes 900 ms to answer, top says the CPU is bored, and the usual CPU flame graph shows a tidy little mountain that adds up to 20 ms. Congratulations: you are profiling the wrong half of the problem. Off-CPU flame graphs show where your Linux service is waiting instead of working, and with eBPF you can build one in about five minutes without recompiling anything.

On-CPU versus off-CPU: the missing 880 ms

A classic CPU profiler samples what threads are executing. A thread that is blocked on a disk read, a mutex, a socket or a futex is not executing, so it never gets sampled. For a latency problem that is exactly the time you care about. The idea of off-CPU analysis is to flip the question: record every time a thread leaves the CPU, record when it comes back, and charge the gap to the stack it was blocked in.

The bcc tool offcputime states it plainly in its documentation: it shows stack traces that were blocked, and the total duration they were blocked. It works by tracing when threads block and when they return to the CPU, and measuring the time in between. Feed that output to FlameGraph and the width of each box becomes microseconds of waiting.

A deliberately slow victim to profile

Let us build a target that waits in three different ways: it sleeps on a lock held by another thread, it forces data to disk with fsync, and it burns a little CPU. Save this as victim.py.

import os, threading, time

lock = threading.Lock()

def lock_holder():
    while True:
        with lock:
            time.sleep(0.05)   # holds the lock while sleeping
        time.sleep(0.001)

def handler():
    fd = os.open("/tmp/victim.dat", os.O_WRONLY | os.O_CREAT)
    while True:
        with lock:                       # off-CPU: waiting for the lock
            pass
        os.write(fd, b"x" * 4096)
        os.fsync(fd)                     # off-CPU: waiting for the disk
        sum(i * i for i in range(20000)) # on-CPU: a little real work

threading.Thread(target=lock_holder, daemon=True).start()
handler()

python3 victim.py &
VPID=$!
sleep 2
top -b -n 1 -p $VPID | tail -n 2

Method 1: bcc offcputime into a flame graph

On most distributions the bcc tools ship as bcc-tools (the binary may be named offcputime-bpfcc on Debian and Ubuntu). The options documented in the tool's example file that matter here are: a trailing duration in seconds, -p PID to trace one process, -f for folded stack output, -U or -K for user-only or kernel-only stacks, -m and -M to keep only blocks longer or shorter than a number of microseconds, and --state to filter by thread-state bitmask, where 2 means TASK_UNINTERRUPTIBLE.

git clone https://github.com/brendangregg/FlameGraph
sudo offcputime-bpfcc -f -p $VPID 30 > out.stacks

./FlameGraph/flamegraph.pl --colors io --countname us \
    --title "Off-CPU time (us), victim.py" < out.stacks > offcpu.svg

The flamegraph.pl script reads folded stacks and writes an SVG; --title, --countname and --colors are documented options, and io is one of the listed palettes. Open offcpu.svg in a browser. You should see two fat towers: one ending in a futex wait (the lock) and one ending in the fsync path (the disk). Their widths tell you which one to fix first, which is something no amount of staring at top will do.

Method 2: a bpftrace one-liner view

bcc is great, but sometimes you want to ask a narrower question without leaving the shell. bpftrace attaches to the sched:sched_switch tracepoint, which fires on every context switch with prev_pid, next_pid and prev_state fields. A prev_state of 0 means the thread was still runnable (it was preempted), anything else means it went to sleep. The script below records when the target thread goes to sleep and builds a histogram of how long it stayed blocked.

sudo bpftrace -e '
tracepoint:sched:sched_switch
/args.prev_pid == $1 && args.prev_state != 0/
{
  @start[args.prev_pid] = nsecs;
}

tracepoint:sched:sched_switch
/args.next_pid == $1 && @start[args.next_pid]/
{
  @blocked_us = hist((nsecs - @start[args.next_pid]) / 1000);
  delete(@start, args.next_pid);
}
' $VPID

Press Ctrl-C after a few seconds and bpftrace prints a log2 histogram. Note that $1 here is the PID, which is also the main thread's TID; for other threads, match on their TIDs from ls /proc/PID/task. A bimodal histogram, say a cluster near 50 ms and another near a millisecond, is the signature of two different wait causes, which is your cue to go back to the flame graph and read the stacks.

Reading the graph: three questions to ask

• Is it disk? Look for block-layer and filesystem frames under the tower (fsync, write, read paths). Filter to uninterruptible sleeps with offcputime --state 2 to isolate this class of wait.
• Is it a lock? Futex wait frames with a user-space stack underneath point at contention in your own code or a library. The user-space frames tell you which lock call sites to shrink.
• Is it the network or a dependency? Stacks ending in socket, poll or epoll waits are often just an idle worker waiting for work. Idle threads look scary but are usually not your problem, so ignore towers that are simply a thread pool parked on its queue.

Gotchas that waste an afternoon

• Idle is not latency. A worker blocked waiting for a request is off-CPU for 99 percent of its life. Judge stacks by whether they sit on the request path, not by width alone.
• User stacks need frame pointers or symbol support. If your runtime or libc is built without frame pointers, user-space frames may show as hex addresses. Use -K for a kernel-only view first, which still separates disk from locks from network.
• Preemption is a different wait. If a runnable thread cannot get a CPU, that time is run-queue delay, not blocking. Pressure metrics such as PSI and tools like perf sched can show that instead; see our PSI guide.
• Keep traces short and filtered. Total blocked time can exceed wall-clock time because many threads wait in parallel, so compare towers with each other rather than to the runtime.

Takeaway

When latency and CPU usage disagree, stop sampling the CPU and start accounting for sleep. Run offcputime on one PID for 30 seconds, render it with flamegraph.pl using the io palette, and read the widest towers on the request path. Fix the biggest wait, measure again, and repeat. Pair this with an on-CPU flame graph and you have the complete picture of where every millisecond went.