The Execution Tracer in Go for Hunting Latency Problems

A CPU profile tells you where the processor went. It says nothing about the time a request spent doing nothing: waiting on a lock, a channel, the network, a syscall, or for the scheduler to give it a processor. Most latency problems in Go services are waiting problems. The tool that sees them is the execution tracer, which records every goroutine state change with nanosecond timestamps. This article runs a service-shaped experiment with a deliberately bad lock, traces it, turns the trace into profiles you can read in a terminal, finds the offending line, fixes it, and ends with the Go 1.25 flight recorder, which captures a trace only when something goes wrong.

It extends CPU profiling and flame graphs with the waiting side, and it complements the earlier tracer article and the mutex and block profiles. Tail latency, the thing it helps explain, is the subject of where p99 comes from. The cornerstone is the Go performance guide.

What the tracer records

When tracing is on, the runtime writes an event each time a goroutine is created, becomes runnable, starts or stops running, blocks, unblocks, makes a system call or does network I/O, and at garbage collection phases and processor handoffs. From that stream you can reconstruct, for any goroutine, how long it ran, how long it was runnable but not running, and how long it was blocked and on what.

Compare with the other profiles:

The cost is volume. A trace of a busy program is large, and recent Go versions keep the overhead low (the Go team describes it as small, and you should measure it on your service), so you trace seconds, not hours. Capture one with trace.Start(f) and trace.Stop(), with go test -trace trace.out, or from a running service with curl -o trace.out 'http://host:6060/debug/pprof/trace?seconds=5' (securing the endpoint).

The experiment

The program models a service with a cache in front of a slow remote call. 64 goroutines each make 200 requests. 30 percent of the keys are new and need the remote fetch (500 microseconds), and 70 percent repeat. The first version, getSlow, holds the cache's mutex while it fetches on a miss. The second, getFast, releases the lock for the fetch and takes it again to store. The program prints per request latency percentiles for both. In trace mode it traces the slow version, and in flight mode it uses the flight recorder.

package main

import (
	"fmt"
	"os"
	"runtime/trace"
	"sort"
	"sync"
	"time"
)

type cache struct {
	mu   sync.Mutex
	data map[int]int
}

// remote stands in for a database or an API call.
func remote(k int) int {
	time.Sleep(500 * time.Microsecond)
	return k * 2
}

// getSlow holds the lock while it fetches, so every miss stalls every other request.
func (c *cache) getSlow(k int) int {
	c.mu.Lock()
	defer c.mu.Unlock()
	if v, ok := c.data[k]; ok {
		return v
	}
	v := remote(k)
	c.data[k] = v
	return v
}

// getFast fetches without the lock and takes it only to read and store.
func (c *cache) getFast(k int) int {
	c.mu.Lock()
	v, ok := c.data[k]
	c.mu.Unlock()
	if ok {
		return v
	}
	v = remote(k)
	c.mu.Lock()
	c.data[k] = v
	c.mu.Unlock()
	return v
}

// onSlow is called by any request slower than 30 ms; the flight recorder mode uses it to save the trace.
var onSlow func(time.Duration)

func percentile(ds []time.Duration, p float64) time.Duration {
	return ds[int(float64(len(ds)-1)*p)]
}

func run(get func(*cache, int) int) (p50, p99, max time.Duration, total time.Duration) {
	c := &cache{data: map[int]int{}}
	var mu sync.Mutex
	var all []time.Duration
	var wg sync.WaitGroup
	start := time.Now()
	for g := 0; g < 64; g++ {
		wg.Add(1)
		go func(g int) {
			defer wg.Done()
			var mine []time.Duration
			for i := 0; i < 200; i++ {
				// 70 percent of keys repeat, 30 percent are new.
				k := i % 7
				if i%10 < 3 {
					k = 1000 + g*1000 + i
				}
				t := time.Now()
				get(c, k)
				d := time.Since(t)
				if d > 30*time.Millisecond && onSlow != nil {
					onSlow(d)
				}
				mine = append(mine, d)
			}
			mu.Lock()
			all = append(all, mine...)
			mu.Unlock()
		}(g)
	}
	wg.Wait()
	total = time.Since(start)
	sort.Slice(all, func(i, j int) bool { return all[i] < all[j] })
	return percentile(all, 0.5), percentile(all, 0.99), all[len(all)-1], total
}

