pprof: Find the Hot Spot, Don't Guess It

Profiling Go with the built-in pprof — a real CPU profile captured with runtime/pprof and read with go tool pprof top and list, plus heap, goroutine, and block profiles and the net/http/pprof endpoint. Real profiler output baked in, compiled and run against Go 1.26.5.

Every engineer has a theory about why their program is slow, and the theory is usually wrong. The function you’re sure is the bottleneck is fine; the innocuous-looking loop three files away is eating 90% of the CPU. Guessing is how you spend an afternoon optimizing code that was never the problem. Profiling is how you find the actual hot spot in about ninety seconds, and Go ships the profiler in the box. This chapter captures a real CPU profile, reads it, and then covers the other profile types — heap, goroutine, block — and the HTTP endpoint that exposes them all live. Every profile and every number below was captured against Go 1.26.5 on this machine; your numbers will differ, but the shape of the output is what matters.

The one rule: measure first

The discipline is simple and almost nobody follows it: profile before you optimize. Not after you’ve formed a hypothesis, not to confirm what you already believe. First. The whole value of a profiler is that it tells you where the time actually goes, which is routinely somewhere you would not have looked. Optimizing without a profile is not engineering; it is superstition with extra steps.

Capturing a CPU profile

A CPU profile answers “where did the wall-clock time go?” by interrupting the program about a hundred times a second and recording the call stack each time. Functions that show up in a lot of samples are where the CPU is. The runtime/pprof package writes one to a file directly:

f, err := os.Create("cpu.prof")
if err != nil {
	panic(err)
}
defer f.Close()

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

// ... the code you want to profile runs here ...

To have something worth profiling, here is a deliberately naive prime counter — trial division all the way up to n, which is exactly the kind of “looks harmless” code that hides a hot loop:

func isPrime(n int) bool {
	if n < 2 {
		return false
	}
	for i := 2; i < n; i++ {
		if n%i == 0 {
			return false
		}
	}
	return true
}

Run twenty passes of countPrimes(30000) under the profile, and you get a cpu.prof file. (In a real program you’d wrap main this way, or better, expose the HTTP endpoint below and grab a profile from a running server without restarting it.)

Reading it with go tool pprof

The profile is a binary file; go tool pprof reads it. The single most useful view is -top, which ranks functions by how much of the CPU they accounted for:

$ go tool pprof -top cpu.prof
Duration: 6.93s, Total samples = 6170ms (88.99%)
Showing nodes accounting for 6160ms, 99.84% of 6170ms total
      flat  flat%   sum%        cum   cum%
    5770ms 93.52% 93.52%     5940ms 96.27%  main.isPrime (inline)
     220ms  3.57% 97.08%     6160ms 99.84%  main.countPrimes (inline)
     170ms  2.76% 99.84%      170ms  2.76%  runtime.asyncPreempt
         0     0% 99.84%     6160ms 99.84%  main.main
         0     0% 99.84%     6160ms 99.84%  runtime.main

There is the answer, no guessing required. main.isPrime is 93.52% of the CPU. The two columns that matter are flat and cum. Flat is time spent in that function’s own body; cum (cumulative) is time in that function plus everything it called. isPrime has a huge flat because it does the work itself; main has zero flat and near-total cum because all it does is call down into the work. When you’re hunting for the hot spot you sort by flat — that is where the CPU is actually being burned.

To find the hot line, not just the hot function, use -list with a function name. It annotates the source with per-line samples:

