golang语言Api系统中CPU功耗优化300倍的过程

作者 fiisio | 发布于 2016-11-05

这个系统的存在是解决大量并发数据库查询的问题，主体思路是通过LRU算法缓存结果信息和请求合并来实现的一个数据缓存和请求削峰服务，从而大量减少直接的数据库连接查询并将查询效率也大大提高。

在系统刚调试完成，请求正确处理的那一刻内心是激动的，然后当服务开启之后，习惯性的查看了下功耗，内存使用正常，CPU却在眼下不断增高，2%－5%－10%－20%－50%－80%－100%，在短短几分钟就飙到了100%。。。内心是崩溃的，此时刚从一堆代码中缕顺流程。呢，如何快速的定位到问题？我应该从哪些方面下手，或者说我应该查看哪些数据来推测所有的可能性？究竟是哪个package，哪个函数甚至是哪一行代码影响了它的性能？

1.遇到这种情况最先想到的是死循环的情况，回到代码，检查有没有死循环之类的bug,仔细看了下所有可能存在循环的地方，并没有发现，而且从症状来看不像是死循环的情况(如果是死循环的情况，CPU的增长不会那么慢，肯定是要立即上去的)

2.打开GC看看是不是由于GC次数过多占用CPU，GC明显是2分钟一次属于默认的情况，所以也不是GC频繁导致的

3.此时只有pprof了，查看程序的运行时数据。。。

好吧，这是一个有意思的事情，golang大法好，稍微修改了几行代码，开启pprof接口查看运行时cpu数据和heap数据。

首先，收集下CPU的信息，看看谁在占着我的cpu

从上面的截图可以看出flat%最高的是rumtime.mach_semaphore_signal方法,在这里只有28%左右其实更高，达到60+%（此图截错了，罢了，罢了，在此说明问题就行）。Ok，知道了到底是什么导致的CPU高，下面我们追溯下代码路径，在此我使用火焰图来分析，更加直观。

从火焰图我们可以很方便的分析各个方法占用的CPU的时间。它是SVG格式的，鼠标放上去还能看细节。Y轴是栈的深度，X轴是所有的采样点的集合，每个方框代表一个栈帧(stack frame)。颜色没有意义，只是随机的选取的。左右顺序也不重要。看的时候可以从最宽的帧看起，从底往上看，帧上的分叉代表不同的代码路径。快速识别和量化的CPU使用率

从火焰图的信息可以看到，在整个cpu占用信息采集过程中几乎全部都是runtime的信息，并且是runtime.timerproc。通过分析go语言的源码我们可以知道这是一个定时器调度goruntine。（代码是go1.7.3源码，我经过了裁剪，保留大意）

调度流程分析如下：

1.判断堆中是否有Timer? 如果没有就将Timers的rescheduling设置为true的状态，true就代表timerproc goroutine被挂起，需要重新调度。这个重新调度的时刻就是在添加一个Timer进来的时候，会ready这个goroutine。这里挂起goroutine使用的是runtime·park()函数。

2.如果堆中有Timer存在，就取出堆顶的一个Timer，判断是否超时。超时后，就删除Timer，执行Timer中挂载的方法。这一步是循环检查堆，直到堆中没有Timer或者没有超时的Timer为止。

3.在堆中的Timer还没超时之前，这个goroutine将处于sleep状态，也就是设置Timers的sleeping为true状态。这个地方是通过runtime·notesleep()函数来完成的，其实现是依赖futex锁。这里，goroutine将sleep多久呢？它将sleep到最近一个Timer超时的时候，就开始执行。

从火焰图往上或者我们从pprof的cpu走向来分析（如下图）看就可以看到我们上面提到的runtime.mach_semaphore_timewait。所以在此我们可以推断，根源就在定时器的使用，那么全代码搜索所有使用time包方法的代码。发现是和time.Tick()和time.After()两个函数相关。那么问题就出在这里啦。

经过反复试验，测试Tick()和After()的使用方法。发现如下的陷阱:

上面这两个例子，单独执行，不会发现任何问题，但是当你将这样的代码放到一个7 * 24小时的Service中，并且timeout间隔为更短时间，比如0.1s时，问题就出现了。

最初我怀疑是不是代码中有死循环，但仔细巡查一遍代码后，没有发现死循环的痕迹，算法逻辑也没问题。于是重启了一下这个service，发现cpu占用降了下来。继续用top观察，不好，这个service占用了1%的CPU一直上升，观察一段时间后，发现这个service对cpu的占用率随着时间的推移而增加。

从火焰图上可以看出几乎都是timeproc goroutine的调度。回到代码，发现可能存在问题的只有这里的tick和after。

回到我们的代码，timerproc指针维护的是一个goroutine，这个goroutine的主要功能就是检查小顶堆中的Timer是否超时。当然，超时就是删除Timer，并且执行Timer对应的动作。我的Timer间隔是1s。这样每1s都会创建一个runtime timer，而通过runtime的源码来看，这些timer都扔给了runtime调度(一个heap)。时间长了，就会有超多的timer需要 runtime调度，不耗CPU才怪。

找到原因之后，继续分析了造成timer过多的原因，一个是配置项中的时间间隔太小(0.1s)一个是上面看到的代码逻辑bug，两者一起造成了CPU飙升.修复代码中存在的bug，调节参数间隔大小.CPU立马降了下来。

那么问题来了我们应该如何正确使用定时器呢？

正常情况下，Tick代表是永久的闹钟，只要你定时了以后就定时叫醒你，After更像是一次性闹钟，到了时间叫醒你，如果你没有接收到，那么它也会停止失效。所以Tick可不要放在循环里面，不然会一直增长下去。但是像左侧第二个你回发现它的位置并不是最里面的循环，所以并没有原则上的不允许，要在具体情况下选择正确的方法。下面是对他们做的测试:（里面的百分比是它们的CPU功耗）

最后，系统正常情况下cpu一直处于1%以下，并且在应对100万请求10万并发情况下依然能将CPU功耗保持在4%以下。