Chapter 19: Debugging Concurrent Programs

19.1 Four Views of a Running Program

19.1.1 What You Already Have

You are not starting from nothing. Six chapters have handed you pieces of a debugging toolkit, and none of them has said how to choose between the pieces.

What is missing is the part that decides which one to reach for, and reaching for the wrong one is how an engineer spends a day finding a symptom.

19.1.2 The Four Views

Every tool in this chapter produces one of four kinds of information about a running program. They answer different questions and they cost different amounts to obtain.

view           answers                   costs
────           ───────                   ─────
snapshot       where is everyone NOW     a freeze you ask for
aggregate      where time ACCUMULATES    sampling overhead
timeline       what happened, in ORDER   heavy, and the only
                                         view that keeps order
single exec    what is THIS goroutine    maximum perturbation
               doing right now

A snapshot is a goroutine dump. It tells you that two hundred goroutines are blocked in semaphore.Acquire — which is often the entire answer, and never tells you which one arrived first.

An aggregate is a profile. It tells you that 60% of blocked time accumulates on one mutex. It cannot tell you the order of any two events, because it has thrown the order away in exchange for being cheap enough to leave on.

A timeline is an execution trace. It is the only view that preserves ordering, which is the only view that can answer questions about interleavings, which is what a concurrent bug is. It is also the most expensive, and §19.5 measures how much.

A single execution is a debugger. It answers questions about one goroutine in exhaustive detail, and it obtains that detail by stopping the program.

There is a fifth thing that fits none of these cleanly, and §19.4 is about it: a continuous counter — runtime/metrics — which is neither sampled nor snapshotted but incremented as the program runs, and is therefore free to read and always correct.

19.1.3 The Perturbation Ladder

Every tool trades fidelity against perturbation, and they order cleanly:

perturbation   tool                    what it costs
────────────   ────                    ─────────────
none           runtime/metrics         a counter read
varies         goroutine dump          ~0.2ms to ~1s, §19.1.4
low            CPU profile             ~100 samples a second
moderate       block / mutex profile   sampling on each event
high           execution tracer        1.1x to 2.3x, see §19.5
total          debugger breakpoint     the schedule itself

19.1.4 Measured: What Each View Costs to Take

That ladder is usually asserted. Here it is measured, against a process holding a varying number of blocked goroutines:

Read the last cell first. At a hundred thousand goroutines — an ordinary number for a service holding connections — one full goroutine dump stops the process for nearly a second. Every in-flight request pauses. Every health check ticks toward its timeout.

Two more things in that table. The debug=1 census pulls ahead of the full dump as the count grows — 112.9 ms against 913.3 ms at 100,000 — because it aggregates identical stacks instead of printing each one, which is a second reason to reach for it first. And metrics.Read is sub-microsecond and effectively independent of goroutine count — the residual spread across rows is measurement noise rather than a trend, which is why the block above prints steady-state values and says so. That distinction is not pedantry: a single reading at each size produces a tidy monotonic rise that looks exactly like a scaling law and is entirely warm-up. That gap — six orders of magnitude in the bottom row — is the entire argument for §19.4.

19.1.5 The Decision Procedure

From which the chapter’s decision procedure follows:

That is not a counsel of caution. It is a correctness rule, because the tools at the bottom of the ladder change the thing they measure.

19.1.6 The Observer Effect Is Not a Metaphor

In a sequential program, a breakpoint is free: the program has one thread of control, you stop it, you look, you continue, and nothing about the answer changes.

In a concurrent program, stopping is an intervention. The bug you are chasing is an ordering, and a breakpoint is a device for changing orderings.

This has three practical consequences, in increasing order of how often they bite.

A debugger cannot show you a race. When you stop at a breakpoint, the goroutine you stopped is not racing with anything, because it is not running. Stepping through a data race is close to hopeless: the interleaving that produced the bug requires two goroutines to be inside the same window simultaneously, and the debugger’s entire function is to prevent that.

Instrumentation changes timing. A log line is a lock, a syscall, a timestamp, and an allocation. Adding one to a racy path narrows or widens the window. “I added a print statement and it went away” is not a mystery — it is a measurement, and what it measured is that your bug is timing-dependent.

Even the race detector distorts. §16.3 covers what it catches; what matters here is that a -race binary runs several times slower with different timing, so a bug that depends on a narrow window may not occur under the detector at all.

19.1.7 Triage: Stuck, Slow, or Rare

Three symptoms, three starting points.

Stuck — requests hang, the process is idle, nothing progresses. Start with a snapshot. A goroutine dump names what everyone is waiting for, and for a hang that is usually the whole answer. §19.2.

Slow — everything works and takes too long. Start with aggregates: the always-on counters first to establish whether there is contention at all (§19.4), then the profiles to find where (§19.3). Reach for the timeline only when the aggregates say the time is going somewhere they cannot see.

Rare — it happened once, at 03:14, and everything is fine now. This is the hard one, and the honest answer is that nothing you can run now will help. The only useful question is what should have been recording. §19.4 for the counters that always are, and §19.7 for the trace that can be.

19.1.8 Common Mistakes

Summary: Four Views of a Running Program

A sequential bug lives in a state and a concurrent bug lives in an interleaving, which is why the tools split into ones that report where everyone ended up and ones that report how they got there.

There are four views. A snapshot says where everyone is now; an aggregate says where time accumulates and has discarded ordering to be cheap; a timeline preserves ordering and is the only view that can answer a question about an interleaving; a single execution answers in exhaustive detail about one goroutine by stopping the program. A fifth thing, the continuous counter, is free to read and always correct.

They form a perturbation ladder, from a counter read that costs nothing to a breakpoint that destroys the schedule you were studying, and the rule is to use the least invasive tool that can answer the question. That ladder is measured rather than asserted: a full dump costs 169 µs at a hundred goroutines and 913 ms at a hundred thousand, while metrics.Read stays sub-microsecond throughout. That is a correctness rule rather than a frugal one: a debugger cannot show you a race, because its function is to prevent the simultaneity the race requires.

Triage is stuck, slow, or rare. Stuck starts at a snapshot, slow starts at the always-on counters, and rare cannot be answered by anything you run afterwards — only by what was already recording.

Self-Check Questions: Four Views of a Running Program

19.2 The Dump, Re-read

The goroutine dump is the snapshot view, and Chapter 10 already taught you to take one. §10.4 covers SIGQUIT, the pprof endpoint, the anatomy of a stack frame, and — importantly — why the runtime’s own deadlock detector almost never fires in production. None of that is repeated here.

What this section owns is the reading: what the dump actually says on a modern toolchain, what decides how much of it you get, and why the labels you carefully added are missing from the one you receive in an incident on any module below go 1.27.

19.2.1 A Debt From Chapter 2

Chapter 2's §2.4 ships a goroutine-state table for exactly this purpose. One of its rows is now wrong:

semacquire does not appear. The runtime now names the primitive rather than the generic semaphore acquire, and runtime2.go's waitReasonStrings carries dozens of distinct entries where the old vocabulary had one. That is a large part of why reading dumps got easier: a goroutine that used to be “waiting on something” now says sync.RWMutex.RLock or sync.WaitGroup.Wait, and you can tell which synchronisation object it is queued behind without reading a single frame.

19.2.2 debug=1 and debug=2 Are Different Tools

Both Chapter 2 and Chapter 12 print goroutine profiles, at different debug levels, and neither explains the difference. It matters more than the name suggests.

// Illustrative snippet — not a complete program
pprof.Lookup("goroutine").WriteTo(w, 1) // aggregated census
pprof.Lookup("goroutine").WriteTo(w, 2) // every stack, in full