$ go tool pprof -list=isPrime cpu.prof
     flat      cum
        .        .     14:	}
    210ms    240ms     15:	for i := 2; i < n; i++ {
    5.56s    5.70s     16:		if n%i == 0 {
        .        .     17:			return false

Line 16 — the modulo — is 5.56 seconds of the 6.17-second total, all by itself. That is the sharpest a profiler gets: it points at a single line. (The fix, incidentally, is to loop i only up to √n, but the point of the chapter is that the profiler told us the line rather than us reasoning our way there.)

The third command is -web, which renders a call graph as SVG. It needs Graphviz installed, and on this machine it isn’t:

failed to execute dot. Is Graphviz installed?

So -web is flagged as unrun here — brew install graphviz (or your platform’s equivalent) enables it. The -top and -list views need nothing extra and answer most questions anyway.

The heap profile: who’s allocating

A heap profile answers “where is the memory going?” It has two lenses, selected by flag. -inuse_space shows what is live right now (chase this for a leak or steady-state bloat); -alloc_space shows the total ever allocated, live or freed (chase this when the allocator itself is the cost, thrashing the GC). Write one with pprof.WriteHeapProfile(f) after a runtime.GC():

func buildRows(n int) [][]byte {
	rows := make([][]byte, n)
	for i := range rows {
		rows[i] = make([]byte, 1024) // 1 KiB each
	}
	return rows
}

Allocate 50,000 of these and profile with -alloc_space:

$ go tool pprof -top -alloc_space heap.prof
      flat  flat%   sum%        cum   cum%
   47.82MB 97.95% 97.95%    47.82MB 97.95%  main.buildRows (inline)
       1MB  2.05%   100%        1MB  2.05%  runtime.mallocgc
         0     0%   100%    47.82MB 97.95%  main.main

main.buildRows allocated 47.82 MB — 97.95% of everything. Same top/list/web commands as the CPU profile; only the meaning of the numbers changes from time to bytes.

Goroutine and block profiles

Two more profile types earn their keep in production.

The goroutine profile is a snapshot of every goroutine and where it’s parked. It is the single best tool for a goroutine leak: if the count climbs forever, this profile shows you exactly which line they’re all stuck on. A hundred goroutines all blocked on a channel receive:

$ go tool pprof -top goroutine.prof
Showing nodes accounting for 101, 100% of 101 total
      flat  flat%   sum%        cum   cum%
       100 99.01% 99.01%        100 99.01%  runtime.gopark
         0     0%   100%        100 99.01%  main.main.func1
         0     0%   100%        100 99.01%  runtime.chanrecv

The unit is goroutines, not time or bytes — 100 of them, all in main.func1, all parked in chanrecv. If that number only grows, there’s your leak and its exact location.

The block profile shows where goroutines wait on synchronization — mutexes, channels, WaitGroups. It is off by default because it has overhead; you enable it with runtime.SetBlockProfileRate(1). Fifty goroutines contending for one mutex:

$ go tool pprof -top block.prof
Type: delay
      flat  flat%   sum%        cum   cum%
     5.03s   100%   100%      5.03s   100%  sync.(*Mutex).Lock (inline)

The unit is delay — 5.03 seconds of aggregate time spent waiting on that lock. A high number here means contention, which a CPU profile won’t show you (waiting on a lock burns no CPU). There’s a sibling mutex profile focused specifically on lock contention, enabled the same way with runtime.SetMutexProfileFraction.

The live endpoint: net/http/pprof

For a running server you don’t want to redeploy to grab a profile. A single blank import wires all of the above onto your HTTP mux:

import _ "net/http/pprof" // registers /debug/pprof/ on http.DefaultServeMux

The _ means “import for its side effects only” — the package’s init registers the handlers, and you never call it directly. Now /debug/pprof/ lists every profile, confirmed live:

allocs        present=true
block         present=true
goroutine     present=true
heap          present=true
mutex         present=true
profile       present=true
threadcreate  present=true

You can point go tool pprof straight at a URL — go tool pprof http://localhost:6060/debug/pprof/profile?seconds=30 captures a 30-second CPU profile from the live process and drops you into the interactive prompt. One caveat that is really a security note: /debug/pprof/ exposes internals and must never be on a public port. Register it on a separate internal listener, or gate it behind auth. Wiring it onto the same mux that serves the internet is a genuine mistake.

A few things that trip people up

CPU profiling is cheap enough to leave on — the sampling interrupt costs a percent or two — but the block and mutex profiles are not, which is why they ship disabled and you turn them on with an explicit rate. Don’t leave those cranked to 1 in production; sample a fraction instead. A second gotcha is profiling the wrong thing: a profile of an idle or toy workload tells you nothing, so capture under realistic load, and for a server that means grabbing a profile while it’s serving traffic through the live endpoint, not from a synthetic benchmark that exercises one path. And read the flat-versus-cum distinction carefully every time — a function with huge cum and tiny flat isn’t slow itself, it’s just the one that called the slow thing. Sort by flat to find where the CPU actually burns, follow cum down the call tree to understand why that path got hit.

Final thoughts

The profiler removes the guessing. A CPU profile found isPrime at 93% and then pointed at the exact modulo line; a heap profile named the function allocating 47 MB; a goroutine profile located a hundred parked goroutines; a block profile measured five seconds of lock contention that no CPU profile would reveal. The commands are the same across all of them — top to rank, list to drop to source lines, web for the call graph if you have Graphviz. And net/http/pprof puts the whole kit on a running server so you can profile production without restarting it. The rule underneath all of it hasn’t changed since the first line of this chapter: measure first, then optimize the thing the measurement actually pointed at.

Next: logs, metrics, and traces — the three telemetry signals, what’s in the standard library, and how to pick the one that answers your question.

Comments