Go Perf Execution Tracer

Go Execution Tracer

"The magic of a trace is that it can easily reveal things about a program that are hard to see in other ways. … a concurrency bottleneck where lots of goroutines block on the same channel … in an execution trace, the lack of execution will show up with amazing clarity." — Michael Knyszek, More powerful Go execution traces

The execution tracer answers a different question than a profiler. A CPU profile ranks on-CPU work; the tracer reconstructs the timeline of what every goroutine, processor, and the runtime did, so it sees the off-CPU gaps — blocked on a channel, parked behind a syscall, waiting for the scheduler, stalled in GC. Which diagnostic answers which question is go-perf-methodology's tool-selection matrix; this skill owns the tracer end to end. All Go below builds clean under gofmt/go vet on Go 1.25/1.26.

1. The Tracer Is Not a Profiler — When to Reach for It

The tracer "captures a wide range of runtime events. Scheduling, syscall, garbage collections, heap size, and other events are collected by runtime and available for visualization by go tool trace" (Diagnostics). It records "goroutine creation/blocking/unblocking, syscall enter/exit/block, GC-related events, changes of heap size, processor start/stop, etc. A precise nanosecond-precision timestamp and a stack trace is captured for most events" (runtime/trace).

The decisive boundary — the tracer is for latency, parallelism, scheduling, and GC behavior, not for hot spots: "it is not great for identifying hot spots such as analyzing the cause of excessive memory or CPU usage. Use profiling tools instead first to address them" (Diagnostics). Reach for the tracer when:

• a request is slow sometimes and a CPU profile shows nothing (the time is spent off CPU);
• a parallel workload won't scale — cores sit idle while work waits;
• goroutines pile up or block on one channel / lock and you want to see the wait;
• you suspect scheduler latency (runnable→running delay) or GC pauses / mark-assist stealing time;
• you need per-request latency breakdown via user tasks/regions (§5).

Hot-spot hunting (where CPU/heap time goes) → go-perf-pprof-profiling. Contention attribution by lock → go-perf-block-mutex-profiles. GC knob tuning → go-perf-gc-tuning.

2. Collecting a Trace — Three Entry Points

(a) In a benchmark or test — the cheapest way to capture a bounded trace:

go test -bench=. -trace=trace.out   # or -trace alone for the test run
go tool trace trace.out             # opens the web UI on a local port

(b) Programmatically with runtime/trace — Start "enables tracing … the trace will be buffered and written to w"; Stop "only returns after all the writes for the trace have completed" (runtime/trace):

f, err := os.Create("trace.out")
if err != nil {
	log.Fatal(err)
}
defer f.Close()

if err := trace.Start(f); err != nil {
	log.Fatal(err)
}
defer trace.Stop()
// ... the code whose timeline you want ...

(c) From a live server via net/http/pprof — import _ "net/http/pprof", then pull a fixed window:

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

The seconds=N endpoint traces for N seconds and streams the result — the production way to grab a window without a code change. Treat that debug port as privileged: never expose net/http/pprof on a public listener (depth → go-perf-pprof-profiling).

3. Reading go tool trace — Which View Answers Which Question

go tool trace trace.out serves a local web UI (cmd/trace). The views, mapped to the question each answers:

The trace viewer ("View trace") page "comes from the Chrome/Chromium project and is only actively tested on that browser" — the derived profiles work on every browser (cmd/trace). The reflex on opening a trace: go to Goroutine analysis first to see what state time is spent in, then the timeline to see when the gaps occur.

4. Deriving pprof Blocking Profiles From a Trace

The same trace yields four pprof-format blocking profiles without re-running anything — the trace already contains every block event (cmd/trace):

go tool trace -pprof=sched   trace.out > sched.pprof    # scheduler latency
go tool trace -pprof=syscall trace.out > syscall.pprof  # time blocked in syscalls
go tool trace -pprof=net     trace.out > net.pprof      # network blocking
go tool trace -pprof=sync    trace.out > sync.pprof     # synchronization blocking
go tool pprof sync.pprof                                # then top/list/web as usual

This is the bridge between the tracer's timeline and pprof's call-tree ranking: the timeline tells you a stall exists and when; these profiles tell you which call stacks account for the blocked time, with familiar top/list ergonomics. (This is trace-derived network/syscall/sched blocking; the rate-gated block/mutex profiles from runtime.SetBlockProfileRate/SetMutexProfileFraction are a different mechanism — go-perf-block-mutex-profiles.)

