Self Time, Total Time, and Where the CPU Went
A CPU profile ranks functions two ways, and confusing them wastes afternoons. Total time says "this subtree is expensive"; self time says "this function is expensive". Only one of them tells you where to put the fix.
Frame the diagnosis
Performance work starts from a symptom and a signal — never from a resource dashboard.
The two rankings
Total time (also called cumulative or inclusive) counts every sample where a function appears anywhere on the stack — including all the time its callees spent. Self time (exclusive) counts only samples where the function was executing at the moment of the sample. main always has ~100% total time and ~0% self time; that is not a bug in the profiler, it is the definition.
You need both, in a specific order. Self time answers "where is the CPU going right now" and is where optimization has direct leverage. Total time answers "which subtree is responsible" and is how you find the *caller* that is invoking expensive work too often — which is frequently the real fix, since making a function 2× faster is harder than calling it 100× less.
The worked profile below is the canonical shape. calculateScore at 55% self time is the answer; everything above it in a total-time ranking would have been framework scaffolding. Note that logging at 5% is not nothing — at high traffic, logging on the hot path routinely reaches double digits, which is the The Log Bill and What It Is Buying problem seen from inside the process.
SELF TOTAL FUNCTION
55.2% 58.1% scoring.calculateScore
-> sortByRelevance 38.4% self
-> normalizeWeights 14.1% self
15.1% 19.7% json.serialize
10.4% 12.0% auth.verifyToken
5.3% 5.3% log.write <- logging on the hot path
5.0% 7.2% http.parseRequest
9.0% - (runtime, GC, syscalls)
TOTAL-TIME RANKING (what you get if you sort the other way):
100.0% main <- true, useless
99.4% server.listen
98.1% router.handle
71.0% handlers.search <- the caller worth looking at
58.1% scoring.calculateScoreCost per call versus number of calls
A profile shows aggregate cost, which means a function at 55% could be one expensive call or a million cheap ones. The two have completely different fixes: an expensive call wants a better algorithm, a million cheap calls want the caller to stop making them. Guessing wrong means rewriting a function that was already fine.
The disambiguation needs call counts, which a sampling CPU profile does not give you. Sources: a counter metric on the function, a span with the call count as an attribute, an APM tool that tracks invocation counts, or simply reading the caller. The N+1 pattern is the same phenomenon one layer out — 100 fast queries look identical to one slow query in aggregate metrics (The Comb: N+1 as a Visible Shape).
The related trap is a hot function that is *supposed* to be hot. A JSON serializer at 15% in a service whose job is serving JSON is not a finding. The question is never "what is the top function" but "what changed", or "what is disproportionate to the work being done" — which is why the diff-against-baseline discipline from When the Trace Runs Out of Answers matters more than the ranking itself.
| Shape | How to confirm | Fix |
|---|---|---|
| One call, expensive algorithm | Call count ≈ requests; cost/call high | Better algorithm or data structure (Algorithmic Cost in a Request Handler) |
| Many calls, cheap each | Call count ≫ requests | Fix the caller: batch, memoize, hoist out of the loop |
| Called once per item, list grew | Cost tracks input size | Same as N+1: restructure to operate on the batch |
| Appropriate work for the job | Ratio stable vs baseline and vs traffic | Nothing — spend the effort elsewhere |
What the profile does not show
Three systematic blind spots, each of which has sent an investigation the wrong way. Time not on CPU is invisible: a thread blocked on a lock, a socket or a disk read produces no CPU samples, so a service that is 95% idle-waiting shows a nearly empty profile while being catastrophically slow (Computing or Waiting?).
Runtime work is often attributed oddly. GC may appear as its own frames, be folded into the allocating function, or be invisible depending on the runtime and profiler — so a service with a GC problem can look like a service with a slow serializer (Garbage Collection: Pause, Throughput, Footprint — Pick Two). JIT compilation and deoptimization similarly appear as mysterious frames or as inflated cost in newly-warm code (JIT and Warm-Up: The First Thousand Requests Are a Different Program).
Inlined and native frames can vanish or merge. An aggressively inlined hot function may be attributed to its caller, and native library frames may show as one opaque symbol or as raw addresses if symbols are missing. This is why a profile with unfamiliar frame names deserves a check of symbolization before a theory is built on it.
| Signal | Value | What it tells you | Verdict |
|---|---|---|---|
| process CPU utilization | 94% of 1 core | Genuinely compute-bound — CPU profile is the right tool | smoking gun |
| run queue length | 3.8 | Threads waiting for CPU; the process wants more cores | suspect |
| voluntary context switches | low | Not blocking on I/O or locks — consistent with CPU-bound | normal |
| GC CPU share | 4% | Not a GC problem; allocation profiling can wait | normal |
| profile sample count | 3,102 | Enough samples for percentage differences to mean something | normal |
Key points
- Total time includes callees, self time does not:
mainis always ~100% total and ~0% self, so a total-time ranking buries the finding under scaffolding. - Rank by self time to find where the CPU goes; use total time to find the caller whose call count is the real bug.
- A profile shows aggregate cost, so 55% may be one expensive call or a million cheap ones — you need call counts to tell them apart, and the fixes are opposite.
- A hot function is not automatically a bug; the question is what changed relative to baseline and what is disproportionate to the work being done.
- CPU profiles are blind to blocked time, attribute runtime work inconsistently, and can lose inlined or unsymbolized frames.
Follow the diagnosis
The causal chain, hop by hop — and the readings that invite the wrong conclusion.
- 1Traffic → process: request rate rises, and CPU utilization reaches 94% of the available core.
- 2Process → latency: with the CPU saturated, requests queue for the scheduler and latency climbs superlinearly (Queueing: Why Systems Get Slow Before They Get Broken).
- 3CPU profile → engineer:
calculateScoreholds 55% of self samples, of whichsortByRelevanceis 38%. - 4Call count → engineer: invoked once per result item, and the result set grew from 50 to 500 after a product change.
- 5Code → engineer: a per-item sort that should have been done once, quadratic in result size.
- • "
mainis 100%, the profiler is broken." That is total time behaving exactly as defined. Switch to self time. - • "The serializer is 15%, let's optimize serialization." In a JSON API that may be entirely appropriate. Compare against baseline before acting.
- • "The profile is nearly empty, so there is no CPU problem." Correct — and there may be a large *waiting* problem a CPU profile cannot see.
- • "GC does not appear in the profile, so GC is not an issue." Depending on runtime and profiler, GC cost can be folded into allocating frames rather than shown separately.
Measure, fix, validate
An optimization is not finished until the metric that motivated it has moved.
- • Sort by self time first; treat total time as a second view for finding the responsible caller.
- • Get call counts from a counter, span attribute or APM before deciding between "expensive call" and "too many calls".
- • Confirm the process is CPU-bound (utilization near saturation, low voluntary context switches) before trusting a CPU profile at all.
- • Check sample count and symbolization quality; unfamiliar or address-like frames mean the profile needs fixing before interpreting.
- • Fix the call count first when the function is cheap per call — hoisting work out of a loop is usually smaller and safer than rewriting the function.
- • Replace the algorithm when cost per call is genuinely high and grows with input ([[algorithmic-cost]]).
- • Move logging, serialization and validation off the hot path, or sample them, when they show disproportionate self time.
- • Add cores or instances only after establishing that the work itself is irreducible — scaling a quadratic function buys a doubling and then loses it again ([[capacity-vs-efficiency]]).
- • Re-profile the same instance and window shape: the target function's self-time share should fall toward its baseline.
- • CPU seconds per request should drop — the efficiency measure, which is unaffected by traffic changes that raw CPU is sensitive to.
- • Endpoint p99 must improve; if CPU fell and latency did not, the process was not the constraint ([[bottleneck-migration]]).
- • Confirm throughput at the same instance count rose, which is the direct consequence of doing less work per request.
- • Optimizing a hot function often costs readability, and the next engineer may undo it without knowing why it was written that way.
- • Moving work off the hot path frequently means doing it asynchronously, which adds a queue and its own failure modes.
- • Sampling logs reduces CPU and reduces the evidence available during the next incident.
- • Adding cores is fast and buys time, but hides an efficiency problem that will return at the next traffic step.
- • Track CPU seconds per request as a first-class efficiency metric and alert on step changes after deploys.
- • Benchmark the specific hot path in CI when its cost is algorithmically sensitive to input size (Regression or Tuesday? Telling a Real Change from Noise).
- • Retain profiles across deploys so a regression can be diffed rather than re-investigated (Always-On Profiling, and the Diff That Finds Regressions).
- • Cap or sample hot-path logging so it cannot silently grow back into double-digit CPU share.
Accuracy
Performance numbers are conditional. These are the conditions.
- ILLUSTRATIVEThe profile listing is constructed. Real profiles have long tails of small frames and messier symbol names.
- RUNTIME-SPECIFICHow GC, JIT and inlined frames are attributed varies substantially by runtime and profiler; the same code can produce quite different-looking profiles on different stacks.