介紹一個對陌生程序快速進行性能瓶頸分析的技巧

前言

???????? 工作多年，一直做的是curd系統。前幾年做的系統應用場景，大多對數據庫依賴比較重。例如報表統計，數據遷移，批量對賬等。所以這些系統出現性能瓶頸一般出在數據庫操作上面。

???????? 如果程序因為數據庫操作出現性能瓶頸是比較好辦的，因為oracle提供了完善的性能分析工具。往往使用awr報告簡單分析一下（top sql和top event）就可以獲知有哪些sql有異常。

???????? 找出問題sql，根據經驗進行優化即可，例如沒索引的加索引，有索引沒走的加hint，IO太慢的話加并行之類。之前我整理過的一些數據庫sql優化經驗在博客里面發過。

? ? ? ???更多關于數據庫應用優化的知識見這里:https://www.cnblogs.com/kingstarer/p/9613626.html

? ? ? ? ?但今年做的系統，有時也會出現數據庫資源充足，但由于程序自身寫得不好，導致cpu消耗太高，系統反應緩慢的情況。

???????? 這種如果是自己寫的程序相對比較好處理，因為寫的時候大概會知道哪些地方容易出問題。

???????? 但有時也會有接手別人的程序出現問題需要優化的情況，這種以前我是都需要花時間重新看一下他們的源碼，然后結合日志分析問題出哪里，效率相對比較低。

???????? 不過最近我發現一個工具，能直觀地統計出程序資源消耗，對于優化幫助特別大。今年我有幾次對項目組的程序做優化，都是先用它發現問題關鍵，然后再進行優化的。

這種方式比以前憑經驗分析好，因為有時自己覺得有問題的代碼，優化后發現效果甚微。（代碼使用頻率低，或者瓶頸出現在其它地方。）例如今年我曾經把系統取環境變量的代碼，從原來直接使用getenv，改為從緩存里面取數（getenv是順序查找，緩存取是自己寫的二分查找），但發現對于系統整體性能提高不到1%。

???????? 下面以一次項目組優化的過程為例，給大家介紹一下這個工具----callgrind的用法：

概述

???????? callgrind是vallgrind工具家族中的一員，它相比其它性能測試工具的好處是不需要修改源碼、編譯選項（推薦加-g，但不是必要的）、系統參數等。但也存在缺點，如分析過程中程序性能下降較大，無法對已啟動的進程進行性能分析，無法分析函數實際耗時（分析的是消耗cpu時間，如果存在sleep、wait之類函數會影響分析結果），對遞歸調用展示不友好等。不過好在我們項目中，這些缺點不太影響我們使用。

???????? callgrind分析完程序后會使用Ir（指令執行的次數）來統計程序中函數調用消耗，同時還會建立函數調用關系圖，需要分析程序流程時可以參考。同時callgrind還能分析程序緩存使用情況，幫助我們優化if和switch順序。還有分析鎖順序等其它功能。

每次運行結束時，它會把分析數據寫入一個文件，之后我們可以通過callgrind_annotate或kcachegrind讀取分析結果展示成可讀的報告。

???????? 接下來我介紹callgrind的使用心得。

背景

rcc查詢業務由于業務量增長，現在部署了查詢的三臺機器平時cpu負荷接近50%，在交易量偏大時cpu會增漲到100%。

項目組臨時投入新機器資源將cpu消耗控制到25~50%，以減少系統性能告警。但后續仍需對應用進行優化，以防故障再次發生。

問題還原與分析

在測試環境上經過一番配置，還原了系統故障現象。仔細觀察可以發現：

在并發數比較低時，系統cpu消耗較低，但并發數高一些時，系統cpu消耗急劇上漲，很快就到達100%，但此時tps基本不變。

并發數	cpu使用率	tps
6	約60%	73
12	約100%	68

觀察top和vmstat信息，發現兩個異常：

1 vmstat顯示user消耗超過90%，而sys只占不到10%。對于非計算密集應用，這個比例有點高

2 top顯示系統消耗cpu最多的進程并非業務服務進程，而是加解密相關的服務進程

圖示：QueryBridgeSrv和QuerySecSrv消耗了比較多的cpu資源。而Query核心業務進程反而消耗得不是很多。（從下到上cpu消耗逐漸下降）

業務服務代碼經常修改，項目組開發人員比較熟悉，通過日志即可迅速定位問題出在哪。但是報文較驗轉換服務由于修改的比較少，比較難定位問題，所以決定使用callgrind輔助分析。

callgrind一般用法

對于一般的程序，我們可以直接啟動callgrind分析程序，只需要在命令行前面加上"valgrind --tool=callgrind "，如下：

等程序運行完退出后會在目錄生成分析文件，命名為callgrind.out.進程號文件，我們可以使用callgrind_annotate在命令行界面上對其進行分析，但一般是拿到windows環境下使用kcachegrind分析。

callgrind在項目中的用法

由于項目中的程序是以服務形式啟動的，不會自然退出，所以需要使用另外的方法收集分析結果文件。

