Profiling With pprof

You have a service that is slower than it should be. The obvious move is to read the code and guess, and the guess is usually wrong: it names the database call that turns out to be 3% of the time, and misses the log line that formats a request body on every request. A profile replaces the guess with a measurement, and the measurement is usually surprising in a way that saves a day.

Go ships the whole apparatus in the standard library. There is nothing to install, no agent to run, and the numbers come from the runtime itself, which is the same code that schedules your goroutines and collects your garbage.

pprof listens on its own port, never the public one

Importing net/http/pprof registers handlers on http.DefaultServeMux, which is convenient and dangerous: a service whose public handler is the default mux has published its heap contents, its goroutine stacks and its command line to anyone who can reach the port. The command line alone is worth not leaking, because it contains the flags your process started with.

The pattern that avoids the accident is a second http.Server on a loopback address, with the profiling handlers mounted on a mux of its own. This service does exactly that, and the log line says which is which:

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

adminMux := http.NewServeMux()
adminMux.Handle("/debug/pprof/", http.DefaultServeMux)
adminSrv := &http.Server{
	Addr:              cfg.PprofAddr, // defaults to 127.0.0.1:6060
	Handler:           adminMux,
	ReadHeaderTimeout: 5 * time.Second,
}

{"time":"2026-10-16T19:49:28.514089Z","level":"INFO","msg":"pprof listening","addr":"127.0.0.1:16070","scope":"loopback only"}

Two things make this safe rather than merely tidy. The address is loopback, so it is reachable from inside the container or the host and not from the network, and the configuration validation from the previous lesson refuses to start in production with a profiling address that is not loopback. If you need to reach it from a laptop, the answer is a port-forward or an SSH tunnel, not a public bind and a firewall rule.

What it exposes is worth knowing before you turn it on. The index lists the profiles available and the sample counts behind each one:

$ curl -s http://127.0.0.1:16070/debug/pprof/
39  allocs
16  block
0   cmdline
7   goroutine
40  heap
176 mutex
0   profile
0   trace

Each profile answers one question, and picking the wrong one wastes the hour

The names are similar enough that people capture the wrong one and conclude that profiling does not work. What each file actually contains:

Profile	The question it answers	Where the samples come from
profile (CPU)	Where is the processor time going while this is running?	A timer interrupt every 10ms records the current stack
heap	What is still allocated right now, and what has been allocated in total?	Sampled at allocation time; inuse_space and alloc_space are separate views
goroutine	What is every goroutine doing, and are they all accounted for?	A full stack dump, taken on request
block	Where are goroutines waiting on channels, mutexes and selects?	Off by default; needs runtime.SetBlockProfileRate
mutex	Which mutexes are contended, and who is waiting for them?	Off by default; needs runtime.SetMutexProfileFraction
trace	When did each goroutine run, and how long did it wait to be scheduled?	Every scheduler event, not a sample

The two that are off by default are off for a reason. Block and mutex profiling cost measurable overhead because every blocking event has to be recorded, so a service that enables them permanently pays for the ability to answer a question it is not asking. Enable them for the duration of an investigation, or leave them at a low rate in production if you have decided the cost is worth it. This service turns them on so the profiles are not empty:

runtime.SetBlockProfileRate(1000)   // sample one blocking event per microsecond of wait
runtime.SetMutexProfileFraction(100) // report 1 in 100 contended mutex events

The heap profile deserves one more sentence, because inuse_space and alloc_space are different files to different readers. A leak shows up in inuse_space and grows over time. Churn, the thing that makes the garbage collector busy while memory stays flat, only shows up in alloc_space. If your service is using 40% of its CPU in runtime.mallocgc and its resident memory is not growing, you want alloc_space.

A real profile, a real bottleneck, and what it said

The service in this lesson parses one line of an ingest feed per iteration of a hot loop. The line format is topic|partition|bytes|key=value,... and the research question is why GET /parse?n=200000 takes 450ms at the median with eight concurrent clients. The load generator ran for 25 seconds at eight workers and managed 562 requests, 22.5 per second, p50 345ms. While it ran, the CPU profile was captured for 15 seconds:

