一次漫长的服务CPU优化过程

从师父那里接了个服务，每天单机的流量并不大，峰值tips也并不高，但是CPU却高的异常。由于，服务十分重要，这个服务最高时占用了100个docker节点在跑，被逼无奈开始了异常曲折的查因和优化过程。

一般情况下，服务的主要性能瓶颈都在cpu和内存，关于内存的瓶颈之前遇到过一次，这次是第一次遇到Cpu的瓶颈。首先介绍下背景，浏览器的插件服务主要服务与QQ浏览器和所有tbs终端，每天的日活超过5亿，而服务的每天流量超过30亿。

这个服务非常重要，从师父那里接过来后一直没有任何改变，直到又一次告警才意外发现这个服务已经自动扩容了100个docker节点了。。。而且每台的负载都还很高（峰值超过70%），然后迫于运维的压力和服务的稳定性考虑，就开始了曲折的查因过程。值得注意的是，这个服务虽然日活很高（因为包含TBS），但是整体的流量不算太多，尤其平分到每个节点上流量并不大。那么问题来了，cpu到底跑哪里了。

一、perf跑火焰图

分析CPU瓶颈，最直接的方法就是用perf看看服务的Cpu到底跑哪里去了，跑的结果也很诡异：



结果显示，CPU并没有耗费在服务的具体某个函数上（火焰图也没看出来），从上面来看服务的主要消耗在int和string的构造和析构上，也就是内存的频繁申请和释放？我把这个结果在组里同步下，组里的各位大神提出了一些建议。其中，bj大神认为，既然都在内存的申请和释放上，建议我把tcmalloc编译进去用于代替libc中内存回收，说对于小内存的频繁释放用tcmalloc会好很多。ok，于是我就照做了，然而吧tcmalloc静态编进去之后，依然没用，所以，应该不是回收机制原因，所以，fail。

二、性能分析

用perf跑出来的东西并没有帮我找到瓶颈，那么只能尝试着换换方法。

于是乎：（1）尝试着查下这个进程在用户态和系统态的cpu时间比，然后想通过strace和time等分析下是不是系统调用等方面的问题，然而我分析了半天和其他服务比较了下，依然没有收获。

（2）这个时候，偶然想到可以看看服务的线程cpu占比是否均衡或者都耗在哪些线程上了。



这个时候就发现诡异的事情了，这个服务的核心线程有30个，其中20个imp主线程，10个异步回调线程，还有些其他的日志线程等。然后，其中有10个线程cpu占比是其他的7到8倍，然后用gstack打了堆栈之后，发现这10个线程居然是回调线程！！！这就奇怪了，为啥回调线程会占这么高的CPU，这个时候结合服务本身的特性，对回调后的插件过滤部分做了和主线程一样的缓存，发到线上，cpu有一定程度的降低，然而，还是没有发现根本原因。因为在单机流量并不大的情况下，服务的CPU到底跑哪里了？按照同等流量下，这个服务的CPU应该是在40%以下，然后实际是80%。而这10个异步线程为啥会这么耗CPU，我review了n遍代码，还是没能解决。。。

三、服务自身优化

这个时候，春节将至，而我查了半个月，发了4个线上版本都没有根本性改变。运维要缩容，服务由很重要，真的头疼。这个时候，就请组里的大佬（xianyi）向他们请教类似的经历和优化方法。这个时候，我们认为，虽然服务的流量不大，但是插件服务没有做任何的缓存和控制，每次请求都会做完整的计算。于是，希望通过和终端联合改版，通过其他方式把服务的计算次数降下来。然而，终端改版要时间，服务的cpu快满了，看来春节是不好过了。。。

四、找到问题or真相

万般无奈下，xianyi告诉我了他们之前关于染色debug日志优化的事情，让我试试改改说不定可以降低很多，于是乎就是下面这段代码：

#define LOG_DEBUG if(mtt_taf_debug_log()||mtt_dye_log()) (MT_LOG->debug(MT_LOG_TAG))<<
发到线上后，奇迹发生了，CPU降了60%！！！



啊，难道说那么多CPu都耗到染色滚动日志上了？我又再一次打印了线程的堆栈，



异步线程的cpu和其他的也差不多了。这个时候我查了下代码，在异步回调时，debug日志的主要是这段代码：



这里，差不多会把每次600多个插件的一些信息做循环打印，也就是说异步线程的CPU就耗在这里了吧？（后续再发个版本验证下。）总之，通过优化debug打印，确实可以优化下来很多的cpu，这个是确定的（尤其是循环打印）。这里更深层次的原因，后续还要分析下。
五、总结
曲折的优化过程，最后却是以比较简单的日志优化解决了。从中可以看出，在日常服务维护当中，经验扮演着至关重要的作用。这里要感谢xianyizhang大神的指导，同时懂得如何找问题以及找问题的方法也至关重要。