1. 程式人生 > >ftrace:跟蹤你的核心函式! | Linux 中國

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

640?wx_fmt=jpeg&wxfrom=5&wx_lazy=1ftrace 是一個 Linux 核心特性,它能夠讓你去跟蹤 Linux 核心的函式呼叫。

為什麼要這麼做呢?好吧,如果你除錯一個奇怪的問題,而你已經得到了你的核心版本號中這個問題在原始碼中的開始的位置。而你想知道這裡究竟發生了什麼?-- Julia Evans
本文導航◈ 什麼是 ftrace?05%◈ 使用 ftrace 的第一步11%◈ 開始使用 trace-cmd:讓我們僅跟蹤一個函式19%◈ 下一個 ftrace 技巧:我們來跟蹤一個程序!35%◈ “function graph” 跟蹤47%◈ 怎樣知道哪些函式能夠被跟蹤62%

◈ 最後一件事:事件!63%◈ ftrace 是怎樣工作的?73%◈ 更easy地使用 ftrace:brendan gregg 的工具及 kernelshark79%◈ 一個新的超能力85%◈ ftrace 系列文章的一個索引87%編譯自 | 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。那樣太easy了!

如果你去讀 使用 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。這一步非常easy。

對於第一個 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

太棒了!

相比閱讀核心程式碼,閱讀函式跟蹤肯定是更easy的找到結果的辦法。而且讓人高興的是。還能看到全部的函式用了多長時間。

怎樣知道哪些函式能夠被跟蹤

如果你去執行 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]