Go GC Pauses in Production and How to Measure Them

A garbage collector has two costs people mix up. The first is the pause, the short moments when the program is stopped so the collector can start and finish a cycle, which is what a user feels as a latency spike. The second is the work, the CPU the collector burns marking live objects in the background while the program keeps running, which a user feels as lower throughput. Go's collector is concurrent, so almost all of its work happens without stopping anything. This article measures both sides on heaps of 50, 200 and 800 MB, with and without pointers, shows what GODEBUG=gctrace=1 prints and how to read the pause numbers in production through runtime/metrics, and gives the cases where a pause really is the problem.

It follows GOGC tuning and GOMEMLIMIT, and leads to RSS against the heap. Where the time goes in a real service is the job of CPU profiles and execution traces. The cornerstone is the Go performance guide.

What stops the world

A collection cycle has three phases. Sweep termination stops the world briefly to finish the previous cycle and enable the write barrier. Marking runs concurrently, using about a quarter of the processors plus assists from goroutines that allocate too fast. Mark termination stops the world again to finish marking and turn the barrier off. Sweeping then frees memory lazily, again with the program running.

So there are two stop the world phases per cycle, and both are short because they only do bookkeeping: the heavy walk over the live objects happens in the concurrent phase. That is the design that makes the pause time nearly independent of heap size, and the lab checks it.

The experiment

The program builds a live heap of a given size, either of small objects linked by pointers or of large byte slices that hold no pointers, then allocates 400000 short lived 4 KB buffers so that the collector must run, and reads the pause history from runtime/debug.ReadGCStats. The script runs three sizes of each kind and then prints one gctrace line.

package main

import (
	"fmt"
	"os"
	"runtime"
	"runtime/metrics"
	"sort"
	"time"
)

type node struct {
	next *node
	val  [6]int64
}

var keep [][]byte

func buildPointers(mb int) *node {
	var head *node
	for i := 0; i < mb*1024*1024/64; i++ {
		head = &node{next: head}
	}
	return head
}

// pauses reads the runtime's histogram of stop-the-world pauses and returns the percentile bounds.
func pauses() (count uint64, p50, p99, max float64) {
	s := []metrics.Sample{{Name: "/sched/pauses/total/gc:seconds"}}
	metrics.Read(s)
	h := s[0].Value.Float64Histogram()
	for _, c := range h.Counts {
		count += c
	}
	if count == 0 {
		return
	}
	var acc uint64
	for i, c := range h.Counts {
		acc += c
		hi := h.Buckets[i+1]
		if p50 == 0 && float64(acc) >= 0.5*float64(count) {
			p50 = hi
		}
		if p99 == 0 && float64(acc) >= 0.99*float64(count) {
			p99 = hi
		}
		if c > 0 {
			max = hi
		}
	}
	return
}

func main() {
	var live int
	var kind string
	fmt.Sscan(os.Args[1], &live)
	kind = os.Args[2]
	var heap *node
	var blob []byte
	if kind == "pointers" {
		heap = buildPointers(live)
	} else {
		blob = make([]byte, live*1024*1024)
		for i := 0; i < len(blob); i += 4096 {
			blob[i] = 1
		}
	}
	runtime.GC()
	var before runtime.MemStats
	runtime.ReadMemStats(&before)
	start := time.Now()
	for i := 0; i < 400000; i++ {
		b := make([]byte, 4096)
		b[0] = byte(i)
		if i%1000 == 0 {
			keep = append(keep[:0], b)
		}
	}
	elapsed := time.Since(start)
	var m runtime.MemStats
	runtime.ReadMemStats(&m)
	n := m.NumGC - before.NumGC
	// The last 256 pauses are in PauseNs.
	var ps []time.Duration
	for i := uint32(0); i < n && i < 256; i++ {
		ps = append(ps, time.Duration(m.PauseNs[(m.NumGC-1-i)%256]))
	}
	sort.Slice(ps, func(i, j int) bool { return ps[i] < ps[j] })
	pct := func(p float64) time.Duration { return ps[int(float64(len(ps)-1)*p)] }
	fmt.Printf("%-8s %4d MB live: %3d GCs in %4d ms, pause p50 %5d µs  p99 %5d µs  max %5d µs  (total %d µs)\n",
		kind, live, n, elapsed.Milliseconds(), pct(0.5).Microseconds(), pct(0.99).Microseconds(), ps[len(ps)-1].Microseconds(),
		time.Duration(m.PauseTotalNs-before.PauseTotalNs).Microseconds())
	runtime.KeepAlive(heap)
	runtime.KeepAlive(blob)
}

