使用 ftrace 調試 Linux 內核，第 2 部分

王 生輝, 軟件工程師, EMC

李 驊宸, 實習生, EMC

簡介： ftrace 是 Linux 內核中提供的一種調試工具。使用 ftrace 能夠對內核中發生的事情進行跟蹤，這在調試 bug 或者分析內核時很是有用。本系列文章對 ftrace 進行了介紹，分爲三部分。本文是第二部分，經過示例介紹瞭如何使用 ftrace 中的跟蹤器，並對不一樣格式的跟蹤信息進行了描述，同時還對如何使用 ftrace 調試指定內核模塊進行了介紹。經過對本文的學習，讀者能夠了解如何在實踐中使用 ftrace 。

發佈日期： 2010 年 6 月 10 日 
級別： 初級 
訪問狀況 ： 6390 次瀏覽 
評論： 0 (查看 | 添加評論 - 登陸)

 平均分 (11個評分)
爲本文評分

內容

• ftrace 操做概述
• fucntion 跟蹤器
• function_graph 跟蹤器
• sched_switch 跟蹤器
• irqsoff 跟蹤器
• 跟蹤指定模塊中的函數
• 小結
• 參考資料
• 做者簡介
• 建議

ftrace 操做概述

使用 ftrace 提供的跟蹤器來調試或者分析內核時須要以下操做：

• 切換到目錄 /sys/kernel/debug/tracing/ 下
• 查看 available_tracers 文件，獲取當前內核支持的跟蹤器列表
• 關閉 ftrace 跟蹤，即將 0 寫入文件 tracing_enabled
• 激活 ftrace_enabled ，不然 function 跟蹤器的行爲相似於 nop；另外，激活該選項還可讓一些跟蹤器好比 irqsoff 獲取更豐富的信息。建議使用 ftrace 時將其激活。要激活 ftrace_enabled ，能夠經過 proc 文件系統接口來設置：

echo 1 > /proc/sys/kernel/ftrace_enabled

• 將所選擇的跟蹤器的名字寫入文件 current_tracer
• 將要跟蹤的函數寫入文件 set_ftrace_filter ，將不但願跟蹤的函數寫入文件 set_ftrace_notrace。一般直接操做文件 set_ftrace_filter 就能夠了
• 激活 ftrace 跟蹤，即將 1 寫入文件 tracing_enabled。還要確保文件 tracing_on 的值也爲 1，該文件能夠控制跟蹤的暫停
• 若是是對應用程序進行分析的話，啓動應用程序的執行，ftrace 會跟蹤應用程序運行期間內核的運做狀況
• 經過將 0 寫入文件 tracing_on 來暫停跟蹤信息的記錄，此時跟蹤器還在跟蹤內核的運行，只是再也不向文件 trace 中寫入跟蹤信息；或者將 0 寫入文件 tracing_enabled 來關閉跟蹤
• 查看文件 trace 獲取跟蹤信息，對內核的運行進行分析調試

接下來將對跟蹤器的使用以及跟蹤信息的格式經過實例加以講解。

回頁首

fucntion 跟蹤器

function 跟蹤器能夠跟蹤內核函數的調用狀況，可用於調試或者分析 bug ，還可用於瞭解和觀察 Linux 內核的執行過程。清單 1 給出了使用 function 跟蹤器的示例。

清單 1. function 跟蹤器使用示例

[root@linux tracing]# pwd /sys/kernel/debug/tracing [root@linux tracing]# echo 0 > tracing_enabled [root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled [root@linux tracing]# echo function > current_tracer [root@linux tracing]# echo 1 > tracing_on [root@linux tracing]# echo 1 > tracing_enabled # 讓內核運行一段時間，這樣 ftrace 能夠收集一些跟蹤信息，以後再中止跟蹤 [root@linux tracing]# echo 0 > tracing_enabled [root@linux tracing]# cat trace | head -10 # tracer: function # # TASK-PID CPU# TIMESTAMP FUNCTION # | | | | | <idle>-0 [000] 20654.426521: _raw_spin_lock <-scheduler_tick <idle>-0 [000] 20654.426522: task_tick_idle <-scheduler_tick <idle>-0 [000] 20654.426522: cpumask_weight <-scheduler_tick <idle>-0 [000] 20654.426523: cpumask_weight <-scheduler_tick <idle>-0 [000] 20654.426523: run_posix_cpu_timers <-update_process_times <idle>-0 [000] 20654.426524: hrtimer_forward <-tick_sched_timer

