GODEBUG之gctrace解析

July 8, 2019
Golang
go
GODEBUG

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

1

GODEBUG='gctrace=1' go run main.go

只需要在run命名前加上一个环境变量。runtime就自动分析出gctrace=1，然后在程序运行的时候，输出相关的统计信息。

GODEBUG变量支持14个参数。在runtime包的doc里其实都有简单介绍。在调度器初始化方法schedinit里，会调用一个parsedebugvars方法对GODEBUG进行初始化。

看下这块的源码：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32


// 这些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的数。

下面的输出来自取值等于1：

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

顺便也贴出官方写的简单介绍

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16


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.²³⁄₅.⁴⁄₁₂+0.40 ms cpu：按顺序分成三部分，0.10表示整个进程在mark阶段STW停顿时间(0.013 * 8)；0.²³⁄₅.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。

这块输出的源码为：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75


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()
	}

}