使用 ftrace 跟蹤內核
在內核層面上分析事件有很多的工具：SystemTap、ktap、Sysdig、LTTNG 等等，你也可以在網路上找到關於這些工具的大量介紹文章和資料。
而對於使用 Linux 原生機制去跟蹤系統事件以及檢索/分析故障信息的方面的資料卻很少找的到。這就是 ftrace，它是添加到內核中的第一款跟蹤工具，今天我們來看一下它都能做什麼，讓我們從它的一些重要術語開始吧。
內核跟蹤和分析
內核分析 可以發現性能「瓶頸」。分析能夠幫我們發現在一個程序中性能損失的準確位置。特定的程序生成一個 概述 — 這是一個事件總結 — 它能夠用於幫我們找出哪個函數佔用了大量的運行時間。儘管這些程序並不能識別出為什麼會損失性能。
瓶頸經常發生在無法通過分析來識別的情況下。要推斷出為什麼會發生事件，就必須保存發生事件時的相關上下文，這就需要去 跟蹤 。
跟蹤可以理解為在一個正常工作的系統上活動的信息收集過程。它使用特定的工具來完成這項工作，就像錄音機來記錄聲音一樣，用它來記錄各種系統事件。
跟蹤程序能夠同時跟蹤應用級和操作系統級的事件。它們收集的信息能夠用於診斷多種系統問題。
有時候會將跟蹤與日誌比較。它們兩者確時很相似，但是也有不同的地方。
對於跟蹤，記錄的信息都是些低級別事件。它們的數量是成百上千的，甚至是成千上萬的。對於日誌，記錄的信息都是些高級別事件，數量上通常少多了。這些包含用戶登錄系統、應用程序錯誤、資料庫事務等等。
就像日誌一樣，跟蹤數據可以被原樣讀取，但是用特定的應用程序提取的信息更有用。所有的跟蹤程序都能這樣做。
在內核跟蹤和分析方面，Linux 內核有三個主要的機制：
- 跟蹤點 ：一種基於靜態測試代碼的工作機制
- 探針 ：一種動態跟蹤機制，用於在任意時刻中斷內核代碼的運行，調用它自己的處理程序，在完成需要的操作之後再返回
- perf_events —— 一個訪問 PMU（ 性能監視單元 ）的介面
我並不想在這裡寫關於這些機制方面的內容，任何對它們感興趣的人可以去訪問 Brendan Gregg 的博客。
使用 ftrace，我們可以與這些機制進行交互，並可以從用戶空間直接得到調試信息。下面我們將討論這方面的詳細內容。示例中的所有命令行都是在內核版本為 3.13.0-24 的 Ubuntu 14.04 中運行的。
ftrace：常用信息
ftrace 是 Function Trace 的簡寫，但它能做的遠不止這些：它可以跟蹤上下文切換、測量進程阻塞時間、計算高優先順序任務的活動時間等等。
ftrace 是由 Steven Rostedt 開發的，從 2008 年發布的內核 2.6.27 中開始就內置了。這是為記錄數據提供的一個調試 Ring 緩衝區的框架。這些數據由集成到內核中的跟蹤程序來採集。
ftrace 工作在 debugfs 文件系統上，在大多數現代 Linux 發行版中都默認掛載了。要開始使用 ftrace，你將進入到 sys/kernel/debug/tracing 目錄（僅對 root 用戶可用）：
# cd /sys/kernel/debug/tracing
這個目錄的內容看起來應該像這樣：
аvailable_filter_functions options stack_trace_filter
available_tracers per_cpu trace
buffer_size_kb printk_formats trace_clock
buffer_total_size_kb README trace_marker
current_tracer saved_cmdlines trace_options
dyn_ftrace_total_info set_event trace_pipe
enabled_functions set_ftrace_filter trace_stat
events set_ftrace_notrace tracing_cpumask
free_buffer set_ftrace_pid tracing_max_latency
function_profile_enabled set_graph_function tracing_on
instances set_graph_notrace tracing_thresh
kprobe_events snapshot uprobe_events
kprobe_profile stack_max_size uprobe_profile
我不想去描述這些文件和子目錄；它們的描述在 官方文檔 中已經寫的很詳細了。我只想去詳細介紹與我們這篇文章相關的這幾個文件：
- available_tracers —— 可用的跟蹤程序
- current_tracer —— 正在運行的跟蹤程序
- tracing_on —— 負責啟用或禁用數據寫入到 Ring 緩衝區的系統文件（如果啟用它，數字 1 被添加到文件中，禁用它，數字 0 被添加）
- trace —— 以人類友好格式保存跟蹤數據的文件
可用的跟蹤程序
我們可以使用如下的命令去查看可用的跟蹤程序的一個列表：
root@andrei:/sys/kernel/debug/tracing#: cat available_tracers
blk mmiotrace function_graph wakeup_rt wakeup function nop
我們來快速瀏覽一下每個跟蹤程序的特性：
- function —— 一個無需參數的函數調用跟蹤程序
- function_graph —— 一個使用子調用的函數調用跟蹤程序
- blk —— 一個與塊 I/O 跟蹤相關的調用和事件跟蹤程序（它是 blktrace 使用的）
- mmiotrace —— 一個內存映射 I/O 操作跟蹤程序
- nop —— 最簡單的跟蹤程序，就像它的名字所暗示的那樣，它不做任何事情（儘管在某些情況下可能會派上用場，我們將在後文中詳細解釋）
函數跟蹤程序
在開始介紹函數跟蹤程序 ftrace 之前，我們先看一個測試腳本：
#!/bin/sh
dir=/sys/kernel/debug/tracing
sysctl kernel.ftrace_enabled=1
echo function > ${dir}/current_tracer
echo 1 > ${dir}/tracing_on
sleep 1
echo 0 > ${dir}/tracing_on
less ${dir}/trace
這個腳本是非常簡單的，但是還有幾個需要注意的地方。命令 sysctl ftrace.enabled=1 啟用了函數跟蹤程序。然後我們通過寫它的名字到 current_tracer 文件來啟用 current tracer。
接下來，我們寫入一個 1 到 tracing_on，它啟用了 Ring 緩衝區。這些語法都要求在 1 和 > 符號前後有一個空格；寫成像 echo 1> tracing_on 這樣將不能工作。一行之後我們禁用它（如果 0 寫入到 tracing_on， 緩衝區不會被清除並且 ftrace 並不會被禁用）。
我們為什麼這樣做呢？在兩個 echo 命令之間，我們看到了命令 sleep 1。我們啟用了緩衝區，運行了這個命令，然後禁用它。這將使跟蹤程序採集了這個命令運行期間發生的所有系統調用的信息。
在腳本的最後一行，我們寫了一個在控制台上顯示跟蹤數據的命令。
一旦腳本運行完成後，我們將看到下列的輸出（這裡只列出了一個小片斷）：
# tracer: function
#
# entries-in-buffer/entries-written: 29571/29571 #P:2
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
trace.sh-1295 [000] .... 90.502874: mutex_unlock <-rb_simple_write
trace.sh-1295 [000] .... 90.502875: __fsnotify_parent <-vfs_write
trace.sh-1295 [000] .... 90.502876: fsnotify <-vfs_write
trace.sh-1295 [000] .... 90.502876: __srcu_read_lock <-fsnotify
trace.sh-1295 [000] .... 90.502876: __srcu_read_unlock <-fsnotify
trace.sh-1295 [000] .... 90.502877: __sb_end_write <-vfs_write
trace.sh-1295 [000] .... 90.502877: syscall_trace_leave <-int_check_syscall_exit_work
trace.sh-1295 [000] .... 90.502878: context_tracking_user_exit <-syscall_trace_leave
trace.sh-1295 [000] .... 90.502878: context_tracking_user_enter <-syscall_trace_leave
trace.sh-1295 [000] d... 90.502878: vtime_user_enter <-context_tracking_user_enter
trace.sh-1295 [000] d... 90.502878: _raw_spin_lock <-vtime_user_enter
trace.sh-1295 [000] d... 90.502878: __vtime_account_system <-vtime_user_enter
trace.sh-1295 [000] d... 90.502878: get_vtime_delta <-__vtime_account_system
trace.sh-1295 [000] d... 90.502879: account_system_time <-__vtime_account_system
trace.sh-1295 [000] d... 90.502879: cpuacct_account_field <-account_system_time
trace.sh-1295 [000] d... 90.502879: acct_account_cputime <-account_system_time
trace.sh-1295 [000] d... 90.502879: __acct_update_integrals <-acct_account_cputime
這個輸出以「緩衝區中的信息條目數量」和「寫入的全部條目數量」開始。這兩者的數據差異是緩衝區中事件的丟失數量（在我們的示例中沒有發生丟失）。
在這裡有一個包含下列信息的函數列表：
- 進程標識符（PID）
- 運行這個進程的 CPU（CPU#）
- 進程開始時間（TIMESTAMP）
- 被跟蹤函數的名字以及調用它的父級函數；例如，在我們輸出的第一行，
rb_simple_write調用了mutex-unlock函數。
function_graph 跟蹤程序
function_graph 跟蹤程序的工作和函數跟蹤程序一樣，但是它更詳細：它顯示了每個函數的進入和退出點。使用這個跟蹤程序，我們可以跟蹤函數的子調用並且測量每個函數的運行時間。
我們來編輯一下最後一個示例的腳本：
#!/bin/sh
dir=/sys/kernel/debug/tracing
sysctl kernel.ftrace_enabled=1
echo function_graph > ${dir}/current_tracer
echo 1 > ${dir}/tracing_on
sleep 1
echo 0 > ${dir}/tracing_on
less ${dir}/trace
運行這個腳本之後，我們將得到如下的輸出：
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) 0.120 us | } /* resched_task */
0) 1.877 us | } /* check_preempt_curr */
0) 4.264 us | } /* ttwu_do_wakeup */
0) + 29.053 us | } /* ttwu_do_activate.constprop.74 */
0) 0.091 us | _raw_spin_unlock();
0) 0.260 us | ttwu_stat();
0) 0.133 us | _raw_spin_unlock_irqrestore();
0) + 37.785 us | } /* try_to_wake_up */
0) + 38.478 us | } /* default_wake_function */
0) + 39.203 us | } /* pollwake */
0) + 40.793 us | } /* __wake_up_common */
0) 0.104 us | _raw_spin_unlock_irqrestore();
0) + 42.920 us | } /* __wake_up_sync_key */
0) + 44.160 us | } /* sock_def_readable */
0) ! 192.850 us | } /* tcp_rcv_established */
0) ! 197.445 us | } /* tcp_v4_do_rcv */
0) 0.113 us | _raw_spin_unlock();
0) ! 205.655 us | } /* tcp_v4_rcv */
0) ! 208.154 us | } /* ip_local_deliver_finish */
在這個圖中，DURATION 展示了花費在每個運行的函數上的時間。注意使用 + 和 ! 符號標記的地方。加號（+）意思是這個函數花費的時間超過 10 毫秒；而感嘆號（!）意思是這個函數花費的時間超過了 100 毫秒。
在 FUNCTION_CALLS 下面，我們可以看到每個函數調用的信息。
和 C 語言一樣使用了花括弧（{）標記每個函數的邊界，它展示了每個函數的開始和結束，一個用於開始，一個用於結束；不能調用其它任何函數的葉子函數用一個分號（;）標記。
函數過濾器
ftrace 輸出可能會很大，精確找出你所需要的內容可能會非常困難。我們可以使用過濾器去簡化我們的搜索：輸出中將只顯示與我們感興趣的函數相關的信息。為實現過濾，我們只需要在 set_ftrace_filter 文件中寫入我們需要過濾的函數的名字即可。例如：
root@andrei:/sys/kernel/debug/tracing# echo kfree > set_ftrace_filter
如果禁用過濾器，我們只需要在這個文件中添加一個空白行即可：
root@andrei:/sys/kernel/debug/tracing# echo > set_ftrace_filter
通過運行這個命令：
root@andrei:/sys/kernel/debug/tracing# echo kfree > set_ftrace_notrace
我們將得到相反的結果：輸出將包含除了 kfree() 以外的任何函數的信息。
另一個有用的選項是 set_ftrace_pid。它是為在一個特定的進程運行期間調用跟蹤函數準備的。
ftrace 還有很多過濾選項。對於它們更詳細的介紹，你可以去查看 Steven Rostedt 在 LWN.net 上的文章。
跟蹤事件
我們在上面提到到跟蹤點機制。跟蹤點是插入的觸發系統事件的特定代碼。跟蹤點可以是動態的（意味著可能會在它們上面附加幾個檢查），也可以是靜態的（意味著不會附加任何檢查）。
靜態跟蹤點不會對系統有任何影響；它們只是在測試的函數末尾增加幾個位元組的函數調用以及在一個獨立的節上增加一個數據結構。
當相關代碼片斷運行時，動態跟蹤點調用一個跟蹤函數。跟蹤數據是寫入到 Ring 緩衝區。
跟蹤點可以設置在代碼的任何位置；事實上，它們確實可以在許多的內核函數中找到。我們來看一下 kmem_cache_alloc 函數（取自 這裡）：
{
void *ret = slab_alloc(cachep, flags, _RET_IP_);
trace_kmem_cache_alloc(_RET_IP_, ret,
cachep->object_size, cachep->size, flags);
return ret;
}
trace_kmem_cache_alloc 它本身就是一個跟蹤點。我們可以通過查看其它內核函數的源代碼找到這樣無數的例子。
在 Linux 內核中為了從用戶空間使用跟蹤點，它有一個專門的 API。在 /sys/kernel/debug/tracing 目錄中，這裡有一個事件目錄，它是為了保存系統事件。這些只是為了跟蹤系統事件。在這個上下文中系統事件可以理解為包含在內核中的跟蹤點。
可以通過運行如下的命令來查看這個事件列表：
root@andrei:/sys/kernel/debug/tracing# cat available_events
這個命令將在控制台中輸出一個很長的列表。這樣看起來很不方便。我們可以使用如下的命令來列出一個結構化的列表：
root@andrei:/sys/kernel/debug/tracing# ls events
block gpio mce random skb vsyscall
btrfs header_event migrate ras sock workqueue
compaction header_page module raw_syscalls spi writeback
context_tracking iommu napi rcu swiotlb xen
enable irq net regmap syscalls xfs
exceptions irq_vectors nmi regulator task xhci-hcd
ext4 jbd2 oom rpm timer
filemap kmem pagemap sched udp
fs kvm power scsi vfs
ftrace kvmmmu printk signal vmscan
所有可能的事件都按子系統分組到子目錄中。在我們開始跟蹤事件之前，我們要先確保啟用了 Ring 緩衝區寫入：
root@andrei:/sys/kernel/debug/tracing# cat tracing_on
如果在控制台中顯示的是數字 0，那麼，我們可以運行如下的命令來啟用它：
root@andrei:/sys/kernel/debug/tracing# echo 1 > tracing_on
在我們上一篇的文章中，我們寫了關於 chroot() 系統調用的內容；我們來跟蹤訪問一下這個系統調用。對於我們的跟蹤程序，我們使用 nop 因為函數跟蹤程序和 function_graph 跟蹤程序記錄的信息太多，它包含了我們不感興趣的事件信息。
root@andrei:/sys/kernel/debug/tracing# echo nop > current_tracer
所有事件相關的系統調用都保存在系統調用目錄下。在這裡我們將找到一個進入和退出各種系統調用的目錄。我們需要在相關的文件中通過寫入數字 1 來激活跟蹤點：
root@andrei:/sys/kernel/debug/tracing# echo 1 > events/syscalls/sys_enter_chroot/enable
然後我們使用 chroot 來創建一個獨立的文件系統（更多內容，請查看 之前這篇文章）。在我們執行完我們需要的命令之後，我們將禁用跟蹤程序，以便於不需要的信息或者過量信息不會出現在輸出中：
root@andrei:/sys/kernel/debug/tracing# echo 0 > tracing_on
然後，我們去查看 Ring 緩衝區的內容。在輸出的結束部分，我們找到了有關的系統調用信息（這裡只是一個節選）。
root@andrei:/sys/kernel/debug/tracing# сat trace
......
chroot-11321 [000] .... 4606.265208: sys_chroot(filename: 7fff785ae8c2)
chroot-11325 [000] .... 4691.677767: sys_chroot(filename: 7fff242308cc)
bash-11338 [000] .... 4746.971300: sys_chroot(filename: 7fff1efca8cc)
bash-11351 [000] .... 5379.020609: sys_chroot(filename: 7fffbf9918cc)
關於配置事件跟蹤的更的信息可以在 這裡 找到。
結束語
在這篇文篇中，我們做了一個 ftrace 的功能概述。我們非常感謝你的任何意見或者補充。如果你想深入研究這個主題，我們為你推薦下列的資源：
- https://www.kernel.org/doc/Documentation/trace/tracepoints.txt — 一個跟蹤點機制的詳細描述
- https://www.kernel.org/doc/Documentation/trace/events.txt — 在 Linux 中跟蹤系統事件的指南
- https://www.kernel.org/doc/Documentation/trace/ftrace.txt — ftrace 的官方文檔
- https://lttng.org/files/thesis/desnoyers-dissertation-2009-12-v27.pdf — Mathieu Desnoyers（作者是跟蹤點和 LTTNG 的創建者）的關於內核跟蹤和分析的學術論文。
- https://lwn.net/Articles/370423/ — Steven Rostedt 的關於 ftrace 功能的文章
- http://alex.dzyoba.com/linux/profiling-ftrace.html — 用 ftrace 分析實際案例的一個概述
via:https://blog.selectel.com/kernel-tracing-ftrace/
作者：Andrej Yemelianov 譯者：qhwdw 校對：wxy
本文轉載來自 Linux 中國: https://github.com/Linux-CN/archive
對這篇文章感覺如何？
You may also like
More in:Linux中國
如何通過 VLC 使用字幕
Unix 桌面：在 Linux 問世之前
Valve 對於 Ubuntu 的 Snap 版本的 Steam 並不滿意：原因何在
Wine 9.0 發布，實驗性地加入了 Wayland 驅動
