整理自《奔跑吧 Linux内核，张天飞著》

1. 简介

ftrace最早出现在Linux 2.6.27版本中，其设计目标简单，基于静态代码插桩技术，不需要用户通过额外的编程来定义trace行为。静态代码插桩技术比较可靠，不会因为用户的不当使用而导致内核崩溃。ftrace的名字由function trace而来，利用gcc编译器的profile特性在所有函数入口处添加了一段插桩（stub）代码，ftrace重载这段代码来实现trace功能。gcc编译器的"-pg"选项会在每个函数入口处加入mcount的调用代码，原本mcount有libc实现，因为内核不会链接libc库，因此ftrace编写了自己的mcount stub函数。

在使用ftrace前，需要确保内核配置编译了其配置选项。

CONFIG_FTRACE=y
CONFIG_HAVE_FUNCTION_TRACER=y
CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y
CONFIG_HAVE_DYNAMIC_FTRACE=y
CONFIG_FUNCTION_TRACER=y
CONFIG_IRQSOFF_TRACER=y
CONFIG_SCHED_TRACER=y
CONFIG_ENABLE_DEFAULT_TRACERS=y
CONFIG_FTRACE_SYSCALLS=y
CONFIG_PREEMPT_TRACER=y

ftrace相关配置选项比较多，针对不同的跟踪器有各自对应的配置选项。ftrace通过debugfs文件系统向用户空间提供访问接口，因此需要修改系统启动时挂载debugfs，可以修改系统的/etc/fstab文件或手动挂载。

mount -t debugfs debugfs /sys/kernel/debug

在/sys/kernel/debug/tracing目录下提供了各种跟踪器（tracer）和事件(event)，一些常用的选项如下：

avaliable_tracers: 列出当前系统支持的跟踪器。
avalibale_events: 列出当前系统支持的event事件
current_tracer: 设置和显示当前正在使用的跟踪器。使用echo命令可以把跟踪器的名字写入该文件，即可以切换不同的跟踪器。默认为nop，即不做任何跟踪操作。
trace: 读取跟踪信息。通过cat命令查看ftrace记录下来的跟踪信息。
tracing_on: 用于开始或暂停跟踪
trace_options: 设置ftrace的一些相关选项

ftrace当前包含多个跟踪器，很方便用户用来跟踪不同类型的信息，例如进程睡眠唤醒、抢占延迟的信息。查看avaliable_tracers可以知道当前系统支持哪些跟踪器，如果系统支持的跟踪器上没有用户想要的，那就必须在配置内核时自行打开，然后重新编译内核。常用的ftrace跟踪器如下：

nop：不跟踪任何信息。将nop写入current_tracer文件可以清空之前收集到的跟踪信息。
function：跟踪内核函数执行情况。
function_graph：可以显示类似C语言的函数调用关系图，比较直观
wakeup: 跟踪进程唤醒信息
irqsoff：跟踪关闭中断信息，并记录关闭的最长时长
preemptoff：跟踪关闭禁止抢占信息，并记录关闭的最长时长
preemptirqsoff：综合了irqoff和preemptoff两个功能
sched_switch：对内核中的进程调度活动进行跟踪

2. 跟踪器

2.1 irqs跟踪器

当中断被关闭（俗称关中断）了，CPU就不能响应其他的事件，如果这时有一个鼠标中断，要在下一次开中断时才能响应这个鼠标中断，这段延迟称为中断延迟。向current_tracer文件写入irqsoff字符串即可打开irqsoff来跟踪中断延迟。

# cd /sys/kernel/debug/tracing
# echo 0 > options/function-trace        // 关闭function-trace可以减少一些延迟
# echo irqsoff > current_tracer
# echo 1 > tracing_on
[...等一会...]
# echo 0 > tracing_on
# cat trace

下面是输出结果：
文件的开头显示了当前跟踪器为irqsoff,并且显示当前跟踪器的版本信息为v1.1.5,运行的内核版本为4.19.176。
显示当前最大的中断延迟是214微妙，跟踪条目和总共跟踪条目为4条，另外VP、KP、SP、HP值暂时没用，#P:4表示当前系统可用的CPU一共有4
个。
started at和ended at显示发生中断时的开始函数和结束函数。

# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 4.19.176
# --------------------------------------------------------------------
# latency: 214 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
#    -----------------
#    | task: AudioPlayback-2198 (uid:1000 nice:0 policy:0 rt_prio:0)
#    -----------------
#  => started at: schedule
#  => ended at:   finish_task_switch
#
#
#                  _------=> CPU#            
#                 / _-----=> irqs-off        
#                | / _----=> need-resched    
#                || / _---=> hardirq/softirq 
#                ||| / _--=> preempt-depth   
#                |||| /     delay            
#  cmd     pid   ||||| time  |   caller      
#     \   /      |||||  \    |   /         
RenderEn-2191    3d..1    1us!: __schedule <-schedule
AudioPla-2198    3d..2  210us : _raw_spin_unlock_irq <-finish_task_switch
AudioPla-2198    3d..2  217us+: tracer_hardirqs_on <-finish_task_switch
AudioPla-2198    3d..2  229us : <stack trace>
 => finish_task_switch
 => __schedule
 => schedule
 => do_nanosleep
 => hrtimer_nanosleep
 => __arm64_compat_sys_nanosleep
 => el0_svc_common.constprop.0
 => el0_svc_compat_handler
 => el0_svc_compat

irqs-off: "d"表示中断已经关闭
need_resched: "N"表示进程设置了TIF_NEED_RESCHED和PREEMPT_NEED_RESCHED标志位；"n"表示进程仅设置了TIF_NEED_RESCHED标志位；"p"表示进程仅设置了PREEMPT_NEED_RESCHED标志位
hardirq/softirq:"H"表示在一次软中断中发生了一个硬件中断；"h"表示硬件中断发生；"s"表示软中断；"."表示没有中断发生。
preempt-depth:表示抢占关闭的嵌套层级
time:表示时间戳。如果打开了latency-format选项，表示时间从开始跟踪算起，这是一个相对时间，方便开发者观察，否则使用系统绝对时间。
delay:用一些特殊符号来延迟的时间，方便开发者观察。"$"表示大于1秒，"#"表示大于1000微秒，"!"表示大于100微秒，"+"表示大于10微秒。

最后要说明的是，文件最开始显示中断延迟是210微秒。但是在<stack trace>里显示229微秒，这是因为在记录最大延迟信息时需要花费一些时间。

2.2 preemptoff跟踪器

todo

2.3 preemptirqsoff跟踪器

todo

2.4 function跟踪器

function跟踪器会记录当前系统运行过程中所有的函数。如果只想跟踪某个进程，可以使用set_ftrace_pid。

# cd /sys/kernel/debug/tracing
# cat set_ftrace_pid
no pid
# echo 5945 > set_ftrace_pid
# cat set_ftrace_pid
5945
# echo function > current_tracer
# echo 1 > tracing_on
[...等一会...]
# echo 0 > tracing_on
# cat trace

ftrace还支持一种更为直观的跟踪器叫function_graph，使用方法和function跟踪器类似。

# echo function_graph > current_tracer

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 2)   9.140 us    |    } /* preempt_count_sub */
 2) + 27.300 us   |  } /* _raw_spin_unlock_irq */
 2)               |  _raw_spin_lock_irq() {
 2)               |    preempt_count_add() {
 2)   5.200 us    |      preempt_count_add.part.2();
 2) + 15.100 us   |    }
 2) + 30.160 us   |  }
 2)   4.820 us    |  rcu_jiffies_till_stall_check();
 2)               |  _raw_spin_unlock_irq() {
 2)   9.240 us    |    preempt_count_sub();
 2) + 24.460 us   |  }
 2)               |  _raw_spin_lock() {
 2)               |    preempt_count_add() {
 2)   8.460 us    |      preempt_count_add.part.2();
 2) + 24.640 us   |    }
 2) + 41.080 us   |  }
......

Linux ftrace的使用（1）