使用gprof來對程式的效能分析總結
阿新 • • 發佈:2019-01-04
目錄
1. GPROF介紹 4
2. 使用步驟 4
3. 使用舉例 4
3.1 測試環境 4
3.2 測試程式碼 4
3.3 資料分析 5
3.3.1 flat profile模式 6
3.3.2 call graph模式 7
4. 連結庫中的函式 7
5. 使用侷限 8
6. 分析示例 12
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
1. gprof介紹
gprof是GNU profile工具,可以運行於linux、AIX、Sun等作業系統進行C、C++、Pascal、Fortran程式的效能分析,用於程式的效能優化以及程式瓶頸問題的查詢和解決。通過分
析應用程式執行時產生的“flat profile”,可以得到每個函式的呼叫次數,每個函式消耗的處理器時間,也可以得到函式的“呼叫關係圖”,包括函式呼叫的層次關係,每個函
數呼叫花費了多少時間。
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
2. 使用步驟
1) 用gcc、g++、xlC編譯程式時,使用-pg引數,如:g++ -pg -o test.exe test.cpp
編譯器會自動在目的碼中插入用於效能測試的程式碼片斷,這些程式碼在程式執行時採集並記錄函式的呼叫關係和呼叫次數,並記錄函式自身執行時間和被呼叫函式的執行時間。
2) 執行編譯後的可執行程式,如:./test.exe。該步驟執行程式的時間會稍慢於正常編譯的可執行程式的執行時間。程式執行結束後,會在程式所在路徑下生成一個預設文
件名為gmon.out的檔案,這個檔案就是記錄程式執行的效能、呼叫關係、呼叫次數等資訊的資料檔案。
3) 使用gprof命令來分析記錄程式執行資訊的gmon.out檔案,如:gprof test.exe gmon.out則可以在顯示器上看到函式呼叫相關的統計、分析資訊。上述資訊也可以採用
gprof test.exe gmon.out> gprofresult.txt 重定向到文字檔案以便於後續分析。
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
3. 使用舉例
3.1 測試環境
本文提供的樣例的測試環境如下:
? Linux server164 2.6.9-22.ELsmp #1 SMP Mon Sep 19 18:32:14 EDT 2005 i686 i686 i386 GNU/Linux
? gcc version 3.2.3 20030502 (Red Hat Linux 3.2.3-47.3)
? GNU gprof 2.15.92.0.2
3.2 測試程式碼
清單 1. 耗時測試應用程式示例
example1.c
#include
int a(void)
{
int i=0,g=0;
while(i++<100000)
{
g+=i;
}
return g;
}
int b(void)
{
int i=0,g=0;
while(i++<400000)
{
g +=i;
}
return g;
}
int main(int argc, char** argv)
{
int iterations;
if(argc != 2)
{
printf("Usage %s \n", argv[0]);
exit(-1);
}
else
iterations = atoi(argv[1]);
printf("No of iterations = %d\n", iterations);
while(iterations--)
{
a();
b();
}
}
這個應用程式包括兩個函式:a 和 b,它們通過執行不同次數的迴圈來消耗不同的CPU時間。main 函式中採用了一個迴圈來反覆呼叫這兩個函式。函式b中迴圈的次數是 a 函式的
4 倍,因此我們期望通過gprof的分析結果可以觀察到大概有 20% 的時間花在了 a 函式中,而 80% 的時間花在了 b 函式中。
3.3 資料分析
在 gcc 編譯命令中加上 –pg引數即可。編譯方法如下:
gcc example1.c -pg -o example1 -O2 -lc
在編譯好這個應用程式之後,按照普通方式執行這個程式:
./example1 50000
程式執行完之後,應該會看到在當前目錄中新建立了一個檔案 gmon.out。
3.3.1 flat profile模式
使用 gprof 命令分析gmon.out 檔案,如下所示:
gprof example1 gmon.out -p
-p引數標識“flat profile”模式,在分析結果中不顯示函式的呼叫關係,AIX平臺預設此引數有效。
輸出以下內容:
清單 2. flat profile 的結果
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ms/call ms/call name
80.38 203.27 203.27 50000 4.07 4.07 b
19.61 252.87 49.60 50000 0.99 0.99 a
0.00 252.88 0.01 main
上面結果中各個列的含義如下:
%time 函式以及衍生函式(函式內部再次呼叫的子函式)所佔的總執行時間的百分比
cumulative seconds 函式累計執行的時間
self seconds 函式執行佔用的時間
calls 函式的呼叫次數
self ms/call 每一次呼叫函式花費的時間microseconds,不包括衍生函式的執行時間
total ms/call 每一次呼叫函式花費的時間microseconds,包括衍生函式的執行時間
name 函式名稱
列的含義,在gprof的輸出結果中都有詳細的說明。
從輸出結果中可以看到,正如我們期望的一樣,b 函式所花費的時間大概是 a 函式所花費的時間的 4倍。
很多函式呼叫(例如 printf)在上面的輸出結果中都沒有出現。這是因為大部分函式都是在C連結庫(libc.so)中,而連結庫並沒有使用 -pg 進行編譯,因此就沒有對連結庫中
的函式收集排程資訊。
3.3.2 call graph模式
如果希望反映函式之間的呼叫關係,需要採用如下命令:
gprof example1 gmon.out –q
-q引數標識“call graph”模式,在分析結果中顯示函式的呼叫關係。
輸出以下內容:
清單 3. Call graph
granularity: each sample hit covers 4 byte(s) for 0.00% of 252.72 seconds
index % time self children called name
[1] 100.0 0.00 252.72 main [1]
201.41 0.00 50000/50000 b [2]
51.31 0.00 50000/50000 a [3]
-----------------------------------------------
201.41 0.00 50000/50000 main [1]
[2] 79.7 201.41 0.00 50000 b [2]
-----------------------------------------------
51.31 0.00 50000/50000 main [1]
[3] 20.3 51.31 0.00 50000 a [3]
-----------------------------------------------
上面結果中各個列的含義如下:
index 每個函式第一次出現時都分配了一個編號,根據編號可以方便的查詢函式的具體分析資料
%time 函式以及衍生函式(函式內部再次呼叫的子函式)所佔的總執行時間的百分比
self 函式的總執行時間
children 衍生函式執行的總時間
called 函式被呼叫的次數,不包括遞迴呼叫
name 函式名稱
在name列中,可以看出函式之間的呼叫關係,main函式呼叫a、b函式,b函式被main函式呼叫,a函式被main函式呼叫。通過函式名稱後面的數字來標識這個檔案中的函式,從而可
以快速定位函式的分析資料的位置,經過一層層的逐步深入的分析就得到各個函式的呼叫關係以及各個函式的效能資料。
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
4. 連結庫中的函式
正如在前面曾經介紹的,對於程式碼剖析的支援是由編譯器增加的,因此如果希望從連結庫(比如libc.a)中獲得剖析資訊,就需要使用 -pg 來編譯這些庫。很多作業系統預設提供
了已經啟用程式碼剖析支援而編譯的連結庫版本,例如:libc.a對應的採用-pg編譯的檔案為libc_p.a。對於沒有按照標準提供類似libc_p.a連結庫的作業系統版本來說,就需要安裝
已經編譯好的啟用程式碼剖析的連結庫版本或者自己下載連結庫的原始碼進行編譯。
使用“啟用程式碼剖析的連結庫版本”的應用場景,舉例如下:
gcc example1.c -g -pg -o example1 -O2 -lc_p
然後,像普通情況下一樣執行gprof對gmon.out進行分析,可以獲得 flat profile 或 call graph,而此時的分析結果會非常豐富,包含很多C的標準庫函式的呼叫資訊,例如:
printf、write等。
注意:上例的libc_p.a是靜態連結庫。gprof目前還不支援對動態連結庫中的函式進行效能分析。
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
5. 使用侷限
gprof的特點是它只能分析應用程式在執行過程中所消耗掉的CPU時間,只有當應用程式的函式消耗CPU的時候,gprof才能夠獲取函式的效能資料。如果應用程式在執行過程中暫時
掛起,並在系統核心喚醒應用程式後進一步執行,那麼在應用程式中間暫停的時間效能資料是無法統計的;而且在應用程式等待I/O操作返回的時間,效能資料也是無法統計的。
如果對清單 1 稍加修改,就可以清楚地看出這個問題:
清單 5. 為清單 1 新增sleep()函式呼叫
example2.c:
#include
int a(void)
{
sleep(1); /*呼叫系統函式進行sleep*/
return 0;
}
int b(void)
{
sleep(4); /*呼叫系統函式進行sleep*/
return 0;
}
int main(int argc, char** argv)
{
int iterations;
if(argc != 2)
{
printf("Usage %s \n", argv[0]);
exit(-1);
}
else
iterations = atoi(argv[1]);
printf("No of iterations = %d\n", iterations);
while(iterations--)
{
a();
b();
}
}
現在 a 函式和 b 函式不再處理繁忙的迴圈了,而是分別呼叫sleep()來掛起1秒和4秒。
使用“啟用程式碼剖析的連結庫版本”,編譯這個應用程式:
gcc example2.c -g -pg -o example2 -O2 -lc_p
並讓這個應用程式迴圈 30 次:
./example2 30
執行gprof example2 gmon.out –p所生成的結果如下:
清單 6. flat profile 顯示了系統呼叫的結果
Flat profile:
Each sample counts as 0.01 seconds.
no time accumulated
% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
0.00 0.00 0.00 21 0.00 0.00 _IO_file_overflow
0.00 0.00 0.00 13 0.00 0.00 strncmp
0.00 0.00 0.00 8 0.00 0.00 memset
0.00 0.00 0.00 8 0.00 0.00 sigprocmask
0.00 0.00 0.00 7 0.00 0.00 getenv
0.00 0.00 0.00 6 0.00 0.00 memcpy
0.00 0.00 0.00 5 0.00 0.00 _int_malloc
0.00 0.00 0.00 5 0.00 0.00 malloc
0.00 0.00 0.00 5 0.00 0.00 sigaction
0.00 0.00 0.00 5 0.00 0.00 strsep
0.00 0.00 0.00 4 0.00 0.00 nanosleep
0.00 0.00 0.00 4 0.00 0.00 sleep
0.00 0.00 0.00 4 0.00 0.00 strpbrk
0.00 0.00 0.00 3 0.00 0.00 _IO_new_file_xsputn
0.00 0.00 0.00 3 0.00 0.00 ____strtoul_l_internal
0.00 0.00 0.00 3 0.00 0.00 __cxa_atexit
0.00 0.00 0.00 3 0.00 0.00 __strtoul_internal
0.00 0.00 0.00 2 0.00 0.00 __errno_location
0.00 0.00 0.00 2 0.00 0.00 __find_specmb
0.00 0.00 0.00 2 0.00 0.00 a
0.00 0.00 0.00 2 0.00 0.00 b
0.00 0.00 0.00 2 0.00 0.00 mempcpy
0.00 0.00 0.00 1 0.00 0.00 _IO_default_xsputn
0.00 0.00 0.00 1 0.00 0.00 _IO_doallocbuf
0.00 0.00 0.00 1 0.00 0.00 _IO_file_doallocate
0.00 0.00 0.00 1 0.00 0.00 _IO_file_stat
0.00 0.00 0.00 1 0.00 0.00 _IO_file_write
0.00 0.00 0.00 1 0.00 0.00 _IO_setb
0.00 0.00 0.00 1 0.00 0.00 ____strtol_l_internal
0.00 0.00 0.00 1 0.00 0.00 ___fxstat64
0.00 0.00 0.00 1 0.00 0.00 __init_misc
0.00 0.00 0.00 1 0.00 0.00 __libc_csu_fini
0.00 0.00 0.00 1 0.00 0.00 __libc_csu_init
0.00 0.00 0.00 1 0.00 0.00 __libc_init_first
0.00 0.00 0.00 1 0.00 0.00 __libc_init_secure
0.00 0.00 0.00 1 0.00 0.00 __libc_setup_tls
0.00 0.00 0.00 1 0.00 0.00 __libc_start_main
0.00 0.00 0.00 1 0.00 0.00 __pthread_initialize_minimal
0.00 0.00 0.00 1 0.00 0.00 __setfpucw
0.00 0.00 0.00 1 0.00 0.00 __strtol_internal
0.00 0.00 0.00 1 0.00 0.00 _dl_aux_init
0.00 0.00 0.00 1 0.00 0.00 _dl_important_hwcaps
0.00 0.00 0.00 1 0.00 0.00 _dl_init_paths
0.00 0.00 0.00 1 0.00 0.00 _dl_non_dynamic_init
0.00 0.00 0.00 1 0.00 0.00 _itoa_word
0.00 0.00 0.00 1 0.00 0.00 _mcleanup
0.00 0.00 0.00 1 0.00 0.00 atexit
0.00 0.00 0.00 1 0.00 0.00 atoi
0.00 0.00 0.00 1 0.00 0.00 exit
0.00 0.00 0.00 1 0.00 0.00 fillin_rpath
0.00 0.00 0.00 1 0.00 0.00 fini
0.00 0.00 0.00 1 0.00 0.00 flockfile
0.00 0.00 0.00 1 0.00 0.00 funlockfile
0.00 0.00 0.00 1 0.00 0.00 main
0.00 0.00 0.00 1 0.00 0.00 mmap
0.00 0.00 0.00 1 0.00 0.00 printf
0.00 0.00 0.00 1 0.00 0.00 setitimer
0.00 0.00 0.00 1 0.00 0.00 strrchr
0.00 0.00 0.00 1 0.00 0.00 uname
0.00 0.00 0.00 1 0.00 0.00 vfprintf
0.00 0.00 0.00 1 0.00 0.00 write
對以上輸出結果進行分析可見,儘管 profile 已經記錄了每個函式被呼叫的確切次數,但是為這些函式記錄的時間(實際上是所有函式)都是 0.00。這是因為 sleep 函式實際上
是執行了一次對核心空間的呼叫,從而將應用程式的執行掛起了,然後有效地暫停執行,並等待核心再次將其喚醒。由於花在使用者空間執行的時間與花在核心中睡眠的時間相比非
常小,因此就被取整成零了。其原因是 gprof 以固定的週期對程式執行時間進行取樣測量,當程式掛起時,gprof就不會對程式進行取樣測量。
Gprof的特性使得有些程式非常難以進行優化,例如花費大部分時間睡眠等待核心喚醒的程式,或者由於外部因素(例如作業系統的 I/O 子系統過載)而執行得非常慢的程式。
通常,有一個很好的基準測試可以用來檢視 gprof 對於應用程式的優化能起多大作用,方法是在 time 命令下面執行應用程式。此命令會顯示一個應用程式執行完成需要多少時間
,並且在使用者空間和核心空間各花費了多少時間。
例如:time ./example2 30
輸出結果如下所示:
清單 7. time 命令的輸出結果
No of iterations = 30
real 2m30.295s
user 0m0.000s
sys 0m0.004s
我們可以看出應用程式整體執行150秒左右,但大部分時間在睡眠狀態,幾乎沒有多少時間被花費在執行使用者空間和核心空間的程式碼上,此時gprof的分析結果無法體現函式的實際
執行時間。
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
6. 分析示例
在新疆聯通進行綜合入庫程式上線前的測試過程中,測試人員發現程式執行效率低下。下面以整個調優的過程來舉例說明基於gprof的效能分析方法。
效能分析前的準備階段,效能分析資料的生成步驟如下:
1) 首先更改makefile檔案中的CC=g++ -g –pg 行,新增-pg引數。
2) 執行make clean刪除所有的目標檔案、可執行檔案
3) 重新編譯
4) 在命令列執行可執行程式,並通過控制檯傳送啟動命令
5) 程式退出後在fileindb執行程式目錄下生成gmon.out(不是控制檯目錄)
6) 執行gprof fileindb > gsmindb_mon_result.txt把分析結果重定向到gsmindb_mon_result.txt檔案
下面就是從gsmindb_mon_result.txt檔案中擷取的部分內容:
開啟gsmindb_mon_result.txt檔案後,可以看到127行:
[3] 37.2 0.00 41.90 1 .main [3]
0.00 41.88 1/1 .CMainManager::Run(int&) [4]
可見main函式中的CMainManager::Run執行時間(41.88)幾乎佔據了所有的執行時間(41.90),再查CMainManager::Run的分析資料在148行:
[4] 37.2 0.00 41.88 1 .CMainManager::Run(int&) [4]
0.00 41.81 1/1 .CBaseBillFile::DoEveryBill() [5]
可見CMainManager::Run 函式中CBaseBillFile::DoEveryBill執行佔了幾乎所有的時間,對於佔用時間比重很小的函式可以忽略。採用上面的方法一步一步向下查詢,最終確定289
行:
0.56 11.98 849922/849922 .CMobileFavour::CheckAllCondition(int,int) [11]
[12] 11.1 0.56 11.98 849922 .CGsmFavourCheck::CheckAllCondition() [12]
0.06 5.82 849922/849922 .CGsmFavourCheck::CheckCallKind() [14]
在CGsmFavourCheck::CheckAllCondition()所呼叫的函式中CGsmFavourCheck::CheckCallKind()佔用時間的比重過大,幾乎達到50%;CGsmFavourCheck::CheckAllCondition總共用
時11.98,而CGsmFavourCheck::CheckCallKind()函式就佔用了5.82,從而說明CGsmFavourCheck::CheckCallKind()函式需要作進一步優化,以提高整體的執行效率。
1. GPROF介紹 4
2. 使用步驟 4
3. 使用舉例 4
3.1 測試環境 4
3.2 測試程式碼 4
3.3 資料分析 5
3.3.1 flat profile模式 6
3.3.2 call graph模式 7
4. 連結庫中的函式 7
5. 使用侷限 8
6. 分析示例 12
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
1. gprof介紹
gprof是GNU profile工具,可以運行於linux、AIX、Sun等作業系統進行C、C++、Pascal、Fortran程式的效能分析,用於程式的效能優化以及程式瓶頸問題的查詢和解決。通過分
析應用程式執行時產生的“flat profile”,可以得到每個函式的呼叫次數,每個函式消耗的處理器時間,也可以得到函式的“呼叫關係圖”,包括函式呼叫的層次關係,每個函
數呼叫花費了多少時間。
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
2. 使用步驟
1) 用gcc、g++、xlC編譯程式時,使用-pg引數,如:g++ -pg -o test.exe test.cpp
編譯器會自動在目的碼中插入用於效能測試的程式碼片斷,這些程式碼在程式執行時採集並記錄函式的呼叫關係和呼叫次數,並記錄函式自身執行時間和被呼叫函式的執行時間。
2) 執行編譯後的可執行程式,如:./test.exe。該步驟執行程式的時間會稍慢於正常編譯的可執行程式的執行時間。程式執行結束後,會在程式所在路徑下生成一個預設文
件名為gmon.out的檔案,這個檔案就是記錄程式執行的效能、呼叫關係、呼叫次數等資訊的資料檔案。
3) 使用gprof命令來分析記錄程式執行資訊的gmon.out檔案,如:gprof test.exe gmon.out則可以在顯示器上看到函式呼叫相關的統計、分析資訊。上述資訊也可以採用
gprof test.exe gmon.out> gprofresult.txt
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
3. 使用舉例
3.1 測試環境
本文提供的樣例的測試環境如下:
? Linux server164 2.6.9-22.ELsmp #1 SMP Mon Sep 19 18:32:14 EDT 2005 i686 i686 i386 GNU/Linux
? gcc version 3.2.3 20030502 (Red Hat Linux 3.2.3-47.3)
? GNU gprof 2.15.92.0.2
3.2 測試程式碼
清單 1. 耗時測試應用程式示例
example1.c
#include
int a(void)
{
int i=0,g=0;
while(i++<100000)
{
g+=i;
}
return g;
}
int b(void)
{
int i=0,g=0;
while(i++<400000)
{
g +=i;
}
return g;
}
int main(int argc, char** argv)
{
int iterations;
if(argc != 2)
{
printf("Usage %s \n", argv[0]);
exit(-1);
}
else
iterations = atoi(argv[1]);
printf("No of iterations = %d\n", iterations);
while(iterations--)
{
a();
b();
}
}
這個應用程式包括兩個函式:a 和 b,它們通過執行不同次數的迴圈來消耗不同的CPU時間。main 函式中採用了一個迴圈來反覆呼叫這兩個函式。函式b中迴圈的次數是 a 函式的
4 倍,因此我們期望通過gprof的分析結果可以觀察到大概有 20% 的時間花在了 a 函式中,而 80% 的時間花在了 b 函式中。
3.3 資料分析
在 gcc 編譯命令中加上 –pg引數即可。編譯方法如下:
gcc example1.c -pg -o example1 -O2 -lc
在編譯好這個應用程式之後,按照普通方式執行這個程式:
./example1 50000
程式執行完之後,應該會看到在當前目錄中新建立了一個檔案 gmon.out。
3.3.1 flat profile模式
使用 gprof 命令分析gmon.out 檔案,如下所示:
gprof example1 gmon.out -p
-p引數標識“flat profile”模式,在分析結果中不顯示函式的呼叫關係,AIX平臺預設此引數有效。
輸出以下內容:
清單 2. flat profile 的結果
Flat profile:
Each sample counts as 0.01 seconds.
% cumulative self self total
time seconds seconds calls ms/call ms/call name
80.38 203.27 203.27 50000 4.07 4.07 b
19.61 252.87 49.60 50000 0.99 0.99 a
0.00 252.88 0.01 main
上面結果中各個列的含義如下:
%time 函式以及衍生函式(函式內部再次呼叫的子函式)所佔的總執行時間的百分比
cumulative seconds 函式累計執行的時間
self seconds 函式執行佔用的時間
calls 函式的呼叫次數
self ms/call 每一次呼叫函式花費的時間microseconds,不包括衍生函式的執行時間
total ms/call 每一次呼叫函式花費的時間microseconds,包括衍生函式的執行時間
name 函式名稱
列的含義,在gprof的輸出結果中都有詳細的說明。
從輸出結果中可以看到,正如我們期望的一樣,b 函式所花費的時間大概是 a 函式所花費的時間的 4倍。
很多函式呼叫(例如 printf)在上面的輸出結果中都沒有出現。這是因為大部分函式都是在C連結庫(libc.so)中,而連結庫並沒有使用 -pg 進行編譯,因此就沒有對連結庫中
的函式收集排程資訊。
3.3.2 call graph模式
如果希望反映函式之間的呼叫關係,需要採用如下命令:
gprof example1 gmon.out –q
-q引數標識“call graph”模式,在分析結果中顯示函式的呼叫關係。
輸出以下內容:
清單 3. Call graph
granularity: each sample hit covers 4 byte(s) for 0.00% of 252.72 seconds
index % time self children called name
[1] 100.0 0.00 252.72 main [1]
201.41 0.00 50000/50000 b [2]
51.31 0.00 50000/50000 a [3]
-----------------------------------------------
201.41 0.00 50000/50000 main [1]
[2] 79.7 201.41 0.00 50000 b [2]
-----------------------------------------------
51.31 0.00 50000/50000 main [1]
[3] 20.3 51.31 0.00 50000 a [3]
-----------------------------------------------
上面結果中各個列的含義如下:
index 每個函式第一次出現時都分配了一個編號,根據編號可以方便的查詢函式的具體分析資料
%time 函式以及衍生函式(函式內部再次呼叫的子函式)所佔的總執行時間的百分比
self 函式的總執行時間
children 衍生函式執行的總時間
called 函式被呼叫的次數,不包括遞迴呼叫
name 函式名稱
在name列中,可以看出函式之間的呼叫關係,main函式呼叫a、b函式,b函式被main函式呼叫,a函式被main函式呼叫。通過函式名稱後面的數字來標識這個檔案中的函式,從而可
以快速定位函式的分析資料的位置,經過一層層的逐步深入的分析就得到各個函式的呼叫關係以及各個函式的效能資料。
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
4. 連結庫中的函式
正如在前面曾經介紹的,對於程式碼剖析的支援是由編譯器增加的,因此如果希望從連結庫(比如libc.a)中獲得剖析資訊,就需要使用 -pg 來編譯這些庫。很多作業系統預設提供
了已經啟用程式碼剖析支援而編譯的連結庫版本,例如:libc.a對應的採用-pg編譯的檔案為libc_p.a。對於沒有按照標準提供類似libc_p.a連結庫的作業系統版本來說,就需要安裝
已經編譯好的啟用程式碼剖析的連結庫版本或者自己下載連結庫的原始碼進行編譯。
使用“啟用程式碼剖析的連結庫版本”的應用場景,舉例如下:
gcc example1.c -g -pg -o example1 -O2 -lc_p
然後,像普通情況下一樣執行gprof對gmon.out進行分析,可以獲得 flat profile 或 call graph,而此時的分析結果會非常豐富,包含很多C的標準庫函式的呼叫資訊,例如:
printf、write等。
注意:上例的libc_p.a是靜態連結庫。gprof目前還不支援對動態連結庫中的函式進行效能分析。
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
5. 使用侷限
gprof的特點是它只能分析應用程式在執行過程中所消耗掉的CPU時間,只有當應用程式的函式消耗CPU的時候,gprof才能夠獲取函式的效能資料。如果應用程式在執行過程中暫時
掛起,並在系統核心喚醒應用程式後進一步執行,那麼在應用程式中間暫停的時間效能資料是無法統計的;而且在應用程式等待I/O操作返回的時間,效能資料也是無法統計的。
如果對清單 1 稍加修改,就可以清楚地看出這個問題:
清單 5. 為清單 1 新增sleep()函式呼叫
example2.c:
#include
int a(void)
{
sleep(1); /*呼叫系統函式進行sleep*/
return 0;
}
int b(void)
{
sleep(4); /*呼叫系統函式進行sleep*/
return 0;
}
int main(int argc, char** argv)
{
int iterations;
if(argc != 2)
{
printf("Usage %s \n", argv[0]);
exit(-1);
}
else
iterations = atoi(argv[1]);
printf("No of iterations = %d\n", iterations);
while(iterations--)
{
a();
b();
}
}
現在 a 函式和 b 函式不再處理繁忙的迴圈了,而是分別呼叫sleep()來掛起1秒和4秒。
使用“啟用程式碼剖析的連結庫版本”,編譯這個應用程式:
gcc example2.c -g -pg -o example2 -O2 -lc_p
並讓這個應用程式迴圈 30 次:
./example2 30
執行gprof example2 gmon.out –p所生成的結果如下:
清單 6. flat profile 顯示了系統呼叫的結果
Flat profile:
Each sample counts as 0.01 seconds.
no time accumulated
% cumulative self self total
time seconds seconds calls Ts/call Ts/call name
0.00 0.00 0.00 21 0.00 0.00 _IO_file_overflow
0.00 0.00 0.00 13 0.00 0.00 strncmp
0.00 0.00 0.00 8 0.00 0.00 memset
0.00 0.00 0.00 8 0.00 0.00 sigprocmask
0.00 0.00 0.00 7 0.00 0.00 getenv
0.00 0.00 0.00 6 0.00 0.00 memcpy
0.00 0.00 0.00 5 0.00 0.00 _int_malloc
0.00 0.00 0.00 5 0.00 0.00 malloc
0.00 0.00 0.00 5 0.00 0.00 sigaction
0.00 0.00 0.00 5 0.00 0.00 strsep
0.00 0.00 0.00 4 0.00 0.00 nanosleep
0.00 0.00 0.00 4 0.00 0.00 sleep
0.00 0.00 0.00 4 0.00 0.00 strpbrk
0.00 0.00 0.00 3 0.00 0.00 _IO_new_file_xsputn
0.00 0.00 0.00 3 0.00 0.00 ____strtoul_l_internal
0.00 0.00 0.00 3 0.00 0.00 __cxa_atexit
0.00 0.00 0.00 3 0.00 0.00 __strtoul_internal
0.00 0.00 0.00 2 0.00 0.00 __errno_location
0.00 0.00 0.00 2 0.00 0.00 __find_specmb
0.00 0.00 0.00 2 0.00 0.00 a
0.00 0.00 0.00 2 0.00 0.00 b
0.00 0.00 0.00 2 0.00 0.00 mempcpy
0.00 0.00 0.00 1 0.00 0.00 _IO_default_xsputn
0.00 0.00 0.00 1 0.00 0.00 _IO_doallocbuf
0.00 0.00 0.00 1 0.00 0.00 _IO_file_doallocate
0.00 0.00 0.00 1 0.00 0.00 _IO_file_stat
0.00 0.00 0.00 1 0.00 0.00 _IO_file_write
0.00 0.00 0.00 1 0.00 0.00 _IO_setb
0.00 0.00 0.00 1 0.00 0.00 ____strtol_l_internal
0.00 0.00 0.00 1 0.00 0.00 ___fxstat64
0.00 0.00 0.00 1 0.00 0.00 __init_misc
0.00 0.00 0.00 1 0.00 0.00 __libc_csu_fini
0.00 0.00 0.00 1 0.00 0.00 __libc_csu_init
0.00 0.00 0.00 1 0.00 0.00 __libc_init_first
0.00 0.00 0.00 1 0.00 0.00 __libc_init_secure
0.00 0.00 0.00 1 0.00 0.00 __libc_setup_tls
0.00 0.00 0.00 1 0.00 0.00 __libc_start_main
0.00 0.00 0.00 1 0.00 0.00 __pthread_initialize_minimal
0.00 0.00 0.00 1 0.00 0.00 __setfpucw
0.00 0.00 0.00 1 0.00 0.00 __strtol_internal
0.00 0.00 0.00 1 0.00 0.00 _dl_aux_init
0.00 0.00 0.00 1 0.00 0.00 _dl_important_hwcaps
0.00 0.00 0.00 1 0.00 0.00 _dl_init_paths
0.00 0.00 0.00 1 0.00 0.00 _dl_non_dynamic_init
0.00 0.00 0.00 1 0.00 0.00 _itoa_word
0.00 0.00 0.00 1 0.00 0.00 _mcleanup
0.00 0.00 0.00 1 0.00 0.00 atexit
0.00 0.00 0.00 1 0.00 0.00 atoi
0.00 0.00 0.00 1 0.00 0.00 exit
0.00 0.00 0.00 1 0.00 0.00 fillin_rpath
0.00 0.00 0.00 1 0.00 0.00 fini
0.00 0.00 0.00 1 0.00 0.00 flockfile
0.00 0.00 0.00 1 0.00 0.00 funlockfile
0.00 0.00 0.00 1 0.00 0.00 main
0.00 0.00 0.00 1 0.00 0.00 mmap
0.00 0.00 0.00 1 0.00 0.00 printf
0.00 0.00 0.00 1 0.00 0.00 setitimer
0.00 0.00 0.00 1 0.00 0.00 strrchr
0.00 0.00 0.00 1 0.00 0.00 uname
0.00 0.00 0.00 1 0.00 0.00 vfprintf
0.00 0.00 0.00 1 0.00 0.00 write
對以上輸出結果進行分析可見,儘管 profile 已經記錄了每個函式被呼叫的確切次數,但是為這些函式記錄的時間(實際上是所有函式)都是 0.00。這是因為 sleep 函式實際上
是執行了一次對核心空間的呼叫,從而將應用程式的執行掛起了,然後有效地暫停執行,並等待核心再次將其喚醒。由於花在使用者空間執行的時間與花在核心中睡眠的時間相比非
常小,因此就被取整成零了。其原因是 gprof 以固定的週期對程式執行時間進行取樣測量,當程式掛起時,gprof就不會對程式進行取樣測量。
Gprof的特性使得有些程式非常難以進行優化,例如花費大部分時間睡眠等待核心喚醒的程式,或者由於外部因素(例如作業系統的 I/O 子系統過載)而執行得非常慢的程式。
通常,有一個很好的基準測試可以用來檢視 gprof 對於應用程式的優化能起多大作用,方法是在 time 命令下面執行應用程式。此命令會顯示一個應用程式執行完成需要多少時間
,並且在使用者空間和核心空間各花費了多少時間。
例如:time ./example2 30
輸出結果如下所示:
清單 7. time 命令的輸出結果
No of iterations = 30
real 2m30.295s
user 0m0.000s
sys 0m0.004s
我們可以看出應用程式整體執行150秒左右,但大部分時間在睡眠狀態,幾乎沒有多少時間被花費在執行使用者空間和核心空間的程式碼上,此時gprof的分析結果無法體現函式的實際
執行時間。
%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%
6. 分析示例
在新疆聯通進行綜合入庫程式上線前的測試過程中,測試人員發現程式執行效率低下。下面以整個調優的過程來舉例說明基於gprof的效能分析方法。
效能分析前的準備階段,效能分析資料的生成步驟如下:
1) 首先更改makefile檔案中的CC=g++ -g –pg 行,新增-pg引數。
2) 執行make clean刪除所有的目標檔案、可執行檔案
3) 重新編譯
4) 在命令列執行可執行程式,並通過控制檯傳送啟動命令
5) 程式退出後在fileindb執行程式目錄下生成gmon.out(不是控制檯目錄)
6) 執行gprof fileindb > gsmindb_mon_result.txt把分析結果重定向到gsmindb_mon_result.txt檔案
下面就是從gsmindb_mon_result.txt檔案中擷取的部分內容:
開啟gsmindb_mon_result.txt檔案後,可以看到127行:
[3] 37.2 0.00 41.90 1 .main [3]
0.00 41.88 1/1 .CMainManager::Run(int&) [4]
可見main函式中的CMainManager::Run執行時間(41.88)幾乎佔據了所有的執行時間(41.90),再查CMainManager::Run的分析資料在148行:
[4] 37.2 0.00 41.88 1 .CMainManager::Run(int&) [4]
0.00 41.81 1/1 .CBaseBillFile::DoEveryBill() [5]
可見CMainManager::Run 函式中CBaseBillFile::DoEveryBill執行佔了幾乎所有的時間,對於佔用時間比重很小的函式可以忽略。採用上面的方法一步一步向下查詢,最終確定289
行:
0.56 11.98 849922/849922 .CMobileFavour::CheckAllCondition(int,int) [11]
[12] 11.1 0.56 11.98 849922 .CGsmFavourCheck::CheckAllCondition() [12]
0.06 5.82 849922/849922 .CGsmFavourCheck::CheckCallKind() [14]
在CGsmFavourCheck::CheckAllCondition()所呼叫的函式中CGsmFavourCheck::CheckCallKind()佔用時間的比重過大,幾乎達到50%;CGsmFavourCheck::CheckAllCondition總共用
時11.98,而CGsmFavourCheck::CheckCallKind()函式就佔用了5.82,從而說明CGsmFavourCheck::CheckCallKind()函式需要作進一步優化,以提高整體的執行效率。