Go Perf Block Mutex Profiles

Go Block, Mutex & Goroutine Profiles

"Block profile is not enabled by default; use runtime.SetBlockProfileRate to enable it." — Diagnostics

A CPU profile is blind to off-CPU time — it "determines where a program spends its time while actively consuming CPU cycles (as opposed to while sleeping or waiting for I/O)" (Diagnostics). When a request is slow because it is blocked on a lock, a channel, or a WaitGroup, that wait contributes nothing to a CPU profile. This skill owns the three profiles that see off-CPU contention: block, mutex, and goroutine. It owns diagnosis only — finding where and how much you are contended. The fix (sharding, batching) is go-perf-contention-and-sharding; atomics-vs-locks cost is go-perf-atomics-vs-locks; Mutex/RWMutex correctness (copylock, critical-section discipline) is the marketplace skill go-sync-primitives; CPU/heap pprof is go-perf-pprof-profiling; the tracer is go-perf-execution-tracer.

All Go below builds clean under gofmt, go vet, and go test on Go 1.26.

1. The Three Contention Profiles

Block answers "who is waiting, and on what?" (the waiter's stack). Mutex answers "which lock, held by whom, is making others wait?" (the holder's unlock stack). They are complementary views of the same contention — collect both.

2. The Empty-Profile Gotcha — Block & Mutex Are OFF by Default

This is the single most common error with these profiles. Both block and mutex profiling "is not enabled by default" (Diagnostics). net/http/pprof does not enable them for you — its docs say to look at the block profile "after calling runtime.SetBlockProfileRate in your program" and the mutex profile "after calling runtime.SetMutexProfileFraction" (net/http/pprof). With neither set, /debug/pprof/block and /debug/pprof/mutex return a valid, empty profile.

// Enable once at startup, BEFORE the workload runs.
func init() {
	runtime.SetBlockProfileRate(10000)    // sample ~1 blocking event / 10µs blocked
	runtime.SetMutexProfileFraction(100)  // sample 1 in 100 mutex contention events
}

The trap: an empty contention profile reads as "no contention" — but it usually means you forgot to set the rate. Confirm the rate is non-zero before concluding a lock is not hot. runtime.SetMutexProfileFraction(-1) returns the current rate without changing it (SetMutexProfileFraction) — use it to verify.

3. SetBlockProfileRate — the Rate Is Nanoseconds, Not a Count

func SetBlockProfileRate(rate int) "controls the fraction of goroutine blocking events that are reported in the blocking profile. The profiler aims to sample an average of one blocking event per rate nanoseconds spent blocked. To include every blocking event in the profile, pass rate = 1. To turn off profiling entirely, pass rate <= 0" (SetBlockProfileRate).

The units trip everyone up — rate is nanoseconds of blocked time per sample, not "1 in N events":

• rate = 1 → record every blocking event (the runtime special-cases 1 to mean "profile everything").
• rate = 10000 → on average one sample per 10µs of aggregate blocked time — cheap, good for production.
• rate <= 0 → off.

A larger rate samples less and costs less. Picking rate = 1 in production records every channel op and lock wait in the process and is needlessly expensive — reserve 1 for a focused local repro.

4. SetMutexProfileFraction — the Fraction Is 1-in-n

func SetMutexProfileFraction(rate int) int "controls the fraction of mutex contention events that are reported in the mutex profile. On average 1/rate events are reported. The previous rate is returned. To turn off profiling entirely, pass rate 0. To just read the current rate, pass rate < 0" (SetMutexProfileFraction).

Different knob, different meaning from block:

• rate = 1 → report every contention event (1/1).
• rate = 100 → report ~1 in 100 — typical production setting.
• rate = 0 → off. Negative reads the current value (the get-without-set idiom).

Two different mental models: block's rate is time-based (ns blocked per sample), mutex's rate is count-based (1 of every n events). Confusing them — e.g. passing 1 to mutex thinking it means "1ns" — silently records everything.

5. Reading a Block Profile

Collect with go test -blockprofile=block.out, or live: enable the rate, then go tool pprof http://host:6060/debug/pprof/block. The default sample value is delay (cumulative time blocked); top ranks the stacks that waited longest.

(pprof) top
      flat  flat%   sum%        cum   cum%
    4.50s  90.0%  90.0%      4.50s  90.0%  main.(*Cache).Get   # 4.5s blocked here
    0.40s   8.0%  98.0%      0.40s   8.0%  runtime.chanrecv1

• The stack "correspond[s] to the location that blocked (for example, sync.Mutex.Lock)" (pprof) — it is the waiter's call site, so list main.(*Cache).Get shows exactly which Lock/channel op the goroutines are parked on.
• A buffered channel that fills up, an unbuffered send with no ready receiver, and a WaitGroup.Wait all show here — block is not just mutexes. Timer channels (time.After) also appear, and can dominate a profile harmlessly.
• The value is wall time spent blocked, summed across goroutines — high block time on a code path that is supposed to wait (e.g. a worker pulling from a job channel) is normal, not a bug. Judge against expectation.

6. Reading a Mutex Profile

go test -mutexprofile=mutex.out or go tool pprof http://host:6060/debug/pprof/mutex. The sample value is the wait time inflicted on others, attributed to the holder's Unlock.

"Stack traces correspond to the end of the critical section causing contention. For example, a lock held for a long time while other goroutines are waiting … will report contention when the lock is finally unlocked (that is, at sync.Mutex.Unlock). Sample values correspond to the approximate cumulative time other goroutines spent blocked waiting for the lock … if a caller holds a lock for 1s while 5 other goroutines are waiting for the entire second to acquire the lock, its unlock call stack will report 5s of contention." (runtime/pprof)

