一次漫长的服务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大神的指导,同时懂得如何找问题以及找问题的方法也至关重要。
posted @ 2017-02-05 11:22  低调的大白兔  阅读(623)  评论(0编辑  收藏  举报