debug=1 is a census. Identical stacks are collapsed and counted, so the output is short and the shape is immediately visible:

One line tells you that 1,820 goroutines are stuck at the same place, which for a leak is the entire diagnosis.

debug=2 is every stack, unaggregated, in the same format the runtime prints on a panic. It is what you need when the goroutines are not identical — when you have to find the one holding the lock among two hundred waiting for it.

The rule of thumb: debug=1 to see the shape, debug=2 to find the individual. Reach for the census first; it is smaller, faster to read, and answers most questions about a hang.

19.2.3 The Labels You Added Were Not in the Dump You Got — Until Go 1.27

runtime/pprof lets you attach key-value labels to goroutines, and they are the best available answer to “which of these ten thousand goroutines is which”:

// Illustrative snippet — not a complete program
pprof.Do(ctx, pprof.Labels("job", "resize", "tenant", tenantID),
    func(ctx context.Context) {
        // everything this spawns inherits the labels
        process(ctx, item)
    })

Labels propagate to goroutines started inside Do, which means one call at the top of a request wraps everything the request creates. Measured: runtime/metrics, pprof.Labels, SetGoroutineLabels and pprof.Do appear in zero of the preceding chapters — this is unspent territory, and it is the single highest-leverage thing in this section.

Now the trap.

Labels appear at debug=1 and are absent from debug=2. The census carries them as a # labels: {"job":"resize"} line above each group; the full-stack dump does not carry them at all.

That inverts the natural assumption — debug=2 is the more verbose format, so it should contain a superset — and it has a sharp practical consequence. SIGQUIT prints the debug=2 format. So does an unrecovered panic. The dump you get automatically in an incident is the one without your labels in it.

That was true on go1.26.1, and it stays true for any module whose go.mod declares a language version below 1.27. Go 1.27 closes the gap: for modules declaring go 1.27 or later the runtime prints labels in the goroutine header of every traceback it produces — panics, SIGQUIT, GOTRACEBACK=all, and the debug=2 dump, which is the same printer — after the state bracket, in the form

(keys sorted, values quoted when they need to be; the runtime documents the format as subject to change, so grep for the goroutine number or the wait reason rather than the braces). The switch is the tracebacklabels GODEBUG, added in 1.26 as an opt-in and defaulted to 1 in 1.27, and the opt-out is one the Go team say they will keep indefinitely, for the reason §19.2.6 makes about the pprof endpoint: a label is whatever you put in it, and a tenant identifier that was harmless in a profile you fetch over a private port is now written to stderr by every panic. Label anyway — but decide, per service, whether GODEBUG=tracebacklabels=0 belongs in the deployment.

One ordering detail decides whether the panic case gets them. A traceback prints the labels the goroutine holds after its deferred functions have run, and pprof.Do defers a SetGoroutineLabels back to the parent's set — so a panic that unwinds through pprof.Do's own frame prints goroutine 1 [running]: with nothing after the bracket, while a goroutine started inside pprof.Do (it inherits the labels and has no such defer) prints them, and so does a SIGQUIT dump taken while pprof.Do is still on the stack. If the panic path matters to you, set the labels with SetGoroutineLabels on the goroutine that can panic, or accept that the created by line and the spawned goroutines carry the context.

One more field can appear in the same header. Once anything has taken the goroutineleak profile (§19.3.6), the goroutines it proved dead also carry (leaked) on their wait reason in this dump and every later one — so pull that profile first and the dump you are handed is annotated; and read its absence correctly, because no (leaked) means nobody asked.

19.2.4 GOTRACEBACK Decides How Much You Get

There is one environment variable that controls how much of the program appears in a crash dump, it has five settings, and it is barely mentioned in the preceding seventeen chapters — measured, Chapter 2 mentions it zero times and Chapters 10 and 15 have one clause each.

Six times the stacks between the default and the most verbose level, decided by one variable, and the default is single.

(The byte counts vary with the length of your source paths, since every frame prints a filename — two machines running the identical program reported 177 and 193 bytes for single. The stack counts are the durable figure and are what the levels actually control.)

That default is the finding. When a Go service panics, you are shown the stack of the panicking goroutine and nothing else. For a sequential bug that is exactly right and admirably concise. For a concurrent bug it is close to useless, because the panicking goroutine is frequently the victim — it found the corrupted state, or it timed out — and the goroutine that caused the problem is not printed at all.

crash is the fifth level: it behaves like system and then raises SIGABRT to produce a core dump, which §19.2.7 uses.

19.2.5 Reading a Dump That Is Mostly Waiting

1,940  [chan receive]         ─┐  the crowd -- these are
   52  [sync.Mutex.Lock]      ─┘  symptoms, not causes
    7  [IO wait]
    1  [running]              ───  the one that matters

Read the biggest wait duration first, then the [running]
goroutine. The crowd tells you WHAT is blocked, and the
one that is running usually tells you WHY.

Two techniques do most of the work on a real dump, and neither is obvious.

The duration annotation tells you what is stuck versus what is slow. A goroutine blocked longer than a minute has its wait time printed:

The runtime only reports this over a threshold, so its absence means “recently” and its presence means “long enough that you should ask why”. In a dump of a hung service, sorting by that number separates the original victim from everyone who piled up behind it — the largest number is usually closest to the cause.

Two dumps beat one. A single dump cannot distinguish a deadlock from slow progress, because both look like goroutines blocked on the same thing. Take two, thirty seconds apart, and compare goroutine IDs. Same IDs in the same states means nothing moved. Different IDs at the same stack means work is flowing and the queue is just deep — a completely different problem with a completely different fix.

There is a sibling to that, and it is the one place this chapter can extend §10.4 rather than cite it. §10.4 is right that a goroutine still doing something suppresses the runtime’s deadlock detector, and chapter_10.md:158 lists the cases: “a time.Sleep loop, a ticker, an idle HTTP server”. Its word is loose, though — it attributes the suppression to a goroutine being “still runnable”, and a goroutine parked in time.Sleep(time.Hour) is not runnable. It is asleep on a timer.

measured, isolating one variable at a time:

The sleeper suppresses detection while being no more runnable than the deadlocked goroutines are. The mechanism is that checkdead looks for a pending timer and, finding one, wakes a thread to wait for it rather than declaring deadlock — because a timer is future progress that requires no other goroutine. So the rule is not “something is runnable” but “the runtime can see a reason to expect progress”, and a single time.Ticker anywhere in your process is such a reason. That is why §10.4 is right that production almost never reports a deadlock, and it is a slightly different reason than the one given.

And the one thing a dump systematically hides: a goroutine that is running does not look interesting. It appears as [running], one line, usually near the top, indistinguishable from healthy. When two hundred goroutines are blocked on a mutex, the one you need is the single [running] goroutine that holds it — and the dump gives it no more prominence than any other.

19.2.6 Getting One Out of Production At All

Everything above assumes you have a dump. On a development machine that is trivial. On a running service it is a decision with consequences, and there are three ways to do it that differ in ways worth knowing before the incident.

SIGQUIT prints a dump and then kills the process. §15.7.5 recommends it for a shutdown that has hung, and §10.4 says the same for a deadlock, and both are right — because in those situations the process is already useless. Chapter 15 measured the consequence: exit status 2, not the 131 you would expect from 128 + 3, because the runtime intercepts the signal. What matters here is the part that is easy to forget under pressure: this is a one-shot, destructive capture. You get one dump, in debug=2 format, without your labels on a pre-1.27 module (§19.2.3), and then the service is gone. If it was serving traffic, it is not any more.