func main() {
	if len(os.Args) > 1 && os.Args[1] == "trace" {
		f, _ := os.Create("trace.out")
		trace.Start(f)
		run((*cache).getSlow)
		trace.Stop()
		f.Close()
		return
	}
	if len(os.Args) > 1 && os.Args[1] == "flight" {
		// The flight recorder keeps the last moments of the trace in memory and writes them only when something goes wrong.
		fr := trace.NewFlightRecorder(trace.FlightRecorderConfig{MinAge: 500 * time.Millisecond})
		fr.Start()
		var once sync.Once
		onSlow = func(d time.Duration) {
			once.Do(func() {
				f, _ := os.Create("flight.out")
				n, err := fr.WriteTo(f)
				f.Close()
				fmt.Printf("a request took %s, so the flight recorder wrote %d KB (error: %v)\n", d.Round(time.Millisecond), n/1024, err)
			})
		}
		run((*cache).getSlow)
		fr.Stop()
		return
	}
	for _, m := range []struct {
		name string
		get  func(*cache, int) int
	}{{"lock held during the fetch", (*cache).getSlow}, {"fetch outside the lock", (*cache).getFast}} {
		p50, p99, max, total := run(m.get)
		fmt.Printf("%-28s p50 %8s  p99 %8s  max %8s  total %s\n", m.name, p50.Round(time.Microsecond), p99.Round(time.Microsecond), max.Round(time.Microsecond), total.Round(time.Millisecond))
	}
}

set -e
go build -o app .
echo "== request latency, 64 goroutines x 200 requests, 30 percent misses"
./app
./app trace
echo
echo "== the flight recorder: only keeps a trace when something goes wrong"
./app flight
go tool trace -pprof=sync flight.out > flight.pprof
go tool pprof -top -nodecount=2 app flight.pprof 2>/dev/null | grep -E "Type|Mutex"
echo
echo "== the execution trace, summarised as a synchronisation profile"
go tool trace -pprof=sync trace.out > sync.pprof
go tool pprof -top -nodecount=6 app sync.pprof 2>/dev/null | grep -vE '^(Time|File|Build ID):'
echo
echo "== where the blocked time was spent, by line"
go tool pprof -list 'main.\(\*cache\).getSlow' app sync.pprof 2>/dev/null | awk '$2 != "." && $3 ~ /^[0-9]+:/'
echo
echo "== the scheduler latency profile: time goroutines waited to be run"
go tool trace -pprof=sched trace.out > sched.pprof
go tool pprof -top -nodecount=3 app sched.pprof 2>/dev/null | grep -vE '^(Time|File|Build ID):'
rm -f app flight.out flight.pprof trace.out sync.pprof sched.pprof

== request latency, 64 goroutines x 200 requests, 30 percent misses
lock held during the fetch   p50  7.826ms  p99 43.703ms  max 48.961ms  total 2.578s
fetch outside the lock       p50       0s  p99  1.312ms  max  10.02ms  total 58ms

== the flight recorder: only keeps a trace when something goes wrong
a request took 30ms, so the flight recorder wrote 8 KB (error: <nil>)
Type: delay
  720.91ms   100%   100%   720.91ms   100%  sync.(*Mutex).Lock

== the execution trace, summarised as a synchronisation profile
Type: delay
Showing nodes accounting for 169.40s, 100% of 169.40s total
Dropped 12 nodes (cum <= 0.85s)
Showing top 6 nodes out of 9
      flat  flat%   sum%        cum   cum%
   164.76s 97.26% 97.26%    164.76s 97.26%  sync.(*Mutex).Lock
     2.64s  1.56% 98.82%      2.64s  1.56%  sync.(*WaitGroup).Wait
        2s  1.18%   100%         2s  1.18%  runtime.chanrecv1
         0     0%   100%    164.75s 97.26%  main.(*cache).getSlow
         0     0%   100%      2.64s  1.56%  main.main
         0     0%   100%      2.64s  1.56%  main.run

== where the blocked time was spent, by line
         .    164.75s     25:	c.mu.Lock()
         .    23.23us     31:	c.data[k] = v

