Skip to content

runtime: sysmon can double-trigger GC #13458

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom
Closed
rhysh opened this issue Dec 2, 2015 · 2 comments
Closed

runtime: sysmon can double-trigger GC #13458

rhysh opened this issue Dec 2, 2015 · 2 comments
Labels
FrozenDueToAge
Milestone
Go1.6

Comments

@rhysh
Copy link
Contributor

rhysh commented Dec 2, 2015

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 aclements self-assigned this Dec 8, 2015
@aclements aclements added this to the Go1.6 milestone Dec 8, 2015
@aclements
Copy link
Member

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
Copy link
Contributor

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

@golang golang locked and limited conversation to collaborators Dec 14, 2016
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
Go1.6
Development

No branches or pull requests
3 participants
@rhysh @aclements @gopherbot