gprof - linux program profiling tool

廢話

上星期五FM作業在同學的指導之下終於生出個形出來，帶著依然存在無數個謎樣bug的程式和NB回下營後，隨即躺平睡覺，儲備星期六要用來和作業決一死戰的HP和MP(?)

享受完寫出最快最好FM的喜悅後，我在夢裡一巴掌將自己給打醒......嗯…果然是夢沒錯= =……..，看看時間7點多，到客廳跟老姐領早餐就回到房間閉關了

改到快中午時，bug差不多都解完了，但是程式還是沒辦法在我理性斷線前跑完…..沒錯…..他就是沒辦法跑完~!@#$%^&，正當我隨手抓起桌上的筆筒準備和它拼命時，我突然想起之前IDEAL Lab的同學曾經介紹過一些tool，好像有一個linux下的tool叫gprof，正是用來profiling程式用的!!!

廢話好像太多了…….

介紹

gprof是一個可以用來檢視程式碼執行時間分佈的工具，藉由gprof產生的文件可以快速地得知程式的瓶頸到底在哪~

環境

作業系統: Linux (Windows的話可以看看cygwin有沒有下面提到的軟體@@a)
軟體: gcc(or g++), gprof

使用方法

1.編譯程式
使用gcc(or g++)編譯source code時加上-gp參數
[awkman@edalab ~]$ g++ -pg fm.cpp -o fm

2.執行程式
完整跑完編譯出來的程式後，會自動產生一個gmon.out檔案在當前工作目錄內

3.利用gprof產生適合地球生物閱讀的文件
gprof 程式名稱 gmon.out > 任意名稱
[awkman@edalab ~]$ grpof fm gmon.out > fm.gprof

4.檢視(請用習慣的editor開啟)上一步產生的分析檔(會有上下兩部分)
[awkman@edalab ~]$ vi fm.gprof 

profile 文件內容

上半部Example:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 33.34      0.02     0.02     7208     0.00     0.00  open
 16.67      0.03     0.01      244     0.04     0.12  offtime
 16.67      0.04     0.01        8     1.25     1.25  memccpy
 16.67      0.05     0.01        7     1.43     1.43  write
 16.67      0.06     0.01                             mcount
  0.00      0.06     0.00      236     0.00     0.00  tzset
  0.00      0.06     0.00      192     0.00     0.00  tolower
  0.00      0.06     0.00       47     0.00     0.00  strlen
  0.00      0.06     0.00       45     0.00     0.00  strchr
  0.00      0.06     0.00        1     0.00    50.00  main
  0.00      0.06     0.00        1     0.00     0.00  memcpy
  0.00      0.06     0.00        1     0.00    10.11  print
  0.00      0.06     0.00        1     0.00     0.00  profil
  0.00      0.06     0.00        1     0.00    50.00  report

欄位說明(以紅色行為例):
% time : memccpy()執行時間佔所有runtime的比例
cumulative seconds: 累計執行時間(table中所有在memccpy()上方function 的執行時間也會加入計總，如open()和offtime())
self seconds: 執行過程中,memccpy()的執行時間
calls: 執行過程中，memccpy()被呼叫的次數
self ms/call: 每次被呼叫時 平均花費了多少milliseconds執行memccpy() function
total ms/call: 每次被呼叫時，平均花費了多milliseconds執行memccpy()和memccpy()中呼叫的routine
name: function 名稱

下半部Example:

index % time    self  children    called     name
                                                 <spontaneous>
[1]    100.0    0.00    0.05                 start [1]
                0.00    0.05       1/1           main [2]
                0.00    0.00       1/2           on_exit [28]
                0.00    0.00       1/1           exit [59]
-----------------------------------------------
                0.00    0.05       1/1           start [1]
[2]    100.0    0.00    0.05       1         main [2]
                0.00    0.05       1/1           report [3]
-----------------------------------------------
                0.00    0.05       1/1           main [2]

