ftrace是内核的一套框架，它将内核多种trace整合在一起，之前我们提到的tracepoint，trace event，kprobe等等都是ftrace base的。ftrace 提供了一个tracefs基本框架。本文介绍ftrace的基本使用 一、ftrace 框架 为了了解ftrace框架，我们需要把其他几个trace都介绍进来，主要如下所示：

如上图所示

• 对于kprobe，我们在函数的开头直接修改的执行指令，所以能够直接抓住函数的堆栈和参数以及地址
• 对于kretprobe，我们在函数的返回直接跳转的新的执行指令，所以能够直接抓住函数的返回值
• 对于tracepoint，我们需要在函数体内部直接定义一个trace函数，这样我们能够直接自定义代码的trace event
• 对于function和function graph，我们类似于kprobe的方式，借助gcc的fentry属性，进行指令替换fentry，所以我们可以获取函数的调用关系

如果关系社区文档的，可以查看如下：

https://lwn.net/Articles/370423/

这样我们就对整个ftrace框架有了一个比较清晰的了解了，接下来介绍ftrace的使用

二、function trace

对于function trace，我们需要关注如下几个文件，目录是在：/sys/kernel/debug/tracing

set_ftrace_filter
set_ftrace_notrace

这里以usbhid鼠标事件为例，开展一个示例。

我们知道，usb事件通过urb提交数据，对于usbhid而言，提交数据的函数是usb_submit_urb，我们此时跟踪usb_submit_urb函数，如下：

cd /sys/kernel/debug/tracing
echo 0 > tracing_on
echo usb_submit_urb > set_ftrace_filter
echo  function > current_tracer
echo 1 > tracing_on
cat trace_pipe

此时我们晃动鼠标，可以知道trace信息如下：

 <idle>-0 [000] .Ns. 802.924876: usb_submit_urb <-hid_irq_in
 <idle>-0 [000] .Ns. 802.928922: usb_submit_urb <-hid_irq_in
 <idle>-0 [000] .Ns. 802.932923: usb_submit_urb <-hid_irq_in
 <idle>-0 [000] .Ns. 802.936922: usb_submit_urb <-hid_irq_in
 <idle>-0 [000] .Ns. 802.940922: usb_submit_urb <-hid_irq_in
 <idle>-0 [000] .Ns. 802.944876: usb_submit_urb <-hid_irq_in

我们能够准确的抓到usb_submit_urb事件信息，其是hid_irq_in调用。但是缺点是我并不知道是如何传入的，所以我们还需要开一个特性，如下：

echo 1 > options/func_stack_trace

此时我们再晃动鼠标，可以看到信息如下：

 <idle>-0 [000] .Ns. 879.322927: usb_submit_urb <-hid_irq_in
 <idle>-0 [000] .Ns. 879.322929: <stack trace>
 => usb_submit_urb
 => hid_irq_in
 => __usb_hcd_giveback_urb
 => usb_giveback_urb_bh
 => tasklet_action_common.isra.0
 => tasklet_hi_action
 => __do_softirq
 => irq_exit
 => __handle_domain_irq
 => gic_handle_irq
 => el1_irq
 => cpuidle_enter_state
 => cpuidle_enter
 => call_cpuidle
 => do_idle
 => cpu_startup_entry
 => rest_init
 => arch_call_rest_init
 => start_kernel

这里我们就清楚的知道，系统idle进程在等待gic中断，也就是我鼠标晃动，然后在gic_handle_irq中根据注册的中断调用回调。我们关注hid_irq_in是谁注册的就知道整个代码调用过程了。

如果不用，则关闭即可。

echo 0 > tracing_on
echo nop > current_tracer

三、function graph trace

function graph trace改进了function trace，可以将整个函数调用堆栈打印出来，并且按照括号给折叠查看，对于排查代码框架问题上比trace更好用

对于function graph trace，主要关注如下文件：

set_graph_function 
set_graph_notrace

这里还是以usbhid为例，开展示例：

cd /sys/kernel/debug/tracing
echo 0 > tracing_on
echo function_graph > current_tracer
echo usb_submit_urb > set_graph_function
echo 0 > max_graph_depth

晃动鼠标

echo 1 > tracing_on
cp /sys/kernel/debug/tracing/trace ~/
echo 0 > tracing_on

我们可以拿到如下日志

# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
------------------------------------------
 0) ukui-po-2485 => <idle>-0
 ------------------------------------------
