ftrace:跟蹤你的核心函式! | Linux 中國
為什麼要這麼做呢?好吧,如果你除錯一個奇怪的問題,而你已經得到了你的核心版本號中這個問題在原始碼中的開始的位置。而你想知道這裡究竟發生了什麼?-- Julia Evans
本文導航◈ 什麼是 ftrace?05%◈ 使用 ftrace 的第一步11%◈ 開始使用 trace-cmd:讓我們僅跟蹤一個函式19%◈ 下一個 ftrace 技巧:我們來跟蹤一個程序!35%◈ “function graph” 跟蹤47%◈ 怎樣知道哪些函式能夠被跟蹤62%
作者 | 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 的簡單樣例像是這樣:
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
。這一步非常easy。
對於第一個 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 行的輸出[4]。
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
。
除了它既能夠進入也能夠退出一個函式外,其他的功能和函式跟蹤器是一樣的。
這裡是那個跟蹤器的輸出[5]
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 的定義[6] (我的核心版本號是 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
!
太棒了!
相比閱讀核心程式碼,閱讀函式跟蹤肯定是更easy的找到結果的辦法。而且讓人高興的是。還能看到全部的函式用了多長時間。
怎樣知道哪些函式能夠被跟蹤
如果你去執行 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]