scrobble.life
StemSocial

Learn Go Series (#18) - Benchmarking, the Race Detector, and Profiling with pprof

scipio@scipio (72)41d

Learn Go Series (#18) - Benchmarking, the Race Detector, and Profiling with pprof

go-banner.png

What will I learn

  • How to write a benchmark with go test -bench and read its ns/op and B/op numbers;
  • b.ReportAllocs and b.ResetTimer, so your measurement is honest;
  • The race detector (-race): what a data race is, and how the tool finds the exact racing accesses;
  • CPU and memory profiling with pprof, and how to read a profile to find the hot line;
  • The golden rule that ties it together: measure before you optimise;
  • Why these tools live right inside go test, no external setup.

Requirements

  • A working modern computer running macOS, Windows or Ubuntu;
  • An installed Go distribution (1.27 or newer, from go.dev/dl) -- tested against Go 1.27;
  • Episode 17 (testing) especially, plus the concurrency episodes 13-14 for the race section;
  • The ambition to learn Go programming.

Difficulty

  • Intermediate

Curriculum (of the Learn Go Series):

Learn Go Series (#18) - Benchmarking, the Race Detector, and Profiling with pprof

Last episode we made code correct; this episode we make it fast -- but only after measuring, never before. That ordering is not a slogan I am padding the intro with, it is the single most important habit in the whole episode, and it matches good engineering everywhere: do not guess where the time goes, measure it, fix what the numbers actually show, and then measure again to prove you helped. Every developer has a story about the day they spent an afternoon optimising a function that turned out to account for 0.3% of the runtime while the real hog sat untouched two files over. The tools in this episode exist so that story stops being yours.

And here is the lovely part, very much in keeping with everything this series has said about Go: the tools live right inside go test. There is no separate profiler to install, no external benchmark harness, no third-party race checker bolted on. Benchmarks that give you nanoseconds-per-operation and allocations-per-operation, a race detector that finally hunts down the concurrency bugs we kept warning about back in episodes 13 and 14, and CPU and memory profilers that point at the exact hot line -- all of it ships in the toolchain you already have. That "it is just there" quality is easy to undervalue until you have fought with the alternative in another language. First, though, as always, last episode's exercises.

Solutions to Episode 17 Exercises

Exercise 1 -- table-test IsPalindrome:

package strutil

import "testing"

func IsPalindrome(s string) bool {
	r := []rune(s)
	for i, j := 0, len(r)-1; i < j; i, j = i+1, j-1 {
		if r[i] != r[j] {
			return false
		}
	}
	return true
}

func TestIsPalindrome(t *testing.T) {
	cases := []struct {
		name string
		in   string
		want bool
	}{
		{"empty", "", true},
		{"single", "x", true},
		{"palindrome", "level", true},
		{"not", "hello", false},
	}
	for _, c := range cases {
		t.Run(c.name, func(t *testing.T) {
			if got := IsPalindrome(c.in); got != c.want {
				t.Errorf("IsPalindrome(%q) = %t; want %t", c.in, got, c.want)
			}
		})
	}
}

Exercise 2 -- Reverse with a helper that reports correctly:

package sliceutil

import (
	"fmt"
	"testing"
)

func Reverse(s []int) []int {
	out := make([]int, len(s))
	for i, v := range s {
		out[len(s)-1-i] = v
	}
	return out
}

func assertSlicesEqual(t *testing.T, got, want []int) {
	t.Helper()
	if fmt.Sprint(got) != fmt.Sprint(want) {
		t.Errorf("got %v; want %v", got, want)
	}
}

func TestReverse(t *testing.T) {
	assertSlicesEqual(t, Reverse([]int{1, 2, 3}), []int{3, 2, 1})
	assertSlicesEqual(t, Reverse([]int{}), []int{})
}

Exercise 3 -- Fatal for setup, Error for checks:

package store

import "testing"

func NewStore() map[string]int {
	return map[string]int{"a": 1, "b": 2}
}

func TestStore(t *testing.T) {
	s := NewStore()
	if s == nil {
		t.Fatal("NewStore returned nil; cannot check contents") // precondition: stop
	}
	if s["a"] != 1 {
		t.Error("expected a == 1") // independent check: keep going
	}
	if len(s) != 2 {
		t.Error("expected length 2")
	}
}

Now, measuring.

Writing a benchmark

A benchmark is func BenchmarkXxx(b *testing.B) in a _test.go file. The framework runs your loop b.N times, choosing b.N automatically to get a statistically stable measurement, then reports the time per operation. You run benchmarks with go test -bench=. (they do not run under a plain go test):

package strutil

import (
	"strings"
	"testing"
)

func Repeat(s string, n int) string {
	var b strings.Builder
	for i := 0; i < n; i++ {
		b.WriteString(s)
	}
	return b.String()
}

// The framework runs the body b.N times and picks b.N for a stable measure.
func BenchmarkRepeat(b *testing.B) {
	for i := 0; i < b.N; i++ {
		_ = Repeat("go", 100)
	}
}

Run it and you get a line like BenchmarkRepeat-8 3000000 410 ns/op, meaning "on 8 CPUs, it ran three million times, averaging 410 nanoseconds per call". Notice you never wrote the loop count 3000000 yourself -- that is b.N, and the framework picks it for you. It starts small, times the run, and keeps scaling b.N up until the total run is long enough to be statistically stable rather than lost in timer noise. This is why you must loop b.N times exactly and not hard-code your own count: you are handing the framework the knob it needs to turn. A benchmark that runs its body a fixed number of times is not measuring anything Go can trust.

The _ = in front of the call matters more than it looks like it should. Assigning the result to the blank identifier stops the compiler from noticing that nobody uses the return value, deciding the whole call is dead code, and optimising it clean away -- at which point you would be proudly benchmarking an empty loop and reporting nonsense. This is the number-one beginner benchmarking mistake in every compiled language, and Go's optimiser is aggressive enough to bite you. Having said that, for cases where even the _ = is not enough to fool the compiler, Go provides a package-level sink variable (assign into a var result string declared outside the function) as the belt-and-braces version. For most benchmarks the blank identifier is plenty.

Comparing two implementations

Benchmarks earn their keep when comparing approaches. Here are the two string-concatenation strategies from episode 7 -- += in a loop versus strings.Builder -- each with its own benchmark, so go test -bench=Concat prints both and you can see the difference directly:

package strutil

import (
	"strings"
	"testing"
)

func concatPlus(parts []string) string {
	s := ""
	for _, p := range parts {
		s += p // reallocates the whole string each iteration
	}
	return s
}

func concatBuilder(parts []string) string {
	var b strings.Builder
	for _, p := range parts {
		b.WriteString(p)
	}
	return b.String()
}

var parts = strings.Fields(strings.Repeat("x ", 200))

func BenchmarkConcatPlus(b *testing.B) {
	for i := 0; i < b.N; i++ {
		_ = concatPlus(parts)
	}
}

func BenchmarkConcatBuilder(b *testing.B) {
	for i := 0; i < b.N; i++ {
		_ = concatBuilder(parts)
	}
}

Run both and the Builder version wins by a wide margin on longer inputs, and -- this is the part that matters -- the gap grows with the size of the input. That growth is the fingerprint of a difference in algorithmic complexity, not just a constant-factor tweak. Back in episode 7 I claimed that += in a loop is quadratic (each += copies the entire string built so far, so building an n-part string does work proportional to n squared) while strings.Builder is linear (it grows a backing buffer and appends into it). At the time you had to take my word for it. Now you do not: run the benchmark at 200 parts, then at 2000, and watch the concatPlus time explode roughly a hundredfold while concatBuilder grows only tenfold. That is the difference between n-squared and n, measured, on your own machine, in about ten seconds.

This is the whole value of a benchmark: it turns "I think this is faster" into "here are the two ns/op figures, and here is how they scale". Opinions about performance are cheap and frequently wrong -- even experienced developers guess badly, because modern CPUs, caches, and compilers are far too subtle to reason about from an armchair. A benchmark is how you stop arguing and start knowing.

Allocations: ReportAllocs and ResetTimer

Speed is often really about allocations -- every heap allocation is future work for the garbage collector. b.ReportAllocs() adds allocations-per-operation and bytes-per-operation to the output, which is frequently more revealing than raw time. And b.ResetTimer() discards any expensive setup you did before the loop, so it does not pollute the measurement:

package strutil

import (
	"strings"
	"testing"
)

func BenchmarkFields(b *testing.B) {
	data := strings.Repeat("word ", 1000) // setup we do NOT want to measure
	b.ResetTimer()                         // start the clock here
	b.ReportAllocs()                       // also report allocs/op and B/op

	for i := 0; i < b.N; i++ {
		_ = strings.Fields(data)
	}
}

With -benchmem (or b.ReportAllocs()), the output gains columns like 128 B/op 3 allocs/op -- 128 bytes and 3 separate heap allocations per call. Why do you care about allocations when the ns/op number is right there? Because in a garbage-collected language, allocation is a hidden, deferred cost. Every object you put on the heap is future work for the collector, and that work does not show up cleanly in a micro-benchmark's time-per-op; it shows up later, as GC pauses, as CPU spent scanning and freeing, as the mysterious latency spikes in a busy server. Reducing allocs/op is very often the single clearest signal that an optimisation is real, and it is frequently more revealing than the raw time. When you rewrite a function and the allocations drop from 12/op to 2/op, you have done something that will pay off under production load even if the micro-benchmark barely moved.

b.ResetTimer() earns its place for a different reason: honesty. If you do expensive setup before the loop -- building a big slice, reading a fixture, constructing a thousand-element map -- and you do NOT reset the timer, that one-time setup cost gets amortised into your per-operation number and quietly poisons it. b.ResetTimer() says "the clock starts here", after the setup, so you measure only the thing you meant to measure. There is a sibling, b.StopTimer()/b.StartTimer(), for when you need to do per-iteration setup inside the loop that should not be counted. Both are small disciplines, and both are the difference between a number you can trust and a number that merely looks precise.

The race detector

A data race is two goroutines accessing the same memory concurrently with at least one writing, and no synchronisation. The result is undefined -- wrong answers, intermittently, the worst kind of bug. Go's race detector finds them: build or test with -race and it instruments memory accesses and reports the exact racing lines. Here is a program with a race baked in:

package main

import (
	"fmt"
	"sync"
)

func main() {
	count := 0 // shared, unsynchronised
	var wg sync.WaitGroup
	for i := 0; i < 1000; i++ {
		wg.Add(1)
		go func() {
			defer wg.Done()
			count++ // DATA RACE: concurrent read-modify-write, no lock
		}()
	}
	wg.Wait()
	fmt.Println("count:", count) // often < 1000, unpredictably
	// Run `go run -race .` and it reports the racing accesses with both stacks.
}

Run this normally and count is usually a bit under 1000, and it varies every single run -- a silent wrong answer, with no crash, no error, nothing to tell you the number is a lie. The reason is that count++ is not one indivisible step; it is read-count, add-one, write-count, and two goroutines can interleave those steps so that updates get lost. This is exactly the class of bug I called the worst kind back in the concurrency episodes: it is intermittent, it depends on timing and CPU load, and it will pass a thousand tests on your quiet laptop and then corrupt data the first busy afternoon in production. You cannot reliably find these by staring at code, and you certainly cannot find them by testing harder.

The race detector changes the game entirely. Build or test with -race and Go instruments every memory access, tracking which goroutine touched which address and whether the accesses were properly ordered by a lock, channel, or other synchronisation. Run the program above with go run -race . and instead of a plausible-looking wrong number you get a loud, unmissable "DATA RACE" report: it names both goroutines, prints both stack traces, and points at the exact line, count++. It does not merely tell you a race exists -- it tells you where, which is 90% of the battle. The fix is the sync.Mutex or the sync/atomic operations from episode 14: guard the shared counter, or use atomic.AddInt64, and the race vanishes. The one habit to internalise from this whole section: run go test -race ./... routinely, ideally in CI on every push. The detector has a real cost (it slows execution several times over and uses more memory, so it is not for production builds), but as a gate on your tests it is nearly free insurance against the nastiest bugs Go can produce.

Profiling with pprof

When a real program is slow, you profile it to find where the time actually goes -- because your guess is usually wrong. go test can emit CPU and memory profiles, and go tool pprof reads them interactively:

# capture a CPU profile while running a benchmark
go test -bench=. -cpuprofile=cpu.out

# capture a memory (allocation) profile
go test -bench=. -memprofile=mem.out

# explore a profile: `top` for the hottest functions, `list Func` for line-by-line
go tool pprof cpu.out
#   (pprof) top10
#   (pprof) list concatPlus
#   (pprof) web        # a visual graph, if graphviz is installed

top shows the functions where the program spent the most time, ranked, so the worst offender is right at the top of the list. list <function> then annotates that function's source line by line with the cost attributed to each line, so you do not just learn which function is slow, you learn which statement inside it -- and it is very often not the one you would have bet on. That gap between where you think the time goes and where it actually goes is the entire reason profilers exist. The web command draws a visual call graph (if you have graphviz installed) where box size and edge thickness show cost, which is wonderful for seeing at a glance how time flows through a bigger program.

Profiling is not only for benchmarks, either. For a long-running server you import net/http/pprof (it registers handlers on your HTTP mux as a side effect of the import) and then grab a live CPU or heap profile from the running process with go tool pprof http://localhost:6060/debug/pprof/profile -- profiling the real thing under real load, which is the gold standard. Whichever way you capture it, the workflow is always the same shape, and it is the shape this whole episode keeps drawing: measure to find the hot spot, fix that hot spot and nothing else, then measure again to confirm you actually helped and did not just move the problem. Optimising a line the profiler did not point at is not engineering, it is superstition -- you are changing code and hoping. The profiler is how you stop hoping. NB: profile-guided optimisation (feeding a real profile back into the compiler with -pgo) takes this idea one step further and lets the compiler itself make better inlining decisions from your production profile, but that is a topic for the day we do performance engineering properly.

The same idea in Python

Python has timeit for micro-benchmarks and cProfile for profiling, but no built-in race detector -- because the GIL prevents true parallel execution of Python bytecode, so classic data races on Python objects are largely a non-issue (and also why Python cannot use threads for CPU parallelism):

import timeit

setup = "parts = ['x'] * 200"
plus = "s=''\nfor p in parts: s += p"
join = "''.join(parts)"

print("plus:", timeit.timeit(plus, setup, number=100000))
print("join:", timeit.timeit(join, setup, number=100000))

timeit is Python's benchmark and shows the same "join beats repeated +=" lesson we proved in Go a moment ago. Go's advantage is integration and scope: benchmarks, allocation reporting, a race detector, and CPU/memory profiling all live inside go test in stead of scattered across a handful of third-party tools, and Go's true parallelism makes the race detector genuinely necessary and genuinely valuable in a way it simply is not under the GIL. Same instinct in both languages, though -- measure first, optimise second ;-)

Exercises

  1. Benchmark two search strategies. Write containsLinear([]int, int) bool and, for a pre-sorted slice, containsBinary([]int, int) bool. Benchmark both on a large slice searching for a missing value, and predict which wins before you run go test -bench=..

  2. Catch a race. Write a program where several goroutines append to a shared []int with no lock, run it with go run -race ., and read the report. Then fix it with a sync.Mutex and confirm -race is now clean. Note in a comment what the race report told you.

  3. Profile a hot function. Write a benchmark for a deliberately wasteful function (say, building a big string with +=), capture a CPU profile with -cpuprofile, open it with go tool pprof, and use top and list to find the hottest line. Write two sentences on what the profiler showed.

What we learned

  • A benchmark is func BenchmarkXxx(b *testing.B) looping b.N times, run with go test -bench=., reporting ns/op -- assign results to _ so the compiler cannot optimise the work away;
  • b.ReportAllocs()/-benchmem add allocs/op and B/op (often the more revealing numbers), and b.ResetTimer() excludes setup from the measurement;
  • A data race is unsynchronised concurrent access with a writer; -race instruments your program and reports the exact racing lines -- run go test -race ./... routinely;
  • pprof finds where time and memory actually go: capture with -cpuprofile/-memprofile, explore with go tool pprof (top, list, web), and fix only the hot spot it identifies;
  • The governing rule is measure before you optimise -- profile, fix the line the numbers point at, then measure again to confirm;
  • All of this lives inside go test with no external setup, which is why Go's performance culture is unusually empirical.

Next episode we take a guided tour of the standard library -- io, bufio, os, time, and the corners of fmt -- the batteries Go ships with that mean you reach for a third-party package far less often than you might expect. See you there.

Bedankt en tot de volgende keer! ;-)

@scipio

Comments

No comments yet — be the first.