Reading Profiles with pprof

## What a profile is, before you read one A profile is a bag of *samples*. Each sample is a stack trace plus a value — for a CPU profile, an amount of CPU time attributed to that stack. `go tool pprof <profile>` loads that bag and opens an interactive prompt where you slice it. Go's own profiles carry function names inside the file, so `go tool pprof cpu.pprof` works on its own; passing the matching binary as well (`go tool pprof ./gen cpu.pprof`) is what lets you disassemble. ## `top` `top` is the first command everyone runs. It prints one row per function, sorted by flat weight, with five columns: - **flat** — the summed value of the samples in which this function was the *currently executing* frame, the leaf of the stack. This is self time. - **flat%** — that flat value as a share of the profile total. - **sum%** — the running sum of flat% from the top row down to this one. When sum% hits 90% you have seen the functions that account for nine tenths of the CPU. - **cum** — the summed value of every sample in which this function appears *anywhere* on the stack, leaf or not. This is self time plus the time of everything it called. - **cum%** — that cumulative value as a share of the total. `top` shows ten rows by default; `top20` or `top -nodecount=20` shows more, and `top -cum` re-sorts the same data by cumulative weight. ## The distinction that decides what you optimise Flat answers *where is the machine spending instructions*. Cum answers *which call path leads there*. They are different questions and the columns are not competing versions of the same number. A long stack of thin wrappers each carries the same enormous cum: `main`, then your top-level driver, then the loop, all the way down to the one function doing string comparison. Only the last of those has meaningful flat. If you sort by cum, the top of the list is your own high-level entry points; if you rewrite them you will change nothing, because none of the time is *in* them. This is the classic misread and it is expensive. Picture joining a team and being handed a CPU profile someone captured last week from the code generator that runs over the repo's schema files as a build step. `top -cum` puts `walkSchema` at 95% and it looks like the villain. Its flat is 0.20s out of 2s. The 1.9s belongs to what it calls — and the leaf underneath it is a byte comparison in a loop. Days spent restructuring `walkSchema` buy nothing; a few lines at the leaf buy most of the profile. The inverse mistake is real too: a function with big flat and no interesting cum is genuinely hot, but if it is called from twenty places, the fix may be to call it less rather than to make it faster — and only cum, per caller, tells you that. ## Reading a row correctly - flat ≈ cum: a leaf. All its time is its own; optimise its body. - flat ≈ 0, cum large: a pass-through. Do not optimise it; follow it downward. - flat large, cum much larger: it does real work *and* calls something expensive. Both are candidates. ## Practical notes Units follow the profile type: a CPU profile is in seconds, so the header reads `Showing nodes accounting for 1.72s, 86.00% of 2s total`. `Dropped N nodes (cum <= …)` means pprof hid nodes below its cutoff — they are still counted in the total, just not printed. Percentages are always of the whole profile, not of the row above, so cum% down a single call chain does not add up to anything; the same seconds are counted once at every level of the stack. A function that never appears as a leaf can still be the problem, and a function with 40% flat can be irreducible (a `memmove` in the runtime often is). `top` narrows the field; it does not name the fix. The next steps are looking at the annotated source of the hot function and at who calls it, which is what pprof's `list` and `peek` commands are for.