5. User Annotation — Regions, Tasks, Logs (App-Level Latency)

Raw runtime events show how goroutines ran but not what they were doing in your domain. Three runtime/trace APIs (all Go 1.11) overlay application structure onto the timeline (runtime/trace):

func handleRequest(ctx context.Context, req *Request) {
	// A task spans a logical operation; tracer measures task latency as the
	// time between NewTask and Task.End, with a latency distribution per type.
	ctx, task := trace.NewTask(ctx, "handleRequest")
	defer task.End()

	// A region marks a code span within the calling goroutine. Region.End
	// must run on the same goroutine; regions must nest.
	defer trace.StartRegion(ctx, "decode").End()

	trace.Log(ctx, "userID", req.UserID) // a one-off keyed event on the timeline
	// ...
}

• NewTask "creates a task instance … The trace tool measures task latency as the time between task creation and when the End method is called, and provides the latency distribution per task type" (runtime/trace). A task can cross goroutines (carried in the context), so it captures an end-to-end request.
• StartRegion/Region.End (or the callback form WithRegion) mark a span "associated with its calling goroutine"; End "must be called from the same goroutine where the region was started. Within each goroutine, regions must nest" (runtime/trace). Use the defer trace.StartRegion(ctx, "name").End() idiom.
• Log/Logf "emits a one-off event with the given category and message"; keep categories to "a handful of unique" values (runtime/trace).

Keep regionType/taskType/category to a bounded, small set of constant strings — the analysis tools "may assume there are only a bounded number of unique task types" (runtime/trace). A high-cardinality label (a per-request ID as the type) defeats the per-type aggregation; put that in a Log value instead. Without these annotations the User-defined-tasks view is empty and the timeline is unreadable on a real service.

6. The Flight Recorder — Capture the Seconds Before the Problem (Go 1.25)

The classic bind: rare latency spikes are exactly what you can't trace, because you don't know when to start tracing, and tracing continuously to disk is too expensive. The flight recorder inverts this: it "continuously records the trace into an in-memory ring buffer," and "when a significant event occurs, a program can call FlightRecorder.WriteTo to snapshot the last few seconds of the trace to a file" (Go 1.25 release notes). It is "like a scalpel cutting directly to the problem area" — you keep only the trace that matters, the window leading up to the anomaly (Flight Recorder in Go 1.25).

Version fact (verified): trace.FlightRecorder landed in the standard library runtime/trace in Go 1.25.0 (runtime/trace, Go 1.25 release notes, blog, 26 Sep 2025). Before 1.25 it was experimental in golang.org/x/exp/trace (execution-traces-2024) — if you target ≤1.24, that is the import path, and the API differs.

fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{
	MinAge:   2 * time.Second, // retain ~this much window; set ~2x your event's time scale
	MaxBytes: 10 << 20,        // hint/cap on buffer size; ~a few MB/s, ~10 MB/s for a busy service
})
if err := fr.Start(); err != nil {
	log.Fatal(err)
}
defer fr.Stop()

// In a request path, snapshot once when an anomaly trips:
if fr.Enabled() && time.Since(start) > 100*time.Millisecond {
	go snapshotOnce(fr) // WriteTo a file; guard with sync.Once so one spike writes one trace
}

• WriteTo "snapshots the moving window tracked by the flight recorder"; "only one goroutine may execute WriteTo at a time" (runtime/trace). Open the resulting file with go tool trace exactly like any other trace.
• MinAge is "a lower bound on the age of an event in the … window"; MaxBytes "takes precedence over MinAge … Treat it as a hint" (runtime/trace). Set MinAge to roughly 2× the timescale of the event you're hunting (blog).
• Constraint: "currently only one flight recorder may be active in the program," though it "is allowed to be concurrently active with a trace consumer using trace.Start" (runtime/trace).

This is the right tool the instant the symptom is "it spikes once an hour and I can never catch it." Tail-latency methodology (p99/p999, coordinated omission) → go-perf-tail-latency.

7. Overhead — Why Continuous Tracing Became Viable

