runtime: sysmon doesn't force GC after two minutes

[rhysh]

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

[aclements]

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

[aclements]

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]

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