runtime: latency in sweep assists when there's no garbage

[rhysh]

go version devel +ae9712c766 Thu Dec 1 22:20:31 2016 +0000 darwin/amd64, and linux/amd64

I wrote a test case for the GC latency described by @WillSewell in https://blog.pusher.com/golangs-real-time-gc-in-theory-and-practice/ . I recorded the timestamps of when pauses (during allocation) were observed, and matched them against GODEBUG=gctrace=1 output.

The pauses come after the GC cycle, during the concurrent sweep phase. Also, they happen as the heap grows and do not happen once the heap size is stable. And the pauses are often longer than the clock time of any single gctrace line.

A goroutine that needs to allocate memory right after a GC cycle is required to help with the sweep work. This means looking through the heap until suitable memory is found. If the heap is growing rapidly with little or no garbage created, this mutator goroutine will need to search for a long time: it can end up sweeping half of the heap (shared with the background sweep worker).

The GC is pretty good at controlling the mark assist burden on any single goroutine—and starting the GC cycle before the allowable heap growth is exhausted, allowing tradeoffs between assist burden and heap growth during the cycle. These protections don't seem to be in place for sweep assists.

The execution tracer's view of this is confusing since it emits events for each call to runtime.(*mspan).sweep, which is called in a loop from runtime.(*mcentral).cacheSpan. This makes it look like the user goroutine is making a lot of progress on sweep work, since a single call to runtime.mallocgc can lead to thousands of tiny "SWEEP" blocks.

Frustrated assists like this are perhaps more likely to happen in microbenchmarks than in production applications, but the way sweep work is shown in the execution tracer makes it hard to say for sure. This could be a contributing factor to #14812 — one of the goroutines in the recent execution trace spent over 17ms in sweep assists.

The test is below, followed by some example runs.

package gc_test

import (
	"flag"
	"testing"
	"time"
)

var (
	start       = time.Now()
	allocSize   = flag.Int("alloc-size", 1000, "Bytes per allocation")
	retainCount = flag.Int("retain-count", 1000000, "Number of allocations to retain")
	loopCount   = flag.Int("loop-count", 10, "Number of times to execute loop")
	preallocate = flag.Bool("preallocate", false, "Preallocate retention slice")
)

func TestHeapGrowthStalls(t *testing.T) {
	var mem [][]byte
	if *preallocate {
		mem = make([][]byte, *retainCount)
	}

	var slowDelta time.Duration

	for i := 0; i < (*loopCount)*(*retainCount); i++ {
		// Allow the program's heap to start small, instead of pre-allocating
		// the entire slice.
		if len(mem) < *retainCount {
			mem = append(mem, nil)
		}

		j := i % len(mem)
		before := time.Now()
		mem[j] = make([]byte, *allocSize)
		delta := time.Since(before)
		if delta > slowDelta || (delta > time.Millisecond && delta > slowDelta/2) {
			slowDelta = delta
			at := time.Since(start)
			t.Logf("i=%-8d at=%.3fs   delta=%.3fms",
				i,
				at.Seconds(),
				delta.Seconds()*float64(time.Second/time.Millisecond))
		}
	}
}

On a darwin/amd64 laptop:

$ GODEBUG=gctrace=1 /tmp/gc.test -test.v
=== RUN   TestHeapGrowthStalls
gc 1 @0.002s 1%: 0.035+0.14+0.019 ms clock, 0.10+0.047/0.12/0.12+0.059 ms cpu, 4->4->3 MB, 5 MB goal, 8 P
gc 2 @0.003s 2%: 0.003+0.63+0.028 ms clock, 0.024+0.054/0.17/0.14+0.22 ms cpu, 6->7->6 MB, 7 MB goal, 8 P
gc 3 @0.004s 3%: 0.003+0.29+0.034 ms clock, 0.026+0.16/0.16/0.095+0.27 ms cpu, 12->12->12 MB, 13 MB goal, 8 P
gc 4 @0.007s 4%: 0.004+1.2+0.048 ms clock, 0.033+0.94/0.059/0.29+0.39 ms cpu, 23->23->22 MB, 24 MB goal, 8 P
gc 5 @0.012s 3%: 0.005+0.59+0.024 ms clock, 0.044+0.054/0.59/0.58+0.19 ms cpu, 44->44->42 MB, 45 MB goal, 8 P
gc 6 @0.020s 2%: 0.005+5.9+0.033 ms clock, 0.040+0.093/1.1/5.7+0.26 ms cpu, 84->84->80 MB, 85 MB goal, 8 P
gc 7 @0.045s 2%: 0.006+1.7+0.036 ms clock, 0.051+0.25/2.2/2.3+0.29 ms cpu, 156->157->152 MB, 160 MB goal, 8 P
gc 8 @0.077s 1%: 0.006+2.1+0.027 ms clock, 0.055+1.0/2.9/7.3+0.21 ms cpu, 297->300->286 MB, 305 MB goal, 8 P
gc 9 @0.154s 1%: 0.008+4.4+0.044 ms clock, 0.070+2.3/4.6/18+0.35 ms cpu, 558->563->537 MB, 573 MB goal, 8 P
gc 10 @0.268s 1%: 0.008+7.5+0.044 ms clock, 0.067+3.7/12/32+0.35 ms cpu, 1047->1056->1004 MB, 1074 MB goal, 8 P
gc 11 @0.428s 1%: 0.008+7.8+0.043 ms clock, 0.070+1.9/13/36+0.34 ms cpu, 1959->1974->1018 MB, 2009 MB goal, 8 P
gc 12 @0.924s 0%: 0.008+8.6+0.17 ms clock, 0.071+1.8/15/38+1.3 ms cpu, 1985->2004->1022 MB, 2036 MB goal, 8 P
gc 13 @1.426s 0%: 0.006+9.0+0.034 ms clock, 0.053+1.8/17/41+0.27 ms cpu, 1993->2000->1010 MB, 2044 MB goal, 8 P
gc 14 @1.658s 0%: 0.008+9.4+0.026 ms clock, 0.070+1.8/15/45+0.21 ms cpu, 1969->1982->1015 MB, 2020 MB goal, 8 P
gc 15 @1.905s 0%: 0.015+9.5+0.075 ms clock, 0.12+1.9/18/41+0.60 ms cpu, 1980->1994->1017 MB, 2031 MB goal, 8 P
gc 16 @2.143s 0%: 0.016+11+0.045 ms clock, 0.12+1.8/21/54+0.36 ms cpu, 1983->1999->1019 MB, 2034 MB goal, 8 P
gc 17 @2.385s 0%: 0.015+10+0.066 ms clock, 0.12+2.4/20/49+0.53 ms cpu, 1987->2002->1018 MB, 2038 MB goal, 8 P
gc 18 @2.616s 0%: 0.015+11+0.077 ms clock, 0.12+2.4/15/59+0.61 ms cpu, 1985->2004->1021 MB, 2036 MB goal, 8 P
--- PASS: TestHeapGrowthStalls (2.85s)
	gc_test.go:42: i=0        at=0.000s   delta=0.000ms
	gc_test.go:42: i=2        at=0.000s   delta=0.001ms
	gc_test.go:42: i=18       at=0.000s   delta=0.002ms
	gc_test.go:42: i=26       at=0.001s   delta=0.002ms
	gc_test.go:42: i=114      at=0.001s   delta=0.003ms
	gc_test.go:42: i=170      at=0.001s   delta=0.004ms
	gc_test.go:42: i=218      at=0.001s   delta=0.014ms
	gc_test.go:42: i=3226     at=0.002s   delta=0.157ms
	gc_test.go:42: i=12016    at=0.005s   delta=0.385ms
	gc_test.go:42: i=22534    at=0.009s   delta=0.408ms
	gc_test.go:42: i=41997    at=0.014s   delta=0.797ms
	gc_test.go:42: i=79541    at=0.028s   delta=1.451ms
	gc_test.go:42: i=152493   at=0.051s   delta=3.489ms
	gc_test.go:42: i=286213   at=0.084s   delta=5.107ms
	gc_test.go:42: i=286229   at=0.087s   delta=2.922ms
	gc_test.go:42: i=536053   at=0.169s   delta=10.281ms
	gc_test.go:42: i=1001709  at=0.295s   delta=20.094ms
