Profiling with pprof

Take CPU and heap profiles from a running Go service, then read them with go tool pprof to find where time and memory go.

Syntaxgo tool pprof -http=:8080 "http://localhost:6060/debug/pprof/profile?seconds=30"

A profile is a sample of what your program was doing. For CPU, the runtime interrupts the program about a hundred times a second and records the stack of function calls in progress. Add up thousands of those samples and the functions burning the time stand out. For memory, the runtime records where allocations came from. pprof is both the file format and the tool that reads it.

Getting a profile

Import net/http/pprof and the package registers routes under /debug/pprof/ that hand out profiles over HTTP. The useful ones are profile (CPU, for a number of seconds you choose), heap (memory in use now), goroutine (every goroutine's stack) and allocs (every allocation since start). From a benchmark instead, use go test -bench=. -cpuprofile cpu.out.

Reading it

Run go tool pprof -http=:8080 cpu.prof to browse it, or use the text prompt and type top. Two columns matter: flat is time inside that function itself, cum is time in it plus everything it called. A tall cum with a tiny flat means the cost is deeper down. list funcName prints the function's source with the cost on each line, which is usually where the answer is.

What trips people up

The heap profile defaults to inuse_space, memory still held. To find the code that churns through short-lived objects, ask for -sample_index=alloc_space instead; a leak and an allocation storm look completely different.

Example

Example · go
package main

import (
	"fmt"
	"os"
	"runtime/pprof"
)

// countPrimes is deliberately slow, so the profile has something to show.
func countPrimes(limit int) int {
	n := 0
	for v := 2; v < limit; v++ {
		prime := true
		for d := 2; d*d <= v; d++ {
			if v%d == 0 {
				prime = false
				break
			}
		}
		if prime {
			n++
		}
	}
	return n
}

func main() {
	f, err := os.Create("cpu.prof")
	if err != nil {
		fmt.Println("create:", err)
		return
	}
	defer f.Close()
	// From here the runtime samples stacks until Stop is called.
	if err := pprof.StartCPUProfile(f); err != nil {
		fmt.Println("start:", err)
		return
	}
	fmt.Println("primes:", countPrimes(200000))
	pprof.StopCPUProfile() // without this the file is truncated and unreadable
	fmt.Println("wrote cpu.prof")
}

// Output:
// primes: 17984
// wrote cpu.prof

When to use it

  • Find the function responsible for a service pinning a CPU core in production.
  • Decide whether rising memory is a leak (inuse_space grows) or just churn (alloc_space is high).
  • Confirm a goroutine leak by seeing hundreds of goroutines parked on the same channel receive.
  • Check that an optimisation actually removed the cost it was meant to remove.

More examples

Profiles on a private port, away from your API

This is the shape to use in production: profiling always available, never exposed. Reach the port with kubectl port-forward, then point go tool pprof at localhost:6060. pprof.Index also serves the heap, goroutine and allocs profiles, so these five registrations cover everything the blank import would have given you.

Example · go
package main

import (
	"net/http"
	"net/http/pprof" // named import: we register the routes ourselves
)

func main() {
	// The blank import _ "net/http/pprof" is shorthand for these five lines,
	// except that it adds them to http.DefaultServeMux instead of your own mux.
	admin := http.NewServeMux()
	admin.HandleFunc("/debug/pprof/", pprof.Index)
	admin.HandleFunc("/debug/pprof/cmdline", pprof.Cmdline)
	admin.HandleFunc("/debug/pprof/profile", pprof.Profile)
	admin.HandleFunc("/debug/pprof/symbol", pprof.Symbol)
	admin.HandleFunc("/debug/pprof/trace", pprof.Trace)

	// Bound to localhost, so only something inside the container can reach it.
	go func() { _ = http.ListenAndServe("127.0.0.1:6060", admin) }()

	api := http.NewServeMux()
	api.HandleFunc("GET /healthz", func(w http.ResponseWriter, r *http.Request) {})
	_ = http.ListenAndServe(":8080", api)
}

Profiling a benchmark instead of a server

Profiling a benchmark is faster than profiling a service, because you control the workload and can repeat it. -run='^$' means no tests run, only the benchmark. Use this when you already know which function is hot and want to see inside it; use the HTTP endpoints when you do not know where to look.

Example · bash
# Run one benchmark and write both profiles.
go test -run='^$' -bench=BenchmarkRender -benchtime=5s \
  -cpuprofile cpu.out -memprofile mem.out ./internal/render

# Where the time went.
go tool pprof -http=:8080 cpu.out

# Where the memory still in use was allocated.
go tool pprof -http=:8081 mem.out

# Where allocations happen, including ones already collected.
go tool pprof -sample_index=alloc_space -http=:8082 mem.out

Comparing two profiles after a change

A single profile tells you where the cost is; two profiles tell you whether your change helped. -base subtracts the first from the second, so unchanged work disappears and only the delta is left. The goroutine profile with debug=1 prints plain-text stacks, which is the quickest way to confirm a suspected goroutine leak.

Example · bash
# Before the change.
curl -o before.prof "http://localhost:6060/debug/pprof/heap"

# ... deploy or patch, let it run under the same load ...
curl -o after.prof "http://localhost:6060/debug/pprof/heap"

# Show only the difference: what the change added or removed.
go tool pprof -base before.prof -http=:8080 after.prof

# Thirty goroutines all parked in the same place is usually a leak.
curl "http://localhost:6060/debug/pprof/goroutine?debug=1" | head -40

Related

go benchmarksgo memorygo perf practicesgo goroutine leaksgo servemux

Discussion

  • Be the first to comment on this lesson.