perf效能分析工具使用分享

良知猶存發表於2022-04-13

@

前言

之前有分享過自己工作中自己搭建的CPU監控指令碼等,但那個屬於是自己手工寫的一些指令碼,比較粗淺的使用。後來就直接使用perf編譯到驅動裡面,在裝置中直接使用perf了,比起自己寫的指令碼,效率直線提升。今天就來分享以下perf的功能使用,它可以將消耗 CPU 時間比較大的使用者程式呼叫棧列印出來,並生成火焰圖。

perf的介紹和安裝

Perf 是Linux kernel自帶的系統效能優化工具。 Perf的優勢在於與Linux Kernel的緊密結合,它可以最先應用到加入Kernel的new feature。pef可以用於檢視熱點函式,檢視cashe miss的比率,從而幫助開發者來優化程式效能,也可以分析程式執行期間發生的硬體事件,比如 instructions retired ,processor clock cycles 等;您也可以分析
軟體事件,比如 Page Fault 和程式切換,這使得 Perf 擁有了眾多的效能分析能力,

通過它,應用程式可以利用 PMU,tracepoint 和核心中的特殊計數器來進行效能統計。它不但可以分析指定應用程式的效能問題 (per thread),也可以用來分析核心的效能問題,當然也可以同時分析應用程式碼和核心,從而全面理解應用程式中的效能瓶頸。

舉例來說,使用 Perf 可以計算每個時鐘週期內的指令數,稱為 IPC,IPC 偏低表明程式碼沒有很好地利用 CPU。Perf 還可以對程式進行函式級別的取樣,從而瞭解程式的效能瓶頸究竟在哪裡等等。Perf 還可以替代 strace,可以新增動態核心 probe 點,還可以做 benchmark 衡量排程器的好壞。。。

ubuntu安裝:

sudo apt-get install linux-tools-common linux-tools-"$(uname -r)" linux-cloud-tools-"$(uname -r)" linux-tools-generic linux-cloud-tools-generic

安裝好之後使用perf -v命令檢視版本


在裝置中安裝
如果你使用yocto,那麼可是用bitbake perf 直接編譯perf工具出來,然後做成映象燒錄到裝置中,如果你使用的是其他根檔案系統製作工具,方法也是類似。


將編譯好的的lib和bin目錄拷貝到裝置中使用。

perf基本使用

它和Oprofile效能調優工具等的基本原理都是對被監測物件進行取樣,最簡單的情形是根據 tick 中斷進行取樣,即在 tick 中斷內觸發取樣點,在取樣點裡判斷程式當時的上下文。假如一個程式 90% 的時間都花費在函式 foo() 上,那麼 90% 的取樣點都應該落在函式 foo() 的上下文中。運氣不可捉摸,那麼只要取樣頻率足夠高,取樣時間足夠長,那麼以上推論就比較可靠。因此,通過 tick 觸發取樣,我們便可以瞭解程式中哪些地方最耗時間,從而重點分析。

上面介紹了perf的原理,“根據 tick 中斷進行取樣,即在 tick 中斷內觸發取樣點,在取樣點裡判斷程式當時的上下文”,我們可以改變取樣的觸發條件使得我們可以獲得不同的統計資料,例如 以時間點 ( 如 tick) 作為事件觸發取樣便可以獲知程式執行時間的分佈;以 cache miss 事件觸發取樣便可以知道 cache miss 的分佈,即 cache 失效經常發生在哪些程式程式碼中。如此等等。

首先我們可以看一下 perf 中能夠觸發取樣的事件有哪些。

perf list使用,可以列出所有的取樣事件

sudo perf list

可以看到 Hadrware event Software event等

  • Hardware Event 是由 PMU 硬體產生的事件,比如 cache 命中,當您需要了解程式對硬體特性的使用情況時,便需要對這些事件進行取樣
  • Software Event 是核心軟體產生的事件,比如程式切換,tick 數等
  • Tracepoint event 是核心中的靜態 tracepoint 所觸發的事件,這些 tracepoint 用來判斷程式執行期間核心的行為細節,比如 slab 分配器的分配次數等

perf stat 概覽程式的執行情況

perf stat選項,可以在終端上執行命令時收集效能統計資訊

