Execution Tracer¶

When profiles are not enough¶

A CPU profile aggregates: it tells you how much CPU each function used in total, and nothing about when. Latency problems are about when: a request that was runnable but waited 40 ms for a CPU, a GC cycle that drafted the handler into mark assist, a goroutine blocked on a mutex while the holder did a syscall. The execution tracer records events — goroutine creation, start, stop, block, unblock, syscalls, GC phases, heap size, processor start and stop — with nanosecond timestamps, so you can see what each goroutine and each P was doing at every moment.

Since Go 1.21–1.23 the tracer was rebuilt: overhead dropped to around 1–2% of CPU, traces became splittable and streamable, and Go 1.25 added the flight recorder, which makes always-on tracing in production practical.

Measurements: Go 1.26.4, Apple M1 Pro, 8 Ps.

Collecting a trace¶

go test -run=TestX -trace=trace.out ./pkg                      # from a test or benchmark
curl -o trace.out 'http://host:6060/debug/pprof/trace?seconds=5'   # from net/http/pprof
go tool trace trace.out                                        # opens the web UI

Programmatically:

f, _ := os.Create("trace.out")
trace.Start(f)
defer trace.Stop()

Traces are large (megabytes per second per busy P); collect a few seconds around the behavior you want, not minutes.

What the UI shows¶

• Timeline per P (and per thread): which goroutine ran on each P at each instant, GC phases, syscalls. Gaps on a P mean it was idle.
• Goroutine analysis: for each goroutine group (by start function), the breakdown of its lifetime: execution, network wait, sync block (mutexes, channels), syscall, and scheduler wait — runnable but not running.
• Profiles derived from the trace, also available on the command line: go tool trace -pprof=TYPE trace.out > TYPE.pprof with TYPE one of net, sync, syscall, sched. Each is a pprof profile of time spent waiting, attributed to the stack where the goroutine waited — the off-CPU complement to the CPU profile.
• User annotations: regions, tasks, and logs you add with runtime/trace.

Scheduler latency: the number that explains "slow under load"¶

The time a goroutine spends runnable but not running is scheduler latency. It is near zero when Ps are available, and grows without bound once offered CPU load exceeds capacity — the run queues act like any other queue (Load Testing and Tail Latency).

Experiment: requests arrive at a steady rate, each burning exactly 1 ms of CPU in its own goroutine, at 50%, 90%, and 110% of the 8 Ps' capacity. Request latency is measured end to end; scheduler latency comes from the runtime's own histogram (/sched/latencies:seconds in runtime/metrics, which is cheap enough to export from every service):

Offered load	Request p50	Request p99	Scheduler latency p50	Scheduler latency p99
50%	1.01 ms	1.06 ms	5 µs	57 µs
90%	1.01 ms	1.93 ms	10 µs	786 µs
110%	44 ms	124 ms	42 ms	134 ms

At 90% load the median is untouched but p99 almost doubles; at 110% the work does not fit, runnable goroutines pile up, and every request waits — the request takes 1 ms of CPU and 43 ms of queueing. No CPU profile shows this: the profile at 110% looks just like the profile at 50%, with more samples. The trace (and the scheduler latency metric) shows it directly.

go tool trace -pprof=sched on a trace of this run attributes the waiting to where goroutines were descheduled — 91% inside time.Now in the CPU-burning loop, i.e. goroutines preempted mid-work and waiting for a P to resume. In a real service the stacks show which handlers are queueing.

Annotating with tasks and regions¶

Out of the box, the trace knows goroutines, not requests. Annotations connect them:

func handle(ctx context.Context, req *Request) {
    ctx, task := trace.NewTask(ctx, "handleRequest") // one logical operation, may span goroutines
    defer task.End()
    trace.Log(ctx, "tenant", req.Tenant)

    trace.WithRegion(ctx, "decode", func() { decode(req) })   // a timed span on this goroutine
    trace.WithRegion(ctx, "query", func() { query(ctx, req) })
}

The UI then lists tasks with their latency distribution, and for a slow task shows every region and every goroutine event that belonged to it — "this request spent 30 ms in query, of which 28 ms blocked on a channel receive from the connection pool".

The flight recorder (Go 1.25)¶

The hardest latency bugs happen rarely and unpredictably: by the time someone starts trace.Start, the moment is gone. The flight recorder keeps the tracer running continuously into an in-memory ring buffer holding only the last few seconds; when the program detects something interesting, it writes that window out.

fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{
    MinAge:   5 * time.Second, // keep at least the last 5 s of events
    MaxBytes: 16 << 20,        // but cap the buffer around 16 MB
})
if err := fr.Start(); err != nil {
    log.Fatal(err)
}

var once sync.Once
func observe(latency time.Duration) {
    if latency > 500*time.Millisecond {
        once.Do(func() { // capture the first incident, not a storm of them
            f, _ := os.Create("slow-request.trace")
            defer f.Close()
            fr.WriteTo(f)  // the last ~5 s, including the slow request
        })
    }
}

In the experiment above, a flight recorder running across all three load levels produced a 322 KB snapshot that go tool trace reads like any other trace. Typical triggers: a request exceeding its latency SLO, a health check failing, a panic recovery, an operator hitting an admin endpoint. Combined with a continuous profiler, this gives you both the aggregate (profiles) and the moment (trace) of an incident you were not watching.

Reading a trace: a checklist¶

1. Are Ps idle while requests are slow? Then the problem is waiting, not CPU: look at the goroutine analysis for sync block, network, and syscall time.
2. Are all Ps busy and scheduler wait high? CPU saturation: the fix is less CPU per request or more capacity, not tuning.
3. Is a GC cycle overlapping the slow requests? Look for mark assist slices on the request goroutines, and STW pauses on the timeline. Long assists mean allocation pressure (Garbage Collector).
4. Long syscalls? A goroutine in a syscall for milliseconds holds a thread; if many do, the runtime creates threads (Runtime Scheduler).
5. One goroutine blocking many? A long "sync block" on many goroutines that ends at the same instant points to a single lock holder; find what it was doing at that instant on the timeline.

Common pitfall¶

Diagnosing tail latency from averages and CPU profiles. A service's p99 rises from 20 ms to 300 ms during daily peaks. CPU utilization averages 70%, the CPU profile is unchanged, and the team concludes the code is fine and suspects the network. A five-second trace during the peak shows every P busy in bursts — traffic is bursty at the millisecond scale, so a 70% one-minute average hides many 100%+ intervals in which runnable goroutines queue for tens of milliseconds. Exporting /sched/latencies:seconds would have shown this all along. Averages over seconds or minutes hide saturation that lasts milliseconds; scheduler latency, measured by the runtime itself, does not.

Review questions¶

1. What can the execution tracer show that a CPU profile cannot, for a request that is slow only under load?
2. Define scheduler latency. Why did it jump from 786 µs at 90% load to 134 ms at 110%?
3. What does go tool trace -pprof=sched attribute, and to which stacks?
4. What problem does the flight recorder solve, and what makes a good trigger for writing it out?
5. Why can a service at 70% average CPU still have runnable goroutines waiting tens of milliseconds?