Linux內核追蹤神器：Ftrace實現原理剖析
在 Linux 內核這片深邃而神秘的技術海洋里，每一個系統進程的運行、每一次資源的調度，都像是在黑暗中上演的復雜劇目。內核開發者們時常面臨著棘手難題：系統莫名卡頓，究竟是哪個內核函數在作祟？進程調度出現異常，問題根源又在何處？在漫長的探索歷程中，開發者們急需一款強大的工具，能夠像聚光燈一樣，穿透重重迷霧，照亮內核運行的每一個角落。而 Ftrace，正是這樣一款應運而生的 “內核追蹤神器”。
它從最初簡單的函數跟蹤器，逐步成長為功能豐富的跟蹤框架，猶如一把萬能鑰匙，為開發者打開了深入探究內核奧秘的大門。接下來，讓我們一同深入到 Ftrace 的世界，探尋它的實現原理，看看它究竟如何施展神奇魔力，助力開發者解決內核開發與調試中的種種難題 。
一、Ftrace是什么？
根據Linux Doc 的介紹，ftrace 是一個 Linux 內部的 trace 工具，能夠幫助開發者和系統設計者知道內核當前正在干啥，從而更好的去分析性能問題。在 Linux 內核開發與系統性能優化的廣袤領域中，Ftrace 宛如一把神奇的瑞士軍刀，發揮著無可替代的關鍵作用。對于內核開發者而言，它是深入探究內核運行機制、精準定位代碼問題的得力助手；對于系統優化者來說，它是剖析系統性能瓶頸、實現高效優化的必備利器。
曾經，在一個高并發的 Web 服務器項目中，服務器在流量高峰時段出現響應延遲的狀況。運維團隊起初一頭霧水，不知問題根源所在。后來，他們借助 Ftrace 工具，對內核函數進行細致跟蹤。通過 Function Graph Tracer，清晰呈現出函數調用關系；利用 Irqsoff Tracer，監測中斷被禁止的時段。最終，成功定位到一個文件讀寫函數存在性能瓶頸，經過針對性優化，服務器響應速度大幅提升，成功解決了延遲問題。
Ftrace 能幫我們分析內核特定的事件，譬如調度，中斷等，也能幫我們去追蹤動態的內核函數，以及這些函數的調用棧還有棧的使用這些。它也能幫我們去追蹤延遲，譬如中斷被屏蔽，搶占被禁止的時間，以及喚醒一個進程之后多久開始執行的時間。
可以看到，使用 ftrace 真的能做到對系統內核非常系統的剖析，甚至都能通過 ftrace 來學習 Linux 內核，不過在更進一步之前，我們需要學會的是 - 如何使用 ftrace
二、 如何使用 ftrace
要使用 ftrace，首先就是需要將系統的 debugfs 或者 tracefs 給掛載到某個地方，幸運的是，幾乎所有的 Linux 發行版，都開啟了 debugfs/tracefs 的支持，所以我們也沒必要去重新編譯內核了。
在比較老的內核版本，譬如 CentOS 7 的上面，debugfs 通常被掛載到 /sys/kernel/debug 上面（debug 目錄下面有一個 tracing 目錄），而比較新的內核，則是將 tracefs 掛載到 /sys/kernel/tracing，無論是什么，我都喜歡將 tracing 目錄直接 link 到 /tracing。后面都會假設直接進入了 /tracing 目錄，后面，我會使用 Ubuntu 16.04 來舉例子，內核版本是 4.13 來舉例子。
在使用ftrace之前，需要內核進行支持，也就是內核需要打開編譯中的ftrace相關選項，關于怎么激活ftrace選項的問題，可以google之，下面只說明重要的設置步驟：
- mkdir /debug；mount -t debugs nodev /debug; /*掛載debugfs到創建的目錄中去*/
- cd /debug; cd tracing; /*如果沒有tracing目錄，則內核目前還沒有支持ftrace，需要配置參數，重新編譯*/。
- echo nop > current_tracer;//清空tracer
- echo function_graph > current_tracer;//使用圖形顯示調用關系
- echo ip_rcv > set_graph_function;//設置過濾函數,可以設置多個
- echo 1 > tracing_enabled開始追蹤
2.1傳統 fracer 的使用
使用傳統的 ftrace 需要如下幾個步驟：
- 選擇一種 tracer
- 使能 ftrace
- 執行需要 trace 的應用程序，比如需要跟蹤 ls，就執行 ls
- 關閉 ftrace
- 查看 trace 文件
用戶通過讀寫 debugfs 文件系統中的控制文件完成上述步驟。使用 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 的開始和結束。
#echo 1 >/debug/tracing/tracing_enable上面的命令使能 ftrace 。同樣，將 0 寫入 tracing_enable 文件便可以停止 ftrace 。
ftrace 的輸出信息主要保存在 3 個文件中：
- Trace，該文件保存 ftrace 的輸出信息，其內容可以直接閱讀。
- latency_trace，保存與 trace 相同的信息，不過組織方式略有不同。主要為了用戶能方便地分析系統中有關延遲的信息。
- trace_pipe 是一個管道文件，主要為了方便應用程序讀取 trace 內容。算是擴展接口吧。
我們使用 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可以看到，里面有非常多的文件和目錄，具體的含義，大家可以去詳細的看官方文檔的解釋，后面只會重點介紹一些文件。
2.2功能
我們可以通過 available_tracers 這個文件知道當前 ftrace 支持哪些插件。
cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop通常用的最多的就是function和function_graph，當然，如果我們不想 trace 了，可以使用nop。我們首先打開function：
echo function > current_tracer
cat current_tracer
function上面我們將 function 寫入到了 current_tracer 來開啟 function 的 trace，我通常會在 cat 下 current_tracer 這個文件，主要是防止自己寫錯了。然后 ftrace 就開始工作了，會將相關的 trace 信息放到 trace 文件里面，我們直接讀取這個文件就能獲取相關的信息。
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我們可以設置只跟蹤特定的 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當然，如果我們不想 trace schedule 這個函數，也可以這樣做：
echo '!schedule' > set_ftrace_filter或者也可以這樣做：
echo schedule > set_ftrace_notraceFunction filter 的設置也支持 *match，match* ，*match* 這樣的正則表達式，譬如我們可以 echo '*lock*' < set_ftrace_notrace 來禁止跟蹤帶 lock 的函數，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函數圖
相比于 function，function_graph 能讓我們更加詳細的去知道內核函數的上下文，我們打開 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() {我們也可以只跟蹤某一個函數的堆棧。
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上面列出來的都是分組的，我們可以繼續深入下去，譬如下面是查看sched相關的事件：
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當然也可以 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 的數據：
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當然，在report的時候也可以加入自己的 filter 來過濾數據，譬如下面，我們就過濾出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插樁技術
Ftrace 主要采用了靜態插樁和動態插樁兩種方式來實現其強大的跟蹤功能。
靜態插樁，簡單來說，就是在編譯內核時，借助編譯器的特定選項，在目標代碼中插入額外的代碼片段。具體而言，當內核配置打開CONFIG_FUNCTION_TRACER功能后，會添加一個-pg編譯選項 ，這就如同在每個函數入口處埋下了一個 “小標記”—— 插入bl mcount跳轉指令。
如此一來，當每個函數運行時，都會先進入mcount函數。這種方式的優點是可靠性高，只要內核編譯時配置好，所有相關函數都會被插樁，能全面地記錄函數調用信息。然而，它的缺點也很明顯，由于對內核中所有函數都進行插樁，會帶來較大的性能開銷，在一些對性能要求極高的場景下，可能會導致系統運行效率大幅下降，甚至影響系統的正常運行。
為了克服靜態插樁的性能問題，動態插樁應運而生。這里的 “動態”，體現在動態修改函數指令。在編譯時，會記錄所有支持追蹤的函數，這些函數原本被添加了跳轉指令。但在內核啟動后，為了減少性能損耗，內核會將所有跳轉指令替換為nop指令（nop指令表示空操作，不執行任何實際運算，對系統性能幾乎沒有影響），此時系統處于非調試狀態，性能損失幾乎為零。
當需要進行跟蹤時，根據function tracer的設置，Ftrace 會動態地將需要調試的函數的nop指令替換為跳轉指令，從而實現對這些特定函數的追蹤。動態插樁就像是一個智能的 “追蹤開關”，只有在需要時才開啟對特定函數的追蹤，大大減少了不必要的性能開銷，使得 Ftrace 在生產環境中的使用更加靈活和高效。
3.2追蹤器類型
Ftrace 擁有豐富多樣的追蹤器，每個追蹤器都有其獨特的功能和適用場景。
Function tracer 是最基礎的追蹤器之一，主要用于跟蹤內核函數的執行情況。它可以清晰地記錄下每個內核函數的調用時間、調用順序以及返回值等信息。在調試內核代碼時，如果懷疑某個函數的執行邏輯存在問題，就可以使用 Function tracer，通過分析它記錄的函數執行信息，快速定位到問題所在。比如，在開發一個新的內核模塊時，發現某個功能無法正常實現，利用 Function tracer 跟蹤相關函數的調用過程，可能會發現某個函數沒有按照預期被調用，或者返回值不符合預期，從而找到問題的根源。
Function graph tracer 則以更加直觀的方式展示函數調用關系。它不僅能記錄函數的調用情況，還能以類似 C 語言函數調用關系圖的形式，展示出函數的調用層次關系以及返回情況 。這對于理解復雜的內核代碼邏輯非常有幫助。在分析系統性能瓶頸時，如果發現某個功能的執行效率較低，使用 Function graph tracer 可以清晰地看到該功能涉及的函數調用鏈，找出哪些函數的執行時間較長，哪些函數的調用次數過于頻繁，從而有針對性地進行優化。例如，在一個文件系統的性能優化中，通過 Function graph tracer 發現文件讀寫函數在調用過程中，存在一些不必要的函數嵌套調用，通過優化這些調用關系，大大提高了文件系統的讀寫性能。
除了上述兩種追蹤器，還有其他一些追蹤器也各有其用。Sched_switch 追蹤器主要用于跟蹤系統中進程調度情況，記錄進程的切換時間、切換原因等信息，對于分析系統的調度性能和進程間的資源競爭問題非常有用；Irqsoff 追蹤器專注于跟蹤禁止中斷的函數及相關信息，能夠記錄中斷被禁止的時長，幫助開發者定位那些可能導致系統響應延遲的中斷操作；Preemptoff 追蹤器則用于跟蹤禁止內核搶占的函數及相關信息，對于優化系統的實時性和響應速度具有重要意義。
3.3數據記錄與存儲
當 Ftrace 通過插樁技術收集到各種跟蹤信息后，這些信息需要被有效地記錄和存儲起來，以便用戶后續查看和分析。Ftrace 采用了 Ring buffer 緩沖區來存儲這些跟蹤數據。
Ring buffer，也稱為環形緩沖區，是一種特殊的數據結構，它就像一個首尾相連的環形數組。在 Ftrace 中，Ring buffer 的工作原理如下：當有新的跟蹤信息產生時，Ftrace 會將其依次寫入 Ring buffer 中。當 Ring buffer 被寫滿后，新的數據會覆蓋最早寫入的數據，就像一個循環的隊列一樣。這種設計方式可以確保 Ring buffer 能夠持續地記錄最新的跟蹤信息，同時又不會因為數據過多而占用大量的內存空間。在讀取數據時，用戶可以從 Ring buffer 的頭部開始讀取，讀取完的數據不會被立即刪除，而是等待被新的數據覆蓋。這樣，用戶可以根據自己的需求，多次讀取 Ring buffer 中的數據，進行不同角度的分析。
為了方便用戶操作和管理 Ring buffer 中的數據，Ftrace 通過debugfs文件系統向用戶空間提供了一系列的接口文件。用戶可以通過這些文件，輕松地開啟或停止跟蹤、選擇使用的追蹤器、設置跟蹤的過濾條件，以及讀取 Ring buffer 中存儲的跟蹤信息。在/sys/kernel/debug/tracing目錄下，有許多與 Ftrace 相關的文件，其中trace文件用于以人類可讀的格式展示當前追蹤的內容，用戶可以通過cat trace命令查看這些內容；tracing_on文件則用于控制追蹤的開啟和停止，向該文件寫入1表示啟用追蹤，寫入0表示停止追蹤 。通過這些簡單的文件操作，用戶就可以靈活地使用 Ftrace 進行各種內核跟蹤和分析工作。
四、ftrace的實現
研究 tracer 的實現是非常有樂趣的。理解 ftrace 的實現能夠啟發我們在自己的系統中設計更好的 trace 功能。
4.1ftrace 的整體構架
圖片
Ftrace 有兩大組成部分，一是 framework，另外就是一系列的 tracer 。每個 tracer 完成不同的功能，它們統一由 framework 管理。ftrace 的 trace 信息保存在 ring buffer 中，由 framework 負責管理。Framework 利用 debugfs 系統在 /debugfs 下建立 tracing 目錄，并提供了一系列的控制文件。
一句話總結：各類tracer往ftrace主框架注冊，不同的trace則在不同的probe點把信息通過probe函數給送到ring buffer中，再由暴露在用戶態debufs實現相關控制。對不同tracer來說：
- 1）需要實現probe點（需要跟蹤的代碼偵測點），有的probe點需要靜態代碼實現，有的probe點借助編譯器在運行時動態替換，event tracing屬于前者；
- 2）還要實現具體的probe函數，把需要記錄的信息送到ring buffer中；
- 3）增加debugfs 相關的文件，實現信息的解析和控制。
而ring buffer 和debugfs的通用部分的管理由框架負責。
4.2Function tracer 的實現
Ftrace 采用 GCC 的 profile 特性在所有內核函數的開始部分加入一段 stub 代碼，ftrace 重載這段代碼來實現 trace 功能。gcc 的 -pg 選項將在每個函數入口處加入對 mcount 的調用代碼。比如下面的 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 在函數 foo 的入口處加入了對 mcount 的調用：call _mcount 。原本 mcount 由 libc 實現，但您知道內核不會連接 libc 庫，因此 ftrace 編寫了自己的 mcount stub 函數，并借此實現 trace 功能。
在每個內核函數入口加入 trace 代碼，必然會影響內核的性能，為了減小對內核性能的影響，ftrace 支持動態 trace 功能。
當 CONFIG_DYNAMIC_FTRACE 被選中后，內核編譯時會調用一個 perl 腳本：recordmcount.pl 將每個函數的地址寫入一個特殊的段：__mcount_loc
在內核初始化的初期，ftrace 查詢 __mcount_loc 段，得到每個函數的入口地址，并將 mcount 替換為 nop 指令。這樣在默認情況下，ftrace 不會對內核性能產生影響。
當用戶打開 ftrace 功能時，ftrace 將這些 nop 指令動態替換為 ftrace_caller，該函數將調用用戶注冊的 trace 函數。其具體的實現在相應 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() 。這樣每個內核函數都將調用 function_trace_call() 。
在 function_trace_call() 函數內，ftrace 記錄函數調用堆棧信息，并將結果寫入 ring buffer，稍后，用戶可以通過 debugfs 的 trace 文件讀取該 ring buffer 中的內容。
4.3 Irqsoff tracer 的實現
Irqsoff tracer 的實現依賴于 IRQ-Flags 。IRQ-Flags 是 Ingo Molnar 維護的一個內核特性。使得用戶能夠在中斷關閉和打開時得到通知，ftrace 重載了其通知函數，從而能夠記錄中斷禁止時間。即，中斷被關閉時，記錄下當時的時間戳。此后，中斷被打開時，再計算時間差，由此便可得到中斷禁止時間。
IRQ-Flags 封裝開關中斷的宏定義：
清單 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（）函數來獲得時間戳。
4.4hw-branch 的實現
Hw-branch 只在 IA 處理器上實現，依賴于 x86 的 BTS 功能。BTS 將 CPU 實際執行到的分支指令的相關信息保存下來，即每個分支指令的源地址和目標地址。
軟件可以指定一塊 buffer，處理器將每個分支指令的執行情況寫入這塊 buffer，之后，軟件便可以分析這塊 buffer 中的功能。
Linux 內核的 DS 模塊封裝了 x86 的 BTS 功能。Debug Support 模塊封裝了和底層硬件的接口，主要支持兩種功能：Branch trace store(BTS) 和 precise-event based sampling (PEBS) 。ftrace 主要使用了 BTS 功能。
4.5branch tracer 的實現
內核代碼中常使用 likely 和 unlikely 提高編譯器生成的代碼質量。Gcc 可以通過合理安排匯編代碼最大限度的利用處理器的流水線。合理的預測是 likely 能夠提高性能的關鍵，ftrace 為此定義了 branch tracer，跟蹤程序中 likely 預測的正確率。
為了實現 branch tracer，重新定義了 likely 和 unlikely 。具體的代碼在 compiler.h 中。
清單 6. likely/unlikely 的 trace 實現
# 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 的實現如下：
清單 7. _branch_check_ 的實現
#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 判斷的正確性，并將結果保存在 ring buffer 中，之后用戶可以通過 ftrace 的 debugfs 接口讀取分支預測的相關信息。從而調整程序代碼，優化性能。
五、Ftrace 的實戰應用
5.1性能優化
在性能優化領域，Ftrace 的作用不可小覷，尤其是在優化文件系統性能方面。假設我們在一個數據存儲服務器上發現文件讀寫操作的速度明顯變慢，嚴重影響了業務的正常運行。這時，我們可以利用 Ftrace 的 Function graph tracer 來深入分析文件系統相關函數的執行情況。
通過設置跟蹤器為 Function graph tracer，并將需要跟蹤的文件讀寫函數（如vfs_read、vfs_write等）添加到set_graph_function文件中，然后啟動跟蹤。在服務器進行文件讀寫操作的過程中，Ftrace 會記錄下這些函數的調用關系和執行時間。從跟蹤結果中，我們可能會發現vfs_read函數在調用ext4_readpage函數時花費了大量時間，進一步分析發現是因為文件系統的塊分配策略不合理，導致頻繁的磁盤 I/O 操作。基于這些發現，我們可以針對性地優化塊分配算法，減少不必要的磁盤 I/O，從而顯著提升文件系統的讀寫性能。
5.2故障排查
當系統出現響應延遲、進程卡頓等問題時，Ftrace 能夠成為我們定位問題的關鍵工具。例如，在一個運行著多個服務的服務器上，用戶反饋系統響應變得遲緩。此時，我們可以使用 Ftrace 的 Irqsoff Tracer 來跟蹤中斷被禁止的情況。因為長時間禁止中斷可能會導致系統無法及時響應外部事件，從而出現延遲現象。
啟用 Irqsoff Tracer 后，Ftrace 會記錄下所有禁止中斷的函數以及中斷被禁止的時長。通過分析這些記錄，我們可能會發現某個設備驅動程序中的中斷處理函數存在問題，它在處理中斷時長時間占用 CPU 資源，導致其他中斷無法及時得到處理，進而影響了系統的整體響應速度。找到問題后，我們可以對該驅動程序進行優化，例如調整中斷處理邏輯，將一些耗時操作放到線程中執行，以減少對中斷的影響，從而解決系統響應延遲的問題。
5.3內核開發與調試
在開發新的內核模塊時，開發者需要確保模塊中的函數調用正確無誤。例如，開發一個新的網絡協議模塊，使用 Ftrace 的 Function tracer，開發者可以清晰地看到該模塊中各個函數的調用順序和參數傳遞情況。如果發現某個函數沒有按照預期被調用，或者參數傳遞出現錯誤，就可以及時調整代碼，確保函數調用的正確性。
Ftrace 還可以用于跟蹤系統調用，幫助開發者了解應用程序與內核之間的交互過程。當應用程序調用系統調用時，Ftrace 可以記錄下系統調用的入口函數、參數以及返回值等信息。在調試一個新的文件操作函數時，通過跟蹤系統調用，開發者可以發現函數在處理文件權限驗證時出現錯誤，導致文件操作失敗，進而對權限驗證邏輯進行修正。
在調試內核模塊時，Ftrace 同樣發揮著重要作用。當內核模塊出現異常時，Ftrace 記錄的函數調用棧信息可以幫助開發者快速定位到問題所在。例如，一個內核模塊在加載時崩潰，通過查看 Ftrace 的跟蹤記錄，開發者可以找到導致崩潰的函數以及該函數的調用路徑，從而深入分析問題的原因，進行針對性的調試和修復。
六、Ftrace 的使用方法與技巧
6.1環境配置
在使用 Ftrace 之前，首先需要確保內核啟用了相關的配置選項。這一步至關重要，因為只有正確配置內核，Ftrace 才能發揮其強大的功能。在編譯內核時，可以通過make menuconfig命令進入內核配置界面。在該界面中，找到 “Kernel hacking” 選項，進入后再找到 “Tracers” 選項 。
在這里，需要確保 “Tracing support” 以及其他與 Ftrace 相關的選項（如 “Kernel Function Tracer”“Kernel Function Graph Tracer” 等）被勾選。這些選項分別對應著 Ftrace 的不同功能，勾選后才能啟用相應的跟蹤功能。
除了內核配置，還需要掛載debugfs文件系統。debugfs是一種特殊的文件系統，Ftrace 通過它向用戶空間提供訪問接口。掛載debugfs文件系統的方法有兩種。一種是將其添加到/etc/fstab文件中，實現自動掛載。具體操作是在/etc/fstab文件中添加一行 “debugfs /sys/kernel/debug debugfs defaults 0 0”，這樣在系統啟動時，debugfs文件系統就會自動掛載到/sys/kernel/debug目錄下。
另一種方法是手動掛載，使用命令 “mount -t debugfs none /sys/kernel/debug” ，該命令會將debugfs文件系統臨時掛載到/sys/kernel/debug目錄，這種方式適用于臨時使用 Ftrace 進行調試的場景。
6.2常用命令與參數
在/sys/kernel/debug/tracing目錄下，有許多用于控制和使用 Ftrace 的文件，這些文件對應著各種常用命令和參數。
echo 1 > tracing_on用于啟用追蹤，當需要開始記錄內核函數調用和系統事件時，執行這個命令，Ftrace 就會開始工作，將跟蹤信息寫入 Ring buffer 中；而echo 0 > tracing_on則用于停止追蹤，當不需要繼續跟蹤時，執行該命令可以停止 Ftrace 的記錄操作，避免不必要的性能開銷和數據占用。
echo function > current_tracer用于設置當前使用的追蹤器為 Function tracer，通過修改current_tracer文件的內容，可以切換不同的追蹤器，以滿足不同的跟蹤需求。例如，若要使用 Function graph tracer，就可以執行echo function_graph > current_tracer 。
echo vfs_read > set_ftrace_filter用于設置過濾條件，只跟蹤特定的函數。在這個例子中，只有vfs_read函數的調用信息會被記錄，其他函數的信息將被忽略。這在需要專注分析某個特定函數的行為時非常有用，可以減少大量無關信息的干擾，使分析更加高效和準確。
6.3使用技巧與注意事項
在使用 Ftrace 時，合理設置過濾條件可以大大提高分析效率。除了可以通過set_ftrace_filter指定要跟蹤的函數外，還可以使用正則表達式來匹配多個函數。echo '*lock*' > set_ftrace_filter表示跟蹤所有包含 “lock” 字樣的函數，這樣可以一次性跟蹤多個相關函數，方便對特定功能模塊的分析。
控制追蹤范圍也是一個重要技巧。可以通過set_ftrace_pid文件指定要跟蹤的進程 ID，從而只跟蹤特定進程的函數調用。echo 1234 > set_ftrace_pid表示只跟蹤進程 ID 為 1234 的進程，這樣可以避免其他進程的干擾，更精準地分析目標進程的行為。
處理大量追蹤數據時，需要注意數據的存儲和分析。由于 Ftrace 生成的跟蹤數據可能會占用大量磁盤空間，因此可以定期清理trace文件，或者將數據導出到其他存儲設備進行長期保存。在分析數據時，可以結合其他工具，如trace-cmd或bpftrace ，這些工具能夠對 Ftrace 生成的數據進行更深入的分析和可視化處理，幫助用戶更直觀地理解系統行為和性能瓶頸。
同時，還需注意 Ftrace 對系統性能的影響。由于 Ftrace 會在內核中插入額外的代碼來實現跟蹤功能，因此在開啟 Ftrace 時，可能會對系統性能產生一定的影響，特別是在跟蹤大量函數時。所以，在生產環境中使用 Ftrace 時，應謹慎開啟，并盡量縮短跟蹤時間，以減少對系統正常運行的影響。
七、實戰案列：隱藏的電燈開關
7.1 iosnoop
首先，Gregg 使用 iosnoop 工具進行檢查，iosnoop 用來跟蹤 I/O 的詳細信息，當然也包括 latency，結果如下：
# ./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 相關的 event，主要是：
- block:block_rq_issue - I/O 發起的時候的事件
- block:block_rq_complete - I/O 完成事件
- block:block_rq_insert - I/O 加入隊列的時間
如果使用了 -Q 參數，我們對于 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]我們根據1367650688 + 8能找到對應的 I/O block sector，然后根據 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 的實現比較簡單，譬如上面的 block:block_rq_insert，它直接會找events/block/block_rq_insert 是否存在，如果存在，就是找到了對應的 event。然后給這個 event 的 enable 文件寫入 1，如果我們要開啟堆棧，就往 options/stacktrace 里面也寫入 1。
從上面的堆棧可以看到，有 readahead 以及 page fault 了。在 Netflix 新升級的 Ubuntu 系統里面，默認的 direct map page size 是 2 MB，而之前的 系統是 4 KB，另外就是默認的 readahead 是 2048 KB，老的系統是 128 KB。看起來慢慢找到問題了。
7.3函數計數
為了更好的看函數調用的次數，Gregg 使用了 funccount 函數，譬如檢查 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，當打開之后，就會在 trace_stat 目錄下面對相關的函數進行統計，可以看到 function0，function1 這樣的文件，0 和 1 就是對應的 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就能知道各個函數的 count 了。
7.4功能變慢
為了更加確定系統的延遲是先前堆棧上面看到的函數引起的，Gregg 使用了 funcslower 來看執行慢的函數：
# ./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 這個函數很慢。對于 funcslower，我們主要是用 tracing_thresh 來進行控制，給這個文件寫入 threshold，如果函數的執行時間超過了 threshold，就會記錄。
7.5funccount（再次）
Gregg 根據堆棧的情況，再次對 readpage 和 readpages 進行統計：
# ./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 的寫放大引起，但他們已經調整了 readahead 的值，但并沒有起到作用。
7.6k探頭
因為 readahead 并沒有起到作用，所以 Gregg 準備更進一步，使用 dynamic tracing。他注意到上面堆棧的函數 __do_page_cache_readahead() 有一個 nr_to_read 的參數，這個參數表明的是每次 read 需要讀取的 pages 的個數，使用 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 來猜測的，也真能蒙對，太猛了。
關于 kprobe 的使用，具體可以參考 kprobetrace 文檔，kprobe 解析需要 trace 的 event 之后，會將其寫入到 kprobe_events 里面，然后在 events/kprobes/<EVENT>/ 進行對應的 enable 和 filter 操作。
7.7函數圖
為了更加確認，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();找到了一個比較明顯的函數 max_sane_readahead。對于 funcgraph，主要就是將需要關注的函數放到 set_graph_function 里面，然后在 current_tracer 里面開啟 function_graph。
7.8 k探針（再次）
然后，Gregg 繼續使用 kprobe 來 trace max_sane_readahead 函數，這次不用猜測寄存器了，直接用 $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
[...]發現仍然是 0x200 個 pages，然后他在發現，readahead 的屬性其實是在 file_ra_state_init 這個函數就設置好了，然后這個函數是在文件打開的時候調用的。但他在進行 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 系統在很多時候對我們是一個黑盒，但是有了 ftrace，如果在黑暗中開啟了一盞燈，能讓我們朝著光亮前行。我們內部也在基于 ftrace 做很多有意思的事情。
八、Ftrace 與其他追蹤工具的比較
在 Linux 性能分析與調試領域，除了 Ftrace，還有 SystemTap、LTTng 等知名的追蹤工具，它們各自有著獨特的特點，適用于不同的場景。
8.1功能對比
Ftrace 作為 Linux 內核自帶的跟蹤工具，主要聚焦于內核函數的調用、系統事件以及內核行為的跟蹤。它提供了豐富的追蹤器，如 Function Tracer 用于記錄內核函數調用情況，Function Graph Tracer 以圖形化展示函數調用關系 ，這些功能使得開發者能夠深入了解內核的運行機制，對于內核開發和性能優化非常有幫助。
SystemTap 則功能更為強大和靈活，它允許開發者使用腳本語言編寫復雜的跟蹤腳本。通過這些腳本，SystemTap 可以對內核行為進行深度分析，不僅能跟蹤內核函數，還能對系統調用、用戶空間程序與內核的交互等進行全面的跟蹤和分析。在分析復雜的系統性能問題時，SystemTap 可以通過編寫腳本來統計特定系統調用的執行次數、執行時間等，從而找出性能瓶頸所在。
LTTng 的功能側重于提供詳細的事件跟蹤，包括 CPU 調度、中斷處理、系統調用、信號傳遞等眾多方面。它支持同時跟蹤內核空間和用戶空間的活動，并且提供了高效的二進制接口和獨立的緩沖設計，適合進行深入的性能分析和故障診斷。在分析多線程應用程序的性能問題時，LTTng 可以精確地記錄每個線程的調度時間、執行時間以及線程之間的同步操作，幫助開發者找出線程相關的性能瓶頸。
8.2使用難度對比
Ftrace 的使用相對較為簡單。用戶主要通過debugfs文件系統與 Ftrace 進行交互，通過對/sys/kernel/debug/tracing目錄下的文件進行簡單的讀寫操作，就能實現跟蹤器的設置、跟蹤的啟動與停止以及跟蹤數據的查看等功能 。對于熟悉 Linux 文件操作的開發者來說，很容易上手。
SystemTap 的使用難度則較高。由于它需要開發者編寫腳本，而這些腳本涉及到特定的語法和函數調用，學習成本相對較大。編寫一個能夠準確獲取所需信息的 SystemTap 腳本，需要開發者對系統的運行機制有深入的了解，并且熟練掌握 SystemTap 的腳本語言。對于初學者來說，可能需要花費一定的時間和精力來學習和掌握。
LTTng 的使用難度介于 Ftrace 和 SystemTap 之間。它提供了一套命令行工具來控制跟蹤會話，如啟動 / 停止跟蹤、配置跟蹤點等。雖然命令行操作相對復雜一些，但相比于編寫腳本，還是較為容易掌握的。不過，在進行復雜的跟蹤配置和數據分析時，仍然需要開發者對 LTTng 的原理和使用方法有一定的了解。
8.3性能影響對比
Ftrace 采用靜態代碼插裝技術，在不進行跟蹤時，對系統性能的影響極小。因為在非跟蹤狀態下，它通過將跳轉指令替換為nop指令，幾乎不占用系統資源 。而在開啟跟蹤時，雖然會有一定的性能開銷，但由于其設計的輕量級特性，這種影響在大多數情況下是可以接受的，特別是在只跟蹤少量關鍵函數時，對系統性能的影響微乎其微。
SystemTap 在運行時，會將腳本語句翻譯成 C 語句并編譯成內核模塊，這個過程會消耗一定的 CPU 資源。而且，由于其功能強大，可能會對系統性能產生較大的影響，特別是在編寫的腳本較為復雜或者跟蹤的范圍較廣時。在生產環境中使用 SystemTap 時，需要謹慎評估其對系統性能的影響，避免因性能問題導致系統不穩定。
LTTng 在設計時就考慮到了對系統性能的最小影響，采用了鎖定最小化、CPU 本地緩存和批量處理等技術，確保在高負載下也能保持較低的開銷。它能夠在不顯著影響系統性能的前提下，收集大量的跟蹤數據，這使得它在生產環境中的應用較為廣泛。不過，在極端情況下，如跟蹤大量事件且系統資源緊張時，LTTng 仍可能對系統性能產生一定的影響。