Pre-1.21, tracing cost "somewhere between 10–20% CPU for many applications, which limits tracing to situational usage." Work on traceback efficiency "cut [it] dramatically, down to 1–2% for many applications," and trace splitting (the runtime can self-contained-split a trace at any time) "landed in Go 1.22 and is now generally available" (execution-traces-2024). That low overhead plus splittability is precisely what made the flight recorder (§6) implementable. Practical consequence: a bounded trace (a few seconds via seconds=N, or a flight-recorder snapshot) is cheap; leaving full trace.Start running forever still writes the entire firehose to your io.Writer — use the windowed forms, not an always-on trace.Start (§10).

8. A Worked Reading — "Poor Parallelism"

A CPU-bound batch job pins one core while seven idle. CPU profile: "looks busy in compute." That's a dead end — the idle cores are the symptom, and idleness has no CPU samples. The trace reading:

1. go test -bench=BatchProcess -trace=trace.out → go tool trace.
2. Goroutine analysis: workers spend most time in block (chan), not execution → they're starved, not slow.
3. Timeline: a single producer goroutine runs continuously while consumers sit idle between bursts → the producer is the serial bottleneck (Amdahl's serial fraction made visible).
4. Fix the fan-out / buffering, re-trace, confirm the idle gaps closed. The throughput fix (pool sizing, batching) → go-perf-worker-pools-throughput; scheduler internals → go-perf-goroutines-scheduler.

The point: the answer was in the absence of execution, which only the tracer renders.

9. Don't

• Don't reach for the tracer to find a CPU/heap hot spot — it "is not great for identifying hot spots … Use profiling tools instead first" (Diagnostics). Hot spots → go-perf-pprof-profiling.
• Don't leave full trace.Start running continuously — it writes the whole event firehose to your writer. For ongoing capture use the flight recorder ring buffer (§6) or a bounded seconds=N window.
• Don't call Region.End on a different goroutine than StartRegion, and don't let regions cross without nesting — End "must be called from the same goroutine … regions must nest" (runtime/trace).
• Don't use high-cardinality task/region/category names — the tools assume "a bounded number of unique task types"; per-request IDs belong in a Log value, not the type (runtime/trace).
• Don't assume trace.FlightRecorder exists pre-1.25 — it's stdlib runtime/trace from 1.25.0; on ≤1.24 it's experimental golang.org/x/exp/trace (Go 1.25, execution-traces-2024).
• Don't run a second flight recorder — "currently only one flight recorder may be active in the program" (runtime/trace).
• Don't trust the "View trace" page on a non-Chromium browser — only the derived -pprof profiles are cross-browser (cmd/trace).
• Don't collect a trace and a precise memory profile in the same run — diagnostics interfere; "use tools in isolation" (Diagnostics).
• Don't expose /debug/pprof/trace on a public port — it's a privileged endpoint (safety → go-perf-pprof-profiling).

10. Routing to Related Skills

This plugin (go-perf-* depth):

• go-perf-methodology — the tool-selection matrix: tracer vs profiler vs block/mutex vs gctrace; read first.
• go-perf-pprof-profiling — CPU/heap hot-spot hunting, net/http/pprof safety, labels, differential profiling.
• go-perf-block-mutex-profiles — the rate-gated block/mutex/goroutine profiles (distinct from trace-derived blocking profiles).
• go-perf-goroutines-scheduler — GMP/work-stealing internals, GODEBUG=schedtrace, container-aware GOMAXPROCS (1.25).
• go-perf-gc-tuning — acting on GC events the trace reveals: GOGC/GOMEMLIMIT, pacer, allocation rate.
• go-perf-tail-latency — p99/p999, coordinated omission; the flight recorder is how you capture a tail incident.
• go-perf-worker-pools-throughput — fixing the poor-parallelism the trace exposes (sizing, batching, fan-out).

Parent / sibling marketplace (go-* correctness):

• go-performance — the measure-first overview; this skill is the tracer leaf under it.
• go-concurrency-goroutines — goroutine lifetime/leak correctness (the tracer shows the cost/blocking).
• go-version-feature-map — version floors: low-overhead tracer 1.21–1.22; flight recorder stdlib 1.25.

11. Reference Files

Tracer anti-patterns in LLM-generated Go, each wrong/right with citations:

references/common-mistakes.md

Source provenance for every claim in this skill:

references/sources.yaml