ftrace使用说明(二)
本文轉自：http://www.yiyon.net/index.php/archives/225
1.1????? Ftrace數據文件介紹
/sys/kernel/debug/tracing目錄下文件和目錄比較多，有些是各種跟蹤器共享使用的，有些是特定于某個跟蹤器使用的。在操作這些數據文件時，通常使用 echo命令來修改其值，也可以在程序中通過文件讀寫相關的函數來操作這些文件的值。下面只對部分文件進行描述，讀者可以參考內核源碼包中 Documentation/trace 目錄下的文檔以及 kernel/trace 下的源文件以了解其余文件的用途。
- README：提供了一個簡短的使用說明，展示了ftrace的操作命令序列。可以通過 cat 命令查看該文件以了解概要的操作流程。
- current_tracer：用于設置或顯示當前使用的跟蹤器；使用 echo 將跟蹤器名字寫入該文件可以切換到不同的跟蹤器。系統啟動后，其缺省值為 nop ，即不做任何跟蹤操作。在執行完一段跟蹤任務后，可以通過向該文件寫入 nop 來重置跟蹤器。
- available_tracers：記錄了當前編譯進內核的跟蹤器的列表，可以通過 cat 查看其內容；其包含的跟蹤器與內核配置選項中所激活的選項是對應的。寫current_tracer文件時用到的跟蹤器名字必須在該文件列出的跟蹤器名字列表中。
- trace：文件提供了查看獲取到的跟蹤信息的接口。可以通過 cat 等命令查看該文件以查看跟蹤到的內核活動記錄，也可以將其內容保存為記錄文件以備后續查看。
- tracing_enabled：用于控制 current_tracer 中的跟蹤器是否可以跟蹤內核函數的調用情況。寫入 0 會關閉跟蹤活動，寫入 1 則激活跟蹤功能；其缺省值為 1 。
- set_graph_function：設置要清晰顯示調用關系的函數，顯示的信息結構類似于 C 語言代碼，這樣在分析內核運作流程時會更加直觀一些。在使用function_graph 跟蹤器時使用；缺省為對所有函數都生成調用關系序列，可以通過寫該文件來指定需要特別關注的函數。
- buffer_size_kb：用于設置單個 CPU 所使用的跟蹤緩存的大小。跟蹤器會將跟蹤到的信息寫入緩存，每個 CPU 的跟蹤緩存是一樣大的。跟蹤緩存實現為環形緩沖區的形式，如果跟蹤到的信息太多，則舊的信息會被新的跟蹤信息覆蓋掉。注意，要更改該文件的值需要先將 current_tracer 設置為 nop 才可以。
- tracing_on：用于控制跟蹤的暫停。有時候在觀察到某些事件 時想暫時關閉跟蹤，可以將 0 寫入該文件以停止跟蹤，這樣跟蹤緩沖區中比較新的部分是與所關注的事件相關的；寫入 1 可以繼續跟蹤。
- available_filter_functions：記錄了當前可以跟蹤的內核函數。對于不在該文件中列出的函數，無法跟蹤其活動。
- set_ftrace_filter/set_ftrace_notrace：在 編譯內核時配置了動態 ftrace （選中 CONFIG_DYNAMIC_FTRACE 選項）后使用。前者用于顯示指定要跟蹤的函數，后者則作用相反，用于指定不跟蹤的函數。如果一個函數名同時出現在這兩個文件中，則這個函數的執行狀況不會 被跟蹤。這些文件還支持簡單形式的含有通配符的表達式，這樣可以用一個表達式一次指定多個目標函數；具體使用在后續文章中會有描述。注意，要寫入這兩個文 件的函數名必須可以在文件 available_filter_functions 中看到。缺省為可以跟蹤所有內核函數，文件 set_ftrace_notrace 的值則為空。
1.2????? Ftrace操作
1.設置tracer 由前述可知，available_tracers中記錄的tracer都是有效的。假設現在已經在目錄/sys/kernel/debug/tracing下。打開trace功能，設置function跟蹤器：
# echo function > current_tracer
# cat current_tracer
function
2.開啟/關閉tracer啟動：#echo 1 > /proc/sys/kernel/ftrace_enabled
停止：#echo 0 > /proc/sys/kernel/ftrace_enabled
3.暫停/繼續跟蹤情況暫停：#echo 0 > tracing_on
繼續：#echo 1 > tracing_on
4.觀察結果
#cat trace | head -10
5.?跟蹤指定的process
也許我們只需要跟蹤指定的process，或者指定一組process；
[root@RedHat tracing]# cat set_ftrace_pid
no pid
[root@RedHat tracing]# echo $$ > set_ftrace_pid
上述將使得function tracer只跟蹤bash shell；如果我們想要跟蹤指定的process，需要創建以下腳本程序：
[root@RedHat tracing]# cat /home/tools/ftracer/ftrace-me
#!/bin/sh
DEBUGFS=`grep debugfs /proc/mounts | awk ‘{ print $2; }’`
echo $$ > $DEBUGFS/tracing/set_ftrace_pid
echo function > $DEBUGFS/tracing/current_tracer
exec $*
[root@RedHat tracing]# /home/tools/ftracer/ftrace-me ls –ltr
Note, you must clear the set_ftrace_pid file if you want to go back to generic function tracing after performing the above.
? [root@RedHat tracing]# echo -1 > set_ftrace_pid?
?
2????????? 調試實例
2.1????? Function跟蹤器
Function tracer的主要功能是跟蹤函數調用。使用方法如下：
| [root@RedHat tracing]# ? [root@RedHat tracing]# pwd /sys/kernel/debug/tracing [root@RedHat tracing]# echo 0 > tracing_enabled [root@RedHat tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled [root@RedHat tracing]# echo function > current_tracer [root@RedHat tracing]# echo 1 > tracing_on [root@RedHat tracing]# echo 1 > tracing_enabled # 運行一段時間，即可采用ftrace手機一些跟蹤信息 [root@RedHat tracing]# echo 0 > tracing_enabled [root@RedHat tracing]# cat trace | head -10 # tracer: function # #?????????? TASK-PID??? CPU#??? TIMESTAMP? FUNCTION #????????????? | |?????? |????????? |???????? | automount-1878? [000]? 8901.818000: _raw_spin_lock_irq <-__schedule automount-1878? [000]? 8901.818000: update_rq_clock <-__schedule automount-1878? [000]? 8901.818000: put_prev_task_fair <-__schedule automount-1878? [000]? 8901.818000: update_curr <-put_prev_task_fair automount-1878? [000]? 8901.818000: pick_next_task_fair <-__schedule automount-1878? [000]? 8901.818000: clear_buddies <-pick_next_task_fair [root@RedHat tracing]# |
| ? |
| ? |
?
解析：trace 文件給出的信息格式很清晰。首先，字段“tracer:”給出了當前所使用的跟蹤器的名字，這里為 function 跟蹤器。然后是跟蹤信息記錄的格式，TASK 字段對應任務的名字，PID 字段則給出了任務的進程 ID，字段 CPU# 表示運行被跟蹤函數的 CPU 號，這里可以看到 automount進程運行在 0 號 CPU 上，其進程 ID 是 1878 ；字段 TIMESTAMP 是時間戳，其格式為“<secs>.<usecs>”，表示執行該函數時對應的時間戳；FUNCTION 一列則給出了被跟蹤的函數，函數的調用者通過符號 “<-” 標明，這樣可以觀察到函數的調用關系。
?
2.2????? function_graph跟蹤器
function_graph跟蹤器也是用來跟蹤系統調用的。
在 function 跟蹤器給出的信息中，可以通過 FUNCTION 列中的符號 “<-” 來查看函數調用關系，但是由于中間會混合不同函數的調用，導致看起來非常混亂，十分不方便。function_graph 跟蹤器則可以提供類似 C 代碼的函數調用關系信息。通過寫文件 set_graph_function 可以顯示指定要生成調用關系的函數，缺省會對所有可跟蹤的內核函數生成函數調用關系圖。下面給出了使用 function_grapch 跟蹤器的示例，示例中將內核函數 __do_fault 作為觀察對象，該函數在內核運作過程中會被頻繁調用
使用方法如下：
?
| [root@RedHat tracing]# echo 0 > tracing_enabled ? [root@RedHat tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled [root@RedHat tracing]# echo function_graph > current_tracer [root@RedHat tracing]# echo __do_fault > set_graph_function [root@RedHat tracing]# echo 1 > tracing_on [root@RedHat tracing]# echo 1 > tracing_enabled # 運行一段時間，即可采用ftrace手機一些跟蹤信息 [root@RedHat tracing]# echo 0 > tracing_enabled [root@RedHat tracing]# cat trace | head -20 # tracer: function_graph # # CPU? DURATION????????????????? FUNCTION CALLS # |???? |?? |???????????????????? |?? |?? |?? | 0)?? 0.000 us ???|????????????????? calc_global_load(); 0) ! 3000.000 us |??????????????? } /* do_timer */ 0) ! 3000.000 us |????????????? } /* tick_do_update_jiffies64 */ 0)?????????????? |????????????? update_process_times() { 0)?????????????? |??????????????? account_process_tick() { 0)?????????????? |????????????????? account_system_time() { 0)?? 0.000 us??? |??????????????????? acct_update_integrals(); 0)?? 0.000 us??? |????????????????? } 0)?? 0.000 us??? |??????????????? } 0)?????????????? |????????????? ??run_local_timers() { 0)?? 0.000 us??? |????????????????? hrtimer_run_queues(); 0)?? 0.000 us??? |????????????????? raise_softirq(); 0)?? 0.000 us??? |??????????????? } 0)?????????????? |??????????????? rcu_check_callbacks() { 0)?? 0.000 us??? |???? ?????????????idle_cpu(); 0)?? 0.000 us??? |????????????????? __rcu_pending(); [root@RedHat tracing]# echo > set_graph_function |
| ? |
| ? |
?
解析：在文件 trace 的輸出信息中，首先給出的也是當前跟蹤器的名字，這里是 function_graph 。接下來是詳細的跟蹤信息，可以看到，函數的調用關系以類似 C 代碼的形式組織。
CPU 字段給出了執行函數的 CPU 號，本例中都為 1 號 CPU。DURATION 字段給出了函數執行的時間長度，以 us 為單位。FUNCTION CALLS 則給出了調用的函數，并顯示了調用流程。注意，對于不調用其它函數的函數，其對應行以“;”結尾，而且對應的 DURATION 字段給出其運行時長；對于調用其它函數的函數，則在其“}”對應行給出了運行時長，該時間是一個累加值，包括了其內部調用的函數的執行時長。 DURATION 字段給出的時長并不是精確的，它還包含了執行 ftrace 自身的代碼所耗費的時間，所以示例中將內部函數時長累加得到的結果會與對應的外圍調用函數的執行時長并不一致；不過通過該字段還是可以大致了解函數在時間 上的運行開銷的。最后通過 echo 命令重置了文件。
?
注：The “+” that are there are annotation marker. When the duration is greater than 10 microseconds, a “+” is shown. If the duration is greater than 100 microseconds a “!” will be displayed.
?
2.3????? irqsoff跟蹤器
當關閉中斷時，CPU會延遲對設備的狀態變化做出反應，有時候這樣做會對系統性能造成比較大的影響。irqsoff 跟蹤器可以對中斷被關閉的狀況進行跟蹤，有助于發現導致較大延遲的代碼；當出現最大延遲時，跟蹤器會記錄導致延遲的跟蹤信息，文件 tracing_max_latency 則記錄中斷被關閉的最大延時。
使用方法如下（因為實用的是虛擬機，輸出信息有誤）：
| [root@RedHat tracing]# pwd ? /sys/kernel/debug/tracing [root@RedHat tracing]# echo 0 > tracing_enabled [root@RedHat tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled [root@RedHat tracing]# echo irqsoff > current_tracer [root@RedHat tracing]# echo 1 > tracing_on [root@RedHat tracing]# echo 1 > tracing_enabled # 運行一段時間，即可采用ftrace手機一些跟蹤信息 [root@RedHat tracing]# echo 0 > tracing_enabled [root@RedHat tracing]# cat trace | head -35 # tracer: irqsoff # # irqsoff latency trace v1.1.5 on 3.2.0trace # ——————————————————————– # latency: 3833000 us, #220/220, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:1) #??? —————– #??? | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0) #??? —————– #? => started at: common_interrupt #? => ended at:?? do_softirq # # #???????????? ?????_——=> CPU# #???????????????? / _—–=> irqs-off #??????????????? | / _—-=> need-resched #??????????????? || / _—=> hardirq/softirq #??????????????? ||| / _–=> preempt-depth #??????????????? |||| /???? delay #? cmd???? pid?? ||||| time? |?? caller #???? \?? /????? |||||? \??? |?? / <idle>-0?????? 0dN..??? 0us : acpi_pm_read <-do_timer <idle>-0?????? 0dN..??? 0us : calc_global_load <-do_timer <idle>-0?????? 0dN..??? 0us : account_idle_ticks <-tick_nohz_restart_sched_tick <idle>-0?????? 0dN..??? 0us : hrtimer_cancel <-tick_nohz_restart_sched_tick <idle>-0?????? 0dN..??? 0us : hrtimer_try_to_cancel <-hrtimer_cancel <idle>-0?????? 0dN..??? 0us : lock_hrtimer_base <-hrtimer_try_to_cancel <idle>-0?????? 0dN..??? 0us : _raw_spin_lock_irqsave <-lock_hrtimer_base <idle>-0?????? 0dN..??? 0us : __remove_hrtimer <-hrtimer_try_to_cancel <idle>-0?????? 0dN..??? 0us : hrtimer_force_reprogram <-__remove_hrtimer <idle>-0?????? 0dN..??? 0us : tick_program_event <-hrtimer_force_reprogram <idle>-0?????? 0dN..??? 0us : clockevents_program_event <-tick_program_event <idle>-0?????? 0dN..??? 0us : ktime_get <-clockevents_program_event <idle>-0?????? 0dN..??? 0us : acpi_pm_read <-ktime_get <idle>-0?????? 0dN..??? 0us : lapic_next_event <-clockevents_program_event <idle>-0?????? 0dN..??? 0us : native_apic_mem_write <-lapic_next_event [root@RedHat tracing]# cat tracing_max_latency 3833000 [root@RedHat tracing]# |
?
解析：從輸出信息中，可以看到當前 irqsoff 延遲跟蹤器的版本信息。接下來是最大延遲時間，以us為單位，本例中為3833000us ，查看文件 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 字段是與大內核鎖相關的，而最近的內核開發工作中有一部分是與移除大內核鎖相關的，這里對該字段不再加以描述。
2.4??????Function Profiling
?
| # echo nop > current_tracer # echo 1 > function_profile_enabled # cat trace_stat/function0 |head ?Function?????????????????????????????? Hit??? Time??????????? Avg ?——–?????????????????????????????? —??? —-??????????? — ?schedule??????????????????? ???????????923??? 325906219 us???? 353094.4 us ?vfs_read?????????????????????????????? 238??? 109621612 us???? 460595.0 us ?sys_read?????????????????????????????? 208??? 108491821 us???? 521595.2 us ?do_sync_read?????????????????????????? 123??? 49456207 us???? 402082.9 us ?pipe_read?????????????????????????????? 63??? 48292785 us???? 766552.1 us ?pipe_wait?????????????????????????????? 63??? 48276550 us???? 766294.4 us ?sys_futex????????????????? ??????????????5??? 48068145 us???? 9613629 us ?do_futex???????????????????????????????? 5??? 48068115 us???? 9613623 us |
?
2.5??????sched_switch跟蹤器
sched_switch 跟蹤器可以對進程的調度切換以及之間的喚醒操作進行跟蹤，使用方法如下：
| [root@RedHat tracing]# pwd ? /sys/kernel/debug/tracing [root@RedHat tracing]# echo 0 > tracing_enabled [root@RedHat tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled [root@RedHat tracing]# echo sched_switch ?> current_tracer [root@RedHat tracing]# echo 1 > tracing_on [root@RedHat tracing]# echo 1 > tracing_enabled # 運行一段時間，即可采用ftrace手機一些跟蹤信息 [root@RedHat tracing]# echo 0 > tracing_enabled [root@RedHat tracing]# cat trace | head -10 [root@RedHat tracing]# 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 。
進程狀態：
R – running?: wants to run, may not actually be running
S – sleep ?: process is waiting to be woken up (handles signals)
D – disk sleep (uninterruptible sleep)?: process must be woken up (ignores signals)
T – stopped?: process suspended
t – traced ?: process is being traced (with something like gdb)
Z – zombie ?: process waiting to be cleaned up
X – unknown
?
?
2.6????? 跟蹤指定模塊中的函數
前面提過，通過文件 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 的內容設置為只包含該模塊中的函數。
指定跟蹤 ipv6 模塊中的函數
| [root@RedHat tracing]# pwd ? /sys/kernel/debug/tracing [root@RedHat tracing]# echo ‘:mod:ipv6′ > set_ftrace_filter [root@RedHat tracing]# cat set_ftrace_filter | head -5 ipv6_opt_accepted inet6_net_exit ipv6_gro_complete inet6_create ipv6_addr_copy |
?
轉載于:https://www.cnblogs.com/ltfbk/archive/2013/05/18/3085992.html
總結
以上是生活随笔為你收集整理的ftrace使用说明(二)的全部內容，希望文章能夠幫你解決所遇到的問題。
- 上一篇： 三年开发项目经验总结
- 下一篇： 声明属性Hibernate的Annota