CPU上漲100%的問題排查
最近修改了一個快一年沒有發過特性的服務;修改只對深圳set生效;但是服務釋出到三地後,三地的CPU分別從20%增長到40%或40%增長到80%;也就是CPU增長了100%;因為本次改動只對深圳有效,而其他兩地的CPU也增長,那麼可以確認是一年中其他修改導致了CPU的增長。
排查CPU增長情況的工具首先是TOP命令檢視佔用CPU最多的是哪幾個程序,毫無疑問就是我的SPP服務的幾個worker程序。於是進一步高手告訴我要用perf工具,perf工具可以看到是哪個函式哪個地方呼叫分別佔用CPU的比例;所以菜鳥第一次開始學習perf工具;按照網友教程學樣先用了/usr/local/tlinux/perf37/bin/perf record -e cpu-clock XXX (可執行程式)檢視CPU是耗在哪個地方;發現CPU耗在SPP的幾個程序但是並沒有如網友例子裡說的那樣顯示耗在哪個函式我這邊是顯示了一個地址,如圖:
這樣完全不知道耗在哪裡,於是接著讀教程發現有一個引數是-p 檢視某個程序CPU消耗情況,於是用了這條指令:
/usr/local/tlinux/perf37/bin/perf record -g --call-graph -p pid
得到了結果:
發現CPU主要耗在pb裡面的反射,列印函式裡面;進一步想通過perf檢視呼叫情況使用了引數-g --call-back
展開也並沒有如教程中的示例那樣,很順利地看到了最終是哪個函式呼叫了這些pb相關的函式。
所以最後採用了比較無奈但是管用的方法,二分查詢svn版本,定位導致CPU上漲的版本。居然只是因為把日誌函式要列印的內容從一個普通的字串變成了呼叫pb的Utf8DebugString;正是Utf8DebugString裡面用到了pb 反射列印的函式導致了CPU的上漲。而很好奇的是並沒有列印日誌,日誌的級別是DEBUG級別的為何會出現這樣的問題呢??研究了一下列印日誌這個巨集的定義,這個巨集沒有進行日誌級別的判斷直接將引數傳給了列印日誌的函式,所以這裡會先呼叫Utf8DebugString生成所需的引數,此時再在列印的函式裡面判斷級別也是沒用的了。而glog這個地方就不是,glog現在巨集裡面進行了日誌級別的判斷所以不會出現這樣的問題。
終於經過兩天找到了這個問題,不過還是有些疑惑的是為何我用perf -g --call-graph為何沒有達到預期得到calling graph,求教高手給出解釋。