6. 如何观察 Go GC？

我们以下面的程序为例，先使用四种不同的方式来介绍如何观察 GC，并在后面的问题中通过几个详细的例子再来讨论如何优化 GC。

  1. package main
  3. func allocate() {
  4.     _ = make([]byte, 1<<20)
  5. }
  7. func main() {
  8.     for n := 1; n < 100000; n++ {
  9.         allocate()
  10.     }
  11. }

方式1：GODEBUG=gctrace=1

我们首先可以通过

  1. $ go build -o main
  2. $ GODEBUG=gctrace=1 ./main
  4. gc 1 @0.000s 2%: 0.009+0.23+0.004 ms clock, 0.11+0.083/0.019/0.14+0.049 ms cpu, 4->6->2 MB, 5 MB goal, 12 P
  5. scvg: 8 KB released
  6. scvg: inuse: 3, idle: 60, sys: 63, released: 57, consumed: 6 (MB)
  7. gc 2 @0.001s 2%: 0.018+1.1+0.029 ms clock, 0.22+0.047/0.074/0.048+0.34 ms cpu, 4->7->3 MB, 5 MB goal, 12 P
  8. scvg: inuse: 3, idle: 60, sys: 63, released: 56, consumed: 7 (MB)
  9. gc 3 @0.003s 2%: 0.018+0.59+0.011 ms clock, 0.22+0.073/0.008/0.042+0.13 ms cpu, 5->6->1 MB, 6 MB goal, 12 P
  10. scvg: 8 KB released
  11. scvg: inuse: 2, idle: 61, sys: 63, released: 56, consumed: 7 (MB)
  12. gc 4 @0.003s 4%: 0.019+0.70+0.054 ms clock, 0.23+0.051/0.047/0.085+0.65 ms cpu, 4->6->2 MB, 5 MB goal, 12 P
  13. scvg: 8 KB released
  14. scvg: inuse: 3, idle: 60, sys: 63, released: 56, consumed: 7 (MB)
  15. scvg: 8 KB released
  16. scvg: inuse: 4, idle: 59, sys: 63, released: 56, consumed: 7 (MB)
  17. gc 5 @0.004s 12%: 0.021+0.26+0.49 ms clock, 0.26+0.046/0.037/0.11+5.8 ms cpu, 4->7->3 MB, 5 MB goal, 12 P
  18. scvg: inuse: 5, idle: 58, sys: 63, released: 56, consumed: 7 (MB)
  19. gc 6 @0.005s 12%: 0.020+0.17+0.004 ms clock, 0.25+0.080/0.070/0.053+0.051 ms cpu, 5->6->1 MB, 6 MB goal, 12 P
  20. scvg: 8 KB released
  21. scvg: inuse: 1, idle: 62, sys: 63, released: 56, consumed: 7 (MB)

在这个日志中可以观察到两类不同的信息：

  1. gc 1 @0.000s 2%: 0.009+0.23+0.004 ms clock, 0.11+0.083/0.019/0.14+0.049 ms cpu, 4->6->2 MB, 5 MB goal, 12 P
  2. gc 2 @0.001s 2%: 0.018+1.1+0.029 ms clock, 0.22+0.047/0.074/0.048+0.34 ms cpu, 4->7->3 MB, 5 MB goal, 12 P
  3. ...

以及：

  1. scvg: 8 KB released
  2. scvg: inuse: 3, idle: 60, sys: 63, released: 57, consumed: 6 (MB)
  3. scvg: inuse: 3, idle: 60, sys: 63, released: 56, consumed: 7 (MB)
  4. ...

对于用户代码向运行时申请内存产生的垃圾回收：

  1. gc 2 @0.001s 2%: 0.018+1.1+0.029 ms clock, 0.22+0.047/0.074/0.048+0.34 ms cpu, 4->7->3 MB, 5 MB goal, 12 P

含义由下表所示：

字段 含义
gc 2 第二个 GC 周期
0.001 程序开始后的 0.001 秒
2% 该 GC 周期中 CPU 的使用率
0.018 标记开始时， STW 所花费的时间（wall clock）
1.1 标记过程中，并发标记所花费的时间（wall clock）
0.029 标记终止时， STW 所花费的时间（wall clock）
0.22 标记开始时， STW 所花费的时间（cpu time）
0.047 标记过程中，标记辅助所花费的时间（cpu time）
0.074 标记过程中，并发标记所花费的时间（cpu time）
0.048 标记过程中，GC 空闲的时间（cpu time）
0.34 标记终止时， STW 所花费的时间（cpu time）
4 标记开始时，堆的大小的实际值
7 标记结束时，堆的大小的实际值
3 标记结束时，标记为存活的对象大小
5 标记结束时，堆的大小的预测值
12 P 的数量