單進程程序QueryBridgeSrv分析方法：

???????? 由于QueryBridgeSrv服務是單進程程序，所以只需要直接啟動即可。

???????? 不過由于我們項目把很多程序啟動參數放在環境變量，不設置的話啟動會出異常。所以啟動前需要設置環境變量，可以使用以下腳本獲取QueryBridgeSrv程序環境變量

????????

???????? 執行腳本后即可獲取設置環境變量語句，執行后即可正常啟動

???????? time valgrind --tool=callgrind --callgrind-out-file="callgrind.bridge_1305_%p.out"? QueryBridgeSrv 1305 17 2001 2002 # callgrind-out-file選項是指定生成的分析文件名字更多選項可參考man valgrind

????????

進程啟動后我們就可以開始執行正常的測試用例，讓callgrind分析程序運行情況。等運行得差不多了，我們可以在其它會話窗口執行callgrind_control命令將收集的信息文件輸出。

callgrind_control選項也不少，一般我們會使用到以下兩個選項：

callgrind_control -d # dump出目前收集的信息

callgrind_control -k # 停止callgrind（不會輸出收集文件 所以先要dump）

多進程程序QuerySecSrv分析方法：

???????? 對于多進程程序，最好由項目的Daemon進程啟動。所以我們可以設計一個啟動腳本放到bin目錄下面：

????????

???????? 然后修改tbl_srv_param參數，將啟動程序名字由QuerySecSrv改為QuerySecSrv.sh

???????? 這樣Daemon就會啟動QuerySecSrv.sh，然后由QuerySecSrv.sh啟動callgrind對QuerySecSrv進行分析。

???????? 進程啟動后獲取分析結果文件方法與QueryBridgeSrv一致。

kcachegrind介紹

???????? 對于生成的文件，我們可以使用kcachegrind進行分析：使用kcachegrind打開之前我們分析QueryBridgeSrv的結果文件（文件一定要以"callgrind."開頭），顯示如下：

???????? 左上角的Flat Profile窗格，第一列是函數消耗的總資源（包括函數本身開銷和函數內部調用的子函數開銷之和），第二列是函數本身的開銷。

???????? 可以想象，main函數一般是系統中總開銷最大的，因為大部分函數是由main函數調用的。但是main函數自身消耗可能不多，大部分指令是它調用的其它函數消耗的。

???????? 右上角的窗格（后面稱callers窗格），我們一般用來顯示該函數被調用的信息(callers)，如圖，可以看出GenCtx函數只有一個調用者GenSecHead。

???????? 右下角窗口（后面稱callees窗格），我們一般用來顯示該函數調用其它函數信息(callees)，如圖，可以看出GenCtx函數調用了好多個函數及分別消耗的指令數。

???????? 因為我們一般不關心函數實際開銷，而是關心函數相對開銷，所以kcachegrind提供了兩個按鈕，把開銷顯示成百分比。

???????? （百分號控制的是Flat Profile窗口顯示方式，十字箭頭控制的是Callers和Callees窗格）

???

???????? 按百分比顯示后我們可以清楚地看出memset函數占用了程序開銷的73%，而且消耗在其自身。(Self)

???????? 對于一般應用，memset函數是沒有優化空間的，所以我們要觀察是哪些函數調用了memset這么多次。

???????? 在Flat Profile窗口單擊memset函數，可以看到調用memset函數的信息

???????? 從上圖我們可以看出20%的memset調用消耗是由于GenCtx引起的，我們先看看這個函數。在Callers窗格雙擊，可以進到GenCtx函數的分析（分析過程可以使用工具欄的導航按鈕前后跳轉）

????????

???????? 可以看到GenCtx函數50%的消耗在于memset，我們可以到對應函數看有沒有調用必要。

???????? 在Flat Profile窗格下拉列表選擇source file就可以看到函數所在源文件。由于windows環境下代碼路徑問題，無法在kcachegrind直接查看代碼信息，只能另外打開vs查看代碼。（根據網上介紹，使用callgrind_annotate可以直接看到每行代碼消耗指令數，對于分析長函數幫助很大，暫時未在項目中實踐）

在源碼里面我們發現幾處memset調用，作用是把某大塊內存（395k）初始化為零。經分析，這幾處地方并不是特別需要調用memset。應是當時寫代碼時使用防御性編程技巧，寧殺錯，不放過，統一清零。當這個函數只調用一次時，這些操作對系統性能消耗不算多。但當業務量比較大，函數調用次數較多時，這種初始化操作會給系統帶來較大性能消耗。

把初始化代碼代碼注釋了（如下），重新編譯程序，驗證發現功能不受影響。

????????

這里本來應該要貼問題代碼，但這里是博客，就不貼了，避免泄密風險。

//注意，這里變量初始化為零，其實也可能導致隱式調用了memset（具體看編譯器實現）

???????? 繼續使用kcachegrind分析其它函數，把不必要的memset都改掉，再重新跑。發現memset消耗降低了很多。

????????