$ ./bin/loadgen -url 'http://127.0.0.1:18090/parse?n=200000' -c 8 -d 25s
562 ok, 0 failed in 25s (22.5 req/s)
latency p50=345ms p95=474ms p99=609ms max=671ms

$ go tool pprof -top http://127.0.0.1:16070/debug/pprof/profile?seconds=15
Duration: 15.19s, Total samples = 42.68s (280.89%)
      flat  flat%   sum%        cum   cum%
   10.15s 23.78% 23.78%     10.16s 23.81%  runtime.usleep
    9.02s 21.13% 44.92%      9.02s 21.13%  runtime.madvise
    4.14s  9.70% 54.62%      4.14s  9.70%  runtime.pthread_cond_wait
    2.69s  6.30% 60.92%      2.69s  6.30%  runtime.pthread_kill
    1.81s  4.24% 65.16%      1.81s  4.24%  runtime.pthread_cond_signal
    0.81s  1.90% 67.06%      0.81s  1.90%  internal/bytealg.CountString

The first four rows are the interesting part and none of them is your code. runtime.usleep is a goroutine sleeping; runtime.madvise is the runtime returning memory to the operating system after a garbage collection; pthread_cond_wait and pthread_cond_signal are the garbage collector's own threads coordinating. A profile dominated by those four functions is a profile of a program whose garbage collector is the busiest component, and the fix is not in the scheduler.

The cumulative view confirms it by asking a different question: not who burned the CPU, but who is on the stack when it is burned. The parser is 28.8% of the whole profile's cumulative time, and almost all of that is underneath allocations:

$ go tool pprof -top -cum -focus='feed\.' cpu-slow.pb.gz
Showing nodes accounting for 1.81s, 4.24% of 42.68s total
      flat  flat%   sum%        cum   cum%
     0.33s  0.77%  0.77%     12.28s 28.77%  lab.example/m6/internal/feed.Slow
     0.34s   0.8%  1.57%      5.75s 13.47%  runtime.mallocgc
     0.66s  1.55%  3.12%      4.94s 11.57%  runtime.mallocgcSmallScanNoHeader
     0.48s  1.12%  4.24%      4.61s 10.80%  runtime.mapassign_faststr

Read that table carefully, because it is the whole lesson. The parser's own instructions are 0.33 seconds of a 15-second profile, 0.77%. Everything else attributed to it is the allocator and the map growth. strings.Split builds a []string for the fields and another for the tags, and make(map[string]string) called without a size grows its buckets as the tags arrive. The heap profile taken during the same load puts a number on the churn with alloc_space: 58.46GB allocated in that window, 43.76GB of it in the parser.

The fix has two parts. Walk the line by index instead of splitting it, so no intermediate slice exists. And let the caller hand the parser a map to reuse, sized once and cleared per call, so a request that parses the same shape a thousand times does not allocate a thousand maps:

type Buffer struct {
	tags map[string]string
}

func (b *Buffer) Parse(line string) (Message, error) {
	// ... same index walk as Fast, then:
	if tags == "" {
		return m, nil
	}
	if b.tags == nil {
		b.tags = make(map[string]string, strings.Count(tags, ",")+1)
	}
	for k := range b.tags {
		delete(b.tags, k)
	}
	m.Tags = b.tags
	// ... fill m.Tags
}

Reusing the map is safe only because the caller is done with the tags before the next parse, which is true for a handler that reads them and returns and false for a parser whose messages are queued. The comment in the real code says so, and that sentence is the price of the optimisation.

Same load, same eight clients, after the change: 184 requests in six seconds, 30.7 per second, p50 264ms against 452ms before. The re-captured profile still shows feed.Fast at 29.3% cumulative, because the map is still allocated once per call there, and the top flat rows are still the garbage collector. The improvement shows up in alloc_space, which is the profile that was telling the truth all along.

go tool pprof does more than print a table

