runtime: TestGcSys is still flaky

[bcmills]

--- FAIL: TestGcSys (0.03s)
    gc_test.go:27: expected "OK\n", but got "using too much memory: 70486024 bytes\n"
FAIL
FAIL	runtime	50.446s

See previously #28574, #27636, #27156, #23343.

CC @mknyszek @aclements

2020-02-15T16:40:12-6917529/freebsd-amd64-race
2020-02-05T18:27:48-702226f/freebsd-amd64-race
2020-01-31T15:04:07-f2a4ab3/freebsd-amd64-race
2020-01-07T19:53:19-7d98da8/darwin-amd64-10_15
2019-12-31T12:11:24-bbd25d2/solaris-amd64-oraclerel
2019-12-11T00:01:17-9c8c27a/solaris-amd64-oraclerel
2019-11-04T15:18:34-d3660e8/plan9-386-0intro
2019-09-12T14:08:16-3d522b1/solaris-amd64-smartosbuildlet

[bcmills]

2020-03-01T02:22:06-2172b22/freebsd-amd64-race

[josharian]

Shall we disable the test for now?

[bcmills]

2020-03-15T08:14:24-dc32553/freebsd-amd64-race
2020-03-04T20:52:43-c55a50e/solaris-amd64-oraclerel

@aclements, @mknyszek: what do you want to do about this test? (Do we understand the cause of these flakes?)

[mknyszek]

@bcmills I'll take a look.

This is usually due to some GC pacing heuristic doing something weird. A GC trace should get us part of the way there.

[mknyszek]

OK sorry for the delay, finally looking into this now.

[mknyszek]

Ugh, OK. So this definitely looks like another GOMAXPROCS=1 GC pacing issue. Looking at the gctrace for a bad run on freebsd-amd64-race (which is pretty easily reproducible):

gc 1 @0.000s 1%: 0.010+0.25+0.011 ms clock, 0.010+0/0.055/0.17+0.011 ms cpu, 0->0->0 MB, 4 MB goal, 1 P (forced)
gc 2 @0.001s 3%: 0.011+0.34+0.015 ms clock, 0.011+0.15/0/0+0.015 ms cpu, 4->5->1 MB, 5 MB goal, 1 P
gc 3 @0.003s 4%: 0.011+0.91+0.014 ms clock, 0.011+0.15/0/0+0.014 ms cpu, 4->5->1 MB, 5 MB goal, 1 P
gc 4 @0.005s 4%: 0.013+0.50+0.014 ms clock, 0.013+0.15/0/0+0.014 ms cpu, 4->5->1 MB, 5 MB goal, 1 P
gc 5 @0.007s 5%: 0.010+0.45+0.013 ms clock, 0.010+0.15/0/0+0.013 ms cpu, 4->5->1 MB, 5 MB goal, 1 P
gc 6 @0.008s 6%: 0.011+0.41+0.013 ms clock, 0.011+0.14/0/0+0.013 ms cpu, 4->5->1 MB, 5 MB goal, 1 P
gc 7 @0.009s 7%: 0.012+0.38+0.013 ms clock, 0.012+0.14/0/0+0.013 ms cpu, 4->5->1 MB, 5 MB goal, 1 P
gc 8 @0.010s 7%: 0.012+0.39+0.015 ms clock, 0.012+0.16/0/0+0.015 ms cpu, 4->5->1 MB, 5 MB goal, 1 P
gc 9 @0.011s 8%: 0.012+0.39+0.018 ms clock, 0.012+0.14/0/0+0.018 ms cpu, 4->5->1 MB, 5 MB goal, 1 P
gc 10 @0.012s 5%: 0.012+10+0.014 ms clock, 0.012+0.059/0.13/0+0.014 ms cpu, 4->80->75 MB, 5 MB goal, 1 P
using too much memory: 70813704 bytes

You'll notice that in gc 10, we trigger the GC at the right time, but while it's happening we blow right past the hard goal.

The last time I debugged this, it was a problem with the fact that we didn't fall back to the hard goal even when we were doing more scan work than expected. It's hard for me to see how this is the case again, so there's likely something else going on. A thought: heap_scan is updated less frequently from local_scan in Go 1.14. Most of the GC work in this test comes from assists (because GOMAXPROCS=1). What if this is an issue where the runtime falls into a case where it's consistently behind on the assist ratio? It finally catches up and the assist work gets done, but it's too late. If that's the case, I'm not sure why this is basically impossible to reproduce on Linux, and easily reproducible on the freebsd-amd64-race builders.

[bcmills]

Hmm, this batch includes a Windows builder too:
2020-05-05T18:05:10-a8e83d5/solaris-amd64-oraclerel
2020-05-01T16:39:43-a81bc8e/windows-amd64-race
2020-03-27T16:05:42-e4a1cf8/freebsd-amd64-race

[nmeum]

I'm not sure why this is basically impossible to reproduce on Linux, and easily reproducible on the freebsd-amd64-race builders.

I think we are also running into this on armv7 and armhf on Alpine Linux edge when building go 1.14.3:

• go-armv7-1.14.3-r0.log
• go-armhf-1.14.3-r0.log

[bcmills]

2020-11-09T14:41:38-feccfb8/aix-ppc64
2020-10-06T20:30:36-04c7e32/solaris-amd64-oraclerel
2020-09-23T07:51:17-150bd4f/solaris-amd64-oraclerel
2020-09-16T17:36:58-10dfb1d/solaris-amd64-oraclerel
2020-08-18T05:23:42-a745171/solaris-amd64-oraclerel
2020-05-29T15:39:54-e8f5a33/linux-s390x-ibm
2020-05-26T21:29:55-b5bf2f0/solaris-amd64-oraclerel
2020-05-07T22:00:07-4fda7dc/solaris-amd64-oraclerel

[mknyszek]

Having dug into this before, I suspect this is related to #42430 but I'm not sure in what way.

Going back to the thought I had in March (#37331 (comment)) I did change a bunch of details in this release regarding how heap_scan is updated (specifically, more often!), so that may be why the failure rate has gone down. @bcmills are those all the recent failures?

[bcmills]

@mknyszek, those are all of the failures I could find using greplogs with the regexp FAIL: TestGcSys, yes.