The pprof endpoint is the non-destructive path, and it is the one to have wired up in advance:

// Illustrative snippet — not a complete program
import _ "net/http/pprof" // registers on DefaultServeMux

go func() {
    log.Println(http.ListenAndServe("localhost:6060", nil))
}()

That gives you /debug/pprof/goroutine?debug=1 — the census, with labels — plus every other profile, on a live process, as many times as you like. Taking two dumps thirty seconds apart to distinguish a deadlock from a queue (§19.2.5) is only possible this way.

Exposing it is a security decision, and the default is wrong. The blank import registers handlers on http.DefaultServeMux, so if your service also serves user traffic on that mux, /debug/pprof/ is on the public internet. It exposes stack traces, function names, and — via the CPU profile and the heap — a great deal about what your process is doing. The endpoints are also a denial-of-service surface: /debug/pprof/profile blocks for thirty seconds by default and /debug/pprof/trace can produce an enormous response.

The third option is worth knowing for constrained environments: a SIGUSR1 handler that writes a dump and keeps running. It is fifteen lines, it needs no open port, and it gives you the format and debug level you choose:

// Illustrative snippet — not a complete program
c := make(chan os.Signal, 1)          // buffered -- Chapter 5
signal.Notify(c, syscall.SIGUSR1)
go func() {
    for range c {
        name := fmt.Sprintf("/tmp/dump-%d.txt", time.Now().Unix())
        f, err := os.Create(name)
        if err != nil {
            continue
        }
        pprof.Lookup("goroutine").WriteTo(f, 1) // debug=1: with labels
        f.Close()
    }
}()

That is SIGQUIT's usefulness without its lethality, and it is the pattern to reach for when a debug port is not available.

19.2.7 Delve, and the One Time It Perturbs Nothing

Delve is the single-execution view, and §19.1.6 already made the argument that it is the wrong default. This subsection is about its narrow legitimate uses.

Attaching to a hung process is the first. When a service is wedged and a dump has told you where but not what with, Delve can read values a dump cannot:

That is the real gap it fills. A dump shows you that handleSearch is blocked on line 52; Delve shows you what tenantID was. For a hang, stopping the process costs nothing, because nothing is progressing anyway — the objection in §19.1.4 does not apply to a program that has already stopped.

The core dump is the second, and it perturbs nothing at all. Set GOTRACEBACK=crash and the process writes a core file on panic, which you can inspect afterwards at leisure:

This is the one use of a debugger in this chapter that is free of the observer effect, for a simple reason: the world has already stopped. You are not changing an interleaving; you are reading the remains of one. It is also the only technique in the chapter that gets you a debugger’s fidelity on a production incident you were not watching — which makes it a quieter cousin of §19.7.

What Delve is still bad at is the case people reach for it first: a data race. Stepping through requires two goroutines inside a window simultaneously, and a breakpoint exists to prevent exactly that.

19.2.8 Common Mistakes

Summary: The Dump, Re-read

Chapter 10 taught you to take a dump; this section is about reading one. Chapter 2's state table is now wrong in one row — the runtime names the primitive, sync.Mutex.Lock rather than semacquire, though the symbol survives as a stack frame and the claim is about the bracket.

debug=1 and debug=2 are different tools: a census that collapses identical stacks and shows the shape, and a full dump that finds the individual. Labels attach to goroutines and propagate to everything they spawn, and — measured — appear only at debug=1. Since SIGQUIT and panics print debug=2, the dump you are handed in an incident is the one without your labels — on modules below go 1.27; from 1.27 the traceback header carries them, behind an opt-out.

GOTRACEBACK decides how much you get, across a sixfold range of goroutine stacks, and defaults to single — one goroutine, which for a concurrent bug is usually the victim rather than the cause.

Two dumps beat one, because a single frame cannot distinguish a deadlock from a deep queue. And the goroutine you need is often the one that looks healthiest: [running], one line, holding the lock everyone else is waiting for.

Getting a dump out of production is its own decision: SIGQUIT is one-shot and destructive, the pprof endpoint is repeatable and is what two dumps thirty seconds apart require, and the blank import publishes it on whatever mux your service already uses. A SIGUSR1 handler is the fifteen-line middle path.

Delve earns its place for hangs, where stopping a stopped program costs nothing, and for dlv core on a GOTRACEBACK=crash dump — the one use in this chapter with no observer effect at all, because the world has already stopped.

Self-Check Questions: The Dump, Re-read

19.3 Profiles, and the Two That Are Empty

A profile is the aggregate view: where does time accumulate, summed over the whole run, with ordering discarded in exchange for being cheap. Go ships seven of them and two are concurrency-specific — and those two are the ones that lie to you first.

19.3.1 Two of Them Are Empty Until You Say Otherwise

Zero. Not “few” — zero. The block and mutex profiles are disabled by default and report an empty profile rather than an error, which means the diagnostic path looks like this:

You fetched the right profile from the right endpoint with the right tool, got a well-formed answer, and the answer says there is no blocking. There is a great deal of blocking. Nothing anywhere reported an error, because nothing went wrong: you asked a profiler that was switched off what it had recorded, and it correctly told you “nothing”.

This is §14.1's thesis in its third costume. The failure mode is not a crash; it is a confident report of health.

// Illustrative snippet — not a complete program
// Enable at startup. Both default to off.
runtime.SetBlockProfileRate(1)      // every blocking event
runtime.SetMutexProfileFraction(1)  // every contention event

cpu           on when you ask for it     samples RUNNING
heap          always collecting          samples allocation
goroutine     always available           snapshot
goroutineleak always available (1.27)    snapshot, leaked only
threadcreate  always available           snapshot
─────────────────────────────────────────────────────
block         OFF   -> empty profile     samples WAITING
mutex         OFF   -> empty profile     samples WAITING

The two below the line are the two a concurrency
bug sends you to, and they report health when off.

The CPU, heap, goroutine, goroutineleak and threadcreate profiles are not like this. They work out of the box. It is specifically the two concurrency profiles that require opt-in, which is precisely the pair a reader of this book will reach for. The newest of the five, goroutineleak (Go 1.27, §19.3.6), needs no knob either, but its cost is not a snapshot's: it is a garbage-collector reachability pass, taken on request and costing nothing until then — a third cost model next to the two knob-gated ones — and taking it has a visible side effect: the goroutines it marks read (leaked) in every later goroutine dump.

19.3.2 A Record Is a Stack, Not an Event

The second way these profiles mislead is arithmetic.

// Illustrative snippet — not a complete program
n := pprof.Lookup("mutex").Count() // records, not events

Count() returns the number of unique stacks in the profile, not the number of events sampled into it. Two hundred sends from the same line of code collapse into one record with a large accumulated value. So a service with catastrophic contention on one lock reports a very small number, and a reader who treats it as an event count concludes the contention is negligible.

The values are in the samples, not the count. go tool pprof shows them correctly by default because it displays the accumulated delay; it is only the record count that misleads, and the record count is what an in-process health check is most likely to read.

19.3.3 One Blames the Waiter, the Other Blames the Holder

The block and mutex profiles are routinely described as overlapping, and the usual summary — that one covers channels and the other covers mutexes — is wrong. Both record mutex contention. They differ in something more useful.

Same contention. Opposite attribution.

The block profile samples the goroutine that waited, and charges the sample where it went to sleep — at Lock. It answers who suffered.

The mutex profile samples on the unlock that releases a waiter, and charges it to the holder — at Unlock. It answers who caused it.

