一次漫長的服務CPU優化過程

從師父那裏接了個服務，天天單機的流量並不大，峯值tips也並不高，可是CPU卻高的異常。因爲，服務十分重要，這個服務最高時佔用了100個docker節點在跑，被逼無奈開始了異常曲折的查因和優化過程。

通常狀況下，服務的主要性能瓶頸都在cpu和內存，關於內存的瓶頸以前遇到過一次，此次是第一次遇到Cpu的瓶頸。首先介紹下背景，瀏覽器的插件服務主要服務與QQ瀏覽器和全部tbs終端，天天的日活超過5億，而服務的天天流量超過30億。

這個服務很是重要，從師父那裏接過來後一直沒有任何改變，直到又一次告警才意外發現這個服務已經自動擴容了100個docker節點了。。。並且每臺的負載都還很高（峯值超過70%），而後迫於運維的壓力和服務的穩定性考慮，就開始了曲折的查因過程。值得注意的是，這個服務雖然日活很高（由於包含TBS），可是總體的流量不算太多，尤爲平分到每一個節點上流量並不大。那麼問題來了，cpu到底跑哪裏了。

1、perf跑火焰圖

分析CPU瓶頸，最直接的方法就是用perf看看服務的Cpu到底跑哪裏去了，跑的結果也很詭異：

結果顯示，CPU並無耗費在服務的具體某個函數上（火焰圖也沒看出來），從上面來看服務的主要消耗在int和string的構造和析構上，也就是內存的頻繁申請和釋放？我把這個結果在組裏同步下，組裏的各位大神提出了一些建議。其中，bj大神認爲，既然都在內存的申請和釋放上，建議我把tcmalloc編譯進去用於代替libc中內存回收，說對於小內存的頻繁釋放用tcmalloc會好不少。ok，因而我就照作了，然而吧tcmalloc靜態編進去以後，依然沒用，因此，應該不是回收機制緣由，因此，fail。

2、性能分析

用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遍代碼，仍是沒能解決。。。

3、服務自身優化

這個時候，春節將至，而我查了半個月，發了4個線上版本都沒有根本性改變。運維要縮容，服務由很重要，真的頭疼。這個時候，就請組裏的大佬（xianyi）向他們請教相似的經歷和優化方法。這個時候，咱們認爲，雖然服務的流量不大，可是插件服務沒有作任何的緩存和控制，每次請求都會作完整的計算。因而，但願經過和終端聯合改版，經過其餘方式把服務的計算次數降下來。然而，終端改版要時間，服務的cpu快滿了，看來春節是很差過了。。。

4、找到問題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，這個是肯定的（尤爲是循環打印）。這裏更深層次的緣由，後續還要分析下。

5、總結

曲折的優化過程，最後倒是以比較簡單的日誌優化解決了。從中能夠看出，在平常服務維護當中，經驗扮演着相當重要的做用。這裏要感謝xianyizhang大神的指導，同時懂得如何找問題以及找問題的方法也相當重要。