Measuring Time a Thread Spends Blocked Instead of Running

A CPU-time profiler answers a question nobody asked. It reports where the processor was executing, which for a latency-bound service is a small fraction of the elapsed time; the rest is spent waiting on locks, sockets, page faults, and the scheduler. The waiting is where latency comes from, and it produces no samples at all under a sampler that is armed only while the thread is on a core.

What “blocked” means in the kernel’s state machine

A task on Linux is in one of a small number of states. TASK_RUNNING means it is runnable: either executing or on a run queue waiting for a core. TASK_INTERRUPTIBLE and TASK_UNINTERRUPTIBLE mean it is sleeping, waiting for a condition, and will be woken by a signal or only by the condition. TASK_IDLE is an uninterruptible sleep that does not contribute to load average. Each transition between states is a scheduler event, and every transition has a timestamp the kernel can export.

The distinction that matters for measurement is between being off-CPU and being blocked. Off-CPU time includes both sleeping and waiting on a run queue. The first is a property of the program; it asked for something and waited. The second is a property of the machine; it was ready and there was no core free. Summing them into a single “off-CPU” figure conflates a program’s own blocking with the effects of contention, and the two lead to opposite conclusions about where to spend effort.

The scheduler tracepoints expose the raw material: sched_switch reports the outgoing task, the incoming task, the outgoing task’s previous state, and the priority of both. A stream of these events, with timestamps and CPU identifiers, is enough to reconstruct every interval during which each task was not running and to classify it by the state it entered.

Building blocked-time from switch records

The reconstruction is a fold over the event stream. For each sched_switch, close the current on-CPU interval of the outgoing task at the event’s timestamp, then open an interval for the outgoing task attributed to its previous state, and close the incoming task’s off-CPU interval if one is open. When the task that went to sleep appears again as the incoming task, its interval is closed and the duration attributed to the state it slept in.

# Fold off-CPU durations, given "timestamp thread_id state" per scheduler
# event (a sleep, or a wake for a task that was previously asleep).
{
    ts = $1; tid = $2; state = $3
    if (tid in start) {                  # this event ends the open interval
        d = ts - start[tid]
        if (d > 0) hist[pending[tid], bucket(d)]++
        delete start[tid]
    }
    if (state !~ /^R/) {                 # R means runnable: ending, not sleeping
        start[tid] = ts; pending[tid] = state   # remember which sleep it was
    }
}
function bucket(d) { return d < 0.001 ? "1ms" : (d < 0.01 ? "10ms" : "100ms") }
END { for (k in hist) print k, hist[k] }

The script is deliberately crude, and its shape is the point: an interval opens when a task sleeps, closes at the next event for that task, and is bucketed by the state it slept in. Real implementations key on the thread id rather than the name, handle tasks that exit while sleeping, and cap absurd intervals caused by lost events in a ring buffer.

The state recorded at the opening event is what separates the two kinds of off-CPU time. A task whose state was runnable was preempted; it was not blocked, it was displaced. A task that went to sleep on a condition was blocked. Aggregate the first as sched_wait and the second as blocked, and the totals answer different questions.

Attaching a stack to the block

A duration alone says a thread waited 40 ms; it does not say for what. Off-CPU profiling attaches a stack to each interval, and the stack used is the one captured at the moment of the switch out, because that is where the blocking call is: futex_wait, epoll_wait, a read on a socket, a page-fault handler. The resulting profile is a flame graph of blocked time, read the same way as a CPU flame graph but with widths in waiting nanoseconds.

Two decisions shape that graph. The first is whether to capture the stack at the switch-out or the wake-up. Switch-out points at the blocking call. Wake-up points at whatever was executing when the wakeup arrived, which is usually unrelated and useless for attribution. Some designs capture both and keep the pair, which lets a blocked interval be attributed to the caller that slept and the waker that woke it.

The second decision is granularity. Capturing a stack at every context switch is expensive on a busy machine: switches can occur at rates of hundreds of thousands per second per core, and each stack capture is the unwinding problem described in stack unwinding. Production systems therefore either sample the switches, capturing a stack only for intervals longer than a threshold or only for one in k, or aggregate by the blocking call site rather than by full stack.

The threshold is a statistical instrument

Filtering by duration is not just an optimisation; it changes the answer. If only intervals longer than 1 ms are recorded, the profile describes the distribution of long waits and says nothing about the aggregate cost of many short ones. Ten million waits of 10 µs each sum to a hundred seconds, and every one of them is dropped by a 1 ms threshold. Systems that use a threshold are measuring the tail by construction, and reporting the tail’s profile as if it were the total misstates where the time goes.

The right use of a threshold is in combination with two numbers: the count of intervals below the threshold and their summed duration, both of which are cheap to collect without a stack. When the sub-threshold total is small relative to the above-threshold total, the stack-captured profile is representative. When it is not, the profile is a partial view and the omitted part must be reported as such.

Blocked time is not always latency

Attributing blocked time to a call site and then optimising that call site is a natural but frequently wrong move. The chain of reasoning fails in three places.

A thread blocked in epoll_wait with no pending work is idle, not slow. Its blocked time is the absence of demand, and reducing it would mean nothing. Distinguishing a wait for work from a wait for a resource requires knowing whether the resource was contended: a lock acquisition that blocked for 5 ms because another thread held it for 5 ms is a scalability problem, while a socket read that blocked because the peer was slow is a problem in another process entirely.

Blocking time is per thread, and threads overlap. Fifty seconds of blocked time summed across eight threads in a one-minute window is an average of about 0.83 threads blocked at any instant, so the other seven were available for work; the same 50 seconds piled onto one thread would mean that thread was blocked for five sixths of the window. The per-thread number becomes latency only after dividing by concurrency and adding the on-CPU time of the critical path.

Wakeup latency adds to the measured block. The interval from the condition becoming true to the thread actually running includes the waker’s own scheduling, the run queue delay, and any IPI needed to wake a core from an idle state. On a busy system, the run-queue portion alone can be milliseconds, and it appears in the blocked-time profile attributed to the blocking call even though the call returned promptly. The sched_stat tracepoints expose run-queue delay separately for exactly this reason: the difference between “the lock was held for 4 ms” and “the lock was free but we ran 4 ms later” is a contention problem versus a placement problem.

Combining the two halves

Neither an on-CPU profile nor an off-CPU profile is a picture of latency, and the sum of the two is not the critical path. What the pair does give is a per-thread accounting that closes: for each thread, total elapsed time equals on-CPU time plus run-queue wait plus blocked time plus a residual for time spent in states the tracer did not observe. That accounting is the diagnostic. A thread whose elapsed time is mostly on-CPU has a code cost; a thread mostly blocked has a dependency cost; a thread mostly run-queueing has a machine cost.

The residual is worth watching. It grows when events are lost, when tracepoints are disabled, and when threads are created and destroyed faster than the tracer can track them. A residual that exceeds a few percent means the other three numbers cannot be trusted to sum to the elapsed time, and any conclusion drawn from their ratios is unsound.

The practical form of the combined view is a timeline for a single request or a small set of threads, with the on-CPU intervals and the blocked intervals laid end to end and labelled by call site. This is the same data as the two flame graphs, rearranged along the time axis, and it answers the question the aggregate profiles cannot: which of the many blocked intervals in the profile were actually on the critical path of the request that was slow. Choosing which requests to look at is a separate problem, treated in selecting workloads to profile.