Tutorial

Profiling Go Services with pprof

A hands-on introduction to Go's built-in profiler. Capture CPU and heap profiles from a running service, read flame data without guessing, dump goroutines, and learn when to reach for block, mutex, and trace tooling instead.

Your Go service got slow. Or it started eating memory. Or goroutine counts keep creeping up for no obvious reason. You can guess, add a few log lines, restart, and hope. Or you can ask the runtime, which has been recording the answer the whole time.

That's what this tutorial is about. Go ships a profiler in the standard library, it's safe enough to run in production, and reading its output is a skill you can learn in an afternoon. We'll do it live: every command below runs against a real service in the playground, and most outputs you'll see here are copy-pasted from real runs.

A note on mindset before we start. Profiling is not about making code faster. It's about replacing guesses with measurements. Sometimes the measurement confirms the hunch. Often it points somewhere you'd never have looked.

Four tools, four questions

Go's diagnostics story is bigger than pprof, and picking the right tool is half the battle. The official diagnostics guide groups them by the question they answer:

ToolAnswers the question
Profiling (pprof)Where did the CPU time / memory go?
Tracing (go tool trace)Why did this request wait? What blocked whom?
Debugging (delve)What is the program's state right now?
Runtime stats (runtime/metrics, GODEBUG)Is the process healthy over time?

One warning from that same guide, which took me too long to take seriously: these tools interfere with each other. A precise memory profile skews CPU profiles; blocking profiling distorts scheduler traces. Turn one thing on at a time.

Meet hello-api

The playground has a small service already running on port 8080. Its source lives in /root/hello-api (readable by everyone, owned by root):

  • GET / says hello
  • GET /work burns CPU for a few milliseconds, on purpose
  • GET /allocate retains 1 MiB of memory per call, also on purpose

The main.go includes this single line:

import _ "net/http/pprof"

That blank import registers everything Go's runtime can measure under /debug/pprof/. No config, no agent, no rebuild. If your service runs an HTTP server, this is all it takes to make it profileable. (If it doesn't run an HTTP server, you can start one on a private port just for profiling, or use runtime/pprof to write profiles to files.)

The pprof HTTP interface

Open the index and see what's available:

curl http://localhost:8080/debug/pprof/

You'll get a plain HTML page listing the profiles. Each one answers a different question:

ProfileWhat it measures
profileCPU: where time goes while code is actually running
heapMemory currently retained by live objects
allocsAll allocations since startup, including already-freed ones
goroutineStack of every goroutine alive right now
blockWhere goroutines wait on channels and sync primitives
mutexWhich lock holders make everyone else wait
threadcreateWhat leads to new OS threads
traceAn execution trace for go tool trace

Three query parameters matter. seconds=N profiles for N seconds (for CPU and trace) or returns a delta (for the others). debug=N switches the response between binary protobuf (for tools) and readable text (for humans). gc=1 runs a garbage collection before taking a heap sample, which gives you a cleaner "live memory" picture.

Stuck?

curl http://localhost:8080/debug/pprof/ and look for href='profile?debug=1'-style links. They're relative links, all under /debug/pprof/.

CPU profiling: where the time goes

The CPU profiler samples the program about 100 times per second and records which function was running at each sample. That's the whole trick. A function that uses 40% of the CPU will show up in roughly 40% of the samples. No instrumentation of your code, no clocks around functions, just statistics.

Which leads to the first thing that trips everyone up: an idle program has an empty CPU profile. Sampling records running code. If nothing runs, there's nothing to record. So generate some load, then capture a 5-second profile:

for i in $(seq 1 50); do curl -s -o /dev/null http://localhost:8080/work & done
curl -o /tmp/cpu.prof 'http://localhost:8080/debug/pprof/profile?seconds=5'

The second command blocks for the whole 5 seconds. That's the profiling window, not a hang. The file it writes is a gzip-compressed protobuf; you can check it starts with the bytes 1f 8b if you're the suspicious type.

Now read it:

go tool pprof -top /tmp/cpu.prof

Here's the report from my run, trimmed:

File: hello-api
Type: cpu
Duration: 5.13s, Total samples = 2.43s (47.40%)
      flat  flat%   sum%        cum   cum%
     2.42s 99.59% 99.59%      2.42s 99.59%  main.busyLoop (inline)

Two columns deserve your attention. flat is time spent in the function's own code. cum (cumulative) adds everything the function calls. A function with high flat time is doing heavy lifting itself. High cum with low flat means it's a manager: the cost belongs to its callees, so read further down the report.

The report says Total samples = 0

The profile caught an idle app. Kill the old file, start the load loop, and capture again. Both commands need to overlap with the 5-second window.

-top is where every investigation starts, but two more views earn their keep:

# line-by-line cost inside one function
go tool pprof -list main.busyLoop /tmp/cpu.prof

# interactive web UI with the call graph and flame view
go tool pprof -http=: /tmp/cpu.prof

The flame graph is the same data as -top, just drawn so that wider boxes mean more CPU. When a coworker asks what your service is doing all day, a flame graph is the screenshot you send them.

Heap profiling: what's still alive

CPU profiles answer "where does time go". Heap profiles answer "who is holding on to memory". Same machinery, different question, and one subtlety that changes how you read it.

Go actually serves two views of the same data. The heap profile's default sample index is inuse_space: bytes retained by objects that are still alive. The allocs profile is byte-for-byte the same data with the default flipped to alloc_space: everything ever allocated, including what the GC already freed. Retained memory points at leaks. Allocation volume points at GC pressure and churn. Both matter; they're different problems with different fixes.

Hammer the allocation endpoint, then grab a heap profile:

for i in $(seq 1 20); do curl -s -o /dev/null http://localhost:8080/allocate; done
curl -o /tmp/heap.prof http://localhost:8080/debug/pprof/heap
go tool pprof -top -sample_index=inuse_space /tmp/heap.prof

From the playground, for real:

Type: inuse_space
Showing nodes accounting for 27498kB, 100% of 27498kB total
      flat  flat%   sum%        cum   cum%
   26984kB 98.13% 98.13%    26984kB 98.13%  main.allocate (inline)

Twenty calls at 1 MiB each, and main.allocate sits at the top holding about 26 MB. (The number is a bit higher than 20 MiB because the slice backing array grows and the old capacity stays reachable through the package-level variable. Profiles are samples, not audits. The signal is overwhelming anyway.)

One more heap quirk worth knowing: a heap profile reports as of the most recent garbage collection. Anything allocated since the last GC doesn't show up in inuse numbers. That's deliberate, it keeps garbage out of the "live memory" picture. If you want the freshest possible snapshot, fetch /debug/pprof/heap?gc=1, which collects garbage first, then samples.

Goroutine dumps: a census of concurrency

Not everything that hurts is using CPU. Goroutines stuck on a channel that nobody reads consume nothing and hurt everything. For those, skip sampling entirely and get the full list:

curl -s 'http://localhost:8080/debug/pprof/goroutine?debug=1' | head -n 5
goroutine profile: total 3
1 @ 0x104cdbee0 0x104ca1080 0x104cdb110 ...
#   0x104cdb10f internal/poll.runtime_pollWait+0x9f .../netpoll.go:351

The first line is the total count, and it's the cheapest health metric a Go service has. Watch that number over time in a healthy service and learn its resting heart rate. When it starts climbing and never comes down, you have a goroutine leak, and the dump above tells you exactly which stack the newcomers are stuck in.

With debug=2 you get the same stacks in panic-dump format, which is the format to attach to a bug report. It's also how you answer "what is this hung process doing right now" without attaching a debugger.

Block and mutex profiles: the ones you have to switch on

Two profiles ship disabled because sampling every wait would tax programs that wait a lot (which is most programs, most of the time). Your service opts in with two runtime calls:

import "runtime"

func init() {
    runtime.SetBlockProfileRate(1000)  // ~1 sample per millisecond blocked
    runtime.SetMutexProfileFraction(5) // sample 1 in 5 contention events
}

Block profiles record goroutines waiting on channels, mutexes, WaitGroups, and friends, with the stack pointing at the waiting call. Mutex profiles record the other side of the same story: the stack of whoever held the lock while others queued. The stack points at the Unlock, which is where the damage gets measured.

