如果你只是需要快速使用工具來進行問題排查，包括但不限于函數(shù)調(diào)用棧跟蹤、函數(shù)調(diào)用子函數(shù)流程、函數(shù)返回結(jié)果，那么推薦你直接使用 BCC trace[1] 或 Brendan Gregg[2] 封裝的 perf-tools[3] 工具即可，本文嘗試從手工操作 Ftrace 跟蹤工具的方式展示在底層是如何通過 tracefs 實現(xiàn)這些能力的。如果你對某個跟蹤主題感興趣，建議直接跳轉(zhuǎn)到相關(guān)的主題查看。

快速說明：

kprobe 為內(nèi)核中提供的動態(tài)跟蹤機制，/proc/kallsym 中的函數(shù)幾乎都可以用于跟蹤，但是內(nèi)核函數(shù)可能隨著版本演進而發(fā)生變化，為非穩(wěn)定的跟蹤機制，數(shù)量比較多。

uprobe 為用戶空間提供的動態(tài)機制；

tracepoint 是內(nèi)核提供的靜態(tài)跟蹤點，為穩(wěn)定的跟蹤點，需要研發(fā)人員代碼編寫，數(shù)量有限；

usdt 為用戶空間提供的靜態(tài)跟蹤點 【本次暫不涉及】

Ftrace 是 Linux 官方提供的跟蹤工具，在 Linux 2.6.27 版本中引入。Ftrace 可在不引入任何前端工具的情況下使用，讓其可以適合在任何系統(tǒng)環(huán)境中使用。

Ftrace 可用來快速排查以下相關(guān)問題：

特定內(nèi)核函數(shù)調(diào)用的頻次 （function）

內(nèi)核函數(shù)在被調(diào)用的過程中流程（調(diào)用棧） （function + stack）

內(nèi)核函數(shù)調(diào)用的子函數(shù)流程（子調(diào)用棧）（function graph）

由于搶占導(dǎo)致的高延時路徑等

Ftrace 跟蹤工具由性能分析器（profiler）和跟蹤器（tracer）兩部分組成：

性能分析器，用來提供統(tǒng)計和直方圖數(shù)據(jù)（需要 CONFIG_ FUNCTION_PROFILER=y）

函數(shù)性能分析

直方圖

跟蹤器，提供跟蹤事件的詳情：

函數(shù)跟蹤（function）

跟蹤點（tracepoint）

kprobe

uprobe

函數(shù)調(diào)用關(guān)系（function_graph）

hwlat 等

除了操作原始的文件接口外，也有一些基于 Ftrace 的前端工具，比如 perf-tools 和 trace-cmd （界面 KernelShark）等。整體跟蹤及前端工具架構(gòu)圖如下：

圖片來自于 《Systems Performance Enterprise and the Cloud 2nd Edition》 14.1 P706

Ftrace 的使用的接口為 tracefs 文件系統(tǒng)，需要保證該文件系統(tǒng)進行加載：

$sysctl-qkernel.ftrace_enabled=1
$mount-ttracefstracefs/sys/kernel/tracing

$mount-tdebugfs,tracefs
tracefson/sys/kernel/tracingtypetracefs(rw,nosuid,nodev,noexec,relatime)
debugfson/sys/kernel/debugtypedebugfs(rw,nosuid,nodev,noexec,relatime)
tracefson/sys/kernel/debug/tracingtypetracefs(rw,nosuid,nodev,noexec,relatime)

$ls-F/sys/kernel/debug/tracing#完整目錄如下圖

tracing 目錄下核心文件介紹如下表格，當前可僅關(guān)注黑體加粗的項，其他項可在需要的時候再進行回顧：

perf_tools 包含了一個復(fù)位所有 ftrace 選型的工具腳本，在跟蹤不符合預(yù)期的情況下，建議先使用 reset-ftrace[4] 進行復(fù)位，然后再進行測試。

1. 內(nèi)核函數(shù)調(diào)用跟蹤

基于 Ftrace 的內(nèi)核函數(shù)調(diào)用跟蹤整體架構(gòu)如下所示：

圖片來自于 《Systems Performance Enterprise and the Cloud 2nd Edition》 14.4 P713

