歡迎光臨
每天分享高質量文章

ftrace:跟蹤你的核心函式! | Linux 中國

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


本文導航
編譯自 | https://jvns.ca/blog/2017/03/19/getting-started-with-ftrace/ 
 作者 | Julia Evans
 譯者 | qhwdw

大家好!今天我們將去討論一個除錯工具: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 的簡單例子像是這樣:

  1. cd /sys/kernel/debug/tracing

  2. echo function > current_tracer

  3. echo do_page_fault > set_ftrace_filter

  4. 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 函式!

  1. $ sudo trace-cmd record -p function -l do_page_fault

  2.  plugin 'function'

  3. Hit Ctrl^C to stop recording

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

  1. $ sudo trace-cmd report

  2.          chrome-15144 [000] 11446.466121: function:             do_page_fault

  3.          chrome-15144 [000] 11446.467910: function:             do_page_fault

  4.          chrome-15144 [000] 11446.469174: function:             do_page_fault

  5.          chrome-15144 [000] 11446.474225: function:             do_page_fault

  6.          chrome-15144 [000] 11446.474386: function:             do_page_fault

  7.          chrome-15144 [000] 11446.478768: function:             do_page_fault

  8. CompositorTileW-15154 [001] 11446.480172: function:             do_page_fault

  9.          chrome-1830  [003] 11446.486696: function:             do_page_fault

  10. CompositorTileW-15154 [001] 11446.488983: function:             do_page_fault

  11. CompositorTileW-15154 [001] 11446.489034: function:             do_page_fault

  12. 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,因此,我使用如下的命令去記錄所有的核心函式:

  1. sudo trace-cmd record --help # I read the help!

  2. sudo trace-cmd record -p function -P 25314 # record for PID 25314

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

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

當系統呼叫 clock_gettime 執行的時候,都發生了什麼:

  1. compat_SyS_clock_gettime

  2.    SyS_clock_gettime

  3.       clockid_to_kclock

  4.       posix_clock_realtime_get

  5.          getnstimeofday64

  6.             __getnstimeofday64

  7.                arch_counter_read

  8.    __compat_put_timespec

這是與行程除錯相關的一些東西:

  1. cpufreq_sched_irq_work

  2.    wake_up_process

  3.       try_to_wake_up

  4.          _raw_spin_lock_irqsave

  5.             do_raw_spin_lock

  6.          _raw_spin_lock

  7.             do_raw_spin_lock

  8.          walt_ktime_clock

  9.             ktime_get

  10.                arch_counter_read

  11.          walt_update_task_ravg

  12.             exiting_task

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

“function graph” 跟蹤

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

  1. sudo trace-cmd record -p function_graph -P 25314

同樣,這裡只是一個片斷(這次來自 futex 程式碼):

  1.             |      futex_wake() {

  2.             |        get_futex_key() {

  3.             |          get_user_pages_fast() {

  4.  1.458 us   |            __get_user_pages_fast();

  5.  4.375 us   |          }

  6.             |          __might_sleep() {

  7.  0.292 us   |            ___might_sleep();

  8.  2.333 us   |          }

  9.  0.584 us   |          get_futex_key_refs();

  10.             |          unlock_page() {

  11.  0.291 us   |            page_waitqueue();

  12.  0.583 us   |            __wake_up_bit();

  13.  5.250 us   |          }

  14.  0.583 us   |          put_page();

  15. + 24.208 us  |        }

我們看到在這個示例中,在 futex_wake 後面呼叫了 get_futex_key。這是在原始碼中真實發生的事情嗎?我們可以檢查一下!!這裡是在 Linux 4.4 中 futex_wake 的定義[6] (我的核心版本是 4.4)。

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

  1. static int

  2. futex_wake(u32 __user *uaddr, unsigned int flags, int nr_wake, u32 bitset)

  3. {

  4.    struct futex_hash_bucket *hb;

  5.    struct futex_q *this, *next;

  6.    union futex_key key = FUTEX_KEY_INIT;

  7.    int ret;

  8.    WAKE_Q(wake_q);

  9.    if (!bitset)

  10.        return -EINVAL;

  11.    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 是什麼,但是,我猜測它與排程有關。

  1. sudo cat /sys/kernel/debug/tracing/available_events

  2. sudo trace-cmd record -e sched:sched_switch

  3. sudo trace-cmd report

輸出如下:

  1. 16169.624862:   Chrome_ChildIOT:24817 [112] S ==> chrome:15144 [120]

  2. 16169.624992:   chrome:15144 [120] S ==> swapper/3:0 [120]

  3. 16169.625202:   swapper/3:0 [120] R ==> Chrome_ChildIOT:24817 [112]

  4. 16169.625251:   Chrome_ChildIOT:24817 [112] R ==> chrome:1561 [112]

  5. 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[7] 倉庫。

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

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

一個新的超能力

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

ftrace 系列文章的一個索引

最後,這裡是我找到的一些 ftrace 方面的文章。它們大部分在 LWN (Linux 新聞週刊)上,它是 Linux 的一個極好的資源(你可以購買一個 訂閱[9]!)

◈ 使用 Ftrace 除錯核心 - part 1[2] (Dec 2009, Steven Rostedt)
◈ 使用 Ftrace 除錯核心 - part 2[10] (Dec 2009, Steven Rostedt)
◈ Linux 函式跟蹤器的秘密[11] (Jan 2010, Steven Rostedt)
◈ trace-cmd:Ftrace 的一個前端[3] (Oct 2010, Steven Rostedt)
◈ 使用 KernelShark 去分析實時除錯器[8] (2011, Steven Rostedt)
◈ Ftrace: 神秘的開關[12] (2014, Brendan Gregg)
◈ 核心檔案:(它十分有用) Documentation/ftrace.txt[13]
◈ 你能跟蹤的事件的檔案 Documentation/events.txt[14]
◈ linux 核心開發上的一些 ftrace 設計檔案 (不是有用,而是有趣!) Documentation/ftrace-design.txt[15]

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

作者:Julia Evans[17] 譯者:qhwdw 校對:wxy

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

LCTT 譯者

qhwdw ? ? ? ?
共計翻譯:53 篇
貢獻時間:86 天


推薦文章

< 左右滑動檢視相關文章 >

點選圖片、輸入文章 ID 或識別二維碼直達

贊(0)

分享創造快樂

© 2022 知識星球   網站地圖