See for yourself. Save this as mutexdemo.go anywhere in the playground and run go run mutexdemo.go:

package main

import (
    "net/http"
    _ "net/http/pprof"
    "runtime"
    "sync"
    "time"
)

func init() { runtime.SetMutexProfileFraction(5) }

var mu sync.Mutex
var counter int

func worker() {
    for {
        mu.Lock()
        counter++
        time.Sleep(10 * time.Millisecond) // "work", done while holding the lock
        mu.Unlock()
    }
}

func main() {
    for i := 0; i < 10; i++ { go worker() }
    http.ListenAndServe("localhost:6060", nil)
}

Ten workers, one mutex, everyone waiting their turn. The mutex profile after a few seconds:

Type: delay
Showing nodes accounting for 13.31s, 100% of 13.31s total
      flat  flat%   sum%        cum   cum%
    13.31s   100%   100%     13.31s   100%  sync.(*Mutex).Unlock (inline)
         0     0%   100%     13.31s   100%  main.worker

Thirteen seconds of cumulative waiting, all blamed on the Unlock inside main.worker. That's the signature of a lock held too long: the fix is almost always shrinking the critical section, in this case by not sleeping while holding mu.

When sampling isn't the right lens

Profilers answer "what's hot". They're blind to what's cold: a hundred goroutines blocked on a channel show zero CPU samples, because zero CPU is what they use. Two more tools cover the blind spots.

The execution tracer records what every goroutine did (and waited for) over a window:

curl -o /tmp/trace.out 'http://localhost:8080/debug/pprof/trace?seconds=5'
go tool trace /tmp/trace.out

go tool trace serves a local web UI with per-goroutine timelines. Tracing used to cost 10-20% CPU, which made it a debugging-only tool; since Go 1.21 it's around 1-2%, and since Go 1.22 the runtime splits long traces into manageable chunks. Treat it as the tool for latency and scheduling questions, not for hotspot hunting.

For a quick health check without any tooling, the runtime can narrate its own GC:

GODEBUG=gctrace=1 ./hello-api 2>&1 | grep '^gc'

Real output from this very app, under allocation load:

gc 2 @1.044s 0%: 0.022+0.70+0.006 ms clock, 0.18+0/0.14/0.60+0.048 ms cpu, 11->11->8 MB, 11 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 3 @1.068s 0%: 0.063+1.3+0.008 ms clock, 0.51+0/0.19/1.2+0.068 ms cpu, 21->21->13 MB, 21 MB goal, 0 MB stacks, 0 MB globals, 8 P

The part I read first is 21->21->13 MB: heap size before GC, after GC, and the live heap after marking. If the first number keeps climbing while the last stays flat, live memory is stable and the GC is just keeping up with churn. If the last number climbs too, something is genuinely being retained, and the heap profile from the previous section will name the culprit.

Rules I'd tattoo on my arm if it were bigger

  • One profile at a time. They interfere with each other, and the results lie to you.
  • Profiling in production is supported and normal. It costs something (CPU profiling more than the others). Measure the cost once, then profile a random replica periodically instead of staring at dashboards when things are already on fire.
  • A profile is a sample, not a census. main.busyLoop at 99% points you at the right function; it doesn't promise the number is exact.
  • Symbolization needs the binary that produced the profile. Keep your release binaries; a profile from build 41 read against build 39 gives confident nonsense.
  • The goroutine count is a free health metric. Graph it. Thank me during the first leak hunt.

Practice time

Reading about profilers is pleasant; catching a real leak is a skill. The challenge below uses the same service family you just explored. Something in it is broken, and the tools you just learned will find it.

When you're done with that one, the natural next steps are heap profiles in anger (-sample_index=alloc_space, diffing profiles with -base), and block profiles under real contention. The runtime has been keeping the receipts this whole time. Now you know where it keeps them.

About the Author

Restu Muzakir

Restu Muzakir

A software engineer working with Golang, Typescript, Python, Docker, and Kubernetes; Automated everythings

Find this author online

More tutorials you might like

Learn by doing, not just by reading or watching

Sign up for a free account to start a VM playground right on this page, track your progress, and get notified about new learning materials.

Sign up for free