trace 文件給出的信息格式很清晰。首先，字段「tracer:」給出了當前所使用的跟蹤器的名字，這裏爲 function 跟蹤器。而後是跟蹤信息記錄的格式，TASK 字段對應任務的名字，PID 字段則給出了任務的進程 ID，字段 CPU# 表示運行被跟蹤函數的 CPU 號，這裏能夠看到 idle 進程運行在 0 號 CPU 上，其進程 ID 是 0 ；字段 TIMESTAMP 是時間戳，其格式爲「<secs>.<usecs>」，表示執行該函數時對應的時間戳；FUNCTION 一列則給出了被跟蹤的函數，函數的調用者經過符號 「<-」 標明，這樣能夠觀察到函數的調用關係。

回頁首

function_graph 跟蹤器

在 function 跟蹤器給出的信息中，能夠經過 FUNCTION 列中的符號 「<-」 來查看函數調用關係，可是因爲中間會混合不一樣函數的調用，致使看起來很是混亂，十分不方便。function_graph 跟蹤器則能夠提供相似 C 代碼的函數調用關係信息。經過寫文件 set_graph_function 能夠顯示指定要生成調用關係的函數，缺省會對全部可跟蹤的內核函數生成函數調用關係圖。清單 2 給出了使用 function_grapch 跟蹤器的示例，示例中將內核函數 __do_fault 做爲觀察對象，該函數在內核運做過程當中會被頻繁調用。

清單 2. function_graph 跟蹤器使用示例

[root@linux tracing]# pwd /sys/kernel/debug/tracing [root@linux tracing]# echo 0 > tracing_enabled [root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled [root@linux tracing]# echo function_graph > current_tracer [root@linux tracing]# echo __do_fault > set_graph_function [root@linux tracing]# echo 1 > tracing_on [root@linux tracing]# echo 1 > tracing_enabled # 讓內核運行一段時間，這樣 ftrace 能夠收集一些跟蹤信息，以後再中止跟蹤 [root@linux tracing]# echo 0 > tracing_enabled [root@linux tracing]# cat trace | head -20 # tracer: function_graph # # CPU DURATION FUNCTION CALLS # | | | | | | | 1) 9.936 us | } 1) 0.714 us | put_prev_task_fair(); 1) | pick_next_task_fair() { 1) | set_next_entity() { 1) 0.647 us | update_stats_wait_end(); 1) 0.699 us | __dequeue_entity(); 1) 3.322 us | } 1) 0.865 us | hrtick_start_fair(); 1) 6.313 us | } 1) | __switch_to_xtra() { 1) 1.601 us | memcpy(); 1) 3.938 us | } [root@linux tracing]# echo > set_graph_function

在文件 trace 的輸出信息中，首先給出的也是當前跟蹤器的名字，這裏是 function_graph 。接下來是詳細的跟蹤信息，能夠看到，函數的調用關係以相似 C 代碼的形式組織。

CPU 字段給出了執行函數的 CPU 號，本例中都爲 1 號 CPU。DURATION 字段給出了函數執行的時間長度，以 us 爲單位。FUNCTION CALLS 則給出了調用的函數，並顯示了調用流程。注意，對於不調用其它函數的函數，其對應行以「;」結尾，並且對應的 DURATION 字段給出其運行時長；對於調用其它函數的函數，則在其「}」對應行給出了運行時長，該時間是一個累加值，包括了其內部調用的函數的執行時長。DURATION 字段給出的時長並非精確的，它還包含了執行 ftrace 自身的代碼所耗費的時間，因此示例中將內部函數時長累加獲得的結果會與對應的外圍調用函數的執行時長並不一致；不過經過該字段仍是能夠大體瞭解函數在時間上的運行開銷的。清單 2 中最後經過 echo 命令重置了文件 set_graph_function 。

回頁首

sched_switch 跟蹤器

sched_switch 跟蹤器能夠對進程的調度切換以及之間的喚醒操做進行跟蹤，如清單 3 所示。

清單 3. sched_switch 跟蹤器使用示例

[root@linux tracing]# pwd /sys/kernel/debug/tracing [root@linux tracing]# echo 0 > tracing_enabled [root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled [root@linux tracing]# echo sched_switch > current_tracer [root@linux tracing]# echo 1 > tracing_on [root@linux tracing]# echo 1 > tracing_enabled # 讓內核運行一段時間，這樣 ftrace 能夠收集一些跟蹤信息，以後再中止跟蹤 [root@linux tracing]# echo 0 > tracing_enabled [root@linux tracing]# cat trace | head -10 # tracer: sched_switch # # TASK-PID CPU# TIMESTAMP FUNCTION # | | | | | bash-1408 [000] 26208.816058: 1408:120:S + [000] 1408:120:S bash bash-1408 [000] 26208.816070: 1408:120:S + [000] 1408:120:S bash bash-1408 [000] 26208.816921: 1408:120:R + [000] 9:120:R events/0 bash-1408 [000] 26208.816939: 1408:120:R ==> [000] 9:120:R events/0 events/0-9 [000] 26208.817081: 9:120:R + [000] 1377:120:R gnome-terminal events/0-9 [000] 26208.817088: 9:120:S ==> [000] 1377:120:R gnome-terminal

