Linux內(nèi)核追蹤神器：Ftrace實現(xiàn)原理剖析
在 Linux 內(nèi)核這片深邃而神秘的技術(shù)海洋里，每一個系統(tǒng)進程的運行、每一次資源的調(diào)度，都像是在黑暗中上演的復(fù)雜劇目。內(nèi)核開發(fā)者們時常面臨著棘手難題：系統(tǒng)莫名卡頓，究竟是哪個內(nèi)核函數(shù)在作祟？進程調(diào)度出現(xiàn)異常，問題根源又在何處？在漫長的探索歷程中，開發(fā)者們急需一款強大的工具，能夠像聚光燈一樣，穿透重重迷霧，照亮內(nèi)核運行的每一個角落。而 Ftrace，正是這樣一款應(yīng)運而生的 “內(nèi)核追蹤神器”。
它從最初簡單的函數(shù)跟蹤器，逐步成長為功能豐富的跟蹤框架，猶如一把萬能鑰匙，為開發(fā)者打開了深入探究內(nèi)核奧秘的大門。接下來，讓我們一同深入到 Ftrace 的世界，探尋它的實現(xiàn)原理，看看它究竟如何施展神奇魔力，助力開發(fā)者解決內(nèi)核開發(fā)與調(diào)試中的種種難題 。
一、Ftrace是什么？
根據(jù)Linux Doc 的介紹，ftrace 是一個 Linux 內(nèi)部的 trace 工具，能夠幫助開發(fā)者和系統(tǒng)設(shè)計者知道內(nèi)核當(dāng)前正在干啥，從而更好的去分析性能問題。在 Linux 內(nèi)核開發(fā)與系統(tǒng)性能優(yōu)化的廣袤領(lǐng)域中，F(xiàn)trace 宛如一把神奇的瑞士軍刀，發(fā)揮著無可替代的關(guān)鍵作用。對于內(nèi)核開發(fā)者而言，它是深入探究內(nèi)核運行機制、精準(zhǔn)定位代碼問題的得力助手；對于系統(tǒng)優(yōu)化者來說，它是剖析系統(tǒng)性能瓶頸、實現(xiàn)高效優(yōu)化的必備利器。
曾經(jīng)，在一個高并發(fā)的 Web 服務(wù)器項目中，服務(wù)器在流量高峰時段出現(xiàn)響應(yīng)延遲的狀況。運維團隊起初一頭霧水，不知問題根源所在。后來，他們借助 Ftrace 工具，對內(nèi)核函數(shù)進行細(xì)致跟蹤。通過 Function Graph Tracer，清晰呈現(xiàn)出函數(shù)調(diào)用關(guān)系；利用 Irqsoff Tracer，監(jiān)測中斷被禁止的時段。最終，成功定位到一個文件讀寫函數(shù)存在性能瓶頸，經(jīng)過針對性優(yōu)化，服務(wù)器響應(yīng)速度大幅提升，成功解決了延遲問題。
Ftrace 能幫我們分析內(nèi)核特定的事件，譬如調(diào)度，中斷等，也能幫我們?nèi)プ粉檮討B(tài)的內(nèi)核函數(shù)，以及這些函數(shù)的調(diào)用棧還有棧的使用這些。它也能幫我們?nèi)プ粉櫻舆t，譬如中斷被屏蔽，搶占被禁止的時間，以及喚醒一個進程之后多久開始執(zhí)行的時間。
可以看到，使用 ftrace 真的能做到對系統(tǒng)內(nèi)核非常系統(tǒng)的剖析，甚至都能通過 ftrace 來學(xué)習(xí) Linux 內(nèi)核，不過在更進一步之前，我們需要學(xué)會的是 - 如何使用 ftrace
二、 如何使用 ftrace
要使用 ftrace，首先就是需要將系統(tǒng)的 debugfs 或者 tracefs 給掛載到某個地方，幸運的是，幾乎所有的 Linux 發(fā)行版，都開啟了 debugfs/tracefs 的支持，所以我們也沒必要去重新編譯內(nèi)核了。
在比較老的內(nèi)核版本，譬如 CentOS 7 的上面，debugfs 通常被掛載到 /sys/kernel/debug 上面（debug 目錄下面有一個 tracing 目錄），而比較新的內(nèi)核，則是將 tracefs 掛載到 /sys/kernel/tracing，無論是什么，我都喜歡將 tracing 目錄直接 link 到 /tracing。后面都會假設(shè)直接進入了 /tracing 目錄，后面，我會使用 Ubuntu 16.04 來舉例子，內(nèi)核版本是 4.13 來舉例子。
在使用ftrace之前，需要內(nèi)核進行支持，也就是內(nèi)核需要打開編譯中的ftrace相關(guān)選項，關(guān)于怎么激活ftrace選項的問題，可以google之，下面只說明重要的設(shè)置步驟：
- mkdir /debug；mount -t debugs nodev /debug; /*掛載debugfs到創(chuàng)建的目錄中去*/
- cd /debug; cd tracing; /*如果沒有tracing目錄，則內(nèi)核目前還沒有支持ftrace，需要配置參數(shù)，重新編譯*/。
- echo nop > current_tracer;//清空tracer
- echo function_graph > current_tracer;//使用圖形顯示調(diào)用關(guān)系
- echo ip_rcv > set_graph_function;//設(shè)置過濾函數(shù),可以設(shè)置多個
- echo 1 > tracing_enabled開始追蹤
2.1傳統(tǒng) fracer 的使用
使用傳統(tǒng)的 ftrace 需要如下幾個步驟：
- 選擇一種 tracer
- 使能 ftrace
- 執(zhí)行需要 trace 的應(yīng)用程序，比如需要跟蹤 ls，就執(zhí)行 ls
- 關(guān)閉 ftrace
- 查看 trace 文件
用戶通過讀寫 debugfs 文件系統(tǒng)中的控制文件完成上述步驟。使用 debugfs，首先要掛載它。命令如下：
# mkdir /debug
# mount -t debugfs nodev /debug此時您將在 /debug 目錄下看到 tracing 目錄。Ftrace 的控制接口就是該目錄下的文件。
選擇 tracer 的控制文件叫作 current_tracer 。選擇 tracer 就是將 tracer 的名字寫入這個文件，比如，用戶打算使用 function tracer，可輸入如下命令：
#echo ftrace > /debug/tracing/current_tracer文件 tracing_enabled 控制 ftrace 的開始和結(jié)束。
#echo 1 >/debug/tracing/tracing_enable上面的命令使能 ftrace 。同樣，將 0 寫入 tracing_enable 文件便可以停止 ftrace 。
ftrace 的輸出信息主要保存在 3 個文件中：
- Trace，該文件保存 ftrace 的輸出信息，其內(nèi)容可以直接閱讀。
- latency_trace，保存與 trace 相同的信息，不過組織方式略有不同。主要為了用戶能方便地分析系統(tǒng)中有關(guān)延遲的信息。
- trace_pipe 是一個管道文件，主要為了方便應(yīng)用程序讀取 trace 內(nèi)容。算是擴展接口吧。
我們使用 ls 來看看目錄下面到底有什么：
README current_tracer hwlat_detector per_cpu set_event_pid snapshot trace_marker tracing_max_latency
available_events dyn_ftrace_total_info instances printk_formats set_ftrace_filter stack_max_size trace_marker_raw tracing_on
available_filter_functions enabled_functions kprobe_events saved_cmdlines set_ftrace_notrace stack_trace trace_options tracing_thresh
available_tracers events kprobe_profile saved_cmdlines_size set_ftrace_pid stack_trace_filter trace_pipe uprobe_events
buffer_size_kb free_buffer max_graph_depth saved_tgids set_graph_function trace trace_stat uprobe_profile
buffer_total_size_kb function_profile_enabled options set_event set_graph_notrace trace_clock tracing_cpumask可以看到，里面有非常多的文件和目錄，具體的含義，大家可以去詳細(xì)的看官方文檔的解釋，后面只會重點介紹一些文件。
2.2功能
我們可以通過 available_tracers 這個文件知道當(dāng)前 ftrace 支持哪些插件。
cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop通常用的最多的就是function和function_graph，當(dāng)然，如果我們不想 trace 了，可以使用nop。我們首先打開function：
echo function > current_tracer
cat current_tracer
function上面我們將 function 寫入到了 current_tracer 來開啟 function 的 trace，我通常會在 cat 下 current_tracer 這個文件，主要是防止自己寫錯了。然后 ftrace 就開始工作了，會將相關(guān)的 trace 信息放到 trace 文件里面，我們直接讀取這個文件就能獲取相關(guān)的信息。
cat trace | head -n 15
# tracer: function
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
bash-29409 [002] .... 16158426.215771: mutex_unlock <-tracing_set_tracer
<idle>-0 [039] d... 16158426.215771: call_cpuidle <-do_idle
<idle>-0 [039] d... 16158426.215772: cpuidle_enter <-call_cpuidle
<idle>-0 [039] d... 16158426.215773: cpuidle_enter_state <-cpuidle_enter
bash-29409 [002] .... 16158426.215773: __fsnotify_parent <-vfs_write
<idle>-0 [039] d... 16158426.215773: sched_idle_set_state <-cpuidle_enter_state我們可以設(shè)置只跟蹤特定的 function
echo schedule > set_ftrace_filter
cat set_ftrace_filter
schedule
cat trace | head -n 15
# tracer: function
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
bash-29409 [010] .... 16158462.591708: schedule <-schedule_timeout
kworker/u81:2-29339 [008] .... 16158462.591736: schedule <-worker_thread
sshd-29395 [012] .... 16158462.591788: schedule <-schedule_hrtimeout_range_clock
rcu_sched-9 [010] .... 16158462.595475: schedule <-schedule_timeout
java-23597 [006] .... 16158462.600326: schedule <-futex_wait_queue_me
java-23624 [020] .... 16158462.600855: schedule <-schedule_hrtimeout_range_clock當(dāng)然，如果我們不想 trace schedule 這個函數(shù)，也可以這樣做：
echo '!schedule' > set_ftrace_filter或者也可以這樣做：
echo schedule > set_ftrace_notraceFunction filter 的設(shè)置也支持 *match，match* ，*match* 這樣的正則表達式，譬如我們可以 echo '*lock*' < set_ftrace_notrace 來禁止跟蹤帶 lock 的函數(shù)，set_ftrace_notrace 文件里面這時候就會顯示：
cat set_ftrace_notrace
xen_pte_unlock
read_hv_clock_msr
read_hv_clock_tsc
update_persistent_clock
read_persistent_clock
set_task_blockstep
user_enable_block_step
...2.3函數(shù)圖
相比于 function，function_graph 能讓我們更加詳細(xì)的去知道內(nèi)核函數(shù)的上下文，我們打開 function_graph：
echo function_graph > current_tracer
cat trace | head -15
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
10) 0.085 us | sched_idle_set_state();
10) | cpuidle_reflect() {
10) 0.035 us | menu_reflect();
10) 0.288 us | }
10) | rcu_idle_exit() {
10) 0.034 us | rcu_dynticks_eqs_exit();
10) 0.296 us | }
10) 0.032 us | arch_cpu_idle_exit();
10) | tick_nohz_idle_exit() {
10) 0.073 us | ktime_get();
10) | update_ts_time_stats() {我們也可以只跟蹤某一個函數(shù)的堆棧。
echo kfree > set_graph_function
cat trace | head -n 15
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
16) | kfree() {
16) 0.147 us | __slab_free();
16) 1.437 us | }
10) 0.162 us | kfree();
17) @ 923817.3 us | } /* intel_idle */
17) 0.044 us | sched_idle_set_state();
17) ==========> |
17) | smp_apic_timer_interrupt() {
17) | irq_enter() {
17) | rcu_irq_enter() {
17) 0.049 us | rcu_dynticks_eqs_exit();2.4事件
上面提到了 function 的 trace，在 ftrace 里面，另外用的多的就是 event 的 trace，我們可以在 events 目錄下面看支持那些事件：
ls events/
alarmtimer cma ext4 fs_dax i2c kvm mmc nmi printk regulator smbus task vmscan xdp
block compaction fib ftrace iommu kvmmmu module oom random rpm sock thermal vsyscall xen
bpf cpuhp fib6 gpio irq libata mpx page_isolation ras sched spi thermal_power_allocator wbt xhci-hcd
btrfs dma_fence filelock header_event irq_vectors mce msr pagemap raw_syscalls scsi swiotlb timer workqueue
cgroup enable filemap header_page jbd2 mdio napi percpu rcu signal sync_trace tlb writeback
clk exceptions fs huge_memory kmem migrate net power regmap skb syscalls udp x86_fpu上面列出來的都是分組的，我們可以繼續(xù)深入下去，譬如下面是查看sched相關(guān)的事件：
ls events/sched/
enable sched_migrate_task sched_process_exit sched_process_wait sched_stat_sleep sched_switch sched_wakeup_new
filter sched_move_numa sched_process_fork sched_stat_blocked sched_stat_wait sched_wait_task sched_waking
sched_kthread_stop sched_pi_setprio sched_process_free sched_stat_iowait sched_stick_numa sched_wake_idle_without_ipi
sched_kthread_stop_ret sched_process_exec sched_process_hang sched_stat_runtime sched_swap_numa sched_wakeup對于某一個具體的事件，我們也可以查看：
ls events/sched/sched_wakeup
enable filter format hist id trigger不知道大家注意到了沒有，上述目錄里面，都有一個enable的文件，我們只需要往里面寫入 1，就可以開始 trace 這個事件。譬如下面就開始 tracesched_wakeup這個事件：
echo 1 > events/sched/sched_wakeup/enable
cat trace | head -15
# tracer: nop
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
bash-29409 [012] d... 16158657.832294: sched_wakeup: comm=kworker/u81:1 pid=29359 prio=120 target_cpu=008
kworker/u81:1-29359 [008] d... 16158657.832321: sched_wakeup: comm=sshd pid=29395 prio=120 target_cpu=010
<idle>-0 [012] dNs. 16158657.835922: sched_wakeup: comm=rcu_sched pid=9 prio=120 target_cpu=012
<idle>-0 [024] dNh. 16158657.836908: sched_wakeup: comm=java pid=23632 prio=120 target_cpu=024
<idle>-0 [022] dNh. 16158657.839921: sched_wakeup: comm=java pid=23624 prio=120 target_cpu=022
<idle>-0 [016] dNh. 16158657.841866: sched_wakeup: comm=java pid=23629 prio=120 target_cpu=016我們也可以 tracesched里面的所有事件：
echo 1 > events/sched/enable
cat trace | head -15
# tracer: nop
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
bash-29409 [010] d... 16158704.468377: sched_waking: comm=kworker/u81:2 pid=29339 prio=120 target_cpu=008
bash-29409 [010] d... 16158704.468378: sched_stat_sleep: comm=kworker/u81:2 pid=29339 delay=164314267 [ns]
bash-29409 [010] d... 16158704.468379: sched_wake_idle_without_ipi: cpu=8
bash-29409 [010] d... 16158704.468379: sched_wakeup: comm=kworker/u81:2 pid=29339 prio=120 target_cpu=008
bash-29409 [010] d... 16158704.468382: sched_stat_runtime: comm=bash pid=29409 runtime=360343 [ns] vruntime=131529875864926 [ns]
bash-29409 [010] d... 16158704.468383: sched_switch: prev_comm=bash prev_pid=29409 prev_prio=120 prev_state=S ==> next_comm=swapper/10 next_pid=0 next_prio=120當(dāng)然也可以 trace 所有的事件：
echo 1 > events/enable
cat trace | head -15
# tracer: nop
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
bash-29409 [010] .... 16158761.584188: writeback_mark_inode_dirty: bdi (unknown): ino=3089 state=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES flags=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES
bash-29409 [010] .... 16158761.584189: writeback_dirty_inode_start: bdi (unknown): ino=3089 state=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES flags=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES
bash-29409 [010] .... 16158761.584190: writeback_dirty_inode: bdi (unknown): ino=3089 state=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES flags=I_DIRTY_SYNC|I_DIRTY_DATASYNC|I_DIRTY_PAGES
bash-29409 [010] .... 16158761.584193: do_sys_open: "trace" 8241 666
bash-29409 [010] .... 16158761.584193: kmem_cache_free: call_site=ffffffff8e862614 ptr=ffff91d241fa4000
bash-29409 [010] .... 16158761.584194: sys_exit: NR 2 = 32.5trace-cmd
從上面的例子可以看到，其實使用 ftrace 并不是那么方便，我們需要手動的去控制多個文件，但幸運的是，我們有 trace-cmd，作為 ftrace 的前端，trace-cmd 能夠非常方便的讓我們進行 ftrace 的操作，譬如我們可以使用 record 命令來 trace sched 事件：
trace-cmd record -e sched然后使用report命令來查看 trace 的數(shù)據(jù)：
trace-cmd report | head -10
version = 6
CPU 27 is empty
cpus=40
trace-cmd-29557 [003] 16159201.985281: sched_waking: comm=kworker/u82:3 pid=28507 prio=120 target_cpu=037
trace-cmd-29557 [003] 16159201.985283: sched_migrate_task: comm=kworker/u82:3 pid=28507 prio=120 orig_cpu=37 dest_cpu=5
trace-cmd-29557 [003] 16159201.985285: sched_stat_sleep: comm=kworker/u82:3 pid=28507 delay=137014529 [ns]
trace-cmd-29585 [023] 16159201.985286: sched_stat_runtime: comm=trace-cmd pid=29585 runtime=217630 [ns] vruntime=107586626253137 [ns]
trace-cmd-29557 [003] 16159201.985286: sched_wake_idle_without_ipi: cpu=5
trace-cmd-29595 [037] 16159201.985286: sched_stat_runtime: comm=trace-cmd pid=29595 runtime=213227 [ns] vruntime=105364596011783 [ns]
trace-cmd-29557 [003] 16159201.985287: sched_wakeup: kworker/u82:3:28507 [120] success=1 CPU:005當(dāng)然，在report的時候也可以加入自己的 filter 來過濾數(shù)據(jù)，譬如下面，我們就過濾出sched_wakeup事件并且是success為 1 的。
trace-cmd report -F 'sched/sched_wakeup: success == 1' | head -10
version = 6
CPU 27 is empty
cpus=40
trace-cmd-29557 [003] 16159201.985287: sched_wakeup: kworker/u82:3:28507 [120] success=1 CPU:005
trace-cmd-29557 [003] 16159201.985292: sched_wakeup: trace-cmd:29561 [120] success=1 CPU:007
<idle>-0 [032] 16159201.985294: sched_wakeup: qps_json_driver:24669 [120] success=1 CPU:032
<idle>-0 [032] 16159201.985298: sched_wakeup: trace-cmd:29590 [120] success=1 CPU:026
<idle>-0 [010] 16159201.985300: sched_wakeup: trace-cmd:29563 [120] success=1 CPU:010
trace-cmd-29597 [037] 16159201.985302: sched_wakeup: trace-cmd:29595 [120] success=1 CPU:039
<idle>-0 [010] 16159201.985302: sched_wakeup: sshd:29395 [120] success=1 CPU:010大家可以注意下success == 1，這其實是一個對事件里面 field 進行的表達式運算了，對于不同的事件，我們可以通過查看其format 來知道它的實際 fields 是怎樣的，譬如：
cat events/sched/sched_wakeup/format
name: sched_wakeup
ID: 294
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:char comm[16]; offset:8; size:16; signed:1;
field:pid_t pid; offset:24; size:4; signed:1;
field:int prio; offset:28; size:4; signed:1;
field:int success; offset:32; size:4; signed:1;
field:int target_cpu; offset:36; size:4; signed:1;
print fmt: "comm=%s pid=%d prio=%d target_cpu=%03d", REC->comm, REC->pid, RE三、Ftrace 工作原理
3.1插樁技術(shù)
Ftrace 主要采用了靜態(tài)插樁和動態(tài)插樁兩種方式來實現(xiàn)其強大的跟蹤功能。
靜態(tài)插樁，簡單來說，就是在編譯內(nèi)核時，借助編譯器的特定選項，在目標(biāo)代碼中插入額外的代碼片段。具體而言，當(dāng)內(nèi)核配置打開CONFIG_FUNCTION_TRACER功能后，會添加一個-pg編譯選項 ，這就如同在每個函數(shù)入口處埋下了一個 “小標(biāo)記”—— 插入bl mcount跳轉(zhuǎn)指令。
如此一來，當(dāng)每個函數(shù)運行時，都會先進入mcount函數(shù)。這種方式的優(yōu)點是可靠性高，只要內(nèi)核編譯時配置好，所有相關(guān)函數(shù)都會被插樁，能全面地記錄函數(shù)調(diào)用信息。然而，它的缺點也很明顯，由于對內(nèi)核中所有函數(shù)都進行插樁，會帶來較大的性能開銷，在一些對性能要求極高的場景下，可能會導(dǎo)致系統(tǒng)運行效率大幅下降，甚至影響系統(tǒng)的正常運行。
為了克服靜態(tài)插樁的性能問題，動態(tài)插樁應(yīng)運而生。這里的 “動態(tài)”，體現(xiàn)在動態(tài)修改函數(shù)指令。在編譯時，會記錄所有支持追蹤的函數(shù)，這些函數(shù)原本被添加了跳轉(zhuǎn)指令。但在內(nèi)核啟動后，為了減少性能損耗，內(nèi)核會將所有跳轉(zhuǎn)指令替換為nop指令（nop指令表示空操作，不執(zhí)行任何實際運算，對系統(tǒng)性能幾乎沒有影響），此時系統(tǒng)處于非調(diào)試狀態(tài)，性能損失幾乎為零。
當(dāng)需要進行跟蹤時，根據(jù)function tracer的設(shè)置，F(xiàn)trace 會動態(tài)地將需要調(diào)試的函數(shù)的nop指令替換為跳轉(zhuǎn)指令，從而實現(xiàn)對這些特定函數(shù)的追蹤。動態(tài)插樁就像是一個智能的 “追蹤開關(guān)”，只有在需要時才開啟對特定函數(shù)的追蹤，大大減少了不必要的性能開銷，使得 Ftrace 在生產(chǎn)環(huán)境中的使用更加靈活和高效。
3.2追蹤器類型
Ftrace 擁有豐富多樣的追蹤器，每個追蹤器都有其獨特的功能和適用場景。
Function tracer 是最基礎(chǔ)的追蹤器之一，主要用于跟蹤內(nèi)核函數(shù)的執(zhí)行情況。它可以清晰地記錄下每個內(nèi)核函數(shù)的調(diào)用時間、調(diào)用順序以及返回值等信息。在調(diào)試內(nèi)核代碼時，如果懷疑某個函數(shù)的執(zhí)行邏輯存在問題，就可以使用 Function tracer，通過分析它記錄的函數(shù)執(zhí)行信息，快速定位到問題所在。比如，在開發(fā)一個新的內(nèi)核模塊時，發(fā)現(xiàn)某個功能無法正常實現(xiàn)，利用 Function tracer 跟蹤相關(guān)函數(shù)的調(diào)用過程，可能會發(fā)現(xiàn)某個函數(shù)沒有按照預(yù)期被調(diào)用，或者返回值不符合預(yù)期，從而找到問題的根源。
Function graph tracer 則以更加直觀的方式展示函數(shù)調(diào)用關(guān)系。它不僅能記錄函數(shù)的調(diào)用情況，還能以類似 C 語言函數(shù)調(diào)用關(guān)系圖的形式，展示出函數(shù)的調(diào)用層次關(guān)系以及返回情況 。這對于理解復(fù)雜的內(nèi)核代碼邏輯非常有幫助。在分析系統(tǒng)性能瓶頸時，如果發(fā)現(xiàn)某個功能的執(zhí)行效率較低，使用 Function graph tracer 可以清晰地看到該功能涉及的函數(shù)調(diào)用鏈，找出哪些函數(shù)的執(zhí)行時間較長，哪些函數(shù)的調(diào)用次數(shù)過于頻繁，從而有針對性地進行優(yōu)化。例如，在一個文件系統(tǒng)的性能優(yōu)化中，通過 Function graph tracer 發(fā)現(xiàn)文件讀寫函數(shù)在調(diào)用過程中，存在一些不必要的函數(shù)嵌套調(diào)用，通過優(yōu)化這些調(diào)用關(guān)系，大大提高了文件系統(tǒng)的讀寫性能。
除了上述兩種追蹤器，還有其他一些追蹤器也各有其用。Sched_switch 追蹤器主要用于跟蹤系統(tǒng)中進程調(diào)度情況，記錄進程的切換時間、切換原因等信息，對于分析系統(tǒng)的調(diào)度性能和進程間的資源競爭問題非常有用；Irqsoff 追蹤器專注于跟蹤禁止中斷的函數(shù)及相關(guān)信息，能夠記錄中斷被禁止的時長，幫助開發(fā)者定位那些可能導(dǎo)致系統(tǒng)響應(yīng)延遲的中斷操作；Preemptoff 追蹤器則用于跟蹤禁止內(nèi)核搶占的函數(shù)及相關(guān)信息，對于優(yōu)化系統(tǒng)的實時性和響應(yīng)速度具有重要意義。
3.3數(shù)據(jù)記錄與存儲
當(dāng) Ftrace 通過插樁技術(shù)收集到各種跟蹤信息后，這些信息需要被有效地記錄和存儲起來，以便用戶后續(xù)查看和分析。Ftrace 采用了 Ring buffer 緩沖區(qū)來存儲這些跟蹤數(shù)據(jù)。
Ring buffer，也稱為環(huán)形緩沖區(qū)，是一種特殊的數(shù)據(jù)結(jié)構(gòu)，它就像一個首尾相連的環(huán)形數(shù)組。在 Ftrace 中，Ring buffer 的工作原理如下：當(dāng)有新的跟蹤信息產(chǎn)生時，F(xiàn)trace 會將其依次寫入 Ring buffer 中。當(dāng) Ring buffer 被寫滿后，新的數(shù)據(jù)會覆蓋最早寫入的數(shù)據(jù)，就像一個循環(huán)的隊列一樣。這種設(shè)計方式可以確保 Ring buffer 能夠持續(xù)地記錄最新的跟蹤信息，同時又不會因為數(shù)據(jù)過多而占用大量的內(nèi)存空間。在讀取數(shù)據(jù)時，用戶可以從 Ring buffer 的頭部開始讀取，讀取完的數(shù)據(jù)不會被立即刪除，而是等待被新的數(shù)據(jù)覆蓋。這樣，用戶可以根據(jù)自己的需求，多次讀取 Ring buffer 中的數(shù)據(jù)，進行不同角度的分析。
為了方便用戶操作和管理 Ring buffer 中的數(shù)據(jù)，F(xiàn)trace 通過debugfs文件系統(tǒng)向用戶空間提供了一系列的接口文件。用戶可以通過這些文件，輕松地開啟或停止跟蹤、選擇使用的追蹤器、設(shè)置跟蹤的過濾條件，以及讀取 Ring buffer 中存儲的跟蹤信息。在/sys/kernel/debug/tracing目錄下，有許多與 Ftrace 相關(guān)的文件，其中trace文件用于以人類可讀的格式展示當(dāng)前追蹤的內(nèi)容，用戶可以通過cat trace命令查看這些內(nèi)容；tracing_on文件則用于控制追蹤的開啟和停止，向該文件寫入1表示啟用追蹤，寫入0表示停止追蹤 。通過這些簡單的文件操作，用戶就可以靈活地使用 Ftrace 進行各種內(nèi)核跟蹤和分析工作。
四、ftrace的實現(xiàn)
研究 tracer 的實現(xiàn)是非常有樂趣的。理解 ftrace 的實現(xiàn)能夠啟發(fā)我們在自己的系統(tǒng)中設(shè)計更好的 trace 功能。
4.1ftrace 的整體構(gòu)架
圖片
Ftrace 有兩大組成部分，一是 framework，另外就是一系列的 tracer 。每個 tracer 完成不同的功能，它們統(tǒng)一由 framework 管理。ftrace 的 trace 信息保存在 ring buffer 中，由 framework 負(fù)責(zé)管理。Framework 利用 debugfs 系統(tǒng)在 /debugfs 下建立 tracing 目錄，并提供了一系列的控制文件。
一句話總結(jié)：各類tracer往ftrace主框架注冊，不同的trace則在不同的probe點把信息通過probe函數(shù)給送到ring buffer中，再由暴露在用戶態(tài)debufs實現(xiàn)相關(guān)控制。對不同tracer來說：
- 1）需要實現(xiàn)probe點（需要跟蹤的代碼偵測點），有的probe點需要靜態(tài)代碼實現(xiàn)，有的probe點借助編譯器在運行時動態(tài)替換，event tracing屬于前者；
- 2）還要實現(xiàn)具體的probe函數(shù)，把需要記錄的信息送到ring buffer中；
- 3）增加debugfs 相關(guān)的文件，實現(xiàn)信息的解析和控制。
而ring buffer 和debugfs的通用部分的管理由框架負(fù)責(zé)。
4.2Function tracer 的實現(xiàn)
Ftrace 采用 GCC 的 profile 特性在所有內(nèi)核函數(shù)的開始部分加入一段 stub 代碼，ftrace 重載這段代碼來實現(xiàn) trace 功能。gcc 的 -pg 選項將在每個函數(shù)入口處加入對 mcount 的調(diào)用代碼。比如下面的 C 代碼。
清單 1. test.c
//test.c
void foo(void)
{
printf( “ foo ” );
}用 gcc 編譯：
gcc – S test.c反匯編如下：
清單 2. test.c 不加入 pg 選項的匯編代碼
_foo:
pushl %ebp
movl %esp, %ebp
subl $8, %esp
movl $LC0, (%esp)
call _printf
leave
ret再加入 -gp 選項編譯：
gcc –pg –S test.c得到的匯編如下：
清單 3. test.c 加入 pg 選項后的匯編代碼
_foo:
pushl %ebp
movl %esp, %ebp
subl $8, %esp
LP3:
movl $LP3,%edx
call _mcount
movl $LC0, (%esp)
call _printf
leave
ret增加 pg 選項后，gcc 在函數(shù) foo 的入口處加入了對 mcount 的調(diào)用：call _mcount 。原本 mcount 由 libc 實現(xiàn)，但您知道內(nèi)核不會連接 libc 庫，因此 ftrace 編寫了自己的 mcount stub 函數(shù)，并借此實現(xiàn) trace 功能。
在每個內(nèi)核函數(shù)入口加入 trace 代碼，必然會影響內(nèi)核的性能，為了減小對內(nèi)核性能的影響，ftrace 支持動態(tài) trace 功能。
當(dāng) CONFIG_DYNAMIC_FTRACE 被選中后，內(nèi)核編譯時會調(diào)用一個 perl 腳本：recordmcount.pl 將每個函數(shù)的地址寫入一個特殊的段：__mcount_loc
在內(nèi)核初始化的初期，ftrace 查詢 __mcount_loc 段，得到每個函數(shù)的入口地址，并將 mcount 替換為 nop 指令。這樣在默認(rèn)情況下，ftrace 不會對內(nèi)核性能產(chǎn)生影響。
當(dāng)用戶打開 ftrace 功能時，ftrace 將這些 nop 指令動態(tài)替換為 ftrace_caller，該函數(shù)將調(diào)用用戶注冊的 trace 函數(shù)。其具體的實現(xiàn)在相應(yīng) arch 的匯編代碼中，以 x86 為例，在 entry_32.s 中：
清單 4. entry_32.s
ENTRY(ftrace_caller)
cmpl $0, function_trace_stop
jne ftrace_stub
pushl %eax
pushl %ecx
pushl %edx
movl 0xc(%esp), %eax
movl 0x4(%ebp), %edx
subl $MCOUNT_INSN_SIZE, %eax
.globl ftrace_call
ftrace_call:
call ftrace_stubline 10popl %edx
popl %ecx
popl %eax
.globl ftrace_stub
ftrace_stub:
ret
END(ftrace_caller)Function tracer 將 line10 這行代碼替換為 function_trace_call() 。這樣每個內(nèi)核函數(shù)都將調(diào)用 function_trace_call() 。
在 function_trace_call() 函數(shù)內(nèi)，ftrace 記錄函數(shù)調(diào)用堆棧信息，并將結(jié)果寫入 ring buffer，稍后，用戶可以通過 debugfs 的 trace 文件讀取該 ring buffer 中的內(nèi)容。
4.3 Irqsoff tracer 的實現(xiàn)
Irqsoff tracer 的實現(xiàn)依賴于 IRQ-Flags 。IRQ-Flags 是 Ingo Molnar 維護的一個內(nèi)核特性。使得用戶能夠在中斷關(guān)閉和打開時得到通知，ftrace 重載了其通知函數(shù)，從而能夠記錄中斷禁止時間。即，中斷被關(guān)閉時，記錄下當(dāng)時的時間戳。此后，中斷被打開時，再計算時間差，由此便可得到中斷禁止時間。
IRQ-Flags 封裝開關(guān)中斷的宏定義：
清單 5. IRQ-Flags 中斷代碼
#define local_irq_enable() \
do { trace_hardirqs_on (); raw_local_irq_enable(); } while (0)ftrace 在文件 ftrace_irqsoff.c 中重載了 trace_hardirqs_on 。具體代碼不再羅列，主要是使用了 sched_clock（）函數(shù)來獲得時間戳。
4.4hw-branch 的實現(xiàn)
Hw-branch 只在 IA 處理器上實現(xiàn)，依賴于 x86 的 BTS 功能。BTS 將 CPU 實際執(zhí)行到的分支指令的相關(guān)信息保存下來，即每個分支指令的源地址和目標(biāo)地址。
軟件可以指定一塊 buffer，處理器將每個分支指令的執(zhí)行情況寫入這塊 buffer，之后，軟件便可以分析這塊 buffer 中的功能。
Linux 內(nèi)核的 DS 模塊封裝了 x86 的 BTS 功能。Debug Support 模塊封裝了和底層硬件的接口，主要支持兩種功能：Branch trace store(BTS) 和 precise-event based sampling (PEBS) 。ftrace 主要使用了 BTS 功能。
4.5branch tracer 的實現(xiàn)
內(nèi)核代碼中常使用 likely 和 unlikely 提高編譯器生成的代碼質(zhì)量。Gcc 可以通過合理安排匯編代碼最大限度的利用處理器的流水線。合理的預(yù)測是 likely 能夠提高性能的關(guān)鍵，ftrace 為此定義了 branch tracer，跟蹤程序中 likely 預(yù)測的正確率。
為了實現(xiàn) branch tracer，重新定義了 likely 和 unlikely 。具體的代碼在 compiler.h 中。
清單 6. likely/unlikely 的 trace 實現(xiàn)
# ifndef likely
# define likely(x) (__builtin_constant_p(x) ? !!(x) : __branch_check__(x, 1))
# endif
# ifndef unlikely
# define unlikely(x) (__builtin_constant_p(x) ? !!(x) : __branch_check__(x, 0))
# endif其中 __branch_check 的實現(xiàn)如下：
清單 7. _branch_check_ 的實現(xiàn)
#define __branch_check__(x, expect) ({\
int ______r; \
static struct ftrace_branch_data \
__attribute__((__aligned__(4))) \
__attribute__((section("_ftrace_annotated_branch"))) \
______f = { \
.func = __func__, \
.file = __FILE__, \
.line = __LINE__, \
}; \
______r = likely_notrace(x);\
ftrace_likely_update(&______f, ______r, expect); \
______r; \
})ftrace_likely_update() 將記錄 likely 判斷的正確性，并將結(jié)果保存在 ring buffer 中，之后用戶可以通過 ftrace 的 debugfs 接口讀取分支預(yù)測的相關(guān)信息。從而調(diào)整程序代碼，優(yōu)化性能。
五、Ftrace 的實戰(zhàn)應(yīng)用
5.1性能優(yōu)化
在性能優(yōu)化領(lǐng)域，F(xiàn)trace 的作用不可小覷，尤其是在優(yōu)化文件系統(tǒng)性能方面。假設(shè)我們在一個數(shù)據(jù)存儲服務(wù)器上發(fā)現(xiàn)文件讀寫操作的速度明顯變慢，嚴(yán)重影響了業(yè)務(wù)的正常運行。這時，我們可以利用 Ftrace 的 Function graph tracer 來深入分析文件系統(tǒng)相關(guān)函數(shù)的執(zhí)行情況。
通過設(shè)置跟蹤器為 Function graph tracer，并將需要跟蹤的文件讀寫函數(shù)（如vfs_read、vfs_write等）添加到set_graph_function文件中，然后啟動跟蹤。在服務(wù)器進行文件讀寫操作的過程中，F(xiàn)trace 會記錄下這些函數(shù)的調(diào)用關(guān)系和執(zhí)行時間。從跟蹤結(jié)果中，我們可能會發(fā)現(xiàn)vfs_read函數(shù)在調(diào)用ext4_readpage函數(shù)時花費了大量時間，進一步分析發(fā)現(xiàn)是因為文件系統(tǒng)的塊分配策略不合理，導(dǎo)致頻繁的磁盤 I/O 操作?；谶@些發(fā)現(xiàn)，我們可以針對性地優(yōu)化塊分配算法，減少不必要的磁盤 I/O，從而顯著提升文件系統(tǒng)的讀寫性能。
5.2故障排查
當(dāng)系統(tǒng)出現(xiàn)響應(yīng)延遲、進程卡頓等問題時，F(xiàn)trace 能夠成為我們定位問題的關(guān)鍵工具。例如，在一個運行著多個服務(wù)的服務(wù)器上，用戶反饋系統(tǒng)響應(yīng)變得遲緩。此時，我們可以使用 Ftrace 的 Irqsoff Tracer 來跟蹤中斷被禁止的情況。因為長時間禁止中斷可能會導(dǎo)致系統(tǒng)無法及時響應(yīng)外部事件，從而出現(xiàn)延遲現(xiàn)象。
啟用 Irqsoff Tracer 后，F(xiàn)trace 會記錄下所有禁止中斷的函數(shù)以及中斷被禁止的時長。通過分析這些記錄，我們可能會發(fā)現(xiàn)某個設(shè)備驅(qū)動程序中的中斷處理函數(shù)存在問題，它在處理中斷時長時間占用 CPU 資源，導(dǎo)致其他中斷無法及時得到處理，進而影響了系統(tǒng)的整體響應(yīng)速度。找到問題后，我們可以對該驅(qū)動程序進行優(yōu)化，例如調(diào)整中斷處理邏輯，將一些耗時操作放到線程中執(zhí)行，以減少對中斷的影響，從而解決系統(tǒng)響應(yīng)延遲的問題。
5.3內(nèi)核開發(fā)與調(diào)試
在開發(fā)新的內(nèi)核模塊時，開發(fā)者需要確保模塊中的函數(shù)調(diào)用正確無誤。例如，開發(fā)一個新的網(wǎng)絡(luò)協(xié)議模塊，使用 Ftrace 的 Function tracer，開發(fā)者可以清晰地看到該模塊中各個函數(shù)的調(diào)用順序和參數(shù)傳遞情況。如果發(fā)現(xiàn)某個函數(shù)沒有按照預(yù)期被調(diào)用，或者參數(shù)傳遞出現(xiàn)錯誤，就可以及時調(diào)整代碼，確保函數(shù)調(diào)用的正確性。
Ftrace 還可以用于跟蹤系統(tǒng)調(diào)用，幫助開發(fā)者了解應(yīng)用程序與內(nèi)核之間的交互過程。當(dāng)應(yīng)用程序調(diào)用系統(tǒng)調(diào)用時，F(xiàn)trace 可以記錄下系統(tǒng)調(diào)用的入口函數(shù)、參數(shù)以及返回值等信息。在調(diào)試一個新的文件操作函數(shù)時，通過跟蹤系統(tǒng)調(diào)用，開發(fā)者可以發(fā)現(xiàn)函數(shù)在處理文件權(quán)限驗證時出現(xiàn)錯誤，導(dǎo)致文件操作失敗，進而對權(quán)限驗證邏輯進行修正。
在調(diào)試內(nèi)核模塊時，F(xiàn)trace 同樣發(fā)揮著重要作用。當(dāng)內(nèi)核模塊出現(xiàn)異常時，F(xiàn)trace 記錄的函數(shù)調(diào)用棧信息可以幫助開發(fā)者快速定位到問題所在。例如，一個內(nèi)核模塊在加載時崩潰，通過查看 Ftrace 的跟蹤記錄，開發(fā)者可以找到導(dǎo)致崩潰的函數(shù)以及該函數(shù)的調(diào)用路徑，從而深入分析問題的原因，進行針對性的調(diào)試和修復(fù)。
六、Ftrace 的使用方法與技巧
6.1環(huán)境配置
在使用 Ftrace 之前，首先需要確保內(nèi)核啟用了相關(guān)的配置選項。這一步至關(guān)重要，因為只有正確配置內(nèi)核，F(xiàn)trace 才能發(fā)揮其強大的功能。在編譯內(nèi)核時，可以通過make menuconfig命令進入內(nèi)核配置界面。在該界面中，找到 “Kernel hacking” 選項，進入后再找到 “Tracers” 選項 。
在這里，需要確保 “Tracing support” 以及其他與 Ftrace 相關(guān)的選項（如 “Kernel Function Tracer”“Kernel Function Graph Tracer” 等）被勾選。這些選項分別對應(yīng)著 Ftrace 的不同功能，勾選后才能啟用相應(yīng)的跟蹤功能。
除了內(nèi)核配置，還需要掛載debugfs文件系統(tǒng)。debugfs是一種特殊的文件系統(tǒng)，F(xiàn)trace 通過它向用戶空間提供訪問接口。掛載debugfs文件系統(tǒng)的方法有兩種。一種是將其添加到/etc/fstab文件中，實現(xiàn)自動掛載。具體操作是在/etc/fstab文件中添加一行 “debugfs /sys/kernel/debug debugfs defaults 0 0”，這樣在系統(tǒng)啟動時，debugfs文件系統(tǒng)就會自動掛載到/sys/kernel/debug目錄下。
另一種方法是手動掛載，使用命令 “mount -t debugfs none /sys/kernel/debug” ，該命令會將debugfs文件系統(tǒng)臨時掛載到/sys/kernel/debug目錄，這種方式適用于臨時使用 Ftrace 進行調(diào)試的場景。
6.2常用命令與參數(shù)
在/sys/kernel/debug/tracing目錄下，有許多用于控制和使用 Ftrace 的文件，這些文件對應(yīng)著各種常用命令和參數(shù)。
echo 1 > tracing_on用于啟用追蹤，當(dāng)需要開始記錄內(nèi)核函數(shù)調(diào)用和系統(tǒng)事件時，執(zhí)行這個命令，F(xiàn)trace 就會開始工作，將跟蹤信息寫入 Ring buffer 中；而echo 0 > tracing_on則用于停止追蹤，當(dāng)不需要繼續(xù)跟蹤時，執(zhí)行該命令可以停止 Ftrace 的記錄操作，避免不必要的性能開銷和數(shù)據(jù)占用。
echo function > current_tracer用于設(shè)置當(dāng)前使用的追蹤器為 Function tracer，通過修改current_tracer文件的內(nèi)容，可以切換不同的追蹤器，以滿足不同的跟蹤需求。例如，若要使用 Function graph tracer，就可以執(zhí)行echo function_graph > current_tracer 。
echo vfs_read > set_ftrace_filter用于設(shè)置過濾條件，只跟蹤特定的函數(shù)。在這個例子中，只有vfs_read函數(shù)的調(diào)用信息會被記錄，其他函數(shù)的信息將被忽略。這在需要專注分析某個特定函數(shù)的行為時非常有用，可以減少大量無關(guān)信息的干擾，使分析更加高效和準(zhǔn)確。
6.3使用技巧與注意事項
在使用 Ftrace 時，合理設(shè)置過濾條件可以大大提高分析效率。除了可以通過set_ftrace_filter指定要跟蹤的函數(shù)外，還可以使用正則表達式來匹配多個函數(shù)。echo '*lock*' > set_ftrace_filter表示跟蹤所有包含 “l(fā)ock” 字樣的函數(shù)，這樣可以一次性跟蹤多個相關(guān)函數(shù)，方便對特定功能模塊的分析。
控制追蹤范圍也是一個重要技巧?？梢酝ㄟ^set_ftrace_pid文件指定要跟蹤的進程 ID，從而只跟蹤特定進程的函數(shù)調(diào)用。echo 1234 > set_ftrace_pid表示只跟蹤進程 ID 為 1234 的進程，這樣可以避免其他進程的干擾，更精準(zhǔn)地分析目標(biāo)進程的行為。
處理大量追蹤數(shù)據(jù)時，需要注意數(shù)據(jù)的存儲和分析。由于 Ftrace 生成的跟蹤數(shù)據(jù)可能會占用大量磁盤空間，因此可以定期清理trace文件，或者將數(shù)據(jù)導(dǎo)出到其他存儲設(shè)備進行長期保存。在分析數(shù)據(jù)時，可以結(jié)合其他工具，如trace-cmd或bpftrace ，這些工具能夠?qū)?Ftrace 生成的數(shù)據(jù)進行更深入的分析和可視化處理，幫助用戶更直觀地理解系統(tǒng)行為和性能瓶頸。
同時，還需注意 Ftrace 對系統(tǒng)性能的影響。由于 Ftrace 會在內(nèi)核中插入額外的代碼來實現(xiàn)跟蹤功能，因此在開啟 Ftrace 時，可能會對系統(tǒng)性能產(chǎn)生一定的影響，特別是在跟蹤大量函數(shù)時。所以，在生產(chǎn)環(huán)境中使用 Ftrace 時，應(yīng)謹(jǐn)慎開啟，并盡量縮短跟蹤時間，以減少對系統(tǒng)正常運行的影響。
七、實戰(zhàn)案列：隱藏的電燈開關(guān)
7.1 iosnoop
首先，Gregg 使用 iosnoop 工具進行檢查，iosnoop 用來跟蹤 I/O 的詳細(xì)信息，當(dāng)然也包括 latency，結(jié)果如下：
# ./iosnoop -ts
STARTs ENDs COMM PID TYPE DEV BLOCK BYTES LATms
13370264.614265 13370264.614844 java 8248 R 202,32 1431244248 45056 0.58
13370264.614269 13370264.614852 java 8248 R 202,32 1431244336 45056 0.58
13370264.614271 13370264.614857 java 8248 R 202,32 1431244424 45056 0.59
13370264.614273 13370264.614868 java 8248 R 202,32 1431244512 45056 0.59
[...]
# ./iosnoop -Qts
STARTs ENDs COMM PID TYPE DEV BLOCK BYTES LATms
13370410.927331 13370410.931182 java 8248 R 202,32 1596381840 45056 3.85
13370410.927332 13370410.931200 java 8248 R 202,32 1596381928 45056 3.87
13370410.927332 13370410.931215 java 8248 R 202,32 1596382016 45056 3.88
13370410.927332 13370410.931226 java 8248 R 202,32 1596382104 45056 3.89
[...]上面看不出來啥，一個繁忙的 I/O，勢必會帶來高的 latency。我們來說說 iosnoop 是如何做的。
iosnoop 主要是處理的 block 相關(guān)的 event，主要是：
- block:block_rq_issue - I/O 發(fā)起的時候的事件
- block:block_rq_complete - I/O 完成事件
- block:block_rq_insert - I/O 加入隊列的時間
如果使用了 -Q 參數(shù)，我們對于 I/O 開始事件就用 block:block_rq_insert，否則就用的 block:block_rq_issue 。下面是我用 FIO 測試 trace 的輸出：
fio-30749 [036] 5651360.257707: block_rq_issue: 8,0 WS 4096 () 1367650688 + 8 [fio]
<idle>-0 [036] 5651360.257768: block_rq_complete: 8,0 WS () 1367650688 + 8 [0]我們根據(jù)1367650688 + 8能找到對應(yīng)的 I/O block sector，然后根據(jù) issue 和 complete 的時間就能知道 latency 了。
7.2 t點
為了更好的定位 I/O 問題，Gregg 使用 tpoint 來追蹤 block_rq_insert，如下：
# ./tpoint -H block:block_rq_insert
Tracing block:block_rq_insert. Ctrl-C to end.
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
java-16035 [000] 13371565.253582: block_rq_insert: 202,16 WS 0 () 550505336 + 88 [java]
java-16035 [000] 13371565.253582: block_rq_insert: 202,16 WS 0 () 550505424 + 56 [java]
java-8248 [007] 13371565.278372: block_rq_insert: 202,32 R 0 () 660621368 + 88 [java]
java-8248 [007] 13371565.278373: block_rq_insert: 202,32 R 0 () 660621456 + 88 [java]
java-8248 [007] 13371565.278374: block_rq_insert: 202,32 R 0 () 660621544 + 24 [java]
java-8249 [007] 13371565.311507: block_rq_insert: 202,32 R 0 () 660666416 + 88 [java]
[...]然后也跟蹤了實際的堆棧：
# ./tpoint -s block:block_rq_insert 'rwbs ~ "*R*"' | head -1000
Tracing block:block_rq_insert. Ctrl-C to end.
java-8248 [005] 13370789.973826: block_rq_insert: 202,16 R 0 () 1431480000 + 8 [java]
java-8248 [005] 13370789.973831: <stack trace>
=> blk_flush_plug_list
=> blk_queue_bio
=> generic_make_request.part.50
=> generic_make_request
=> submit_bio
=> do_mpage_readpage
=> mpage_readpages
=> xfs_vm_readpages
=> read_pages
=> __do_page_cache_readahead
=> ra_submit
=> do_sync_mmap_readahead.isra.24
=> filemap_fault
=> __do_fault
=> handle_pte_fault
=> handle_mm_fault
=> do_page_fault
=> page_fault
java-8248 [005] 13370789.973831: block_rq_insert: 202,16 R 0 () 1431480024 + 32 [java]
java-8248 [005] 13370789.973836: <stack trace>
=> blk_flush_plug_list
=> blk_queue_bio
=> generic_make_request.part.50
[...]tpoint 的實現(xiàn)比較簡單，譬如上面的 block:block_rq_insert，它直接會找events/block/block_rq_insert 是否存在，如果存在，就是找到了對應(yīng)的 event。然后給這個 event 的 enable 文件寫入 1，如果我們要開啟堆棧，就往 options/stacktrace 里面也寫入 1。
從上面的堆棧可以看到，有 readahead 以及 page fault 了。在 Netflix 新升級的 Ubuntu 系統(tǒng)里面，默認(rèn)的 direct map page size 是 2 MB，而之前的 系統(tǒng)是 4 KB，另外就是默認(rèn)的 readahead 是 2048 KB，老的系統(tǒng)是 128 KB?？雌饋砺业絾栴}了。
7.3函數(shù)計數(shù)
為了更好的看函數(shù)調(diào)用的次數(shù)，Gregg 使用了 funccount 函數(shù)，譬如檢查 submit_bio ：
# ./funccount -i 1 submit_bio
Tracing "submit_bio"... Ctrl-C to end.
FUNC COUNT
submit_bio 27881
FUNC COUNT
submit_bio 28478
# ./funccount -i 1 filemap_fault
Tracing "filemap_fault"... Ctrl-C to end.
FUNC COUNT
filemap_fault 2203
FUNC COUNT
filemap_fault 3227
[...]上面可以看到，有 10 倍的膨脹。對于 funccount 腳本，主要是需要開啟 function profile 功能，也就是給 function_profile_enabled 文件寫入 1，當(dāng)打開之后，就會在 trace_stat 目錄下面對相關(guān)的函數(shù)進行統(tǒng)計，可以看到 function0，function1 這樣的文件，0 和 1 就是對應(yīng)的 CPU。cat 一個文件:
cat function0
Function Hit Time Avg s^2
-------- --- ---- --- ---
schedule 56 12603274 us 225058.4 us 4156108562 us
do_idle 51 4750521 us 93147.47 us 5947176878 us
call_cpuidle 51 4748981 us 93117.27 us 5566277250 us就能知道各個函數(shù)的 count 了。
7.4功能變慢
為了更加確定系統(tǒng)的延遲是先前堆棧上面看到的函數(shù)引起的，Gregg 使用了 funcslower 來看執(zhí)行慢的函數(shù)：
# ./funcslower -P filemap_fault 1000
Tracing "filemap_fault" slower than 1000 us... Ctrl-C to end.
0) java-8210 | ! 5133.499 us | } /* filemap_fault */
0) java-8258 | ! 1120.600 us | } /* filemap_fault */
0) java-8235 | ! 6526.470 us | } /* filemap_fault */
2) java-8245 | ! 1458.30 us | } /* filemap_fault */
[...]可以看到，filemap_fault 這個函數(shù)很慢。對于 funcslower，我們主要是用 tracing_thresh 來進行控制，給這個文件寫入 threshold，如果函數(shù)的執(zhí)行時間超過了 threshold，就會記錄。
7.5funccount（再次）
Gregg 根據(jù)堆棧的情況，再次對 readpage 和 readpages 進行統(tǒng)計：
# ./funccount -i 1 '*mpage_readpage*'
Tracing "*mpage_readpage*"... Ctrl-C to end.
FUNC COUNT
mpage_readpages 364
do_mpage_readpage 122930
FUNC COUNT
mpage_readpages 318
do_mpage_readpage 110344
[...]仍然定位到是 readahead 的寫放大引起，但他們已經(jīng)調(diào)整了 readahead 的值，但并沒有起到作用。
7.6k探頭
因為 readahead 并沒有起到作用，所以 Gregg 準(zhǔn)備更進一步，使用 dynamic tracing。他注意到上面堆棧的函數(shù) __do_page_cache_readahead() 有一個 nr_to_read 的參數(shù)，這個參數(shù)表明的是每次 read 需要讀取的 pages 的個數(shù)，使用 kprobe：
# ./kprobe -H 'p:do __do_page_cache_readahead nr_to_read=%cx'
Tracing kprobe m. Ctrl-C to end.
# tracer: nop
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
java-8714 [000] 13445354.703793: do: (__do_page_cache_readahead+0x0/0x180) nr_to_read=200
java-8716 [002] 13445354.819645: do: (__do_page_cache_readahead+0x0/0x180) nr_to_read=200
java-8734 [001] 13445354.820965: do: (__do_page_cache_readahead+0x0/0x180) nr_to_read=200
java-8709 [000] 13445354.825280: do: (__do_page_cache_readahead+0x0/0x180) nr_to_read=200
[...]可以看到，每次 nr_to_read 讀取了 512 （200 的 16 進制）個 pages。在上面的例子，他并不知道 nr_to_read 實際的符號是多少，于是用 %cx 來猜測的，也真能蒙對，太猛了。
關(guān)于 kprobe 的使用，具體可以參考 kprobetrace 文檔，kprobe 解析需要 trace 的 event 之后，會將其寫入到 kprobe_events 里面，然后在 events/kprobes/<EVENT>/ 進行對應(yīng)的 enable 和 filter 操作。
7.7函數(shù)圖
為了更加確認(rèn)，Gregg 使用 funcgraph 來看 filemap_fault 的實際堆棧，來看 nr_to_read 到底是從哪里傳進來的。
# ./funcgraph -P filemap_fault | head -1000
2) java-8248 | | filemap_fault() {
2) java-8248 | 0.568 us | find_get_page();
2) java-8248 | | do_sync_mmap_readahead.isra.24() {
2) java-8248 | 0.160 us | max_sane_readahead();
2) java-8248 | | ra_submit() {
2) java-8248 | | __do_page_cache_readahead() {
2) java-8248 | | __page_cache_alloc() {
2) java-8248 | | alloc_pages_current() {
2) java-8248 | 0.228 us | interleave_nodes();
2) java-8248 | | alloc_page_interleave() {
2) java-8248 | | __alloc_pages_nodemask() {
2) java-8248 | 0.105 us | next_zones_zonelist();
2) java-8248 | | get_page_from_freelist() {
2) java-8248 | 0.093 us | next_zones_zonelist();
2) java-8248 | 0.101 us | zone_watermark_ok();
2) java-8248 | | zone_statistics() {
2) java-8248 | 0.073 us | __inc_zone_state();
2) java-8248 | 0.074 us | __inc_zone_state();
2) java-8248 | 1.209 us | }
2) java-8248 | 0.142 us | prep_new_page();
2) java-8248 | 3.582 us | }
2) java-8248 | 4.810 us | }
2) java-8248 | 0.094 us | inc_zone_page_state();找到了一個比較明顯的函數(shù) max_sane_readahead。對于 funcgraph，主要就是將需要關(guān)注的函數(shù)放到 set_graph_function 里面，然后在 current_tracer 里面開啟 function_graph。
7.8 k探針（再次）
然后，Gregg 繼續(xù)使用 kprobe 來 trace max_sane_readahead 函數(shù)，這次不用猜測寄存器了，直接用 $retval 來看返回值:
# ./kprobe 'r:m max_sane_readahead $retval'
Tracing kprobe m. Ctrl-C to end.
java-8700 [000] 13445377.393895: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
java-8723 [003] 13445377.396362: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
java-8701 [001] 13445377.398216: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
java-8738 [000] 13445377.399793: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
java-8728 [000] 13445377.408529: m: (do_sync_mmap_readahead.isra.24+0x62/0x9c <- \
max_sane_readahead) arg1=200
[...]發(fā)現(xiàn)仍然是 0x200 個 pages，然后他在發(fā)現(xiàn)，readahead 的屬性其實是在 file_ra_state_init 這個函數(shù)就設(shè)置好了，然后這個函數(shù)是在文件打開的時候調(diào)用的。但他在進行 readahead tune 的時候，一直是讓 Cassandra 運行著，也就是無論怎么改 readahead，都不會起到作用，于是他把 Cassandra 重啟，問題解決了。
# ./kprobe 'r:m max_sane_readahead $retval'
Tracing kprobe m. Ctrl-C to end.
java-11918 [007] 13445663.126999: m: (ondemand_readahead+0x3b/0x230 <- \
max_sane_readahead) arg1=80
java-11918 [007] 13445663.128329: m: (ondemand_readahead+0x3b/0x230 <- \
max_sane_readahead) arg1=80
java-11918 [007] 13445663.129795: m: (ondemand_readahead+0x3b/0x230 <- \
max_sane_readahead) arg1=80
java-11918 [007] 13445663.131164: m: (ondemand_readahead+0x3b/0x230 <- \
max_sane_readahead) arg1=80
[...]這次只會讀取 0x80 個 pages 了。
上面就是一個完完整整使用 ftrace 來定位問題的例子，可以看到，雖然 Linux 系統(tǒng)在很多時候?qū)ξ覀兪且粋€黑盒，但是有了 ftrace，如果在黑暗中開啟了一盞燈，能讓我們朝著光亮前行。我們內(nèi)部也在基于 ftrace 做很多有意思的事情。
八、Ftrace 與其他追蹤工具的比較
在 Linux 性能分析與調(diào)試領(lǐng)域，除了 Ftrace，還有 SystemTap、LTTng 等知名的追蹤工具，它們各自有著獨特的特點，適用于不同的場景。
8.1功能對比
Ftrace 作為 Linux 內(nèi)核自帶的跟蹤工具，主要聚焦于內(nèi)核函數(shù)的調(diào)用、系統(tǒng)事件以及內(nèi)核行為的跟蹤。它提供了豐富的追蹤器，如 Function Tracer 用于記錄內(nèi)核函數(shù)調(diào)用情況，F(xiàn)unction Graph Tracer 以圖形化展示函數(shù)調(diào)用關(guān)系 ，這些功能使得開發(fā)者能夠深入了解內(nèi)核的運行機制，對于內(nèi)核開發(fā)和性能優(yōu)化非常有幫助。
SystemTap 則功能更為強大和靈活，它允許開發(fā)者使用腳本語言編寫復(fù)雜的跟蹤腳本。通過這些腳本，SystemTap 可以對內(nèi)核行為進行深度分析，不僅能跟蹤內(nèi)核函數(shù)，還能對系統(tǒng)調(diào)用、用戶空間程序與內(nèi)核的交互等進行全面的跟蹤和分析。在分析復(fù)雜的系統(tǒng)性能問題時，SystemTap 可以通過編寫腳本來統(tǒng)計特定系統(tǒng)調(diào)用的執(zhí)行次數(shù)、執(zhí)行時間等，從而找出性能瓶頸所在。
LTTng 的功能側(cè)重于提供詳細(xì)的事件跟蹤，包括 CPU 調(diào)度、中斷處理、系統(tǒng)調(diào)用、信號傳遞等眾多方面。它支持同時跟蹤內(nèi)核空間和用戶空間的活動，并且提供了高效的二進制接口和獨立的緩沖設(shè)計，適合進行深入的性能分析和故障診斷。在分析多線程應(yīng)用程序的性能問題時，LTTng 可以精確地記錄每個線程的調(diào)度時間、執(zhí)行時間以及線程之間的同步操作，幫助開發(fā)者找出線程相關(guān)的性能瓶頸。
8.2使用難度對比
Ftrace 的使用相對較為簡單。用戶主要通過debugfs文件系統(tǒng)與 Ftrace 進行交互，通過對/sys/kernel/debug/tracing目錄下的文件進行簡單的讀寫操作，就能實現(xiàn)跟蹤器的設(shè)置、跟蹤的啟動與停止以及跟蹤數(shù)據(jù)的查看等功能 。對于熟悉 Linux 文件操作的開發(fā)者來說，很容易上手。
SystemTap 的使用難度則較高。由于它需要開發(fā)者編寫腳本，而這些腳本涉及到特定的語法和函數(shù)調(diào)用，學(xué)習(xí)成本相對較大。編寫一個能夠準(zhǔn)確獲取所需信息的 SystemTap 腳本，需要開發(fā)者對系統(tǒng)的運行機制有深入的了解，并且熟練掌握 SystemTap 的腳本語言。對于初學(xué)者來說，可能需要花費一定的時間和精力來學(xué)習(xí)和掌握。
LTTng 的使用難度介于 Ftrace 和 SystemTap 之間。它提供了一套命令行工具來控制跟蹤會話，如啟動 / 停止跟蹤、配置跟蹤點等。雖然命令行操作相對復(fù)雜一些，但相比于編寫腳本，還是較為容易掌握的。不過，在進行復(fù)雜的跟蹤配置和數(shù)據(jù)分析時，仍然需要開發(fā)者對 LTTng 的原理和使用方法有一定的了解。
8.3性能影響對比
Ftrace 采用靜態(tài)代碼插裝技術(shù)，在不進行跟蹤時，對系統(tǒng)性能的影響極小。因為在非跟蹤狀態(tài)下，它通過將跳轉(zhuǎn)指令替換為nop指令，幾乎不占用系統(tǒng)資源 。而在開啟跟蹤時，雖然會有一定的性能開銷，但由于其設(shè)計的輕量級特性，這種影響在大多數(shù)情況下是可以接受的，特別是在只跟蹤少量關(guān)鍵函數(shù)時，對系統(tǒng)性能的影響微乎其微。
SystemTap 在運行時，會將腳本語句翻譯成 C 語句并編譯成內(nèi)核模塊，這個過程會消耗一定的 CPU 資源。而且，由于其功能強大，可能會對系統(tǒng)性能產(chǎn)生較大的影響，特別是在編寫的腳本較為復(fù)雜或者跟蹤的范圍較廣時。在生產(chǎn)環(huán)境中使用 SystemTap 時，需要謹(jǐn)慎評估其對系統(tǒng)性能的影響，避免因性能問題導(dǎo)致系統(tǒng)不穩(wěn)定。
LTTng 在設(shè)計時就考慮到了對系統(tǒng)性能的最小影響，采用了鎖定最小化、CPU 本地緩存和批量處理等技術(shù)，確保在高負(fù)載下也能保持較低的開銷。它能夠在不顯著影響系統(tǒng)性能的前提下，收集大量的跟蹤數(shù)據(jù)，這使得它在生產(chǎn)環(huán)境中的應(yīng)用較為廣泛。不過，在極端情況下，如跟蹤大量事件且系統(tǒng)資源緊張時，LTTng 仍可能對系統(tǒng)性能產(chǎn)生一定的影響。