這里我們嘗試對于內(nèi)核中的系統(tǒng)調(diào)用函數(shù) __arm64_sys_openat 進行跟蹤（前面兩個下劃線），需要注意的是 __arm64_sys_openat 是在 arm64 結(jié)構(gòu)體系下 sys_openat 系統(tǒng)調(diào)用的包裝，如果在 x86_64 架構(gòu)下則為 __x64_sys_openat() ，由于我們本地的電腦是 M1 芯片，所以演示的樣例以 arm64 為主。

在不同的體系結(jié)構(gòu)下，可以在 /proc/kallsym 文件中搜索確認。

后續(xù)的目錄，如無特殊說明，都默認位于 /sys/kernel/debug/tracing/ 根目錄。

#使用function跟蹤器，并將其設(shè)置到current_tracer
$sudoechofunction>current_tracer

#將跟蹤函數(shù)__arm64_sys_openat設(shè)置到set_ftrace_filter文件中
$sudoecho__arm64_sys_openat>set_ftrace_filter

#開啟全局的跟蹤使能
$sudoecho1>tracing_on

#運行l(wèi)s命令觸發(fā)sys_openat系統(tǒng)調(diào)用，新的內(nèi)核版本中直接調(diào)用sys_openat
$ls-hl

#關(guān)閉
$sudoecho0>tracing_on
$sudoechonop>current_tracer

#需要主要這里的echo后面有一個空格，即“echo+空格>"
$sudoecho>set_ftrace_filter

#通過cattrace文件進行查看
$sudocattrace
#tracer:function
#
#entries-in-buffer/entries-written:224/224#P:4
#
#_-----=>irqs-off
#/_----=>need-resched
#|/_---=>hardirq/softirq
#||/_--=>preempt-depth
#|||/delay
#TASK-PIDCPU#||||TIMESTAMPFUNCTION
#|||||||||
sudo-15099[002]....29469.444400:__arm64_sys_openat<-invoke_syscall
????????????sudo-15099???[002]?....?29469.444594:?__arm64_sys_openat?<-invoke_syscall

我們可以看到上述的結(jié)果表明了函數(shù)調(diào)用的任務(wù)名稱、PID、CPU、標記位、時間戳及函數(shù)名字。

在 perf_tools[5] 工具集中的前端封裝工具為 functrace[6] ，需要注意的是該工具默認不會設(shè)置 tracing_on 為 1， 需要在啟動前進行設(shè)置，即 ”echo 1 > tracing_on“。

perf_tools[7] 工具集中 kprobe[8] 也可以實現(xiàn)類似的效果，底層基于 kprobe 機制實現(xiàn)，ftrace 機制中的 kprobe 在后續(xù)章節(jié)會詳細介紹。

2. 函數(shù)被調(diào)用流程（棧）

在第 1 部分我們獲得了內(nèi)核函數(shù)的調(diào)用，但是有些場景我們更可能希望獲取調(diào)用該內(nèi)核函數(shù)的流程（即該函數(shù)是在何處被調(diào)用），這需要通過設(shè)置 options/func_stack_trace 選項實現(xiàn)。

$sudoechofunction>current_tracer
$sudoecho__arm64_sys_openat>set_ftrace_filter
$sudoecho1>options/func_stack_trace#設(shè)置調(diào)用棧選項
$sudoecho1>tracing_on

$ls-hl

$sudoecho0>tracing_on

$sudocattrace
#tracer:function
#
#entries-in-buffer/entries-written:292/448#P:4
#
#_-----=>irqs-off
#/_----=>need-resched
#|/_---=>hardirq/softirq
#||/_--=>preempt-depth
#|||/delay
#TASK-PIDCPU#||||TIMESTAMPFUNCTION
#|||||||||
sudo-15134[000]....29626.670430:__arm64_sys_openat<-invoke_syscall
????????????sudo-15134???[000]?....?29626.670431:?
=>__arm64_sys_openat
=>invoke_syscall
=>el0_svc_common.constprop.0
=>do_el0_svc
=>el0_svc
=>el0_sync_handler
=>el0_sync

#關(guān)閉
$sudoechonop>current_tracer
$sudoecho>set_ftrace_filter
$sudoecho0>options/func_stack_trace

