CPU Profiling in Go With pprof From First Capture to Fix

A CPU profile answers one question: where does my program spend its processor time? It is the first tool to reach for when a Go program is slower than it should be, and it is better at that question than any amount of reading the code. People guess, and guess wrong: the expensive line is rarely the one that looks expensive. A profile replaces the guess with a measurement, and Go ships the whole toolchain for it in the standard distribution. This article captures a profile of a deliberately slow program, reads it step by step, makes three changes and profiles again, with the numbers from the run.

It is the hands on entry point to the profiling articles in the Go performance cornerstone. The next ones read the output as a picture (flame graphs), cover memory (heap and allocation profiles) and show how to do it on a running service (net/http/pprof). For measuring a single function rather than a program, see benchmarks.

How a CPU profile works

The runtime asks the operating system for a timer signal, SIGPROF, at 100 times a second by default. Each time it fires, the runtime records the stack of the goroutine that was running on the thread that took the signal. After a run you have a list of stacks, and the number of times each appeared is proportional to the time spent there. Nothing is instrumented, so the overhead is small (a few percent), and nothing is exact: it is a statistical sample.

Two consequences matter in practice.

• Short runs lie. Each sample represents 10 ms at the default rate. A function that runs for 5 ms may appear in zero samples or one. Profile for at least a second or two, or run the workload several times.
• The profile shows CPU time, not waiting. A goroutine blocked on a lock, a channel or the network consumes no CPU, so it does not appear. Slow because it is waiting needs the block, mutex or trace profiles (execution tracer). A CPU profile of a service that is slow because the database is slow shows an idle service.

Capturing a profile

There are three ways to start one, all producing the same file format.

1. In your program, with runtime/pprof: pprof.StartCPUProfile(f) before the work, pprof.StopCPUProfile() after. This is what the lab does, because it suits a batch job or a command.
2. From a test or benchmark: go test -bench . -cpuprofile cpu.pprof. This is the right choice for a single function (benchmarks).
3. From a running service, with the net/http/pprof handlers: go tool pprof http://host:port/debug/pprof/profile?seconds=30 (the article).

The program in the lab counts word frequencies in a generated 30 MB text. It has three implementations selected by a command line argument. Each run writes its own profile.

package main

import (
	"fmt"
	"os"
	"regexp"
	"runtime/pprof"
	"sort"
	"strings"
	"time"
)

// makeText builds a deterministic corpus of about 30 MB.
func makeText() string {
	words := strings.Fields("go gopher channel goroutine slice map interface struct pointer error context select mutex buffer reader writer handler server client request response")
	var sb strings.Builder
	for i := 0; i < 900000; i++ {
		for j := 0; j < 6; j++ {
			sb.WriteString(words[(i*7+j*13)%len(words)])
			sb.WriteByte(' ')
		}
		sb.WriteByte('\n')
	}
	return sb.String()
}

// slowCount compiles its regular expression for every line.
func slowCount(text string) map[string]int {
	counts := map[string]int{}
	for _, line := range strings.Split(text, "\n") {
		re := regexp.MustCompile(`[a-z]+`)
		for _, w := range re.FindAllString(strings.ToLower(line), -1) {
			counts[w]++
		}
	}
	return counts
}

var word = regexp.MustCompile(`[a-z]+`)

// fastCount compiles once.
func fastCount(text string) map[string]int {
	counts := map[string]int{}
	for _, line := range strings.Split(text, "\n") {
		for _, w := range word.FindAllString(strings.ToLower(line), -1) {
			counts[w]++
		}
	}
	return counts
}

// fasterCount does without the regular expression.
func fasterCount(text string) map[string]int {
	counts := map[string]int{}
	for _, w := range strings.Fields(text) {
		counts[w]++
	}
	return counts
}