sudo perf stat -p 11664
指定程式檢視,ctrl +c 殺死程式之後,就可以看到相應的資料了。

  • task-clock(msec)是指程式執行期間佔用了xx的任務時鐘週期,該值高,說明程式的多數時間花費在 CPU 計算上而非 IO
  • context-switches是指程式執行期間發生了xx次上下文切換,記錄了程式執行過程中發生了多少次程式切換,頻繁的程式切換是應該避免的。(有程式程式間頻繁切換,或者核心態與使用者態頻繁切換)
  • cpu-migrations 是指程式執行期間發生了xx次CPU遷移,即使用者程式原本在一個CPU上執行,後來遷移到另一個CPU
  • cycles:處理器時鐘,一條機器指令可能需要多個 cycles
  • Instructions: 機器指令數目。
  • 其他可以監控的譬如分支預測、cache命中,page-faults 是指程式發生了xx次頁錯誤等
sudo  perf stat -p 13465
root@lyn:/mnt# ps -ux | grep target
root     13465 89.7  0.1   4588  1472 pts/1    R+   17:30   0:07 ./target
root     13467  0.0  0.0   3164   744 pts/0    S+   17:30   0:00 grep target
root@lyn:/mnt# perf stat -p 13465
^C
 Performance counter stats for process id '13465':

      13418.914783      task-clock (msec)         #    1.000 CPUs utilized          
                13      context-switches          #    0.001 K/sec                  
                 0      cpu-migrations            #    0.000 K/sec                  
                 0      page-faults               #    0.000 K/sec                  
       25072130385      cycles                    #    1.868 GHz                    
          20056061      stalled-cycles-frontend   #    0.08% frontend cycles idle   
        8663621265      stalled-cycles-backend    #   34.55% backend  cycles idle   
       27108898221      instructions              #    1.08  insns per cycle        
                                                  #    0.32  stalled cycles per insn
        3578980615      branches                  #  266.712 M/sec                  
            841545      branch-misses             #    0.02% of all branches        

      13.419173431 seconds time elapsed

參考 連結

perf top實時顯示當前系統的效能統計資訊

sudo perf top -g

用於實時顯示當前系統的效能統計資訊。該命令主要用來觀察整個系統當前的狀態,比如可以通過檢視該命令的輸出來檢視當前系統最耗時的核心函式或某個使用者程式。

[.] : user level 使用者態空間,若自己監控的程式為使用者態程式,那麼這些即主要為使用者態的cpu-clock佔用的數值
[k]: kernel level 核心態空間
[g]: guest kernel level (virtualization) 客戶核心級別
[u]: guest os user space 作業系統使用者空間
[H]: hypervisor 管理程式
The final column shows the symbol name.

當 perf 收集呼叫鏈時,開銷可以在兩列中顯示為Children和Self 。這裡的Self列與沒有“-g”的列類似:這是每個函式花費的 CPU 週期百分比。但是Children列在其下方新增了所有呼叫函式所花費的時間。不僅是直系子女,而且是所有後代。對於呼叫圖的葉子,函式不呼叫其他任何東西,Self 和 Children 的值是相等的。但是對於 main(),它增加了在 f1()<-main() 和 f2()<-main() 中花費的時間。您將第一行讀為: 95.61% 的時間花在呼叫 main() 上,而只有 8.19% 的時間花在 main() 指令上,因為它大部分時間都在呼叫其他函式。請注意,您可以新增“Self”以覆蓋 100%,但在“Children”中,兒童樣本佔多行。這個想法是在頂部檢視佔樣本最多的呼叫堆疊片段。

有一個“+”,可以向下檢視呼叫關係。

perf record 記錄採集的資料

使用 top 和 stat 之後,perf可能已經大致有數了。要進一步分析,便需要一些粒度更細的資訊。比如說我們已經斷

使用 top 和 stat 之後,perf可能已經大致有數了。要進一步分析,便需要一些粒度更細的資訊。比如說我們已經斷定目標程式計算量較大,也許是因為有些程式碼寫的不夠精簡。那麼面對長長的程式碼檔案,究竟哪幾行程式碼需要進一步修改呢?這便需要使用 perf record 記錄單個函式級別的統計資訊,並使用 perf report 來顯示統計結果(perf record表示記錄到檔案,perf top直接會顯示到介面)。

perf record ,它可以對事件進行取樣,將取樣的資料收集在一個 perf.data 的檔案中,這將會帶來一定的效能開銷,不過這個命令很有用,可以用來找出最佔 CPU 的程式。

下面的命令對系統 CPU 事件做取樣,取樣時間為 60 秒,每秒取樣 99 個事件,-g表示記錄程式的呼叫棧。
sudoperf record -F 99 -a -g -- sleep 60