== the scheduler latency profile: time goroutines waited to be run
Type: delay
Showing nodes accounting for 193.71ms, 99.14% of 195.39ms total
Dropped 26 nodes (cum <= 0.98ms)
Showing top 3 nodes out of 9
      flat  flat%   sum%        cum   cum%
  160.44ms 82.11% 82.11%   193.71ms 99.14%  sync.(*Mutex).Unlock
   33.27ms 17.03% 99.14%    33.27ms 17.03%  runtime.goyield
         0     0% 99.14%    33.27ms 17.03%  internal/sync.(*Mutex).Unlock

The symptom

The first output is what a dashboard would show:

• lock held during the fetch: p50 7.826 ms, p99 43.703 ms, max 48.961 ms, total 2.578 s.
• fetch outside the lock: p50 under a microsecond (printed 0s, since cache hits are that fast), p99 1.312 ms, max 10.02 ms, total 58 ms.

Every request in the slow version waited on the lock, and the median request took 7.8 milliseconds to do a map lookup. A CPU profile of this program would show almost nothing: the processors are idle, since the goroutines are asleep inside time.Sleep (the remote call) with the lock held, and everyone else is parked waiting for it. This is the shape of lock contention: low CPU, high latency, and a profile that says everything is fine.

Finding it: the sync profile

go tool trace has a web UI with timelines, and it can also emit pprof profiles from a trace. The -pprof flag selects the kind:

These write a standard pprof file to standard output, so the script pipes it to a file and reads it with go tool pprof. The sync profile of the slow run:

Type: delay, Showing nodes accounting for 169.40s, 100% of 169.40s total

and the top entries:

• sync.(*Mutex).Lock: 164.76 s, 97.26 percent
• sync.(*WaitGroup).Wait: 2.64 s
• runtime.chanrecv1: 2 s
• main.(*cache).getSlow: 164.75 s cum

The unit is goroutine seconds. The run lasted 2.6 s of wall time, and 64 goroutines were each blocked for most of it, so the total is 64 times larger. Do not read it as wall time: read the shares. 97 percent of all blocked time was goroutines waiting in Mutex.Lock, called from getSlow. The Wait and chanrecv1 entries are the main goroutine waiting for the workers, which is not a problem.

pprof -list on getSlow names the line:

• line 25, c.mu.Lock(): 164.75 s
• line 31, c.data[k] = v: 23.23 microseconds

The time is spent waiting at the lock call. It is not spent in the map or the fetch. The profile says where the waiting happens, and the reading of the function says why: the lock is held for the 500 microsecond fetch on each miss, 30 percent of the time, so with 64 goroutines the average request waits behind several fetches.

What the scheduler profile excludes

A different explanation for slow requests is that goroutines are runnable but the scheduler cannot give them a processor: too much CPU work, too few cores, a long GC. The scheduler profile measures that, and in this run it was small:

Type: delay, 195.39 ms in total, dominated by sync.(*Mutex).Unlock (160 ms, the goroutine woken by an unlock waiting to be scheduled) and runtime.goyield.

195 ms spread over 12 800 requests is 15 microseconds each, against a median of 7.8 milliseconds. Scheduling latency is not the cause. The trace separates the two, and that decision, "is it blocked or is it starved", is worth the price of a trace by itself.

The fix, and what it bought

getFast takes the lock to look up the key, releases it, fetches if needed, and takes it again to store. The remote call no longer serialises the requests. Cache hits (70 percent) are about a lock and a map read.

The result in the output above: p99 from 43.7 ms to 1.3 ms, total from 2.578 s to 58 ms, 44 times. The fix changes behaviour in one respect to design for: two goroutines missing the same key at the same time now both fetch it. If duplicate fetches matter, use singleflight (golang.org/x/sync/singleflight) to collapse them, which is a separate, larger change. The right fix is rarely "remove the lock" and often "shrink what is inside it".

Reading a trace in the browser

go tool trace trace.out starts a local web server with several views. The ones that matter for latency:

