GODEBUG 查看GC信息
[TOC]
查看GC信息
gctrace
使用环境变量 GODEBUG 可以控制运行时的调试变量，格式为：name=val。
gctrace = 1选项生成GC trace。每次发生垃圾收集时，运行时都会将GC trace信息写入stderr。可以观察 GC 时间占比，Gc 回收内存大小，下次出发GC 的堆阈值，使用处理数量等信息。
gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P
格式： gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P
gc # GC序号，在每次GC时递增
@#s 程序运行到目前的秒数
#% 自程序启动花费在GC上的时间百分比
#+...+# wall-clock/CPU times for the phases of the GC 阶段标记CPU 世间占比
#->#-># MB GC开始堆大小，结束堆大小，剩余活跃堆内存大小
# MB goal 下一次出发 GC 堆阈值
# P 当前使用处理器数量
以代码为例：
func main() {
x := make([]int64, 0)
for i := 0; i < 20000; i++ {
x = append(x, int64(i))
time.Sleep(time.Microsecond * 10)
}
}
运行 GODEBUG=gctrace=1 go run main.go
gc 1 @0.003s 10%: 0.042+3.7+0.020 ms clock, 0.16+0.39/2.3/5.3+0.083 ms cpu, 4->6->5 MB, 5 MB goal, 4 P
gc 2 @0.014s 6%: 0.007+1.7+0.013 ms clock, 0.030+0/1.2/2.3+0.055 ms cpu, 8->9->7 MB, 10 MB goal, 4 P
gc 3 @0.033s 4%: 0.020+2.2+0.016 ms clock, 0.083+0.50/1.9/0.90+0.064 ms cpu, 12->13->8 MB, 14 MB goal, 4 P
gc 4 @0.050s 5%: 0.021+3.6+0.012 ms clock, 0.087+0.98/3.5/1.3+0.050 ms cpu, 16->16->10 MB, 17 MB goal, 4 P
gc 5 @0.099s 4%: 0.24+4.0+0.017 ms clock, 0.97+0.53/3.7/2.3+0.070 ms cpu, 19->19->12 MB, 20 MB goal, 4 P
gc 6 @0.128s 4%: 0.039+6.9+0.024 ms clock, 0.15+0/6.5/8.6+0.096 ms cpu, 23->24->14 MB, 24 MB goal, 4 P
以gc 6 为例：
gc 6 @0.128s 4%: 0.039+6.9+0.024 ms clock, 0.15+0/6.5/8.6+0.096 ms cpu, 23->24->14 MB, 24 MB goal, 4 P
gc 6 @0.128s 4% 依次表示： gc 6 — 目前程序运行0.128s—-目前花在GC上时间共占4%
0.039+6.9+0.024 ms clock 依次表示：本次GC标记前STW 时间 0.039ms，并发标记6.9ms，标记终止关闭写屏障和清理STW 时间为 0.024ms
0.039ms : STW : Mark Start - Write Barrier on 本次GC标记前STW 时间
6.9ms : Concurrent : Marking 并发标记6.9ms
0.024ms : STW : Mark Termination - Write Barrier off and clean up 标记终止关闭写屏障和清理STW 时间为 0.024ms
0.15+0/6.5/8.6+0.096 ms cpu ：CPU 时间，
0.15ms : STW : Mark Start 标记开始
0ms : Concurrent : Mark - Assist Time (GC performed in line with allocation) 辅助标记
6.5ms : Concurrent : Mark - Background GC time 后台并发标记
8.6ms : Concurrent : Mark - Idle GC time 空闲GC 时间 ？
0.096ms : STW : Mark Term 标记结束 STW 时间
23->24->14 MB, 24 MB goal 堆内存信息
23MB : Heap memory in-use before the Marking started
24MB : Heap memory in-use after the Marking finished
14MB : Heap memory marked as live after the Marking finished
24MB : Collection goal for heap memory in-use after Marking finished
gcpacertrace
GODEBUG=gctrace=1,gcpacertrace=1 go run main.go
GODEBUG=gcpacertrace=1 go run main.go
调取器信息
func main() {
var wg sync.WaitGroup
for i := 0;i < 2000 ;i++ {
wg.Add(1)
go func() {
a := 0
for i := 0; i < 1e7; i++ {
a += 1
if i % 1e3 == 0 {
time.Sleep(time.Nanosecond*1)
}
}
time.Sleep(time.Second*1)
wg.Done()
}()
}
wg.Wait()
}
schedtrace
执行 GODEBUG=schedtrace=2000 go run main.go ， 其中 schedtrace=2000 表示每 2000ms 输出追踪信息。
SCHED 0ms: gomaxprocs=4 idleprocs=1 threads=5 spinningthreads=1 idlethreads=0 runqueue=0 [1 0 0 0]
SCHED 0ms: gomaxprocs=4 idleprocs=1 threads=5 spinningthreads=1 idlethreads=0 runqueue=0 [1 0 0 0]
SCHED 2001ms: gomaxprocs=4 idleprocs=4 threads=11 spinningthreads=0 idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 2004ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=1660 [104 53 46 49]
SCHED 4003ms: gomaxprocs=4 idleprocs=4 threads=11 spinningthreads=0 idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 4010ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=1374 [115 91 87 79]
SCHED 6014ms: gomaxprocs=4 idleprocs=4 threads=11 spinningthreads=0 idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 6018ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=1215 [58 97 102 102]
SCHED 8020ms: gomaxprocs=4 idleprocs=4 threads=11 spinningthreads=0 idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 8020ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=928 [68 118 115 119]
SCHED 10030ms: gomaxprocs=4 idleprocs=4 threads=11 spinningthreads=0 idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 10027ms: gomaxprocs=4 idleprocs=0 threads=5 spinningthreads=0 idlethreads=0 runqueue=721 [94 125 30 0]
SCHED 12040ms: gomaxprocs=4 idleprocs=4 threads=11 spinningthreads=0 idlethreads=4 runqueue=0 [0 0 0 0]
SCHED 12030ms: gomaxprocs=4 idleprocs=3 threads=6 spinningthreads=0 idlethreads=3 runqueue=0 [0 0 0 0]
- SCHED：表示启动到现在的运行时间(毫秒)，输出的时间间隔受
schedtrace的值影响。 - gomaxprocs：CPU 核心数（GOMAXPROCS值）。
- idleprocs：表示当前的空闲数量。
- threads：当前正在运行的 OS 线程数量。
- spinningthreads：自旋状态的 OS 线程数量。
- idlethreads：空闲的线程数量。
- runqueue：全局队列中中的 Goroutine 数量，而后面的 1660 [104 53 46 49] 中括号中的分别代表这 4 个 P 的本地队列正在运行的 Goroutine 数量。
自旋线程的这个说法，是因为 Go Scheduler 的设计者在考虑了 “OS 的资源利用率” 以及 “频繁的线程抢占给 OS 带来的负载” 之后，提出了 “Spinning Thread” 的概念。也就是当 “自旋线程” 没有找到可供其调度执行的 Goroutine 时，并不会销毁该线程 ，而是采取 “自旋” 的操作保存了下来。虽然看起来这是浪费了一些资源，但是考虑一下 syscall 的情景就可以知道，比起 “自旋”，线程间频繁的抢占以及频繁的创建和销毁操作可能带来的危害会更大。
scheddetail
通过参数 scheddetail 查看调度的细节逻辑。
如执行 GODEBUG=scheddetail=1,schedtrace=1000 go run main.go
SCHED 1005ms: gomaxprocs=4 idleprocs=4 threads=11 spinningthreads=0 idlethreads=4 runqueue=0 gcwaiting=0 nmidlelocked=1 stopwait=0 sysmonwait=0
P0: status=0 schedtick=754 syscalltick=3332 m=-1 runqsize=0 gfreecnt=5 timerslen=0
P1: status=0 schedtick=958 syscalltick=2682 m=-1 runqsize=0 gfreecnt=3 timerslen=0
P2: status=0 schedtick=442 syscalltick=4812 m=-1 runqsize=0 gfreecnt=0 timerslen=0
P3: status=0 schedtick=384 syscalltick=2648 m=-1 runqsize=0 gfreecnt=4 timerslen=0
M10: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
M9: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
M8: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
M7: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
M6: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
M4: p=-1 curg=83 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
M3: p=-1 curg=73 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=-1
M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=2 dying=0 spinning=false blocked=false lockedg=-1
M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
M0: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=82
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
G18: status=4(GC sweep wait) m=-1 lockedm=-1
G19: status=4(GC scavenge wait) m=-1 lockedm=-1
G34: status=4(finalizer wait) m=-1 lockedm=-1
G13: status=6() m=-1 lockedm=-1
G11: status=6() m=-1 lockedm=-1
G16: status=6() m=-1 lockedm=-1
G46: status=6() m=-1 lockedm=-1
G25: status=4(chan receive) m=-1 lockedm=-1
G72: status=4(select) m=-1 lockedm=-1
G15: status=6() m=-1 lockedm=-1
G82: status=4(select) m=-1 lockedm=0
G43: status=6() m=-1 lockedm=-1
G3: status=4(GC worker (idle)) m=-1 lockedm=-1
G44: status=4(GC worker (idle)) m=-1 lockedm=-1
G45: status=4(GC worker (idle)) m=-1 lockedm=-1
G50: status=4(GC worker (idle)) m=-1 lockedm=-1
G73: status=3(chan send) m=3 lockedm=-1
G52: status=6() m=-1 lockedm=-1
G22: status=6() m=-1 lockedm=-1
G71: status=4(select) m=-1 lockedm=-1
G5: status=6() m=-1 lockedm=-1
G51: status=6() m=-1 lockedm=-1
G74: status=4(select) m=-1 lockedm=-1
G75: status=6() m=-1 lockedm=-1
G76: status=6() m=-1 lockedm=-1
G83: status=3() m=4 lockedm=-1
SCHED 1000ms: gomaxprocs=4 idleprocs=4 threads=7 spinningthreads=0 idlethreads=5 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
P0: status=0 schedtick=13 syscalltick=0 m=-1 runqsize=0 gfreecnt=0 timerslen=3
P1: status=0 schedtick=17 syscalltick=0 m=-1 runqsize=0 gfreecnt=0 timerslen=4
P2: status=0 schedtick=11 syscalltick=0 m=-1 runqsize=0 gfreecnt=0 timerslen=6
P3: status=0 schedtick=15 syscalltick=0 m=-1 runqsize=0 gfreecnt=0 timerslen=7
M6: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
...
M
- p：隶属哪一个 P。
- curg：当前正在使用哪个 G。
- runqsize：运行队列中的 G 数量。
- gfreecnt：可用的G（状态为 Gdead）。
- mallocing：是否正在分配内存。
- throwing：是否抛出异常。
- preemptoff：不等于空字符串的话，保持 curg 在这个 m 上运行。
P
- status：P 的运行状态。
- schedtick：P 的调度次数。
- syscalltick：P 的系统调用次数。
- m：隶属哪一个 M。
- runqsize：运行队列中的 G 数量。
- gfreecnt：可用的G（状态为 Gdead）。
P 的状态有：
| 状态 | 值 | 含义 |
|---|---|---|
| _Pidle | 0 | 刚刚被分配，还没有进行进行初始化。 |
| _Prunning | 1 | 当 M 与 P 绑定调用 acquirep 时，P 的状态会改变为 _Prunning。 |
| _Psyscall | 2 | 正在执行系统调用。 |
| _Pgcstop | 3 | 暂停运行，此时系统正在进行 GC，直至 GC 结束后才会转变到下一个状态阶段。 |
| _Pdead | 4 | 废弃，不再使用。 |
G
- status：G 的运行状态；
- m：属于哪一个 M， 没有分配为 -1；
- lockedm：是否有锁定 M。
| 状态 | 值 | 含义 |
|---|---|---|
| _Gidle | 0 | 刚刚被分配，还没有进行初始化。 |
| _Grunnable | 1 | 已经在运行队列中，还没有执行用户代码。 |
| _Grunning | 2 | 不在运行队列里中，已经可以执行用户代码，此时已经分配了 M 和 P。 |
| _Gsyscall | 3 | 正在执行系统调用，此时分配了 M。 |
| _Gwaiting | 4 | 在运行时被阻止，没有执行用户代码，也不在运行队列中，此时它正在某处阻塞等待中。 |
| Gmoribundunused | 5 | 尚未使用，但是在 gdb 中进行了硬编码。 |
| _Gdead | 6 | 尚未使用，这个状态可能是刚退出或是刚被初始化，此时它并没有执行用户代码，有可能有也有可能没有分配堆栈。 |
| Genqueueunused | 7 | 尚未使用。 |
| _Gcopystack | 8 | 正在复制堆栈，并没有执行用户代码，也不在运行队列中。 |
对于 ` G18: status=4(GC sweep wait) m=-1 lockedm=-1。G 的状态为4，也就是 _Gwaiting`，表示在运行时被阻止，没有执行用户代码，也不在运行队列中，此时它正在某处阻塞等待中。
常见的可能造成等待的原因还有：
// A waitReason explains why a goroutine has been stopped.
// See gopark. Do not re-use waitReasons, add new ones.
type waitReason uint8
const (
waitReasonZero waitReason = iota // ""
waitReasonGCAssistMarking // "GC assist marking"
waitReasonIOWait // "IO wait"
waitReasonChanReceiveNilChan // "chan receive (nil chan)"
waitReasonChanSendNilChan // "chan send (nil chan)"
waitReasonDumpingHeap // "dumping heap"
waitReasonGarbageCollection // "garbage collection"
waitReasonGarbageCollectionScan // "garbage collection scan"
waitReasonPanicWait // "panicwait"
waitReasonSelect // "select"
waitReasonSelectNoCases // "select (no cases)"
waitReasonGCAssistWait // "GC assist wait"
waitReasonGCSweepWait // "GC sweep wait"
waitReasonGCScavengeWait // "GC scavenge wait"
waitReasonChanReceive // "chan receive"
waitReasonChanSend // "chan send"
waitReasonFinalizerWait // "finalizer wait"
waitReasonForceGCIdle // "force gc (idle)"
waitReasonSemacquire // "semacquire"
waitReasonSleep // "sleep"
waitReasonSyncCondWait // "sync.Cond.Wait"
waitReasonTimerGoroutineIdle // "timer goroutine (idle)"
waitReasonTraceReaderBlocked // "trace reader (blocked)"
waitReasonWaitForGCCycle // "wait for GC cycle"
waitReasonGCWorkerIdle // "GC worker (idle)"
waitReasonPreempted // "preempted"
waitReasonDebugCall // "debug call"
)
- 当我们执行
go func()时，实际上就是创建一个全新的 Goroutine，我们称它为 G。 - 新创建的 G 会被放入 P 的本地队列（Local Queue）或全局队列（Global Queue）中，准备下一步的动作。
- 唤醒或创建 M 以便执行 G。
- 不断地进行事件循环
- 寻找在可用状态下的 G 进行执行任务
- 清除后，重新进入事件循环