通過上述跟蹤記錄，我們可以發(fā)現(xiàn)記錄同時展示了函數(shù)調(diào)用的記錄和被調(diào)用的函數(shù)流程，__arm64_sys_openat 的被調(diào)用棧如下：

=>__arm64_sys_openat
=>invoke_syscall
=>el0_svc_common.constprop.0
=>do_el0_svc
=>el0_svc
=>el0_sync_handler
=>el0_sync

perf_tools[9] 工具集中 kprobe[10] 通過添加 ”-s“ 參數(shù)實現(xiàn)同樣的功能，運行的命令如下：

$./kprobe-s'p:__arm64_sys_openat'

3. 函數(shù)調(diào)用子流程跟蹤（棧）

如果想要分析內(nèi)核函數(shù)調(diào)用的子流程（即本函數(shù)調(diào)用了哪些子函數(shù)，處理的流程如何），這時需要用到 function_graph 跟蹤器，從字面意思就可看出這是函數(shù)調(diào)用關(guān)系跟蹤。

基于 __arm64_sys_openat 子流程調(diào)用關(guān)系的跟蹤的完整設(shè)置過程如下：

#將當前current_tracer設(shè)置為function_graph
$sudoechofunction_graph>current_tracer
$sudoecho__arm64_sys_openat>set_graph_function

#設(shè)置跟蹤子函數(shù)的最大層級數(shù)
$sudoecho3>max_graph_depth#設(shè)置最大層級
$sudoecho1>tracing_on

$ls-hl

$sudoecho0>tracing_on
#$echonop>set_graph_function
$sudocattrace
#tracer:function_graph
#
#CPUDURATIONFUNCTIONCALLS
#|||||||
1)|__arm64_sys_openat(){
1)|do_sys_openat2(){
1)0.875us|getname();
1)0.125us|get_unused_fd_flags();
1)2.375us|do_filp_open();
1)0.084us|put_unused_fd();
1)0.125us|putname();
1)4.083us|}
1)4.250us|}

在本樣例中 __arm64_sys_openat 函數(shù)的調(diào)用子流程僅包括 do_sys_openat2() 子函數(shù)，而 do_sys_openat2() 函數(shù)又調(diào)用了 getname()/get_unused_fd_flags() 等子函數(shù)。

這種完整的子函數(shù)調(diào)用關(guān)系，對于我們學(xué)習(xí)內(nèi)核源碼和分析線上的問題都提供了便利，排查問題時則可以順藤摸瓜逐步縮小需要分析的范圍。

在 perf_tools[11] 工具集的前端工具為 funcgraph[12] ，使用 funcgraph 啟動命令如下所示：

$./funcgraph-m3__arm64_sys_openat

如果函數(shù)調(diào)用棧比較多，直接查看跟蹤記錄則非常不方便，基于此社區(qū)補丁 [PATCH] ftrace: Add vim script to enable folding for function_graph traces[13] 提供了一個基于 vim 的配置，可通過樹狀關(guān)系來折疊和展開函數(shù)調(diào)用的最終記錄，vim 設(shè)置完整如下：

"Enablefoldingforftracefunction_graphtraces.
"
"Touse,:sourcethisfilewhileviewingafunction_graphtrace,orusevim's
"-Soptiontoloadfromthecommand-linetogetherwithatrace.Youcanthen
"usetheusualvimfoldcommands,suchas"za",toopenandclosenested
"functions.Whileclosed,afoldwillshowthetotaltimetakenforacall,
"aswouldnormallyappearonthelinewiththeclosingbrace.Folded
"functionswillnotincludefinish_task_switch(),sofoldingshouldremain
"relativelysaneeventhroughacontextswitch.
"
"Notethatthiswillalmostcertainlyonlyworkwellwitha
"single-CPUtrace(e.g.trace-cmdreport--cpu1).

function!FunctionGraphFoldExpr(lnum)
letline=getline(a:lnum)
ifline[-1:]=='{'
ifline=~'finish_task_switch(){$'
return'>1'
endif
return'a1'
elseifline[-1:]=='}'
return's1'
else
return'='
endif
endfunction

