CPU and Runtime Profiling with pprof

Latency alerts point at one endpoint. The handler looks trivial: decode JSON, call three services, encode. Adding time.Now() around each call says the work takes 12 ms — yet users see four seconds. The gap between measured-in-code and measured-in-production is where profiling starts: you are not looking for code you suspected, you are looking for code the process is actually spending time in.

Go samples CPU while it runs — the profiler interrupts the program 100 times per second and records where the program counter was. Attach to a running service through net/http/pprof:

import _ "net/http/pprof"

That blank import registers /debug/pprof/ on http.DefaultServeMux, which is fine only if you serve nothing else on it. The explicit version, which avoids the footgun of accidentally publishing handlers you did not intend to:

func profileMux() http.Handler {
	mux := http.NewServeMux()
	mux.HandleFunc("/debug/pprof/", pprof.Index)
	mux.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
	mux.HandleFunc("/debug/pprof/profile", pprof.Profile)
	mux.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
	mux.HandleFunc("/debug/pprof/trace", pprof.Trace)
	return mux
}

With the service under load, capture the profile and open it:

curl -o cpu.out 'http://localhost:6060/debug/pprof/profile?seconds=30'
go tool pprof cpu.out
(pprof) top -cum
(pprof) list decodeOrder
(pprof) web

top with -cum sorts by cumulative time — the total time inside a function including everything it calls — which is what you want when hunting a slow request path; without -cum you see flat time, the time spent in the function's own instructions. list projects samples onto source lines, so the hottest line of your own code shows its exact cost. web renders the call graph, where edge thickness is sample count: the classic find is a thick edge you never suspected — a fmt.Sprintf in a loop, a json.Marshal of a huge struct, a DNS lookup inside the critical section.

Two properties of CPU profiles determine how to read them. Sampling means rare-but-critical paths (a once-a-minute cron inside the window) may not appear at all, and profiles taken without load show nothing but idle. Capture during the symptom, for long enough to average — 30 seconds is the usual floor.

The four-second mystery in our scenario turned out to be a mutex held during a synchronous call, visible as a thick edge from the handler into sync.Mutex.Lock. The code timing said 12 ms because it measured the fast path; the profile said four seconds because it measured where the thread actually waited — which is the skill CPU and Runtime Profiling with pprof exists to build: reading what the runtime reports rather than what the author assumed.

CPU profile is the wrong instrument for half of all performance bugs. A request that is slow but not CPU-bound will barely register there; a service that leaks memory will not appear in it at all. The /debug/pprof/ index lists the profiles, each answering a different question.

The heap profile deserves the most care because it has two views that answer opposite questions. By default it shows inuse_space — what is live right now, sampled at one entry per 512 KB of allocation (runtime.MemProfileRate). Switch to allocation volume with -sample_index=alloc_space:

go tool pprof -sample_index=alloc_space http://localhost:6060/debug/pprof/heap
(pprof) top 10

A service with steady RSS but enormous allocation rate is churning: nothing leaks, but the garbage collector runs constantly and CPU goes to GC. inuse_space would show a flat, healthy graph; alloc_space exposes the churn. Reading both is the difference between diagnosing a leak and mislabeling a garbage-collector bill.

The goroutine profile is the leak detector. When a shutdown path stops draining, the count plateaus instead of falling, and the profile shows the same stack repeated:

curl 'http://localhost:6060/debug/pprof/goroutine?debug=1' | head -40

Look for your own functions in the blocked frames — chan send, select, net.(*pollDesc).waitRead — repeated dozens of times. Twenty goroutines parked in workerLoop waiting for a channel nobody closes is a diagnosis, not a hint; the underlying patterns are the ones Goroutine Leaks walks through. Full goroutine dumps (including the blocking profile) are best captured with debug=2, which prints every stack without collapsing duplicates.

A practical capture workflow: reproduce the symptom, grab curl -o out '.../profile?seconds=30' plus heap plus goroutine in one script, and analyze offline with go tool pprof out. Profiles are files — keep them with the incident ticket, because a profile without load conditions is unreproducible evidence.

The /debug/pprof/ handler serves runtime internals to anyone who can reach the port. The famous disclosure pattern is a cloud instance with :6060 open to the world: an attacker reads /debug/pprof/cmdline (the full command line, including flags that may hold credentials), maps the code layout from profiles and — on services that also expose expvar or admin endpoints — reads internal state. Containment is not optional: bind profiling to localhost, put it behind auth, or expose it only on a management listener.

Cost is the second constraint. A CPU profile costs roughly 2% of throughput while active plus the memory of storing samples; the endpoints are cheap enough to leave registered and expensive enough never to leave reachable. That combination — cheap to capture, dangerous to expose — suggests the modern default: leave profiling compiled in, gated, and enable it on demand or on a schedule.

On-demand capture is the standard incident response:

# three artifacts, one script, attached to the incident
curl -o cpu.out  "http://svc:6060/debug/pprof/profile?seconds=30"
curl -o heap.out "http://svc:6060/debug/pprof/heap"
curl -o gor.out  "http://svc:6060/debug/pprof/goroutine?debug=2"

Short-lived programs never reach an HTTP port, so they start and stop the profiler around the interesting region with runtime/pprof:

func main() {
	flag.Parse()
	f, err := os.Create("reindex.out")
	if err != nil {
		log.Fatal(err)
	}
	defer f.Close()

	if err := pprof.StartCPUProfile(f); err != nil {
		log.Fatal(err)
	}
	reindex(flag.Args())          // the work being investigated
	pprof.StopCPUProfile()        // flushes samples now; the deferred Close runs after return
}

StopCPUProfile must run before the file closes — deferring it after f.Close() produces an empty profile — and it is the only profile function safe to defer like that. Heap snapshots for a CLI use pprof.WriteHeapProfile after the work finishes.

Cadence for long-running services: some teams take a profile every few minutes into object storage and compare week over week; that is continuous profiling, usually done with a collector rather than home-grown cron, and it converts "performance regressed somewhere last Tuesday" into a diffable answer. Whether you schedule it or curl it during an incident, the discipline is the same: capture under load, save the file, and confirm the fix by capturing again — a profile is evidence, and evidence needs a before and an after. Benchmarks give you the repeatable local version of that loop (Coverage and Benchmarks); pprof gives you the production one.