That distinction is the reason to have both, and it decides which one to fetch:

19.3.4 What Each One Cannot See

Every profile has a shape of blindness, and knowing it is most of what separates a useful reading from a plausible one.

The block profile is a sampler with a time bias. SetBlockProfileRate(n) aims to record one event per n nanoseconds spent blocked, so long waits are almost certain to be sampled and very short ones are almost certain to be missed. It is therefore honest about lock convoys and systematically quiet about high-frequency, short-duration handoffs — a channel passing a million small items may barely appear.

The mutex profile only sees contended unlocks. An uncontended Lock/Unlock pair costs a few nanoseconds and is never sampled, correctly. But it means the profile cannot tell you a lock is hot, only that it is contended. A mutex taken ten million times with no waiter is invisible, and that is exactly the lock you would want to make lock-free.

The goroutine profile is a snapshot with the ordering discarded twice over. It says what everyone is doing now, aggregated.

The goroutineleak profile (Go 1.27) only sees what the collector can prove. It reports a goroutine as leaked when the channel, mutex or condition variable it is parked on is unreachable from every runnable goroutine; a primitive still reachable through a global variable, or through a local of a goroutine that is merely slow, is not a leak to it however leaked it looks to you, and a goroutine parked on I/O or a syscall is not its business at all.

And no profile can see a goroutine that is running. The blocking profiles record waiting. A goroutine spinning in a busy loop, or holding a lock while doing slow work, contributes nothing to either — it is contributing to everyone else’s block profile, which is the indirection you have to reason through.

19.3.5 The Two Knobs Are Not Symmetric

Turning these on has a cost, and turning them off again has a surprise.

// Illustrative snippet — not a complete program
func SetMutexProfileFraction(rate int) int  // returns PREVIOUS rate
func SetBlockProfileRate(rate int)           // returns nothing

SetMutexProfileFraction returns the previous rate, and reads without setting when passed a negative number. So it can be saved and restored:

// Illustrative snippet — not a complete program
prev := runtime.SetMutexProfileFraction(1)
defer runtime.SetMutexProfileFraction(prev)

SetBlockProfileRate returns nothing and there is no getter. The block rate cannot be read or restored through the public API at all. Two sibling knobs, introduced together, in the same package, for the same purpose — and one of them is one-way.

That asymmetry matters as soon as you write anything that enables profiling temporarily: a diagnostic endpoint, a debug handler, a test. You can restore half of what you changed, and for the other half you have to decide a policy — usually “the process owns one setting for its lifetime, set it at startup, never touch it” — and write it down. The exercise at the end of this chapter is built on exactly this.

On cost: both are cheap at low rates and neither is free. SetBlockProfileRate(1) records every blocking event, which on a channel-heavy service is a great deal of events; production settings usually use a rate in the microseconds so that only substantial waits are sampled. SetMutexProfileFraction(n) records one in n.

19.3.6 Diffing Two Profiles, and Why It Needs §19.2's Labels

The standard way to find a leak in production is to take a profile, wait, take another, and subtract. §10.6 already prints the command:

What §10.6 does not say is what the result means, and there are two limits worth knowing before you act on one.

A diff shows growth, never causation. The stack that grew is where the goroutines are parked, which is the place they could not leave — not the place that created them or the reason they were created. A diff showing 4,000 new goroutines in handleSearch tells you they are blocked in handleSearch; the bug is upstream, in whatever stopped cancelling them.

A diff of an unlabelled profile is often unreadable. Real services have one or two stacks that account for most goroutines, and they grow under load whether or not anything is leaking. Distinguishing “grew because traffic doubled” from “grew because they never exit” needs a second dimension — which is what §19.2.3's labels provide. A diff by stack says handleSearch grew; a diff of a labelled profile says handleSearch grew for one tenant, which is a different investigation and usually the right one.

This is where the chapter’s two halves meet: the labels are added at deploy time, months before the incident, and they are the difference between a diff that names the cause and a diff that names the symptom.

Go 1.27 adds a third profile to this workflow, and it answers the question the diff cannot. /debug/pprof/goroutineleak — pprof.Lookup("goroutineleak") in code — reports only goroutines the runtime has proved can never wake: parked on a channel, mutex or condition variable that is unreachable from every runnable goroutine, and from everything those could unblock. The proof is the collector's reachability walk, so the profile is taken rather than always on (WriteTo runs that collection itself; you do not call runtime.GC first), it takes ?seconds= for a delta like the others, and it carries the same # labels: line the census does; at debug=2 the state reads [chan receive (leaked)]. Its blind spot is stated in the release notes and worth remembering: a primitive still reachable through a global, or through a local of a goroutine that is merely slow, is not a leak to the collector however leaked it looks to you. So the diff still finds growth, and the labels still say whose; goroutineleak says which of the grown stacks are provably dead. Experimental behind GOEXPERIMENT=goroutineleakprofile in 1.26, on by default from 1.27.

Its Count() is not a metric: it reports the last collection, and a process nobody has profiled reports zero leaks forever — the block-profile shape from §19.3.1, one section later.

19.3.7 CPU, Heap, and Flame Graphs

Chapter 10 promised this section by name — “for general profiling techniques including CPU profiling, memory profiling, flame graphs, and advanced pprof analysis, see Chapter 19” — so here is the part of it that is about concurrency.

The CPU profile is on by default and samples at 100 Hz. For concurrent code its most useful property is the one people forget: it samples running goroutines, so it is exactly complementary to the block and mutex profiles, which sample waiting ones. A service that is slow with idle CPUs has its answer in the blocking profiles; a service that is slow with saturated CPUs has it here.

The heap profile matters here for one reason: goroutine stacks are heap-allocated, so a goroutine leak shows up as memory growth, and §14.4.4's 2.7 KB per parked goroutine — 2,081 bytes of stack plus 606 of heap — is the conversion factor. Note which number that is: §2.5 quotes the familiar ~2 KB, and §14.4.4 measured the rest, warning in the same breath that “the commonly quoted 2 KB per goroutine is the stack half only”. Use the larger figure when converting a goroutine count into expected memory, or you will under-predict by a third. If inuse_space is climbing and the goroutine count is climbing proportionally, you have a leak rather than a memory bug, and the goroutine profile is the better tool.

Flame graphs are a rendering, not a profile: go tool pprof -http=:8080 profile.pprof opens a browser with a flame graph view of whichever profile you fed it. Width is accumulated value, stacking is call depth. For a block profile the flame graph reads as “where we wait”, which is the view most people have never looked at and the fastest way to see a convoy.

The interpretation question — what to change once you have read one — is Chapter 20's.

19.3.8 The Number You Should Have Read First

Everything in this section requires you to have enabled something, in advance, and to have chosen correctly which thing.

There is one contention figure that requires none of that, is always correct, and costs a counter read. It is in the next section, and it is what should send you here in the first place.

19.3.9 Common Mistakes

Summary: Profiles, and the Two That Are Empty

Two of the seven standard profiles are disabled by default and report an empty profile rather than an error. Measured, 32,000 contended lock operations and 200 blocking sends produce zero block records and zero mutex records until SetBlockProfileRate and SetMutexProfileFraction are called — so an empty block profile means either nothing blocked or nothing was recording, and the profile cannot tell you which.

A record is a unique stack, not an event: 200 blocking sends collapse to single digits, and the counts are not even stable between runs. Read the accumulated delay, and report counts only as zero versus non-zero.

Both profiles record mutex contention, and the real distinction is attribution — measured, the block profile’s leaf is Mutex.Lock and the mutex profile’s is Mutex.Unlock. One blames the goroutine that suffered; the other blames the one that caused it.

