一、GODEBUG 介绍
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
gctrace用于分析golang程序的gc信息
命令:
GODEBUG='gctrace=1' go run main.go
输出:
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,8P
释义:
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。
二、GMP 调度跟踪:schedtrace 、scheddetail
go自带的分析GMP调度的工具,功能比较有限,推荐使用更专业的工具:GDB,dlv等
command:
GODEBUG='schedtrace=1000' go run main.go -- 1000是指间隔1000ms 收集一次
GOMAXPROCS=1 GODEBUG=schedtrace=1000 go run main.go // 指定最大CPU数
output:
SCHED 1006ms: gomaxprocs=8 idleprocs=8 threads=19 spinningthreads=0 idlethreads=14 runqueue=0 [0 0 0 0 0 0 0 0]
释义:
SCHED 程序执行的时间
gomaxprocs=8 配置的处理器数(逻辑的processor,也就是Go模型中的P,会通过操作系统的线程绑定到一个物理处理器上)
idleprocs=8 空闲的处理器数
threads=19 运行期管理的线程数
spinningthreads=0 处于自旋状态的线程数
idlethreads=14 处于空闲的线程数
runqueue=0 在全局g队列中的g数(g代表goroutine)
[0 0 0 0 0 0 0 0] 代表绑定在每个处理器上的本地g队列上的g数
三、GMP 跟踪细节信息
command:
GOMAXPROCES=2 GODEBUG=schedtrace=1000,scheddetail=1 go run main.go
输出:
SCHED 4028ms: gomaxprocs=2 idleprocs=0 threads=4 spinningthreads=0
idlethreads=1 runqueue=2 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
P0: status=1 schedtick=10 syscalltick=0 m=3 runqsize=3 gfreecnt=0
P1: status=1 schedtick=10 syscalltick=1 m=2 runqsize=3 gfreecnt=0
M3: p=0 curg=4 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0 spinning=0 blocked=0 lockedg=-1
M2: p=1 curg=10 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0 spinning=0 blocked=0 lockedg=-1
M1: p=-1 curg=-1 mallocing=0 throwing=0 gcing=0 locks=1 dying=0 helpgc=0 spinning=0 blocked=0 lockedg=-1
M0: p=-1 curg=-1 mallocing=0 throwing=0 gcing=0 locks=0 dying=0 helpgc=0 spinning=0 blocked=0 lockedg=-1
G1: status=4(semacquire) m=-1 lockedm=-1
G2: status=4(force gc (idle)) m=-1 lockedm=-1
G3: status=4(GC sweep wait) m=-1 lockedm=-1
G4: status=2(sleep) m=3 lockedm=-1
G5: status=1(sleep) m=-1 lockedm=-1
G6: status=1(stack growth) m=-1 lockedm=-1
G7: status=1(sleep) m=-1 lockedm=-1
G8: status=1(sleep) m=-1 lockedm=-1
G9: status=1(stack growth) m=-1 lockedm=-1
G10: status=2(sleep) m=2 lockedm=-1
G11: status=1(sleep) m=-1 lockedm=-1
G12: status=1(sleep) m=-1 lockedm=-1
G13: status=1(sleep) m=-1 lockedm=-1
G17: status=4(timer goroutine (idle)) m=-1 lockedm=-1
协程状态(详细信息查看源码: http://golang.org/src/runtime/runtime.h)
Gidle, // 0
Grunnable, // 1 runnable and on a run queue
Grunning, // 2 running
Gsyscall, // 3 performing a syscall
Gwaiting, // 4 waiting for the runtime
Gmoribund_unused, // 5 currently unused, but hardcoded in gdb scripts
Gdead, // 6 goroutine is dead
Genqueue, // 7 only the Gscanenqueue is used
Gcopystack, // 8 in this state when newstack is moving the stack