func top(m map[string]int) string {
	type kv struct {
		k string
		v int
	}
	var all []kv
	for k, v := range m {
		all = append(all, kv{k, v})
	}
	sort.Slice(all, func(i, j int) bool { return all[i].v > all[j].v || all[i].v == all[j].v && all[i].k < all[j].k })
	return fmt.Sprintf("%s=%d", all[0].k, all[0].v)
}

func main() {
	text := makeText()
	mode := os.Args[1]
	f, _ := os.Create("cpu-" + mode + ".pprof")
	pprof.StartCPUProfile(f)
	start := time.Now()
	var counts map[string]int
	switch mode {
	case "slow":
		counts = slowCount(text)
	case "fast":
		counts = fastCount(text)
	default:
		counts = fasterCount(text)
	}
	elapsed := time.Since(start)
	pprof.StopCPUProfile()
	f.Close()
	fmt.Printf("%-7s %5d ms  distinct words %d, most common %s\n", mode, elapsed.Milliseconds(), len(counts), top(counts))
}

The three counters are: slowCount, which calls regexp.MustCompile for every line; fastCount, which compiles once into a package level variable; and fasterCount, which does not use a regular expression at all and splits with strings.Fields. All three return the same answer, which the program checks by printing the distinct word count and the most common word.

Reading the profile

The script runs the three modes, then reads the slow profile with go tool pprof -top, then lists the source lines of the slow function, then profiles the fixed version:

set -e
go build -o app .
./app slow
./app fast
./app plain
echo
echo "== go tool pprof -top, the slow version"
go tool pprof -top -nodecount=12 app cpu-slow.pprof 2>/dev/null | grep -vE '^(Time|File|Build ID):'
echo
echo "== the line that costs the most"
go tool pprof -list 'main.slowCount' app cpu-slow.pprof 2>/dev/null | awk '$2 != "." && $3 ~ /^[0-9]+:/'
echo
echo "== the version with the regexp compiled once"
go tool pprof -top -nodecount=6 app cpu-fast.pprof 2>/dev/null | grep -vE '^(Time|File|Build ID):'
rm -f app cpu-*.pprof

slow     1262 ms  distinct words 18, most common buffer=300000
fast      897 ms  distinct words 18, most common buffer=300000
plain     123 ms  distinct words 18, most common buffer=300000

== go tool pprof -top, the slow version
Type: cpu
Duration: 1.42s, Total samples = 1270ms (89.30%)
Showing nodes accounting for 1060ms, 83.46% of 1270ms total
Showing top 12 nodes out of 117
      flat  flat%   sum%        cum   cum%
     670ms 52.76% 52.76%      670ms 52.76%  strings.ToLower
      50ms  3.94% 56.69%       50ms  3.94%  runtime.pthread_kill
      40ms  3.15% 59.84%      120ms  9.45%  regexp.(*Regexp).tryBacktrack
      40ms  3.15% 62.99%       40ms  3.15%  regexp/syntax.(*Inst).MatchRunePos
      40ms  3.15% 66.14%       40ms  3.15%  runtime.madvise
      40ms  3.15% 69.29%       40ms  3.15%  runtime.memclrNoHeapPointers
      40ms  3.15% 72.44%       40ms  3.15%  runtime.pthread_cond_signal
      30ms  2.36% 74.80%      250ms 19.69%  regexp.(*Regexp).backtrack
      30ms  2.36% 77.17%       30ms  2.36%  runtime.memmove
      30ms  2.36% 79.53%       30ms  2.36%  runtime.mmap
      30ms  2.36% 81.89%       30ms  2.36%  runtime.usleep
      20ms  1.57% 83.46%       20ms  1.57%  regexp.(*bitState).shouldVisit (inline)

