Off-CPU time

A request's latency includes everything that happens to it, not just the time it runs on the CPU. When a thread waits for a database, a network reply or a lock, it is off-CPU. A CPU profiler cannot see that waiting, so a service can look healthy on a CPU graph while its users wait seconds.

The big idea

Split a request's wall-clock time into two parts.

wall-clock time = on-CPU time + off-CPU time
off-CPU time    = waiting on I/O + network + locks + connection pools
                  + run queue + sleep

A CPU profile measures only the first term. If most of the time is in the second, the CPU profile will be mostly empty of useful information.

Walking through the numbers

Take a web service whose hosts run at 10% CPU, while its p99 is 2 seconds. The cores are mostly idle, so a request that takes 2 seconds is not busy computing for 2 seconds. Most of its time goes to something else.

p99 request       = 2,000 ms
hosts' CPU use    =    10%   (cores mostly idle)
so most of the    ≈ 2,000 ms is off-CPU: waiting

Adding CPU or servers will not fix a wait. The first step is to find out what the request is waiting for.

Tools that measure waiting

• Distributed tracing (OpenTelemetry, Jaeger, Honeycomb, Datadog APM). Each database query, cache call and downstream request becomes a span with a start and end time. A trace shows exactly where the wall time went. For a request-latency problem, this is usually the fastest first step. See observability.
• Wall-clock profiling. async-profiler's wall mode, py-spy record --idle, and Go's block and mutex profiles all sample waiting threads.
• Off-CPU flame graphs. On Linux, eBPF tools such as offcputime from BCC show the stacks where threads blocked and for how long.
• Saturation metrics. Connection pool wait time, thread pool queue length and run queue length show when a resource is full. Brendan Gregg's USE method checks utilization, saturation and errors for each resource. See Linux performance.

A typical trace

A distributed trace for one slow request might look like this.

GET /api/orders                              448 ms
├─ SELECT * FROM orders ... LIMIT 100         12 ms
├─ SELECT * FROM line_items WHERE order_id=?   4 ms  ┐
├─ SELECT * FROM line_items WHERE order_id=?   4 ms  │ × 100 rows
├─ ...                                               ┘ ≈ 400 ms
└─ serialize response                         30 ms

Each query is fast on its own, so no slow-query log flags it. The total is slow because the code makes one query per row. A CPU profile would show almost nothing here, because the process is waiting on the database for most of the time.

Typical off-CPU causes

• A connection pool too small for the traffic. Requests queue for a free connection. Little's law shows how big the pool should be. See Amdahl's and Little's laws.
• Lock contention on a shared map or cache.
• Calls made one after another that could run in parallel.
• DNS lookups without caching.
• Retries with long timeouts, which hold a request open for the full timeout on each attempt.

Common mistakes

• Reading a healthy CPU graph as proof that the service is fast. Check where the wall time goes.
• Adding servers to fix a wait. More servers do not shorten a database call.
• Ignoring pool wait time. A pool that is always full is a queue, and queues add latency to every request.

Check yourself

1. A service runs at 10% CPU, and its p99 is 2 seconds. Is it probably CPU-bound? No. Most of the request time is spent waiting, which is off-CPU time.
2. Which tool shows one request's calls to the database and their timing? Distributed tracing, which records a span for each call.

Key takeaways

• Wall-clock time is on-CPU time plus off-CPU time. CPU profiles only see the first part.
• Low CPU with high latency usually means the requests are waiting.
• Use tracing first for request latency, then wall-clock and off-CPU profiles to dig into the waits.
• Connection pool wait time and run queue length are the saturation signals to watch.

Further learning

Next, read benchmarking without lying to measure a fix honestly before you ship it.