Each has a shape of blindness: block is biased toward long waits, mutex sees only contended unlocks so a hot uncontended lock is invisible, and no blocking profile can see a goroutine that is running.

The two knobs are asymmetric — SetMutexProfileFraction returns the previous rate and reads with -1; SetBlockProfileRate returns nothing and has no getter — so anything that enables profiling temporarily can restore only half of what it changed.

And a profile diff shows growth rather than causation, and needs §19.2's labels to separate a leak from load.

Self-Check Questions: Profiles, and the Two That Are Empty

19.4 Always-On, and What It Costs You

Everything in §19.3 required a decision made in advance: enable this profiler, at this rate, before the thing you want to observe happens. Get that wrong and you have an empty profile and an incident that is over.

There is a whole class of instrument with no such requirement. runtime/metrics exposes counters the runtime maintains anyway, as part of doing its job. Reading them costs a function call. They are always correct, they were correct during the incident you missed, and — measured — runtime/metrics, like the goroutine labels in §19.2.3, appears in zero of the preceding eighteen chapters.

19.4.1 The Contention Number That Needs Nothing

// Illustrative snippet — not a complete program
s := []metrics.Sample{{Name: "/sync/mutex/wait/total:seconds"}}
metrics.Read(s)
total := s[0].Value.Float64()

That is the number §19.3.8 was pointing at. It is cumulative across the process lifetime, so the useful form is a rate: sample it twice and divide by the interval, and you have seconds of mutex wait per second, which is a directly interpretable saturation figure. Four seconds of accumulated wait per wall-clock second means roughly four goroutines are blocked on locks at any moment.

It cannot tell you which lock. That is exactly the division of labour this chapter keeps arriving at:

always on, free              searched on evidence
───────────────              ───────────────────
/sync/mutex/wait/total  ──►  the mutex profile
  "is there contention"        "which lock, and who held it"

                        ──►  the block profile
                               "who is waiting, and on what"

/sched/goroutines/       ──►  the execution trace
  runnable                     "what order did it happen in"
  "are we saturated"

A smoke detector cannot find the fire, and a search you
run continuously is not a search -- it is overhead.

The practical consequence is a two-tier design. Export the metric always. Enable the profiler when the metric says something is wrong — or, better, keep it enabled at a low sampling rate so it is there when you need it, which is a decision the metric lets you make with evidence.

19.4.2 Goroutines, Split by State

Recent runtimes split the goroutine count by scheduler state, and this is §19.4's best material. Confirm the exact set with metrics.All() on your toolchain — the list grows between releases:

runnable is the one that matters, and it is the cheapest possible signal for a saturated scheduler. A goroutine in that state has work to do, is not blocked on anything, and is not running — the only thing it lacks is a processor.

Two things are legible at a glance. running pins at exactly GOMAXPROCS — 16, because that is all the processors there are. And runnable is the queue: 113 goroutines that could run and cannot.

That distinction is what the total goroutine count hides. A service with 10,000 goroutines is completely healthy if they are all in waiting — blocked on network I/O, which is what a server does. The same 10,000 with a large runnable figure is CPU-saturated and every one of those goroutines is accruing latency for a request that has already arrived.

/sched/latencies:seconds is the histogram behind it: how long goroutines wait between becoming runnable and actually running. Under the saturation above, the mean was 13.66 ms.

19.4.3 The Version That Needs No Code At All

runtime/metrics requires you to have written a reader. There is a cruder view that requires nothing but an environment variable, and it shows one thing the metrics do not.

One line every 100 ms, to standard error, with no code change and no recompilation. idleprocs falling to 0 and runqueue climbing to 60 is §19.4.2's saturation seen from the runtime’s side.

The bracketed array is the part runtime/metrics does not give you: the per-processor run queue depths. In the second line, processors 7 and 8 have 35 and 34 goroutines queued while processor 6 has none — the work is real and it is not evenly spread. Persistent imbalance like that points at work that is not being stolen effectively, usually because goroutines are being created in a pattern the scheduler cannot rebalance.

19.4.4 Pauses, and the One You Caused Yourself

The runtime also measures its own stop-the-world pauses, and it does so with nothing enabled:

Two of these repay knowing.

stopping is a sub-phase of total, and their ratio is the interesting part. stopping is time spent waiting for every goroutine to actually reach a point where it can be stopped; total is the whole pause. When stopping approaches total, the collector is not slow — it is waiting on a goroutine that will not yield, which points at a tight loop with no preemption point rather than at the garbage collector. “It must be GC pauses” is a hypothesis, and this is how to check it for free before capturing anything.

other is where you find the pauses you inflicted on yourself. Non-GC stop-the-world events include goroutine profile collection — which is to say, §19.1.4's debug=2 dump appearing as a metric.

Five dumps, five pause events. The correspondence is exact — though not in the way the obvious follow-up experiment suggests. measured, the same five calls at debug=1 produce ten pause events, because the census stops the world twice per call rather than once. That does not reverse §19.2.2's advice: debug=1 is still far cheaper in wall time (112.9 ms against 913.3 ms at a hundred thousand goroutines) and still the one to reach for. It simply is not free, and a reader who repeats this measurement at the other debug level should get ten rather than conclude the chapter is wrong.

It closes a loop this chapter has been drawing since §19.1.4: your monitoring system’s periodic goroutine dumps are stop-the-world pauses that appear in your own pause metrics — and on a process holding a hundred thousand goroutines, §19.1.4 measured each one at 913 ms rather than the 57 µs above.

19.4.5 Reading Metrics Without Getting Them Wrong

Three mechanical points, each of which produces wrong numbers when missed.

Most are cumulative, not instantaneous. /sync/mutex/wait/total only increases. Reading it once tells you nothing; the information is in the difference between two reads and the time between them.

Check Kind before reading the value. metrics.Read fills a union, and a metric that does not exist on your build comes back as KindBad rather than an error:

// Illustrative snippet — not a complete program
if s[0].Value.Kind() == metrics.KindBad {
    // not supported on this toolchain -- do not read it
}

That matters here because the per-state goroutine breakdown is recent. Code that reads it unconditionally will get a zero on an older runtime and report a perfectly idle scheduler.

Read them in one batch. metrics.Read takes a slice and fills all of it from a consistent view. Separate calls for related metrics can straddle a change and produce a set that never simultaneously existed.

19.4.6 What This Adds to Chapter 17's Four Numbers

§17.7.5 argued for exporting four numbers about your limiter — admitted, rejected by reason, queue depth, wait-time p99 — on the grounds that a limiter reporting only its permitted rate cannot show you what it is holding.

This is the same argument one level down. Those four are about your admission control; these are about the runtime underneath it. And they compose in a specific and useful way: a rising /sched/goroutines/runnable with a healthy limiter says your admission control is working and the machine is simply out of processors, which is a capacity decision. A healthy runnable with a growing limiter queue says the opposite — the machine is fine and your own bound is the constraint.

Neither number can distinguish those cases alone. Together they do, for the cost of two counter reads.

19.4.7 Common Mistakes

Summary: Always-On, and What It Costs You

runtime/metrics exposes counters the runtime maintains anyway, so reading them costs a function call and they were correct during the incident you missed. Measured, they appear in zero preceding chapters.

/sync/mutex/wait/total reports accumulated mutex wait with no profiling enabled at all — the figure §19.3 kept pointing at. It cannot say which lock, which is the division of labour: cheap always-on metrics tell you whether, expensive on-demand profiles tell you where.