function!FunctionGraphFoldText()
lets=split(getline(v:foldstart),'|',1)
ifgetline(v:foldend+1)=~'finish_task_switch(){$'
lets[2]='taskswitch'
else
lete=split(getline(v:foldend),'|',1)
lets[2]=e[2]
endif
returnjoin(s,'|')
endfunction

setlocalfoldexpr=FunctionGraphFoldExpr(v:lnum)
setlocalfoldtext=FunctionGraphFoldText()
setlocalfoldcolumn=12
setlocalfoldmethod=expr

將上述指令保存為 function-graph-fold.vim 文件，在 vim 使用時通過 -S 參數(shù)指定上述配置，就可實現(xiàn)按照層級展示跟蹤記錄。在 vim 中，可通過 za 展開，zc 折疊跟蹤記錄。（通過文件分析，我們需要在 cat trace 文件時候重定向到文件）。

$vim-Sfunction-graph-fold.vimtrace.log

4. 內(nèi)核跟蹤點（tracepoint）跟蹤

可基于 ftrace 跟蹤內(nèi)核靜態(tài)跟蹤點，可跟蹤的完整列表可通過 available_events 查看。events 目錄下查看到各分類的子目錄，詳見下圖：

#available_events文件中包括全部可用于跟蹤的靜態(tài)跟蹤點
$sudogrepopenatavailable_events
syscalls:sys_exit_openat2
syscalls:sys_enter_openat2
syscalls:sys_exit_openat
syscalls:sys_enter_openat

#我們可以在events/syscalls/sys_enter_openat中查看該跟蹤點相關(guān)的選項
$sudols-hlevents/syscalls/sys_enter_openat
total0
-rw-r-----1rootroot0Jan11970enable#是否啟用跟蹤1啟用
-rw-r-----1rootroot0Jan11970filter#跟蹤過濾
-r--r-----1rootroot0Jan11970format#跟蹤點格式
-r--r-----1rootroot0Jan11970hist
-r--r-----1rootroot0Jan11970id
--w-------1rootroot0Jan11970inject
-rw-r-----1rootroot0Jan11970trigger


$sudocatevents/syscalls/sys_enter_openat/format
name:sys_enter_openat
ID:555
format:
field:unsignedshortcommon_type;offset:0;size:2;signed:0;
field:unsignedcharcommon_flags;offset:2;size:1;signed:0;
field:unsignedcharcommon_preempt_count;offset:3;size:1;signed:0;
field:intcommon_pid;offset:4;size:4;signed:1;

field:int__syscall_nr;offset:8;size:4;signed:1;
field:intdfd;offset:16;size:8;signed:0;
field:constchar*filename;offset:24;size:8;signed:0;
field:intflags;offset:32;size:8;signed:0;
field:umode_tmode;offset:40;size:8;signed:0;

printfmt:"dfd:0x%08lx,filename:0x%08lx,flags:0x%08lx,mode:0x%08lx",((unsignedlong)(REC->dfd)),((unsignedlong)(REC->filename)),((unsignedlong)(REC->flags)),((unsignedlong)(REC->mode))

這里直接使用 tracepoint 跟蹤 sys_openat 系統(tǒng)調(diào)用，設(shè)置如下：

$sudoecho1>events/syscalls/sys_enter_openat/enable
$sudoecho1>tracing_on
$sudocattrace
#tracer:nop
#
#entries-in-buffer/entries-written:19/19#P:4
#
#_-----=>irqs-off
#/_----=>need-resched
#|/_---=>hardirq/softirq
#||/_--=>preempt-depth
#|||/delay
#TASK-PIDCPU#||||TIMESTAMPFUNCTION
#|||||||||
cat-16961[003]....47683.934082:sys_openat(dfd:ffffffffffffff9c,filename:ffff9abf20f0,flags:80000,mode:0)
cat-16961[003]....47683.934326:sys_openat(dfd:ffffffffffffff9c,filename:ffff9ac09f20,flags:80000,mode:0)
cat-16961[003]....47683.935468:sys_openat(dfd:ffffffffffffff9c,filename:ffff9ab75150,flags:80000,mode:0)

#關(guān)閉
$sudoecho0>events/syscalls/sys_enter_openat/enable