此外我們還可以使用PID監控程式perf record -e cpu-clock -g -p pid 監控 已啟動的程式;也可以使用程式名監控程式perf record -e cpu-clock -g -p grep your_program

-e選項允許您在perf list命令中列出的多個類別中選擇一個事件類別。例如,在這裡,我們使用-e cpu-clock 是指perf record監控的指標為cpu週期程式執行完之後,perf record會生成一個名為perf.data的檔案(預設值),如果之前已有,那麼之前的perf.data檔案會變為perf.data.old檔案

-g選項是告訴perf record額外記錄函式的呼叫關係,因為原本perf record記錄大都是庫函式,直接看庫函式,大多數情況下,你的程式碼肯定沒有標準庫的效能好對吧?除非是針對產品進行特定優化,所以就需要知道是哪些函式頻繁呼叫這些庫函式,通過減少不必要的呼叫次數來提升效能

perf record的其他引數:

  • -f:強制覆蓋產生的.data資料

  • -c:事件每發生count次取樣一次

  • -p:指定程式

  • -t:指定執行緒

可以使用ctrl+c中斷perf程式,或者在命令最後加上引數 --sleep n (n秒後停止)


  • sudo perf report -n可以生成報告的預覽。
  • sudo perf report -n --stdio可以生成一個詳細的報告。
  • sudo perf script可以 dump 出 perf.data 的內容。

獲得這個perf.data檔案之後,我們其實還不能直接檢視,下面就需要perf report工具進行檢視

perf report輸出 record的結果

如果record之後想直接輸出結果,使用perf report即可
perf report的相關引數:
-i : 指定檔案輸出
  -k:指定未經壓縮的核心映象檔案,從而獲得核心相關資訊
  --report:cpu按照cpu列出負載

sudo perf report

Samples: 123K of event 'cycles', Event count (approx.): 36930701307
Overhead  Command          Shared Object                                       Symbol
  18.91%  swapper          [kernel.kallsyms]                                   [k] intel_idle
     5.18%  dev_ui		    libQt5lxxx                                    [.] 0x00000000013044c7
    3.20%  dev_ui             libc-2.19.so                                 [.] _int_malloc                                                                                                                                    
	1.03%  dev_ui            libc-2.19.so                                  [.] __clock_gettime                                                                                                                                      
   3.04%  todesk           libpixman-1.so.0.38.4                               [.] 0x000000000008cac0
   1.20%  todesk           [JIT] tid 126593                                    [.] 0x0000000001307c7a
   0.84%  todesk           [JIT] tid 126593                                    [.] 0x000000000143c3f4
   0.73%  Xorg             i965_dri.so                                         [.] 0x00000000007cefe0
   0.65%  todesk           libsciter-gtk.so                                    [.] tool::tslice<gool::argb>::xcopy
   0.58%  Xorg             i965_dri.so                                         [.] 0x00000000007cf00e
   0.53%  Xorg             i965_dri.so                                         [.] 0x00000000007cf03c
   0.49%  todesk           [JIT] tid 126593                                    [.] 0x0000000001307cb2
   0.48%  Xorg             i965_dri.so                                         [.] 0x00000000007cf06a
   0.44%  todesk           [JIT] tid 126593                                    [.] 0x0000000001307cb6
   0.41%  todesk           [JIT] tid 126593                                    [.] 0x0000000001307cc0
   0.40%  x-terminal-emul  libz.so.1.2.11                                      [.] adler32_z
   0.40%  todesk           [JIT] tid 126593                                    [.] 0x0000000001307c83
   0.38%  todesk           [JIT] tid 126593                                    [.] 0x0000000001307cbb
   0.33%  swapper          [kernel.kallsyms]                                   [k] menu_select
   0.32%  gnome-shell      libmutter-clutter-6.so.0.0.0                        [.] clutter_actor_paint
   0.31%  gnome-shell      libgobject-2.0.so.0.6400.6                          [.] g_type_check_instance_is_a
   0.31%  swapper          [kernel.kallsyms]                                   [k] psi_group_change
   0.24%  SDK_Timer-8      [kernel.kallsyms]                                   [k] psi_group_change
   0.24%  todesk           libc-2.31.so                                        [.] __memset_avx2_unaligned_erms
   0.18%  todesk           [JIT] tid 126593                                    [.] 0x00000000013044c7
   0.18%  todesk           [JIT] tid 126593                                    [.] 0x000000000143c3f0
   0.17%  gnome-shell      libglib-2.0.so.0.6400.6                             [.] g_hash_table_lookup
   0.17%  todesk           [JIT] tid 126593                                    [.] 0x000000000143c426
   0.17%  todesk           [JIT] tid 126593                                    [.] 0x000000000143c3dd
   0.16%  todesk           [JIT] tid 126593                                    [.] 0x000000000143c3d9
   0.16%  swapper          [kernel.kallsyms]                                   [k] cpuidle_enter_state
   0.16%  SDK_Timer-8      [kernel.kallsyms]                                   [k] syscall_exit_to_user_mode
   0.16%  swapper          [kernel.kallsyms]                                   [k] __sched_text_start

  • 在第二行我們發現一個dev_ui ,佔用了5.18%,使用了libQt5lxxx庫, 它本身功能UI顯示,,但是佔用較高的CPU,說明呼叫該庫存在問題(程式碼本身問題),需要對呼叫該庫的程式碼進行檢查。

  • 第三行libc-2.19.so [.] _int_malloc 這是常用的malloc操作,由於對程式碼比較熟悉,在這個過程中不應該有這麼多次申請記憶體,說明程式碼本身有問題,需要對申請動態記憶體的程式碼進行檢查

  • 第四行行 __clock_gettime 這個是由於計時需要,需要頻繁獲取時間,通常是指 gettimeofday()函式

  • 整個統計顯示有很多task-clock佔用是由於kernel.kallsyms導致,同時也驗證了對perf stat獲得的資料的初步判斷,即CPU飆升也與頻繁的CPU遷移(核心態中斷使用者態操作)導致,解決辦法是採用CPU綁核