set -e
go build -o app .
echo "400000 short lived 4 KB buffers on top of a live heap of each size and kind"
for mb in 50 200 800; do ./app $mb pointers; done
for mb in 50 200 800; do ./app $mb bytes; done
echo
echo "what GODEBUG=gctrace=1 prints for one collection (fields of the first line, with times removed)"
GODEBUG=gctrace=1 ./app 50 pointers 2>&1 >/dev/null | head -1 | sed -E 's/@[0-9.]+s [0-9]+%: /@T P: /; s/[0-9.]+\+[0-9.]+\+[0-9.]+ ms clock/A+B+C ms clock/; s/[0-9.\/+]+ ms cpu/... ms cpu/'
rm -f app

400000 short lived 4 KB buffers on top of a live heap of each size and kind
pointers   50 MB live:  22 GCs in 1338 ms, pause p50    16 µs  p99    45 µs  max    62 µs  (total 474 µs)
pointers  200 MB live:   5 GCs in 1357 ms, pause p50    51 µs  p99    61 µs  max   216 µs  (total 369 µs)
pointers  800 MB live:   1 GCs in 1218 ms, pause p50    24 µs  p99    24 µs  max    24 µs  (total 24 µs)
bytes      50 MB live:  31 GCs in  117 ms, pause p50    22 µs  p99   179 µs  max   202 µs  (total 1105 µs)
bytes     200 MB live:   7 GCs in  121 ms, pause p50    30 µs  p99    32 µs  max    41 µs  (total 208 µs)
bytes     800 MB live:   1 GCs in  165 ms, pause p50    23 µs  p99    23 µs  max    23 µs  (total 23 µs)

what GODEBUG=gctrace=1 prints for one collection (fields of the first line, with times removed)
gc 1 @T P: A+B+C ms clock, ... ms cpu, 3->4->4 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 10 P

Results

Pauses were tens of microseconds at every size

The longest single pause in any run was 216 µs, on the 200 MB pointer heap, and the typical one was 16 to 51 µs. A heap sixteen times larger (50 MB against 800 MB) did not produce a longer pause: the 800 MB runs paused for 23 to 24 µs. This is the property the concurrent collector was built for. A pause of a few tens of microseconds is below what almost any network request can notice.

The cost of a pointer heap is the work, not the pause

Compare the two kinds at the same size. The byte heaps finished in 117 to 165 ms and the pointer heaps in 1218 to 1357 ms, ten times longer, with similar pauses. The collector has to look at every pointer in the pointer heap to decide what is alive, and has to look at none inside the byte slices, because the allocator marks those spans as pointer free. The extra second is mark work, spread over background workers and over assists charged to the allocating goroutines, which slow the program rather than stopping it.

That is the finding to keep: the number users complain about is rarely the pause. It is the throughput lost to marking, and the latency added when assists make a request goroutine do some of the work.

Cycle count falls as the heap grows

The 50 MB heaps ran 22 and 31 cycles, the 200 MB heaps 5 and 7, the 800 MB heaps one. With GOGC at 100 the next cycle starts when the heap has doubled, so a larger live heap leaves more room before the trigger. Fewer cycles means fewer pauses, which is why total pause time dropped from 474 µs to 24 µs along the pointer row.

Reading gctrace

Setting GODEBUG=gctrace=1 prints one line per cycle to standard error. The lab printed the shape of the first line:

gc 1 @T P: A+B+C ms clock, ... ms cpu, 3->4->4 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 10 P

• gc 1 is the cycle number, and @T the time since the program started.
• A+B+C ms clock is the wall time of the three phases: sweep termination (stop the world), concurrent mark, and mark termination (stop the world). The pause is A plus C. B is the concurrent part and can be long without affecting anything.
• ms cpu splits the CPU time into assist, background and idle workers, and shows how much of the cost was paid by your goroutines.
• 3->4->4 MB is the heap size at the start of the cycle, at the end, and what was live. The last number is the one that sets the next trigger.
• 4 MB goal is the target heap size for the cycle.
• 10 P is the number of processors.

When a service has a latency problem, look at A and C for pause and at the assist figure in the cpu column for the work forced onto request goroutines.

Measuring in production

You cannot run with gctrace in every deployment, and the standard library exposes the same information as metrics:

• /gc/pauses:seconds is a histogram of stop the world pauses, from which p50, p99 and max follow.
• /gc/cycles/total:gc-cycles counts cycles, and the rate tells you how often the collector runs.
• /gc/heap/live:bytes gives the live heap after the last cycle, the floor for any memory limit.
• /cpu/classes/gc/total:cpu-seconds is the CPU spent in the collector. Divide its rate by total CPU for the GC share.
• /gc/limiter/last-enabled:gc-cycle shows whether the GC CPU limiter engaged (GOMEMLIMIT).

runtime/metrics.Read returns these without stopping the world, and most Prometheus client libraries for Go export them already. Alert on the GC CPU share and on the pause p99, not on the cycle count, which rises harmlessly with allocation rate.

When a pause is the problem

The measurements above are for a healthy heap on an idle machine. Pauses grow in three situations:

