skip to content

How do you capture a CPU profile from a running Go program with runtime/pprof?

level: juniorimportance: must knowfreq 60%

answer

  1. two calls bracket the work
  2. the first one takes a writer
  3. deferred calls run last-in-first-out
  4. the second call is what flushes
  5. os.Exit skips defers, so the file is empty

basics

~10 s

Open a file, call runtime/pprof.StartCPUProfile(f), run the workload, then call StopCPUProfile before exiting. Stop flushes the buffered samples; without it the file is unusable. Inside tests, go test -cpuprofile does the same thing.

solid answer

~50 s

You bracket the work with two calls. `pprof.StartCPUProfile(w io.Writer)` starts sampling and returns an error if a CPU profile is already running — only one can be active per process. `pprof.StopCPUProfile()` takes no arguments and returns only after every sample has been written, so it is the call that actually makes the file readable. The usual shape is `f, _ := os.Create("cpu.out")`, then `pprof.StartCPUProfile(f)`, then `defer pprof.StopCPUProfile()`. Two things bite people: exiting through `os.Exit` or `log.Fatal` skips deferred calls, so you get a truncated or empty profile; and the profile covers wall-clock time between the two calls, so if you start it at process start you are profiling initialisation too. For a hot path like a search-ranking scorer, start the profile immediately before the batch of queries you care about and stop it right after.

code

go · 12 lines
go
f, err := os.Create("cpu.out")
if err != nil {
	log.Fatal(err)
}
defer f.Close()

if err := pprof.StartCPUProfile(f); err != nil {
	log.Fatal(err)
}
defer pprof.StopCPUProfile()

scoreQueries(queries) // only this is profiled

go deeper

for a junior

Be ready to write the four lines from memory: create a file, StartCPUProfile with it, defer StopCPUProfile, run the work. Say out loud that Stop is what makes the file readable.

for a middle

Explain why the pair is required, why defer order matters when the file is also deferred closed, and why only one CPU profile can be active in a process at a time.

for a senior

Show judgment about the window: profile the scoring loop, not process start-up, and choose a duration that yields enough samples for the traffic you actually have.

for a principal

Be able to say why this instrument is cheap enough to leave available in production — fixed cost per second rather than cost per call — and what a team should standardise on for capturing profiles.

## What a CPU profile is A Go CPU profile is a statistical record of where the program's threads were executing while the profiler was on. Roughly 100 times a second, per thread that is burning CPU, the runtime interrupts execution, walks the stack of the goroutine running on that thread, and records it. At the end you have a set of stacks with counts; multiplied by the sample period each count becomes an amount of CPU time. It is a sample, not a log: nothing counts calls, and nothing is instrumented into your functions. ## The two calls The whole API for an in-process capture is two functions in `runtime/pprof`: - `func StartCPUProfile(w io.Writer) error` — turns sampling on and streams the encoded profile to `w`. It returns a non-nil error if a CPU profile is already in progress; a process can only have one at a time. - `func StopCPUProfile()` — turns sampling off. It takes nothing and returns nothing, but it does not return until all pending writes to `w` have completed. That second point is the one juniors trip over. Samples are buffered and drained by a background goroutine; the file on disk is not a valid profile until `StopCPUProfile` has run. If the program exits without it — `os.Exit`, `log.Fatal`, a panic that is not recovered, a `kill -9` — you are left with a truncated file that `go tool pprof` refuses or reads as almost empty. ## The idiomatic shape ```go f, err := os.Create("cpu.out") if err != nil { log.Fatal(err) } defer f.Close() if err := pprof.StartCPUProfile(f); err != nil { log.Fatal(err) } defer pprof.StopCPUProfile() ``` Note the defer order. Deferred calls run last-in-first-out, so `StopCPUProfile` runs before `f.Close()` — which is what you want, because Stop still needs to write into the file. Reversing the two lines gives you writes to a closed file. ## Scoping the window The profile covers exactly the interval between the two calls, and it covers the whole process — every goroutine on every thread, not just the one that called Start. If your goal is to cut the cost of a search-ranking scorer that runs once per query inside a larger service, wrapping `main` gives you a profile dominated by configuration loading, index warm-up and connection setup. Start the profile immediately before the scoring loop instead, or drive the scorer from a benchmark and use `go test -cpuprofile`, which brackets the run for you. A second consequence of the interval being wall-clock: you need enough of it. At roughly 100 samples per second per busy core, a two-second profile of a mostly idle process yields a handful of samples and tells you nothing. Ten to thirty seconds of genuinely busy work — or a benchmark run with a longer `-benchtime` — is the normal target. ## Cost and safety Sampling is cheap and bounded: it is a fixed number of stack walks per second, independent of how many function calls the program makes. That is why the overhead stays in the low single-digit percent and does not scale with call volume, and why taking a CPU profile of a live service is a routine operation rather than an emergency measure. Long-running services usually expose the capture through an HTTP endpoint rather than calling Start and Stop by hand, but the underlying mechanism is exactly these two functions. ## Common mistakes - Calling Start and never calling Stop, then wondering why the file is empty. - Calling `os.Exit` inside the profiled region, which skips every deferred call. - Calling Start twice — the second call errors and, if you ignore the error, you believe you are profiling when you are not. - Profiling for two seconds and treating a function with three samples as a hotspot. - Expecting the profile to explain latency. It records CPU time. A goroutine parked on a channel, a lock or a network read burns no CPU and therefore leaves no samples. ## Where the data goes The output is a gzipped protocol-buffer profile. You do not read it by hand; you feed the file to `go tool pprof` together with the binary that produced it so symbols resolve. Keeping the binary that produced the profile matters — a profile from one build inspected against a different build produces nonsense addresses.

  • What happens if you call runtime/pprof.StartCPUProfile while a CPU profile is already running?
    It returns a non-nil error and does nothing else — the first profile keeps running and the new writer receives nothing. A process supports one CPU profile at a time. Code that ignores the error believes it is profiling when it is not, which is why the error return should always be checked.
  • Why does a profile come out empty when the program ends with log.Fatal?
    log.Fatal calls os.Exit, and os.Exit does not run deferred functions. StopCPUProfile never executes, so the buffered samples are never flushed and the file on disk is truncated. If a code path can exit that way, call StopCPUProfile explicitly before exiting rather than relying on defer.
  • How long should you leave a CPU profile running?
    Long enough to accumulate thousands of samples. At roughly 100 samples per second per busy core, ten seconds of one saturated core is about a thousand samples — enough for a function with a few percent share to be visible. For a low-traffic service, profile longer or drive the code from a benchmark instead.

saying these in an interview costs you the question

  • Thinks StartCPUProfile alone writes a complete file
  • Says the profiler records every function call
  • Calls os.Exit inside the profiled region
  • Expects two concurrent CPU profiles to both work
  • Profiles the whole of main and blames initialisation code