Recent runtimes split goroutines by scheduler state, and runnable — ready, not blocked, and not running — is the cheapest saturation signal available. Measured, 128 spinners on 16 processors gave running pinned at exactly 16 and runnable at 113, with a mean scheduling latency of 13.66 ms. The total count hides this: 10,000 goroutines in waiting is a healthy server, and the same 10,000 with a large runnable is a saturated one.

Read them as rates, check Kind before trusting a value, and batch the read. Together with §17.7.5's four numbers they separate “the machine is out of processors” from “my own limiter is the constraint” — a distinction neither can make alone.

Self-Check Questions: Always-On, and What It Costs You

19.5 The Execution Tracer: Order, Finally

Everything so far has thrown away ordering. A dump is one instant; a profile is a sum; a counter is a total. None of them can answer a question of the form “what happened between the request arriving and the response leaving” — and that is the shape of every question about an interleaving.

The execution tracer is the only view that keeps ordering. It records goroutine creation, blocking, unblocking, syscall entry and exit, garbage collection, and processor start and stop, each with a nanosecond timestamp and a stack. What comes out is a timeline rather than a summary.

Or from a running program, over the standard endpoint:

19.5.1 Three Questions Only the Tracer Answers

The tracer’s interface is large and its views are numerous, and it is easy to spend an afternoon in it without learning anything. It repays being pointed at specific questions.

“Was this goroutine slow, or was it never scheduled?” This is the tracer’s signature question, and no profile can answer it. A handler that takes 40 ms might have spent 40 ms working, or 2 ms working and 38 ms sitting in the run queue while sixteen processors were busy with something else. The CPU profile attributes the same samples either way; the block profile sees no blocking, because being runnable is not blocking. Only the timeline shows the gap between “became runnable” and “started running”. §19.4's /sched/latencies says this is happening somewhere; the trace says it happened to this request.

handler wall time: 40ms

runnable ───────────────────────────────►│ running │
|<--------------- 38ms ------------------>|<- 2ms ->|
     ready to run, but given no processor    working

the CPU profile sees:    2ms  -- it samples what is running
the block profile sees:  0    -- runnable is not blocked
the execution trace sees: both, and the gap between them

“What is stealing time from my handler?” Garbage collection is the usual answer and the tracer shows it directly: stop-the-world pauses appear as gaps across every processor at once, and the mark phase appears as assist work charged to goroutines that were merely trying to allocate. A latency spike that correlates exactly with a GC cycle is a memory problem wearing a concurrency costume, and this is where you see the correlation rather than infer it.

“What actually happened during this one slow request?” Aggregates cannot answer questions about individuals. The trace, combined with §19.6's tasks, can show a single request’s whole life — which goroutines it spawned, what each blocked on, in what order, and where the time went.

Everything else the tracer displays is real and mostly not worth your afternoon. Start from a question.

19.5.2 Measured: The Profiles Hidden Inside go tool trace

The tracer’s most useful output for concurrency is not the visual timeline at all, and it is the least known thing in this chapter. go tool trace will convert a trace into pprof-format profiles, including one that measures the quantity §19.4 could only count:

Twenty-eight seconds of scheduler delay, attributed to a call stack. That is time goroutines spent runnable and not running, broken down by the code that was waiting for a processor — and it is exactly the quantity the CPU, block and mutex profiles are all blind to (§19.5.1).

This closes the loop with §19.4. /sched/latencies gives you the distribution of that delay, always on, for nothing. -pprof=sched gives you the call stacks, on demand, for the price of a trace. The metric tells you scheduling delay is your problem; the trace tells you which code is paying it.

Four such profiles exist, and the other three matter:

They separate kinds of waiting that a single “blocking profile” conflates, and net reporting exactly zero on a workload with no network is a useful demonstration that they are measuring what they claim.

19.5.3 What It Costs, and Why the Honest Answer Is Two Numbers

The tracer’s overhead is quoted constantly and almost always without conditions, which makes the figure useless. The overhead is a function of how many events your program generates, and programs differ by orders of magnitude in that respect.

workload                        untraced    traced    ratio
───────────────────────────────────────────────────────────
channel ping-pong (unbuffered)  182.2 ns   426.1 ns    2.3x
TCP socket writes              20182   ns 22153   ns    1.10x

An independent run of the same shape measured 1.03x. The
claim is "a few percent", not a specific ratio -- so measure
your own workload rather than quoting either number.

The first is a ceiling constructed on purpose: an unbuffered channel send between two goroutines is nearly pure scheduler activity, so almost every nanosecond of work generates a trace event. Real code does not look like this, and quoting 2.3× as “the cost of tracing” is quoting the worst case as the typical one.

The second is closer to a service: goroutines that block on a socket, do a little work, and block again. Ten percent. The syscall dominates, the event rate per unit of work is far lower, and the tracer’s cost largely disappears into the noise of doing actual I/O.

That range is why §19.7 can seriously propose leaving a tracer running in production. At 2.3× nobody would. At 10% it is a straightforward trade against the cost of never being able to explain an incident — and 10% is what a service that blocks on things actually pays.

19.5.4 Reading a Trace Without Drowning

Two habits make the difference.

Start from the goroutine analysis, not the timeline. The landing page’s “Goroutine analysis” link gives a per-function breakdown of where goroutines spent their time — execution, scheduler wait, block time, syscall, GC assist. That table is closer to a profile than a timeline and it is the fastest way to find the goroutine worth looking at. Go to the timeline afterwards, having decided what to look for.

The scheduler latency profile is the one to fetch first. go tool trace can emit synthetic profiles from a trace, and the scheduler-wait one is the answer to §19.5.1's first question in aggregate form: which call sites spent the most time runnable-but-not-running. It is a profile that no runtime/pprof endpoint can produce, because the information only exists in a timeline.

And a caution that saves an afternoon: a trace of a busy service for five seconds is enormous, and the tool loads it into memory. Trace for one second, not thirty. If the thing you are chasing is rare, that is not a sampling problem to be solved with a longer trace — it is §19.7's problem.

19.5.5 Common Mistakes

Summary: The Execution Tracer: Order, Finally

The tracer is the only view that preserves ordering, which makes it the only one that can answer a question about an interleaving. It records goroutine transitions, syscalls, GC and processor activity with timestamps and stacks.

Three questions repay it: whether a goroutine was slow or merely never scheduled, what is stealing time from a handler, and what happened during one specific slow request. Everything else it displays is real and mostly not worth the afternoon.

Its cost is two numbers, not one. Measured, a channel ping-pong chosen to maximise scheduler events cost 2.3×; a workload blocking on a TCP socket cost 1.10×. The first is a deliberate ceiling and the second is closer to a service, and the factor of twenty between them is why “the tracer is too expensive for production” is a claim about a benchmark rather than about tracing.

Its least-known output is the most useful: go tool trace -pprof= converts a trace into pprof-format profiles for sched, sync, net and syscall. Measured, -pprof=sched attributed 28.65 s of runnable-but-not-running time to a call stack, which no standard profile records — and -pprof=sync recovers blocking attribution from a trace even when the block profiler was never enabled, which is §19.3.1's escape hatch.

Start from the goroutine analysis rather than the timeline, and trace for one second rather than thirty.

Self-Check Questions: The Execution Tracer: Order, Finally

19.6 Putting Your Own Events on the Timeline

A raw execution trace is a record of what the runtime did. It knows about goroutines, processors, syscalls and garbage collection, and it knows nothing whatsoever about requests, orders, tenants or retries. Which means that for a real service the timeline is precise, complete, and unreadable: thousands of goroutine transitions with no indication of which ones belong to the thing you are investigating.

