How to read a flame graph without guessing

Most people’s first flame graph looks like a city skyline drawn by a toddler, and they close it. That is a shame, because once you know the three rules for reading one, it is the fastest way I know to answer “where is the CPU time going?”

This post uses a regression from our API gateway, written in Go. After a release, CPU per request went up by about 30% and p99 latency followed. The diff was 2,000 lines. The flame graph found the problem in about four minutes.

Getting a profile from a Go service

Go ships a sampling CPU profiler in the standard library. Importing net/http/pprof registers its handlers on the default mux. We serve that on a separate, internal-only port:

// imports: "log", "net/http" and the blank import _ "net/http/pprof"
func startDebugServer() {
	go func() {
		// never expose this port publicly
		log.Println(http.ListenAndServe("localhost:6060", nil))
	}()
}

Then capture 30 seconds of CPU samples while the service is under real load, and open the interactive viewer:

curl -s -o cpu.pprof "http://localhost:6060/debug/pprof/profile?seconds=30"
go tool pprof -http=:8081 cpu.pprof   # then View -> Flame Graph in the browser

The profiler interrupts the program about 100 times a second and records the current call stack. A flame graph is those stacks merged and drawn as boxes.

The three rules

Width is the share of samples, not time order. A box that spans 40% of the width means that function, including everything it called, was on the stack in 40% of the samples. The horizontal position means nothing: boxes are sorted alphabetically, not chronologically. This is the one people get wrong most often.

Vertical is call depth. Each box sits on top of its caller. Go’s pprof viewer draws the root at the top and grows downward, which some people call an icicle graph. The logic is identical either way.

Colour is decoration. In most viewers it groups by package or is simply random. Do not read meaning into a red box.

What to look for

With those rules, the reading technique is straightforward. Start at the root, follow the widest path downward, and look for a plateau: a wide box with little or nothing underneath it. Nothing underneath means the time is spent in that function itself, its “self” time, rather than in anything it calls.

Wide boxes with many thin children are usually fine. That is ordinary work spread across many callees. Wide boxes with a flat bottom are where to look.

Our profile had one. Under the request handler, a box for validateHeaders took 31% of the width, and directly beneath it sat regexp.MustCompile, nearly as wide, with only parsing internals below.

The fix

Someone had moved header validation into a helper during a refactor, and the pattern was compiled inside the function, on every request:

+var tenantHeader = regexp.MustCompile(`^[a-z0-9-]{3,40}$`)
+
 func validateHeaders(h http.Header) error {
-	tenantHeader := regexp.MustCompile(`^[a-z0-9-]{3,40}$`)
 	if !tenantHeader.MatchString(h.Get("X-Tenant")) {
 		return errBadTenant
 	}
 	return nil
 }

Compiling a regular expression is far more expensive than matching one. Hoisting it to a package-level variable compiles it once at startup. A compiled *regexp.Regexp is safe for concurrent use, so sharing it is fine. CPU per request went back to its previous level, and the box vanished from the next profile.

When the flame graph is the wrong tool

A CPU profile only sees time spent on the CPU. If your requests are slow because they are waiting on a database, a lock or the network, the flame graph will look healthy and tell you nothing. For that, use the block and mutex profiles from the same pprof endpoint, or a trace. The habit worth keeping is to profile before you guess, and to save the profile alongside the pull request that fixes the problem.