1. Many goroutines. Stopping the world requires every goroutine to reach a safe point. A goroutine in a tight loop with no function calls used to delay this for milliseconds, and since asynchronous preemption in Go 1.14 it rarely does. A program with a million goroutines also pays to scan their stacks, though that is in the concurrent phase.
2. An overloaded machine. The collector's background workers share the processors. On a host where the container is throttled by its CPU quota, a stop the world phase that takes microseconds on an idle core can take milliseconds while the thread waits to be scheduled. If pauses in the histogram are long only in production, look at CPU throttling first.
3. A very high allocation rate with a tight limit. Assists make request goroutines do marking, so tail latency rises even when the pauses stay small. The signs are a large assist share in gctrace and a rising p99 that tracks allocation rate. The cure is allocating less (reducing allocations).

How to reduce the cost

• Allocate less. Fewer bytes per request means fewer cycles. This beats every tunable.
• Keep pointers out of big structures. A large cache stored as []byte or as slices of structs without pointers costs the collector almost nothing to mark, as the byte rows show. A map of strings to pointers does.
• Tune GOGC and GOMEMLIMIT to trade memory for fewer cycles (GOGC).
• Cap goroutine counts where a design creates one per item.
• Avoid pausing for the wrong reason. Calling runtime.GC() in a request path forces a full cycle and stops the world; use it only in tests and benchmarks.

Why a pause is short by design

The two stop the world phases do a fixed amount of work. Sweep termination makes sure every span from the previous cycle has been swept, turns on the write barrier and publishes the roots. Mark termination checks that no grey objects remain, flushes per processor caches and turns the barrier off. Neither walks the heap. The marking in between runs on dedicated background workers, which take about 25 percent of the processors, and on assists: a goroutine that allocates while marking is under way is charged for the allocation and must mark an equivalent amount of memory before it continues.

That split explains the lab. The pause total for 31 cycles of the 50 MB byte heap was 1105 µs, about 36 µs a cycle. The pause total for the single cycle on the 800 MB heap was 23 µs. A design that scanned the heap while stopped would have produced pauses proportional to size, and the 800 MB case would have been sixteen times worse than the 50 MB one. It was not.

A worked reading of a trace

Run the pointer lab with GODEBUG=gctrace=1 and each cycle prints a line in the shape shown earlier. Take an illustrative line (made up to show the reading, not copied from the lab) such as gc 7 @0.612s 4%: 0.018+14+0.021 ms clock; the two small numbers (0.018 and 0.021 ms) are the stop the world phases, 39 µs together, and the 14 ms in the middle is concurrent marking. The 4% is the share of CPU the program has spent in the collector since it started. If you saw 14 ms in the middle and concluded the program paused for 14 ms you would chase the wrong problem.

The heap figures tell the second half of the story. In 3->4->4 MB, the first number is the heap when the cycle started, the second when marking ended, and the third what survived. If the second figure is far above the first, the program allocated heavily while marking ran, which means assists were charged to request goroutines. If the goal in the next field is close to the survivors, the heap is near its minimum and the cycles will be frequent.

Putting numbers on the work

The pause is easy to read and the work is easy to miss. To measure the work, compare two runs of the same program: one with the collector effectively off (GOGC=off, with enough memory) and one with the default. The difference in wall time is what the collector cost, including assists. In the GOGC lab the default run took 1897 ms against 517 ms with the collector off, so about three quarters of the time was collection, even though the total pause was 237 µs. That is the number to bring to a conversation about GC cost, and it is the reason this article keeps pointing away from pauses.

In a service, the equivalent is the CPU share. If /cpu/classes/gc/total:cpu-seconds grows at 0.3 seconds per second on a 4 core host, the collector uses 7.5 percent of the machine. A single digit share is normal. A share above 20 percent is a sign that the live heap is large and full of pointers, that the allocation rate is high, or that the memory limit is tight.

Pitfalls when reading pause data

Averages hide the tail. The histogram has a long tail on busy hosts. Look at p99 and max, over a window that includes your busiest period.

Pause is not latency. A request that arrives during a pause waits for it, but a request that arrives during marking can be slowed by assists for much longer than any pause. Compare the request latency histogram with the GC cycle times.

Throttling looks like a collector problem. On Kubernetes, a container with a CPU limit is stopped by the kernel for part of every accounting period. A pause that coincides with throttling reflects that, not the Go runtime. Check the container's throttled time before changing runtime settings.

A microbenchmark is not the service. The lab has one allocation pattern on an otherwise idle machine. A service with thousands of goroutines, mixed object sizes and other processes sharing the host will have different numbers. The method carries over and the figures do not.

Checklist

• Distinguish pause (stop the world) from work (mark CPU and assists).
• Read pauses from /gc/pauses:seconds, and the GC share from /cpu/classes/gc/total:cpu-seconds.
• Expect tens of microseconds on a healthy heap, regardless of its size.
• Pointer rich heaps cost mark work; pointer free ones almost nothing.
• Look at CPU throttling when production pauses exceed the lab's.
• Reduce allocation before tuning.

The collector is described in the Go GC guide and the metrics in the runtime/metrics package.