wall clock 是指开始执行到完成所经历的实际时间，包括其他程序和本程序所消耗的时间；cpu time 是指特定程序使用 CPU 的时间；他们存在以下关系：

  • wall clock < cpu time: 充分利用多核
  • wall clock ≈ cpu time: 未并行执行
  • wall clock > cpu time: 多核优势不明显

对于运行时向操作系统申请内存产生的垃圾回收（向操作系统归还多余的内存）：

  1. scvg: 8 KB released
  2. scvg: inuse: 3, idle: 60, sys: 63, released: 57, consumed: 6 (MB)

含义由下表所示：

字段 含义
8 KB released 向操作系统归还了 8 KB 内存
3 已经分配给用户代码、正在使用的总内存大小 (MB)
60 空闲以及等待归还给操作系统的总内存大小（MB）
63 通知操作系统中保留的内存大小（MB）
57 已经归还给操作系统的（或者说还未正式申请）的内存大小（MB）
6 已经从操作系统中申请的内存大小（MB）

方式2：go tool trace

go tool trace 的主要功能是将统计而来的信息以一种可视化的方式展示给用户。要使用此工具，可以通过调用 trace API：

  1. package main
  3. func main() {
  4.     f, _ := os.Create("trace.out")
  5.     defer f.Close()
  6.     trace.Start(f)
  7.     defer trace.Stop()
  8.     (...)
  9. }

并通过 

  1. $ go tool trace trace.out
  2. 2019/12/30 15:50:33 Parsing trace...
  3. 2019/12/30 15:50:38 Splitting trace...
  4. 2019/12/30 15:50:45 Opening browser. Trace viewer is listening on http://127.0.0.1:51839

命令来启动可视化界面：

6. 如何观察 Go GC？ - 图1

选择第一个链接可以获得如下图示：

6. 如何观察 Go GC？ - 图2

右上角的问号可以打开帮助菜单，主要使用方式包括：

  • w/s 键可以用于放大或者缩小视图
  • a/d 键可以用于左右移动
  • 按住 Shift 可以选取多个事件

方式3：debug.ReadGCStats

此方式可以通过代码的方式来直接实现对感兴趣指标的监控，例如我们希望每隔一秒钟监控一次 GC 的状态：

  1. func printGCStats() {
  2.     t := time.NewTicker(time.Second)
  3.     s := debug.GCStats{}
  4.     for {
  5.         select {
  6.         case <-t.C:
  7.             debug.ReadGCStats(&s)
  8.             fmt.Printf("gc %d last@%v, PauseTotal %v\n", s.NumGC, s.LastGC, s.PauseTotal)
  9.         }
  10.     }
  11. }
  12. func main() {
  13.     go printGCStats()
  14.     (...)
  15. }

我们能够看到如下输出：

  1. $ go run main.go
  3. gc 4954 last@2019-12-30 15:19:37.505575 +0100 CET, PauseTotal 29.901171ms
  4. gc 9195 last@2019-12-30 15:19:38.50565 +0100 CET, PauseTotal 77.579622ms
  5. gc 13502 last@2019-12-30 15:19:39.505714 +0100 CET, PauseTotal 128.022307ms
  6. gc 17555 last@2019-12-30 15:19:40.505579 +0100 CET, PauseTotal 182.816528ms
  7. gc 21838 last@2019-12-30 15:19:41.505595 +0100 CET, PauseTotal 246.618502ms

方式4：runtime.ReadMemStats

除了使用 debug 包提供的方法外，还可以直接通过运行时的内存相关的 API 进行监控：

  1. func printMemStats() {
  2.     t := time.NewTicker(time.Second)
  3.     s := runtime.MemStats{}
  5.     for {
  6.         select {
  7.         case <-t.C:
  8.             runtime.ReadMemStats(&s)
  9.             fmt.Printf("gc %d last@%v, next_heap_size@%vMB\n", s.NumGC, time.Unix(int64(time.Duration(s.LastGC).Seconds()), 0), s.NextGC/(1<<20))
  10.         }
  11.     }
  12. }
  13. func main() {
  14.     go printMemStats()
  15.     (...)
  16. }
  1. $ go run main.go
  3. gc 4887 last@2019-12-30 15:44:56 +0100 CET, next_heap_size@4MB
  4. gc 10049 last@2019-12-30 15:44:57 +0100 CET, next_heap_size@4MB
  5. gc 15231 last@2019-12-30 15:44:58 +0100 CET, next_heap_size@4MB
  6. gc 20378 last@2019-12-30 15:44:59 +0100 CET, next_heap_size@6MB

当然，后两种方式能够监控的指标很多，读者可以自行查看 debug.GCStats [2] 和runtime.MemStats [3] 的字段，这里不再赘述。