Off-CPU Time and Scheduler Delay as a Profile

A CPU profile answers where processor time went. Almost every question that starts with a latency complaint needs the opposite number: where the time went while the thread was not on a processor. Blocking on a socket, waiting on a futex, sleeping in a retry, and sitting on a run queue are all invisible to a CPU-time sampler, because a thread that is not running executes no instructions to be sampled.

The complement is measurable, and the measurement is structurally different from sampling: it is event-driven, it is exact rather than statistical, and its cost scales with the number of scheduler transitions rather than with a chosen frequency. That difference in cost model is what makes off-CPU profiling the part of continuous collection that has to be engineered most carefully.

Three kinds of not-running

Time off the processor splits into categories that have different causes and different fixes, and conflating them is the main source of misdiagnosis.

Blocked time is when the thread is sleeping, waiting for a wakeup. Blocking a mutex, reading from a socket, waiting on a condition variable, or sleeping in a timer all put the thread in a state where the scheduler will not select it until an event arrives. The stack at the moment it blocked identifies the call site that requested the wait.

Runnable but not running time is scheduler delay. The thread was ready and the CPU was busy with other work, so it sat in the run queue. The absolute amount on a machine with enough idle capacity is small; on a fully subscribed machine it can be a substantial fraction of latency, and it is the mechanism by which a service on a saturated host becomes slower without any change to its own code.

Involuntary preemption is the same phenomenon at a different granularity: a thread that was running was removed because a higher-priority thread or an interrupt needed the processor. The time it loses is not a block, since it never asked to wait, and its stack at the moment of preemption says nothing about where it will resume.

A fourth category is often folded in: time the thread spent running but on behalf of someone else, such as a kernel worker thread doing I/O for a request. Attributing that requires following work across threads, which is a different technique.

Blocked time is captured at the transition

The measurement of blocked time is straightforward in outline. A scheduler event reports that one thread is being switched out and another switched in, with a state value describing why the outgoing thread left. A pair of events, one for the switch out and one for the switch in of the same thread, bounds an interval during which the thread was not running. The elapsed time between them is the off-CPU duration, and the stack at the switch-out moment is the attributed stack.

Attribution to the switch-out stack rather than the switch-in stack is the central design choice, and it is the right one because the block was requested by the code that called the blocking operation. If the sampler instead used the stack at wake time, it would attribute the wait to whatever the waker was doing, which answers a different question: who caused the wakeup rather than who suffered the wait. Both are useful, and confusing them produces stacks that look plausible and point at the wrong code.

The state value distinguishes blocked from preempted, which matters because the two have different interpretations. A thread switched out in a sleeping state chose to wait; a thread switched out while runnable was displaced. Aggregating both into a single off-CPU number produces a distribution that mixes a self-inflicted delay with an environmental one.

struct wait_key { uint64_t stack_id; uint32_t state; };

/* Called for each sched_switch pair: on(t) is when the thread left the CPU. */
static void account(uint64_t on_ns, uint64_t off_ns, uint32_t state)
{
    uint64_t dur = off_ns - on_ns;
    /* Log-scale buckets: off-CPU durations span microseconds to seconds,
       so linear buckets would put almost every sample in the first one. */
    int bucket = dur ? 63 - __builtin_clzll(dur) : 0;
    agg[hash(stack_id, state)].buckets[bucket]++;
    agg[hash(stack_id, state)].total_ns += dur;
}

The clock used for the timestamps must be the same across all CPUs, or durations computed from events on different cores will be nonsense. A monotonic clock readable from kernel context serves this purpose; wall-clock time does not.

Run-queue latency needs a different pair of events

The interval between a thread becoming runnable and being selected is not bounded by a switch-out event for that thread, because the thread was not running before it became runnable. It is bounded by a wakeup event, which reports that a thread was made runnable, and the subsequent switch-in event for that thread. The difference between those two timestamps is the scheduler delay.

Measuring it requires tracking two events per thread and correlating them, which the kernel tracing interface supports by reporting the target thread on the wakeup event. The stack at the wakeup moment is the stack that made the thread runnable, which is usually a different thread’s stack: the producer that enqueued work. Attributed that way, run-queue latency answers “which producer’s wakeup was delayed”, which is often the more actionable framing, since the consumer has no control over the delay.