The same profile is useful in three modes and the table is the least of them. Interactive mode lets you walk the call graph and ask for the callers of a function, which is how you find out that the expensive TrimSpace call is reached from four places and only one of them is hot:

$ go tool pprof cpu-slow.pb.gz
(pprof) top -cum
(pprof) peek feed.Slow
(pprof) list strings.TrimSpace
(pprof) web        # opens an SVG graph in a browser
(pprof) exit

The -http flag serves the same data as a browsable interface with a flame graph, a call graph, a source view and a disassembly view of the same file, which is what you want when the question is "which line inside this function", not "which function":

$ go tool pprof -http=127.0.0.1:8081 cpu-slow.pb.gz

A flame graph is a call tree laid out by time, and reading one is mostly about understanding that width is not severity. Each frame's width is the share of samples whose stack contained it, the tree is sorted so the widest child sits leftmost, and the x-axis is alphabetical within a frame rather than chronological. The thing to look for is a wide frame with no wide children: that is a function doing the work itself, and it is where a change is worth making. A wide frame with wide children is a frame you can only fix by fixing what is underneath it, which is exactly what the table above showed for feed.Slow.

runtime/trace answers the question a CPU profile cannot

A CPU profile is a histogram of stacks taken while threads were running. It has nothing to say about time a goroutine spent waiting, which means it is silent about the failure mode that looks exactly like a slow service: goroutines that are runnable and not being scheduled, contention on a channel, or a garbage collection pause that stalls everything for two milliseconds at a time. If your pprof output is dominated by runtime functions that sleep and coordinate, the next question is a scheduling question and the tool is the execution tracer:

$ curl -s -o trace.out 'http://127.0.0.1:16070/debug/pprof/trace?seconds=3'
$ ls -l trace.out
-rw-r--r--  1 moisesbonillacode  wheel  662001  trace.out
$ go tool trace trace.out
2026/10/16 13:46  Parsing trace...
2026/10/16 13:46  Splitting trace...
2026/10/16 13:46  Opening browser. Trace viewer is listening on http://127.0.0.1:57168

Three seconds of trace produced 662 kilobytes of scheduler events, which is the first thing to understand about it: the trace records everything, so it is captured for seconds rather than minutes. The viewer opens on a task list and the views that earn their space are Scheduler latency profile, which gives you the same top-function table but for time spent waiting to be scheduled, and the goroutine analysis, which reports how long the average goroutine of each kind spent running, runnable, blocked on a channel and blocked on a syscall. If the CPU is not saturated and requests are slow, those two numbers are the ones that will say why.

Show the solution and the reasoning

The answer that matters is the last question. In the profile in this lesson the CPU was not saturated, at 280% of a possible 800% across eight cores, and the top flat rows were the garbage collector rather than any request-handling code. A service in that state is allocation-bound: it spends a third of its CPU on the consequences of allocating, and the useful measurement is alloc_space, not the flat CPU table.

That is why the numbers look strange if you only read the flat table after the fix. feed.Fast still shows 29.3% cumulative and the top rows are still the collector, because one map allocation per call remains. The alloc_space profile is the one that moves, and the benchmark agrees with it: 448 bytes and 4 allocations per operation before, 0 bytes and 0 allocations after. When the profile and the benchmark tell the same story, you can stop.

On the trace question, the way to tell the two apart is to look at the scheduler latency profile next to the CPU profile. If the CPU profile is busy with your own code and the latency profile is short, the service is CPU-bound and the fix is a better algorithm or more cores. If the CPU profile is quiet and the latency profile shows goroutines waiting to run, you have either more runnable goroutines than GOMAXPROCS can satisfy, which is capacity, or you have a mutex or a channel serialising work that should be parallel, which is a design problem. The tracer separates those two cases; a CPU profile cannot see either, because waiting is not running.

One caution about the lab endpoint specifically. A loop that parses the same document a few thousand times is a legitimate way to create a hot spot, but the compiler can notice when the result is unused and remove the work, and the profile will then be empty and confusing. Assign the result to a package-level variable or feed it into a checksum, as the benchmarks in this lesson do, and the samples appear.