0 full gc时cpu idle_Go语言中如何观察GC

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

package mainfunc allocate() {    _ = make([]byte, 1<<20)}func main() {    for n := 1; n < 100000; n++ {        allocate()    }}

方式一：GODEBUG=gctrace=1

我们首先可以通过命令：GODEBUG=gctrace=1 ./main 来查看，如下所示：

$ go build -o main$ GODEBUG=gctrace=1 ./maingc 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 Pscvg: 8 KB releasedscvg: inuse: 3, idle: 60, sys: 63, released: 57, consumed: 6 (MB)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 Pscvg: inuse: 3, idle: 60, sys: 63, released: 56, consumed: 7 (MB)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 Pscvg: 8 KB releasedscvg: inuse: 2, idle: 61, sys: 63, released: 56, consumed: 7 (MB)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 Pscvg: 8 KB releasedscvg: inuse: 3, idle: 60, sys: 63, released: 56, consumed: 7 (MB)scvg: 8 KB releasedscvg: inuse: 4, idle: 59, sys: 63, released: 56, consumed: 7 (MB)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 Pscvg: inuse: 5, idle: 58, sys: 63, released: 56, consumed: 7 (MB)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 Pscvg: 8 KB releasedscvg: inuse: 1, idle: 62, sys: 63, released: 56, consumed: 7 (MB)

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

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 Pgc 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...

另外还有：

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

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

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: 多核优势不明显

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

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

含义由下表所示：

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

方式二：go tool trace

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

package mainfunc main() {    f, _ := os.Create("trace.out")    defer f.Close()    trace.Start(f)    defer trace.Stop()    (...)}

并通过执行以下命令，来启动可视化界面：：

$ go tool trace trace.out2020/12/09 12:50:33 Parsing trace...2020/12/09 12:50:38 Splitting trace...2020/12/09 12:50:45 Opening browser. Trace viewer is listening on http://127.0.0.1:51839

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

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

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

方式三：debug.ReadGCStats

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

func printGCStats() {    t := time.NewTicker(time.Second)    s := debug.GCStats{}    for {        select {        case             debug.ReadGCStats(&s)            fmt.Printf("gc %d last@%v, PauseTotal %v\n", s.NumGC, s.LastGC, s.PauseTotal)        }    }}func main() {    go printGCStats()    (...)}

我们能够看到如下输出：

$ go run main.gogc 4954 last@2020-12-09 13:19:37.505575 +0100 CET, PauseTotal 29.901171msgc 9195 last@2020-12-09 13:19:38.50565 +0100 CET, PauseTotal 77.579622msgc 13502 last@2020-12-09 13:19:39.505714 +0100 CET, PauseTotal 128.022307msgc 17555 last@2020-12-09 13:19:40.505579 +0100 CET, PauseTotal 182.816528msgc 21838 last@2020-12-09 13:19:41.505595 +0100 CET, PauseTotal 246.618502ms

方式四：runtime.ReadMemStats

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

func printMemStats() {    t := time.NewTicker(time.Second)    s := runtime.MemStats{}    for {        select {        case             runtime.ReadMemStats(&s)            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))        }    }}func main() {    go printMemStats()    (...)}

$ go run main.gogc 4887 last@2020-12-09 13:44:56 +0100 CET, next_heap_size@4MBgc 10049 last@2020-12-09 13:44:57 +0100 CET, next_heap_size@4MBgc 15231 last@2020-12-09 13:44:58 +0100 CET, next_heap_size@4MBgc 20378 last@2020-12-09 13:44:59 +0100 CET, next_heap_size@6MB

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

以上是关于Go语言如何观察GC 的介绍，感谢您的阅读，如有疑问或意见请及时反馈给我们。