Debugging Concurrency

Off-CPU Time: The Thing a CPU Profiler Cannot See

A CPU profiler samples threads that are on a processor. A thread waiting for a lock is not on a processor, so it contributes nothing to the profile — and the flame graph of a fully contended service looks empty. Concurrency profiling measures the time you were *not* running, and attributes it to a stack.

The question this answers

The question

The flame graph is nearly empty and the service is slow. What is a CPU profile structurally unable to show me?

The work

A request handler whose p99 is 900ms, of which roughly 120ms is computation and the rest is spent waiting on a lock, a connection pool and a downstream call.

What is shared

The lock around a shared cache, the connection pool, and the runtime's scheduler run queue — all three are places where a thread stops being on-CPU.

The invariant — what must stay true under every interleaving

Wall-clock time for a request equals on-CPU time plus off-CPU time plus runnable-but-not-scheduled time, with nothing unaccounted for.

Synchronization exists to preserve this sentence. If a schedule can make it false, the code is wrong no matter which primitive it uses.

WorkCan it overlap?Can it parallelise?What is shared?What ordering?What synchronization?Where is contention?What can deadlock?What can race?What is gained?What complexity?

Two clocks, and why one of them is invisible

A CPU profiler works by sampling: many times a second, it interrupts and records the stack of whatever is currently executing on each core. This is a sound way to find where compute goes, and Self Time, Total Time, and Where the CPU Went and Reading a Flame Graph cover reading it. Its blind spot is definitional. A thread parked on a mutex is not executing on any core, so no sample can ever land on it. Ninety percent of your latency can be completely absent from a correct, complete CPU profile.

The consequence is a specific and very confusing incident shape: latency p99 is terrible, the flame graph is thin and unremarkable, and the widest frame accounts for eight milliseconds of a nine-hundred-millisecond request. Engineers then conclude the profiler is broken, or that the slowness is "in the network". Neither is true — the profiler is measuring the correct thing and the correct thing is not where the time went.

Off-CPU profiling inverts the question. Instead of sampling who is running, it records the moments a thread *stops* running and the moment it resumes, and attributes the interval to the stack at the point of blocking. A lock acquisition that parks for 640ms produces a 640ms-wide frame. That is the entire idea, and it is why the two profiles must be read together: on-CPU tells you what work costs, off-CPU tells you what waiting costs.

One 900ms request. The shaded on-CPU slices are all a CPU profiler can ever sample.ILLUSTRATIVE
Request thread
blocked: cache lock acquire
blocked: pool.acquire
waiting: db query round trip
runnable, no core free
serialize response (on-CPU)
What the CPU profile records
(nothing sampled)
(nothing sampled)
serialize
What an off-CPU profile records
lock acquire — 240ms
pool.acquire — 150ms
db round trip — 300ms
run-queue delay — 90ms
(not sampled)
↑ request in↑ response out (900ms)
runningreadywaitingblockedidle1 tick ≈ 30ms

Four profile types, four different questions

It is worth being precise about what "concurrency profiling" collects, because the term covers several distinct instruments. A blocking profile records where threads parked and for how long. A lock contention profile records the same thing narrowed to synchronization primitives, and usually also records the *holder* — which is what makes it more useful than the raw blocking profile. A scheduler-latency profile records runnable-but-not-running time, which is neither work nor blocking but oversubscription. A queue-wait profile records time between enqueue and dequeue for your own work items.

Reading them together is what pins down the cause. High blocking with low lock contention means downstream I/O, and the answer lives in Timeouts and the caller. High lock contention means What Contention Actually Costs and possibly Lock Scope: What You Hold It Across. High scheduler latency with low blocking means too many runnable threads for the cores available — Oversubscription — and the fix is fewer threads, which is deeply counterintuitive during an incident. High queue wait with idle workers means the consumer is stalled, not overwhelmed.

The read-out below shows a service where all four are collected. Note that on-CPU accounts for 14% of wall time, which is why the flame graph looked empty, and note that scheduler latency is non-trivial — that number is invisible in both CPU and blocking profiles and gets missed constantly.