我們通過設(shè)置 sys_enter_openat/enable 開啟對于 sys_enter_openat 的跟蹤，trace 文件中的跟蹤記錄格式與 sys_enter_openat/format 中的 print 章節(jié)的格式一致。

printfmt:"dfd:0x%08lx,filename:0x%08lx,flags:0x%08lx,mode:0x%08lx"...

Filter 跟蹤記錄條件過濾

關(guān)于 sys_enter_openat/filter 文件為跟蹤記錄的過濾條件設(shè)置，格式如下：

fieldoperatorvalue

其中：

field 為 sys_enter_openat/format 中的字段。

operator 為比較符

整數(shù)支持：==，!=，= 和 & ，

字符串支持 ==，!=，~ 等，其中 ~ 支持 shell 腳本中通配符 *，？，[] 等操作。

不同的條件也支持 && 和 || 進行組合。

如需要通過 format 格式中的 mode 字段過濾：

field:umode_tmode;offset:40;size:8;signed:0;

只需要將進行如下設(shè)置即可：

$sudoecho'mode!=0'>events/syscalls/sys_enter_openat/filter

如果需要清除 filter，直接設(shè)置為 0 即可：

$sudoecho0>events/syscalls/sys_enter_openat/filter

5. kprobe 跟蹤

kprobe 為內(nèi)核提供的動態(tài)跟蹤機制。與第 1 節(jié)介紹的函數(shù)跟蹤類似，但是 kprobe 機制允許我們跟蹤函數(shù)任意位置，還可用于獲取函數(shù)參數(shù)與結(jié)果返回值。使用 kprobe 機制跟蹤函數(shù)須是 available_filter_functions 列表中的子集。

kprobe 設(shè)置文件和相關(guān)文件如下所示，其中部分文件為設(shè)置 kprobe 跟蹤函數(shù)后，F(xiàn)trace 自動創(chuàng)建：

kprobe_events

設(shè)置 kprobe 跟蹤的事件屬性；

完整的設(shè)置格式如下，其中 GRP 用戶可以直接定義，如果不設(shè)定默認為 kprobes：

p[:[GRP/]EVENT][MOD:]SYM[+offs]|MEMADDR[FETCHARGS]#設(shè)置probe探測點
r[:[GRP/]EVENT][MOD:]SYM[+0][FETCHARGS]#函數(shù)地址的返回跟蹤
-:[GRP/]EVENT#刪除跟蹤

kprobes///enabled

設(shè)置后動態(tài)生成，用于控制是否啟用該內(nèi)核函數(shù)的跟蹤；

kprobes///filter

設(shè)置后動態(tài)生成，kprobe 函數(shù)跟蹤過濾器，與上述的跟蹤點 fliter 類似；

kprobes///format

設(shè)置后動態(tài)生成，kprobe 事件顯示格式；

kprobe_profile

kprobe 事件統(tǒng)計性能數(shù)據(jù)；

Kprobe 跟蹤過程可以指定函數(shù)參數(shù)的顯示格式，這里我們先給出 sys_openat 函數(shù)原型：

SYSCALL_DEFINE4(openat,int,dfd,constchar__user*,filename,int,flags,
umode_t,mode);

跟蹤函數(shù)入口參數(shù)

這里仍然以 __arm64_sys_openat 函數(shù)為例，演示使用 kpboe 機制進行跟蹤：

#p[:[GRP/]EVENT][MOD:]SYM[+offs]|MEMADDR[FETCHARGS]
#GRP=my_grpEVENT=arm64_sys_openat
#SYM=__arm64_sys_openat
#FETCHARGS=dfd=$arg1flags=$arg3mode=$arg4
$sudoecho'p:my_grp/arm64_sys_openat__arm64_sys_openatdfd=$arg1flags=$arg3mode=$arg4'>>kprobe_events

$sudocatevents/my_grp/arm64_sys_openat/format
name:__arm64_sys_openat
ID:1475
format:
field:unsignedshortcommon_type;offset:0;size:2;signed:0;
field:unsignedcharcommon_flags;offset:2;size:1;signed:0;
field:unsignedcharcommon_preempt_count;offset:3;size:1;signed:0;
field:intcommon_pid;offset:4;size:4;signed:1;

field:unsignedlong__probe_ip;offset:8;size:8;signed:0;

