如果你只是需要快速使用工具來進行問題排查,包括但不限于函數調用棧跟蹤、函數調用子函數流程、函數返回結果,那么推薦你直接使用 BCC trace[1] 或 Brendan Gregg[2] 封裝的 perf-tools[3] 工具即可,本文嘗試從手工操作 Ftrace 跟蹤工具的方式展示在底層是如何通過 tracefs 實現這些能力的。如果你對某個跟蹤主題感興趣,建議直接跳轉到相關的主題查看。
快速說明:
kprobe 為內核中提供的動態跟蹤機制,/proc/kallsym 中的函數幾乎都可以用于跟蹤,但是內核函數可能隨著版本演進而發生變化,為非穩定的跟蹤機制,數量比較多。
uprobe 為用戶空間提供的動態機制;
tracepoint 是內核提供的靜態跟蹤點,為穩定的跟蹤點,需要研發人員代碼編寫,數量有限;
usdt 為用戶空間提供的靜態跟蹤點 【本次暫不涉及】
Ftrace 是 Linux 官方提供的跟蹤工具,在 Linux 2.6.27 版本中引入。Ftrace 可在不引入任何前端工具的情況下使用,讓其可以適合在任何系統環境中使用。
Ftrace 可用來快速排查以下相關問題:
特定內核函數調用的頻次 (function)
內核函數在被調用的過程中流程(調用棧) (function + stack)
內核函數調用的子函數流程(子調用棧)(function graph)
由于搶占導致的高延時路徑等
Ftrace 跟蹤工具由性能分析器(profiler)和跟蹤器(tracer)兩部分組成:
性能分析器,用來提供統計和直方圖數據(需要 CONFIG_ FUNCTION_PROFILER=y)
函數性能分析
直方圖
跟蹤器,提供跟蹤事件的詳情:
函數跟蹤(function)
跟蹤點(tracepoint)
kprobe
uprobe
函數調用關系(function_graph)
hwlat 等
除了操作原始的文件接口外,也有一些基于 Ftrace 的前端工具,比如 perf-tools 和 trace-cmd (界面 KernelShark)等。整體跟蹤及前端工具架構圖如下:
圖片來自于 《Systems Performance Enterprise and the Cloud 2nd Edition》 14.1 P706
Ftrace 的使用的接口為 tracefs 文件系統,需要保證該文件系統進行加載:
$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 目錄下核心文件介紹如下表格,當前可僅關注黑體加粗的項,其他項可在需要的時候再進行回顧:
文件 | 描述 |
---|---|
available_tracers | 可用跟蹤器,hwlat blk function_graph wakeup_dl wakeup_rt wakeup function nop,nop 表示不使用跟蹤器 |
current_tracer | 當前使用的跟蹤器 |
function_profile_enabled | 啟用函數性能分析器 |
available_filter_functions | 可跟蹤的完整函數列表 |
set_ftrace_filter | 選擇跟蹤函數的列表,支持批量設置,例如 *tcp、tcp* 和 *tcp* 等 |
set_ftrace_notrace | 設置不跟蹤的函數列表 |
set_event_pid | 設置跟蹤的 PID,表示僅跟蹤 PID 程序的函數或者其他跟蹤 |
tracing_on | 是否啟用跟蹤,1 啟用跟蹤 0 關閉跟蹤 |
trace_options | 設置跟蹤的選項 |
trace_stat(目錄) | 函數性能分析的輸出目錄 |
kprobe_events | 啟用 kprobe 的配置 |
uprobe_events | 啟用 uprobe 的配置 |
events ( 目錄 ) | 事件(Event)跟蹤器的控制文件:tracepoint、kprobe、uprobe |
trace | 跟蹤的輸出 (Ring Buffer) |
trace_pipe | 跟蹤的輸出;提供持續不斷的數據流,適用于程序進行讀取 |
perf_tools 包含了一個復位所有 ftrace 選型的工具腳本,在跟蹤不符合預期的情況下,建議先使用 reset-ftrace[4] 進行復位,然后再進行測試。
1. 內核函數調用跟蹤
基于 Ftrace 的內核函數調用跟蹤整體架構如下所示:
圖片來自于 《Systems Performance Enterprise and the Cloud 2nd Edition》 14.4 P713
這里我們嘗試對于內核中的系統調用函數 __arm64_sys_openat 進行跟蹤(前面兩個下劃線),需要注意的是 __arm64_sys_openat 是在 arm64 結構體系下 sys_openat 系統調用的包裝,如果在 x86_64 架構下則為 __x64_sys_openat() ,由于我們本地的電腦是 M1 芯片,所以演示的樣例以 arm64 為主。
在不同的體系結構下,可以在 /proc/kallsym 文件中搜索確認。
后續的目錄,如無特殊說明,都默認位于 /sys/kernel/debug/tracing/ 根目錄。
#使用function跟蹤器,并將其設置到current_tracer $sudoechofunction>current_tracer #將跟蹤函數__arm64_sys_openat設置到set_ftrace_filter文件中 $sudoecho__arm64_sys_openat>set_ftrace_filter #開啟全局的跟蹤使能 $sudoecho1>tracing_on #運行ls命令觸發sys_openat系統調用,新的內核版本中直接調用sys_openat $ls-hl #關閉 $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
我們可以看到上述的結果表明了函數調用的任務名稱、PID、CPU、標記位、時間戳及函數名字。
在 perf_tools[5] 工具集中的前端封裝工具為 functrace[6] ,需要注意的是該工具默認不會設置 tracing_on 為 1, 需要在啟動前進行設置,即 ”echo 1 > tracing_on“。
perf_tools[7] 工具集中 kprobe[8] 也可以實現類似的效果,底層基于 kprobe 機制實現,ftrace 機制中的 kprobe 在后續章節會詳細介紹。
2. 函數被調用流程(棧)
在第 1 部分我們獲得了內核函數的調用,但是有些場景我們更可能希望獲取調用該內核函數的流程(即該函數是在何處被調用),這需要通過設置 options/func_stack_trace 選項實現。
$sudoechofunction>current_tracer $sudoecho__arm64_sys_openat>set_ftrace_filter $sudoecho1>options/func_stack_trace#設置調用棧選項 $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 #關閉 $sudoechonop>current_tracer $sudoecho>set_ftrace_filter $sudoecho0>options/func_stack_trace
通過上述跟蹤記錄,我們可以發現記錄同時展示了函數調用的記錄和被調用的函數流程,__arm64_sys_openat 的被調用棧如下:
=>__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“ 參數實現同樣的功能,運行的命令如下:
$./kprobe-s'p:__arm64_sys_openat'
3. 函數調用子流程跟蹤(棧)
如果想要分析內核函數調用的子流程(即本函數調用了哪些子函數,處理的流程如何),這時需要用到 function_graph 跟蹤器,從字面意思就可看出這是函數調用關系跟蹤。
基于 __arm64_sys_openat 子流程調用關系的跟蹤的完整設置過程如下:
#將當前current_tracer設置為function_graph $sudoechofunction_graph>current_tracer $sudoecho__arm64_sys_openat>set_graph_function #設置跟蹤子函數的最大層級數 $sudoecho3>max_graph_depth#設置最大層級 $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 函數的調用子流程僅包括 do_sys_openat2() 子函數,而 do_sys_openat2() 函數又調用了 getname()/get_unused_fd_flags() 等子函數。
這種完整的子函數調用關系,對于我們學習內核源碼和分析線上的問題都提供了便利,排查問題時則可以順藤摸瓜逐步縮小需要分析的范圍。
在 perf_tools[11] 工具集的前端工具為 funcgraph[12] ,使用 funcgraph 啟動命令如下所示:
$./funcgraph-m3__arm64_sys_openat
如果函數調用棧比較多,直接查看跟蹤記錄則非常不方便,基于此社區補丁 [PATCH] ftrace: Add vim script to enable folding for function_graph traces[13] 提供了一個基于 vim 的配置,可通過樹狀關系來折疊和展開函數調用的最終記錄,vim 設置完整如下:
"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 參數指定上述配置,就可實現按照層級展示跟蹤記錄。在 vim 中,可通過 za 展開,zc 折疊跟蹤記錄。(通過文件分析,我們需要在 cat trace 文件時候重定向到文件)。
$vim-Sfunction-graph-fold.vimtrace.log
4. 內核跟蹤點(tracepoint)跟蹤
可基于 ftrace 跟蹤內核靜態跟蹤點,可跟蹤的完整列表可通過 available_events 查看。events 目錄下查看到各分類的子目錄,詳見下圖:
#available_events文件中包括全部可用于跟蹤的靜態跟蹤點 $sudogrepopenatavailable_events syscalls:sys_exit_openat2 syscalls:sys_enter_openat2 syscalls:sys_exit_openat syscalls:sys_enter_openat #我們可以在events/syscalls/sys_enter_openat中查看該跟蹤點相關的選項 $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 系統調用,設置如下:
$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) #關閉 $sudoecho0>events/syscalls/sys_enter_openat/enable
我們通過設置 sys_enter_openat/enable 開啟對于 sys_enter_openat 的跟蹤,trace 文件中的跟蹤記錄格式與 sys_enter_openat/format 中的 print 章節的格式一致。
printfmt:"dfd:0x%08lx,filename:0x%08lx,flags:0x%08lx,mode:0x%08lx"...
Filter 跟蹤記錄條件過濾
關于 sys_enter_openat/filter 文件為跟蹤記錄的過濾條件設置,格式如下:
fieldoperatorvalue
其中:
field 為 sys_enter_openat/format 中的字段。
operator 為比較符
整數支持:==,!=,、,<=,>= 和 & ,
字符串支持 ==,!=,~ 等,其中 ~ 支持 shell 腳本中通配符 *,?,[] 等操作。
不同的條件也支持 && 和 || 進行組合。
如需要通過 format 格式中的 mode 字段過濾:
field:umode_tmode;offset:40;size:8;signed:0;
只需要將進行如下設置即可:
$sudoecho'mode!=0'>events/syscalls/sys_enter_openat/filter
如果需要清除 filter,直接設置為 0 即可:
$sudoecho0>events/syscalls/sys_enter_openat/filter
5. kprobe 跟蹤
kprobe 為內核提供的動態跟蹤機制。與第 1 節介紹的函數跟蹤類似,但是 kprobe 機制允許我們跟蹤函數任意位置,還可用于獲取函數參數與結果返回值。使用 kprobe 機制跟蹤函數須是 available_filter_functions 列表中的子集。
kprobe 設置文件和相關文件如下所示,其中部分文件為設置 kprobe 跟蹤函數后,Ftrace 自動創建:
kprobe_events
設置 kprobe 跟蹤的事件屬性;
完整的設置格式如下,其中 GRP 用戶可以直接定義,如果不設定默認為 kprobes:
p[:[GRP/]EVENT][MOD:]SYM[+offs]|MEMADDR[FETCHARGS]#設置probe探測點 r[:[GRP/]EVENT][MOD:]SYM[+0][FETCHARGS]#函數地址的返回跟蹤 -:[GRP/]EVENT#刪除跟蹤
kprobes/
設置后動態生成,用于控制是否啟用該內核函數的跟蹤;
kprobes/
設置后動態生成,kprobe 函數跟蹤過濾器,與上述的跟蹤點 fliter 類似;
kprobes/
設置后動態生成,kprobe 事件顯示格式;
kprobe_profile
kprobe 事件統計性能數據;
Kprobe 跟蹤過程可以指定函數參數的顯示格式,這里我們先給出 sys_openat 函數原型:
SYSCALL_DEFINE4(openat,int,dfd,constchar__user*,filename,int,flags, umode_t,mode);
跟蹤函數入口參數
這里仍然以 __arm64_sys_openat 函數為例,演示使用 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 #關閉,注意需要先echo0>enable停止跟蹤 #然后再使用"-:my_grp/arm64_sys_openat"停止,否則會正在使用或者忙的錯誤 $sudoecho0>events/my_grp/arm64_sys_openat/enable $sudoecho'-:my_grp/arm64_sys_openat'>>kprobe_events
跟蹤函數返回值
kprobe 可用于跟蹤函數返回值,格式如下:
r[:[GRP/]EVENT][MOD:]SYM[+offs]|MEMADDR[FETCHARGS]
例如:
$sudoecho'r:my_grp/arm64_sys_openat__arm64_sys_openatret=$retval'>>kprobe_events
變量 $retval 參數表示函數返回值,其他的使用格式與 kprobe 類似。
6. uprobe 跟蹤
uprobe 為用戶空間的動態跟蹤機制,格式和使用方式與 kprobe 的方式類似,但是由于是用戶態程序跟蹤需要指定跟蹤的二進制文件和偏移量。
p[:[GRP/]EVENT]]PATH:OFFSET[FETCHARGS]#跟蹤函數入口 r[:[GRP/]EVENT]]PATH:OFFSET[FETCHARGS]#跟蹤函數返回值 -:[GRP/]EVENT]#刪除跟蹤點
這里以跟蹤 /bin/bash 二進制文件中的 readline() 函數為例:
$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 跟蹤是跟蹤用戶態的函數,因此需要指定二進制文件+符號偏移量才能進行跟蹤。不同系統中的二進制版本或者編譯方式不同,會導致函數符號表的位置不同,因此需要跟蹤前進行確認。
7. 總結
至此,我們完整介紹 Ftrace 的整體應用場景,也通過具體的設置,學習了使用的完整流程。
實際問題排查中,考慮到效率和易用性,推薦大家這樣選擇:
如果排查問題機器上支持 eBPF 技術,首選 BCC trace[14] 及相關工具;
否則推薦使用 perf-tools[15] ;
最后的招數就是使用本文 Ftrace 的完整流程了。
但目前基于 eBPF 的工具還未支持 function_graph 跟蹤器,特定場景下還需要 ftrace 的 function_graph 跟蹤器的配合。
Ftrace 與 eBPF 并非是相互替代,而是相互補充協同關系,在后續的問題排查案例中我們將看到這一點。
-
封裝
+關注
關注
127文章
8142瀏覽量
143852 -
分析器
+關注
關注
0文章
93瀏覽量
12597 -
函數
+關注
關注
3文章
4353瀏覽量
63292
原文標題:問題排查利器:Linux 原生跟蹤工具 Ftrace 必知必會
文章出處:【微信號:LinuxDev,微信公眾號:Linux閱碼場】歡迎添加關注!文章轉載請注明出處。
發布評論請先 登錄
相關推薦
如何通過Tracealyzer實現Linux系統的跟蹤?

評論