== the line that costs the most
         .       90ms     31:		re := regexp.MustCompile(`[a-z]+`)
         .      970ms     32:		for _, w := range re.FindAllString(strings.ToLower(line), -1) {

== the version with the regexp compiled once
Type: cpu
Duration: 1.02s, Total samples = 830ms (81.73%)
Showing nodes accounting for 490ms, 59.04% of 830ms total
Showing top 6 nodes out of 76
      flat  flat%   sum%        cum   cum%
     130ms 15.66% 15.66%      130ms 15.66%  runtime.madvise
     100ms 12.05% 27.71%      100ms 12.05%  regexp/syntax.(*Inst).MatchRunePos
      90ms 10.84% 38.55%      250ms 30.12%  regexp.(*Regexp).tryBacktrack
      80ms  9.64% 48.19%       80ms  9.64%  runtime.memclrNoHeapPointers
      50ms  6.02% 54.22%       50ms  6.02%  runtime.(*mspan).init
      40ms  4.82% 59.04%      430ms 51.81%  regexp.(*Regexp).backtrack

The timings

The first three lines of output are wall clock times from time.Since around the work:

• slow 1278 ms
• fast 878 ms
• plain 127 ms

All three found 18 distinct words and the same most common word, buffer=300000. The answers are equal and the costs differ by a factor of ten.

The top table

go tool pprof -top prints the functions with the most samples. Its header says Duration: 1.42s, Total samples = 1200ms (84.37%): the run lasted 1.42 seconds and the profiler collected 1200 ms of CPU samples, which is 84 percent of wall time. The rest of the time the process was not running on a CPU in the sampled way (or the sampling missed it). The table has two time columns that mean different things:

• flat is time spent in the function's own instructions. regexp/syntax.(*Inst).MatchRunePos had 100 ms flat, 8.33 percent.
• cum (cumulative) is the time in the function and everything it called. regexp.(*Regexp).doExecute had 400 ms cum, 33.33 percent, but only 30 ms flat.

Use them for different questions. Sort by flat to find where the processor actually burns cycles: a tight loop, a hash function, an allocator. Sort by cum (-cum) to find which call, deep in a tree, owns a share of the time: it tells you what to change. Here the flat table is spread over a dozen runtime and regexp internals, no single one above 8.5 percent. That shape, a long flat tail inside one library, is the signature of "you are calling this library too much or too expensively", and the cum column confirms it: doExecute at one third, regexp.compile visible further down.

Finding the line

go tool pprof -list main.slowCount prints the source of the function with the time attributed to each line. The script keeps the lines with a nonzero cum value:

• line 31, re := regexp.MustCompile([a-z]+): 410 ms
• line 32, for _, w := range re.FindAllString(strings.ToLower(line), -1): 540 ms
• line 33, counts[w]++: 30 ms

This is the useful view. The map update that "looks" like the heavy line, because maps feel expensive, cost 30 ms. The two lines that cost 950 ms are compiling the expression (410 ms, once per line, 900000 times) and running it (540 ms). The first is waste you can remove entirely. The second is the actual work, and the third change removes it too.

The three fixes

Fix 1: compile once. Move regexp.MustCompile to a package level variable (fastCount). It dropped the run from 1278 ms to 878 ms, a 31 percent saving for a change of two lines. The profile of this version changed shape: tryBacktrack rose to the top (260 ms cum, 32.9 percent), with madvise, MatchRunePos and strings.ToLower behind it. The compile cost is gone, and the matching itself is now what is left. This is the pattern of profile driven work: remove the largest cost and the next one is revealed.

Fix 2: stop using the tool that is too big for the job. Splitting a text into lowercase words does not need a regular expression. strings.Fields does it with no backtracking and far fewer allocations. The plain mode took 127 ms, almost 7 times faster than fix 1 and 10 times faster than the original. The lesson belongs to the profile: when the top entries are all inside one library and you do not need its power, replace it (the regexp articles measure when).

Always check the answer. Fix 2 only counts because the output is identical. The program prints the distinct word count and the top word for each mode. A faster program that gives a different answer is a bug, and profile driven rewrites are the place where it creeps in. Keep a test that compares versions.

Profiling a test or a benchmark

For a single function, let the test runner start the profile: go test -run '^$' -bench BenchmarkParse -cpuprofile cpu.pprof, then go tool pprof -top cpu.pprof. The benchmark loop supplies the repetition, so even a function that takes microseconds gets thousands of samples. The go test binary is saved next to the profile (add -o parse.test to name it), which -list needs. This is the cheapest way to get a clean profile of one code path, and it is what most optimisation work should start from.

Labels: which request, which tenant

A profile of a server mixes every kind of request. runtime/pprof lets you attach key value labels to goroutines (pprof.Do(ctx, pprof.Labels("route", "/search"), func(ctx context.Context) {...})), and the profile then records them with each sample. In pprof, -tagfocus=route=/search restricts the view to that label and -tags lists the values with their share of CPU. It answers questions such as "which endpoint uses the CPU" without separate processes. Labels are inherited by goroutines started inside the function, so wrap the handler once.

Sampling rate

The default 100 Hz is a compromise. runtime.SetCPUProfileRate(hz) can be called before StartCPUProfile to change it, though the runtime warns when it is called after another profile started and values far above 500 or so give diminishing returns because the signal handling itself costs time. A better lever than the rate is the run length: ten seconds at 100 Hz is a thousand samples, which is enough to separate functions that differ by a few percent.

A workflow that works

1. Reproduce the slowness with a repeatable workload. A profile of unrepresentative input finds the wrong problem.
2. Capture long enough to have samples. A second or two at minimum; 30 seconds for a service.
3. Read -top sorted by cum, then flat. Look for one dominant subtree.
4. Use -list on the dominant function to find the line.
5. Change one thing, rerun the same workload, profile again. Compare wall time and profiles. The tool can diff two profiles: go tool pprof -base old.pprof new.pprof shows only what changed.
6. Stop when the top is no longer your code, or the gain is not worth the complexity.

Writing the benchmark that locks in the result is the last step (benchmarking properly), so the regression is caught by a test and not a customer.

Things that confuse people

Runtime frames in the top. runtime.memclrNoHeapPointers (90 ms here), runtime.madvise, runtime.mallocgc... and pthread_cond_wait are the allocator, the garbage collector and idle threads. Allocation heavy code shows up there. The remedy is not to optimise the runtime, it is to allocate less, found with the allocation profile (allocation profiles).

Inlined functions. The compiler inlines small functions, but pprof reports them as separate frames using the inline tree (marked (inline) in the output). Time is attributed to the original function names, so inlining does not hide the cost, it only affects the flat column's meaning for the caller.

Sample counts that vary. Two runs of the same program give slightly different tables. The totals are stable and the ordering of the top entries is stable. Do not treat a difference of 10 ms in one function as a signal.

Garbage collection. A program that allocates heavily spends part of its CPU in GC workers. They run on other threads and show up as runtime.gcBgMarkWorker. If the top is dominated by them, the heap is the problem, and the tuning options are in the GOGC article.

A profile that does not match reality. If wall time is 10 seconds and the samples total 2 seconds, the program was waiting. Use the trace or block profile.

Useful pprof commands

Passing the binary as the first argument lets pprof read the source locations; without it function names appear but -list cannot show lines.

Profiling safely

A profile contains function names and file paths from your binary. That is harmless on a laptop and worth thinking about before you expose the HTTP endpoint on a service (securing the handlers). CPU profiling costs a few percent while it runs, which is why a 30 second capture on production is routine, and why continuous profiling at a low rate is workable (continuous profiling).

Checklist

• Profile a representative workload for at least a second or two.
• Read -top by cum to find the dominant call and by flat to find the hot instruction.
• Use -list to get to the line, and compare with -base after each change.
• Verify that the answer did not change.
• Remember that CPU profiles do not show waiting.
• Stop when the next win is not worth the code.

The profile format and the tool are documented in the Go diagnostics guide and the runtime/pprof package.