printfmt:"(%lx)",REC->__probe_ip

events/my_grp/arm64_sys_openat/format
$sudoecho1>events/my_grp/arm64_sys_openat/enable
#$sudoecho1>options/stacktrace#啟用棧

$cattrace
#tracer:nop
#
#entries-in-buffer/entries-written:38/38#P:4
#
#_-----=>irqs-off
#/_----=>need-resched
#|/_---=>hardirq/softirq
#||/_--=>preempt-depth
#|||/delay
#TASK-PIDCPU#||||TIMESTAMPFUNCTION
#|||||||||
cat-17025[002]d...52539.651096:arm64_sys_openat:(__arm64_sys_openat+0x0/0xb4)dfd=0xffff8000141cbeb0flags=0x1bfmode=0xffff800011141778

#關(guān)閉，注意需要先echo0>enable停止跟蹤
#然后再使用"-:my_grp/arm64_sys_openat"停止，否則會正在使用或者忙的錯誤
$sudoecho0>events/my_grp/arm64_sys_openat/enable
$sudoecho'-:my_grp/arm64_sys_openat'>>kprobe_events

跟蹤函數(shù)返回值

kprobe 可用于跟蹤函數(shù)返回值，格式如下：

r[:[GRP/]EVENT][MOD:]SYM[+offs]|MEMADDR[FETCHARGS]

例如：

$sudoecho'r:my_grp/arm64_sys_openat__arm64_sys_openatret=$retval'>>kprobe_events

變量 $retval 參數(shù)表示函數(shù)返回值，其他的使用格式與 kprobe 類似。

6. uprobe 跟蹤

uprobe 為用戶空間的動態(tài)跟蹤機制，格式和使用方式與 kprobe 的方式類似，但是由于是用戶態(tài)程序跟蹤需要指定跟蹤的二進制文件和偏移量。

p[:[GRP/]EVENT]]PATH:OFFSET[FETCHARGS]#跟蹤函數(shù)入口
r[:[GRP/]EVENT]]PATH:OFFSET[FETCHARGS]#跟蹤函數(shù)返回值
-:[GRP/]EVENT]#刪除跟蹤點

這里以跟蹤 /bin/bash 二進制文件中的 readline() 函數(shù)為例：

$readelf-s/bin/bash|grep-wreadline
920:00000000000d6070208FUNCGLOBALDEFAULT13readline

$echo'p:my_grp/readline/bin/bash:0xd6070'>>uprobe_events
$echo1>events/my_grp/readline/enable

$cattrace
#tracer:nop
#
#entries-in-buffer/entries-written:1/1#P:4
#
#_-----=>irqs-off
#/_----=>need-resched
#|/_---=>hardirq/softirq
#||/_--=>preempt-depth
#|||/delay
#TASK-PIDCPU#||||TIMESTAMPFUNCTION
#|||||||||
bash-14951[003]....54570.055093:readline:(0xaaaab3ce6070)

$echo0>events/my_grp/readline/enable
$echo'-:my_grp/readline'>>uprobe_events

uprobe 跟蹤是跟蹤用戶態(tài)的函數(shù)，因此需要指定二進制文件+符號偏移量才能進行跟蹤。不同系統(tǒng)中的二進制版本或者編譯方式不同，會導(dǎo)致函數(shù)符號表的位置不同，因此需要跟蹤前進行確認。

7. 總結(jié)

至此，我們完整介紹 Ftrace 的整體應(yīng)用場景，也通過具體的設(shè)置，學(xué)習(xí)了使用的完整流程。

實際問題排查中，考慮到效率和易用性，推薦大家這樣選擇：

如果排查問題機器上支持 eBPF 技術(shù)，首選 BCC trace[14] 及相關(guān)工具；

否則推薦使用 perf-tools[15] ；

最后的招數(shù)就是使用本文 Ftrace 的完整流程了。

但目前基于 eBPF 的工具還未支持 function_graph 跟蹤器，特定場景下還需要 ftrace 的 function_graph 跟蹤器的配合。

Ftrace 與 eBPF 并非是相互替代，而是相互補充協(xié)同關(guān)系，在后續(xù)的問題排查案例中我們將看到這一點。