GOGCTRACE and collection time

Question

Go supports a GOGCTRACE environment variable, and prints collection statistics on each run. However it doesn't print when the GC occurred. Example:

gc6231(8): 0+1+0 ms, 10 -> 5 MB 89540 -> 5294 (520316701-520311407) objects, 9(80) handoff, 32(404) steal, 288/168/37 yields

How do I correlate a collection line, with the time it occurred?

Answer 1

The trace does not show an absolute time but one relative to the output. When the line occurs the GC happened 0 + 1 + 0 ms ago.

See the corresponding output line in the code for reference.

If you prefix each line on stdout with a timestamp you then get the time of the GC run (timestamp - time in milliseconds = time the GC ran).

Example:

GOGCTRACE=1 ./myprog 2>&1 | while read line; do echo $(date +%s) $line; done

If you just want to have a feeling when a GC run happened with accuracy of seconds then this is totally sufficient. The output will most likely not lag behind much and even if it does, you'd still have the timestamps to get the correct time.

Another solution would be to use ReadGCStats from runtime/debug which gives you the GCStats struct, which in turn has a field LastGC of type time.Time, holding the absolute time of the last GC run. Alternatively you can use runtime.ReadMemStats, which gives you even more information.

Of course you would still need to know when a garbage collection happened. For this you could use a finalizer on a object which you create solely for the purpose of being garbage collected and apply runtime.SetFinalizer on it. In the finalizer you would then read the LastGC time and print it.

Example (on play):

type Garbage struct{ a int }

func notify(f *Garbage) {
    stats := &runtime.MemStats{}
    runtime.ReadMemStats(stats)

    fmt.Println("Last GC was:", stats.LastGC)

    go ProduceFinalizedGarbage()
}

func ProduceFinalizedGarbage() {
    x := &Garbage{}
    runtime.SetFinalizer(x, notify)
}

func main() {
    go ProduceFinalizedGarbage()

    for {
        runtime.GC()
        time.Sleep(30 * time.Second) // Give GC time to run
    }
}