PASS

The at=0.169s delta=10.281ms line matches up with gc 9 @0.154s 1%: 0.008+4.4+0.044 ms clock. The GC cycle began at 0.154s and completed around 0.158s. The record-breaking allocation delay finished at 0.169s and began at 0.159s.

On a linux/amd64 server:

$ GOMAXPROCS=8 GODEBUG=gctrace=1 ./gc.test.linux_amd64 -test.v -retain-count=20000000 -preallocate=true -loop-count=3
=== RUN   TestHeapGrowthStalls
gc 1 @0.045s 11%: 0.11+21+0.072 ms clock, 0.22+20/43/106+0.14 ms cpu, 458->459->458 MB, 459 MB goal, 8 P
gc 2 @0.068s 14%: 0.004+27+0.10 ms clock, 0.036+0.063/46/93+0.87 ms cpu, 459->513->513 MB, 917 MB goal, 8 P
gc 3 @0.172s 10%: 0.019+30+0.084 ms clock, 0.15+0.20/54/135+0.67 ms cpu, 739->785->784 MB, 1027 MB goal, 8 P
gc 4 @0.389s 6%: 0.014+33+0.039 ms clock, 0.11+0.71/64/161+0.31 ms cpu, 1315->1388->1388 MB, 1569 MB goal, 8 P
gc 5 @0.795s 4%: 0.026+33+0.044 ms clock, 0.21+1.6/62/164+0.35 ms cpu, 2486->2557->2557 MB, 2777 MB goal, 8 P
gc 6 @1.589s 3%: 0.025+84+0.046 ms clock, 0.20+2.3/159/406+0.37 ms cpu, 4780->4915->4915 MB, 5115 MB goal, 8 P
gc 7 @3.202s 2%: 0.015+63+0.041 ms clock, 0.12+4.3/126/313+0.32 ms cpu, 9377->9499->9499 MB, 9830 MB goal, 8 P
gc 8 @6.350s 1%: 0.018+204+0.091 ms clock, 0.14+55/395/998+0.72 ms cpu, 18438->18685->18685 MB, 18999 MB goal, 8 P
gc 9 @13.058s 1%: 0.019+300+0.066 ms clock, 0.15+112/565/1496+0.52 ms cpu, 36436->36706->20259 MB, 37370 MB goal, 8 P
gc 10 @34.001s 0%: 0.017+265+0.11 ms clock, 0.13+83/507/1313+0.91 ms cpu, 39506->39732->20215 MB, 40519 MB goal, 8 P
--- PASS: TestHeapGrowthStalls (53.37s)
        gc_test.go:42: i=0        at=0.045s   delta=0.581ms
        gc_test.go:42: i=57055    at=0.097s   delta=2.220ms
        gc_test.go:42: i=331266   at=0.200s   delta=2.323ms
        gc_test.go:42: i=334871   at=0.221s   delta=19.590ms
        gc_test.go:42: i=952975   at=0.454s   delta=32.232ms
        gc_test.go:42: i=2150327  at=0.889s   delta=61.852ms
        gc_test.go:42: i=4564455  at=1.799s   delta=126.545ms
        gc_test.go:42: i=9258703  at=3.533s   delta=268.414ms
        gc_test.go:42: i=18664799 at=7.354s   delta=799.231ms
PASS

/cc @aclements @RLH

[aclements]

Very interesting. I knew this problem existed for large allocations, but hadn't really thought about it with small allocations.

Assuming I understand what's going on, this isn't really a "sweep assist" problem, since it would happen even if the sweep ratio was 0. Sweep assists don't care if they found more space or not; you get credit for sweeping a span regardless of the outcome. The problem is that allocation ultimately has to find a span with some free space on it and currently it will keep sweeping until it does.

I might have a simple fix: put a threshold on how many spans allocation is willing to sweep before it gives up and just allocates a fresh span from the heap. The heap overhead of this is bounded at 1/threshold.

[aclements]

There are actually a few distinct causes of this.

• One is when sweep has to process a lot of full spans from an mcache before finding one that has space to allocate from. My proposed fix targets this, but doesn't actually work because it just shifts the time into the next problem. (All + timestamps below are in ns.)

