Benchmarking and Profiling

The idea in one minute#

A benchmark answers “how fast is this function?” by running it enough times to get a stable number. A profile answers “where does the time (or memory) go in the whole program?” by sampling it while it runs. You need both: profiles to find what to improve, benchmarks to prove that a change did improve it.

The discipline matters more than the tools. Measure before changing anything, change one thing, measure again with enough repetitions to tell signal from noise, and keep the change only if the numbers moved.

An analogy#

A stopwatch and a time-lapse camera. The stopwatch times one runner over a set distance — a benchmark. The camera, taking a frame every second across the whole stadium, shows where everyone actually spends the day — a profile. Timing a runner tells you nothing about why the queue at the gate is long.

A picture#

flowchart TB
  OBS["Observation:<br/>slow, or memory-hungry"] --> PROF["Profile under realistic load<br/>CPU, heap, block, mutex, trace"]
  PROF --> HOT["Hot spot found:<br/>one function, one allocation site"]
  HOT --> BENCH["Write a benchmark that isolates it<br/>go test -bench -benchmem -count=10"]
  BENCH --> BASE["Save the baseline"]
  BASE --> CHG["Change ONE thing"]
  CHG --> AGAIN["Benchmark again"]
  AGAIN --> STAT{"benchstat:<br/>significant?"}
  STAT -->|"no"| CHG
  STAT -->|"yes"| KEEP["Keep it. Profile again:<br/>the hot spot has moved"]
  KEEP --> PROF
  class OBS neutral
  class PROF,BENCH,AGAIN compute
  class HOT,BASE memory
  class CHG,STAT queue
  class KEEP neutral

How it really works#

Writing a benchmark#

func BenchmarkDot(b *testing.B) {
    x, y := make([]float32, 1024), make([]float32, 1024)   // setup: not timed
    for b.Loop() {                                          // Go 1.24+
        sink = Dot(x, y)
    }
}

b.Loop() runs the body until the timing is stable, excludes setup before the loop, and keeps the compiler from optimizing the body away. The older form — for i := 0; i < b.N; i++ — still works and is what the runnable programs in this course use so that they build with Go 1.22.

go test -bench=Dot -benchmem -count=10 -run='^$' ./... | tee new.txt

The ways a benchmark lies#

benchstat old.txt new.txt (from golang.org/x/perf) compares two runs and reports the change with a confidence interval — or “~” when the difference is not statistically significant. A result without it is an anecdote.

Profiles#

import _ "net/http/pprof"          // adds /debug/pprof/* to the default mux
go http.ListenAndServe("localhost:6060", nil)

go tool pprof -http=: http://localhost:6060/debug/pprof/profile?seconds=30   # CPU
go tool pprof -http=: http://localhost:6060/debug/pprof/heap                 # memory
go tool pprof -http=: cpu.out                                               # from a file

Reading pprof:

• flat = time in the function itself. cum = time in it and everything it calls.
• top, list FuncName (source with per-line cost), web/flame graph, peek.
• -diff_base=old.prof shows what changed between two profiles.
• Look for the runtime in a CPU profile: runtime.mallocgc, runtime.gcBgMarkWorker, runtime.scanobject mean allocation and GC cost (module III); runtime.futex/pthread_cond and runtime.schedule mean contention or too many wake-ups (module IV).

The execution tracer#

A profile aggregates; a trace records every event with a timestamp: goroutines starting, blocking, being scheduled; GC phases; system calls.

curl -o trace.out 'http://localhost:6060/debug/pprof/trace?seconds=5'
go tool trace trace.out

It answers questions a CPU profile cannot: “why did this request take 80 ms when it used 2 ms of CPU?” — it was waiting to be scheduled, or blocked on a lock, or paused by a GC assist. The tracer’s overhead is low enough for production (1–2% since Go 1.21), and the flight recorder (trace.NewFlightRecorder, Go 1.25) keeps the last few seconds in memory so you can snapshot a trace after something goes wrong.

Runtime metrics#

runtime/metrics exposes the runtime’s own counters and histograms with stable names — heap sizes, GC pauses, scheduler latency, goroutine count. Exporters publish them; alert on them the way Observability teaches.

Latency is not throughput#

Benchmarks report averages. A service cares about p99 (see Observability I.04). Measure a server with an open-loop load generator and look at the distribution; GC assists, lock convoys and scheduler delays live in the tail and vanish in the mean.