On a host where the run queue is never empty, scheduler delay is roughly the time to finish the current slice plus whatever higher-priority work intervenes. The kernel’s scheduling policies and their tunables determine the slice lengths; the ordinary time-sharing policy runs tasks for a slice on the order of milliseconds before considering a switch, with a boost for tasks that have slept. The practical numbers are that a woken task typically preempts a running task if it has slept, and does not if it has been running, so the delay after a wakeup is bimodal: near-zero for the common case and up to a slice length when it is not.

Why the distribution, not the mean, is the answer

Off-CPU durations are heavy-tailed in the extreme, because waiting times are products of queueing and retries rather than sums of a fixed cost. A lock acquisition costs the critical section of whoever holds it, which may itself include a blocking operation, which may itself wait. The resulting distribution has a long right tail and a mean dominated by it.

Reporting an average off-CPU time per call site therefore produces a number that describes the outliers and misrepresents the common case. The useful representation is a distribution with log-spaced buckets, showing the mode, the median, and the tail separately, because the three usually have different causes: the mode is the ordinary wait, the median reflects the typical contention level, and the tail reflects the pathological cases that show up in latency graphs.

The heavy tail also means that sampling the transition events rather than recording all of them is a legitimate way to bound cost, provided the sampling is unbiased. Skipping every $k$-th transition records a random subset of waits, and the aggregate duration per call site is estimated from that subset. The estimate is biased toward short waits if the sampling is fixed-period rather than random, because a long wait spans more sampling periods and would be counted more than once; the fix is to sample transitions rather than time, so each transition is either recorded or not.

Cost scales with context switches, not with frequency

This is the property that makes off-CPU instrumentation expensive in a way that CPU sampling is not. A host running a busy network service performs context switches at a rate set by its I/O and scheduling activity, which on many cores and many threads is on the order of tens to hundreds of thousands per second. Attaching a program to the switch event fires that program on every one of them.

The cost per firing is small but not free: the tracepoint’s own bookkeeping, the program’s execution, and a stack capture if the program requests one. Stack capture is the dominant term and is the reason a naive implementation that walks the stack on every switch can consume a noticeable fraction of a host’s CPU.

The standard mitigations follow from the cost model. Aggregate in kernel-side maps rather than emitting an event per transition, so the userspace path is not in the loop, as described in In-Kernel Aggregation: Counting Stacks in a Hash Map Instead of Shipping Them. Capture stacks only on transitions that matter, either by filtering on the state value, by filtering on the thread, or by capturing a stack only when a duration threshold is exceeded, which requires deferring the capture to the wakeup side. And bound the map as discussed earlier, exporting a saturation indicator so that dropped transitions are visible.

The last technique changes what is measured and is worth stating plainly: capturing the stack at wake time and pairing it with the recorded block site produces a profile of waits that were long enough to matter, and omits the short ones. The threshold is a parameter of the measurement, and it biases the result toward exactly the tail that the analysis is usually interested in.

Combining the two profiles

Wall-clock latency per request is roughly the sum of CPU time and off-CPU time, plus the time during which the request had no thread associated with it at all, such as time sitting in a network queue or waiting for a thread pool slot. The ratio between the two measured parts is the first diagnostic: a call path that is nearly all CPU time wants optimization of its computation, and one that is nearly all off-CPU time wants a structural change to the dependency or the concurrency limit.

Producing that ratio requires the two profiles to use compatible attribution, which is harder than it sounds. CPU samples are attributed to the leaf function executing; off-CPU intervals are attributed to the call site that blocked, which is often a leaf in a different subsystem, such as a futex wait inside the kernel’s lock implementation. Comparing the two requires resolving both to a common frame, typically the application-level function that called into the blocking primitive. Without that mapping, the CPU profile shows application functions and the off-CPU profile shows kernel functions, and the two lists do not line up.

The synchronization itself is a latent source of both CPU and off-CPU cost, since a contended lock produces spin time, which is CPU, followed by block time, which is not. Spin time appears in a CPU profile as time in the lock’s acquire path, which looks like the lock implementation being expensive when it is actually the contention being expensive. Distinguishing the two requires counting acquisition attempts and their outcomes, which is an event-based measurement rather than a sampled one, and it belongs with the same class of counting instrumentation as allocation profiling.