long cacheSpan @0.286 10ms, 83577 swept, 0 reclaimed, 1 grow
+27 (p 0) lock mcentral
+71 (p 0) locked; scanning lists
+10539832 (p 0) grow()
+10539993 (p 0) mheap.alloc()
+10540090 (p 0) mheap.alloc_m()
+10540149 (p 0) got lock
+10540220 (p 0) reclaim
+10542490 (p 0) reclaim done
+10542536 (p 0) allocSpanLocked
+10542977 (p 0) initialize span
+10543065 (p 0) unlock
+10543110 (p 0) mheap.alloc_m done
+10543166 (p 0) mheap.alloc done
+10543204 (p 0) initSpan
+10543524 (p 0) grow done
+10543588 (p 0) have span

• When we go to allocate a fresh span, either because of the fallback in my fix or because we're genuinely out of spans of that size class, the heap also tries to sweep. This is not to find individual free objects, but to free up whole spans before allocating a new one and potentially growing the RSS. This is, in a sense, even more aggressive since it's trying to find completely empty spans. I've been aware of this one for a while and have various schemes for how to fix it, but none that are simple. This doesn't happen very often, but when it does it's really expensive.

long cacheSpan @2.890 22ms, 0 swept, 1 reclaimed, 1 grow
+25 (p 0) lock mcentral
+70 (p 0) locked; scanning lists
+121 (p 0) grow()
+263 (p 0) mheap.alloc()
+380 (p 0) mheap.alloc_m()
+480 (p 0) got lock
+525 (p 0) reclaim
+22056552 (p 0) reclaim done
+22056982 (p 0) allocSpanLocked
+22057164 (p 0) initialize span
+22057377 (p 0) unlock
+22057418 (p 0) mheap.alloc_m done
+22057638 (p 0) memclr
+22058327 (p 0) mheap.alloc done
+22058448 (p 0) initSpan
+22058975 (p 0) grow done
+22059177 (p 0) have span

With my proposed fix, we fall into this case any time we would otherwise have fallen into the previous case. For this particular application, the reclaim sweep has just as much trouble finding free space as the mcentral sweep. This may be less true in a more heterogeneous application.

long cacheSpan @0.161 5ms, 50+0 swept, 0 skipped, 1 grow
+27 (p 0) lock mcentral
+66 (p 0) locked; scanning lists
+5336 (p 0) retry failed
+5375 (p 0) grow()
+5425 (p 0) mheap.alloc()
+5485 (p 0) mheap.alloc_m()
+5525 (p 0) got lock
+5556 (p 0) reclaim
+5092799 (p 0) reclaim done
+5093019 (p 0) allocSpanLocked
+5093269 (p 0) initialize span
+5093403 (p 0) unlock
+5093441 (p 0) mheap.alloc_m done
+5093631 (p 0) memclr
+5098431 (p 0) mheap.alloc done
+5098462 (p 0) initSpan
+5100228 (p 0) grow done
+5100424 (p 0) have span

• Every once in a while when I run the benchmark, I get dozens of ~10ms stalls. When this happens, it's because memclr in mheap.alloc_m takes 5--14ms. This almost certainly has something to do with page faults and kernel state, though I don't know what. I have a hunch it has to do with transparent huge page scavenging (not clearing; clearing a huge page takes 40 us), but that's purely a hunch.

long cacheSpan @1.643 9ms, 0 swept, 0 reclaimed, 1 grow
+28 (p 0) lock mcentral
+74 (p 0) locked; scanning lists
+194 (p 0) grow()
+247 (p 0) mheap.alloc()
+307 (p 0) mheap.alloc_m()
+350 (p 0) got lock
+391 (p 0) allocSpanLocked
+701 (p 0) initialize span
+761 (p 0) unlock
+804 (p 0) mheap.alloc_m done
+843 (p 0) memclr
+9365603 (p 0) mheap.alloc done
+9366045 (p 0) initSpan
+9366973 (p 0) grow done
+9367295 (p 0) have span

[gopherbot]

CL https://golang.org/cl/34291 mentions this issue.

[aclements]

