新手问题 Go GC打印出来的这些信息都是什么含义?

astaxie · 2016年11月02日 · 最后由 cbsheng 回复于 2019年07月08日 · 153 次阅读
gc 87 @2.361s 9%: 0.032+2.6+0.13 ms clock, 0.26+2.7/4.9/4.2+1.1 ms cpu, 19->19->9 MB, 20 MB goal, 8 P
gc 88 @2.375s 9%: 0.006+2.1+0.18 ms clock, 0.051+0.048/3.8/9.0+1.4 ms cpu, 18->18->9 MB, 19 MB goal, 8 P
gc 89 @2.402s 9%: 0.005+1.7+0.11 ms clock, 0.047+0.032/3.1/8.7+0.95 ms cpu, 18->18->10 MB, 19 MB goal, 8 P
gc 90 @2.412s 9%: 0.004+1.7+0.080 ms clock, 0.039+0/3.4/10+0.64 ms cpu, 19->19->9 MB, 20 MB goal, 8 P
gc 91 @2.457s 9%: 0.006+2.4+0.14 ms clock, 0.049+0.53/3.7/0+1.1 ms cpu, 18->18->6 MB, 19 MB goal, 8 P
gc 92 @10.996s 2%: 0.011+2.1+0.33 ms clock, 0.088+0/3.7/10+2.6 ms cpu, 11->12->6 MB, 12 MB goal, 8 P
gc 93 @68.771s 0%: 0.012+1.9+0.089 ms clock, 0.098+0.010/3.2/8.5+0.71 ms cpu, 12->12->6 MB, 13 MB goal, 8 P

当我们调试 GC 打开 GODEBUG=gctrace=1 打开的时候就会输出如上所示的这些信息,这些都是对应什么意思啊?

更多原创文章干货分享,请关注公众号
  • 加微信实战群请加微信(注明:实战群):gocnio
Currently, it is:
    gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P
where the fields are as follows:
    gc #        the GC number, incremented at each GC
    @#s         time in seconds since program start
    #%          percentage of time spent in GC since program start
    #+...+#     wall-clock/CPU times for the phases of the GC
    #->#-># MB  heap size at GC start, at GC end, and live heap
    # MB goal   goal heap size
    # P         number of processors used
The phases are stop-the-world (STW) sweep termination, concurrent
mark and scan, and STW mark termination. The CPU times
for mark/scan are broken down in to assist time (GC performed in
line with allocation), background GC time, and idle GC time.
If the line ends with "(forced)", this GC was forced by a
runtime.GC() call and all phases are STW.

http://stackoverflow.com/questions/20551748/decipher-golang-garbage-collection-output

https://godoc.org/runtime

ctrl-f gctrace ~ 另外不同版本的 go 输出有差异

  • 0.005+1.7+0.11 ms 这三个分别表示什么意思?
  • 0.039+0/3.4/10+0.64 ms 这三个表示什么意思
  • 13 MB goal goal 是什么意思啊?

这个 gc 信息怎么开启啊

以这个举例: gc 252 @4316.062s 0%: 0.013+2.9+0.050 ms clock, 0.10+0.23/5.4/12+0.40 ms cpu, 16->17->8 MB, 17 MB goal, 8 P

gc 252: 这是第 252 次 gc。

@4316.062s: 这次 gc 的 markTermination 阶段完成后,距离 runtime 启动到现在的时间。

0%:当目前为止,gc 的标记工作(包括两次 mark 阶段的 STW 和并发标记)所用的 CPU 时间占总 CPU 的百分比。

0.013+2.9+0.050 ms clock:按顺序分成三部分,0.013 表示 mark 阶段的 STW 时间(单 P 的);2.9 表示并发标记用的时间(所有 P 的);0.050 表示 markTermination 阶段的 STW 时间(单 P 的)。

0.10+0.23⁄5.4⁄12+0.40 ms cpu:按顺序分成三部分,0.10 表示整个进程在 mark 阶段 STW 停顿时间 (0.013 * 8);0.23⁄5.4/12 有三块信息,0.23 是 mutator assists 占用的时间,5.4 是 dedicated mark workers+fractional mark worker 占用的时间,12 是 idle mark workers 占用的时间。这三块时间加起来会接近 2.9*8(P 的个数);0.40 ms 表示整个进程在 markTermination 阶段 STW 停顿时间 (0.050 * 8)。

16->17->8 MB:按顺序分成三部分,16 表示开始 mark 阶段前的 heap_live 大小;17 表示开始 markTermination 阶段前的 heap_live 大小;8 表示被标记对象的大小。

17 MB goal:表示下一次触发 GC 的内存占用阀值是 17MB,等于 8MB * 2,向上取整。

8 P:本次 gc 共有多少个 P。

http://cbsheng.github.io/posts/godebug%E4%B9%8Bgctrace%E8%A7%A3%E6%9E%90/

需要 登录 后方可回复, 如果你还没有账号请点击这里 注册