[3]    100.0    0.00    0.05       1         report [3]

                0.00    0.03       8/8           timelocal [6]

                0.00    0.01       1/1           print [9]

                0.00    0.01       9/9           fgets [12]

                0.00    0.00      12/34          strncmp <cycle 1> [40]

                0.00    0.00       8/8           lookup [20]

                0.00    0.00       1/1           fopen [21]

                0.00    0.00       8/8           chewtime [24]

                0.00    0.00       8/16          skipspace [44]

-----------------------------------------------
[4]     59.8    0.01        0.02       8+472     <cycle 2 as a whole>    [4]
                0.01        0.02     244+260         offtime <cycle 2> [7]
                0.00        0.00     236+1           tzset <cycle 2> [26]
-----------------------------------------------

primary line(第一個欄位有出現[數字]的那幾行，這裡拿紅色行為例):
欄位說明
index: report()的index
% time: report()執行時間在所有runtime所佔的比例(包含report()中呼叫的subroutine的執行時間)
self: 同上一個table的self seconds
children: report()中呼叫的subroutine的執行時間
called: report()被呼叫的次數，如果是遞迴呼叫，會有兩個數字，第一個數字表示非遞迴呼叫的次數，第二個數字表示遞迴呼叫的次數(如藍色行)

caller line(dash line到primary line之間，此例中以綠色行為例):
欄位說明
self: 呼叫report()所花費的執行時間(不含report()中又去呼叫其它subroutine的執行時間)
children: report()呼叫其它subroutine的執行時間
self + children的總合等於report()被main()呼叫後的實際執行時間
called: 兩個數字，第一個代表report()被main()呼叫的次數，第二個數字代表被所有caller functions(程式可能也會有其它function呼叫report())呼叫的次數
name: function 名稱

subroutine line(灰色行):
欄位說明
self: 被report()呼叫後的執行時間(不含執行其它subroutine的時間)
children: 被report()呼叫後，執行其它subroutine的時間
self + children的時間等於此subroutine被report()呼叫後的執行時間
called: 兩個數字，第一個數字代表在report()是被main()呼叫的狀況之下，此function被report()呼叫的次數，第二個數字代表整個程式的執行過程中，被report()呼叫的次數(不限定report()必須被main() 呼叫)

分析範例

上面可能寫的有些模糊，以下拿個例子來說明一下

-----------------------------------------------
                0.00    0.05       1/1           main [2]
[3]    100.0    0.00    0.05       1         report [3]
                0.00    0.03       8/8           timelocal [6]
                0.00    0.01       1/1           print [9]
                0.00    0.01       9/9           fgets [12]
                0.00    0.00      12/34          strncmp  [40]
                0.00    0.00       8/8           lookup [20]
                0.00    0.00       1/1           fopen [21]
                0.00    0.00       8/8           chewtime [24]
                0.00    0.00       8/16          skipspace [44]
-----------------------------------------------

此block主要是顯示report()被main()呼叫後執行時間和次數的資訊

由caller line(綠色行)可以得知在整個程式執行過程中，report()總共只被main()呼叫過一次而已(因為called欄位的兩個數字都是1)，main()呼叫report()後，實際在report()中(不含執行其它subroutine的時間)執行的時間為0.00(self)，report()呼叫的其它subroutine的執行時間為0.05(children)

由primary line(紅色行)可以得知，report()只被main()呼叫一次(called)，在report()中(不含執行其它subroutine的時間)花費的執行時間為0.00，report()中呼叫其它subroutine的執行時間為0.05

由subroutine line(灰色行)可以得知, timelocal()在整個程式執行過程，只會被report()呼叫8次(因為called欄位兩個數字都是8)，timelocal()自己的執行時間(不含執行其它subroutine的時間)為0.00(self)，timelocal()中呼叫其它subroutine的執行時間為0.03(children)

Reference

GNU gprof profile範例來源
GNU/Linux Application Programming
感謝NCKU IDEAL Lab碩一同學暑假期間的教學