Go gctrace引起 runtime 调度阻塞
这是一个奇葩的问题！当你开启 GODEBUG=gctrace=1，并且日志是重定向到文件，那么有概率会造成 runtime 调度阻塞。😅
查找问题
开始业务方说我们的 grpc sidecar 时不时发生高时延抖动，我对比了监控上的性能数据，貌似是磁盘 io 引起的，我迅速调高了日志级别及修改日志库为异步写入模式。接口的时延抖动问题确实减少了，但依旧还是出现。
通过项目代码变更得知，一同事在部署脚本里加入了 gctrace 监控。开始不觉得是这个问题引起的，但近一段时间也就这一个 commit 提交，我就尝试回滚代码，问题居然就这么解决了。
分析 GC gctrace 源码
我们先来分析下 golang GC gctrace 相关的代码，我们知道 go 的 stop the world 会发生 mark 的两个阶段，一个是 mark setup 开始阶段，另一个就是 mark termination 收尾阶段。GC 在进行到 gcMarkTermination 时，会stop the world，然后判断是否需要输出 gctrace 的调试日志。
简单说，这个打印输出的过程是在 stop the world 里。默认是打印到 pts 伪终端上，这个过程是纯内存操作，理论是很快的。
但如果在开启 gctrace 时进行文件重定向，那么他的操作就是文件 io 操作了。如果这时候你的服务里有大量的磁盘 io 的操作，本来写 page buffer 的操作，会触发阻塞 flush 磁盘。那么这时候 go gctrace 打印日志是在开启 stop the world 之后操作的，因为磁盘繁忙，只能是等待磁盘 io 操作完，这里的 stw 会影响 runtime 对其他协程的调度。
// xiaorui.cc
func gcMarkTermination(nextTriggerRatio float64) {
// World is stopped 已经开启了stop the world
...
// Print gctrace before dropping worldsema.
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()
}
semrelease(&worldsema) // 关闭stop the world
...
}
解决方法
线上就不应该长期的去监控 gctrace 的日志。另外需要把较为频繁的业务日志进行采样输出。前面有说，我们第一个解决方法就修改日志的写入模式，当几千个协程写日志时，不利于磁盘的高效使用和性能，可以借助 disruptor 做日志缓存，然后由独立的协程来写入日志。
除此之外，还发现一个问题，开始时整个 golang 进程开了几百个线程，这是由于过多的写操作超过磁盘瓶颈，继而触发了 disk io 阻塞。这时候 golang runtime sysmon 检测到 syscall 超时，继而解绑 mp，接着实例化新的 m 线程绑定 p。记得以前专门写过文章介绍过golang线程爆满的问题。
后话
我们可以想到如果函数 gcMarkTermination 输出日志放在关闭 stop the world 后面，这样就不会影响 runtime 调度。当然，这个在线上重定向 go gctrace 的问题本来就很奇葩。😅
⬇⬇⬇