也許有的人會奇怪為什麼自己完全是一個使用者態的程式為什麼還會統計到核心態的指標?一是使用者態程式執行時會受到核心態的影響,若核心態對使用者態影響較大,統計核心態資訊可以瞭解到是核心中的哪些行為導致對使用者態產生影響;二則是有些使用者態程式也需要依賴核心的某些操作,譬如I/O操作+ 4.93% dev_ui libcurl-gnutls.so.4.3.0 [.] 0x000000000001e1e0 ,左邊的加號代表perf已經記錄了該呼叫關係,按enter鍵可以檢視呼叫關係,perf監控該程式結果記錄到很多核心呼叫,說明該程式在執行過程中,有可能被核心態任務頻繁中斷,應儘量避免這種情況,對於這個問題我的解決辦法是採用綁核,譬如機器有8個CPU,那麼我就繫結核心操作、中斷等主要在0-5CPU,GW由於有兩個執行緒,分別繫結到6、7CPU上。

注意:調優應該將注意力集中到百分比高的熱點程式碼片段上,假如一段程式碼只佔用整個程式執行時間的 0.1%,即使您將其優化到僅剩一條機器指令,恐怕也只能將整體的程式效能提高 0.1%。俗話說,好鋼用在刀刃上.

參考文章:連結

也可以用關鍵詞篩選
使用了sudo perf report 可以檢視當前perf.data的資料,但是當你程式碼呼叫很多時候不好進行分析檢視,這個時候我們就可以選擇我們需要關注的重點資訊檢視,提高效率。例如以下的futex_wait:

選中之後,使用 --call-graph ,,,,callee --symbol-filter = 後面增加你需要篩選監控的型別就可以單獨顯示了。

sudo perf report --call-graph ,,,,callee --symbol-filter=futex_wait

這篇文章可以更多的幫助你理解filter:連結

perf diff進行兩次record對比

我們多次perf record之後,當前路徑下會有兩個perf.data 和perf.data.old檔案,分別是本次和上次record的記錄,這個時候我們可以通過perf diff進行對比優化的結果。

sudo perf diff perf.data perf.data.old


介紹一些了perf細節使用的描繪,再給大家分享一個perf詳細使用介紹的網址,大家對於perf介紹中有需要繼續深入探索的部分,可以點選以下連結進行學習。

perf Examples 詳細的使用介紹

連結:https://www.brendangregg.com/perf.html

Linux Perf commands命令介紹使用
連結:https://linuxhint.com/linux-perf-commands/
在這裡插入圖片描述

火焰圖的製作

CPU 的效能,它可以將消耗 CPU 時間比較大的使用者程式呼叫棧列印出來,並生成火焰圖。通過分析火焰圖的頂層的顯示,我們就可以很直觀的檢視我們函式的效能情況了。

