Profiling with pprof

Profile, don't guess

Intuition about where a program spends its time is wrong often enough that experienced engineers stop trusting it. A profile replaces "I think the JSON encoding is slow" with "41% of CPU samples are under readBlock, and 83% of allocated bytes come from line 161". This page covers Go's built-in profilers, how to collect them safely in production, how to read them, and a complete worked investigation on the storage engine built in this handbook.

Measurements: Go 1.26.4, Apple M1 Pro.

The profiles

Profile What a sample is How it is collected Answers
cpu A stack, every 10 ms of CPU time per thread (SIGPROF, 100 Hz) pprof.StartCPUProfile, /debug/pprof/profile?seconds=30, -cpuprofile Where is CPU time spent?
heap A stack per sampled allocation (one per 512 KB allocated on average) Always on; /debug/pprof/heap, -memprofile inuse_*: what holds memory now; alloc_*: what allocated the most since start
allocs Same data as heap, defaulting to alloc_space /debug/pprof/allocs Which code drives GC work
goroutine Stack of every goroutine /debug/pprof/goroutine?debug=1/2 Leaks, deadlocks, what is everything waiting on
block Time goroutines spent blocked on channels, select, Cond, mutexes Off by default: runtime.SetBlockProfileRate(n) Where do goroutines wait?
mutex Time other goroutines waited, attributed to the stack that held the lock and released it Off by default: runtime.SetMutexProfileFraction(n) Which locks are contended, and by whom?
threadcreate Stacks that created OS threads /debug/pprof/threadcreate Why do we have 3,000 threads? (blocking syscalls, cgo)
trace Not a profile — a full event log /debug/pprof/trace?seconds=5 Latency, scheduling, GC interplay: Execution Tracer

The CPU profile only sees on-CPU time. A goroutine waiting for a lock, a channel, or a network reply is not running and produces no samples. If a request takes 200 ms and the CPU profile accounts for 5 ms of it, the other 195 ms is waiting — use the block/mutex profiles or the tracer. "The profile shows nothing hot, but it's slow" is the signature of an off-CPU problem.

Collecting

In tests and benchmarks:

go test -run='^$' -bench=Get -cpuprofile=cpu.out -memprofile=mem.out ./kv
go tool pprof -http=:8080 cpu.out      # interactive UI: flame graph, source, graph

In a service, expose net/http/pprof on an internal port:

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

go func() {
    // Never on the public listener: profiles leak source paths and data,
    // and a 30 s CPU profile request is a cheap way to burn your CPU.
    log.Println(http.ListenAndServe("127.0.0.1:6060", nil))
}()

go tool pprof -http=:8080 'http://host:6060/debug/pprof/profile?seconds=30'
go tool pprof -http=:8080 'http://host:6060/debug/pprof/heap'

Overhead: CPU profiling costs a few percent while active; heap sampling is always on and cheap; block and mutex profiling cost scales with the rate you choose (a mutex fraction of 100 — sample 1 in 100 contention events — is a common production setting). Continuous profiling systems (Pyroscope, Parca, Google Cloud Profiler, Datadog) collect these periodically from every instance, so you can look at last Tuesday's profile when the incident is already over.

Reading a profile

go tool pprof -top cpu.out             # flat list
go tool pprof -list 'Table..readBlock' mem.out   # per-line annotation of a function
go tool pprof -peek 'rawsyscalln' cpu.out        # callers and callees of a function
go tool pprof -http=:8080 -diff_base=old.out new.out   # what changed
  • flat: samples where this function itself was executing.
  • cum: samples where this function was on the stack (itself plus everything it called).
  • A function with high cum and low flat is a path to the cost; follow it down. High flat is where the work actually happens.
  • In a flame graph, width is cum; the frames at the top edge of each tower are the flat costs. Look for wide plateaus, not tall towers.

Sample counts are statistical: a function with 3 samples in a 30 s profile is noise. Profile long enough to have thousands of samples.

Worked investigation: a slow Get

The storage engine's point-lookup benchmark — 200,000 keys with 100-byte values, random reads — reports:

BenchmarkGet-8   1221699   2945 ns/op   4894 B/op   14 allocs/op

Three microseconds for an in-memory lookup is slow, and 4.9 KB allocated per lookup is suspicious. Hypotheses come after the profile.

Step 1: CPU profile

      flat  flat%   sum%        cum   cum%
     3.69s 77.20% 77.20%      3.69s 77.20%  syscall.rawsyscalln
     0.42s  8.79% 85.98%      0.42s  8.79%  runtime.pthread_cond_wait
     0.20s  4.18% 90.17%      0.20s  4.18%  runtime.pthread_cond_signal
         0     0% 97.49%      2.81s 58.79%  internal/poll.(*FD).Pread
         0     0% 97.49%      2.81s 58.79%  kv.(*DB).Get
         0     0% 97.49%      0.87s 18.20%  internal/poll.(*FD).Write
         0     0% 97.49%      0.72s 15.06%  kv.(*DB).commit

