runtime: multi-ms sweep termination pauses (second edition)

[rafael]

What version of Go are you using (go version)?

go1.15.5 linux/amd64

Does this issue reproduce with the latest release?

N/A

What operating system and processor architecture are you using (go env)?

linux/amd64

What did you do?

This is in the context of vttablet process in Vitess. VTablet provides a grpc service that runs as a sidecar to a MySQL server. It is mostly forwarding requests to mysql and then marshal/unmarshal data using protocol buffers. Some stats gathered during this test:

• It is processing around 5k requests per second.
• The live heap is around 100MB.
• The rate of allocation reported by go_memstats_alloc_bytes_total is around 800MB/s.
• ~1k goroutines per second are running.
• ~14 GC operations per second.

What did you expect to see?

I expected sub-millisecond stop-the-world times during garbage collections. This seems very similar to what is reported in #17831. It seems like this shouldn't be happening.

What did you see instead?

Similar to what is described in #17831, I'm seeing mark termination STW times of over 1ms somewhat regularly:

gc 734 @86.464s 1%: 1.2+6.9+0.074 ms clock, 121+29/89/24+7.1 ms cpu, 113->133->82 MB, 121 MB goal, 96 P
gc 735 @86.532s 1%: 3.2+4.4+0.15 ms clock, 314+10/86/19+15 ms cpu, 147->151->80 MB, 165 MB goal, 96 P
gc 736 @86.618s 1%: 0.14+5.8+0.087 ms clock, 13+8.8/122/71+8.4 ms cpu, 149->153->61 MB, 160 MB goal, 96 P
gc 737 @86.694s 1%: 0.28+12+0.12 ms clock, 27+14/141/79+11 ms cpu, 117->119->72 MB, 122 MB goal, 96 P
gc 738 @86.819s 1%: 1.0+7.4+0.12 ms clock, 103+37/153/102+12 ms cpu, 142->149->90 MB, 144 MB goal, 96 P
gc 739 @86.914s 1%: 0.80+4.8+0.13 ms clock, 77+7.4/90/70+12 ms cpu, 176->179->71 MB, 180 MB goal, 96 P
gc 740 @87.026s 1%: 0.10+4.5+0.17 ms clock, 10+33/85/28+16 ms cpu, 142->148->49 MB, 143 MB goal, 96 P
gc 741 @87.114s 1%: 0.090+3.9+0.10 ms clock, 8.7+2.2/66/38+10 ms cpu, 93->95->42 MB, 99 MB goal, 96 P
gc 742 @87.241s 1%: 0.19+3.7+0.10 ms clock, 18+19/66/10+10 ms cpu, 87->89->49 MB, 88 MB goal, 96 P
gc 743 @87.331s 1%: 1.1+4.6+0.14 ms clock, 113+19/80/35+13 ms cpu, 99->103->48 MB, 100 MB goal, 96 P
gc 744 @87.438s 1%: 0.094+4.0+0.11 ms clock, 9.0+3.5/67/44+10 ms cpu, 91->95->42 MB, 97 MB goal, 96 P
gc 745 @87.477s 1%: 0.11+3.3+0.069 ms clock, 10+2.7/66/41+6.6 ms cpu, 81->83->48 MB, 85 MB goal, 96 P
gc 746 @87.564s 1%: 2.0+5.6+0.11 ms clock, 194+40/82/18+11 ms cpu, 93->100->49 MB, 96 MB goal, 96 P
gc 747 @87.590s 1%: 1.8+6.8+0.099 ms clock, 179+24/75/23+9.5 ms cpu, 99->109->67 MB, 100 MB goal, 96 P
gc 748 @87.650s 1%: 7.9+13+0.072 ms clock, 759+37/86/23+6.9 ms cpu, 126->142->57 MB, 135 MB goal, 96 P
gc 749 @87.697s 1%: 0.71+3.6+0.11 ms clock, 68+2.2/66/40+11 ms cpu, 107->110->54 MB, 114 MB goal, 96 P
gc 750 @87.756s 1%: 0.20+3.5+0.10 ms clock, 19+7.0/70/8.0+9.6 ms cpu, 100->105->44 MB, 109 MB goal, 96 P

Here a look of the trace in detail:

Would love to see if you have some pointers on how to debug this further.

[odeke-em]

Thank you for filing this bug @rafael, welcome to the Go project, and great to catch you here!

I shall kindly loop in the runtime crew @dr2chase @mknyszek @aclements @randall77 @cherrymui.

[mknyszek]

That looks a lot to me like #10958 which should have been fixed by #24543... but it could be one of the points listed at #36365. Do you happen to know if your service is generating a lot of fairly large allocations and therefore doing a lot of zeroing in the runtime? That's one place where the scheduler still can't quite preempt that we've seen is still an issue for other folks (having trouble finding the GitHub issue for it). What are the blue and orange goroutines doing during that "STW"?

[dr2chase]

Several pause-causes are described in #27732 ; you might want to give that a look, and I'll stare hard at you traces for a bit. We fixed some of those hiccups, but not all.

[rafael]

Thanks @odeke-em! Great to see you over here 🙌

@mknyszek / @dr2chase thanks for the pointers. I will start looking at those to see if it could explain what we are seeing.

Do you happen to know if your service is generating a lot of fairly large allocations and therefore doing a lot of zeroing in the runtime?

What would be considered big? This is doing a fairly large of allocations but most of them seem small to me. I have uploaded a heap profile here so you can take a look.

