skip to content

A Go service's p99 doubled, yet a 30-second CPU profile shows no new hot function. Why might the cost be invisible?

level: seniorimportance: should knowfreq 52%

answer

  1. the profile only sees threads on a CPU
  2. waiting costs latency and no samples
  3. compare CPU seconds against wall-clock times cores
  4. throttled and runnable looks identical in the profile
  5. the answer is not here is still an answer

basics

~20 s

A CPU profile samples only threads that are executing, so time a goroutine spends parked on a channel, a mutex, a syscall or a network read produces no samples at all. Latency spent waiting, or lost to CPU throttling, is invisible to that instrument by construction.

solid answer

~50 s

Because a CPU profile answers a different question from the one latency asks. Sampling is driven by CPU-time timers, so a goroutine that is not on a CPU is never interrupted and never sampled: waiting on a channel, contending for a mutex, blocking in a read, or sitting runnable while the cgroup throttles the process all cost wall-clock time and produce zero samples. The check I run first is arithmetic: total CPU in the profile against wall-clock time times cores. If a scoring request takes 40 ms end to end and the profile attributes 2 ms of CPU to its call path, then 38 ms is off-CPU and no amount of optimising the sampled functions will help. That result redirects the investigation — to the profiles and traces that record blocking and scheduling rather than CPU — instead of sending me to micro-optimise whichever function happened to be top of the CPU profile.

code

go · 9 lines
go
func (s *Scorer) Score(ctx context.Context, query string) (float64, error) {
	terms := normalize(query) // real CPU work: shows up in the profile

	w, err := s.weights.Get(ctx, terms) // parks on a channel: no samples
	if err != nil {
		return 0, err
	}
	return dot(terms, w), nil
}

go deeper

for a junior

Remember the one-line rule: a CPU profile records time spent computing, not time spent waiting, so a slow program can have a completely boring CPU profile.

for a middle

Explain why waiting is unrepresentable — sampling is driven by CPU-time timers, so a parked goroutine is never interrupted — and list the kinds of waiting involved.

for a senior

Show the diagnostic move: compute CPU time against wall-clock time per request, state what fraction is off-CPU, and change instruments rather than micro-optimising the top entry.

for a principal

Own the framing for the team: agree which question each instrument answers before an incident, so that a latency regression is not investigated with a throughput tool.

