# Tracing with Ftrace
> 資料來源：NCKU 黃敬群（Jserv）教授編撰之 Demystifying the Linux CPU Scheduler。
「核心除錯」即使對於經驗豐富的核心開發者來說也是一個重大挑戰。
例如，如果系統出現延遲或同步問題（如 undetected Race conditions），很難精確找到問題的根源－哪些子系統涉及其中？在什麼條件下問題會出現？
Ftrace 是專門為了解決這類問題而設計的除錯工具，不僅能用來觀察核心發生的事情，還能透過「觀察函式的運作流程」來接近原始碼。
Ftrace 的名稱來自「函式追蹤器（function tracer）」，這是其多個功能中的一個。每種追蹤模式都稱為追蹤器（tracer），每個追蹤器都帶有許多可以調整的選項。它們可以進行函式追蹤、事件追蹤，測量 Context-switch 的時間，或測量中斷被禁用的時間；Ftrace 也非常具有擴展性，因為可以像模組一樣添加新的追蹤器。
正如預期的那樣，排程相關事件的記錄是本書的目標之一。要了解這些事件的作用及其重要性，必須理解 Ftrace，因為它是使用這些事件的工具。掌握排程相關事件的功能和價值，需要先理解 Ftrace 這個工具。
## How does it work?
### Code Instrumentation
追蹤（Tracing）是指記錄運行時發生的事件，以便分析程式碼行為和性能。
> 更一般來說，這被稱為 *Software Profiling*，它可以通過不同的技術實現。
在我們的案例中，這是透過 *Code Instrumentation* 來實現的，這包括向原始碼或其二進制檔中「添加指令」，以進行剖析。
使用 Ftrace 有兩種主要方式，每種方式使用不同的 *Instrumentation* 技術：
- **Function tracing**：使用由 gcc 提供的 code instrumentation 機制，通過使用 `-pg` 編譯標誌來啟用。
- **Event tracing**：使用原始碼中的 *tracepoints*。
### Function Tracing: Runtime Injection
函式追蹤使用的是一種 dynamic profiling 形式：**Tracing instructions** 可以在程式執行時，於「二進制可執行檔」中切換，而無需重新編譯程式碼。
其工作方式如下：在編譯時，gcc 會在每個函式的開頭加入**額外的 NOP** 組合語言指令。
這些指令的位置會被保存於「二進制檔」中，以便隨時將這些 NOP 指令**替換成其他指令**。
ftrace 即透過在運行時**切換這些指令**來「開啟或關閉追蹤」。
- 開啟追蹤：將這些 NOP 指令轉換為 JMP 指令，以便跳轉至追蹤函式。
- 關閉追蹤：把 JMP 改回 NOP。
這種儀器化技術被稱為 *Runtime Injection*，有兩大優點：
- 當追蹤被禁用時（99% 的情況下），幾乎沒有任何額外負擔。
- 可以篩選被追蹤的對象。
> 例如，可以動態地僅啟動單一子系統中的函式追蹤，或者僅追蹤某個特定函式。
### Event Tracing: Tracepoints
事件追蹤的方式與函式追蹤有所不同，且其效率較低，因其不使用 Runtime Injection 技術。
相反，事件追蹤使用 C 語言中的 **Tracepoints**，因此是靜態的。
Tracepoints 基本上是對追蹤函式的直接呼叫，該函式會透過參數收集一些資訊，並將其與事件名稱一起寫入 Trace output。
由於這種機制是靜態的，因此需要**重新編譯整個核心**來切換 Tracepoints－
透過在編譯核心前，切換 `CONFIG_TRACEPOINTS` 巨集來完成。
> 以兩個排程事件為例：`sched_stat_runtime` 和 `sched_migrate_task`。
> 前者發生在「排程程式碼的特定位置」，並包含關於**某個行程的核心排程資訊**；
> 後者發生在「任務遷移」時，並包含**該執行緒被遷移到的 CPU** 等資訊。
可以如下程式碼來呼叫：
```c
// curtask and curr are task_structs, delta_exec is the difference in runtime
// since the last timer interrupt.
trace_sched_stat_runtime(curtask, delta_exec, curr->vruntime);
// p is a task_struct, new_cpu is the CPU the thread migrated to
trace_sched_migrate_task(p, new_cpu);
```
當這些事件發生後，會產生如下之追蹤輸出：
> 從此 Trace output 可得知一些資訊（可直接從 `tast_struct` 獲得）：**命令**、**pid**、**運行時間**、**優先級**。
### Ring Buffer & Filtering
那麼，這些追蹤函式到底做了什麼？
這些函式會將新的事件寫入 buffer，Ftrace 即使用 **Ring Buffer** 來儲存所有在運行時發生的事件。基本上，**生產者**是核心，而**消費者**是使用者，使用者會從使用者空間中讀取資料。
**Entries losing**：
- 由於這是一個 Circular Buffer，如果事件沒有及時被讀取，所有舊的 entries 都會被覆寫（這在事件追蹤時經常發生，因為自開機以來，事件就持續寫入 buffer，即使沒有人在讀取）。
- 另一種 losing entries 的情況是，寫入的速度比讀取的速度快：這在我們「不使用任何 filter 追蹤每一個函式或事件」時很常見。
**Filtering**：
通常，可以盡量多做 filter，以避免 losing entries，這在動態追蹤中是可以實現的，但靜態追蹤則無法。確實，我們可以輕鬆篩選追蹤輸出，但在靜態追蹤中，entries 無論如何都會寫入 buffer，而導致覆寫－這就是為什麼**函式追蹤中有真正的篩選功能，而事件追蹤中則沒有**。
## Enable the kernel tracing infrastructure
為了進行與「核心追蹤」有關的實驗，必須在 Linux 核心中啟用 ftrace 模組。可以透過檢查「包含核心配置資訊的檔案」來確認某個 Linux 發行版是否具備 ftrace 功能。
```shell
# For Ubuntu/Debian GNU/Linux
cat /boot/config-$(uname -r) | grep CONFIG_HAVE_FUNCTION_TRACER
```
在某些發行版中，核心配置檔案可能不會出現在 `/boot` 目錄下。在這種情況下，如果核心配置中啟用了 `CONFIG_IKCONFIG` 和 `CONFIG_IKCONFIG_PROC`，可以使用以下指令檢查是否具備 ftrace 功能：
```shell
# View compressed file contents
zcat /proc/config.gz
# Alternative path
cat /lib/modules/$(uname -r)/build/.config
```
如果要從頭編譯具有 ftrace 功能的核心，可以在核心原始碼目錄中，執行 `make menuconfig`。
進入 **Kernel hacking > Tracers** 子目錄，然後使用 **Enter** 鍵選擇 **Kernel Function Tracer** 以及其他必要的 ftrace 設定。最後，儲存設定並編譯核心。
> Select Kernel Function Tracer option to enable ftrace in kernel.
## Interfacing with ftrace
追蹤用來監控「頻繁發生的事件」，故需要一種極其輕量的機制。
ftrace 提供了這種可能性，因為其是 self-contained 的，且完全在核心中實現，不需要任何使用者空間的工具。正如先前所述，ftrace 的輸出來自核心，而在使用者空間中被讀取。
那麼，如何在沒有專門程式的情況下讀取它呢？
### `tracefs`
`tracefs` 是一種專門的檔案系統，位於另一個檔案系統 `sysfs` 中，包含與 ftrace 互動的檔案和目錄。此檔案系統可透過執行 `mount -t tracefs nodev /sys/kernel/tracing/` 來掛載；由於沒有實際的裝置被掛載，因此使用 *nodev* 作為目標裝置，並以 `/sys/kernel/tracing/` 作為目標掛載點。
### `debugfs`
在 Linux v4.1 之前，所有 ftrace 的追蹤控制檔案都位於 `debugfs` 檔案系統中，該檔案系統通常位於 `/sys/kernel/debug/tracing`。`tracefs` 會自動掛載到 `/sys/kernel/debug/tracing`，並且為了向後相容，其也會掛載到 `/sys/kernel/debug/`。
### Interfacing
我們可以僅使用 `echo` 和 `cat` 來與 ftrace 互動，這些工具可以在輕量或嵌入式 Linux 發行版中找到。只需在這些檔案中寫入 `echo your_value > file`，即可在追蹤前或追蹤過程中，切換選項並設定參數。
#### Trace Directory
以下是位於該檔案系統中的追蹤目錄。
```shell
# ls /sys/kernel/tracing
available_events max_graph_depth stack_trace_filter
available_filter_functions options synthetic_events
available_tracers per_cpu timestamp_mode
buffer_percent printk_formats trace
buffer_size_kb events trace_clock
...
```
其中一些檔案的用途不是用來設定選項，而是列出可用的選項。
例如，**可用的追蹤器**可以如下列出：
```shell
# cat /sys/kernel/tracing/available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
```
這些基本上是不同的追蹤模式：我們可以通過執行 `echo function > current_tracer` 來啟動 `function` 追蹤器；而要禁用追蹤，只需執行 `echo nop > current_tracer`。
#### Trace Output
有兩個檔案可以用來**讀取追蹤輸出**：`trace` 和 `trace_pipe`。
- `cat trace`：是 nonconsuming read，當我們在暫停追蹤後，讀取 `trace` 時，會反覆獲得相同的結果。
- `cat trace_pipe`：是一種與 ftrace 的單向溝通方式，追蹤資料會不斷被消耗並寫入終端機；而當沒有更多資料時，該 pipe 會阻塞。
其他大多數檔案則用於過濾「正在追蹤的內容」。
#### Interfacing Example
現在讓我們看看與 ftrace 互動的不同方式：
```bash
# Interfacing through an application program
sudo trace-cmd record -p function -P 622
sudo trace-cmd report
# Interfacing through the filesystem
cd /sys/kernel/debug/tracing
echo 622 > set_ftrace_pid
echo function > current_tracer
cat trace
```
> 此為展示「從 User space 與 Kernel space 之間」不同溝通方式的好例子。
在這段程式碼中，兩種方法都追蹤了 PID 為 622 的行程，其本質上是以相同的方式進行，因為 `trace-cmd` 只是查詢了 `tracefs`，就像 `ps` 查詢 `procfs` 一樣。而第二種方法（我們會使用的），明確顯示了如何與核心進行互動，但在實踐中，有時使用像 `trace-cmd` 這樣的工具更方便。
另一種互動工具是 `kernelshark`，其有一 GUI 可顯示「透過 `trace-cmd` 完成」的追蹤圖表。
## Ftrace usage
### Function Tracing
#### Script
寫一份簡單的 script 如下，可輸入任何行程並追蹤：
```bash
# !/bin/bash
# trace_process.sh
TRACE_DIR=/sys/kernel/debug/tracing
echo $$ > $TRACE_DIR/set_ftrace_pid
# echo every function to filter
echo handle_mm_fault > $TRACE_DIR/set_ftrace_filter
echo function > $TRACE_DIR/current_tracer
exec $*
```
> `$$` 是變數，包含腳本本身的 PID；
> `$*` 則是腳本的參數，在此舉例中，是「要追蹤的行程」。
運作方式如下：
1. 開始追蹤當前行程的函式呼叫，透過將當前的 PID `$$` 寫入 `set_ftrace_pid`。
2. 透過 `set_ftrace_filter` 過濾函式，設定只追蹤 `handle_mm_fault`。
3. 將追蹤器設置為函式追蹤器。
4. 執行輸入的程式。
5. 由於行程 `$*` 是腳本的子行程，其會自動被添加到 `set_ftrace_pid` 並繼續被追蹤。
#### Filtering the Function
當核心中的中斷處理程式，因「Page faults」被呼叫時，通常會先呼叫函式 `do_page_fault`（在 x86 架構中則是 `exc_page_fault`）。
未經過濾的輸出會顯示輸入行程所呼叫的「每一個核心函式」，這對我們的需求來說通常是無關且缺乏資訊的。為了過濾掉特定的函式，我們可以先在 `available_filter_functions` 中搜尋其名稱，以檢查該函式是否可用。如果可用，我們就可以將其名稱寫入 `set_ftrace_filter` 進行過濾。
追蹤輸出可以在 `/sys/kernel/debug/tracing/trace` 檔案中找到，或者可以實時查看 `/sys/kernel/debug/tracing/trace_pipe` 的輸出。
以下是使用 `./trace_process.sh ls` 來追蹤 `ls` 的輸出範例：
如預期的，我們只看到了 Page faults（共 92 次）。這些資訊本身並不太有用，但時間戳記卻相當有用；透過時間戳記，可以輕易檢測核心中的延遲。另外，使用 **kernelshark** 可以畫出追蹤資料圖，讓延遲顯而易見；如此，可以看到「哪些操作造成最多的額外負擔」。
#### `function_graph`
另一種僅使用 ftrace 的方法是使用 **function_graph** 追蹤器：它類似於 function 追蹤器，但會「顯示每個函數的進入和退出點」，從而建立函式呼叫圖。
與顯示時間戳不同，**function_graph** 會顯示每個函式執行的持續時間。符號 `+`, `!`, `#` 用來表示執行時間大於 10, 100 和 1000 µs 的情況。
如我們所知，「排程」和「執行緒遷移」會帶來許多額外負擔，因此我們可以嘗試使用 **function_graph** 來觀察這些情況。
#### Tracing Example & Entry Point Missing
```bash
#!/bin/bash
# graph_funct.sh
TRACE_DIR=/sys/kernel/debug/tracing
echo > $TRACE_DIR/trace
echo $$ > $TRACE_DIR/set_ftrace_pid
echo > $TRACE_DIR/set_ftrace_filter
echo function_graph > $TRACE_DIR/current_tracer
echo schedule > $TRACE_DIR/set_graph_function
echo nofuncgraph-tail > $TRACE_DIR/trace_options
exec $*
```
此為針對「某完整函式」呼叫追蹤的片段，未設置任何函式或行程過濾器，並且已清除 `funcgraph-tail` 選項，以避免與孤立的退出點混淆。
每個葉節點函式及函式退出點（`}`）處會顯示函式持續時間；能發現，`schedule()` 的執行時間比其他函式長，並且**有 `#` 符號，因為其持續時間超過了 1000µs**。
在某些情況下，我們可能會遇到**只看到退出點（`}`），但追蹤中找不到其進入點**的情況。
這種問題通常發生在：
- buffer 達到容量上限時；
- 當函式在追蹤行程開始後，才開始執行，因此其進入點未被捕獲。
> 這是在「未經過濾的追蹤」中常見的情況，這正是我們在此所進行的操作。
> 如 Ftrace 文件所述：The function name is always displayed after the closing bracket for a function if the start of that function is not in the trace buffer.
在我們的例子中，這表示退出點「`} /* schedule */`」並**不指向初始的 `schedule()` 進入點**！即使我們能看到該函式的開銷，但實際的進入點並不在追蹤中，因為它未能被寫入。
#### Dealing with Entry Missing
為了減少這種情況，我們可以「只在單個 CPU 上進行追蹤」，而不是所有 4 個 CPU。
這種方法有三個優勢：
- 輸出結果不會有跨 CPU 的函式呼叫交錯，這樣函式呼叫的流程不會被打斷。
- 由於追蹤的 entries 變少，buffer 不會被填滿，也就不會丟失太多 entries。
- 性能提升：追蹤每一個函式呼叫會產生顯著的開銷。
通常，最好**將過濾範圍盡量縮小**。例如，僅追蹤感興趣的函式，並且只在單個 CPU 上進行追蹤會是個好方法。在第 7 章中，我們將始終以這種方式進行追蹤，以減少雜訊。
#### Tracing `schedule()`
讓我們嘗試只追蹤 `schedule()` 函式，並在所有 CPU 上進行追蹤，看看它可能需要多少時間。
我們可以通過執行以下命令來完成這個操作：
```bash
# !/bin/bash
# trace_schedule.sh
TRACE_DIR=/sys/kernel/debug/tracing
echo > $TRACE_DIR/trace
echo $$ > $TRACE_DIR/set_ftrace_pid
echo schedule > $TRACE_DIR/set_ftrace_filter
echo function_graph > $TRACE_DIR/current_tracer
echo schedule > $TRACE_DIR/set_graph_function
exec $*
```
輸出如下：
輸出的結果並不是平均時間，而是未經排序的混合，且以記錄到的最長時間為主。原因在於我們「僅查找了有註解的退出點」，因此這些其實只是那些「在追蹤中沒有對應進入點的退出點」（如 ftrace 文件所述）。
有些情況下，執行時間超過了 1 秒（`$`），這些是極端情況（呼叫被中斷，並且在此期間進行了其他核心工作），因此實際上並非僅「呼叫」就花費了整整 1 秒。
如果我們查找所有的退出點（而不僅僅是「無對應進入點的退出點」），我們可以看到，平均而言，`schedule()` routine 所需的時間會更短，但仍然比其他函式花費更多時間。
這份追蹤還有另一個問題。
ftrace 的創作者 Steven Rostedt 在其一篇文章中提到：
> **Only the leaf functions, the ones that do not call other functions, have an accurate duration**, since the duration of parent functions also includes the overhead of the `function_graph` tracer calling the child functions.
這表示，「只計算進入點和退出點之間的時間差」是不夠的，因為 ftrace 的額外開銷並未被考慮進去。
文章中還提到：
> **By using the `set_ftrace_filter` file, you can force any function into becoming a leaf function in the `function_graph` tracer**, and this will allow you to see an accurate duration of that function.
如果我們這樣做，會更準確地，發現大部分時間內 `schedule()` 的執行時間在 20µs 到 400µs 之間。
### Event Tracing
#### Event Directory
Function tracing 非常有用，有助於理解程式碼，但我們現在將重點放在「事件」上。
你可能已經注意到在 `/sys/kernel/tracing` 的目錄列表中，有一個名為 `events` 的目錄。此目錄包含「每個事件子系統」的目錄，而「排程子系統」目錄則位於 `/sys/kernel/tracing/events/sched`。
> Every event associated with scheduling
上圖顯示了其內容：每個事件都有一個目錄，其中包含相關資訊和一個用來啟用/停用的開關。這基本上是一個我們將要記錄的事件列表，儘管其中一些名稱幾乎是不言自明的。
#### `printk()` v.s. `trace_printk()`
那麼，事件到底是什麼呢？
如前所述，事件追蹤比函式追蹤更加靜態。表示「事件追蹤點是直接嵌入在程式碼中」的，並且以類似函式的方式呼叫。它們無法在執行時動態切換，若要修改或禁用它們，則需要重新編譯整個核心。
> 在這方面，事件更像是常見的 print 語述，儘管在實際操作中，它們比 `printk()` 更加高效。
Steven Rostedt 對此解釋得相當清楚，說明了為什麼會出現這種情況：
> `printk()` is the king of all debuggers, but it has a problem. If you are debugging a high volume area such as the timer interrupt, the scheduler, or the network, `printk()` can lead to bogging down the system or can even create a live lock.
>
> It is also quite common to see a bug “disappear” when adding a few `printk()`s. This is due to the sheer overhead that `printk()` introduces.
>
> Ftrace introduces a new form of `printk()` called `trace_printk()`. It can be used just like `printk()`, and can also be used in any context (interrupt code, NMI code, and scheduler code). What is nice about `trace_printk()` is that it does not output to the console. Instead it writes to the Ftrace ring buffer and can be read via the trace file.
>
> Writing into the ring buffer with `trace_printk()` only takes around a tenth of a microsecond or so. But using `printk()`, especially when writing to the serial console, may take several milliseconds per write.
`trace_printk()` 只是在追蹤 buffer 中寫入一則訊息，這與事件的運作方式完全相同，只是事件使用了「預先定義的格式」和「多個 print 欄位」。因此，Steven Rostedt 的描述同樣適用於事件。
#### Event Format
> Control files for the `sched_switch` event
> Fields and print format of the `sched_switch` event
如上圖，可以看到事件與 print 的相似之處。
每個事件都有一個格式檔案，該檔案指出欄位和 print 格式，語法與 `printk()` 相同。
#### Example of Event Tracing & Filtering
現在來看看如何啟用事件追蹤以及過濾事件。
事件與任何追蹤器都無關，因為追蹤器僅用於動態追蹤。如果只想查看事件，必須使用 **nop 追蹤器**（它不追蹤任何內容），但也可以在追蹤函式的同時，啟用其他追蹤器來追蹤事件。
```bash
TRACE_DIR=/sys/kernel/debug/tracing
# enable scheduling events
echo nop > $TRACE_DIR/current_tracer
echo 1 > $TRACE_DIR/events/sched/enable
# enable just the sched_switch event
echo nop > $TRACE_DIR/current_tracer
echo 1 > $TRACE_DIR/events/sched/sched_switch/enable
```
每個事件目錄樹的目錄中都有一個 `enable` 檔案。
從目錄結構中可以看到，該層次結構用來切換單一事件、整個事件子系統，或所有現有的事件。
> 需要注意的是，這種過濾器並**不會阻止事件被寫入追蹤 buffer**，只是忽略了它們。
所謂的「必須重新編譯整個核心來禁用特定事件」，實際上可以解釋為「必須重新編譯整個核心才能**防止 ftrace 將特定事件寫入 buffer，即使這些事件在 `tracefs` 中已被禁用**」。
#### Example of Tracing Output & Switching
以下是一小段「每個排程事件」的追蹤資料：
這段追蹤涉及到「**交換行程**（`pid 0`）」和一個名為「Xorg（`pid 1450`）的應用程式」，Xorg 是系統的顯示伺服器（本質上是 GUI）。
從換掉**交換行程**以執行 **Xorg 行程**，到 Xorg 消耗其 CPU 時間，然後**排程行程**再次切換回**交換行程**，整個過程僅需 143µs。
完成以下任務共耗時 143µs：
1. **交換行程**被切換出去
2. **排程行程**選擇 **Xorg 行程**執行
3. **Xorg** 消耗其 CPU 時間
4. **排程行程**切換回**交換行程**
#### `sched_switch` & `sched_stat_runtime`
`sched_switch` 和 `sched_stat_runtime` 是最常見的排程事件。
它們相應的追蹤點，在程式碼中如下所示：
```c
trace_sched_switch(preempt, prev, next);
trace_sched_stat_runtime(curtask, delta_exec, curr->vruntime);
```
`sched_switch` 會在每次「行程切換」時報告，並 print
- 有關**舊行程**的資訊，這些資訊是從 `prev` 參數中提取的；
- 有關**新行程**的訊息，這些訊息則來自 `next`。
而 `sched_stat_runtime` print「正在運行的行程」的核心排程訊息，例如 pid、實際運行時間和虛擬運行時間。這些訊息同樣是從追蹤點的參數中提取的。
## Creating new events
追蹤點是在核心中建立的。在這個層面上，事件被視為 **「攜帶事件所需訊息」的結構**。追蹤點必須建立這個結構，填充資料，並將其寫入 ftrace Ring buffer。
因此，這個 buffer 基本上是一個**二進制資料的陣列**，會定期被消耗、解碼並 print 為 Trace output 中的字串。
除了 ftrace 的核心基礎設施外，還有一些介面來**簡化建立追蹤點的過程**。
如今，這個過程幾乎可以完全自動化，這得益於 `TRACE_EVENT()` 巨集和其他由 `TRACE_EVENT()` 呼叫的巨集。使用 `TRACE_EVENT()` 可以快速在核心模組；或甚至在 core kernel code 中建立追蹤點，而無需大量樣板程式碼。
所有現有的**排程事件追蹤點**都是使用 `TRACE_EVENT()` 建立的：這些追蹤點在一「單獨且專用的標頭檔」中宣告，然後包含在主程式碼中。
這些標頭檔的預設路徑是 `include/trace/events`，因此**排程事件**的宣告位於 [`include/trace/events/sched.h`](https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/tree/include/trace/events/sched.h) 中。
#### Header File
讓我們看看這個標頭檔中包含了什麼**內容**。
此程式碼片段是 `sched_migrate_task` 的宣告：
> 整個檔案都是「類似 `sched_migrate_task` 事件」的宣告列表。
```c
#undef TRACE_SYSTEM
#define TRACE_SYSTEM sched
#if !defined(_TRACE_SCHED_H) || \
defined(TRACE_HEADER_MULTI_READ) // Special guard
#define _TRACE_SCHED_H
// ... some other includes ...
#include <linux/tracepoint.h> //TRACE_EVENT() defined in here, then redefined at the end of this trace header
/*
* Tracepoint for a task being migrated:
*/
TRACE_EVENT(sched_migrate_task, TP_PROTO(struct task_struct *p, int dest_cpu),
TP_ARGS(p, dest_cpu),
TP_STRUCT__entry(__array(char, comm, TASK_COMM_LEN)
__field(pid_t, pid) __field(int, prio)
__field(int, orig_cpu)
__field(int, dest_cpu)),
TP_fast_assign(memcpy(__entry->comm, p->comm, TASK_COMM_LEN);
__entry->pid = p->pid;
__entry->prio = p->prio; /* XXX SCHED_DEADLINE */
__entry->orig_cpu = task_cpu(p);
__entry->dest_cpu = dest_cpu;),
TP_printk("comm=%s pid=%d prio=%d orig_cpu=%d dest_cpu=%d",
__entry->comm, __entry->pid, __entry->prio,
__entry->orig_cpu, __entry->dest_cpu));
// ... many more event declarations ...
#endif /* _TRACE_SCHED_H */
/* This part must be outside protection */
#include <trace/define_trace.h>
```
> 註：`#include` 的存在，和「檔案末的特殊保護」與「`TRACE_EVENT()` 的內部運作」有關（後面會提到）。
該巨集有 6 個參數和 5 個不同的子巨集：
1. `trace_NAME`：即首個參數，為**追蹤點名稱**。
2. `TP_PROTO` & `TP_ARGS`：**追蹤點的參數**。
3. `TP_STRUCT__entry`：**事件的結構**，包含每個屬性的類型和名稱。
> 此處有兩個不同的子子巨集來定義 fields 和陣列。
5. `TP_fast_assign`：**如何填充事件結構**，通常使用事件參數來填充。
> 這並不簡單，因為可以使用其他函式、巨集或 `memcpy()`、`memmove()` 等來填充它們。
7. `TP_printk`：具有與 `printk()` 相同的語法，定義了**如何在追蹤輸出中，以人類可讀的形式 print 結構**。
> 在本節開頭的例子中，可見 `sched_migrate_task` 就是如此 print 的。
使用 `TP_printk` 定義的格式可以從「使用者空間在事件目錄的 `format` 子目錄」中查看。`TRACE_SYSTEM` 是事件的追蹤系統，這會在事件目錄中，產生相應的目錄，並用於這些事件。
如下圖，可以看到在標頭中宣告的 `sched` 目錄：
> All of the systems in which events are subdivided
### Kernel module to test tracepoints
讓我們來建立自己的**核心模組**，這個模組將執行一些「可以從核心外部追蹤」的操作。
#### *doSomething.c* & *my_module_trace.h*
```c=
#include <linux/module.h>
#include <linux/kthread.h>
#define CREATE_TRACE_POINTS
#include "my_module_trace.h"
static int do_stuff(void *arg)
{
struct task_struct *p = current;
u64 count = 0;
printk(KERN_INFO "Current process is %s with pid %d\n", current->comm, current->pid);
while (!kthread_should_stop()) {
set_current_state(TASK_INTERRUPTIBLE);
schedule_timeout(HZ);
printk("hi! %llu\n", count);
count++;
trace_my_event(p, jiffies); // Tracepoint
p = next_task(p);
}
return 0;
}
static struct task_struct *my_tsk;
static int __init init_func(void)
{
u32 i = 0, j = 0;
struct task_struct *p, *t;
printk(KERN_INFO "Hello world\n");
for_each_process(p) {
i++;
for_each_thread(p, t) {
j++;
}
}
printk(KERN_INFO "There are %d processes\n", i);
printk(KERN_INFO "There are %d threads\n", j);
// printk(KERN_INFO "Average threads per process: %s\n", division_hack(j, i));
printk(KERN_INFO "Current process is %s with pid %d\n", current->comm, current->pid);
my_tsk = kthread_run(do_stuff, NULL, "my-kthread");
if (IS_ERR(my_tsk))
return -1;
return 0;
}
static void __exit exit_func(void)
{
kthread_stop(my_tsk);
printk(KERN_INFO "Goodbye world\n");
}
module_init(init_func);
module_exit(exit_func);
MODULE_LICENSE("GPL");
```
以下是模組中包含的**追蹤標頭** `my_module_trace.h`：
```c=
#undef TRACE_SYSTEM
#define TRACE_SYSTEM my_system
#if !defined(_MY_MODULE_TRACE_H) || defined(TRACE_HEADER_MULTI_READ) // Special guard
#define _MY_MODULE_TRACE_H
#include <linux/tracepoint.h> // TRACE_EVENT() is defined here
TRACE_EVENT(my_event,
TP_PROTO(struct task_struct *t, unsigned long ticks),
TP_ARGS(t, ticks),
TP_STRUCT__entry(
__array(char, name, TASK_COMM_LEN)
__field(pid_t, pid)
__field(u64, vruntime)
__field(unsigned long, ticks)
),
TP_fast_assign(
memcpy(__entry->name, t->comm, TASK_COMM_LEN);
__entry->pid = t->pid;
__entry->vruntime = t->se.vruntime;
__entry->ticks = ticks;
),
TP_printk("name=%s pid=%d vruntime=%lli ticks=%li",
__entry->name, __entry->pid, __entry->vruntime, __entry->ticks)
);
#endif /* _MY_MODULE_TRACE_H */
/* This part must be outside protection */
#undef TRACE_INCLUDE_PATH
#define TRACE_INCLUDE_PATH .
#define TRACE_INCLUDE_FILE my_module_trace
#include <trace/define_trace.h>
```
#### Compile & Insert & Print
我們可以
- **Compile** module：透過 link 系統中「當前運行的核心標頭」來編譯模組。
> 這些標頭，可以在使用者空間中的 `/lib/modules/your-kernel-version/build/include` 找到。
- **Insert** module：`sudo insmod my_module.ko`。
- **Print** kernel log：`sudo dmesg`（在這裡可以看到我們的 `printk()` 輸出）。
#### Explanation of Code
我們基本上使用了核心 API，這些 API 於包含的標頭檔中定義。
`for_each_process()`、`for_each_thread()` 和 `current` 都是巨集，也在排程程式碼中使用。
`init_func()` 是模組插入時執行的初始化函式，因此當我們第一次輸出當前執行的程式時，會讀取到 `insmod`。
接著我們產生一個**核心執行緒**，該執行緒進入休眠狀態，並在 HZ 週期（1 秒）後喚醒；然後其輸出 `hi!` 並觸發一個事件，再次進入休眠。
我們用 `sudo rmmod my_module` 移除模組，這樣 `exit_func()` 就會執行，**核心執行緒**被終止，模組被移除。
#### If Bugs in Kernel
如前所述，核心中的錯誤，可能會導致系統遭鎖定，最糟糕的情況還會損壞資料：這就是為什麼核心模組通常在虛擬機中測試的原因，Core kernel 程式碼也同樣適用。
例如，在我們的模組中，第 11 行和第 12 行非常重要：如果我們註解掉這兩行，系統在模組插入後幾秒鐘內完全凍結，然後崩潰。
發生的情況是，該執行緒佔用了 CPU，導致其他行程無法獲取資源：由於它是**核心執行緒**，因此不會被搶占。雖然**核心執行緒**像普通任務一樣被排程，但如果它們不自願釋放 CPU，那麼它們幾乎可以無限執行，因其優先權極高。
在佔用 CPU 期間，Kernel log 中可能會讀到如下訊息：
#### Event Trace Output
由於使用了 `TRACE_EVENT()`，現有一專屬於我們追蹤系統的目錄。
我們可以通過在 `tracefs` 中，執行 `echo 1 > trace/events/my_system/enable` 來追蹤我們的事件。
以下是 **Trace Output**：
其會每秒走訪一次「行程列表」，並**輸出有關行程的資訊**。
> 首先會追蹤**核心執行緒**（較低的 pid），最終找到使用者行程。
### Overview of `TRACE_EVENT()` infrastructure
此巨集，會展開許多其他子巨集，以便運作。
其作用為「產生 `struct`」，並「產生追蹤點函式的程式碼」，該函式基本上會將事件寫入 trace ring buffer。為了實現這一點，此巨集使用了一種 **C 前處理器** 的技巧，允許在「使用相同輸入資料」的情況下，改變其行為。
#### Example of C Pre-processor
以下是一個來自 Steven Rostedt 文章的完美範例：
```c
#define DOGS \
{ \
C(JACK_RUSSELL), C(BULL_TERRIER), C(ITALIAN_GREYHOUND) \
}
#undef C
#define C(a) ENUM_##a
enum dog_enums DOGS;
#undef C
#define C(a) #a
char *dog_strings[] = DOGS;
char *dog_to_string(enum dog_enums dog)
{
return dog_strings[dog];
}
```
透過在程式中**重新定義子巨集 `C(a)`**，以改變 `DOGS` 的行為；
如此一來，就能夠使用相同的資料，產生不同的程式碼。
#### Macro Changing of `TRACE_EVENT()`
`TRACE_EVENT()` 也是以相似的方式處理其參數，但這種技巧的使用方式相當獨特。
想像我們有兩個不同的標頭檔：*generate_code.h* 和 *change_behavior.h*：
- *generate_code.h*：
1. 使用巨集，展開並以給定的輸入資料來產生程式碼。
2. 執行 `#include change_behavior.h`。
- *change_behavior.h*：
1. **重新定義子巨集**，改變原始巨集的行為。
2. 執行 `#include generate_code.h`，重新 include 剛剛包含過的標頭檔，以產生新的程式碼
3. 多次重複此過程。
雖然不易看出實際發生的事情，但這正是我們對 DOGS 所做的。
透過這種技巧，改變巨集的使用方式變得更加簡單，因為我們有兩個分開的檔案，但這樣的程式碼也變得難以閱讀。
#### Module of `TRACE_EVENT()`
接下來，我們將透過模組，來展示這個機制在「實際的核心程式碼」中的運作。
*my_module.c*：
```c
#define CREATE_TRACE_POINTS
#include "my_module_trace.h"
```
> `CREATE_TRACE_POINTS` 只有在核心編譯時「啟用了追蹤選項」時，才會被定義。
*my_module_trace.h*：
```c
#if !defined(_MY_MODULE_TRACE_H) || \
defined(TRACE_HEADER_MULTI_READ) // Special guard
#define _MY_MODULE_TRACE_H
#include <linux/tracepoint.h> // TRACE_EVENT() is defined here
TRACE_EVENT(my_event, TP_PROTO(struct task_struct *t, unsigned long ticks),
TP_ARGS(t, ticks),
TP_STRUCT__entry(
__array(char, name, TASK_COMM_LEN)
__field(pid_t, pid)
__field(u64, vruntime)
__field(unsigned long, ticks)
),
TP_fast_assign(
memcpy(__entry->name, t->comm, TASK_COMM_LEN);
__entry->pid = t->pid;
__entry->vruntime = t->se.vruntime;
__entry->ticks = ticks;
),
TP_printk("name=%s pid=%d vruntime=%lli ticks=%li",
__entry->name, __entry->pid, __entry->vruntime, __entry->ticks)
);
#endif /* _MY_MODULE_TRACE_H */
/* This part must be outside protection */
#undef TRACE_INCLUDE_PATH
#define TRACE_INCLUDE_PATH .
#define TRACE_INCLUDE_FILE my_module_trace
#include <trace/define_trace.h>
```
這是使用 `TRACE_EVENT()` 的檔案，特殊的保護機制使我們能夠多次 reinclude 它。
#### Special Guard
通常，保護機制用於**避免多次包含**。因為如果「函式宣告」被包含了兩次，將無法編譯，因為會有兩個有相同名稱的函式；而因為追蹤標頭中沒有函式，只有巨集，因此多次包含是完全安全的（在這種情況下也是必要的）。
作為參考，這是**保護機制**的常見用法：
```c
#ifndef _MY_MODULE_TRACE_H
#define _MY_MODULE_TRACE_H
// ... Code ...
#endif /* _MY_MODULE_TRACE_H */
```
#### `TRACE_INCLUDE_FILE` & `TRACE_INCLUDE_PATH`
在檔案的最後，我們定義了兩個額外的巨集：
- `TRACE_INCLUDE_FILE`：此檔案的名稱，稍後在「重新包含」時需要它。
- `TRACE_INCLUDE_PATH` ：改變了追蹤標頭的路徑，此情況下，設置為 `.` 以表當前目錄。
> 這對於模組來說是必要的，因為它們從不使用 core kernel code 的預設路徑 (`include/trace/events/`)。
#### *define_trace.h*
這些資訊在重新包含時也很重要，「重新包含」是在最後包含的標頭 *define_trace.h* 中執行的（對應於前面提到的 *change_behavior.h*）。
*define_trace.h*：
```c=
#ifdef CREATE_TRACE_POINTS // Defined to activate the tracepoints, used here as a guard
/* Prevent recursion */
#undef CREATE_TRACE_POINTS
// ... Redefine the sub-macros to change the behavior ...
#ifndef TRACE_INCLUDE_FILE
#define TRACE_INCLUDE_FILE TRACE_SYSTEM
#define UNDEF_TRACE_INCLUDE_FILE
#endif
#ifndef TRACE_INCLUDE_PATH
#define __TRACE_INCLUDE(system) \
<trace/events/system.h> // Reread system.h (e.g.: sched.h) trace header
#define UNDEF_TRACE_INCLUDE_PATH
#else
#define __TRACE_INCLUDE(system) __stringify(TRACE_INCLUDE_PATH/system.h)
#endif
#define TRACE_INCLUDE(system) __TRACE_INCLUDE(system)
/* Let the trace headers be reread */
#define TRACE_HEADER_MULTI_READ
// Reinclusion: includes the file that just included it
// e.g.: if the subsystem was sched, this just included <trace/events/sched.h>, in our example it is <./my_module_trace.h>
#include TRACE_INCLUDE(TRACE_INCLUDE_FILE)
#ifdef TRACEPOINTS_ENABLED
#include <trace/trace_events.h>
#endif
// ... Undefine every single macro and sub-macro ...
/* We may be processing more files */
#define CREATE_TRACE_POINTS
#endif /* CREATE_TRACE_POINTS */
```
- 1~4 行：在重新包含之前，重要的是要**取消定義 `CREATE_TRACE_POINTS`**，這樣可以啟用保護機制。這是因為重新包含的檔案（*my_module_trace.h*）可能會再次包含此檔案（*define_trace.h*），導致編譯時出現無限循環。
- 6~19 行：產生了「包含此檔案的檔案」的路徑，並從 `TRACE_SYSTEM`、`TRACE_INCLUDE_FILE` 和 `TRACE_INCLUDE_PATH` 中獲取資訊。最後，「生成路徑中的檔案」被重新包含，這導致 `TRACE_EVENT()` 產生不同的代碼。
- 28 行：最後，*trace_events.h* 被包含進來：這個標頭只是重複這個過程多次。
- 其程式碼具有以下一般結構：
```c
// Stage 1: change behavior
#include TRACE_INCLUDE(TRACE_INCLUDE_FILE) // Generate
// Stage 2: change behavior
#include TRACE_INCLUDE(TRACE_INCLUDE_FILE) // Generate
// Stage 3: change behavior
#include TRACE_INCLUDE(TRACE_INCLUDE_FILE) // Generate
// ...
```
- 每個 Stage 僅僅是「重新定義子巨集，以生成特定目的」的程式碼。
- 這些 Stages 可能生成如下程式碼之範例：
- Stage 1：生成具有正確 fields 的 event struct
- Stage 2：生成 event struct 中「每個 field 的偏移量」struct
- Stage 3：在 `tracefs` 的事件目錄中創建目錄
- Stage 4：生成「以追蹤輸出格式 print 原始事件」的函式
- Stage 5：生成「將 struct 寫入 ring buffer」的函式
就是這樣！這個檔案中的程式碼不難理解，只是難以閱讀。
且其程式碼量也很大，這也是為什麼我們不會詳細探討它。
對我們來說，這並不是特別有趣，但最有趣的是 `TRACE_EVENT()` 的結構（以及它的黑科技）。
對於好奇的人，該檔案的路徑是 [include/trace/trace_events.h](https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/tree/include/trace/trace_events.h)。
Sign in with Wallet
Connect another wallet