ftrace：跟蹤你的核心函式！ | Linux 中國

大家好！今天我們將去討論一個除錯工具：ftrace，之前我的部落格上還沒有討論過它。還有什麼能比一個新的除錯工具更讓人激動呢？

這個非常棒的 ftrace 並不是個新的工具！它大約在 Linux 的 2.6 核心版本中就有了，時間大約是在 2008 年。這一篇是我用谷歌能找到的最早的檔案[1]。因此，如果你是一個除錯系統的“老手”，可能早就已經使用它了！

我知道，ftrace 已經存在了大約 2.5 年了（LCTT 譯註：距本文初次寫作時），但是還沒有真正的去學習它。假設我明天要召開一個專題研究會，那麼，關於 ftrace 應該討論些什麼？因此，今天是時間去討論一下它了！

什麼是 ftrace？

ftrace 是一個 Linux 核心特性，它可以讓你去跟蹤 Linux 內核的函式呼叫。為什麼要這麼做呢？好吧，假設你除錯一個奇怪的問題，而你已經得到了你的核心版本中這個問題在原始碼中的開始的位置，而你想知道這裡到底發生了什麼？

每次在除錯的時候，我並不會經常去讀核心原始碼，但是，極個別的情況下會去讀它！例如，本週在工作中，我有一個程式在核心中卡死了。檢視到底是呼叫了什麼函式，能夠幫我更好的理解在核心中發生了什麼，哪些系統涉及其中！（在我的那個案例中，它是虛擬記憶體系統）。

我認為 ftrace 是一個十分好用的工具（它肯定沒有 strace 那樣使用廣泛，也比它難以使用），但是它還是值得你去學習。因此，讓我們開始吧！

使用 ftrace 的第一步

不像 strace 和 perf，ftrace 並不是真正的 程式 – 你不能只執行 ftrace my_cool_function。那樣太容易了！

如果你去讀 使用 ftrace 除錯核心[2]，它會告訴你從 cd /sys/kernel/debug/tracing 開始，然後做很多檔案系統的操作。

對於我來說，這種辦法太麻煩——一個使用 ftrace 的簡單例子像是這樣：

cd /sys/kernel/debug/tracing
echo function > current_tracer
echo do_page_fault > set_ftrace_filter
cat trace

這個檔案系統是跟蹤系統的介面（“給這些神奇的檔案賦值，然後該發生的事情就會發生”）理論上看起來似乎可用，但是它不是我的首選方式。

幸運的是，ftrace 團隊也考慮到這個並不友好的使用者介面，因此，它有了一個更易於使用的介面，它就是 trace-cmd！！！trace-cmd 是一個帶命令列引數的普通程式。我們後面將使用它！我在 LWN 上找到了一個 trace-cmd 的使用介紹：trace-cmd: Ftrace 的一個前端[3]。

開始使用 trace-cmd：讓我們僅跟蹤一個函式

首先，我需要去使用 sudo apt-get install trace-cmd 安裝 trace-cmd，這一步很容易。

對於第一個 ftrace 的演示，我決定去瞭解我的核心如何去處理一個頁面故障。當 Linux 分配記憶體時，它經常偷懶，（“你並不是真的計劃去使用記憶體，對嗎？”）。這意味著，當一個應用程式嘗試去對分配給它的記憶體進行寫入時，就會發生一個頁面故障，而這個時候，核心才會真正的為應用程式去分配物理記憶體。

我們開始使用 trace-cmd 並讓它跟蹤 do_page_fault 函式！

$ sudo trace-cmd record -p function -l do_page_fault
  plugin 'function'
Hit Ctrl^C to stop recording

我將它運行了幾秒鐘，然後按下了 Ctrl+C。 讓我大吃一驚的是，它竟然產生了一個 2.5MB 大小的名為 trace.dat 的跟蹤檔案。我們來看一下這個檔案的內容！

$ sudo trace-cmd report
          chrome-15144 [000] 11446.466121: function:             do_page_fault
          chrome-15144 [000] 11446.467910: function:             do_page_fault
          chrome-15144 [000] 11446.469174: function:             do_page_fault
          chrome-15144 [000] 11446.474225: function:             do_page_fault
          chrome-15144 [000] 11446.474386: function:             do_page_fault
          chrome-15144 [000] 11446.478768: function:             do_page_fault
 CompositorTileW-15154 [001] 11446.480172: function:             do_page_fault
          chrome-1830  [003] 11446.486696: function:             do_page_fault
 CompositorTileW-15154 [001] 11446.488983: function:             do_page_fault
 CompositorTileW-15154 [001] 11446.489034: function:             do_page_fault
 CompositorTileW-15154 [001] 11446.489045: function:             do_page_fault

sudo trace-cmd record --help # I read the help!
sudo trace-cmd record -p function -P 25314 # record for PID 25314

 compat_SyS_clock_gettime
    SyS_clock_gettime
       clockid_to_kclock
       posix_clock_realtime_get
          getnstimeofday64
             __getnstimeofday64
                arch_counter_read
    __compat_put_timespec

 cpufreq_sched_irq_work
    wake_up_process
       try_to_wake_up
          _raw_spin_lock_irqsave
             do_raw_spin_lock
          _raw_spin_lock
             do_raw_spin_lock
          walt_ktime_clock
             ktime_get
                arch_counter_read
          walt_update_task_ravg
             exiting_task

sudo trace-cmd record -p function_graph -P 25314

             |      futex_wake() {
             |        get_futex_key() {
             |          get_user_pages_fast() {
  1.458 us   |            __get_user_pages_fast();
  4.375 us   |          }
             |          __might_sleep() {
  0.292 us   |            ___might_sleep();
  2.333 us   |          }
  0.584 us   |          get_futex_key_refs();
             |          unlock_page() {
  0.291 us   |            page_waitqueue();
  0.583 us   |            __wake_up_bit();
  5.250 us   |          }
  0.583 us   |          put_page();
+ 24.208 us  |        }

static int
futex_wake(u32 __user *uaddr, unsigned int flags, int nr_wake, u32 bitset)
{
    struct futex_hash_bucket *hb;
    struct futex_q *this, *next;
    union futex_key key = FUTEX_KEY_INIT;
    int ret;
    WAKE_Q(wake_q);
    if (!bitset)
        return -EINVAL;
    ret = get_futex_key(uaddr, flags & FLAGS_SHARED, &key, VERIFY_READ);

sudo cat /sys/kernel/debug/tracing/available_events
sudo trace-cmd record -e sched:sched_switch
sudo trace-cmd report

 16169.624862:   Chrome_ChildIOT:24817 [112] S ==> chrome:15144 [120]
 16169.624992:   chrome:15144 [120] S ==> swapper/3:0 [120]
 16169.625202:   swapper/3:0 [120] R ==> Chrome_ChildIOT:24817 [112]
 16169.625251:   Chrome_ChildIOT:24817 [112] R ==> chrome:1561 [112]
 16169.625437:   chrome:1561 [112] S ==> chrome:15144 [120]