Skip to content

A CPU profile names the hot function

Level: 301 · anyone who has guessed which function is slow

One line: With runtime/pprof recording, the runtime samples the program's call stacks a hundred times a second, and go tool pprof -top lists functions by the samples that landed in them — main.hot, which sums a million readings four hundred times, is the top row on every run, while the sample counts, the Duration: and the Time: around it are different each time.

The program fills a slice of a million readings, starts a CPU profile into cpu.prof, calls hot (four hundred passes over the slice) and cold (one pass), and stops the profile. The script builds it, runs it, runs go tool pprof -top on the result, and prints only what cannot vary: two header lines and which function is in the top row.

Verified output of a_cpu_profile_names_the_hot_function_sh.sh — regenerated by tools/run_examples.py, never hand-typed.

$ go mod init example
$ go build -o sumreadings .
$ ./sumreadings
total is not zero: true
exit status 0
$ go tool pprof -top -nodecount=5 ./sumreadings cpu.prof >top.txt
exit status 0
$ grep -E '^(File|Type):' top.txt
File: sumreadings
Type: cpu
$ awk 'header { print "top row: " $NF; exit } /^ *flat +flat%/ { header = 1 }' top.txt
top row: main.hot
$ grep -c ' main\.hot$' top.txt
main.hot in the top 5: yes

Reading the output

File: sumreadings, Type: cpu. The header names the binary the profile came from and the kind of profile. The other header lines — Time:, Duration: and the sample totals — change on every run and are left out; on Linux there is also a Build ID: line that macOS does not print (seen in Docker with go1.25.14 on 2026-09-23; not machine-checked here).

top row: main.hot. The table is sorted by flat, the time sampled with that function at the top of the stack. hot does four hundred times the work of everything else in the program, so it is first every time — twenty runs here, and the Linux run — and that is the one fact about the table that is a key. The Real runs fence below has the numbers.

Why hot carries //go:noinline. Had the compiler pasted hot into main — The compiler says what it inlines — the profile would still name it, since Go profiles record inlined frames, but its row would read main.hot (inline) and the key's awk would pick up the wrong field. The directive keeps the experiment simple; it is not something to leave in production code. (The (inline) marker is not machine-checked here.)

Where cold went. One pass over the slice is a millisecond or two, and the profiler takes a sample every ten milliseconds: cold is in the profile on some runs and missing on others, which is why the key does not mention it. A function that runs for less than the sampling interval is not something a CPU profile can rank.

The sampling. StartCPUProfile ↗ relies on the SIGPROF signal, and pprof.go ↗ sets the rate to 100 Hz, with a comment that it is frequent enough to be useful and rare enough not to distort the program. Each sample records the stack of the goroutine that was running on that thread. The profile is a gzip-compressed protocol buffer (format ↗) — the kata reads it back without pprof.

Real runs — go1.25.5, x86-64 Mac, 1 run, 2026-09-23
$ ./sumreadings
total is not zero: true
$ go tool pprof -top ./sumreadings cpu.prof
File: sumreadings
Type: cpu
Time: 2026-09-23 19:44:21 EDT
Duration: 402.57ms, Total samples = 200ms (49.68%)
Showing nodes accounting for 200ms, 100% of 200ms total
      flat  flat%   sum%        cum   cum%
     190ms 95.00% 95.00%      190ms 95.00%  main.hot
      10ms  5.00%   100%       10ms  5.00%  runtime/pprof.StopCPUProfile
         0     0%   100%      200ms   100%  main.main
         0     0%   100%      200ms   100%  runtime.main
$ go tool pprof -top -nodecount=3 ./sumreadings mem.prof
File: sumreadings
Type: inuse_space
Time: 2026-09-23 19:44:21 EDT
Showing nodes accounting for 10243.25kB, 95.24% of 10755.47kB total
Showing top 3 nodes out of 17
      flat  flat%   sum%        cum   cum%
    8192kB 76.17% 76.17%     8192kB 76.17%  main.init
    1539kB 14.31% 90.47%  2051.22kB 19.07%  runtime.allocm
  512.25kB  4.76% 95.24%   512.25kB  4.76%  runtime.gcBgMarkWorker
$ go tool pprof -top -nodecount=3 -sample_index=alloc_space ./sumreadings mem.prof
File: sumreadings
Type: alloc_space
Time: 2026-09-23 19:44:21 EDT
Showing nodes accounting for 10.66MB, 80.90% of 13.18MB total
Showing top 3 nodes out of 24
      flat  flat%   sum%        cum   cum%
       8MB 60.71% 60.71%        8MB 60.71%  main.init
    1.50MB 11.41% 72.12%        2MB 15.20%  runtime.allocm
    1.16MB  8.78% 80.90%     1.16MB  8.78%  runtime/pprof.StartCPUProfile