## The instrument decides what you can see Go's CPU profiler works by arming CPU-time timers and recording the stack of whatever goroutine is running when they fire. The consequence is absolute and worth stating plainly: **a goroutine that is not executing on a thread cannot be sampled.** A CPU profile is a map of where CPU is burned. It is not a map of where time goes. For a search-ranking scorer invoked once per query, that distinction is the whole investigation. Suppose the scorer normalises the query text, looks up term weights, and returns a score. If the weight lookup waits on a channel served by a background loader, that wait might be thirty milliseconds of user-visible latency and produce not one sample. The CPU profile will happily show you that UTF-8 normalisation is the hottest function in the process — true, and irrelevant to the regression. ## The categories of invisible time - **Channel operations.** A goroutine parked in a send or receive is descheduled entirely. - **Mutex contention.** A goroutine waiting to acquire a lock is not running. Only the successful acquire path costs CPU. - **Syscalls and I/O.** A blocking read from a socket or a file hands off the P and parks; no CPU is consumed while the kernel waits. - **Sleep and timers.** Time in a sleep is off-CPU by definition. - **Scheduling delay.** A goroutine that is runnable but waiting for a P, or a thread that is runnable but throttled by the container's CPU quota, is not executing. The last one is the nastiest in production. If a service's CPU quota is exhausted, the process spends periods runnable-but-not-scheduled. The CPU profile looks exactly as it did last week — same functions, same proportions — while latency has doubled, because the profile is expressed in CPU time, and CPU time did not change. What changed is the ratio of CPU time to wall-clock time. ## The arithmetic that settles it Before theorising, quantify. A CPU profile records a total: the sum of all samples, in CPU-seconds. Compare it to the wall-clock length of the profiling window times the number of cores available. - Thirty seconds of window on a four-core quota gives a ceiling of 120 CPU-seconds. - If the profile totals 6 CPU-seconds, the process was about 5% busy. Nothing about latency is going to be explained by making that 6 seconds smaller. - Per request: if a scoring call takes 40 ms of wall-clock and the profile attributes about 2 ms of CPU across its call path, roughly 95% of that request's latency is off-CPU. That single ratio decides whether you are looking at a CPU problem at all. It is the first thing to compute and the thing weak candidates skip — they open the profile, take the top entry, and start optimising a function that accounts for 5% of the latency. ## What the CPU profile *can* still tell you Even when the answer is off-CPU, the CPU profile is not useless: - A profile whose total CPU has not moved while latency doubled is strong evidence that the code path did not get more expensive, which rules out a whole class of causes. - If garbage collection work grew, that *is* CPU and does show up, so the profile distinguishes a GC-driven regression from a waiting one. - Comparing the CPU total per request before and after a release tells you whether the release added computation, independent of what happened to latency. ## Redirecting the investigation Once the ratio says off-CPU, you change instruments rather than settings. Go ships profiles that record blocking and lock contention, an execution trace that shows scheduling and goroutine state over time, and a goroutine profile that shows where goroutines are parked right now. Each of those answers the question the CPU profile structurally cannot, and choosing between them is the next step — but the decisive move is recognising that the CPU profile has already given you its answer, and that its answer was `not here`. ## The other direction of the same mistake The mirror-image error is treating a low CPU total as proof that nothing is CPU-bound. Aggregate CPU can be low while one specific request path is CPU-heavy, because the profile mixes an idle process with a busy path. That is why the per-request comparison matters more than the process-wide one, and why profiling under load — or under a benchmark that saturates the path — beats profiling a mostly idle service. ## What good sounds like in an interview Name the mechanism (CPU-time sampling, so off-CPU is unrepresentable), compute the ratio out loud, list the categories of waiting that could account for the gap, mention throttling as the one that leaves the profile looking identical, and only then say which instrument you would reach for next. Jumping straight to `I would add a block profile` skips the reasoning the question is testing.

  • How do you quantify, from the profile itself, how much of a request's latency was off-CPU?
    Compare CPU time to wall-clock time. Sum the samples attributed to the request path and divide by the number of requests served in the window to get CPU per request, then compare that against measured latency per request. Forty milliseconds of latency against two milliseconds of CPU means about 95% of the time was spent waiting.
  • The container's CPU quota is being throttled. What does that do to the CPU profile?
    Very little, which is what makes it dangerous. Threads that are runnable but not scheduled burn no CPU time, so no samples are taken during the throttled periods. The profile keeps the same shape and roughly the same totals while latency climbs; the tell is the collapsed ratio of CPU time to wall-clock time, not anything inside the profile.
  • Does a CPU profile show time spent in garbage collection?
    Yes. Collection work and the assists that allocating goroutines perform are ordinary CPU execution, so they appear as runtime frames in the profile. That is useful: if latency rose and GC-related CPU rose with it, the regression is on-CPU and the profile is the right instrument after all.
  • Why is a low total CPU in the profile not proof that no code path is CPU-bound?
    Because the process-wide total averages a busy path with an idle process. One request path can be heavily CPU-bound while overall utilisation is a few percent. Attribute CPU per request or per code path, or drive the path under a load that saturates it, before concluding that computation is not the problem.

saying these in an interview costs you the question

  • Optimises the top CPU profile entry without checking its share of latency
  • Believes blocked goroutines appear as samples in a CPU profile
  • Never compares CPU seconds against wall-clock time
  • Concludes the code is fine because CPU usage is low
  • Thinks raising the sampling rate will reveal waiting time