我们以下面的程序为例,先使用四种不同的方式来介绍如何观察 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 的介绍,感谢您的阅读,如有疑问或意见请及时反馈给我们。
推荐文章:
Go语言中的GC(二)