遇到问题

最近在处理日志上报kafka时，为防止上报过程中因kafka异常而导致主业务协程阻塞，为此建立了如下日志上报模型：日志主协程负责将消息发给生产者，再由生产者异步写入到broker集群，日志work协程则将收集的日志项通过带缓冲的channel将其传递给日志主协程，从而达到解耦。因日志模型是一对多的关系，为防止work协程长时间等待，为此为每次传递过程设置超时机制，于是在work协程中很容易写出如下代码：

函数Log2Kafka在每次写日志时调用，为防止单条日志过长同时对超长日志进行切分，切分后再将日志写入到channel中异步传递，同时设定每次传递日志最长时间不能超过500ms，否则认为系统处理不过来直接丢弃本次写操作，这样避免因写channel阻塞而引起协程阻塞。用golang自带的go test对该模型进行压测，每次4KB数据下QPS能达到百万级别，最低也有1万【kafka异常情况下】。感觉性能ok，应用到业务服务上并先发布到测试环境进行灰度和进一步压测。在测试环境灰度期间，发现服务器CPU曲线图如下所示。

引进新日志组件时CPU曲线

未引进新日志组件时CPU曲线

问题排查

从发布后开始压测CPU曲线逐渐增大，压测结束后一直维持在40%左右，且中间有极短间歇性的波谷，这和存在定时任务的曲线很类似，不过压测后即使服务空转CPU消耗也维持在40%的水平极为不寻常。但通过排查代码没有发现怀疑点，能确定的是肯定是新引进的日志组件导致的。于是在本地对服务进行重新压测，同时开启pprof监控go tool pprof -http 0.0.0.0:3001 -seconds 60 ，抓取一分钟CPU火焰图。

上图左侧是压测中代码业务逻辑函数的CPU占用情况，中间红色框内的是系统调用，图中可以看出系统调用占用CPU时间较长，且从函数名如park_m、schedule、findrunnable可以猜测出应该是与协程调度相关，这说明程序空转的时候系统在不断进行协程上下文切换，另外其中与时间相关的函数也占用了较长CPU时间。因此从火焰图所展示的调用层次不难推出是如下场景导致的CPU高：程序的某个定时器不断的被触发，从而唤起对应的协程被调度执行。

好了，根据如上的现象及分析结论我们再去看新引入的日志组件的代码，重点关注有定时器逻辑的，开头提到Log2Kafka函数有段代码如下图所示。

按照写代码时的理解这里每次写日志才会开启一个定时器，且定时器的作用域在该函数内，按理来说没有继续写日志应该不会有定时器在运行才对。那为什么程序空转的时候还存在定时器不断触发的情况呢？难道是定时器一直存在而没有随着函数调用结束被回收？带着这个疑问我们看下golang time包的几个定时器函数：

time.NewTimer：创建定时器，调用startTimer开启定时器并将其加入到当前P的定时器堆中【startTimer内部调用了addtimer实现】，到时间后向channel写入当前时间，只执行一次。time.NewTicker：创建过程和NewTimer类似，每次间隔固定时间向channel写入当前时间。time.Tick：创建隐式定时器，其实际是调用了NewTicker，只不过返回的是定时器的只读channel而不是定时器本身，属于NewTicker的间接访问方式。time.AfterFunc：创建隐式定时器，固定时间后触发某个函数执行，只执行一次。

所以实际上无论调用哪个函数创建定时器都不会自动回收，需要开发人员手动调用stop函数终止才能释放资源，这样也就能解释得通为何在压测后即使程序空转也一直在不断的触发定时器并导致协程调度了。因为每次调用Log2Kafka函数时都会执行time.Tick，从而在压测时不断的创建出一个每500毫秒触发一次的定时器且又没有释放。

解决问题

为避免上述问题，我们需要避免重复创建且在日志写完后主动将定时器关闭。基于此优化后的代码如下：在写之前先显示创建定时器【由于只需要定时器触发一次，故调用NewTimer】，同时通过defer机制保障一定会被关闭。

修改后再次压测结果如下：压测瞬间CPU不断飚高，压测结束后CPU消耗曲线立马下降到正常水平，不会再出现之前的无法恢复的现象。

修复后压测前后CPU曲线

修复后空转时COU曲线

另一种修复方式：

除了使用定时器外，我们还可以用golang自带的上下文来解决上述问题，代码可改为如下形式，其实际内部实现也是通过调用time.AfterFunc函数生成定时器来实现，只不过不需要开发自己去手动关闭。

写在最后go编程中如使用定时器时尽量显示创建且需手动关闭，否则容易出现协程和channel泄露。使用go test压测时除了注意QPS外还应该多关注CPU消耗。select在执行时会判断每个case是否就绪，然后再随机执行就绪的case，并不是只遇到已就绪的case后续的case就不判断了。这样若在case中有执行语句会被执行。go自带的pprof是个好东西，在性能分析上应该经常使用。