flat and cum. main.hot has 190 ms flat: nineteen of the twenty samples were taken inside it. main.main has 0 flat and 200 ms cum: no sample was taken in main's own code, but every sample had main on the stack. Read flat to find where the time is spent, cum to find who asked for it. In this run cold was not sampled at all, and Total samples = 200ms (49.68%) says that only half the program's wall time was covered — the fill loop before StartCPUProfile and process start-up are the rest.

Heap profiles, by two measures. The demo also writes a heap profile with pprof.WriteHeapProfile after a runtime.GC(). Read with the default inuse_space, it shows what is still live: the 8 MB slice of readings, allocated in main.init because a package-level make runs at initialisation. Read with -sample_index=alloc_space, it shows everything allocated since the program started, live or not — the right measure when the question is "who is making the garbage collector work", and the one to pair with the allocs/op column of allocs/op is a key, ns/op is not. A benchmark gets the same profiles from go test -bench=X -cpuprofile cpu.prof -memprofile mem.prof. Run bash demo/profile_full.sh from this folder to see all three tables on your machine.

Traces are the other tool. A CPU profile answers "which function"; it cannot say which goroutine was waiting for what, because it only samples goroutines that are running. runtime/trace ↗ records every goroutine's state changes, and go tool trace ↗ shows them over time; the execution traces blog post ↗ is the introduction, and the Concurrency library's Where does a concurrent program spend its time? ↗ draws the line between the two. Neither is run here.

a_cpu_profile_names_the_hot_function_sh.sh

a_cpu_profile_names_the_hot_function_sh.sh in full — pasted here by tools/run_examples.py from the file CI runs.

#!/usr/bin/env bash
# A CPU profile names the function the time went to. The program below sums a
# million readings four hundred times in `hot` and once in `cold`, writing a
# profile with runtime/pprof; `go tool pprof -top` then lists functions by the
# time sampled in them. Every number in that table changes from run to run, so
# this script prints only what does not: the two header lines that name the
# binary and the profile type, and which function sits in the top row. The
# whole table is in demo/profile_full.sh.
set -u
export GOTOOLCHAIN=local

dir=$(mktemp -d)
trap 'rm -rf "$dir"' EXIT
cd "$dir" || exit 1

cat >main.go <<'GO'
package main

import (
    "fmt"
    "os"
    "runtime/pprof"
)

var readings = make([]int64, 1<<20)

// hot does almost all the work. go:noinline keeps it a function of its own in
// the profile rather than a line inside main.
//
//go:noinline
func hot(rounds int) int64 {
    var total int64
    for range rounds {
        for _, r := range readings {
            total += r
        }
    }
    return total
}

//go:noinline
func cold() int64 {
    var total int64
    for _, r := range readings {
        total += r % 7
    }
    return total
}

func main() {
    for i := range readings {
        readings[i] = int64(i % 97)
    }
    f, err := os.Create("cpu.prof")
    if err != nil {
        panic(err)
    }
    if err := pprof.StartCPUProfile(f); err != nil {
        panic(err)
    }
    total := hot(400) + cold()
    pprof.StopCPUProfile()
    f.Close()
    fmt.Println("total is not zero:", total != 0)
}
GO

say() { printf '$ %s\n' "$*"; }

say 'go mod init example'
go mod init example >/dev/null 2>&1 || exit 1

say 'go build -o sumreadings .'
go build -o sumreadings . || exit 1

say './sumreadings'
./sumreadings
echo "exit status $?"

say 'go tool pprof -top -nodecount=5 ./sumreadings cpu.prof >top.txt'
go tool pprof -top -nodecount=5 ./sumreadings cpu.prof >top.txt 2>&1
echo "exit status $?"

# The header: File and Type are fixed; Time, Duration and the sample totals
# are not, and Linux adds a Build ID line that macOS does not.
say "grep -E '^(File|Type):' top.txt"
grep -E '^(File|Type):' top.txt

# The table: the function in the first row after the column headings, and
# whether main.hot is among the five rows at all.
first='header { print "top row: " $NF; exit } /^ *flat +flat%/ { header = 1 }'
say "awk '$first' top.txt"
awk "$first" top.txt

say "grep -c ' main\\.hot\$' top.txt"
if [ "$(grep -c ' main\.hot$' top.txt)" -ge 1 ]; then
    echo "main.hot in the top 5: yes"
else
    echo "main.hot in the top 5: no"
fi

What to do

  • Profile a run that does real work for hundreds of milliseconds at least, and ideally seconds: at a hundred samples a second, a twenty-millisecond run is two samples, and a profile of two samples names nothing.
  • Read flat first, then cum. A row with high cum and zero flat is a caller, not a cost.
  • Profile benchmarks with -cpuprofile and -memprofile, and read the memory profile with -sample_index=alloc_space when the question is allocation.
  • Feed the profile back. A CPU profile saved as default.pgo beside main is what profile-guided optimization ↗ uses to raise the inlining budget on the hot path.
  • Reach for a trace when the CPU profile shows idle time. Goroutines that wait do not appear in a CPU profile at all.