在 sched_swich 跟蹤器獲取的跟蹤信息中記錄了進程間的喚醒操做和調度切換信息，能夠經過符號‘ + ’和‘ ==> ’區分；喚醒操做記錄給出了當前進程喚醒運行的進程，進程調度切換記錄中顯示了接替當前進程運行的後續進程。

描述進程狀態的格式爲「Task-PID:Priority:Task-State」。以示例跟蹤信息中的第一條跟蹤記錄爲例，能夠看到進程 bash 的 PID 爲 1408 ，其對應的內核態優先級爲 120 ，當前狀態爲 S（可中斷睡眠狀態），當前 bash 並無喚醒其它進程；從第 3 條記錄能夠看到，進程 bash 將進程 events/0 喚醒，而在第 4 條記錄中發生了進程調度，進程 bash 切換到進程 events/0 執行。

在 Linux 內核中，進程的狀態在內核頭文件 include/linux/sched.h 中定義，包括可運行狀態 TASK_RUNNING（對應跟蹤信息中的符號‘ R ’）、可中斷阻塞狀態 TASK_INTERRUPTIBLE（對應跟蹤信息中的符號‘ S ’）等。同時該頭文件也定義了用戶態進程所使用的優先級的範圍，最小值爲 MAX_USER_RT_PRIO（值爲 100 ），最大值爲 MAX_PRIO - 1（對應值爲 139 ），缺省爲 DEFAULT_PRIO（值爲 120 ）；在本例中，進程優先級都是缺省值 120 。

回頁首

irqsoff 跟蹤器

當關閉中斷時，CPU 會延遲對設備的狀態變化作出反應，有時候這樣作會對系統性能形成比較大的影響。irqsoff 跟蹤器能夠對中斷被關閉的情況進行跟蹤，有助於發現致使較大延遲的代碼；當出現最大延遲時，跟蹤器會記錄致使延遲的跟蹤信息，文件 tracing_max_latency 則記錄中斷被關閉的最大延時。

清單 4. irqsoff 跟蹤器使用示例

[root@linux tracing]# pwd /sys/kernel/debug/tracing [root@linux tracing]# echo 0 > tracing_enabled [root@linux tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled [root@linux tracing]# echo irqsoff > current_tracer [root@linux tracing]# echo 1 > tracing_on [root@linux tracing]# echo 1 > tracing_enabled # 讓內核運行一段時間，這樣 ftrace 能夠收集一些跟蹤信息，以後再中止跟蹤 [root@linux tracing]# echo 0 > tracing_enabled [root@linux tracing]# cat trace | head -35 # tracer: irqsoff # # irqsoff latency trace v1.1.5 on 2.6.33.1 # -------------------------------------------------------------------- # latency: 34380 us, #6/6, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:2) # ----------------- # | task: -0 (uid:0 nice:0 policy:0 rt_prio:0) # ----------------- # => started at: reschedule_interrupt # => ended at: restore_all_notrace # # # _------=> CPU# # / _-----=> irqs-off # | / _----=> need-resched # || / _---=> hardirq/softirq # ||| / _--=> preempt-depth # |||| /_--=> lock-depth # |||||/ delay # cmd pid |||||| time | caller # \ / |||||| \ | / <idle>-0 1dN... 4285us!: trace_hardirqs_off_thunk <-reschedule_interrupt <idle>-0 1dN... 34373us+: smp_reschedule_interrupt <-reschedule_interrupt <idle>-0 1dN... 34375us+: native_apic_mem_write <-smp_reschedule_interrupt <idle>-0 1dN... 34380us+: trace_hardirqs_on_thunk <-restore_all_notrace <idle>-0 1dN... 34384us : trace_hardirqs_on_caller <-restore_all_notrace <idle>-0 1dN... 34384us : <stack trace> => trace_hardirqs_on_thunk [root@linux tracing]# cat tracing_max_latency 34380

從清單 4 中的輸出信息中，能夠看到當前 irqsoff 延遲跟蹤器的版本信息。接下來是最大延遲時間，以 us 爲單位，本例中爲 34380 us ，查看文件 tracing_max_latency 也能夠獲取該值。從「task:」字段能夠知道延遲發生時正在運行的進程爲 idle（其 pid 爲 0 ）。中斷的關閉操做是在函數 reschedule_interrupt 中進行的，由「=> started at:」標識，函數 restore_all_ontrace 從新激活了中斷，由「=> ended at:」標識；中斷關閉的最大延遲發生在函數 trace_hardirqs_on_thunk 中，這個能夠從最大延遲時間所在的記錄項看到，也能夠從延遲記錄信息中最後的「=>」標識所對應的記錄行知道這一點。

