Golang profiling with pprof: a slow regex and a leaking slice, found and measured

The service below searches 20,000 log lines with a regular expression. It has two bugs, one that burns CPU and one that holds memory, and neither is obvious from reading the handler. pprof finds both in a few minutes, and the fixes are three lines each.

Everything ran on Go 1.27.1 inside a Linux container (--cpus 4 -m 1g) on a Mac. The code is on GitHub: huseyinbabal/go-profiling.

The numbers

The handler

var logs = makeLogs(20000)

// recent keeps every search result for the "recent searches" page.
var (
	mu     sync.Mutex
	recent [][]byte
)

func search(w http.ResponseWriter, r *http.Request) {
	q := r.URL.Query().Get("q")
	var out strings.Builder
	for _, line := range logs {
		re := regexp.MustCompile(q)
		if re.MatchString(line) {
			out.WriteString(line)
			out.WriteByte('\n')
		}
	}
	body := []byte(out.String())

	mu.Lock()
	recent = append(recent, body)
	mu.Unlock()

	w.Write(body)
}server/main.go

logs is 20,000 generated log lines held in memory. recent stands in for a feature many services have: a list of the latest results to show on a “recent searches” page. The demo doesn’t serve that page, so only the slice is there, and the handler appends every response to it under mu.

Profiling is switched on with one import:

import _ "net/http/pprof"

The package’s init registers handlers under /debug/pprof/ on http.DefaultServeMux. The blank identifier is there because nothing else from the package is used.

Why a container

The first CPU profiles were taken with the service running natively on macOS. The flame graph was dominated by runtime.usleep, runtime.lock2 and runtime.madvise, and the application code was hard to find. The same binary built with GOOS=linux and run in a distroless container gave a profile where main.search holds about 95% of the samples. If a profile on a Mac looks like it is mostly runtime, try it on Linux before drawing conclusions.

GOOS=linux go build -o bin/server-linux ./server
docker build -t goprof:v1 --build-arg BIN=server .
docker run -d --name goprof -p 9092:9092 --cpus 4 -m 1g goprof:v1

CPU: what a profile is

A CPU profile is a sample. While it runs, the runtime interrupts the program 100 times a second and records the stack of the goroutine that was running. A function’s share of the samples estimates its share of CPU time. Nothing is recorded between samples, so a function that runs for less than 10 ms total may not show up at all.

With k6 putting load on the service:

k6 run -q k6/search.js
go tool pprof -http=:9093 "localhost:9092/debug/pprof/profile?seconds=10"

http_req_duration..............: avg=41.25ms p(95)=66.08ms
http_reqs......................: 1937   96.709389/sk6,

-http opens pprof’s web UI instead of the interactive shell. The top view, sorted by cumulative time:

Flat is time spent in the function’s own code. Cum also counts everything it called. main.search has almost no flat time and 94.6% cum: the handler itself is cheap, the functions under it are not.

Reading the flame graph

The flame graph in pprof’s web UI draws the same samples as boxes, with the root at the top (it hangs down, some call it an icicle graph). Each box is a function and the boxes under it are its callees.

• Width is the share of samples that had the function on the stack.
• Left to right is not time. Boxes are sorted, not placed on a timeline.
• Colour doesn’t measure anything; it groups by package.

So the rule is to look for wide boxes. Under main.search, almost the whole width is regexp.MustCompile, and under that are syntax.Parse, syntax.Compile, mallocgc and growslice. The regex is being parsed and compiled, and a lot of memory is allocated doing it.

The source view (/ui/source?f=main.search) puts the samples next to the lines, and the line is re := regexp.MustCompile(q), inside the loop. Each search compiles the same pattern 20,000 times.

The CPU fix

