Golang: Using the Garbage Collection tracing

golang garbage collection gc trace

3 min read | by Jordi Prats

Go is a garbage-collected language: It will reclaim any unused memory. This automation can sometimes introduce performance challenges. We can use the GODEBUG environment variable to provide insights into specific internal operations of the Go runtime, such as scheduling, memory allocation, and garbage collection.

We can set the GODEBUG environment variable to gctrace=1 to enable tracing for the garbage collector. Go is going to output detailed logs about each garbage collection cycle to the standard error output. This is particularly useful for understanding how often garbage collection is happening, how much time it is taking, and how it affects the overall performance of your application.

gc 1 @0.005s 0%: 0.006+0.29+0.003 ms clock, 0.068+0.043/0.47/0.057+0.034 ms cpu, 3->3->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 2 @0.010s 1%: 0.025+0.29+0.004 ms clock, 0.25+0.21/0.52/0.006+0.045 ms cpu, 3->3->1 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 10 P
(...)
gc 1 @0.007s 4%: 0.022+0.53+0.17 ms clock, 0.22+0.17/1.1/0.25+1.7 ms cpu, 3->4->2 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 10 P
gc 47 @128.598s 0%: 0.21+4.4+0.004 ms clock, 2.1+0/13/0+0.047 ms cpu, 50->50->16 MB, 62 MB goal, 0 MB stacks, 0 MB globals, 10 P
GC forced

In the previous example, the lines starting with gc are telling us the following information (using the first line as an example):

  • gc: The first word is always gc, indicating that this is a garbage collection cycle.
  • 1: The number after gc is the garbage collection number. This is a counter that increments with each garbage collection cycle. If we see it going back to 1, it's just another child reporting it's stats.
  • @0.005s: Seconds since the program started.
  • 0%: The percentage of the available CPU spent in garbage collection.
  • 0.006+0.29+0.003 ms clock: Wall-clock/CPU times for the phases of the GC.
  • 0.068+0.043/0.47/0.057+0.034 ms cpu: CPU times for the phases of the GC.
  • 3->3->0 MB: Heap size at GC start, at GC end, and live heap.
  • 4 MB goal: Heap size goal.
  • 0 MB stacks:
  • 0 MB globals:
  • 10 P: Number of logical processors or threads used to run Goroutines.

We might also see some lines with GC forced. This means that the garbage collector was forced to run even though it wasn't necessary: It will forcefully run every two minutes, being just an heuristic to keep the memory usage under control.

To learn more about the garbage collector in Go, you can check the official documentation at https://tip.golang.org/doc/gc-guide.

Posted on 30/10/2024

Categories