77% of CPU is inside system calls. Pread under DB.Get accounts for 59% of all samples — the lookups are reading from the file, which should not happen for hot data that fits in memory. (The Write and commit samples are from the benchmark's setup phase loading the 200,000 keys; the CPU profile covers the whole process, not only the timed loop.)

Step 2: heap profile, alloc_space

ROUTINE ======================== kv.(*Table).readBlock in table.go
    4.79GB     4.89GB (flat, cum) 85.14% of Total
         .          .    158:   if b, ok := t.cache.Get(t.id, h.off); ok {
         .          .    159:       return b, nil
         .          .    160:   }
    4.79GB     4.79GB    161:   buf := make([]byte, h.size+blockTrailer)
         .          .    162:   if _, err := t.r.ReadAt(buf, int64(h.off)); err != nil {
         .   103.02MB    170:   t.cache.Put(t.id, h.off, b)

85% of all allocated bytes are fresh 4 KB block buffers on line 161 — the cache-miss path. Both profiles point the same way: the block cache is missing.

Step 3: form a hypothesis and measure it directly

The data set is ~26 MB of key/value bytes; the block cache defaults to 8 MB. Random reads over a working set three times larger than the cache should miss most of the time. Instead of guessing, add a metric to the benchmark:

b.ReportMetric(float64(hits)/float64(hits+misses)*100, "hit%")

Step 4: change one thing, compare with statistics

Rerun with an 8 MB and a 64 MB cache, 8 runs each:

Metric 8 MB cache 64 MB cache Change
Time per Get 2.962 µs ± 2% 1.085 µs ± 1% −63.4% (p=0.000, n=8)
Block cache hit rate 8.2% 99.5% +91 points
Bytes allocated per Get 4,892 B 582.5 B −88.1% (p=0.000, n=8)

The hit rate went from 8% to 99.5%, latency dropped 63%, and allocation per lookup dropped 88%. The mechanism is fully explained: every miss paid a pread system call, a 4 KB allocation, and a CRC32 over the block.

Step 5: decide what the result means

The finding is not "use a bigger cache". It is: lookup cost is dominated by block-cache hit rate, and the engine exposes too little to see it. Real follow-ups would be exporting hit-rate metrics, sizing the cache from the working set, and reducing the miss cost (reusing buffers, or reading through the OS page cache with smaller blocks). The 11 remaining allocations per cached lookup — internal-key construction, iterator objects, the copied value — are the next profile's target.

Mutex and block profiles in practice

runtime.SetMutexProfileFraction(100) // at startup
runtime.SetBlockProfileRate(int((10 * time.Microsecond).Nanoseconds())) // ~1 sample per 10 µs spent blocked

A mutex profile answers "who is holding the lock that everyone waits for", attributing the waiters' delay to the unlocker's stack — exactly where to look to shorten the critical section. The block profile shows where goroutines wait (including channel receives that are supposed to wait, such as idle workers — filter with -focus).

Profiling hygiene

  • Profile what runs in production: same build flags, same GOMAXPROCS, realistic data. Profiles of a debug build or a toy input describe a different program.
  • Don't stack profilers. -memprofilerate=1 (record every allocation) adds a stack walk to every malloc; a CPU profile taken at the same time is dominated by runtime.callers and runtime.pcvalue — the profiler profiling itself.
  • Symbolization needs the binary. go tool pprof binary profile for profiles from stripped builds or other machines.
  • Compare, don't stare. -diff_base between a good and a bad version, or between a normal and an incident period, points straight at the change.
  • Use labels to slice a profile by request type or tenant: pprof.Do(ctx, pprof.Labels("endpoint", "/search"), func(ctx context.Context) { ... }), then -tagfocus=endpoint=/search.

Common pitfall

Optimizing the top of a CPU profile of an idle service. Someone takes a 30-second profile of a production instance during a quiet period and sees runtime.findRunnable, runtime.usleep, and GC background workers at the top, and starts tuning the scheduler. In a mostly idle process, the runtime's own bookkeeping is naturally the largest consumer of the little CPU used. Profile under representative load (or during the incident), check the total sample duration against wall time (Duration: 30s, Total samples = 1.2s (4%) means the process was 96% idle), and focus on your own code's cumulative cost per request rather than flat runtime frames.

Review questions

  1. Why does a request that takes 200 ms often show only a few ms in the CPU profile, and which tools see the rest?
  2. What is the difference between inuse_space and alloc_space, and which one relates to GC CPU cost?
  3. In the Get investigation, which two independent profile signals pointed at the block cache?
  4. Why did the investigation add a hit-rate metric instead of directly increasing the cache size?
  5. What does the mutex profile attribute to the unlocker's stack, and why is that the useful place?