This is the overall amount of allocation reported by this host. It is important to call out that we are trying to move a lot of data. During some of these tests we are pushing 200MB/s of data through the network:

What are the blue and orange goroutines doing during that "STW"?

It's always kind of similar. From the application perspective, around these pauses what I've seen is that it's either reading from a unix socket or marshaling data into protocol buffers. It's always stopping at a malloc call, but I'm assuming this is just where golang was able to stop the goroutine.

Here detailed example from a bigger pause:

The blue here is reading from a unix socket:

Then for the purple one, this is the end stack trace:

[mknyszek]

The fact that the stack trace has a makeslice in it suggests very strongly to me that the scheduler got stuck trying to preempt allocation of some large buffer (and specifically zeroing, the allocation itself is likely relatively fast, definitely much less than several milliseconds, even for large things). These pauses occur relatively often judging by the GC trace so I don't think it's the runtime talking to the OS or anything, either.

I suspect that these large buffers aren't showing up in the heap profile that you shared because that's an inuse_space profile and there probably aren't too many of these buffers live at the same time. It would be great if we could confirm this is the problem by identifying how large these buffers are.

[rafael]

Thinking how can we instrument this. Is there something in the golang profiling toolkit that I can leverage to confirm this?

[dr2chase]

@mknyszek was going to make a suggestion, decided to make a CL instead. Incoming....

Is a megabyte something that we can zero "quickly"? That was the lump size I chose. I tested it with 1k, of course.

[gopherbot]

Change https://golang.org/cl/270943 mentions this issue: runtime: break up large calls to memclrNoHeapPointers to allow preemption

[rafael]

Anecdotally, after @mknyszek comment about large buffers, I tried a change in Vitess codebase that seemed to have helped. I need to gather more data to confirm. I'll post more info about this tomorrow.

[dr2chase]

The second version of the CL above might also help; it addresses one instance of uninterruptibly zeroing large buffers that would have caused the traces you provided.

[rafael]

I used the stats from Memstats by size allocations and this is the distribution:

0      ▏ 0
8      ▌ 1.557397117e+09
16     ███████████████████▏ 6.0339252894e+10
32     █████▌ 1.7407392825e+10
48     ████▏ 1.3326983655e+10
64     ███████▏ 2.2233258888e+10
80     ██████ 1.8959178597e+10
96     ██ 6.076362153e+09
112    ▏ 5.83462182e+08
128    ▌ 1.317646087e+09
144    █▎ 3.903451002e+09
160    █▏ 3.587883411e+09
176    ▏ 1.02819092e+08
192    ▏ 2.58323406e+08
208    ▍ 1.211457619e+09
224    █▎ 3.962731206e+09
240    █▏ 3.651110021e+09
256    ▎ 7.86321473e+08
288    ▊ 2.355958895e+09
320    ▎ 7.27910111e+08
352    ▏ 4.7019461e+08
384    ▏ 2.21418366e+08
416    ▏ 1.26196223e+08
448    ▏ 1.14244214e+08
480    ▏ 1.36488985e+08
512    ▏ 8.1271424e+07
576    ▏ 1.69730361e+08
640    ▏ 3.29448594e+08
704    ▏ 5.3287569e+07
768    ▏ 1.42214736e+08
896    ▍ 1.072132732e+09
1024   ▍ 1.009615789e+09
1152   ▏ 1.28482225e+08
1280   ▏ 8.6099698e+07
1408   ▏ 6.0357244e+07
1536   ▏ 8.4883717e+07
1792   ▏ 2.05473615e+08
2048   ▏ 3.66724011e+08
2304   ▏ 2.66266386e+08
2688   ▏ 2.37473527e+08
3072   ▏ 1.24092779e+08
3200   ▏ 7.841361e+06
3456   ▏ 3.0968758e+07
4096   ▏ 1.07436131e+08
4864   ▏ 2.5853161e+07
5376   ▏ 1.8418524e+07
6144   ▏ 3.2067115e+07
6528   ▏ 1.407301e+07
6784   ▏ 1.0100237e+07
6912   ▏ 3.334964e+06
8192   ▏ 3.1100912e+07
9472   ▏ 1.5581866e+07
9728   ▏ 1.963955e+06
10240  ▏ 6.2289e+06
10880  ▏ 3.8646e+06
12288  ▏ 2.1823942e+07
13568  ▏ 7.014784e+06
14336  ▏ 2.612276e+06
16384  ▏ 1.9442245e+07
18432  ▏ 3.851829e+06
19072  ▏ 1.08006e+06

Overall, it doesn't look like the service is doing large allocations. Is there something I'm still missing here?

[mknyszek]

@rafael MemStats.BySize doesn't include allocations larger than 32 KiB and the runtime doesn't track them exactly, only a total. Fishing this out is going to be a bit tricky. We're probably looking for something on the order of tens of MiB. It might be more likely to show up in an alloc_space view of a heap profile? It's just another view of the heap profile whose screenshot you shared earlier, which is an inuse_space view; look for the --sample_index flag in the pprof tool's help section.

It's also still possible this is something else entirely, and that we're just getting "lucky" and the first possible preemption is at an allocation. We may need to just instrument the runtime to try to confirm this.

[rafael]

Cool! Let me do that. FWIW, I also manually instrumented the area of the vitess codebase were most of the allocations are happening in this program and also didn't notice large allocations.

[rafael]

@mknyszek uploaded the alloc_space view here for the same heap profile I shared earlier.