WALL-CLOCK ATTRIBUTION   (60s window, 24 request threads, 8 cores)

  on-CPU                    14.2 %   <-- the entire CPU flame graph lives here
  off-CPU: lock wait        31.0 %
  off-CPU: pool acquire     16.4 %
  off-CPU: network I/O      27.8 %
  runnable, not scheduled    9.9 %   <-- oversubscription, invisible to both
  other                      0.7 %

  TOP OFF-CPU STACKS BY BLOCKED TIME
    412.0 s   catalog.refreshIndex -> lock.acquire(cacheLock)
                  holder stack: catalog.refreshIndex -> http.get(inventory)
                  ^^ the holder is doing I/O inside the critical section
    218.6 s   handler.getOrder -> pool.acquire(primary)
    369.7 s   handler.getOrder -> db.execute -> socket.read
    131.4 s   <scheduler> runnable delay, 24 threads / 8 cores

  TOP ON-CPU STACKS (the whole CPU profile)
     11.9 s   json.serialize
      4.1 s   gzip.compress
      2.2 s   validate
Combined profile over a 60-second window, aggregated by wall-clock contribution. Illustrative.

What it costs to collect, and how it lies

Off-CPU profiling is more expensive than CPU profiling, and for a structural reason: CPU profiling samples at a fixed rate regardless of how much the program does, while off-CPU profiling fires on every blocking event. A program that blocks a million times a second generates a million events, and capturing a stack per event is not cheap. Real implementations mitigate with sampling, with duration thresholds (ignore blocks under 1ms), or by aggregating without stacks.

That mitigation is also how off-CPU profiles lie. A threshold that ignores sub-millisecond blocks hides exactly the "many tiny waits" pattern that lock striping is meant to fix; a 2ms lock acquired constantly may never appear. Conversely, a profile dominated by one 30-second block from a single idle worker parked on an empty queue is technically accurate and completely uninteresting — idle time is off-CPU time, and any off-CPU profile must be read with idleness filtered out or it will confidently report that your thread pool spends all day waiting for work.

Continuous collection with diffing is the mature form of this — see Always-On Profiling, and the Diff That Finds Regressions — because a contention regression is usually a *change* in the off-CPU profile across a deploy, and that comparison is far more actionable than an absolute number. The general "measure before optimizing" discipline is Measure Before You Optimize; the concurrency-specific addition is that measuring only CPU is measuring 14% of the problem.

InstrumentAnswersCannot seeCollection cost
CPU profileWhere compute goesAll waiting — lock, I/O, queue, schedulerLow, fixed sample rate
Blocking / off-CPU profileWhere threads stopped running, with a stackWhich thread caused the blockPer blocking event; needs thresholds
Lock contention profileWhich lock, how long, and who held itWaiting that is not a lockPer acquisition; the holder link costs extra
Scheduler-latency profileRunnable-but-not-running timeAnything about why the work is slow, only that cores were shortRuntime or kernel support required
Queue-wait profileTime between enqueue and dequeue of your work itemsAnything inside the work itselfOne timestamp per item
Thread dumpThe instantaneous state of everythingDuration, and anything between samplesNear zero, but a safepoint pause
Which instrument answers which question — and what each one structurally cannot see.

Key points

  • A CPU profiler samples threads that are running. A blocked thread is not running, so contention is structurally absent from a correct CPU profile.
  • The incident signature is a thin, boring flame graph next to a terrible p99 — the profiler is not broken, it is answering a different question.
  • Off-CPU profiling attributes the time a thread spent *not* running to the stack at the point where it stopped.
  • Four distinct instruments matter: blocking, lock contention (which also names the holder), scheduler latency, and queue wait.
  • Runnable-but-not-scheduled time is neither work nor blocking; it is oversubscription, and it is invisible to both other profiles.
  • Off-CPU collection fires per blocking event, so it needs thresholds — and those thresholds hide the "many tiny waits" pattern by design.

The loop, answered

Every field is required, which is why no lesson here can recommend concurrency without naming the interleaving that breaks it, the complexity it adds, and the simpler thing to consider first.

How it works
  • Instrument or hook the moments a thread leaves and re-enters the run queue: a scheduler switch-out, a futex wait, a park, an I/O submit.
  • Capture the stack at switch-out and record the interval until switch-in, attributing that wall-clock duration to the captured stack.
  • For lock contention specifically, also record the current owner so the profile links waiter stacks to a holder stack.
  • Separately measure runnable-to-running delay, which requires the scheduler's view and is not derivable from the thread's own timestamps.
  • Aggregate by stack, filter deliberate idleness, and merge with the CPU profile so wall-clock attribution sums to roughly 100%.