0) | usb_submit_urb() {
 0) | usb_hcd_submit_urb() {
 0) | usb_get_urb() {
 0) 0.875 us | usb_get_urb.part.0();
 0) 2.625 us | }
 0) 0.875 us | usb_hcd_map_urb_for_dma();
 0) | ehci_urb_enqueue() {
 0) | qh_urb_transaction() {
 0) | ehci_qtd_alloc() {
 0) | dma_pool_alloc() {
 0) | _raw_spin_lock_irqsave() {
 0) 0.583 us | do_raw_spin_lock();
 0) 1.750 us | }
 0) | _raw_spin_unlock_irqrestore() {
 0) 0.584 us | do_raw_spin_unlock();
 0) 1.750 us | }
 0) 5.541 us | }
 0) 6.709 us | }
 0) 0.583 us | qtd_fill.isra.0();
 0) 9.625 us | }
 0) | _raw_spin_lock_irqsave() {
 0) 0.583 us | do_raw_spin_lock();
 0) 1.750 us | }
 0) | usb_hcd_link_urb_to_ep() {
 0) | _raw_spin_lock() {
 0) 0.584 us | do_raw_spin_lock();
 0) 1.458 us | }
 0) | _raw_spin_unlock() {
 0) 0.583 us | do_raw_spin_unlock();
 0) 1.459 us | }
 0) 6.416 us | }
 0) 0.875 us | qh_append_tds();
 0) 1.750 us | qh_append_tds();
 0) | _raw_spin_unlock_irqrestore() {
 0) 0.583 us | do_raw_spin_unlock();
 0) 1.750 us | }
 0) + 26.542 us | }
 0) + 32.375 us | }
 0) + 37.916 us | }

我们可以看到usb_submit_urb的调用流程了，便于分析解决usb_submit_urb函数内部存在的问题。

这里，我们发现能够直接追到usb_submit_urb后面所有的调用和运行的时间了，但是这些括号匹配起来很麻烦，所以我们应该打开如下：

echo 1 > options/funcgraph-tail

此时日志不一样了，如下：

0) | usb_submit_urb() {
 0) | usb_hcd_submit_urb() {
 0) | usb_get_urb() {
 0) 0.583 us | usb_get_urb.part.0();
 0) 1.750 us | } /* usb_get_urb */
 0) 0.583 us | usb_hcd_map_urb_for_dma();
 0) | ehci_urb_enqueue() {
 0) | qh_urb_transaction() {
 0) | ehci_qtd_alloc() {
 0) | dma_pool_alloc() {
 0) | _raw_spin_lock_irqsave() {
 0) 0.583 us | do_raw_spin_lock();
 0) 1.458 us | } /* _raw_spin_lock_irqsave */
 0) | _raw_spin_unlock_irqrestore() {
 0) 0.583 us | do_raw_spin_unlock();
 0) 1.750 us | } /* _raw_spin_unlock_irqrestore */
 0) 4.666 us | } /* dma_pool_alloc */
 0) 5.834 us | } /* ehci_qtd_alloc */
 0) 0.583 us | qtd_fill.isra.0();
 0) 8.458 us | } /* qh_urb_transaction */
 0) | _raw_spin_lock_irqsave() {
 0) 0.583 us | do_raw_spin_lock();
 0) 1.750 us | } /* _raw_spin_lock_irqsave */
 0) | usb_hcd_link_urb_to_ep() {
 0) | _raw_spin_lock() {
 0) 0.583 us | do_raw_spin_lock();
 0) 1.750 us | } /* _raw_spin_lock */
 0) | _raw_spin_unlock() {
 0) 0.292 us | do_raw_spin_unlock();
 0) 2.625 us | } /* _raw_spin_unlock */
 0) 5.834 us | } /* usb_hcd_link_urb_to_ep */
 0) 0.583 us | qh_append_tds();
 0) 1.750 us | qh_append_tds();
 0) | _raw_spin_unlock_irqrestore() {
 0) 0.583 us | do_raw_spin_unlock();
 0) 1.458 us | } /* _raw_spin_unlock_irqrestore */
 0) + 23.625 us | } /* ehci_urb_enqueue */
 0) + 28.292 us | } /* usb_hcd_submit_urb */

可以发现括号后面带注释了

但是这还不满足，我想要折叠function graph的信息。

内核有一个vim配置脚本，如下：

scp Documentation/trace/function-graph-fold.vim root@172.25.xx.xx:~

我们用vim打开trace文件的时候执行这个脚本如下：

vim -S function-graph-fold.vim  trace

此时日志长这样了：

# tracer: function_graph
 #
 # CPU DURATION FUNCTION CALLS
 # | | | | | | |
 6) $ 115370075 us | } /* schedule */
+ 0) | usb_submit_urb() {-------------------------------------------------------------------------------------------------------------------------------------

我们在折叠的地方按下L即可展开。

四、总结

ftrace是一个黑盒测试调试的很好的工具，基本上所有调试过内核的人都知道使用，本文作为普及的目的说了一下ftrace的使用。