#go gctrace 调试GC日志
gctrace 用途主要是用于跟踪 GC 的不同阶段的耗时与 GC 前后的内存量对比。
信息比较简洁，可以用于对 runtime 本身进行调试之外，还可以观察线上应用的 GC 情况。
Dave Cheney 就写了一个工具 gcvis 专门用于分析 gctrace 的输出，通过可视化的方式展示出指标的变化。
如果你只关心每次 GC 的整体 STW 耗时，而对每次 GC 的 mark 与 markTermination 这两个阶段各自的 STW 耗时，包括不同的 mark workers 执行时间耗时不感兴趣的话。那只需要采集 memstats.pauseNs 这个指标就可以。因为它记录了两次 mark 的过程中 STW 的耗时。
下面给出 gctrace 的用法和输出结果字段详细解释。
以下分析基于 go 1.9.3
GODEBUG='gctrace=1' go run main.go
只需要在 run 命名前加上一个环境变量。runtime 就自动分析出 gctrace=1，然后在程序运行的时候，输出相关的统计信息。
GODEBUG 变量支持 14 个参数。在 runtime 包的 doc 里其实都有简单介绍。在调度器初始化方法 schedinit() 里，会调用 parsedebugvars() 对 GODEBUG 进行初始化。
看下这块的源码：
// 这些flag可以通过在go run 命令中设置GODEBUG变量来使用。但每个flag的不同取值对应的含义并没常量标识，都是硬编码
var debug struct {
allocfreetrace int32
cgocheck int32
efence int32
gccheckmark int32
gcpacertrace int32
gcshrinkstackoff int32
gcrescanstacks int32
gcstoptheworld int32
gctrace int32
invalidptr int32
sbrk int32
scavenge int32
scheddetail int32
schedtrace int32
}
var dbgvars = []dbgVar{
{"allocfreetrace", &debug.allocfreetrace},
{"cgocheck", &debug.cgocheck},
// ...
}
func parsedebugvars() {
// ...
for p := gogetenv("GODEBUG"); p != ""; {
// ...
}
// ...
}
gctrace 取值可以等于 1，或任何大于 1 的数。
下面的输出来自取值 gctrace=1：
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
顺便也贴出官方写的简单介绍
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.
在看过 runtime 里 GC 和内存管理源码后，以上面给出的输出为例，通俗介绍下这些不同部分的含义。
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。
补充说明两点：
一、heap_live 要结合 go 的内存管理来理解。因为 go 按照不同的对象大小，会分配不同页数的 span。span 是对内存页进行管理的基本单元，每页 8k 大小。所以肯定会出现 span 中有内存是空闲着没被用上的。
不过怎么用 go 先不管，反正是把它划分给程序用了。而 heap_live 就表示所有 span 的大小。
而程序到底用了多少呢？就是在 GC 扫描对象时，扫描到的存活对象大小就是已用的大小。对应上面就是 8MB。
二、mark worker 分为三种，dedicated、fractional 和 idle。分别表示标记工作干活时的专注程度。dedicated 最专注，除非被抢占打断，否则一直干活。idle 最偷懒，干一点活就退出，控制权让给出别的 goroutine。它们都是并发标记工作里的 worker。
这块输出的源码为：
type work struct {
// ...
// tSweepTerm 开始mark阶段前的时间戳
// tMark mark阶段完成后的时间戳
// tMarkTerm markTermination阶段开始前的时间戳
// tEnd markTermination阶段结束后的时间戳
tSweepTerm, tMark, tMarkTerm, tEnd int64 // nanotime() of phase start
// heap0 开始mark阶段前，当前heap_live的大小
// heap1 开始marktermination阶段前，当前heap_live的大小
// heap2 这次GC对heap_live大小的内存进行标记对象的大小
// heapGoal 下次触发GC的内存占用目标阀值
heap0, heap1, heap2, heapGoal uint64
}
func gcMarkTermination(nextTriggerRatio float64) {
// ...
// mark阶段的STW时间
sweepTermCpu := int64(work.stwprocs) * (work.tMark - work.tSweepTerm)
// 并行mark所占用的CPU时间
markCpu := gcController.assistTime + gcController.dedicatedMarkTime + gcController.fractionalMarkTime
// markTermination阶段的STW时间
markTermCpu := int64(work.stwprocs) * (work.tEnd - work.tMarkTerm)
// 整个标记所占用的时间
cycleCpu := sweepTermCpu + markCpu + markTermCpu
work.totaltime += cycleCpu
// 总CPU时间
totalCpu := sched.totaltime + (now-sched.procresizetime)*int64(gomaxprocs)
// 整个标记所占用的时间 / 总CPU时间 。 不能超过25%
memstats.gc_cpu_fraction = float64(work.totaltime) / float64(totalCpu)
if debug.gctrace > 0 {
util := int(memstats.gc_cpu_fraction * 100)
var sbuf [24]byte
printlock()
print("gc ", memstats.numgc,
" @", string(itoaDiv(sbuf[:], uint64(work.tSweepTerm-runtimeInitTime)/1e6, 3)), "s ",
util, "%: ")
prev := work.tSweepTerm
for i, ns := range []int64{work.tMark, work.tMarkTerm, work.tEnd} {
if i != 0 {
print("+")
}
print(string(fmtNSAsMS(sbuf[:], uint64(ns-prev))))
prev = ns
}
print(" ms clock, ")
for i, ns := range []int64{sweepTermCpu, gcController.assistTime, gcController.dedicatedMarkTime + gcController.fractionalMarkTime, gcController.idleMarkTime, markTermCpu} {
if i == 2 || i == 3 {
// Separate mark time components with /.
print("/")
} else if i != 0 {
print("+")
}
print(string(fmtNSAsMS(sbuf[:], uint64(ns))))
}
print(" ms cpu, ",
work.heap0>>20, "->", work.heap1>>20, "->", work.heap2>>20, " MB, ",
work.heapGoal>>20, " MB goal, ",
work.maxprocs, " P")
if work.userForced {
print(" (forced)")
}
print("\n")
printunlock()
}
}
原文地址 zhuanlan.zhihu.com