runtime/trace fixes this with three functions, and they are the Go-native answer to what the original outline for this chapter called “logging and instrumentation strategies”.

19.6.1 Tasks, Regions, and Logs

// Illustrative snippet — not a complete program
ctx, task := trace.NewTask(ctx, "checkout")
defer task.End()

trace.Log(ctx, "order", orderID)

func() {
    defer trace.StartRegion(ctx, "validate").End()
    validate(ctx, order)
}()

func() {
    defer trace.StartRegion(ctx, "charge").End()
    charge(ctx, order)
}()

A task is a logical operation that may span goroutines. It is carried in the context, so anything that inherits the context inherits the task — including goroutines started downstream. That is what makes it the right tool for a request: the work does not stay on one goroutine, and a task follows it.

A region is an interval on one goroutine. It nests, it is cheap, and defer trace.StartRegion(ctx, name).End() is the whole idiom.

A log is a key-value pair attached to the task at an instant. It is how the identifier gets in.

The payoff is the tool’s task-oriented views. go tool trace will show you the distribution of checkout durations, let you pick the slow one, and display that request’s goroutines, blocking, and regions against the scheduler’s own events on one axis. That is the difference between a trace you can use on a service and one you can only use on a toy.

19.6.2 What This Replaces

The instinct, when a handler is mysteriously slow, is to add log lines with timestamps and subtract them afterwards. Tasks and regions are better on four counts, and it is worth being explicit because the log-line habit is deeply ingrained.

They cost almost nothing when tracing is off. A region is a check of whether tracing is enabled and an early return. A log line is a lock, a format, a write, and usually a syscall — paid on every request forever, whether or not anyone is debugging.

They are on the same axis as the scheduler’s events. Your timestamps and the runtime’s are in one timeline, so “my handler took 40 ms” and “38 of those were spent runnable” appear together. Correlating a log file with a trace by wall-clock timestamps is an exercise in clock-domain frustration.

They survive concurrency. A task follows the context across goroutines. Log lines from a request that fans out to eight goroutines interleave with every other request’s lines and have to be re-associated by an identifier you remembered to include in all of them.

They do not change the timing they measure. This is §19.1.6's point, and it is the important one. A log line in a hot path is a lock: it serialises goroutines that were not previously serialised, and it can hide the very interleaving you added it to observe. Regions are designed to be nearly free and to be free entirely when tracing is off.

19.6.3 The Same Idea, Twice

This is the second time the chapter has said decide in advance, and the symmetry is worth naming rather than leaving implicit.

artifact         annotation       read with
────────         ──────────       ─────────
goroutine dump   pprof labels     debug=1 census (any
                 (19.2.3)         traceback from go 1.27)

execution trace  tasks, regions,  go tool trace,
                 logs (19.6.1)    task and region views

Neither can be added after the incident, and both
turn "some goroutines" into "this tenant's
re-index, in its query phase".

They are separate mechanisms with no overlap: a pprof label does not appear in a trace, and a trace task does not appear in a dump. A service that wants both artifacts readable has to add both — which is perhaps forty lines in one middleware, written once, and the difference between an incident you can describe and one you can only measure.

19.6.4 What to Instrument

The useful rule is that regions should map to decisions, not to functions.

Wrapping every function in a region produces a trace as unreadable as the raw one, with extra overhead. What you want are the boundaries where a request could plausibly stall: the acquire of a limiter or semaphore, a downstream call, a lock held across real work, a batch flush. Those are the places where a region’s start and end will differ by something interesting, and they are the same places Chapter 17 told you to bound and Chapter 15 told you to drain.

For a service, a workable default is one task per inbound request, one region per outbound dependency call, one region per contended resource acquisition, and a log for the identifiers you would need to correlate with anything else — request, tenant, job.

And they compose with §19.2.3's labels, which is worth noticing because they look redundant and are not. Labels attach to goroutines and are visible in profiles and the goroutine census. Tasks attach to contexts and are visible in traces. Setting both from the same place at the start of a request means an incident dump and an execution trace can be talked about in the same vocabulary — the same tenant, the same job type, named identically in two different instruments.

19.6.5 Common Mistakes

Summary: Putting Your Own Events on the Timeline

A raw trace records what the runtime did and knows nothing about requests, which makes it precise and unreadable on a real service. Tasks, regions and logs add your vocabulary to the runtime’s.

A task is a logical operation carried in the context, so it follows work across goroutines; a region is an interval on one goroutine; a log is a key-value pair at an instant. Measured, all three survive a round trip through go tool trace.

They replace timestamped log lines on four counts: near-zero cost when tracing is off, the same axis as scheduler events, survival across goroutine boundaries, and — most importantly — not changing the timing they measure. A log line takes a mutex, and adding one to a racy path serialises goroutines that were not previously serialised.

Instrument decisions rather than functions: limiter acquisitions, downstream calls, locks held across real work. And set goroutine labels from the same place you create the task, so that a dump and a trace can be discussed in one vocabulary.

Self-Check Questions: Putting Your Own Events on the Timeline

19.7 The Trace You Were Not Recording

Every technique so far has one of two problems. The cheap ones — dumps, profiles, counters — throw away ordering, so they cannot describe an interleaving. The one that keeps ordering costs too much to leave on, so it is never running when the interesting thing happens.

That is the bind the chapter opened with, and it is the reason “it happened once at 03:14” is the hardest category in §19.1.7's triage. You cannot start a tracer in response to an event that has already finished.

runtime/trace.FlightRecorder, added in Go 1.25, is the way out. It keeps a moving window of execution trace in memory — always the most recent few seconds — and writes it out only when you ask. You do not have to predict when the interesting thing will happen. You have to be able to recognise it afterwards, which is a much easier problem.

19.7.1 The Shape

// Illustrative snippet — not a complete program
fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{
    MinAge:   5 * time.Second,   // keep at least this much history
    MaxBytes: 8 << 20,           // a hint; see §19.7.3
})
if err := fr.Start(); err != nil {
    log.Fatal(err)
}
defer fr.Stop()

// ... later, in the code that notices something is wrong:
if latency > slo {
    f, _ := os.Create("incident.trace")
    n, err := fr.WriteTo(f)   // the last MinAge seconds
    f.Close()
    log.Printf("captured %d bytes of trace: %v", n, err)
}

t-30s            t-5s                      now
  │                │                         │
  │                ├──────── kept ───────────┤   MinAge = 5s
  ├─── dropped ────┤                         │
                                             ▲
                                  the trigger fires here:
                                  WriteTo() the last 5s

You do not predict the moment, you recognise it afterwards
-- and by then the window it needed is already behind you.

That is the whole mechanism, and the interesting part is the trigger rather than the API. The recorder runs continuously; something in your code has to decide that now is the moment worth keeping. Good triggers are the ones you already have: an SLO breach, a health check failing, a request exceeding its deadline, a circuit breaker opening (§17.6), a shutdown taking longer than its budget (§15.7).

19.7.2 It Is Not the Cheap Option

The universal assumption about the flight recorder is that it is a lightweight alternative to full tracing. It is not, and this is the section’s most useful finding.

The two tracing modes are statistically indistinguishable. That makes sense once stated: the flight recorder does not trace less, it traces exactly as much and throws away the oldest data instead of writing it out. The runtime is generating the same events either way.

What the flight recorder saves is storage, and the decision of when to start — which are the two things that actually prevented you from having a trace of the incident. It does not save CPU.

