一、perf簡介
從2.6.31內(nèi)核開始，linux內(nèi)核自帶了一個性能分析工具perf，能夠進行函數(shù)級與指令級的熱點查找。通過它，應用程序可以利用 PMU，tracepoint 和內(nèi)核中的特殊計數(shù)器來進行性能統(tǒng)計。它不但可以分析指定應用程序的性能問題 (per thread)，也可以用來分析內(nèi)核的性能問題，當然也可以同時分析應用代碼和內(nèi)核，從而全面理解應用程序中的性能瓶頸。
Perf是內(nèi)置于Linux內(nèi)核源碼樹中的性能剖析(profiling)工具。它基于事件采樣原理，以性能事件為基礎(chǔ)，支持針對處理器相關(guān)性能指標與操作系統(tǒng)相關(guān)性能指標的性能剖析，常用于性能瓶頸的查找與熱點代碼的定位。
1.1安裝Perf
安裝 perf 非常簡單, 只要內(nèi)核版本高于2.6.31的, perf已經(jīng)被內(nèi)核支持. 首先安裝內(nèi)核源碼:
apt-get install linux-source
那么在 /usr/src 目錄下就已經(jīng)下載好了內(nèi)核源碼, 我們對源碼包進行解壓, 然后進入 tools/perf 目錄然后敲入下面兩個命令即可：
make
make install
可能因為系統(tǒng)原因, 需要提前安裝下面的開發(fā)包:
apt-get install -y binutils-dev
apt-get install -y libdw-dev
apt-get install -y Python/ target=_blank class=infotextkey>Python-dev
apt-get install -y libnewt-dev
1.2Perf的基本使用
CPU周期(cpu-cycles)是默認的性能事件，所謂的CPU周期是指CPU所能識別的最小時間單元，通常為億分之幾秒，是CPU執(zhí)行最簡單的指令時所需要的時間，例如讀取寄存器中的內(nèi)容，也叫做clock tick。
perf COMMAND [-e event ...] PROGRAM, perf 是采用的這么一個命令格式, COMMAND一般常用的就是 top, stat, record, report等. 然后用 -e 參數(shù)來統(tǒng)計需要關(guān)注的事件. 多個事件就用多個 -e 連接。
Perf是一個包含22種子工具的工具集，以下是最常用的5種：
- perf-list
- perf-stat
- perf-top
- perf-record
- perf-report
- perf-trace
perf-list
Perf-list用來查看perf所支持的性能事件，有軟件的也有硬件的。
List all symbolic event types。
perf list [hw | sw | cache | tracepoint | event_glob]
perf stat
說明一個工具的最佳途徑是列舉一個例子。考查下面這個例子程序。其中函數(shù) longa() 是個很長的循環(huán)，比較浪費時間。函數(shù) foo1 和 foo2 將分別調(diào)用該函數(shù) 10 次，以及 100 次。
//t1.c
void longa()
{
int i,j;
for(i = 0; i < 1000000; i++)
j=i; //am I silly or crazy? I feel boring and desperate.
}
void foo2()
{
int i;
for(i=0 ; i < 10; i++)
longa();
}
void foo1()
{
int i;
for(i = 0; i< 100; i++)
longa();
}
int mAIn(void)
{
foo1();
foo2();
}
然后編譯它:
gcc -o t1 -g t1.c
下面演示了 perf stat 針對程序 t1 的輸出：
root@ubuntu-test:~# perf stat ./t1
Performance counter stats for './t1':
218.584169 task-clock # 0.997 CPUs utilized
18 context-switches # 0.000 M/sec
0 CPU-migrations # 0.000 M/sec
82 page-faults # 0.000 M/sec
771,180,100 cycles # 3.528 GHz
<not counted> stalled-cycles-frontend
<not counted> stalled-cycles-backend
550,703,114 instructions # 0.71 insns per cycle
110,117,522 branches # 503.776 M/sec
5,009 branch-misses # 0.00% of all branches
0.219155248 seconds time elapsed
程序 t1 是一個 CPU bound 型，因為 task-clock-msecs 接近 1
對 t1 進行調(diào)優(yōu)應該要找到熱點 ( 即最耗時的代碼片段 )，再看看是否能夠提高熱點代碼的效率。缺省情況下，除了 task-clock-msecs 之外，perf stat 還給出了其他幾個最常用的統(tǒng)計信息：
- Task-clock-msecs：CPU 利用率，該值高，說明程序的多數(shù)時間花費在 CPU 計算上而非 IO。
- Context-switches：進程切換次數(shù)，記錄了程序運行過程中發(fā)生了多少次進程切換，頻繁的進程切換是應該避免的。
- Cache-misses：程序運行過程中總體的 cache 利用情況，如果該值過高，說明程序的 cache 利用不好
- CPU-migrations：表示進程 t1 運行過程中發(fā)生了多少次 CPU 遷移，即被調(diào)度器從一個 CPU 轉(zhuǎn)移到另外一個 CPU 上運行。
- Cycles：處理器時鐘，一條機器指令可能需要多個 cycles，Instructions: 機器指令數(shù)目。
- IPC：是 Instructions/Cycles 的比值，該值越大越好，說明程序充分利用了處理器的特性。
- Cache-references: cache 命中的次數(shù)，Cache-misses: cache 失效的次數(shù)。
通過指定 -e 選項，您可以改變 perf stat 的缺省事件 ( 關(guān)于事件，在上一小節(jié)已經(jīng)說明，可以通過 perf list 來查看 )。假如您已經(jīng)有很多的調(diào)優(yōu)經(jīng)驗，可能會使用 -e 選項來查看您所感興趣的特殊的事件。
有些程序慢是因為計算量太大，其多數(shù)時間都應該在使用 CPU 進行計算，這叫做 CPU bound 型；有些程序慢是因為過多的 IO，這種時候其 CPU 利用率應該不高，這叫做 IO bound 型；對于 CPU bound 程序的調(diào)優(yōu)和 IO bound 的調(diào)優(yōu)是不同的。
perf top
使用 perf stat 的時候，往往您已經(jīng)有一個調(diào)優(yōu)的目標。比如我剛才寫的那個無聊程序 t1。
也有些時候，您只是發(fā)現(xiàn)系統(tǒng)性能無端下降，并不清楚究竟哪個進程成為了貪吃的 hog。
此時需要一個類似 top 的命令，列出所有值得懷疑的進程，從中找到需要進一步審查的家伙。
Perf top 用于實時顯示當前系統(tǒng)的性能統(tǒng)計信息。該命令主要用來觀察整個系統(tǒng)當前的狀態(tài)，比如可以通過查看該命令的輸出來查看當前系統(tǒng)最耗時的內(nèi)核函數(shù)或某個用戶進程。
讓我們再設(shè)計一個例子來演示吧，我很快就想到了如代碼清單 2 所示的一個程序：
//t2.c
main(){
int i;
while(1) i++;
}
然后編譯這個程序：
gcc -o t2 -g t2.c
運行這個程序后， 我們另起一個窗口，運行perf top來看看：
Events: 8K cycles
98.67% t2 [.] main
1.10% [kernel] [k] __do_softirq
0.07% [kernel] [k] _raw_spin_unlock_irqrestore
0.05% perf [.] kallsyms__parse
0.05% libc-2.15.so [.] 0x807c7
0.05% [kernel] [k] kallsyms_expand_symbol
0.02% perf [.] map__process_kallsym_symbol
很容易便發(fā)現(xiàn) t2 是需要關(guān)注的可疑程序。不過其作案手法太簡單：肆無忌憚地浪費著 CPU。所以我們不用再做什么其他的事情便可以找到問題所在。但現(xiàn)實生活中，影響性能的程序一般都不會如此愚蠢，所以我們往往還需要使用其他的 perf 工具進一步分析。
使用 perf record, 解讀 report
使用 top 和 stat 之后，您可能已經(jīng)大致有數(shù)了。要進一步分析，便需要一些粒度更細的信息。比如說您已經(jīng)斷定目標程序計算量較大，也許是因為有些代碼寫的不夠精簡。那么面對長長的代碼文件，究竟哪幾行代碼需要進一步修改呢？這便需要使用 perf record 記錄單個函數(shù)級別的統(tǒng)計信息，并使用 perf report 來顯示統(tǒng)計結(jié)果。
您的調(diào)優(yōu)應該將注意力集中到百分比高的熱點代碼片段上，假如一段代碼只占用整個程序運行時間的 0.1%，即使您將其優(yōu)化到僅剩一條機器指令，恐怕也只能將整體的程序性能提高 0.1%。俗話說，好鋼用在刀刃上，不必我多說了。
perf record -e cpu-clock ./t1
perf report
perf report 輸出結(jié)果：
Events: 229 cpu-clock
100.00% t1 t1 [.] longa
不出所料，hot spot 是 longa( ) 函數(shù)。但，代碼是非常復雜難說的，t1 程序中的 foo1() 也是一個潛在的調(diào)優(yōu)對象，為什么要調(diào)用 100 次那個無聊的 longa() 函數(shù)呢？但我們在上圖中無法發(fā)現(xiàn) foo1 和 foo2，更無法了解他們的區(qū)別了。
我曾發(fā)現(xiàn)自己寫的一個程序居然有近一半的時間花費在 string 類的幾個方法上，string 是 C++ 標準，我絕不可能寫出比 STL 更好的代碼了。因此我只有找到自己程序中過多使用 string 的地方。因此我很需要按照調(diào)用關(guān)系進行顯示的統(tǒng)計信息。
使用 perf 的 -g 選項便可以得到需要的信息：
perf record -e cpu-clock -g ./t1
perf report
輸出結(jié)果：
Events: 270 cpu-clock
- 100.00% t1 t1 [.] longa
- longa
+ 91.85% foo1
+ 8.15% foo2
通過對 calling graph 的分析，能很方便地看到 91.85% 的時間都花費在 foo1() 函數(shù)中，因為它調(diào)用了 100 次 longa() 函數(shù)，因此假如 longa() 是個無法優(yōu)化的函數(shù)，那么程序員就應該考慮優(yōu)化 foo1，減少對 longa() 的調(diào)用次數(shù)。
使用 tracepoint
當 perf 根據(jù) tick 時間點進行采樣后，人們便能夠得到內(nèi)核代碼中的 hot spot。那什么時候需要使用 tracepoint 來采樣呢？
我想人們使用 tracepoint 的基本需求是對內(nèi)核的運行時行為的關(guān)心，如前所述，有些內(nèi)核開發(fā)人員需要專注于特定的子系統(tǒng)，比如內(nèi)存管理模塊。這便需要統(tǒng)計相關(guān)內(nèi)核函數(shù)的運行情況。另外，內(nèi)核行為對應用程序性能的影響也是不容忽視的：
以之前的遺憾為例，假如時光倒流，我想我要做的是統(tǒng)計該應用程序運行期間究竟發(fā)生了多少次系統(tǒng)調(diào)用。在哪里發(fā)生的？
下面我用 ls 命令來演示 sys_enter 這個 tracepoint 的使用：
root@ubuntu-test:~# perf stat -e raw_syscalls:sys_enter ls
bin libexec off perf.data.old t1 t3 tutong.iso
bwtest minicom.log perf.data pktgen t1.c t3.c
Performance counter stats for 'ls':
111 raw_syscalls:sys_enter
0.001557549 seconds time elapsed
個報告詳細說明了在 ls 運行期間發(fā)生了多少次系統(tǒng)調(diào)用 ( 上例中有 111 次 )。
二、常見性能問題分析
性能測試大致分以下幾個步驟：
- 需求分析
- 腳本準備
- 測試執(zhí)行
- 結(jié)果整理
- 問題分析
需求描述：有一個服務，啟動時會加載一個1G的詞表文件到內(nèi)存，請求來了之后，會把請求詞去詞表里做模糊匹配，如果匹配到了就向一個后端服務發(fā)送一條http請求，拿回數(shù)據(jù)之后，返回給客戶端的同時，向MySQL記錄請求的唯一標識和一個請求次數(shù)的標記；
其中有幾個關(guān)鍵函數(shù)
模糊匹配（fuzzyMatching）
后端請求函數(shù)（sendingRequest）
拼裝請求函數(shù)（buildResponse）
記錄mysql請求次數(shù)標記（signNum）
問題及分析：
第一組：完全隨機請求詞，qps達到1k時，服務器未見異常，cpu、內(nèi)存、帶寬均未滿，qps無法繼續(xù)提升；
- 分析：由于此服務后端連接了其它服務，所以在壓測之前，要確認后端服務不會成為瓶頸點，目前的狀態(tài)很可能是后端服務限制了被測服務的性能；此時可以檢查后端服務所在機器的各項指標，或者查看本機的連接狀況，一般后端服務無法處理，而被測服務又會一直向后面請求的話，timewait狀態(tài)的連接會變得比較多；
第二組：解決后端服務的問題后，第二組使用平均30個字的請求詞，來打壓，qps到400時，cpu load已滿；
- 分析：這種情況明顯是由于fuzzyMatching函數(shù)計算效率的問題導致cpu滿載，從而無法提升qps，使響應時間不斷增大，此時可以通過perf+火焰圖來確定整個處理請求過程中響應時間長的函數(shù)；此時需要評估壓測數(shù)據(jù)是否合理，如果線上平均請求詞只有2個的時候，此組測試明顯不合理，此時要開發(fā)進行性能優(yōu)化就是浪費時間的；如果評估測試數(shù)據(jù)合理，可以再次更換短詞數(shù)據(jù)進行壓測驗證猜測；
第三組：解決了上述兩個問題之后，使用完全隨機請求詞，qps到達3k后降低至1k，然后再次提升到3k，如此反復；
- 分析：此時關(guān)注一下各項指標，排除了以上的問題的話，操作mysql慢的問題可能性大一些，對這種需要高并發(fā)的系統(tǒng)來說，直接讀寫mysql不是個聰明的解決方案，一般會用redis做一層緩存，這里說道的另一個問題就是開發(fā)設(shè)計不合理，導致的性能問題；
第四組：將后端換做真實的服務來做整體壓測，發(fā)現(xiàn)qps最高只能到300，此時檢查各項指標，發(fā)現(xiàn)入口帶寬占滿了；
- 分析：這次問題比較明顯，后端服務返回內(nèi)容過大，導致帶寬被占滿，此時依然需要評估需求：1、是否需要后端返回的所有數(shù)據(jù)內(nèi)容；2、評估更換萬兆網(wǎng)卡的性價比；3、是否可以通過技術(shù)手段優(yōu)化帶寬占用，比如把一次請求分散到多組服務的多個請求；
2.1perf+火焰圖定位函數(shù)問題
這里簡單說一下如何使用perf+火焰圖來直觀的定位性能問題：
perf
Perf 擁有了眾多的性能分析能力，舉例來說，使用 Perf 可以計算每個時鐘周期內(nèi)的指令數(shù)，稱為 IPC，IPC 偏低表明代碼沒有很好地利用 CPU。Perf 還可以對程序進行函數(shù)級別的采樣，從而了解程序的性能瓶頸究竟在哪里等等。Perf 還可以替代 strace，可以添加動態(tài)內(nèi)核 probe 點，還可以做 benchmark 衡量調(diào)度器的好壞。
- 使用舉例：perf record -e cpu-clock -g -p 11110 -o data/perf.data sleep 30
- -g 選項是告訴perf record額外記錄函數(shù)的調(diào)用關(guān)系 -e cpu-clock 指perf record監(jiān)控的指標為cpu周期 -p 指定需要record的進程pid
生成火焰圖
1、第一步：使用壓力測試工具對程序進行打壓，壓到程序拐點；
$sudo perf record -e cpu-clock -g -p 11110
Ctrl+c結(jié)束執(zhí)行后，在當前目錄下會生成采樣數(shù)據(jù)perf.data.
2、第二步：用perf 工具對perf.data進行解析
perf -i perf.data &> perf.unfold
3、第三步：將perf.unfold中的符號進行折疊：
./stackcollapse-perf.pl perf.unfold &> perf.folded
4、最后生成svg圖：
./flamegraph.pl perf.folded > perf.svg
到這兒可以生成函數(shù)調(diào)用火焰圖，如下圖：
原生的perf可以直接定位C/C++的程序，通常編譯debug版本的程序能看到更多的信息，JAVA、go等語言可以通過各自定制的工具來生成，原理類似；通過火焰圖可以輕松定位到哪個函數(shù)的處理時間最長，從而找到問題所在。