@rhysh, care to give CL 34291 a shot? I don't think that's entirely the right approach, but it definitely makes things better.

[rhysh]

Hi @aclements , yes CL 34291 PS 1 makes things better. It's particularly apparent when the heap is large, and the stalls of over 500ms are reduced to less than 100ms.

Here's the output I got from go1.8rc2 with CL 34291 PS 1 cherry-picked on linux/amd64:

$ GOMAXPROCS=8 GODEBUG=gctrace=1 ./gc.test.go18rc2.cl34291ps1.linux_amd64 -test.v -retain-count=20000000 -preallocate=true -loop-count=3
=== RUN   TestHeapGrowthStalls
gc 1 @0.043s 13%: 0.17+25+0.070 ms clock, 0.35+23/49/122+0.14 ms cpu, 458->459->458 MB, 459 MB goal, 8 P
gc 2 @0.069s 15%: 0.007+34+0.13 ms clock, 0.057+0.12/57/119+1.1 ms cpu, 459->524->524 MB, 917 MB goal, 8 P
gc 3 @0.182s 11%: 0.008+29+0.054 ms clock, 0.070+0.29/57/144+0.43 ms cpu, 748->800->800 MB, 1048 MB goal, 8 P
gc 4 @0.397s 7%: 0.016+29+0.043 ms clock, 0.13+0.75/56/142+0.34 ms cpu, 1332->1375->1375 MB, 1601 MB goal, 8 P
gc 5 @0.801s 4%: 0.013+33+0.066 ms clock, 0.10+1.5/64/162+0.53 ms cpu, 2482->2555->2555 MB, 2750 MB goal, 8 P
gc 6 @1.604s 3%: 0.013+41+0.033 ms clock, 0.11+2.3/79/202+0.26 ms cpu, 4792->4876->4876 MB, 5111 MB goal, 8 P
gc 7 @3.199s 2%: 0.020+85+0.063 ms clock, 0.16+4.3/158/368+0.50 ms cpu, 9367->9524->9524 MB, 9752 MB goal, 8 P
gc 8 @6.374s 1%: 0.019+149+0.10 ms clock, 0.15+19/280/682+0.80 ms cpu, 18515->18767->18767 MB, 19049 MB goal, 8 P
gc 9 @12.683s 1%: 0.018+169+0.054 ms clock, 0.14+31/334/834+0.43 ms cpu, 36597->36799->20191 MB, 37535 MB goal, 8 P
gc 10 @37.305s 0%: 0.026+190+0.040 ms clock, 0.21+39/363/912+0.32 ms cpu, 39373->39596->20212 MB, 40382 MB goal, 8 P
--- PASS: TestHeapGrowthStalls (55.54s)
	gc_test.go:42: i=0        at=0.043s   delta=0.710ms
	gc_test.go:42: i=68087    at=0.107s   delta=0.870ms
	gc_test.go:42: i=331280   at=0.202s   delta=2.343ms
	gc_test.go:42: i=351240   at=0.230s   delta=1.670ms
	gc_test.go:42: i=940256   at=0.456s   delta=4.094ms
	gc_test.go:42: i=2150448  at=0.898s   delta=7.048ms
	gc_test.go:42: i=4529512  at=1.789s   delta=22.685ms
	gc_test.go:42: i=9294784  at=3.549s   delta=39.208ms
	gc_test.go:42: i=18770456 at=7.122s   delta=88.855ms
PASS

The longest stall, 89ms, started around (7.122s-0.089s = 7.033s), which is not immediately after the previous GC, which ended around (6.374s+0.149s = 6.523s). It's likely still during the concurrent sweep phase (which takes around 560ms, based on the go1.8rc2 run below), but it doesn't start at the beginning of the sweep phase.

Compared with the output from vanilla go1.8rc2:

$ GOMAXPROCS=8 GODEBUG=gctrace=1 ./gc.test.go18rc2.linux_amd64 -test.v -retain-count=20000000 -preallocate=true -loop-count=3
=== RUN   TestHeapGrowthStalls
gc 1 @0.038s 13%: 0.17+21+0.080 ms clock, 0.35+20/42/105+0.16 ms cpu, 458->459->458 MB, 459 MB goal, 8 P
gc 2 @0.061s 15%: 0.006+29+0.076 ms clock, 0.055+0.21/49/99+0.61 ms cpu, 459->502->502 MB, 917 MB goal, 8 P
gc 3 @0.171s 10%: 0.009+26+0.051 ms clock, 0.073+0.25/48/121+0.41 ms cpu, 729->785->785 MB, 1005 MB goal, 8 P
gc 4 @0.369s 6%: 0.013+29+0.10 ms clock, 0.10+0.69/57/143+0.83 ms cpu, 1311->1347->1347 MB, 1570 MB goal, 8 P
gc 5 @0.785s 4%: 0.015+48+0.062 ms clock, 0.12+1.6/82/175+0.49 ms cpu, 2441->2506->2505 MB, 2694 MB goal, 8 P
gc 6 @1.594s 2%: 0.011+43+0.060 ms clock, 0.090+2.5/82/211+0.48 ms cpu, 4716->4805->4805 MB, 5011 MB goal, 8 P
gc 7 @3.143s 2%: 0.016+73+0.030 ms clock, 0.13+4.8/145/364+0.24 ms cpu, 9238->9366->9365 MB, 9610 MB goal, 8 P
gc 8 @6.224s 1%: 0.019+139+0.037 ms clock, 0.15+20/267/697+0.30 ms cpu, 18241->18472->18472 MB, 18731 MB goal, 8 P
gc 9 @12.331s 1%: 0.020+152+0.038 ms clock, 0.16+30/302/755+0.30 ms cpu, 36020->36228->20196 MB, 36944 MB goal, 8 P
gc 10 @32.834s 0%: 0.013+209+0.058 ms clock, 0.10+36/397/1053+0.46 ms cpu, 39383->39624->20229 MB, 40393 MB goal, 8 P
--- PASS: TestHeapGrowthStalls (55.93s)
	gc_test.go:42: i=0        at=0.039s   delta=1.323ms
	gc_test.go:42: i=45710    at=0.091s   delta=1.879ms
	gc_test.go:42: i=331286   at=0.195s   delta=2.284ms
	gc_test.go:42: i=335222   at=0.206s   delta=9.855ms
	gc_test.go:42: i=910622   at=0.446s   delta=48.938ms
	gc_test.go:42: i=2097248  at=0.904s   delta=70.692ms
	gc_test.go:42: i=4451669  at=1.777s   delta=140.077ms
	gc_test.go:42: i=9121877  at=3.487s   delta=271.325ms
	gc_test.go:42: i=18446653 at=6.923s   delta=560.603ms
PASS

I'm not aware of any production applications that this issue affects: observing the issue (if I understand it correctly) seems to require the unusual combination of 1) a growing heap, 2) very little garbage to reclaim, and 3) caring about latency in individual goroutines.

[WillSewell]

I'm trying to understand this problem, and there's a few things that are confusing me. In my original benchmark, when I visualise a run of the program with go tool trace, the pauses look like this:

i.e. all processors are running a combination of runtime.gcBgMarkWorker and MARK and GC.

When I visualise the benchmark listed at the top of this issue, the pauses look like this:

This also has all processors running runtime.gcBgMarkWorker at the start, and processors running MARK at the end, but for a very short time (<0.05ms). But one processor runs runtime.gcBgMarkWorker and one runs GC for relatively much longer.

A couple of things about this confuses me:

1. Why is the work done during the pauses not quite the same? I appreciate this could just be due to a larger heap size.
2. From what I can tell (just from the names of the events) that all the work is to do with the mark phase. What about this indicates it's pausing doing sweep assist work? Is it to do with the mysteriously named GC event?
3. I came to the conclusion that the problem we are seeing in the visualisation is this: runtime: idle mark workers run when there's work to do #16528. Is this not correct? Or am I seeing runtime: idle mark workers run when there's work to do #16528 in the above screenshots, and I'm missing the issue discussed here in the trace visualisations?

Happy to take this offline if someone would be willing to explain this to me.

[gopherbot]

Change https://golang.org/cl/60790 mentions this issue: cmd/trace: add minimum mutator utilization (MMU) plot