Skip to content

runtime: sysmon doesn't force GC after two minutes #12026

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.

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

Closed
rhysh opened this issue Aug 5, 2015 · 3 comments
Closed

runtime: sysmon doesn't force GC after two minutes #12026

rhysh opened this issue Aug 5, 2015 · 3 comments
Milestone

Comments

@rhysh
Copy link
Contributor

rhysh commented Aug 5, 2015

At latest tip, runtime.sysmon doesn't successfully force a GC every two minutes. It prints a "GC forced" line to the log (when running with GODEBUG=gctrace=1), but it does not cause a GC to occur.

I expected several GCs near 0 seconds, a single "GC forced" line followed by a GC near 120 seconds, and then more GCs near 125 seconds.

@aclements

$ go version
go version devel +e019767 Wed Aug 5 00:52:00 2015 +0000 darwin/amd64
package main

import (
    "log"
    "time"
)

var global []byte

func main() {
    log.SetFlags(0)
    log.Printf("begin")

    for i := 0; i < 20; i++ {
        global = make([]byte, 1<<20)
    }

    time.Sleep(2*time.Minute + 5*time.Second)

    for i := 0; i < 20; i++ {
        global = make([]byte, 1<<20)
    }

    log.Printf("end")
}
$ GODEBUG=gctrace=1 ./sleep
begin
gc 1 @0.007s 2%: 0.18+0.11+0+0.33+0.25 ms clock, 0.55+0.11+0+0.007/0.033/0.027+0.77 ms cpu, 6->9->4 MB, 4 MB goal, 8 P
gc 2 @0.008s 3%: 0.036+0.43+0.031+0.040+0.063 ms clock, 0.21+0.43+0+0.042/0/0.002+0.38 ms cpu, 5->6->2 MB, 4 MB goal, 8 P
gc 3 @0.010s 3%: 0.006+0.40+0.39+0.39+0.092 ms clock, 0.053+0.40+0+0/0.019/0.050+0.73 ms cpu, 4->7->4 MB, 6 MB goal, 8 P
gc 4 @0.012s 4%: 0.017+0.096+0.028+0.058+0.093 ms clock, 0.13+0.096+0+0.019/0/0.030+0.75 ms cpu, 5->6->3 MB, 2 MB goal, 8 P
gc 5 @0.012s 5%: 0.017+0.095+0.12+0.049+0.083 ms clock, 0.13+0.095+0+0/0/0.046+0.66 ms cpu, 4->5->3 MB, 4 MB goal, 8 P
GC forced
GC forced
GC forced
GC forced
GC forced
GC forced
gc 6 @125.014s 0%: 0.93+0.37+0.002+0.051+0.11 ms clock, 7.4+0.37+0+0.16/0.002/0.001+0.94 ms cpu, 4->4->2 MB, 4 MB goal, 8 P
gc 7 @125.017s 0%: 0.014+0.85+0.001+0.059+0.11 ms clock, 0.11+0.85+0+0.005/0.016/0.078+0.88 ms cpu, 4->5->2 MB, 4 MB goal, 8 P
gc 8 @125.019s 0%: 0.009+0.13+0.005+0.041+0.086 ms clock, 0.072+0.13+0+0.005/0/0.053+0.68 ms cpu, 4->5->2 MB, 4 MB goal, 8 P
gc 9 @125.020s 0%: 0.007+0.13+0.001+0.043+0.12 ms clock, 0.059+0.13+0+0/0.002/0.074+0.98 ms cpu, 4->5->3 MB, 4 MB goal, 8 P
gc 10 @125.021s 0%: 0.017+0.11+0.005+0.044+0.079 ms clock, 0.13+0.11+0+0/0.001/0.058+0.63 ms cpu, 4->5->3 MB, 4 MB goal, 8 P
gc 11 @125.021s 0%: 0.008+0.098+0.005+0.043+0.11 ms clock, 0.064+0.098+0+0/0.001/0.076+0.94 ms cpu, 4->5->3 MB, 4 MB goal, 8 P
gc 12 @125.022s 0%: 0.006+0.096+0.006+0.041+0.070 ms clock, 0.053+0.096+0+0/0/0.044+0.56 ms cpu, 4->5->3 MB, 4 MB goal, 8 P
gc 13 @125.022s 0%: 0.006+0.080+0.016+0.037+0.071 ms clock, 0.054+0.080+0+0.019/0/0.029+0.57 ms cpu, 4->5->2 MB, 4 MB goal, 8 P
end
@rsc rsc added this to the Go1.5Maybe milestone Aug 5, 2015
@aclements
Copy link
Member

Darn. I broke sysmon GC with 88e945f. Working on an alternate fix (and seeing if I can construct a test).

@aclements
Copy link
Member

Thanks for finding this. I've posted a fix plus a test that should ensure we don't break periodic GC in such an obvious way again: https://go-review.googlesource.com/13168.

@gopherbot
Copy link
Contributor

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

@mikioh mikioh modified the milestones: Go1.5, Go1.5Maybe Aug 5, 2015
@golang golang locked and limited conversation to collaborators Aug 5, 2016
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests

5 participants