Linux中國

ftrace：跟蹤你的內核函數！

277 views0
By
Share

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

這個非常棒的 ftrace 並不是個新的工具！它大約在 Linux 的 2.6 內核版本中就有了，時間大約是在 2008 年。這一篇是我用谷歌能找到的最早的文檔。因此，如果你是一個調試系統的「老手」，可能早就已經使用它了！

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

什麼是 ftrace？

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

每次在調試的時候，我並不會經常去讀內核源代碼，但是，極個別的情況下會去讀它！例如，本周在工作中，我有一個程序在內核中卡死了。查看到底是調用了什麼函數，能夠幫我更好的理解在內核中發生了什麼，哪些系統涉及其中！（在我的那個案例中，它是虛擬內存系統）。

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

使用 ftrace 的第一步

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

如果你去讀 使用 ftrace 調試內核，它會告訴你從 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 的一個前端。

開始使用 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

看起來很整潔 – 它展示了進程名（chrome）、進程 ID（15144）、CPU ID（000），以及它跟蹤的函數。

通過察看整個文件，（sudo trace-cmd report | grep chrome）可以看到，我們跟蹤了大約 1.5 秒，在這 1.5 秒的時間段內，Chrome 發生了大約 500 個頁面故障。真是太酷了！這就是我們做的第一個 ftrace！

下一個 ftrace 技巧：我們來跟蹤一個進程！

好吧，只看一個函數是有點無聊！假如我想知道一個程序中都發生了什麼事情。我使用一個名為 Hugo 的靜態站點生成器。看看內核為 Hugo 都做了些什麼事情？

在我的電腦上 Hugo 的 PID 現在是 25314，因此，我使用如下的命令去記錄所有的內核函數：

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

sudo trace-cmd report 輸出了 18,000 行。如果你對這些感興趣，你可以看 這裡是所有的 18,000 行的輸出。

18,000 行太多了，因此，在這裡僅摘錄其中幾行。

當系統調用 clock_gettime 運行的時候，都發生了什麼：

 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

雖然你可能還不理解它們是做什麼的，但是，能夠看到所有的這些函數調用也是件很酷的事情。

「function graph」 跟蹤

這裡有另外一個模式，稱為 function_graph。除了它既可以進入也可以退出一個函數外，其它的功能和函數跟蹤器是一樣的。這裡是那個跟蹤器的輸出

sudo trace-cmd record -p function_graph -P 25314

同樣，這裡只是一個片斷（這次來自 futex 代碼）：

             |      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  |        }

我們看到在這個示例中，在 futex_wake 後面調用了 get_futex_key。這是在源代碼中真實發生的事情嗎？我們可以檢查一下！！這裡是在 Linux 4.4 中 futex_wake 的定義 (我的內核版本是 4.4）。

為節省時間我直接貼出來，它的內容如下：

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);

如你所見，在 futex_wake 中的第一個函數調用真的是 get_futex_key！ 太棒了！相比閱讀內核代碼，閱讀函數跟蹤肯定是更容易的找到結果的辦法，並且讓人高興的是，還能看到所有的函數用了多長時間。

如何知道哪些函數可以被跟蹤

如果你去運行 sudo trace-cmd list -f，你將得到一個你可以跟蹤的函數的列表。它很簡單但是也很重要。

最後一件事：事件！

現在，我們已經知道了怎麼去跟蹤內核中的函數，真是太酷了！

還有一類我們可以跟蹤的東西！有些事件與我們的函數調用並不相符。例如，你可能想知道當一個程序被調度進入或者離開 CPU 時，都發生了什麼事件！你可能想通過「盯著」函數調用計算出來，但是，我告訴你，不可行！

由於函數也為你提供了幾種事件，因此，你可以看到當重要的事件發生時，都發生了什麼事情。你可以使用 sudo cat /sys/kernel/debug/tracing/available_events 來查看這些事件的一個列表。

我查看了全部的 schedswitch 事件。我並不完全知道 schedswitch 是什麼，但是，我猜測它與調度有關。

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]

現在，可以很清楚地看到這些切換，從 PID 24817 -> 15144 -> kernel -> 24817 -> 1561 -> 15114。(所有的這些事件都發生在同一個 CPU 上）。

ftrace 是如何工作的？

ftrace 是一個動態跟蹤系統。當我們開始 ftrace 內核函數時，函數的代碼會被改變。讓我們假設去跟蹤 do_page_fault 函數。內核將在那個函數的彙編代碼中插入一些額外的指令，以便每次該函數被調用時去提示跟蹤系統。內核之所以能夠添加額外的指令的原因是，Linux 將額外的幾個 NOP 指令編譯進每個函數中，因此，當需要的時候，這裡有添加跟蹤代碼的地方。

這是一個十分複雜的問題，因為，當不需要使用 ftrace 去跟蹤我的內核時，它根本就不影響性能。而當我需要跟蹤時，跟蹤的函數越多，產生的開銷就越大。

（或許有些是不對的，但是，我認為的 ftrace 就是這樣工作的）

更容易地使用 ftrace：brendan gregg 的工具及 kernelshark

正如我們在文件中所討論的，你需要去考慮很多的關於單個的內核函數/事件直接使用 ftrace 都做了些什麼。能夠做到這一點很酷！但是也需要做大量的工作！

Brendan Gregg （我們的 Linux 調試工具「大神」）有個工具倉庫，它使用 ftrace 去提供關於像 I/O 延遲這樣的各種事情的信息。這是它在 GitHub 上全部的 perf-tools 倉庫。

這裡有一個權衡，那就是這些工具易於使用，但是你被限制僅能用於 Brendan Gregg 認可並做到工具裡面的方面。它包括了很多方面！:)

另一個工具是將 ftrace 的輸出可視化，做的比較好的是 kernelshark。我還沒有用過它，但是看起來似乎很有用。你可以使用 sudo apt-get install kernelshark 來安裝它。

一個新的超能力

我很高興能夠花一些時間去學習 ftrace！對於任何內核工具，不同的內核版本有不同的功效，我希望有一天你能發現它很有用！

ftrace 系列文章的一個索引

最後，這裡是我找到的一些 ftrace 方面的文章。它們大部分在 LWN （Linux 新聞周刊）上，它是 Linux 的一個極好的資源（你可以購買一個 訂閱！）

via: https://jvns.ca/blog/2017/03/19/getting-started-with-ftrace/

作者：Julia Evans 譯者：qhwdw 校對：wxy

本文由 LCTT 原創編譯，Linux中國 榮譽推出

本文轉載來自 Linux 中國: https://github.com/Linux-CN/archive

對這篇文章感覺如何？

太棒了
0
不錯
0
愛死了
0
不太好
0
感覺很糟
0
雨落清風。心向陽
    Previous
    Next

    You may also like

    Leave a reply

    您的電子郵箱地址不會被公開。 必填項已用 * 標註

    此站點使用Akismet來減少垃圾評論。了解我們如何處理您的評論數據。

    More in:Linux中國