And §19.5's second measurement is what makes that acceptable. The 2.36× is the scheduler-heavy ceiling; a workload that blocks on a socket paid 1.10×. Leaving a flight recorder running on a service that spends its time in network calls costs on the order of ten percent, permanently, in exchange for being able to explain any incident you can recognise. That is a real trade with a real price, and it is a very different conversation from 136 percent.

19.7.3 MaxBytes Is a Hint, Not a Bound

The configuration has a MaxBytes field, and it does not do what its name suggests. The documentation is honest — it says to treat the value as a hint — and the size of the discrepancy is worth knowing before you size a disk or a network payload from it.

The overshoot is not a fixed factor. It scales with the event rate, because the window is defined primarily by MinAge — a duration — and a busy program simply generates more bytes in that duration. An independent run at a lower load produced roughly 2×. So the durable claim is the qualitative one:

The companion constraint: at most one flight recorder may be active in a process.

19.7.4 Two Errors, and Why the Difference Matters

Start fails in two distinguishable ways, and telling them apart is a diagnostic you cannot get any other way.

The first says you double-started: a bug in your own initialisation, usually a retry or a duplicated setup path.

The second says something else. Only one recorder may be active process-wide, so this error means another component in this process already owns it — an APM agent, a profiling sidecar library, a framework’s debug mode, something a dependency enabled without telling you. That is a fact about your process you have no other way to discover, and it explains an otherwise baffling situation: your flight recorder never captures anything, because it never started, because a library beat you to it.

19.7.5 Wiring It Up

Three practical points, in the order they bite.

Set MinAge from what you need to see, not from what feels tidy. The window must cover the interval before the trigger fires, because the trigger is a consequence and the cause is earlier. If your SLO breach is detected when a request completes at 800 ms, a 1-second window may already have discarded the beginning of that request. Five seconds is a reasonable default; think in terms of the longest causal chain you might need to look backwards through.

The trigger must be cheap and must not fire continuously. WriteTo is not free and a service that captures on every slow request will spend its time writing traces. Rate-limit the capture — one per minute is generous — which is Chapter 17's machinery pointed at your own diagnostics.

Capture on the way out, not on the way in. The natural place is wherever you already decide something went wrong: the error path, the deadline check, the breaker’s transition to open. Those places have the context to name the capture usefully, and §19.6's task identifiers are what make the resulting trace searchable.

19.7.6 A Worked Investigation, End to End

Everything in this chapter is a piece of one procedure. Here it is on a single symptom, with the perturbation ladder climbed one rung at a time and stopped as soon as it answers.

The report. “Checkout is slow. Started around 14:00. No errors.”

Rung 1 — the always-on numbers (§19.4), a few hundred nanoseconds. Before capturing anything, read what is already there:

That is a complete triage in one read, for the cost of a memory load. runnable is zero and scheduler latency is unchanged, so you are not CPU-saturated — which rules out the most common guess and saves a wasted GOMAXPROCS change. Mutex wait is flat, so it is not lock contention. pauses/total/other is zero, so nobody’s monitoring is stopping you (§19.4.4). And waiting has grown by an order of magnitude: goroutines are accumulating in a blocked state.

Rung 2 — the snapshot (§19.2), one HTTP call. debug=1, because it aggregates, it carries labels, and §19.1.4 measured it at an eighth of the cost of the full dump on a process this size:

Nearly four thousand goroutines at one line, all blocked, all labelled. The labels are doing exactly what §19.2.3 promised — without them this is 3,891 identical stacks with no indication of whose work it is, and below go 1.27, with debug=2 you would not have them at all.

Rung 3 — is it growing? (§19.3.6), one more profile. Five minutes later, and subtract:

Still climbing. That is the difference between a busy period that will drain and a leak that will not — between waiting and paging someone.

Rung 4 — what are they waiting on, and for how long (§19.3). The stack says payment.go:112; the block profile would say how long each wait lasts. If nobody enabled it — which §19.3.1 says is the default — you do not have to deploy anything to find out: capture a five-second trace and run go tool trace -pprof=sync (§19.5.2). Same attribution, no restart, at 2 a.m.

What was never needed. No debugger, because nothing was worth stopping and stopping it would have cost the schedule (§19.1.6). No CPU profile, because runnable=0 had already established the time was not being spent on a processor. No stress harness, because the failure was happening continuously in front of us — Chapter 16's tooling is for the failures that are not.

And the one case where all of it fails. If this had been a transient stall — three seconds at 03:14, recovered on its own, gone before anyone looked — every rung above would have been useless, because all of them require the problem to be happening while you look. That is the case this section exists for.

metrics    ~300 ns   │ is anything wrong, and what kind?
dump       ~ms-1s    │ where is everyone?
diff       2 dumps   │ is it growing?
profile    enable    │ how long, and blamed on whom?
trace      seconds   │ in what order, and against what?
debugger   stops it  ▼ what are the actual values?

Each rung costs more and answers a narrower
question. Stop as soon as you have the answer.

19.7.7 A Capture Without Tasks Is Nearly Unreadable

There is a failure mode specific to flight recording that does not arise with a deliberate trace, and it is worth anticipating because you discover it at the worst moment.

When you start a trace by hand you already know what you are investigating. You started it because a particular endpoint was slow, you ran the thing that makes it slow, and you stopped it. The trace is a few seconds long and every goroutine in it is plausibly relevant.

A flight recording is the opposite. It fires on a trigger, it contains whatever the whole process was doing for the last several seconds, and the request that breached the SLO is one of perhaps ten thousand things in it. You have the ordering — which is what you could not get any other way — and no way to find the part you care about.

§19.6's tasks are what make it navigable, which is why the two sections are adjacent. With one task per request, go tool trace's task view gives a duration distribution, you pick the outlier, and you get that request’s goroutines, regions and blocking against the scheduler’s own events. Without them you get a correct, complete, unsearchable timeline.

So the deployment order matters: instrument first, record second. A service that adds a flight recorder before it adds tasks has bought the ability to capture an incident it will not be able to read.

Two smaller things follow from the same observation.

Log the trigger alongside the capture. The file is useless six months later if nobody wrote down why it was taken. One log line naming the trigger, the request identifier and the file path costs nothing and is the difference between an artefact and a diagnosis.

Name the capture after the thing that fired it. incident-<trigger>-<request-id>-<timestamp>.trace lets you correlate with the logs that made you take it, which is where §19.6's shared identifier pays off a second time.

19.7.8 Common Mistakes

Summary: The Trace You Were Not Recording

The cheap views discard ordering and the view that keeps ordering costs too much to leave on — which is why the hardest category of incident is the one that is already over. The flight recorder resolves it by keeping a moving window in memory and writing it out on a trigger, so you no longer have to predict the moment, only recognise it afterwards.

Measured, it is not the cheap option: 429.8 ns/op with the flight recorder against 426.1 with full tracing and 182.2 untraced. It traces exactly as much and discards the oldest data. What it saves is storage and the decision of when to start — which are precisely the two things that stopped you having a trace. Its acceptability rests on §19.5's other number: 1.10× on a workload that blocks on a socket.

MaxBytes is a hint and overshot by 26× at high event rates, so size for the event rate rather than the field. Only one recorder may be active, and the two Start errors distinguish “you double-started” from “something else in this process already owns it” — a fact about your process available no other way.

Set MinAge to cover the causal chain, rate-limit the trigger, and capture where you already decide something went wrong. And instrument before you record: a flight recording without §19.6's tasks contains the ordering you could not otherwise get, in a form you cannot search.

Self-Check Questions: The Trace You Were Not Recording