在輸出信息中，irqs-off、need_resched 等字段對應於進程結構 struct task_struct 的字段或者狀態標誌，能夠從頭文件 arch/<platform>/include/asm/thread_info.h 中查看進程支持的狀態標誌，include/linux/sched.h 則給出告終構 struct task_struct 的定義。其中，irqs-off 字段顯示是否中斷被禁止，爲‘ d ’表示中斷被禁止；need_resched 字段顯示爲‘ N ’表示設置了進程狀態標誌 TIF_NEED_RESCHED。hardirq/softirq 字段表示當前是否發生硬件中斷 / 軟中斷；preempt-depth 表示是否禁止進程搶佔，例如在持有自旋鎖的狀況下進程是不能被搶佔的，本例中進程 idle 是能夠被其它進程搶佔的。結構 struct task_struct 中的 lock_depth 字段是與大內核鎖相關的，而最近的內核開發工做中有一部分是與移除大內核鎖相關的，這裏對該字段再也不加以描述。

另外，還有用於跟蹤禁止進程搶佔的跟蹤器 preemptoff 和跟蹤中斷 / 搶佔禁止的跟蹤器 preemptirqsoff，它們的使用方式與輸出信息格式與 irqsoff 跟蹤器相似，這裏再也不贅述。

回頁首

跟蹤指定模塊中的函數

前面提過，經過文件 set_ftrace_filter 能夠指定要跟蹤的函數，缺省目標爲全部可跟蹤的內核函數；能夠將感興趣的函數經過 echo 寫入該文件。爲了方便使用，set_ftrace_filter 文件還支持簡單格式的通配符。

• begin*選擇全部名字以 begin 字串開頭的函數
• *middle*選擇全部名字中包含 middle 字串的函數
• *end選擇全部名字以 end 字串結尾的函數

須要注意的是，這三種形式不能組合使用，好比「begin*middle*end」實際的效果與「begin」相同。另外，使用通配符表達式時，須要用單引號將其括起來，若是使用雙引號，shell 可能會對字符‘ * ’進行擴展，這樣最終跟蹤的對象可能與目標函數不同。

經過該文件還能夠指定屬於特定模塊的函數，這要用到 mod 指令。指定模塊的格式爲：

echo ':mod:[module_name]' > set_ftrace_filter

下面給出了一個指定跟蹤模塊 ipv6 中的函數的例子。能夠看到，指定跟蹤模塊 ipv6 中的函數會將文件 set_ftrace_filter 的內容設置爲只包含該模塊中的函數。

清單 5. 指定跟蹤 ipv6 模塊中的函數

[root@linux tracing]# pwd /sys/kernel/debug/tracing [root@linux tracing]# echo ':mod:ipv6' > set_ftrace_filter [root@linux tracing]# cat set_ftrace_filter | head -5 ipv6_opt_accepted inet6_net_exit ipv6_gro_complete inet6_create ipv6_addr_copy

回頁首

小結

本系列文章對 ftrace 的配置和使用進行了介紹。本文是其中的第二部分，介紹了 ftrace 所提供的跟蹤器的使用，重點對不一樣格式的跟蹤信息進行了描述，並對如何跟蹤指定模塊中的函數進行了介紹。當前 Linux 內核中 ftrace 支持多個跟蹤器，因爲篇幅限制，這裏不能對其所有加以描述。讀者可參照參考資料中給出的信息對 ftrace 跟蹤器進行更深刻的瞭解。下一篇文章將對如何在代碼中經過 ftrace 提供的工具函數與 ftrace 交互進行描述。

參考資料

• 內核文檔 Documentation/trace/ftrace.txt。
  
  
• LWN 上的文章 Secrets of the Ftrace function tracer 以及其它與 ftrace 相關的文章。
  
  
• 查看內核源碼 kernel/trace目錄下的文件以瞭解 ftrace 支持的各類跟蹤器。
  
  
• 《 Understanding the Linux Kernel, Third Edition 》描述了 Linux 內核的實現。
  
  
• 在 developerWorks Linux 專區 尋找爲 Linux 開發人員（包括 Linux 新手入門）準備的更多參考資料，查閱咱們 最受歡迎的文章和教程。 
  
  
• 在 developerWorks 上查閱全部 Linux 技巧 和 Linux 教程。 
  
  

做者簡介

王生輝，軟件工程師。目前在 IBM 系統技術實驗室從事 Linux for Power 方面的測試工做。

李驊宸，實習生。目前在 IBM 系統技術實驗室從事 Linux for Power 方面的測試工做。