這個是自己ubuntu20系統做捕獲的火焰圖顯示

  • x軸表示取樣次數或者頻率,如果一個函式在 x 軸佔據的寬度越寬,就表示它被抽到的次數多,即執行的時間長。注意,x 軸不代表時間,而是所有的呼叫棧合併後,按字母順序排列的。

  • y 軸表示呼叫棧,每一層都是一個函式。呼叫棧越深,火焰就越高,頂部就是正在執行的函式,下方都是它的父函式。

火焰圖就是看頂層的哪個函式佔據的寬度最大。只要有"平頂"(plateaus),就表示該函式可能存在效能問題。

參考:連結1; 連結2

具體步驟:

  • 1 首先,在 Ubuntu 安裝 perf 工具:

  • 2 再從github下載分析指令碼
    git clone https://github.com/brendangregg/FlameGraph.git

  • 3 使用perf script工具對perf.data進行解析
    perf script -i perf.data &> perf.unfold
    生成火焰圖通常的做法是將 perf.unfold 拷貝到本地機器,在本地生成火焰圖

  • 4 將perf.unfold中的符號進行摺疊
    FlameGraph/stackcollapse-perf.pl perf.unfold &> perf.folded

  • 5 最後生成svg圖
    FlameGraph/flamegraph.pl perf.folded > perf.svg
      生成火焰圖可以指定引數,–width 可以指定圖片寬度,–height 指定每一個呼叫棧的高度,生成的火焰圖,寬度越大就表示CPU耗時越多。


:如果svg圖出現unknown函式,使用如下命令

sudo perf record -e cpu-clock --call-graph dwarf -p pid

範例:perf record -e cpu-clock -g -p 29713 --call-graph dwarf 使用--call-graph dwarf 之後record生成的perf.data很大,大家生成的時候要時刻注意裝置剩餘空間是否足夠

實際測試範例

如圖一段程式碼
main -> do_main -> foo -> bar
其中 foo 函式和 bar 各有一個for迴圈,用來表示程式碼時間執行消耗的cpu

#include <iostream>
#include <vector>
#include <string>
#include <unistd.h>

using namespace std;
void bar(){
//   usleep(40*1000);
  /* do something here */
  for(int i=0;i< 4000;i++)
  {

  }
}

void foo(){
//   usleep(60*1000);
  for(int i=0;i< 5700;i++)
  {
      
  }      
  bar();
}

void do_main() {
  foo();
}

int main(int argc,char** argv){
    while(1)
    {
        do_main();
    }
}

執行程式碼之後進行 top實時檢視(因為我的裝置預設都是sudo許可權,所以以下命令都不用字首sudo)

ps -xu | grep target

perf top -e cpu-clock -p 29713

發現 foo 佔用 60%cpu時間,而bar佔用40%時間,和for迴圈展示的大致一樣

perf record -e cpu-clock -g -p 29713

ctrl + c停止記錄,發現當前目錄下儲存了檔案perf.data

使用report檢視
perf report -i perf.data

對比兩者差異,因為只是單純記錄兩次,程式碼沒有修改,所以沒有差異
perf diff perf.data perf.data

perf script -i perf.data &> perf.unfold

FlameGraph/stackcollapse-perf.pl test_data/perf.unfold &> test_data/perf.folded

拷貝到主機端進行轉換成火焰圖
FlameGraph/flamegraph.pl test_data/perf.folded > test_data/perf.svg

大家可以看到這個cpu佔用關係,火焰圖的頂層是個大平層,說明這段程式碼cpu單個函式foo和bar佔用率太高,這段程式碼優化空間很大。

結語

這就是我自己的一些perf使用分享。如果大家有更好的想法和需求,也歡迎大家加我好友交流分享哈。


作者:良知猶存,白天努力工作,晚上原創公號號主。公眾號內容除了技術還有些人生感悟,一個認真輸出內容的職場老司機,也是一個技術之外豐富生活的人,攝影、音樂 and 籃球。關注我,與我一起同行。

                              ‧‧‧‧‧‧‧‧‧‧‧‧‧‧‧‧  END  ‧‧‧‧‧‧‧‧‧‧‧‧‧‧‧‧

推薦閱讀

【1】jetson nano開發使用的基礎詳細分享

【2】Linux開發coredump檔案分析實戰分享

【3】CPU中的程式是怎麼執行起來的 必讀

【4】cartographer環境建立以及建圖測試

【5】設計模式之簡單工廠模式、工廠模式、抽象工廠模式的對比

本公眾號全部原創乾貨已整理成一個目錄,回覆[ 資源 ]即可獲得。

相關文章