問題排查利器：Linux 原生跟蹤工具 Ftrace 必知必會

本文地址：https://www.ebpf.top/post/ftrace_tools

TLDR，建議收藏，需要時查閱。

如果你只是需要快速使用工具來進行問題排查，包括但不限於函數調用棧跟蹤、函數調用子函數流程、函數返回結果，那么推薦你直接使用 BCC trace 或 Brendan Gregg 封裝的 perf-tools 工具即可，本文嘗試從手工操作 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 -q kernel.ftrace_enabled=1
$ mount -t tracefs tracefs /sys/kernel/tracing

$ mount -t debugfs,tracefs
tracefs on /sys/kernel/tracing type tracefs (rw,nosuid,nodev,noexec,relatime)
debugfs on /sys/kernel/debug type debugfs (rw,nosuid,nodev,noexec,relatime)
tracefs on /sys/kernel/debug/tracing type tracefs (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 進行復位，然后再進行測試。

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
$ sudo echo function > current_tracer

# 將跟蹤函數 __arm64_sys_openat 設置到 set_ftrace_filter 文件中
$ sudo echo __arm64_sys_openat > set_ftrace_filter

# 開啟全局的跟蹤使能
$ sudo echo 1 > tracing_on

# 運行 ls 命令觸發 sys_openat 系統調用，新的內核版本中直接調用 sys_openat
$ ls -hl 

# 關閉
$ sudo echo 0 > tracing_on
$ sudo echo nop > current_tracer

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

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

我們可以看到上述的結果表明了函數調用的任務名稱、PID、CPU、標記位、時間戳及函數名字。

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

perf_tools 工具集中 kprobe 也可以實現類似的效果，底層基於 kprobe 機制實現，ftrace 機制中的 kprobe 在后續章節會詳細介紹。

2. 函數被調用流程（棧）

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

$ sudo echo function > current_tracer
$ sudo echo __arm64_sys_openat > set_ftrace_filter
$ sudo echo 1 > options/func_stack_trace # 設置調用棧選項
$ sudo echo 1 > tracing_on

$ ls -hl 

$ sudo echo 0 > tracing_on

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

# 關閉
$ sudo echo nop > current_tracer
$ sudo echo  > set_ftrace_filter 
$ sudo echo 0 > 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 工具集中 kprobe 通過添加 ”-s“ 參數實現同樣的功能，運行的命令如下：

$ ./kprobe -s 'p:__arm64_sys_openat'

3. 函數調用子流程跟蹤（棧）

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

基於 __arm64_sys_openat 子流程調用關系的跟蹤的完整設置過程如下：

# 將當前 current_tracer 設置為 function_graph
$ sudo echo function_graph > current_tracer
$ sudo echo __arm64_sys_openat > set_graph_function

# 設置跟蹤子函數的最大層級數
$ sudo echo 3 > max_graph_depth  # 設置最大層級
$ sudo echo 1 > tracing_on

$ ls -hl

$ sudo echo 0 > tracing_on
#$ echo nop > set_graph_function
$ sudo cat trace
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 1)               |  __arm64_sys_openat() {
 1)               |    do_sys_openat2() {
 1)   0.875 us    |      getname();
 1)   0.125 us    |      get_unused_fd_flags();
 1)   2.375 us    |      do_filp_open();
 1)   0.084 us    |      put_unused_fd();
 1)   0.125 us    |      putname();
 1)   4.083 us    |    }
 1)   4.250 us    |  }

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

這種完整的子函數調用關系，對於我們學習內核源碼和分析線上的問題都提供了便利，排查問題時則可以順藤摸瓜逐步縮小需要分析的范圍。

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

$./funcgraph -m 3 __arm64_sys_openat

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

" Enable folding for ftrace function_graph traces.
"
" To use, :source this file while viewing a function_graph trace, or use vim's
" -S option to load from the command-line together with a trace.  You can then
" use the usual vim fold commands, such as "za", to open and close nested
" functions.  While closed, a fold will show the total time taken for a call,
" as would normally appear on the line with the closing brace.  Folded
" functions will not include finish_task_switch(), so folding should remain
" relatively sane even through a context switch.
"
" Note that this will almost certainly only work well with a
" single-CPU trace (e.g. trace-cmd report --cpu 1).

