一、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