Interleavings that matter
  • Thread A holds the cache lock and issues a 300ms HTTP call; threads B..X park on acquire. The CPU profile records only A's brief pre-call parsing, so 240ms × 23 threads of latency appears nowhere at all.
  • 24 request threads on 8 cores, all runnable after a burst: each waits its turn, adding tens of milliseconds of pure run-queue delay per request. Neither a CPU profile nor a blocking profile sees it, because the threads are neither running nor blocked.
  • A pool worker parks on an empty queue for 58 of 60 seconds. Unfiltered, that single idle thread dominates the off-CPU profile and buries the 412 seconds of real lock waiting spread across 23 threads.
What it guarantees — and does not
  • An off-CPU profile guarantees that time was spent not running, attributed to the stack where the thread stopped. It does not guarantee the stack is the *cause* — the cause is usually the holder, which only a contention profile links.
  • It does not distinguish deliberate idleness from harmful blocking. That is a filtering decision you make, not a property of the data.
  • With a duration threshold, it guarantees nothing about waits shorter than the threshold — including the aggregate cost of millions of them.
  • Attribution sums to wall clock only if scheduler latency is collected too; without it there is a gap that gets silently absorbed into "other".
Where contention appears
  • The profiler's own aggregation structure is written from every blocking thread, and a naive shared map turns a contention profile into a contention source.
  • Stack capture at switch-out happens on the scheduling path, which is latency-sensitive; a slow capture lengthens the very blocks being measured.
  • On systems with millions of short blocks per second, unthresholded collection can cost more CPU than the application.
How it fails
  • Concluding "the code is fast, it must be the network" from an empty flame graph, when 31% of wall clock was one lock.
  • Reading an unfiltered off-CPU profile and optimizing the idle worker loop that "dominates" it.
  • Missing striping opportunities because a 1ms threshold hides a 0.4ms lock acquired forty million times.
  • Attributing to the waiter stack and never to the holder, so the fix targets the wrong function — the waiters are fine, the holder is doing I/O.
  • Ignoring scheduler latency, then "fixing" oversubscription by adding threads, which increases it.
When it helps
  • Any latency problem where CPU utilization is low — that combination is the definition of the case off-CPU profiling exists for.
  • Attributing a p99 regression across a deploy, where the diff of two off-CPU profiles points at the newly-blocking call directly.
  • Deciding whether to shrink a critical section or shard a lock: the profile shows both the holder's stack and the waiter volume, which is exactly the input to that choice.
When it hurts
  • CPU-bound services, where off-CPU time is small, the collection cost is pure overhead, and a plain CPU profile is both cheaper and sufficient.
  • Extremely high blocking-event rates, where the instrument perturbs the system enough to change the answer.
  • As a first step, when a thread dump would have named the problem in thirty seconds with nothing to install.
How you would know
  • The ratio of on-CPU to wall-clock across the profiling window — well under half means a CPU profile alone is the wrong instrument.
  • Blocked time per stack, ranked, with deliberate idleness excluded.
  • Whether the top blocking stack is a lock, a pool, or a socket — three different owners and three different fixes.
  • Runnable-not-running time as a share of wall clock, compared against thread count over core count.
  • Diff of blocked time per stack across a deploy boundary, which is where regressions actually show up.
Complexity it introduces
  • Two profile types to collect, store, merge and reason about, with different sampling semantics that do not compose naively.
  • Threshold and filter choices are now part of your observability contract, and a wrong threshold silently deletes a class of finding.
  • Holder attribution requires the lock implementation to expose ownership, which often means wrapping every lock in the codebase.
  • Storage: off-CPU profiles with per-event stacks are far larger than sampled CPU profiles at equivalent windows.
Simpler alternatives
  • Lock wait and hold metrics, which are dramatically cheaper and answer the "is this lock the bottleneck" question without stacks — Hold Time, Wait Time, and the Ratio Between Them.
  • Three thread dumps thirty seconds apart, which cost nothing and identify a stall's owner immediately — Reading a Thread Dump.
  • Distributed tracing with explicit wait spans, when the waiting crosses process boundaries rather than living inside one — Distributed Tracing.
  • Simply timing the suspect section with two clock reads. Unfashionable, precise, and frequently the fastest path to an answer.

What people believe, and what is true

Claim

The flame graph is empty, so the code is fast.

Reality

The flame graph is empty because the threads were not running. Empty plus slow is the strongest possible signal that the time is off-CPU.

Claim

Off-CPU profiling is just CPU profiling with more events.

Reality

It has different sampling semantics: CPU profiling samples at a fixed rate, off-CPU fires per event. That is why one is cheap regardless of workload and the other is not.

Claim

The top off-CPU stack is the problem.

Reality

The top off-CPU stack is usually the *victim*. The problem is whoever held the resource, and only a contention profile with holder attribution shows that.

Apply it