Consequences:

• The stack lands at Unlock, so use list / peek to walk up to the holder of the long critical section — that caller, not the unlock itself, is the target.
• The "5s for a 1s lock with 5 waiters" example means mutex sample values exceed wall-clock time — they aggregate per-waiter, scaled by 1/rate. Read them as relative contention magnitude, not absolute seconds.
• A hot Unlock stack is the signal to route to the fix: shard the state (go-perf-contention-and-sharding), shrink the critical section, or switch a single word to an atomic (go-perf-atomics-vs-locks). This profile finds contention; it does not remove it.

7. The Goroutine Profile — Leaks and Pile-Ups

The goroutine profile is always available (no rate to set) and dumps "stack traces of all current goroutines" (pprof). It is the primary tool for goroutine leaks and pile-ups.

# Human-readable full dump: every goroutine's stack, grouped by identical stack.
curl 'http://host:6060/debug/pprof/goroutine?debug=2' > g.txt
# debug=1 = pprof text with counts; debug=2 = the panic-style stack dump.

WriteTo(w, debug) controls format: debug=1 is the legacy text format with counts; debug=2 "prints goroutine stacks in the same form used when a Go program dies due to an unrecovered panic" (runtime/pprof) — the most useful for a human read.

Diagnosis pattern:

• Leak = the count grows without bound. Read /sched/goroutines:goroutines from runtime/metrics (or sample runtime.NumGoroutine()) over time; a monotonic climb is a leak. The profile then shows where the leaked goroutines are parked (typically thousands stuck on the same channel recv or ctx.Done() that never fires).
• Pile-up = thousands of identical stacks blocked at one point — unbounded fan-out, or a downstream stall backing up. debug=1 groups by stack so a huge count on one frame jumps out.
• The leak's root cause (a goroutine started without a cancellation path) is correctness, owned by go-concurrency-goroutines; this skill owns detecting it from the profile.

Go 1.26 adds a dedicated goroutineleak profile — "stack traces of all leaked goroutines" — which runs a leak-detection GC cycle and filters the goroutine profile to only those the runtime has proven unreachable (runtime/pprof source). On 1.26+, /debug/pprof/goroutineleak separates true leaks from goroutines that are merely (correctly) blocked.

8. The Overhead Tradeoff & Production Use

Contention profiling is sampled precisely because it is not free — every covered blocking/contention event does extra bookkeeping. The cost scales with how often you sample (smaller block rate / smaller mutex rate = more samples = more overhead) and how contended the program is.

• Production: a coarse setting (block rate ≈ 10000+, mutex rate ≈ 100) gives actionable data at low cost. These are starting points; tune to your event volume.
• Local repro: SetBlockProfileRate(1) / SetMutexProfileFraction(1) capture everything when you control the load.
• Don't run every diagnostic at once. "Some diagnostics tools may interfere … goroutine blocking profiling affects scheduler trace. Use tools in isolation to get more precise info" (Diagnostics). A block profile perturbs the very scheduling a go tool trace is trying to measure.
• Leaving block profiling at an expensive rate in production is a real cost — set it deliberately, and consider lowering or disabling (rate <= 0) once you have the data.
• Exposing /debug/pprof/* (security, auth) is owned by go-perf-pprof-profiling — never bind it to a public port.

9. Don't

• Don't conclude "no contention" from an empty block/mutex profile — first verify the rate is set (SetMutexProfileFraction(-1) to read it); off-by-default is the usual cause (§2).
• Don't reach for a CPU profile to explain blocking or latency. It is blind to off-CPU waits; use block/mutex/goroutine profiles and the tracer (Diagnostics).
• Don't confuse the two knobs: block rate is nanoseconds blocked per sample; mutex rate is 1-in-n events. Passing 1 to either means "record everything," not "1ns" (§3, §4).
• Don't read mutex sample values as absolute seconds — they aggregate per-waiter and scale by 1/rate; treat them as relative magnitude (§6).
• Don't stop at the profile. A hot lock is a finding; the fix is sharding/batching/atomics — route it (§6).
• Don't run block/mutex profiling at rate = 1 in production — needless overhead; use a coarse rate (§8).
• Don't panic at a high block count on a path designed to wait (worker reading a job channel, WaitGroup.Wait) — blocked-by-design is not contention.
• Don't Add/Remove on a predefined profile — they "panic on an explicit Profile.Add or Profile.Remove" (runtime/pprof).

10. Routing to Related Skills

This plugin (go-perf-* depth):

• go-perf-contention-and-sharding — the fix: shard hot state, sync.Map vs sharded map, batching under one lock.
• go-perf-atomics-vs-locks — atomic-vs-mutex cost, RWMutex pitfalls; the fix when one word is contended.
• go-perf-pprof-profiling — CPU/heap pprof subcommands (top/list/peek/-cum), labels, net/http/pprof exposure safety.
• go-perf-execution-tracer — go tool trace for the timeline of a stall; scheduler-latency view.
• go-perf-methodology — the tool-selection matrix that sends a contention question here in the first place; the "should I optimize this" gate.

Parent / sibling marketplace (go-* correctness):

• go-sync-primitives — Mutex/RWMutex copy rules, critical-section discipline, sync.Map's two cases — the correctness of the lock this profile found hot.
• go-concurrency-goroutines — goroutine lifetime, cancellation, leak prevention (the root cause behind a goroutine-profile pile-up).
• go-channels-select — channel send/recv/select semantics behind a block-profile entry.

11. Reference Files

Contention-profiling anti-patterns in LLM-generated Go, each with wrong/right contrast and citations:

references/common-mistakes.md

Source provenance for every claim in this skill:

references/sources.yaml