proposal: runtime: trace the cause which triggered a gc event #76276
Description
Proposal Details
package main
import (
"fmt"
"os"
"runtime"
"runtime/debug"
)
func bToMb(b uint64) float64 {
return float64(b) / 1024 / 1024
}
func printMemUsage() {
var m runtime.MemStats
runtime.ReadMemStats(&m)
fmt.Fprintf(os.Stderr, "Alloc = %v MiB\t", bToMb(m.Alloc))
fmt.Fprintf(os.Stderr, "TotalAlloc = %v MiB\t", bToMb(m.TotalAlloc))
fmt.Fprintf(os.Stderr, "Sys = %v MiB\t", bToMb(m.Sys))
fmt.Fprintf(os.Stderr, "NumGC = %v\n", m.NumGC)
os.Stderr.Sync()
}
func main() {
debug.SetMemoryLimit(64 << 20)
elemNumb := 100 * 1024 * 1024
i := 0
for i < 3 {
a := make([]int8, elemNumb)
a[i] = int8(i)
printMemUsage()
i++
}
}On my workstation, running GODEBUG=gctrace=1 ./main with the above program compiled to ./main outputs:
Alloc = 101.34723663330078 MiB TotalAlloc = 101.34723663330078 MiB Sys = 107.34207916259766 MiB NumGC = 0
gc 1 @0.000s 6%: 0.13+0.49+0.076 ms clock, 17+0.078/0.36/0+9.7 ms cpu, 101->101->1 MB, 101 MB goal, 0 MB stacks, 0 MB globals, 128 P
gc 2 @0.001s 8%: 0.10+0.64+0.14 ms clock, 13+0/0.75/0+19 ms cpu, 101->101->101 MB, 101 MB goal, 0 MB stacks, 0 MB globals, 128 P
Alloc = 101.3740463256836 MiB TotalAlloc = 201.38040161132812 MiB Sys = 108.46707916259766 MiB NumGC = 2
gc 3 @0.050s 0%: 0.048+0.46+0.080 ms clock, 6.2+0.18/0.68/0.060+10 ms cpu, 101->101->1 MB, 101 MB goal, 0 MB stacks, 0 MB globals, 128 P
gc 4 @0.051s 1%: 0.11+0.67+0.13 ms clock, 14+0/1.0/0.042+16 ms cpu, 101->101->101 MB, 101 MB goal, 0 MB stacks, 0 MB globals, 128 P
Alloc = 101.3942642211914 MiB TotalAlloc = 301.41857147216797 MiB Sys = 108.96707916259766 MiB NumGC = 4
It is very clear that GC running twice during each iteration in this program, but it is not very clear why GC is triggered twice. And when I comment out the printMemUsage() line in main function then rebuild and rerun this program, the gc behavior changed to:
gc 1 @0.000s 7%: 0.15+0.32+0.11 ms clock, 19+0.10/0.39/0.099+14 ms cpu, 101->101->1 MB, 101 MB goal, 0 MB stacks, 0 MB globals, 128 P
gc 2 @0.001s 10%: 0.073+0.44+0.14 ms clock, 9.3+0/0.47/0.098+17 ms cpu, 101->101->101 MB, 101 MB goal, 0 MB stacks, 0 MB globals, 128 P
Only 2 GC is triggered rather than 4 GC. I want to know why calling printMemUsage() increases the GC count. Furthermore, I propose adding the reason that triggers the GC to the gctrace output, so that users can more clearly understand what causes the GC to occur.
My workstation information:
- Distribution: Ubuntu 24.04.2 LTS
- Kernel: Linux r760 6.8.0-59-generic
- CPU: INTEL(R) XEON(R) GOLD 6530, 128 cores
- Memory: 256GB (I am working on a really good server)
- go version: version go1.25.3 linux/amd64