function! FunctionGraphFoldExpr(lnum)
  let line = getline(a:lnum)
  if line[-1:] == '{'
    if line =~ 'finish_task_switch() {$'
      return '>1'
    endif
    return 'a1'
  elseif line[-1:] == '}'
    return 's1'
  else
    return '='
  endif
endfunction

function! FunctionGraphFoldText()
  let s = split(getline(v:foldstart), '|', 1)
  if getline(v:foldend+1) =~ 'finish_task_switch() {$'
    let s[2] = ' task switch  '
  else
    let e = split(getline(v:foldend), '|', 1)
    let s[2] = e[2]
  endif
  return join(s, '|')
endfunction

setlocal foldexpr=FunctionGraphFoldExpr(v:lnum)
setlocal foldtext=FunctionGraphFoldText()
setlocal foldcolumn=12
setlocal foldmethod=expr

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

$ vim -S function-graph-fold.vim trace.log

4. 內核跟蹤點（tracepoint）跟蹤

可基於 ftrace 跟蹤內核靜態跟蹤點，可跟蹤的完整列表可通過 available_events 查看。events 目錄下查看到各分類的子目錄，詳見下圖：

# available_events 文件中包括全部可用於跟蹤的靜態跟蹤點
$ sudo grep openat available_events
syscalls:sys_exit_openat2
syscalls:sys_enter_openat2
syscalls:sys_exit_openat
syscalls:sys_enter_openat

# 我們可以在 events/syscalls/sys_enter_openat 中查看該跟蹤點相關的選項
$ sudo ls -hl events/syscalls/sys_enter_openat
total 0
-rw-r----- 1 root root 0 Jan  1  1970 enable  # 是否啟用跟蹤 1 啟用
-rw-r----- 1 root root 0 Jan  1  1970 filter  # 跟蹤過濾
-r--r----- 1 root root 0 Jan  1  1970 format  # 跟蹤點格式
-r--r----- 1 root root 0 Jan  1  1970 hist
-r--r----- 1 root root 0 Jan  1  1970 id
--w------- 1 root root 0 Jan  1  1970 inject
-rw-r----- 1 root root 0 Jan  1  1970 trigger


$ sudo cat events/syscalls/sys_enter_openat/format
name: sys_enter_openat
ID: 555
format:
	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
	field:unsigned char common_preempt_count;	offset:3;	size:1;	signed:0;
	field:int common_pid;	offset:4;	size:4;	signed:1;

	field:int __syscall_nr;	offset:8;	size:4;	signed:1;
	field:int dfd;	offset:16;	size:8;	signed:0;
	field:const char * filename;	offset:24;	size:8;	signed:0;
	field:int flags;	offset:32;	size:8;	signed:0;
	field:umode_t mode;	offset:40;	size:8;	signed:0;

print fmt: "dfd: 0x%08lx, filename: 0x%08lx, flags: 0x%08lx, mode: 0x%08lx", ((unsigned long)(REC->dfd)), ((unsigned long)(REC->filename)), ((unsigned long)(REC->flags)), ((unsigned long)(REC->mode))

這里直接使用 tracepoint 跟蹤 sys_openat 系統調用，設置如下：

$ sudo echo 1 > events/syscalls/sys_enter_openat/enable
$ sudo echo 1 > tracing_on
$ sudo cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 19/19   #P:4
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
#              | |         |   ||||      |         |
             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)

# 關閉
$ sudo echo 0 > events/syscalls/sys_enter_openat/enable

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

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

Filter 跟蹤記錄條件過濾

關於 sys_enter_openat/filter 文件為跟蹤記錄的過濾條件設置，格式如下：

field operator value

其中：

