How do you read a line of GODEBUG=gctrace=1 output?
Question 342MediumGo 1.22 to 1.25
gc 14 @2.104s 3%: 0.021+4.1+0.034 ms clock, 0.17+1.2/7.9/15+0.27 ms cpu, 48->52->21 MB, 50 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 14 @2.104s 3%: the 14th cycle, 2.1 s after start. 3% of CPU has gone to GC since the program started.0.021+4.1+0.034 ms clock: wall-clock time for the STW sweep termination, the concurrent mark, and the STW mark termination. The first and last numbers are the pauses.0.17+1.2/7.9/15+0.27 ms cpu: CPU time for STW, then mark split into assist / background / idle, then STW. A large assist number points to allocation pressure that hurts latency.48->52->21 MB: heap when marking started, heap when it ended, and live heap after marking. The heap grew during marking because allocation continued concurrently.50 MB goal: the pacer's target for this cycle. It was computed from the live heap marked by the previous cycle, plus roots, times GOGC. This cycle's 21 MB live result sets the goal for the next cycle, about 42 MB with GOGC=100.8 P: GOMAXPROCS.
Diagnosis tips: if live heap keeps growing across cycles, suspect a leak. If GC runs many times per second with a small live heap, raise GOGC or set GOMEMLIMIT. GODEBUG=gctrace=1,gcpacertrace=1 shows the pacer's decisions as well.
More on Memory, GC & Runtime Internals
- Q340What does GOGC control, exactly? What happens with GOGC=off, 50 or 200?
- Q341What is GOMEMLIMIT and how would you set it in a container?
- Q343Why is the process RSS much larger than the heap in use? How does Go return memory to the OS?
- Q344What techniques do you use to reduce allocations in a hot path?
- Q345How does
sync.Poolbehave, and what are its pitfalls? - Q346How do you measure and assert allocation counts?