大貓咪的新玩具Uftrace：profiling 剖析程式的好工具，找出程式耗時的地方
目錄
最近不知道又從哪邊看到了 uftrace
覺得對於 profiling 很有用
於是就研究記錄了一下…
Uftrace
uftrace 是一個 C/C++, Python, Rust 的函數呼叫 tracer
可以負責紀錄 Function 呼叫的次數、時間
在 profiling 的時候非常有用，能針對問題的點做處理
把耗時的 function 改寫來減少時間，或是降低呼叫次數
也能知道程式 function 之間的呼叫關係
是 profiling 的一大利器
Install
使用之前一樣要先安裝
有兩種安裝方式，推間直接使用 Package Repository 安裝
如果想要嘗試自己編譯的話也可以 Build From Source
Package Repository
以下用 Ubuntu 舉例：
sudo apt update
sudo apt install uftraceBuild From Source
一樣在 Ubuntu 舉例，在開始之前要確認我們有安裝以下套件：
- Git
- Make
- gcc & g++
沒有的話記得先安裝：
sudo apt update
sudo apt install git make gcc g++clone 專案下來
git clone https://github.com/namhyung/uftrace接著進入資料夾
cd uftrace安裝編譯必要套件
sudo ./misc/install-deps.sh(可以根據自己需求決定要不要安裝 libunwind-dev)
sudo apt install libunwind-dev然後產生編譯文件
./configureuftrace detected system features: ... prefix: /usr/local ... libelf: [ on ] - more flexible ELF data handling ... libdw: [ on ] - DWARF debug info support ... libpython: [ on ] - python tracing & scripting support ... libluajit: [ on ] - luajit scripting support ... libncursesw: [ on ] - TUI support ... cxa_demangle: [ on ] - full demangler support with libstdc++ ... perf_event: [ on ] - perf (PMU) event support ... schedule: [ on ] - scheduler event support ... capstone: [ on ] - full dynamic tracing support ... libtraceevent: [ on ] - kernel tracing support ... libunwind: [ on ] - stacktrace support (optional for debugging)編譯程式和安裝
sudo make install
Usage
接下來開始分析紀錄 C/C++ 的程式吧
uftrace 一共可以分析以下四種類型的資料：
- User functions
- Library functions
- Kernel functions
- System events
其中如果要紀錄 User functions 的話
要記得編譯程式的時候要加上 -pg 或是 -finstrument-functions，兩者擇一即可
-pg會在 function 的一開始呼叫 mcount 來記錄相關資訊-finstrument-functions會在呼叫 function 的時候增加 hook 來記錄 function 的呼叫次數和時間
Basic
這篇主要是基本操作，講解如何使用
用以下的範例程式來舉例：
(舉例而已，就不寫 delete 了)
#include <cstdlib>
int* allocate2(int num){
int* arr = new int[num];
for(int i = 0; i < num; ++i){
arr[i] = i;
}
return arr;
}
int** allocate1(int num){
int** arr = new int*[num];
for(int i = 0; i < num; ++i){
arr[i] = allocate2(num);
}
return arr;
}
int main(int argc, char* argv[]){
if(argc < 2) exit(EXIT_FAILURE);
int num = atoi(argv[argc-1]);
allocate1(num);
}編譯的時候記得加上參數 -pg 或是 -finstrument-functions
g++ -pg test.cpp -o test接著使用 uftrace 的 record 功能紀錄相關資訊
uftrace record test執行完後，同目錄下會產生 uftrace.data 的檔案，這個就是紀錄檔
接著使用 replay 來看資訊
uftrace replay由於我沒有給參數，因此程式直接呼叫 exit 後關閉
# DURATION TID FUNCTION
[ 5916] | main() {
[ 5916] | exit() {
uftrace stopped tracing with remaining functions
================================================
task: 5916
[1] exit
[0] main給個參數，試試看 3：
uftrace record test 3
uftrace replay可以看到有呼叫了 allocate2 3 次的紀錄
# DURATION TID FUNCTION
[ 5923] | main() {
0.900 us [ 5923] | atoi();
[ 5923] | allocate1() {
3.400 us [ 5923] | operator new[]();
[ 5923] | allocate2() {
0.100 us [ 5923] | operator new[]();
0.400 us [ 5923] | } /* allocate2 */
[ 5923] | allocate2() {
0.400 us [ 5923] | operator new[]();
0.800 us [ 5923] | } /* allocate2 */
[ 5923] | allocate2() {
0.200 us [ 5923] | operator new[]();
0.600 us [ 5923] | } /* allocate2 */
6.100 us [ 5923] | } /* allocate1 */
8.800 us [ 5923] | } /* main */如果不想一直 record 又 replay 的話，可以直接使用 live
live 甚至可以不要加，預設就是使用 live
uftrace live test 3
# or
uftrace test 3接下來，如果我不想看到 library function 的紀錄
那就可以加上 --no-libcall
可以看到 operator new 都不見了
uftrace --no-libcall test 3
# DURATION TID FUNCTION
[ 5942] | main() {
[ 5942] | allocate1() {
0.500 us [ 5942] | allocate2();
0.200 us [ 5942] | allocate2();
0.100 us [ 5942] | allocate2();
5.400 us [ 5942] | } /* allocate1 */
7.700 us [ 5942] | } /* main */如果想看巢狀的 library function 紀錄
加上 --nest-libcall
uftrace --nest-libcall test 3
# DURATION TID FUNCTION
[ 5954] | main() {
17.300 us [ 5954] | atoi();
[ 5954] | allocate1() {
[ 5954] | operator new[]() {
[ 5954] | operator new() {
0.400 us [ 5954] | malloc();
2.300 us [ 5954] | } /* operator new */
5.400 us [ 5954] | } /* operator new[] */
[ 5954] | allocate2() {
[ 5954] | operator new[]() {
[ 5954] | operator new() {
0.100 us [ 5954] | malloc();
0.400 us [ 5954] | } /* operator new */
0.500 us [ 5954] | } /* operator new[] */
0.700 us [ 5954] | } /* allocate2 */
6.500 us [ 5954] | } /* allocate1 */
25.900 us [ 5954] | } /* main */除了 User functions 和 library functions 之外
接下來說說 kernel functions
我們可以加上參數 -k 或是 --kernel 來記錄 kernel 的呼叫資訊
但是 kernel 編譯的時候要加上 CONFIG_FUNCTION_GRAPH_TRACER=y
我沒有加，所以這裡就只給指令就好了
sudo uftrace -k test 1如果在紀錄中有出現 event 的紀錄，像是下面 linux:sched-out
可以加上 --no-event 來取消顯示
# DURATION TID FUNCTION
[ 14528] | main() {
127.033 us [ 14528] | fork();
[ 14528] | wait() {
[ 14528] | /* linux:sched-out */
[ 14540] | } /* fork */Filter
上篇的是基礎操作，這篇屬於進階操作
可以更客製化，去除或增加想要的資訊
-D DEPTH--depth=DEPTH：指定層數uftrace -D 3 test 3 # or uftrace --depth 3 test 3 # DURATION TID FUNCTION [ 1349] | main() { 1.100 us [ 1349] | atoi(); [ 1349] | allocate1() { 4.500 us [ 1349] | operator new[](); 0.600 us [ 1349] | allocate2(); 0.400 us [ 1349] | allocate2(); 0.300 us [ 1349] | allocate2(); 6.800 us [ 1349] | } /* allocate1 */ 12.801 us [ 1349] | } /* main */-F FUNC--filter=FUNC：只追蹤該 function 和其下的 children functionsuftrace -F allocate2 test 3 # or uftrace --filter allocate2 test 3 # DURATION TID FUNCTION [ 5978] | allocate2() { 0.100 us [ 5978] | operator new[](); 1.200 us [ 5978] | } /* allocate2 */ [ 5978] | allocate2() { 0.300 us [ 5978] | operator new[](); 0.600 us [ 5978] | } /* allocate2 */ [ 5978] | allocate2() { 0.100 us [ 5978] | operator new[](); 0.300 us [ 5978] | } /* allocate2 */-N FUNC--notrace=FUNC：不追蹤該 function 和其下的 children functionsuftrace -N allocate1 test 3 # or uftrace --notrace allocate1 test 3 # DURATION TID FUNCTION [ 5990] | main() { 1.000 us [ 5990] | atoi(); 20.001 us [ 5990] | } /* main */-C FUNC--caller-filter=FUNC：只追蹤呼叫該 function 的來源uftrace -C allocate1 test 3 # or uftrace --caller-filter allocate1 test 3 # DURATION TID FUNCTION [ 6002] | main() { 4.800 us [ 6002] | allocate1(); 7.500 us [ 6002] | } /* main */-H FUNC--hide=FUNC：只不追蹤該 functionuftrace -H allocate2 test 3 # or uftrace --hide allocate2 test 3 # DURATION TID FUNCTION [ 6014] | main() { 0.500 us [ 6014] | atoi(); [ 6014] | allocate1() { 2.300 us [ 6014] | operator new[](); 0.100 us [ 6014] | operator new[](); 0.200 us [ 6014] | operator new[](); 0.100 us [ 6014] | operator new[](); 3.900 us [ 6014] | } /* allocate1 */ 5.500 us [ 6014] | } /* main */-t TIME--time-filter=TIME：過濾花費時間低於設定的閥值的 functionuftrace -t 1us test 3 # or uftrace --time-filter 1us test 3 # DURATION TID FUNCTION [ 6027] | main() { [ 6027] | allocate1() { 3.500 us [ 6027] | operator new[](); 5.600 us [ 6027] | } /* allocate1 */ 8.400 us [ 6027] | } /* main */
Arguments
上面都是紀錄 function 之間呼叫的狀態
接下來要講講紀錄 function 傳進去的參數和回傳值
-A--argumentatoi 裡面就有傳入的參數 0x7ffc9be63805
uftrace -A atoi@arg1 test 3 # or uftrace --argument atoi@arg1 test 3 # DURATION TID FUNCTION [ 6078] | main() { 1.700 us [ 6078] | atoi(0x7ffc9be63805); [ 6078] | allocate1() { 2.999 us [ 6078] | operator new[](); [ 6078] | allocate2() { 0.100 us [ 6078] | operator new[](); 0.400 us [ 6078] | } /* allocate2 */ [ 6078] | allocate2() { 0.300 us [ 6078] | operator new[](); 0.600 us [ 6078] | } /* allocate2 */ [ 6078] | allocate2() { 0.100 us [ 6078] | operator new[](); 0.300 us [ 6078] | } /* allocate2 */ 4.998 us [ 6078] | } /* allocate1 */ 8.897 us [ 6078] | } /* main */我想你一定看不懂 0x7ffc9be63805，因為這個傳入的是地址
我們可以設定變數型態，來幫助我們更好地了解數據
uftrace -A atoi@arg1/s test 3 # or uftrace --argument atoi@arg1/s test 3 # DURATION TID FUNCTION [ 6096] | main() { 108.501 us [ 6096] | atoi("3"); [ 6096] | allocate1() { 2.400 us [ 6096] | operator new[](); 0.400 us [ 6096] | allocate2(); [ 6096] | allocate2() { 0.100 us [ 6096] | operator new[](); 0.400 us [ 6096] | } /* allocate2 */ [ 6096] | allocate2() { 0.100 us [ 6096] | operator new[](); 0.300 us [ 6096] | } /* allocate2 */ 4.500 us [ 6096] | } /* allocate1 */ 114.801 us [ 6096] | } /* main */-R--retval顯示 atoi 的回傳為 3，atoi() = 3
uftrace -R atoi@retval test 3 # or uftrace --retval atoi@retval test 3 # DURATION TID FUNCTION [ 6090] | main() { 0.500 us [ 6090] | atoi() = 3; [ 6090] | allocate1() { 6.600 us [ 6090] | operator new[](); [ 6090] | allocate2() { 0.100 us [ 6090] | operator new[](); 0.400 us [ 6090] | } /* allocate2 */ [ 6090] | allocate2() { 0.200 us [ 6090] | operator new[](); 0.300 us [ 6090] | } /* allocate2 */ [ 6090] | allocate2() { 0.100 us [ 6090] | operator new[](); 0.400 us [ 6090] | } /* allocate2 */ 8.600 us [ 6090] | } /* allocate1 */ 11.200 us [ 6090] | } /* main */
更詳細的使用方法可以參考官方的教學 slide
如果你又嫌麻煩的話，可以用 auto-args
可以自動記錄參數和回傳值
也會自動判別型態
但是編譯的時候要加上 -g
g++ -pg -g test.cpp -o test-a--auto-args顯示 atoi 的回傳為 3，atoi() = 3
uftrace -a test 3 # or uftrace --auto-args test 3 # DURATION TID FUNCTION [ 6126] | main(2, 0x7ffe36ad0298) { 113.901 us [ 6126] | atoi("3") = 3; [ 6126] | allocate1(3) { 2.300 us [ 6126] | operator new[](24) = 0x5592719742e0; [ 6126] | allocate2(3) { 0.200 us [ 6126] | operator new[](12) = 0x5592719d5460; 0.700 us [ 6126] | } = 0x5592719d5460; /* allocate2 */ [ 6126] | allocate2(3) { 0.100 us [ 6126] | operator new[](12) = 0x559271a4db40; 0.500 us [ 6126] | } = 0x559271a4db40; /* allocate2 */ [ 6126] | allocate2(3) { 0.100 us [ 6126] | operator new[](12) = 0x559271a4da00; 0.400 us [ 6126] | } = 0x559271a4da00; /* allocate2 */ 5.100 us [ 6126] | } = 0x5592719742e0; /* allocate1 */ 122.101 us [ 6126] | } = 0; /* main */
Report
前面介紹了很多用法，從基礎的到進階的用法都有
接著我們要介紹產生報告的用法了
在 record 之後，我們可以使用 report 來產生報告
g++ -pg test.cpp -o test
uftrace record test 3
uftrace report產生的結果會列出每個 function 被呼叫的次數以及所使用的時間
- Total time：包含自身以及 child functions 所花費的時間
- Self time：只包含自身 function 所花費的時間
Total time Self time Calls Function
========== ========== ========== ====================
54.400 us 1.400 us 1 main
31.900 us 1.000 us 1 allocate1
30.200 us 30.200 us 4 operator new[]
21.100 us 21.100 us 1 atoi
1.100 us 0.700 us 3 allocate2我們也可以加上參數 -s 來選擇排列順序
預設為 total
total：依照整個 function 所花費的全部時間由多到少排列self：依照自身 function 所花費的時間由多到少排列call：依照呼叫次數由多到少排列
// uftrace report -s self
Total time Self time Calls Function
========== ========== ========== ====================
30.200 us 30.200 us 4 operator new[]
21.100 us 21.100 us 1 atoi
54.400 us 1.400 us 1 main
31.900 us 1.000 us 1 allocate1
1.100 us 0.700 us 3 allocate2
// uftrace report -s call
Total time Self time Calls Function
========== ========== ========== ====================
30.200 us 30.200 us 4 operator new[]
1.100 us 0.700 us 3 allocate2
31.900 us 1.000 us 1 allocate1
21.100 us 21.100 us 1 atoi
54.400 us 1.400 us 1 mainCall Graph
有時候看程式的 call graph 也可以了解到程式裡的 function 之間的關係
所以接下來就來看看怎麼印出 call graph
g++ -pg -g test.cpp -o test
uftrace record test 3
uftrace graph從下方可以看到，allocate2 被 allocate1 呼叫了 3 次
# Function Call Graph for 'test' (session: ada5bbce53605976)
========== FUNCTION CALL GRAPH ==========
# TOTAL TIME FUNCTION
8.800 us : (1) test
8.800 us : (1) main
0.800 us : +-(1) atoi
: |
6.200 us : +-(1) allocate1
3.800 us : +-(1) operator new[]
: |
1.400 us : +-(3) allocate2
0.500 us : (3) operator new[]Info
如果有 reocrd 的話，可以使用 info 來顯示紀錄的時候系統和程式的資訊
g++ -pg test.cpp -o test
uftrace record test 3
uftrace info
# system information
# ==================
# program version : v0.14-95-g7db1 ( x86_64 dwarf python3 luajit tui perf sched dynamic kernel )
# recorded on : Thu Jan 4 08:43:43 2024
# cmdline : uftrace record test 3
# cpu info : Intel(R) Core(TM) i7-6700HQ CPU @ 2.60GHz
# number of cpus : 8 / 8 (online / possible)
# memory info : 3.7 / 7.7 GB (free / total)
# system load : 0.10 / 0.04 / 0.01 (1 / 5 / 15 min)
# kernel version : Linux 5.15.133.1-microsoft-standard-WSL2
# hostname : d5d3bb409e3f
# distro : "Ubuntu 22.04.3 LTS"
#
# process information
# ===================
# number of tasks : 1
# task list : 6196(test)
# exe image : /home/test
# build id : 077c727e65eda48408306d5431c98adbaa88d403
# pattern : regex
# exit status : exited with code: 0
# elapsed time : 0.021972084 sec
# cpu time : 0.022 / 0.000 sec (sys / user)
# context switch : 2 / 0 (voluntary / involuntary)
# max rss : 7704 KB
# page fault : 1 / 644 (major / minor)
# disk iops : 0 / 8 (read / write)Reference
如果你覺得這篇文章有用 可以考慮贊助飲料給大貓咪