前言:
这是一个奇葩的问题。当你开启GODEBUG=gctrace=1，并且日志是重定向到文件，那么有概率会造成runtime调度阻塞。😅
该文章后续仍在不断的更新修改中， 请移步到原文地址 http://xiaorui.cc/?p=6232
查找问题：
开始业务方说我们的grpc sidecar时不时发生高时延抖动，我对比了监控上的性能数据，貌似是磁盘io引起的，我迅速调高了日志级别及修改日志库为异步写入模式。接口的时延抖动问题确实减少了，但依旧还是出现。
通过项目代码变更得知，一同事在部署脚本里加入了gctrace监控。开始不觉得是这个问题引起的，但近一段时间也就这一个commit提交，我就尝试回滚代码，问题居然就这么解决了。
分析gc gctrace源码：
我们先来分析下golang gc gctrace相关的代码，我们知道go 1.12的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的问题本来就很奇葩。😅
一个腾讯的朋友说跟我说，go夜读里有个腾讯小哥做了runtime分享，中间也遇到了同样的问题，针对该问题也做了分析。看来这奇葩事情不止是我遇到了。😁
