GODEBUG
简介
GODEBUG 环境变量可以控制程序运行时的调度信息输出，方便开发者了解程序运行内部细节。
语法是通过逗号分割多个键值对，例如:
# 运行 main.go, 每秒输出 1 次调度信息
$ GODEBUG=scheddetail=1,schedtrace=1000 go run main.go
常用参数
| 名称 | 值 | 描述 |
|---|---|---|
| scheddetail | 1 | 设置 schedtrace=X 和 scheddetail=1, 每 X 毫秒输出 1 次调度信息 |
| schedtrace | X | 每 X 毫秒输出 1 次调度信息 |
| allocfreetrace | 1 | 监控每次分配，分析和打印每个对象的分配和释放的调用堆栈 |
| cgocheck | [0, 1, 2] | CGO 是否检查 Go 指针传递给非 Go 代码, 0: 禁用 1: 弱检查 2: 强检查 |
| efence | 1 | 让分配器把每个对象都分配在一个唯一的从未回收的页面 |
| gccheckmark | 1 | 启用 GC 执行并发标记 |
| gcpacertrace | 1 | 打印并发 pacer 的内部状态 |
| gcshrinkstackoff | 1 | 禁用移动 goroutines 到较小的栈上，在这种模式下，goroutine 的栈只能增长 |
| gcstoptheworld | 1 | 禁用并发 GC，每次 GC 都会触发 STW |
| gctrace | 1 | 每次 GC 时输出一行日志，统计内存回收和暂停时间 |
| memprofilerate | [0, X] | 0: 禁用 X: 更新 runtime.MemProfileRate 的值 |
示例程序
本文后面的几个用例，全部使用该程序演示。
package main
import (
"sync"
"time"
)
func main() {
var wg sync.WaitGroup
for i := 0; i < 10; i++ {
wg.Add(1)
go func() {
defer wg.Done()
time.Sleep(1 * time.Second)
}()
}
wg.Wait()
}
输出调度基础信息
执行命令
$ GODEBUG=schedtrace=1000 go run main.go
# 输出如下
SCHED 0ms: gomaxprocs=8 idleprocs=6 threads=5 spinningthreads=1 idlethreads=0 runqueue=0 [1 0 0 0 0 0 0 0]
...
SCHED 0ms: gomaxprocs=8 idleprocs=6 threads=5 spinningthreads=1 idlethreads=2 runqueue=0 [0 0 0 0 0 0 0 0]
SCHED 0ms: gomaxprocs=8 idleprocs=6 threads=5 spinningthreads=1 idlethreads=2 runqueue=0 [9 0 0 0 0 0 0 0]
SCHED 1007ms: gomaxprocs=8 idleprocs=8 threads=13 spinningthreads=0 idlethreads=6 runqueue=0 [0 0 0 0 0 0 0 0]
输出结果说明
| 名称 | 描述 |
|---|---|
| SCHED | 标志字符串，代表 goroutine 调度器 |
| 0ms | 从程序启动到输出这行日志的时间 |
| gomaxprocs | P 的数量，(默认的 P 和 CPU 核心数量一致 |
| idleprocs | 空闲状态的 P 的数量 |
| threads | 线程数量 |
| spinningthreads | 自旋状态的线程数量 |
| idlethread | 空闲状态的线程数量 |
| runqueue | 全局队列中 G 的数量 |
| [0 … 0] | 每个 P 的本地队列中 G 的数量 |
输出 GC 时内存示例
执行命令
$ GODEBUG=gctrace=1 go run main.go
# 输出如下
gc 1 @0.028s 1%: 0.058+1.1+0.19 ms clock, 0.46+0/1.0/0.36+1.5 ms cpu, 3->4->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 2 @0.034s 1%: 0.083+0.63+0.005 ms clock, 0.66+0.094/0.51/0.27+0.044 ms cpu, 3->3->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 3 @0.039s 1%: 0.031+0.66+0.042 ms clock, 0.25+0.091/0.49/0.39+0.34 ms cpu, 3->4->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 4 @0.043s 2%: 0.027+0.70+0.14 ms clock, 0.22+0.039/0.50/0.34+1.1 ms cpu, 3->3->0 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
...
gc 1 @0.002s 4%: 0.012+0.78+0.005 ms clock, 0.098+0.49/0.58/0.32+0.040 ms cpu, 4->6->5 MB, 4 MB goal, 0 MB stacks, 0 MB globals, 8 P
gc 2 @0.015s 2%: 0.016+1.3+0.034 ms clock, 0.12+0.022/1.1/0.90+0.27 ms cpu, 9->9->7 MB, 10 MB goal, 0 MB stacks, 0 MB globals, 8 P
输出结果说明
| 名称 | 描述 |
|---|---|
| gc | GC 次数编号，每次 GC 时递增 |
| @#s | 距离程序开始执行的时间 |
| #% | GC 执行占用的时间百分比 |
| #ms | GC 使用的时间 |
| #MB | GC 开始前，结束时，当前正在被使用堆内存的大小 |
| MB goal | 下一次触发 GC 的堆大小 |
| MB stacks | 估计扫描栈大小 |
| MB global | 可扫描的全局大小 |
| #P | P 的数量 |
下面以最后一行输出为例进行说明：
gc 2 @0.015s 2%: 0.016+1.3+0.034 ms clock, 0.12+0.022/1.1/0.90+0.27 ms cpu, 9->9->7 MB, 10 MB goal, 0 MB stacks, 0 MB globals, 8 P
| 名称 | 描述 |
|---|---|
| gc 17 | GC 编号为 2 |
| @0.015s | 程序已经执行了 0.015s |
| 2% | GC 执行占用的时间为 1% |
| 0.016+1.3+0.034 ms clock | GC 使用时间，分别为 STW 清扫的时间 + 并发标记和扫描的时间 + STW 标记的时间 |
| 0.12+0.022/1.1/0.90+0.27 ms cpu | GC 占用 CPU 时间 |
| 9->9->7 MB | GC 开始前堆内存 9 M， 结束时堆内存 9 M，当前正在被使用堆内存 7 M |
| 10 MB goal | 下一次触发 GC 的堆大小为 10M |
| 8 P | P 的数量为 8 个 |
输出调度完整信息
执行命令
$ GODEBUG=scheddetail=1,schedtrace=1000 go run main.go
# 输出如下
SCHED 0ms: gomaxprocs=8 idleprocs=6 threads=6 spinningthreads=1 idlethreads=2 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
P0: status=1 schedtick=1 syscalltick=0 m=0 runqsize=0 gfreecnt=0 timerslen=0
P1: status=0 schedtick=2 syscalltick=0 m=-1 runqsize=0 gfreecnt=0 timerslen=0
...
P7: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0 timerslen=0
M5: p=2 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=true blocked=false lockedg=-1
...
M0: p=0 curg=1 mallocing=0 throwing=0 preemptoff= locks=5 dying=0 spinning=false blocked=false lockedg=1
G1: status=2(chan receive) m=0 lockedm=0
...
G4: status=4(GC scavenge wait) m=-1 lockedm=-1
...
SCHED 1008ms: gomaxprocs=8 idleprocs=8 threads=14 spinningthreads=0 idlethreads=7 runqueue=0 gcwaiting=0 nmidlelocked=1 stopwait=0 sysmonwait=0
P0: status=0 schedtick=262 syscalltick=826 m=-1 runqsize=0 gfreecnt=0 timerslen=0
...
P7: status=0 schedtick=17 syscalltick=307 m=-1 runqsize=0 gfreecnt=3 timerslen=0
M13: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
...
M0: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
G1: status=4(semacquire) m=-1 lockedm=-1
G17: status=6() 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=4(sleep) m=-1 lockedm=-1
G5: status=4(finalizer wait) m=-1 lockedm=-1
G12: status=6() m=-1 lockedm=-1
G22: status=6() m=-1 lockedm=-1
G10: status=4(GC worker (idle)) m=-1 lockedm=-1
...
G78: status=4(select) m=-1 lockedm=10
G146: status=4(chan receive) m=-1 lockedm=-1
输出结果说明
P 的相关输出说明，以下面这行输出为例:
P0: status=1 schedtick=1 syscalltick=0 m=0 runqsize=0 gfreecnt=0 timerslen=0
| 名称 | 描述 |
|---|---|
| P0 | 编号 |
| status | 状态 |
| schedtick | 调度次数 |
| syscalltick | 系统调用次数 |
| m | 关联的 M |
| runqsize | 运行队列中 G 的数量 |
| gfreecnt | 可用的 G 的数量 |
| timerslen | 关联的定时器数量 |
P 的状态列表
const (
// 处理器没有在执行代码或者调度，位于空闲列表或者被可以改变其状态的结构持有
_Pidle = iota
// 处理器被线程 M 持有，并且正在执行代码或者调度
_Prunning
// 处理器没有在执行代码，线程陷入系统调用
_Psyscall
// 处理器被线程 M 持有，由于 GC 被停止
_Pgcstop
// 处理器不再被使用
_Pdead
)
M 的相关输出说明，以下面这行输出为例:
M0: p=0 curg=1 mallocing=0 throwing=0 preemptoff= locks=5 dying=0 spinning=false blocked=false lockedg=1
| 名称 | 描述 |
|---|---|
| M0 | 编号 |
| p | 关联的 P |
| curg | 当前运行的 G |
| mallocing | 是否正在分配内存 |
| throwing | 是否抛出异常 |
| preemptoff | 是否和当前运行的 G 绑定 |
| locks | 锁 |
| dying | 销毁状态 |
| spinning | 是否正在自旋 |
| blocked | 是否阻塞 |
G 的相关输出说明，以下面这行输出为例:
G1: status=2(chan receive) m=0 lockedm=0
| 名称 | 描述 |
|---|---|
| G1 | 编号 |
| status | 状态 |
| m | 关联的 M |
G 的状态列表
const (
// goroutine 刚被分配并且还没有被初始化
_Gidle = iota // 0
// goroutine 处于运行队列中，没有在执行代码，没有栈的所有权
_Grunnable // 1
// goroutine 可以执行代码并且拥有有栈的所有权，M 和 P 已经设置并且有效
_Grunning // 2
// goroutine 正在执行系统调用，没有在执行代码，拥有栈的所有权但是不在运行队列中，此外，M 已经设置
_Gsyscall // 3
// goroutine 处于阻塞中，没有在执行代码并且不在运行队列中，但是可能存在于 Channel 的等待队列上
_Gwaiting // 4
// 没有使用这个状态，但是被硬编码到了 gbd 脚本中
_Gmoribund_unused // 5
// goroutine 没有被使用 (可能已经退出或刚刚初始化)，没有在执行代码，可能存在分配的栈
_Gdead // 6
// 没有使用这个状态
_Genqueue_unused // 7
// goroutine 的栈正在被移动，没有在执行代码并且不在运行队列中
_Gcopystack // 8
// goroutine 由于抢占而阻塞，等待唤醒
_Gpreempted // 9
// GC 正在扫描栈空间，没有在执行代码，可以与上述其他状态同时存在
_Gscan = 0x1000
)
可视化
国外的大佬 Dave Cheney 开发了一个工具，可以实时可视化 GC trace 数据，项目地址 在这里。