• field 為 sys_enter_openat/format 中的字段。
• operator 為比較符
  • 整數支持：==，!=，</、，<=，>= 和 & ，
  • 字符串支持 ==，!=，~ 等，其中 ~ 支持 shell 腳本中通配符 *，？，[] 等操作。
  • 不同的條件也支持 && 和 || 進行組合。

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

field:umode_t mode;	offset:40;	size:8;	signed:0;

只需要將進行如下設置即可：

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

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

$ sudo echo 0 > 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/<GRP>/<EVENT>/enabled

  設置后動態生成，用於控制是否啟用該內核函數的跟蹤；

• kprobes/<GRP>/<EVENT>/filter

  設置后動態生成，kprobe 函數跟蹤過濾器，與上述的跟蹤點 fliter 類似；

• kprobes/<GRP>/<EVENT>/format

  設置后動態生成，kprobe 事件顯示格式；

• kprobe_profile

  kprobe 事件統計性能數據；

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

SYSCALL_DEFINE4(openat, int, dfd, const char __user *, filename, int, flags,
		umode_t, mode);

**跟蹤函數入口參數 **

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

# p[:[GRP/]EVENT] [MOD:]SYM[+offs]|MEMADDR [FETCHARGS]
# GRP=my_grp EVENT=arm64_sys_openat  
# SYM=__arm64_sys_openat
# FETCHARGS = dfd=$arg1 flags=$arg3 mode=$arg4
$ sudo echo 'p:my_grp/arm64_sys_openat __arm64_sys_openat dfd=$arg1 flags=$arg3 mode=$arg4' >> kprobe_events

$ sudo cat events/my_grp/arm64_sys_openat/format
name: __arm64_sys_openat
ID: 1475
format:
	field:unsigned short common_type;	offset:0;	size:2;	signed:0;
	field:unsigned char common_flags;	offset:2;	size:1;	signed:0;
	field:unsigned char common_preempt_count;	offset:3;	size:1;	signed:0;
	field:int common_pid;	offset:4;	size:4;	signed:1;

	field:unsigned long __probe_ip;	offset:8;	size:8;	signed:0;

print fmt: "(%lx)", REC->__probe_ip

events/my_grp/arm64_sys_openat/format
$ sudo echo 1 > events/my_grp/arm64_sys_openat/enable
# $ sudo echo 1 > options/stacktrace # 啟用棧

$ cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 38/38   #P:4
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||   TIMESTAMP  FUNCTION
#              | |         |   ||||      |         |
             cat-17025   [002] d... 52539.651096: arm64_sys_openat: (__arm64_sys_openat+0x0/0xb4) dfd=0xffff8000141cbeb0 flags=0x1bf mode=0xffff800011141778

# 關閉，注意需要先 echo 0 > enable 停止跟蹤
# 然后再使用 "-:my_grp/arm64_sys_openat" 停止，否則會正在使用或者忙的錯誤
$ sudo echo 0 > events/my_grp/arm64_sys_openat/enable
$ sudo echo '-:my_grp/arm64_sys_openat' >> kprobe_events

**跟蹤函數返回值 **

kprobe 可用於跟蹤函數返回值，格式如下：

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

例如：

$ sudo echo 'r:my_grp/arm64_sys_openat __arm64_sys_openat ret=$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 -w readline
   920: 00000000000d6070   208 FUNC    GLOBAL DEFAULT   13 readline

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

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

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

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

7. 總結

至此，我們完整介紹 Ftrace 的整體應用場景，也通過具體的設置，學習了使用的完整流程。

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

• 如果排查問題機器上支持 eBPF技術，首選 BCC trace 及相關工具；
• 否則推薦使用 perf-tools ；
• 最后的招數就是使用本文 Ftrace 的完整流程了。

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

Ftrace 與 eBPF 並非是相互替代，而是相互補充協同關系，在后續的問題排查案例中我們將看到這一點。

參考

• 高效分析 Linux 內核源碼 ， 相關代碼參見這里 。
• Linux kprobe 調試技術使用
• ftrace 在實際問題中的應用
• 《Systems Performance Enterprise and the Cloud 2nd Edition》