golang gctrace引起runtime调度阻塞

前言:

这是一个奇葩的问题。当你开启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对其他协程的调度。

解决方法:

线上就不应该长期的去监控gctrace的日志。另外需要把较为频繁的业务日志进行采样输出。前面有说,我们第一个解决方法就修改日志的写入模式,当几千个协程写日志时,不利于磁盘的高效使用和性能,可以借助disruptor做日志缓存,然后由独立的协程来写入日志。

除此之外,还发现一个问题,开始时整个golang进程开了几百个线程,这是由于过多的写操作超过磁盘瓶颈,继而触发了disk io阻塞。这时候golang runtime sysmon检测到syscall超时,继而解绑mp,接着实例化新的m线程进行绑定p。记得以前专门写过文章介绍过golang线程爆满的问题。

后话:

我们可以想到如果函数gcMarkTermination输出日志放在关闭stop the world后面,这样就不会影响runtime调度。当然,这个在线上重定向go gctrace的问题本来就很奇葩。😅

一个腾讯的朋友说跟我说,go夜读里有个腾讯小哥做了runtime分享,中间也遇到了同样的问题,针对该问题也做了分析。看来这奇葩事情不止是我遇到了。😁


大家觉得文章对你有些作用! 如果想赏钱,可以用微信扫描下面的二维码,感谢!
另外再次标注博客原地址  xiaorui.cc