Practice

Profile into memory instead of a file, and check that the profile names the hot function without leaving the program: start the profile on a bytes.Buffer, run hot, stop it, gunzip the buffer with compress/gzip, and use bytes.Contains to look for main.hot in the raw bytes — the profile's string table holds every function name as plain UTF-8. Print the first two bytes as well, to show the gzip magic number.

Solution

a_cpu_profile_names_the_hot_function_kata_go.go in full — pasted here by tools/run_examples.py from the file CI runs.

// Kata: profile into memory instead of a file, and check the profile names
// the hot function without leaving the program. A CPU profile is a
// gzip-compressed protocol buffer whose string table holds every function
// name as plain UTF-8, so after gunzipping, bytes.Contains can find them.
//
//  go build a_cpu_profile_names_the_hot_function_kata_go.go && ./a_cpu_profile_names_the_hot_function_kata_go
package main

import (
    "bytes"
    "compress/gzip"
    "fmt"
    "io"
    "runtime/pprof"
)

var readings = make([]int64, 1<<20)

//go:noinline
func hot(rounds int) int64 {
    var total int64
    for range rounds {
        for _, r := range readings {
            total += r
        }
    }
    return total
}

func main() {
    for i := range readings {
        readings[i] = int64(i % 97)
    }

    var profile bytes.Buffer
    if err := pprof.StartCPUProfile(&profile); err != nil {
        panic(err)
    }
    total := hot(400)
    pprof.StopCPUProfile()
    fmt.Println("total is not zero:", total != 0)

    fmt.Printf("first two bytes: % x (the gzip magic number)\n", profile.Bytes()[:2])
    unzipped, err := gzip.NewReader(&profile)
    if err != nil {
        panic(err)
    }
    raw, err := io.ReadAll(unzipped)
    if err != nil {
        panic(err)
    }
    for _, name := range []string{"main.hot", "main.main", "cpu", "nanoseconds"} {
        fmt.Printf("profile names %-14q %t\n", name, bytes.Contains(raw, []byte(name)))
    }
}

Verified output of a_cpu_profile_names_the_hot_function_kata_go.go — regenerated by tools/run_examples.py, never hand-typed.

total is not zero: true
first two bytes: 1f 8b (the gzip magic number)
profile names "main.hot"     true
profile names "main.main"    true
profile names "cpu"          true
profile names "nanoseconds"  true

cpu and nanoseconds are the sample type's name and unit, which the profile also stores as strings; a main.cold would be found only on a run in which it was sampled, so the kata does not look for one.

In other languages

  • The Concurrency library's Where does a concurrent program spend its time? ↗ — the same hot-function question put to six languages, and the case for a tracer when the answer is "waiting".
  • Rust has no profiler in its toolchain; the usual pair is Linux perf ↗ and cargo flamegraph ↗, which sample the same way Go's runtime does, from outside the process. Python's cProfile ↗ is deterministic rather than sampled: it counts every call, and slows the program to do so.

Sources

  • runtime/pprof ↗ — StartCPUProfile, StopCPUProfile, WriteHeapProfile, and the package overview on how to use go tool pprof; src/runtime/pprof/pprof.go ↗ — the 100 Hz rate.
  • pprof ↗ — the tool's documentation: -top, -nodecount, -sample_index; the profile format ↗.
  • Russ Cox and Shenghou Ma, Profiling Go Programs ↗, the Go blog, 2011, updated 2013 — the original walk-through; Diagnostics ↗ — profiling, tracing and debugging, side by side.
  • runtime/trace ↗, go tool trace ↗ and More powerful Go execution traces ↗.
  • Profile-guided optimization ↗ — what a CPU profile is for after the reading.
  • Alan Donovan and Brian Kernighan, The Go Programming Language (Addison-Wesley, 2015), chapter 11, "Testing" — 11.5, "Profiling".
  • Jon Bodner, Learning Go, 2nd ed. (O'Reilly, 2024), chapter 15, "Writing Tests" — "Using Benchmarks", with its box "Profiling Your Go Code".
  • Miki Tebeka, Effective Go Recipes (Pragmatic, 2024), Recipe 33, "Calculating Cumulative Sum" — -cpuprofile on a benchmark and top in go tool pprof; Recipe 75, "Using Build Tags for Conditional Builds" — net/http/pprof behind a build tag.
  • Dave Cheney, High Performance Go Workshop ↗, GopherCon 2019 — benchmarking, profiling and tracing in one afternoon.