runtime: sysmon can double-trigger GC

[rhysh]

When sysmon triggers a GC, the messages from GODEBUG=gctrace=1 show multiple "GC forced" lines and sometimes show that two consecutive GCs were forced.

I've included the output from of a run of issue #12026's test program demonstrating both bugs.

$ go version
go version devel +e4e4942 Tue Dec 1 23:12:09 2015 +0000 darwin/amd64

$ GODEBUG=gctrace=1 ./issue12026
begin
gc 1 @0.001s 7%: 0.083+0+0+0.10+0.49 ms clock, 0.16+0+0+0/0.087/0.047+0.99 ms cpu, 4->5->2 MB, 5 MB goal, 8 P
gc 2 @0.002s 6%: 0.037+0+0+0.66+0.049 ms clock, 0.22+0+0+0.008/0.071/0.074+0.29 ms cpu, 4->5->3 MB, 5 MB goal, 8 P
gc 3 @0.004s 17%: 0.003+0+0+0.10+0.61 ms clock, 0.029+0+0+0/0.090/0.019+4.8 ms cpu, 4->5->2 MB, 5 MB goal, 8 P
gc 4 @0.005s 17%: 0.003+0+0+0.070+0.057 ms clock, 0.028+0+0+0/0.056/0.052+0.45 ms cpu, 4->4->1 MB, 5 MB goal, 8 P
gc 5 @0.005s 17%: 0.003+0+0+0.074+0.066 ms clock, 0.025+0+0+0/0.083/0.026+0.53 ms cpu, 4->4->1 MB, 5 MB goal, 8 P
gc 6 @0.006s 17%: 0.003+0+0+0.077+0.055 ms clock, 0.026+0+0+0/0.061/0.057+0.44 ms cpu, 4->4->1 MB, 5 MB goal, 8 P
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
gc 7 @120.007s 0%: 0.042+0+0+0.84+0.066 ms clock, 0.30+0+0+0/1.5/0.18+0.46 ms cpu, 3->3->1 MB, 4 MB goal, 8 P
gc 8 @120.008s 0%: 0.098+0+0+0.094+0.075 ms clock, 0.59+0+0+0/0.10/0.050+0.45 ms cpu, 1->1->1 MB, 4 MB goal, 8 P
gc 9 @125.007s 0%: 0.006+0+0+0.12+0.063 ms clock, 0.051+0+0+0/0.080/0.11+0.51 ms cpu, 4->4->1 MB, 5 MB goal, 8 P
gc 10 @125.007s 0%: 0.005+0+0+0.087+0.064 ms clock, 0.040+0+0+0/0.080/0.085+0.51 ms cpu, 4->4->1 MB, 5 MB goal, 8 P
gc 11 @125.008s 0%: 0.004+0+0+0.089+0.052 ms clock, 0.033+0+0+0/0.069/0.068+0.41 ms cpu, 4->4->1 MB, 5 MB goal, 8 P
gc 12 @125.008s 0%: 0.003+0+0+0.098+0.052 ms clock, 0.028+0+0+0/0.056/0.051+0.42 ms cpu, 4->4->1 MB, 5 MB goal, 8 P
gc 13 @125.009s 0%: 0.004+0+0+0.085+0.063 ms clock, 0.034+0+0+0/0.090/0.031+0.50 ms cpu, 4->4->1 MB, 5 MB goal, 8 P
gc 14 @125.009s 0%: 0.003+0+0+0.068+0.11 ms clock, 0.027+0+0+0/0.059/0.064+0.91 ms cpu, 4->4->1 MB, 5 MB goal, 8 P
end

Allocations are responsible for gc1 through gc6 and for gc9 through gc14. gc7 is correctly triggered by sysmon, but gc8 is an unexpected second sysmon-triggered run. Additionally, I'd expect only a single "GC forced" line between gc6 and gc7.

CC @aclements

[aclements]

What's happening is that sysmon triggers a forced GC based on memstats.last_gc, but memstats.last_gc isn't updated until mark termination. Hence, once sysmon starts triggering forced GC, it will keep triggering them until GC finishes. The first of these actually starts a GC (gc 7 in your trace); the remainder up to the last print "GC forced", but gcStart actually returns almost immediately because it sees the GC is running; then the last may start another GC (gc 8 in your trace) if the previous GC finishes (and sets last_gc) between sysmon triggering it and gcStart checking the GC phase.

The fix is trivial. I'll send a CL shortly.

[gopherbot]

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