通過 ftrace 來分析 Linux 內核
通過
ftrace來了解 Linux 內核內部工作方式是一個好方法。
操作系統的內核是最難以理解的軟件之一。自從你的系統啟動后，它會一直在后臺運行。盡管每個用戶都不與內核直接交互，但他們在內核的幫助下完成自己的計算任務。與內核的交互發生在調用系統調用或者用戶日常使用的各種庫或應用間接調用了系統調用。
在之前的文章里我介紹了如何使用 strace 來追蹤系統調用。然而，使用 strace 時你的視野是有限的。它允許你查看特定參數的系統調用。并在工作完成后，看到其返回值或狀態，以表明是成功還是失敗。但是你無法知道內核在這段時間內發生了什么。除了系統調用外，還有很多其他活動內核中發生，而你卻視而不見。
ftrace 介紹
本文的旨在通過使用一個名為 ftrace 的機制來闡明追蹤內核函數的一些情況。它使得任何 Linux 用戶可以輕松地追蹤內核，并且了解更多關于 Linux 內核內部如何工作。
ftrace 默認產生的輸出往往是巨大的，因為內核總是忙碌的。為了節省空間，很多情況下我會通過截斷來給出盡量小的輸出。
我使用 Fedora 來演示下面的例子，但是它們應該在其他最新的 Linux 發行版上同樣可以運行。
啟用 ftrace
ftrace 現在已經是內核中的一部分了，你不再需要事先安裝它了。也就是說，如果你在使用最近的 Linux 系統，那么 ftrace 是已經啟用了的。為了驗證 ftrace 是否可用，運行 mount 命令并查找 tracefs。如果你看到類似下面的輸出，表示 ftrace 已經啟用，你可以輕松地嘗試本文中下面的例子。下面有些命令需要在 root 用戶下使用（用 sudo 執行是不夠的）。
# mount | grep tracefsnone on /sys/kernel/tracing type tracefs (rw,relatime,seclabel)
要想使用 ftrace，你首先需要進入上面 mount 命令中找到的特定目錄中，在那個目錄下運行文章中的其他命令。
# cd /sys/kernel/tracing
一般的工作流程
首先，你需要理解捕捉蹤跡和獲取輸出的一般流程。如果你直接運行 ftrace，不會運行任何特定的 ftrace 命令。相反的，基本操作是通過標準 Linux 命令來寫入或讀取一些文件。
一般的步驟如下：
- 通過寫入一些特定文件來啟用/結束追蹤
- 通過寫入一些特定文件來設置/取消追蹤時的過濾規則
- 從文件中讀取基于第 1 和 2 步的追蹤輸出
- 從文件中清除早期輸出或緩沖區
- 縮小到你的特定用例（你要追蹤的內核函數），重復 1、2、3、4 步
可用的追蹤器類型
有多種不同的追蹤器可供使用。之前提到，在運行任何命令前，你需要進入一個特定的目錄下，因為需要的文件在這些目錄下。我在我的例子中使用了相對路徑（而不是絕對路徑）。
你可以查看 available_tracers 文件內容來查看所有可用的追蹤器類型。你可以看下面列出了幾個。不需要擔心這些：
$ pwd/sys/kernel/tracing$ sudo cat available_tracershwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
在所有輸出的追蹤器中，我會聚焦于下面三個特殊的：啟用追蹤的 function 和 function_graph，以及停止追蹤的 nop。
確認當前的追蹤器
通常情況默認的追蹤器設定為 nop。即在特殊文件中 current_tracer 中的 “無操作”，這意味著追蹤目前是關閉的：
$ pwd/sys/kernel/tracing$ sudo cat current_tracernop
查看追蹤輸出
在啟用任何追蹤功能之前，請你看一下保存追蹤輸出的文件。你可以用 cat 命令查看名為 trace 的文件的內容：
# cat trace# tracer: nop## entries-in-buffer/entries-written: 0/0 #P:8## _-----=> irqs-off# / _----=> need-resched# | / _---=> hardirq/softirq# || / _--=> preempt-depth# ||| / delay# TASK-PID CPU# |||| TIMESTAMP FUNCTION# | | | |||| | |
啟用 function 追蹤器
你可以通過向 current_tracer 文件寫入 function 來啟用第一個追蹤器 function（文件原本內容為 nop，意味著追蹤是關閉的）。把這個操作看成是啟用追蹤的一種方式：
$ pwd/sys/kernel/tracing$ sudo cat current_tracernop$ echo function > current_tracer$$ cat current_tracerfunction
查看 function 追蹤器的更新追蹤輸出
現在你已啟用追蹤，是時候查看輸出了。如果你查看 trace 文件內容，你將會看到許多被連續寫入的內容。我通過管道只展示了文件內容的前 20 行。根據左邊輸出的標題，你可以看到在某個 CPU 上運行的任務和進程 ID。根據右邊輸出的內容，你可以看到具體的內核函數和其父函數。中間顯示了時間戳信息：
# sudo cat trace | head -20# tracer: function## entries-in-buffer/entries-written: 409936/4276216 #P:8## _-----=> irqs-off# / _----=> need-resched# | / _---=> hardirq/softirq# || / _--=> preempt-depth# ||| / delay# TASK-PID CPU# |||| TIMESTAMP FUNCTION# | | | |||| | |<idle>-0 [000] d... 2088.841739: tsc_verify_tsc_adjust <-arch_cpu_idle_enter<idle>-0 [000] d... 2088.841739: local_touch_nmi <-do_idle<idle>-0 [000] d... 2088.841740: rcu_nocb_flush_deferred_wakeup <-do_idle<idle>-0 [000] d... 2088.841740: tick_check_broadcast_expired <-do_idle<idle>-0 [000] d... 2088.841740: cpuidle_get_cpu_driver <-do_idle<idle>-0 [000] d... 2088.841740: cpuidle_not_available <-do_idle<idle>-0 [000] d... 2088.841741: cpuidle_select <-do_idle<idle>-0 [000] d... 2088.841741: menu_select <-do_idle<idle>-0 [000] d... 2088.841741: cpuidle_governor_latency_req <-menu_select
請記住當追蹤打開后，這意味著追蹤結果會被一直連續寫入直至你關閉追蹤。
關閉追蹤
關閉追蹤是簡單的。你只需要在 current_tracer 文件中用 nop 替換 function 追蹤器即可：
$ sudo cat current_tracerfunction$ sudo echo nop > current_tracer$ sudo cat current_tracernop
啟用 function_graph 追蹤器
現在嘗試第二個名為 function_graph 的追蹤器。你可以使用和上面相同的步驟：在 current_tracer 文件中寫入 function_graph：
$ sudo echo function_graph > current_tracer$ sudo cat current_tracerfunction_graph
function_tracer 追蹤器的追蹤輸出
注意到目前 trace 文件的輸出格式已經發生變化。現在，你可以看到 CPU ID 和內核函數的執行時長。接下來，一個花括號表示一個函數的開始，以及它內部調用了哪些其他函數：
# cat trace | head -20# tracer: function_graph## CPU DURATION FUNCTION CALLS# | | | | | | |6) | n_tty_write() {6) | down_read() {6) | __cond_resched() {6) 0.341 us | rcu_all_qs();6) 1.057 us | }6) 1.807 us | }6) 0.402 us | process_echoes();6) | add_wait_queue() {6) 0.391 us | _raw_spin_lock_irqsave();6) 0.359 us | _raw_spin_unlock_irqrestore();6) 1.757 us | }6) 0.350 us | tty_hung_up_p();6) | mutex_lock() {6) | __cond_resched() {6) 0.404 us | rcu_all_qs();6) 1.067 us | }
啟用追蹤的設置來增加追蹤的深度
你可以使用下面的步驟來調整追蹤器以看到更深層次的函數調用。完成之后，你可以查看 trace 文件的內容并發現輸出變得更加詳細了。為了文章的可讀性，這個例子的輸出被省略了：
# cat max_graph_depth0# echo 1 > max_graph_depth ## or:# echo 2 > max_graph_depth# sudo cat trace
查找要追蹤的函數
上面的步驟足以讓你開始追蹤。但是它產生的輸出內容是巨大的，當你想試圖找到自己感興趣的內容時，往往會很困難。通常你更希望能夠只追蹤特定的函數，而忽略其他函數。但如果你不知道它們確切的名稱，你怎么知道要追蹤哪些進程？有一個文件可以幫助你解決這個問題 —— available_filter_functions 文件提供了一個可供追蹤的函數列表：
$ sudo wc -l available_filter_functions63165 available_filter_functions
查找一般的內核函數
現在試著搜索一個你所知道的簡單內核函數。用戶空間由 malloc 函數用來分配內存，而內核由 kmalloc 函數，它提供類似的功能。下面是所有與 kmalloc 相關的函數：
$ sudo grep kmalloc available_filter_functionsdebug_kmallocmempool_kmallockmalloc_slabkmalloc_orderkmalloc_order_tracekmalloc_fix_flagskmalloc_large_node__kmalloc__kmalloc_track_caller__kmalloc_node__kmalloc_node_track_caller[...]
查找內核模塊或者驅動相關函數
在 available_filter_functions 文件的輸出中，你可以看到一些以括號內文字結尾的行，例如下面的例子中的 [kvm_intel]。這些函數與當前加載的內核模塊 kvm_intel 有關。你可以運行 lsmod 命令來驗證：
$ sudo grep kvm available_filter_functions | tail__pi_post_block [kvm_intel]vmx_vcpu_pi_load [kvm_intel]vmx_vcpu_pi_put [kvm_intel]pi_pre_block [kvm_intel]pi_post_block [kvm_intel]pi_wakeup_handler [kvm_intel]pi_has_pending_interrupt [kvm_intel]pi_update_irte [kvm_intel]vmx_dump_dtsel [kvm_intel]vmx_dump_sel [kvm_intel]$ lsmod | grep -i kvmkvm_intel 335872 0kvm 987136 1 kvm_intelirqbypass 16384 1 kvm
僅追蹤特定的函數
為了實現對特定函數或模式的追蹤，你可以利用 set_ftrace_filter 文件來指定你要追蹤上述輸出中的哪些函數。這個文件也接受 * 模式，它可以擴展到包括具有給定模式的其他函數。作為一個例子，我在我的機器上使用 ext4 文件系統。我可以用下面的命令指定 ext4 的特定內核函數來追蹤：
# mount | grep home/dev/mapper/fedora-home on /home type ext4 (rw,relatime,seclabel)# pwd/sys/kernel/tracing# cat set_ftrace_filter#### all functions enabled ####$$ echo ext4_* > set_ftrace_filter$$ cat set_ftrace_filterext4_has_free_clustersext4_validate_block_bitmapext4_get_group_numberext4_get_group_no_and_offsetext4_get_group_desc[...]
現在當你可以看到追蹤輸出時，你只能看到與內核函數有關的 ext4 函數，而你之前已經為其設置了一個過濾器。所有其他的輸出都被忽略了：
# cat trace |head -20## tracer: function## entries-in-buffer/entries-written: 3871/3871 #P:8## _-----=> irqs-off# / _----=> need-resched# | / _---=> hardirq/softirq# || / _--=> preempt-depth# ||| / delay# TASK-PID CPU# |||| TIMESTAMP FUNCTION# | | | |||| | |cupsd-1066 [004] .... 3308.989545: ext4_file_getattr <-vfs_fstatcupsd-1066 [004] .... 3308.989547: ext4_getattr <-ext4_file_getattrcupsd-1066 [004] .... 3308.989552: ext4_file_getattr <-vfs_fstatcupsd-1066 [004] .... 3308.989553: ext4_getattr <-ext4_file_getattrcupsd-1066 [004] .... 3308.990097: ext4_file_open <-do_dentry_opencupsd-1066 [004] .... 3308.990111: ext4_file_getattr <-vfs_fstatcupsd-1066 [004] .... 3308.990111: ext4_getattr <-ext4_file_getattrcupsd-1066 [004] .... 3308.990122: ext4_llseek <-ksys_lseekcupsd-1066 [004] .... 3308.990130: ext4_file_read_iter <-new_sync_read
排除要被追蹤的函數
你并不總是知道你想追蹤什么，但是，你肯定知道你不想追蹤什么。因此，有一個 set_ftrace_notrace —— 請注意其中的 “no”。你可以在這個文件中寫下你想要的模式，并啟用追蹤。這樣除了所提到的模式外，任何其他東西都會被追蹤到。這通常有助于刪除那些使我們的輸出變得混亂的普通功能：
$ sudo cat set_ftrace_notrace#### no functions disabled ####
具有目標性的追蹤
到目前為止，你一直在追蹤內核中發生的一切。但是，它無法幫助你追蹤與某個特定命令有關的事件。為了達到這個目的，你可以按需打開和關閉跟蹤，并且在它們之間，運行我們選擇的命令，這樣你就不會在跟蹤輸出中得到額外的輸出。你可以通過向 tracing_on 寫入 1 來啟用跟蹤，寫 0 來關閉跟蹤。
# cat tracing_on0# echo 1 > tracing_on# cat tracing_on1### Run some specific command that we wish to trace here #### echo 0 > tracing_on# cat tracing_on0
追蹤特定的 PID
如果你想追蹤與正在運行的特定進程有關的活動，你可以將該 PID 寫入一個名為 set_ftrace_pid 的文件，然后啟用追蹤。這樣一來，追蹤就只限于這個 PID，這在某些情況下是非常有幫助的。
$ sudo echo $PID > set_ftrace_pid
總結
ftrace 是一個了解 Linux 內核內部工作的很好方式。通過一些練習，你可以學會對 ftrace 進行調整以縮小搜索范圍。要想更詳細地了解 ftrace 和它的高級用法，請看 ftrace 的核心作者 Steven Rostedt 寫的這些優秀文章。