re, err := regexp.Compile(q)
if err != nil {
	http.Error(w, err.Error(), http.StatusBadRequest)
	return
}
for _, line := range logs {
	if re.MatchString(line) {fixed/main.go

Compiling once also changes what happens with a bad pattern. MustCompile panics; net/http recovers a panic in a handler and closes the connection, so the client gets no response at all. Compile returns an error and the client gets a 400.

http_req_duration..............: avg=3.24ms p(95)=4.27ms
http_reqs......................: 24299  1214.784668/sk6,

Memory: two views of the heap profile

The heap profile is also a sample: by default the runtime records the stack for roughly one allocation per 512 KB allocated (runtime.MemProfileRate). It has two views that answer different questions:

For a leak, inuse_space is the one to read. In the alloc_space view of the buggy service, 16.02 GB had been allocated, almost all of it under regexp.MustCompile: the regex compilation from the CPU section, which becomes garbage almost immediately.

Finding the leak

At a steady 10 searches a second, docker stats showed the container go from 5 MiB at idle to 399 MiB after a minute, still rising.

One heap profile shows where live memory was allocated, but a single snapshot can’t tell you whether that memory is growing or just large. Two profiles a minute apart, with the first passed as -base, can:

k6 run -q k6/steady.js &
curl -s localhost:9092/debug/pprof/heap > heap1.pb.gz
sleep 60
curl -s localhost:9092/debug/pprof/heap > heap2.pb.gz
go tool pprof -http=:9094 -base heap1.pb.gz heap2.pb.gz

pprof subtracts the base, so the graph shows only what was added in between: 179.18 MB, all under main.search. The source view narrows it to one line:

177.41MB   177.41MB   body := []byte(out.String())pprof

A heap profile records where memory was allocated, not who is holding on to it. body is allocated on that line, but it stays alive because of the next one: recent = append(recent, body). Every response goes into a slice for a “recent searches” page and nothing ever removes it. When the profile points at an allocation site, the next question is which reference keeps the result reachable.

The leak fix

mu.Lock()
recent = append(recent, body)
if len(recent) > 50 {
	recent = recent[1:]
}
mu.Unlock()fixed/main.go

With the same 60-second test, memory peaked at 96 MiB and ended at 70 MiB.

recent[1:] keeps the same backing array, and append copies to a new array when it runs out of capacity, so the old array and the responses it points to become garbage on the next growth. For a small, fixed limit like 50 that is fine. For a bigger buffer, a ring buffer avoids the repeated copying.

Can it stay on in production?

Heap profiling is always on. The runtime samples allocations at MemProfileRate whether or not net/http/pprof is imported; the import only adds an HTTP endpoint to read it.

The CPU profiler is idle until asked. It only costs something while a profile is being collected. One pair of k6 runs on the fixed service, first without and then during a 20-second CPU profile:

http_req_duration..............: avg=3.23ms p(95)=4.45ms
http_reqs......................: 24368  1218.166843/sk6,

http_req_duration..............: avg=3.47ms p(95)=4.66ms
http_reqs......................: 22675  1133.49842/sk6,

That pair shows 7% fewer requests. Over four more pairs the profiled run averaged 1.4% fewer, and two plain runs back to back differed by up to 5%, so on this service the cost of a running CPU profile was inside the run-to-run noise. Measure your own service before deciding; this one does almost no I/O.

Other things worth knowing:

• One profile at a time. The Go diagnostics docs note that diagnostics tools can interfere with each other (their example: precise memory profiling skews CPU profiles) and recommend using them in isolation.
• Block and mutex profiles are off by default. They need runtime.SetBlockProfileRate and runtime.SetMutexProfileFraction. Both record events on the hot path (every sampled blocking event or contended lock), so measure the overhead before leaving them on.
• Don’t expose /debug/pprof publicly. The blank import registers on http.DefaultServeMux. If your public server uses that mux, anyone can start a 30-second CPU profile, pull heap profiles, or read /debug/pprof/cmdline, the full command line the process was started with (flags, sometimes secrets). Serve your API on its own http.ServeMux and pprof on a separate port that only your network reaches:

go func() { log.Println(http.ListenAndServe("localhost:6060", nil)) }() // pprof, default mux
api := http.NewServeMux()
api.HandleFunc("/search", search)
log.Fatal(http.ListenAndServe(":9092", api))

• Continuous profiling. The diagnostics docs suggest profiling in production on a schedule: pick a random replica, profile it for a few seconds, store the result, repeat. That keeps the cost on one instance at a time and gives you profiles from before an incident, not only after.

Run it yourself

git clone https://github.com/huseyinbabal/go-profiling && cd go-profiling
GOOS=linux go build -o bin/server-linux ./server
docker build -t goprof:v1 --build-arg BIN=server .
docker run -d --name goprof -p 9092:9092 --cpus 4 -m 1g goprof:v1
k6 run -q k6/search.js &
go tool pprof -http=:9093 "localhost:9092/debug/pprof/profile?seconds=10"

The README has the heap steps and the fixed build.

Sources

• Go diagnostics: profiling
• Package net/http/pprof
• Package runtime/pprof
• runtime.MemProfileRate
• pprof README: web interface and flame graph
• Code on GitHub: huseyinbabal/go-profiling