• Goroutine analysis: for each function that ran as a goroutine, a table with time in execution, scheduler wait, blocked on sync, blocked on network, in syscall and in GC assist. Sort by the "sync block" column.
• View trace: the timeline, with a row per processor and goroutine, which shows convoys visually: many goroutines parked, one running.
• Scheduler latency profile and Synchronisation blocking profile: the same data as the -pprof flags, with a graph.
• User defined tasks and regions: trace.NewTask, trace.WithRegion and trace.Log let you mark request boundaries and phases, so the trace reads in your terms ("handle /search", "db query"). Add a task per request in a service and the UI can show the latency distribution per task and drill into the slowest.

Use the browser view for exploration and the -pprof text output when you want something to paste into an issue or a pull request.

The flight recorder

A trace of a problem you cannot reproduce is hard to catch: you either record constantly (large files) or you record after the problem has passed (nothing). Go 1.25 adds trace.FlightRecorder, which keeps a rolling window of recent trace data in memory and writes it on demand. The lab's flight mode starts a recorder with a window of at least 500 ms and arranges for any request slower than 30 ms to call fr.WriteTo(file):

a request took 30ms, so the flight recorder wrote 8 KB (error: <nil>)

The saved 8 KB file is a normal trace. Its sync profile again shows the story: Type: delay and 720.91ms 100% sync.(*Mutex).Lock, the same line, from a window around the slow request. This is the production pattern: run the recorder always (the cost is the memory for the window and a small overhead), and trigger a dump from the code that detects the symptom: a request over its latency budget, a health check failing, a queue depth threshold. Then you have the trace of the incident, not of the quiet period after it. Check the API of your Go version, since the recorder is new, and the configuration fields (MinAge, MaxBytes) are what bound the memory.

Adding your own structure

The raw trace knows goroutines and functions. Your service thinks in requests. The runtime/trace package lets you add that vocabulary: trace.NewTask(ctx, "handle search") marks a logical operation that may span goroutines, trace.WithRegion(ctx, "db query", fn) marks a phase inside it, and trace.Log(ctx, "tenant", id) attaches a key and value. In the UI the task view groups latency by task type, lists the slowest instances, and shows for each the time spent in its regions and in the scheduler and GC. A request that took 200 ms can then be decomposed in one screen: 8 ms running, 150 ms blocked on a lock, 40 ms waiting on a connection. The cost when tracing is off is negligible, so instrument handlers and the few expensive phases permanently.

The usual causes of waiting

When the sync profile points at a lock, the lab's bug is one of a short list. Knowing the list shortens the diagnosis:

• A lock held across I/O or a slow computation. The lab. Shrink the critical section, or copy the data under the lock and work on the copy.
• A single mutex protecting a hot map. Shard the map, use sync.Map for read mostly workloads, or use a copy on write snapshot.
• A bounded resource: a connection pool, a semaphore, a worker pool. The trace shows goroutines blocked on a channel receive or a pool Get. The fix is capacity or backpressure (pool sizes).
• A channel with a slow consumer. Senders block on chansend. Look at the consumer.
• GC assists and stop the world pauses. The goroutine analysis shows "GC assist" time per function, and the timeline shows the pauses. Reduce allocation or tune the collector (GC pauses).
• System calls and the network. The -pprof=syscall and -pprof=net profiles name them.
• Scheduler starvation. Too many runnable goroutines for the cores, or GOMAXPROCS below the CPU count in a container. This is the one the scheduler profile detects, and it was not the cause here.

A procedure for a latency problem

1. Measure the distribution, not the mean: p50, p99, max. A bad p99 with a good p50 means a minority of requests is waiting.
2. Check the CPU profile. If CPU is high, the problem is computation. If low and latency is high, it is waiting.
3. Take a trace of a few seconds under load (or arm the flight recorder).
4. Run the sync, sched, net and syscall profiles. The largest share names the kind of waiting.
5. Use -list on the dominant function to find the line.
6. Fix, then measure the distribution again, as the table above does.

Checklist

• A CPU profile cannot see waiting; the trace can.
• Convert a trace into pprof profiles with go tool trace -pprof=sync|sched|net|syscall.
• Compare blocked time with scheduler latency to tell waiting from starvation.
• Read the shares of blocked time, since goroutine seconds add up across goroutines.
• Do not hold a lock across I/O; use singleflight for duplicate work.
• Use the flight recorder to capture incidents you cannot reproduce.

The tracer is documented in the runtime/trace package and the Go diagnostics guide.