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 等資訊。

可以如下程式碼來呼叫：

// 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 功能。

# For Ubuntu/Debian GNU/Linux
cat /boot/config-$(uname -r) | grep CONFIG_HAVE_FUNCTION_TRACER

在某些發行版中，核心配置檔案可能不會出現在 /boot 目錄下。在這種情況下，如果核心配置中啟用了 CONFIG_IKCONFIG 和 CONFIG_IKCONFIG_PROC，可以使用以下指令檢查是否具備 ftrace 功能：

# 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

以下是位於該檔案系統中的追蹤目錄。

# 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
...

其中一些檔案的用途不是用來設定選項，而是列出可用的選項。
例如，可用的追蹤器可以如下列出：

# 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 互動的不同方式：

# 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 如下，可輸入任何行程並追蹤：

# !/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

#!/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 上進行追蹤，看看它可能需要多少時間。

我們可以通過執行以下命令來完成這個操作：

# !/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 追蹤器（它不追蹤任何內容），但也可以在追蹤函式的同時，啟用其他追蹤器來追蹤事件。

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 是最常見的排程事件。

它們相應的追蹤點，在程式碼中如下所示：

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 中。

Header File

讓我們看看這個標頭檔中包含了什麼內容。

此程式碼片段是 sched_migrate_task 的宣告：

整個檔案都是「類似 sched_migrate_task 事件」的宣告列表。

#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 和陣列。

4. TP_fast_assign：如何填充事件結構，通常使用事件參數來填充。

   這並不簡單，因為可以使用其他函式、巨集或 memcpy()、memmove() 等來填充它們。

5. 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

#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：

#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 文章的完美範例：

#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：

#define CREATE_TRACE_POINTS
#include "my_module_trace.h"

CREATE_TRACE_POINTS 只有在核心編譯時「啟用了追蹤選項」時，才會被定義。

my_module_trace.h：

#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

通常，保護機制用於避免多次包含。因為如果「函式宣告」被包含了兩次，將無法編譯，因為會有兩個有相同名稱的函式；而因為追蹤標頭中沒有函式，只有巨集，因此多次包含是完全安全的（在這種情況下也是必要的）。

作為參考，這是保護機制的常見用法：

#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：

#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 被包含進來：這個標頭只是重複這個過程多次。
  • 其程式碼具有以下一般結構：
    ​​​​​​​​// 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。