Code#

A correct benchmark, three wrong ones, and a profile of a deliberately lopsided program — all from an ordinary main.

// bench.go — how benchmarks lie, how to compare runs, and reading a CPU profile's top entries.
package main

import (
	"bytes"
	"fmt"
	"math"
	"runtime/pprof"
	"sort"
	"strings"
	"testing"
)

var sink float32

func Dot(a, b []float32) float32 {
	var s float32
	for i := range a {
		s += a[i] * b[i]
	}
	return s
}

func bench(name string, f func(b *testing.B)) float64 {
	// Five runs: report the median and the spread, as benchstat would.
	ns := make([]float64, 5)
	for i := range ns {
		r := testing.Benchmark(f)
		ns[i] = float64(r.T.Nanoseconds()) / float64(r.N)
	}
	sort.Float64s(ns)
	fmt.Printf("%-34s median %8.1f ns/op   spread ±%.0f%%\n", name, ns[2], 100*(ns[4]-ns[0])/2/ns[2])
	return ns[2]
}

func softmaxSlow(x []float32) []float32 { // allocates and uses float64 math per element
	out := make([]float32, len(x))
	sum := 0.0
	for _, v := range x {
		sum += math.Exp(float64(v))
	}
	for i, v := range x {
		out[i] = float32(math.Exp(float64(v)) / sum)
	}
	return out
}

func tokenize(s string) int { return len(strings.Fields(s)) }

func main() {
	x := make([]float32, 1024)
	y := make([]float32, 1024)
	for i := range x {
		x[i], y[i] = float32(i), 0.5
	}

	full := bench("correct: result kept", func(b *testing.B) {
		for i := 0; i < b.N; i++ {
			sink = Dot(x, y)
		}
	})
	bench("WRONG: result discarded", func(b *testing.B) {
		for i := 0; i < b.N; i++ {
			_ = Dot(x[:4], y[:4]) // small and unused: the compiler may remove most of it
		}
	})
	bench("WRONG: setup inside the loop", func(b *testing.B) {
		for i := 0; i < b.N; i++ {
			a := make([]float32, 1024)
			sink = Dot(a, y)
		}
	})
	small := x[:8]
	tiny := bench("misleading: tiny input (8)", func(b *testing.B) {
		for i := 0; i < b.N; i++ {
			sink = Dot(small, y[:8])
		}
	})
	fmt.Printf("   per element: %.2f ns at length 1024, %.2f ns at length 8 — a tiny input is not a scale model\n\n",
		full/1024, tiny/8)

	// A CPU profile of a program with one obvious hot spot.
	var buf bytes.Buffer
	if err := pprof.StartCPUProfile(&buf); err != nil {
		fmt.Println("profiling unavailable:", err)
		return
	}
	logits := make([]float32, 4096)
	text := strings.Repeat("the quick brown fox ", 50)
	words := 0
	for i := 0; i < 3000; i++ {
		sink += softmaxSlow(logits)[0] // ~all of the CPU time
		words += tokenize(text)        // a little
	}
	pprof.StopCPUProfile()
	fmt.Printf("profile captured: %d bytes (pprof protobuf, gzip). Write it to a file and run\n", buf.Len())
	fmt.Println("  go tool pprof -top cpu.out      or     go tool pprof -http=: cpu.out")
	fmt.Println("to see math.Exp and softmaxSlow at the top, and runtime.mallocgc from the make().")
	_ = words
}

Remember this#

• Profile to find the hot spot; benchmark to prove a fix.
• Keep results alive, keep setup out of the loop, use realistic sizes, repeat and use benchstat.
• CPU profile for time, heap profile for memory (inuse versus alloc), trace for waiting.
• Runtime functions in a profile point back to modules III and IV.

Try it#

1. Run bench.go. Write the profile bytes to cpu.out and open it with go tool pprof -http=:. Find the line inside softmaxSlow that costs most.
2. Rewrite softmaxSlow to take an output slice and to compute exp once per element. Benchmark both with -count=10 in a real _test.go and compare with benchstat.
3. Add net/http/pprof to any server you have, apply load, and take a 30 s CPU profile and a heap profile. What is the top entry of each?

Check yourself#

1. What is the difference between a benchmark and a profile?
2. Name three ways a benchmark can report a misleadingly small number.
3. Which tool shows why a request waited rather than where it computed?