runtime: high memory usage on Go 1.14

[karalabe]

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

1.13.8 vs 1.14

Does this issue reproduce with the latest release?

Yes

What did you do?

I wanted to benchmark the go-etheruem full sync performance with the new Go release vs. the old one. Speed wise Go 1.14 is maybe 10-15% faster, but that's not what this issue is about.

What did you expect to see?

Faster execution at the same memory usage.

What did you see instead?

Side by side, go-ethereum built with:

• Go 1.13 used (runtime.MemStats.Alloc) 7.5GB RAM and held (runtime.MemStats.HeapSys - runtime.MemStats.HeapReleased) 9GB
• Go 1.14 used (runtime.MemStats.Alloc) 8.5GB RAM and held (runtime.MemStats.HeapSys - runtime.MemStats.HeapReleased) 11GB

I've ran the tests on 4 VMs (two on Go 1.13 and two on Go 1.14), swapping the Go builds and restarting after a day to avoid false positives due to VM asymmetries. The results were the same on all 4 comparison runs. Go 1.14 was 10% faster and used significantly more memory.

---

At this point I'm unsure how I could help debug this further. Have there been any memory allocation changes made in Go 1.14 that could point towards heavier use? We do maintain significant in-memory caches, some large blobs, some tiny tiny slices. Perhaps some internal map field got more expensive?

[karalabe]

One other idea. We do tweak the GC percentage via SetGCPercent on startup. Perhaps Go 1.13 and Go 1.14 behaves differently wrt to GOGC?

[ianlancetaylor]

CC @mknyszek @aclements

[mknyszek]

@karalabe The most useful thing in this scenario would be a bunch of heap profiles from both Go 1.13 and Go 1.14 runs. That will tell us a lot about the difference in "used."

I have a hunch it's not more total allocated bytes and instead it's more likely that objects are being kept alive longer. In working on #35112 I did run into GC pacing changes (as a result of an increased allocation rate in some cases) that caused more objects to stay alive, which snowballed into up to a 2x RSS increase. We made a GC pacing change to stave off the most severe effects but it could still cause an RSS increase in some cases.

If it does turn out to be this, then my recommendation is to just lower GOGC until you reach an acceptable level of memory use per performance (for whatever that metric is; wall clock time, latency, throughput, etc.). The overall performance should still be similar or better. If not, we'll move on from there.

The increase in "held" being larger than "used" could just be fragmentation scaling up, but it could also be #35788 playing a role. Let's tackle "used" first, the "held" increase might go away (or only be slight).

[pijng]

I'm facing the same problem.
Working on load balancer with reverseproxy and built-in cache.
For test purposes returning the same value from cache on each request.

go1.13.3 darwin/amd64 with debug.SetGCPercent(3) produces ~87 NumGC on 200k requests and RSS peak at ~80mb.

go1.14 darwin/amd64 with debugSetGCPercent(3) produces ~8 NumGC on 200k requests and RSS peak at ~698mb.

[mknyszek]

I'm facing the same problem.
Working on load balancer with reverseproxy and built-in cache.
For test purposes returning the same value from cache on each request.

go1.13.3 darwin/amd64 with debug.SetGCPercent(3) produces ~87 NumGC on 200k requests and RSS peak at ~80mb.

go1.14 darwin/amd64 with debugSetGCPercent(3) produces ~8 NumGC on 200k requests and RSS peak at ~698mb.

The fact that fewer GCs are happening suggests to me a snowball scenario in live heap.

Can you please share the output of running your benchmark/application with GODEBUG=gctrace=1 (both 1.13 and 1.14)? With such a dramatic difference, and only 8 GCs in Go 1.14, this should hopefully tell us a lot.

[pijng]

@mknyszek sure, here's the output!

1.13.3:
https://drive.google.com/file/d/1zzG6Yw9vGyeSSKhSMVH-f6tsqQOxm063/view?usp=sharing

1.14:
https://drive.google.com/file/d/1t8hp26A9kthReUn_SLiGADRMztgewDZx/view?usp=sharing

UPD: sorry, for some reasons I thought there were 87 GC cycles when I ran the tests for the first time, but now it's always 59 on each run. Still, the difference is huge.

[mknyszek]

@pijng Thanks for the prompt reply!

So one thing I'll note is that 1.13.3 has a 1 GiB heap still, which doesn't square quite right with your 80 MiB number. Could you explain more how you obtained that?

In Go 1.14, it looks like a few GCs end up having larger heaps (1.6 GiB) so there's still a clear peak memory use increase. It almost seems like there's an out-running happening here; the heap goal of e.g. GC 4 is 1025 MiB and then suddenly the next GC starts at 1683 MiB of heap which is very off. The 1.13.3 trace suggests your application isn't just suddenly making a 600 MiB allocation (which is the usual way something like this might happen), so instead it seems like the GC start condition is being missed.

Also, could you re-run the Go 1.14 one with GODEBUG=gctrace=1,gcpacertrace=1 and share the output? (Sorry to ask you to keep re-running, I should've asked you to enable the pacer trace the first time...)

[pijng]

@mknyszek I'm looking at the "Physical memory" of my process on the macos' built-in activity monitor. That's where I got the numbers from. I'm not experienced enough in this matter, so if you can tell me a proper way to obtain a helpful stats – I'll make sure to do it :)

Output with GODEBUG=gctrace=1,gcpacertrace=1
1.13.3
https://drive.google.com/file/d/1HdoSKJQL8zKhl1GXyiACOaBP1ge0J0A5/view?usp=sharing

1.14
https://drive.google.com/file/d/1jUevlPCh45CmkpZCjGEEemDjKrWv41jd/view?usp=sharing

[mknyszek]

@pijng I think I have a root cause for your problem and I submitted a new issue. We should continue the conversation there, since it may be unrelated to this issue.

@karalabe Given that you mentioned that you tweak GC percent, what do you tweak it to? Based on the value, your problem may be the same as #37927 (but I don't want to assume).

[karalabe]

@mknyszek Our GOGC tweak is https://github.com/ethereum/go-ethereum/blob/613af7ceea0f94b92f0e63e8db3a5f5926421087/cmd/geth/main.go#L288

I.e. math.Max(20, math.Min(100, 100/(float64(cache)/1024))), where cache is 4096 in the charts I posted. So all in all, we're running with GOGC=25 in my opening post.

[mknyszek]

@karalabe OK! Then it seems to me like this could definitely be #37927. Could you try running your application/benchmark against a Go toolchain with the following patch? https://go-review.googlesource.com/c/go/+/223937

[karalabe]

Can confirm that the patch released in Go 1.14.2 indeed fixes the spurious memory blowup. Thanks!