Linux: ftrace 使用手册

1. 前言

限于作者能力水平，本文可能存在谬误，因此而给读者带来的损失，作者不做任何承诺。

2. 背景

本文基于对 Linux 内核 ftrace 文档 翻译整理而成。

3. ftrace

3.1 简介

ftrace 是 Linux 内核内置的追踪机制，用来帮助系统设计人员了解内核内部当前发生的事情，它可以用于用户空间调试和分析内核延迟和性能问题。虽然 ftrace 通常被认为是 function tracer ，但它实际上已经发展为内核的追踪框架。后文中的所有 ftrace ，指代整个 ftrace 框架，而非 function tracer 。

3.2 挂载 ftrace 文件系统

ftrace 通过 debugfs 向用户空间导出接口：

# mount
tracefs on /sys/kernel/debug/tracing type tracefs (rw,relatime)

ftrace 目录树默认挂载在 /sys/kernel/debug/tracing 路径下。

3.3 ftrace 文件系统说明

3.3.1 current_tracer

内核集成了各种 tracer ，如用来追踪内核函数的 function tracer 等等。通过文件 available_tracers 可以查看当前编译到内核的 tracer 列表：

# cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop

current_tracer 表示当前启用的 tracer ，默认为 nop ，即不做任何追踪工作：

# cat current_tracer
nop

通过写 current_tracer 可以修改当前 tracer ，available_tracers 文件中列出了可以写入到 current_tracer 的 tracer 名。如想追踪系统内核函数调用，可以向 current_tracer 写入 function ：

# echo function > current_tracer
# cat current_tracer
function

3.3.2 available_tracers

available_tracers 文件中包含的是当前编译到内核的 tracer 列表，也即可以写到 current_tracer 的 tracer 名。

3.3.3 tracing_on

向 tracing_on 写入 1，启用追踪；向 tracing_on 写入 0，停止追踪。ftrace 使用 ring buffer 记录追踪数据。修改 tracing_on 不会影响 ring buffer 当前记录的内容。

# echo 1 > tracing_on 启用追踪过程
# echo 0 > tracing_on 关闭追踪过程

3.3.4 trace

trace 文件包含当前追踪的内容，以人类可读的格式展现。来看一个简单例子：

# echo function > current_tracer
# echo 1 > tracing_on
# cat trace
...
<idle>-0     [001] dNh.  8786.470388: __enqueue_entity <-enqueue_entity
          <idle>-0     [001] dNh.  8786.470388: hrtick_update <-enqueue_task_fair
          <idle>-0     [001] dNh.  8786.470388: ttwu_do_wakeup <-ttwu_do_activate
          <idle>-0     [001] dNh.  8786.470389: check_preempt_curr <-ttwu_do_wakeup
          <idle>-0     [001] dNh.  8786.470389: resched_curr <-check_preempt_curr
...
# echo 0 > tracing_on

我们看到，trace 文件包含了内核函数调用记录。

3.3.5 trace_pipe

trace_pipe 和 trace 一样，都是记录当前的追踪内容，但它和 trace 不一样的是：

o 对 `trace_pipe` 的读操作会阻塞，直到有新的追踪数据进来为止；
o 当前从`trace_pipe` 读取的内容会被消耗掉，再次读 `trace_pipe` 又会阻塞到新数据进来为止。

3.3.5 trace_options

trace_options 文件中包含用来控制 ftrace 写入到 trace 和 trace_pipe 中内容的选项列表。trace_options 中列举的每一个选项名，在 options 目录 下都有一个对应文件，对 options 目录 下的文件写 0 或 1 来关闭或启用对应的选项，以达到控制 ftrace 写入到 trace 和 trace_pipe 的内容。后续在对 set_ftrace_pid 文件的说明中，将对此选项做进一步说明。

3.3.6 options

trace_options 文件中包含的每个选项名，在 options 目录下都会有一个同名文件，可以通过对这些文件写 0 或 1 来关闭或启用对应的选项。

3.3.7 tracing_max_latency

有些 tracer 记录最大延迟。如禁用中断的最长时间(即最大中断延迟)。tracing_max_latency 记录当前的最大延迟时间，单位为 微妙(us) 。在追踪过程中，如果有延迟时间大于 tracing_max_latency 记录的时长，将更新 tracing_max_latency 文件。 trace 文件记录当前的延迟时间。

3.3.8 tracing_thresh

有些 延迟追踪类 tracer ，只有延迟时间大于某个阈值的时候，才记录追踪数据，此时tracing_thresh 记录这个阈值。tracing_thresh 需要 大于 0 才会激活这种机制，小于等于0的值没有意义。

3.3.9 buffer_size_kb

buffer_size_kb 记录 CPU buffer 的大小，单位为 KB 。per_cpu/cpuX/buffer_size_kb 记录 每个CPU buffer 大小，单位为 KB 。可通过写 buffer_size_kb 来改变 CPU buffer 的大小。当所有的 CPU buffer 有不同大小时，buffer_size_kb 将显示为 X 。对 buffer_size_kb 写入，将重置所有 CPU buffer 的大小(即重置 per_cpu/cpuX/buffer_size_kb)。

3.3.10 buffer_total_size_kb

buffer_total_size_kb 记录所有 CPU buffer 的总大小，即所有 CPU buffer 大小总和，如有 128 个 CPU buffer ，每个大小 7KB，则 buffer_total_size_kb 记录的总大小为 128 * 7KB = 896。buffer_total_size_kb 文件是只读的。

3.3.11 free_buffer

TODO:

3.3.12 tracing_cpumask

指定追踪的 CPU buffer 掩码，如追踪所有 128 个 CPU buffer，则：

# cat tracing_cpumask 
ffffffff,ffffffff,ffffffff,ffffffff

所有 128 个 CPU buffer 掩码位全为1。
注：这里的 128 个并非对应到 CPU 的个数，CPU buffer 个数 和 CPU 个数不是一一对应的关系。

3.3.13 set_ftrace_filter

ftrace 仅追踪文件 set_ftrace_filter 中列举的内核函数。可以写入 set_ftrace_filter 文件的内核函数名列举在 available_filter_functions 中。通常是写内核函数名到 set_ftrace_filter ，但也可以写内核函数在文件 available_filter_functions 中所在的行位置到 set_ftrace_filter ，行位置起始编号为 1 。

3.3.14 set_ftrace_notrace

set_ftrace_notrace 和 set_ftrace_filter 刚好相反，ftrace 禁用对其中列举函数的追踪。

3.3.15 set_ftrace_pid

ftrace 对 set_ftrace_pid 文件中包含的 PID 关联的进程进行追踪。如果开启了 options/function-fork 选项，fork 的子进程的 PID 也会自动加入该文件，同时该选项也会引起 ftrace 自动将已终止进程的 PID 从文件中移除。

3.3.16 set_ftrace_notrace_pid

set_ftrace_notrace_pid 和 set_ftrace_pid 相反，ftrace 将不对 set_ftrace_notrace_pid 文件中包含的 PID 关联的进程进行追踪。如果开启了 options/function-fork 选项，fork 的子进程的 PID 也会自动加入文件，同时该选项也会引起 ftrace 自动将已终止进程的 PID 从文件中移除。
如果 set_ftrace_pid 和 set_ftrace_notrace_pid 同时包含某个进程 PID ，set_ftrace_notrace_pid 的设置具有更高优先级。

3.3.17 set_event_pid

如果对 set_event_pid 文件进行了设置，ftrace 将仅追踪 set_event_pid 中 PID 指定进程的 event 。如果开启了 options/event-fork 选项，fork 的子进程的 PID 也会自动加入文件，同时该选项也会引起 ftrace 自动将已终止进程的 PID 从文件中移除。

3.3.18 set_event_notrace_pid

ftrace 不追踪 set_event_notrace_pid 中 PID 指定进程的 event 。如果开启了 options/event-fork 选项，fork 的子进程的 PID 也会自动加入文件，同时该选项也会引起 ftrace 自动将已终止进程的 PID 从文件中移除。

3.3.19 set_graph_function

function_graph tracer 将仅追踪文件 set_graph_function 中列举的函数。注意，set_ftrace_filter 和 set_ftrace_notrace 仍会影响 被追踪 或 不被追踪 的函数列表。

3.3.20 set_graph_notrace

set_graph_notrace 和 set_graph_function 相反，包含不被 function_graph tracer 追踪的函数列表。

3.3.21 available_filter_functions

可以被追踪的内核函数列表，即可以写到 set_ftrace_filter，set_ftrace_notrace，set_graph_function，set_graph_notrace 文件的函数列表。

3.3.22 dyn_ftrace_total_info

用于调试，记录系统中可被追踪的函数总数。

3.3.23 enabled_functions

TODO:

3.3.24 function_profile_enabled

如果设置了 function_profile_enabled（对文件写1），ftrace 将启用对所有 available_filter_functions 列举的内核函数的 function tracer 追踪，如果启用了 function_graph tracer ，也将启用对available_filter_functions 列举的内核函数的 function_graph 追踪。同时也会保留调用的函数数量的直方图，还将跟踪在这些函数中花费的时间。直方图内容可以显示在文件中：trace_stat/function[cpu] 。如：

# echo 1 > function_profile_enabled
# cat trace_stat/function0
  Function                               Hit    Time            Avg             s^2
  --------                               ---    ----            ---             ---
  schedule                              4368    334221648 us     76515.94 us     735411.5 us 
  do_syscall_64                        15508    222285003 us     14333.56 us     19887.52 us 
  schedule_hrtimeout_range              1879    189004501 us     100587.8 us     220126.6 us 
  schedule_hrtimeout_range_clock        1879    189003100 us     100587.0 us     222184.7 us
...

注意，如果设置了 function_profile_enabled (对文件写1)，tracing_on 即使为 0 ，ftrace 也会启动追踪过程，更新 ring buffer 。

3.3.25 trace_stat

包含各种 ftrace 统计数据的目录，为每个 CPU buffer 建立1个目录：trace_stat/function[cpu] 。

# ls -l trace_stat
total 0
-rw-r--r-- 1 root root 0 4月  12 10:06 function0
-rw-r--r-- 1 root root 0 4月  12 10:06 function1
...

3.3.26 kprobe_events

类似于事件追踪，kprobe 追踪事件 不需要通过 current_tracer 来激活；相反，通过下列两个文件节点设置 kprobe 追踪事件：

/sys/kernel/tracing/kprobe_events : 设置 kprobe 探测点
/sys/kernel/tracing/events/kprobes/<EVENT>/enable : 激活 kprobe 探测点

还可以通过 /sys/kernel/tracing/dynamic_events 设置 kprobe 追踪事件，该节点不仅限于设置 kprobe 追踪事件，还可以设置其它动态动态追踪事件。给一个追踪 ALSA 内核代码的示例：

# echo 'p snd_pcm_hw_rule_ratdens' >> kprobe_events 
# echo 'r snd_pcm_hw_rule_ratdens $retval' >> kprobe_events
# echo > trace
# echo 1 > events/kprobes/enable
# echo 1 > tracing_on

/* 执行一段播放 wav 的代码后，观察： */

# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 2/2   #P:12
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
    alsa_playwav-4637  [010] .... 27018.498650: p_snd_pcm_hw_rule_ratdens_0: (snd_pcm_hw_rule_ratdens+0x0/0x340 [snd_pcm])
    alsa_playwav-4637  [010] d... 27018.498653: r_snd_pcm_hw_rule_ratdens_0: (snd_pcm_hw_refine+0x331/0x3a0 [snd_pcm] <- snd_pcm_hw_rule_ratdens) arg1=0xffffffea

发现函数 snd_pcm_hw_rule_ratdens() 返回 -EINVAL (即 0xffffffea) 给调用函数 snd_pcm_hw_refine() ，表示出错了。
更多细节参见 Kprobe-based Event Tracing 。

3.3.27 kprobe_profile

参见 Kprobe-based Event Tracing 。

3.3.28 max_graph_depth

function_graph 类别追踪中，显示的函数调用栈的最大深度。

3.3.29 printk_formats

如果某个追踪事件上报到 ring buffer 的数据引用了字符串，那么 ring buffer 只会记录该字符串的地址，这样我们没法知道该地址指向的字符串内容。printk_formats 文件建立了 字符串地址 到 字符串内容 的映射表，这样就可以通过地址来查找到字符串的内容。

# cat printk_formats
0xffffffff950be839 : "CPU_ON"
0xffffffff950be839 : "CPU_ON"
0xffffffff950be840 : "CPU_OFF"
0xffffffff950be840 : "CPU_OFF"
0xffffffff950c6525 : "thaw_processes"
0xffffffff950c6525 : "thaw_processes"
0xffffffff950c66e4 : "suspend_enter"
...

3.3.29 saved_cmdlines

saved_cmdlines 文件记录了 进程 PID 到 进程名 的映射表。除非特别去记录 进程名，否则 trace event 通常只会记录 进程 PID 。ftrace 维护一个 进程 PID 到 进程名 的映射到 saved_cmdlines 缓存文件，当输出追踪信息时，通过文件 saved_cmdlines 将 进程 PID 映射为 进程名 显示出来，如果当前 saved_cmdlines 没有某个 进程 PID 的映射项，输出显示 进程名 为 <…> ，如：

<...>-4587  [001] .... 19257.259293: vfs_open <-path_openat

如果选项文件 options/record-cmd 设为 0 ，表示在追踪过程中，不缓存 进程 PID 到 进程名 的映射数据到文件 saved_cmdlines ，默认 options/record-cmd 的值为 1。

3.3.30 saved_cmdlines_size

默认 saved_cmdlines 只缓存 128 个进程名映射项，如果要增加缓存数目，通过修改 saved_cmdlines_size 来完成。

3.3.31 saved_tgids

saved_tgids 文件记录 进程 PID 到 进程所在进程组 ID 的映射表。如果选项文件 options/record-tgid 为 1 ，每当发生进程切换时，进程 PID 到 进程所在进程组 ID 的映射将记录到文件 saved_tgids 。默认 options/record-tgid 为 0 。

3.3.32 snapshot

见后面章节。

3.3.33 stack_max_size

见后面章节。

3.3.34 stack_trace

见后面章节。

3.3.35 stack_trace_filter

见后面章节。

3.3.36 trace_clock

ftrace 记录追踪事件到 ring buffer 时，总会记录它的时间戳信息。时间戳来源于指定的时钟，默认情况下，ftrace 使用 CPU 本地时钟(local)，这个时间变换很快，并且是特定于 CPU 的。

# cat trace_clock
[local] global counter uptime perf mono mono_raw boot x86-tsc

有时候可能有需求，要形成全局的参照，这时候使用 CPU 本地时钟 local ，可能就不合适了。此时可以通过命令修改为全局时钟(global)，将所有CPU追踪记录的时间戳，统一到同一时间轴上来，这样就可以看出不同CPU事件数据之间发生的先后关系了。

# echo global > trace_clock
# cat trace_clock
local [global] counter uptime perf mono mono_raw boot x86-tsc

修改 trace_clock 文件，将会清空 ring buffer 和 snapshot 缓冲内容。

3.3.37 trace_marker

写到文件 trace_marker 的内容，将会写入到 ftrace 的追踪缓冲。通常的应用是：启用追踪，写一个开始标记；结束追踪前，再写一个结束标记。这样很方便在两个标记之间查找关心的内容。

# echo 1 > tracing_on 
# echo "START_MAKER" > trace_marker
# echo "END_MARKER" > trace_marker
# echo 0 > tracing_on 
# cat trace | grep "START_MAKER"
            bash-2819  [000] .... 11433.485740: tracing_mark_write: START_MAKER
# cat trace | grep "END_MARKER"
            bash-2819  [000] .... 11453.265817: tracing_mark_write: END_MARKER

3.3.38 trace_marker_raw

类似于 trace_marker ，但是以二进制方式写入到 trace 缓冲。对 trace 原始数据感兴趣的工具可以从 trace_pipe_raw 中提取标记。

3.3.39 uprobe_events

参见 https://www.kernel.org/doc/html/latest/trace/uprobetracer.html 。

3.3.40 uprobe_profile

参看内核文档 Documentation/trace/uprobetracer.txt 。

3.3.41 instances

见后面章节。

3.3.42 events

trace event 目录，包含静态编译到内核的 event tracepoint 。

3.3.43 set_event

写文件 set_event 将启用指定的 trace event 。可写入的 trace event 名，查看文件 available_events 。更多细节参考 Event Tracing 和 Event Histograms 。

3.3.44 available_events

系统支持的 trace event 列表，可通过写 trace event 名到文件 set_event 启用。

3.3.45 timestamp_mode

TODO:

3.3.46 hwlat_detector

包含延迟检查硬件信息文件。

3.3.47 per_cpu

包含追踪系统 每 CPU buffer 包含的信息。

3.4 ftrace 各类 tracer

3.4.1 简介

3.4.1.1 function

跟踪所有内核函数的 tracer。

3.4.1.2 function_graph

类似于 function tracer ，和 function tracer 不同的是：function tracer 只跟踪函数的进入，而 function_graph tracer 既跟踪函数的进入，又跟踪函数的退出，因此可以绘制类似于C代码的函数调用图。

3.4.1.3 blk

block tracer，供 blktrace 存储 IO 工具使用。

3.4.1.4 hwlat

硬件延迟 tracer ，用来检测是否有硬件产生的延迟。

3.4.1.5 irqsoff

追踪中断延迟，记录最大中断延迟到 tracing_max_latency 。

3.4.1.6 preemptoff

追踪禁用抢占的最长时间，记录最长禁用时间到 tracing_max_latency 。

3.4.1.7 preemptirqsoff

追踪 中断延迟 和 禁用抢占 两者中的最长时间，记录到 tracing_max_latency 。

3.4.1.8 wakeup

追踪记录最高优先级任务，从其被唤醒开始到被调度的最大延迟，记录到 tracing_max_latency 。

3.4.1.9 wakeup_rt

类似于 wakeup tracer ，但仅追踪记录 RT 调度类 任务。

3.4.1.10 wakeup_dl

类似于 wakeup tracer ，但仅追踪记录 DL(DeadLine) 调度类 任务。

3.4.1.11 mmiotrace

TODO:

3.4.1.12 branch

用来追踪系统中 likely() 或 unlikely() 调用，用于观察 likely() 或 unlikely() 分支预测是否正确。

3.4.1.13 nop

关闭 tracer 。

3.4.2 tracer 使用示例

3.4.2.1 function

# echo function > current_tracer
# echo > trace 清空跟踪缓冲
# echo 1 > tracing_on 开启追踪
# cat trace 查看追踪信息 
# tracer: function
#
# entries-in-buffer/entries-written: 205087/1383792   #P:4
#
#                                      _-----=> irqs-off
#                                     / _----=> need-resched
#                                    | / _---=> hardirq/softirq
#                                    || / _--=> preempt-depth
#                                    ||| /     delay
#           TASK-PID    TGID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |        |      |   ||||       |         |
        vmtoolsd-1512  (-----) [000] .... 29892.117923: __inode_wait_for_writeback <-inode_wait_for_writeback
        vmtoolsd-1512  (-----) [000] .... 29892.117923: bit_waitqueue <-__inode_wait_for_writeback
...

3.4.2.2 wakeup

# echo wakeup > current_tracer
# echo > trace 清空跟踪缓冲
# echo 1 > tracing_on 开启追踪
# cat trace 查看追踪信息
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 4.15.0-142-generic
# --------------------------------------------------------------------
# latency: 112 us, #146/146, CPU#2 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
#    -----------------
#    | task: kworker/2:1H-313 (uid:0 nice:-20 policy:0 rt_prio:0)
#    -----------------
#
#                  _------=> CPU#            
#                 / _-----=> irqs-off        
#                | / _----=> need-resched    
#                || / _---=> hardirq/softirq 
#                ||| / _--=> preempt-depth   
#                |||| /     delay            
#  cmd     pid   ||||| time  |   caller      
#     \   /      |||||  \    |   /         
  <idle>-0       2dNs.    1us :      0:120:R   + [002]   313:100:R kworker/2:1H
  <idle>-0       2dNs.    4us : ttwu_do_activate <-try_to_wake_up
  <idle>-0       2dNs.    4us : ttwu_stat <-try_to_wake_up
  <idle>-0       2dNs.    5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
  <idle>-0       2.Ns.    5us : _raw_spin_lock_irq <-run_timer_softirq
  <idle>-0       2.Ns.    6us : _raw_spin_lock_irq <-run_timer_softirq
  <idle>-0       2dNs.    6us : __next_timer_interrupt <-run_timer_softirq
  <idle>-0       2dNs.    8us : call_timer_fn <-run_timer_softirq
  <idle>-0       2dNs.    8us : delayed_work_timer_fn <-call_timer_fn
  <idle>-0       2dNs.    8us : __queue_work <-delayed_work_timer_fn
  <idle>-0       2dNs.    9us : get_work_pool <-__queue_work
  <idle>-0       2dNs.   10us : _raw_spin_lock <-__queue_work
  <idle>-0       2dNs.   10us : insert_work <-__queue_work
  <idle>-0       2dNs.   11us : get_pwq.isra.20 <-insert_work
  <idle>-0       2dNs.   12us : wake_up_process <-insert_work
  <idle>-0       2dNs.   13us : try_to_wake_up <-wake_up_process
  ...
  <idle>-0       2d...  302us : __schedule <-schedule_idle
  <idle>-0       2d...  302us :      0:120:R ==> [002]  1732:  0:R rtkit-daemon

# cat tracing_max_latency 查看最大延迟为 302us
302

3.4.2.3 function_graph

# echo function_graph > current_tracer
# echo > trace 清空跟踪缓冲
# echo 1 > tracing_on 开启追踪
# cat trace 查看追踪信息
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
   3)   2.319 us    |              } /* apparmor_socket_recvmsg */
   3)   3.737 us    |            } /* security_socket_recvmsg */
   3)               |            unix_stream_recvmsg() {
   3)               |              unix_stream_read_generic() {
   3)               |                mutex_lock() {
   3)               |                  _cond_resched() {
   3)   0.481 us    |                    rcu_all_qs();
   3)   1.369 us    |                  }
   3)   2.188 us    |                }
   3)   0.479 us    |                _raw_spin_lock();
   3)   0.526 us    |                mutex_unlock();
   3)   0.465 us    |                put_pid();
   3)   6.043 us    |              }
   3)   7.018 us    |            }
   3) + 12.114 us   |          } /* sock_recvmsg */
   ...
   3) ! 122.290 us  |      }
   3) ! 123.110 us  |    }
   3) ! 125.997 us  |  }
   ...
 ------------------------------------------
   3)  gnome-t-3300  =>    <idle>-0   
 ------------------------------------------

   3)   0.621 us    |      finish_task_switch();
   3) # 1956.576 us |    } /* schedule_idle */
   3) * 11216.74 us |  } /* do_idle */

function_graph 是很有用的 tracer ，因为它追踪了函数的进入和退出，所以能够评测函数的执行时间。在上面我们看到 #，*，！ 等这些奇怪的符号，它们的含义是用来标记值得注意的时间消耗，这些符号的具体含义如下：

‘$’ - greater than 1 second
‘@’ - greater than 100 millisecond
‘*’ - greater than 10 millisecond
‘#’ - greater than 1000 microsecond
‘!’ - greater than 100 microsecond
‘+’ - greater than 10 microsecond
‘ ‘ - less than or equal to 10 microsecond.

3.5 ftrace 追踪选项

# cat trace_options 查看支持的追踪选项
print-parent
nosym-offset
nosym-addr
noverbose
noraw
nohex
nobin
noblock
trace_printk
annotate
...

要禁用某个选项，通过在选项名前加上 "no" 前缀，然后写入到 trace_options 文件，或者写 0 到 options/选项名 文件；
要启用某个选项，通过移除选项名前 "no" 前缀，然后写入到 trace_options 文件，或者写 1 到 options/选项名 文件。

3.5.1 print-parent

function tracer的输出数据中，是否输出调用链中 caller 函数。

# cat trace_options | grep print-parent
print-parent
# echo function > current_tracer
# echo > trace 清空跟踪缓冲
# echo 1 > tracing_on 开启追踪
# cat trace 查看追踪信息
      irqbalance-995   [003] .... 32160.569842: seq_put_decimal_ull <-show_stat
      irqbalance-995   [003] .... 32160.569843: kstat_irqs_usr <-show_stat

# echo noprint-parent > trace_options
# cat trace_options
noprint-parent
...
# echo > trace 清空跟踪缓冲
# echo 1 > tracing_on 开启追踪
# cat trace
 update-notifier-2727  [003] .... 32315.372687: copy_msghdr_from_user
 update-notifier-2727  [003] .... 32315.372689: rw_copy_check_uvector
 update-notifier-2727  [003] .... 32315.372689: __check_object_size
 update-notifier-2727  [003] .... 32315.372690: check_stack_object
 update-notifier-2727  [003] .... 32315.372691: sock_recvmsg

看看，后一记录没有了 <- 标记的调用链。

3.5.2 sym-offset

以函数名+偏移形式显示调用链：

# echo sym-offset > trace_options
# cat trace 查看追踪信息
 gnome-terminal--3300  [000] .... 33488.523955: sock_poll+0x0/0x90 <-do_sys_poll+0x367/0x600
...

3.5.3 sym-addr

# echo sym-addr > trace_options
# cat trace 查看追踪信息
          compiz-2280  [003] .... 33594.617764: sock_poll+0x0/0x90 <ffffffff9484dc30> <-do_sys_poll+0x367/0x600 <ffffffff9429bec7>
...

3.5.4 trace_printk

写 0 禁用 trace_printk() 写入缓冲区。

3.5.5 annotate

有些时候，当所有的 CPU buffer 被填满了，其中一个 CPU 的某个 buffer 有很多新近的事件数据，因此其包含的事件数据时间范围更短；而另一个 CPU 的某个 buffer 可能只有几个新近的事件数据，这使得其包含的事件数据的时间范围较前一个CPU buffer更早。当报告事件数据时，会先显示时间上更靠前的数据，这样输出的报告数据，看起来就像是只有包含时间上更早事件数据的CPU在运行一样，让人感到困惑。当开启 annotate 选项时，每当报告另一个 CPU 的 buffer 数据时，就会插入一个注释行，提示接下来输出的是另一个 CPU 的 buffer 数据。如：

 <idle>-0     [001] d... 36111.794219: nohz_balance_enter_idle <-__tick_nohz_idle_enter
          <idle>-0     [001] d... 36111.794219: rcu_irq_exit <-irq_exit
          <idle>-0     [001] d... 36111.794219: rcu_eqs_enter_common <-rcu_irq_exit
          <idle>-0     [001] .... 36111.794221: rcu_idle_exit <-do_idle
          <idle>-0     [001] d... 36111.794221: rcu_dynticks_eqs_exit <-rcu_idle_exit
          <idle>-0     [001] .... 36111.794221: arch_cpu_idle_exit <-do_idle
          <idle>-0     [001] d... 36111.794222: arch_cpu_idle_enter <-do_idle
          <idle>-0     [001] d... 36111.794222: tsc_verify_tsc_adjust <-arch_cpu_idle_enter
          <idle>-0     [001] d... 36111.794223: local_touch_nmi <-arch_cpu_idle_enter
          <idle>-0     [001] d... 36111.794223: tick_check_broadcast_expired <-do_idle
          <idle>-0     [001] d... 36111.794224: cpuidle_get_cpu_driver <-do_idle
          <idle>-0     [001] d... 36111.794224: rcu_idle_enter <-do_idle
          <idle>-0     [001] d... 36111.794224: rcu_eqs_enter_common <-rcu_idle_enter
          <idle>-0     [001] d... 36111.794224: cpuidle_not_available <-do_idle
          <idle>-0     [001] d... 36111.794225: default_idle_call <-do_idle
          <idle>-0     [001] d... 36111.794225: arch_cpu_idle <-default_idle_call
          <idle>-0     [001] d... 36111.794225: default_idle <-arch_cpu_idle
##### CPU 2 buffer started ####
          compiz-2280  [002] .... 36111.798775: __check_object_size <-do_sys_poll
          ...

看上面的输出，当从 CPU 1 的 buffer 切换到 CPU 2 的 buffer 时，输出了一个注释行：

##### CPU 2 buffer started ####

这就是 annotate 选项的作用。

3.5.6 userstacktrace

在每个 trace event 记录之后，都伴随着一个当前用户空间线程的栈追踪记录。

3.5.7 sym-userobj

当 userstacktrace 开启时，开启 sym-userobj 时将输出堆栈中地址所属的 文件/目标/行号，并且打印地址在所属目标文件内的相对地址。这在启用了 ASLR(Address Space Layout Randomization)，否则在应用退出后，你将再没有机会将栈中地址解析为对应的 文件/目标/行号。如：

a.out-1623  [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0
x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]

3.5.8 overwrite

控制当 ftrace 追踪 ring buffer 满时，采取的策略。如果为1(默认值)，覆写时间上最早的数据；如果为0，则丢弃新数据。

3.5.9 function-trace

如果启用，延迟追踪类 tracer(如 irqoff 等) 将开启对函数的追踪(function trace)。默认启用。

3.5.10 stacktrace

如果启用，在每个 trace event 记录之后，都会伴随着一个栈追踪记录。

3.5.11 其它

TODO

3.6 ftrace 过滤命令

ftrace 过滤命令有如下通用格式：

echo <function>:<command>:<parameter> > set_ftrace_filter
echo <function>:<command>:<parameter> >> set_ftrace_filter

3.6.1 mod 过滤命令

mod 命令用来控制每 module 的函数过滤。
如：

echo 'write*:mod:ext3' > set_ftrace_filter

其中 mod 命令使能每 module 的函数过滤，write*:mod:ext3 合起来的意思就是只追踪模块 ext3 中的匹配 write* 模式的函数。用下面的命令移除上述过滤器：

echo '!write*:mod:ext3' >> set_ftrace_filter

就是在过滤表示式前加一个 ! 号。下面列举了几个常见 mod 操作命令：

echo '!*:mod:!ext3' >> set_ftrace_filter 禁用除了ext3外其它所有模块函数的跟踪
echo '!*:mod:*' >> set_ftrace_filter 禁用对所有模块的追踪
...

3.6.2 traceon/traceoff 过滤命令

在特定的函数被调用时，打开或关闭追踪系统。

echo '__schedule_bug:traceoff:5' > set_ftrace_filter 前5次__schedule_bug()调用关闭trace
echo '!__schedule_bug:traceoff:0' > set_ftrace_filter 移除上一条过滤规则

echo '__schedule_bug:traceoff' > set_ftrace_filter 只要调用__schedule_bug()就关闭trace
echo '!__schedule_bug:traceoff' > set_ftrace_filter 移除上一条过滤规则

3.6.3 snapshot 过滤命令

echo 'native_flush_tlb_others:snapshot' > set_ftrace_filter 触发snapshot每当native_flush_tlb_others()被调用时
echo '!native_flush_tlb_others:snapshot' > set_ftrace_filter 移除上一条过滤规则

echo 'native_flush_tlb_others:snapshot:1' > set_ftrace_filter 只触发一次snapshot
echo '!native_flush_tlb_others:snapshot:0' > set_ftrace_filter 移除上一条过滤规则

3.6.4 启用/关闭事件过滤命令

命令格式如下：

echo <function>:enable_event:<system>:<event>[:count] > set_ftrace_filter
echo <function>:disable_event:<system>:<event>[:count] > set_ftrace_filter

如：

# 启用事件 sched:sched_switch 的过滤规则
echo 'try_to_wake_up:enable_event:sched:sched_switch:2' > set_ftrace_filter

# 移除事件 sched:sched_switch 过滤规则的两种方式
echo '!try_to_wake_up:enable_event:sched:sched_switch:0' > set_ftrace_filter
echo '!schedule:disable_event:sched:sched_switch' > set_ftrace_filter

3.6.5 其它

dump: 某 function 触发时，导出 trace 缓冲内容到控制台
cpudump: 某 function 触发时，导出执行 function 的 CPU 的缓冲内容到控制台
stacktrace: 某 function 触发时，记录 stack trace

命令的格式同前面一样：

echo <function>:<command>:<parameter> > set_ftrace_filter

其中的 command 分别是 dump,cpudump,stacktrace 。

3.7 ftrace snapshot

如果内核开启了配置项 CONFIG_TRACER_SNAPSHOT ，所有 非延迟类追踪tracer 都可以使用 snapshot 特性。那到底什么是 snapshot ？顾名思义，snapshot 就是当前 ftrace 追踪 ring buffer 内容的一个快照，即保存当前 ftrace 追踪 ring buffer 内容的一个缓冲区。
接下来，看看该怎么使用 snapshot ，下面的表格给出了 snapshot 用法：

 -----------------------------------------------------------
| status \ input | 0            | 1          | else         |
|----------------|--------------|------------|--------------|
| not allocated  | (do nothing) | alloc+swap | (do nothing) |
|----------------|--------------|------------|--------------|
| allocated      | free         | swap       | clear        |
 -----------------------------------------------------------

以一个例子来说明 snapshot 的用法：

# echo 1 > events/sched/enable 启用对调度事件的追踪
# echo 1 > snapshot 分配一个snapshot缓冲，并且将该缓冲和当前ftrace缓冲互换
# cat snapshot 读取snapshot缓冲，即ftrace缓冲的快照
# tracer: nop
#
# entries-in-buffer/entries-written: 12153/12153   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
 systemd-journal-392   [001] d...  1257.482249: sched_stat_runtime: comm=systemd-journal pid=392 runtime=208507 [ns] vruntime=111987337 [ns]
            bash-2819  [002] dN..  1257.482257: sched_stat_runtime: comm=bash pid=2819 runtime=1572127 [ns] vruntime=97226080 [ns]
       in:imklog-1090  [002] d...  1257.482357: sched_stat_runtime: comm=in:imklog pid=1090 runtime=274641 [ns] vruntime=27355353 [ns]
     kworker/2:0-2818  [002] d...  1257.482367: sched_stat_runtime: comm=kworker/2:0 pid=2818 runtime=10041 [ns] vruntime=103641088200 [ns]
   rs:main Q:Reg-1092  [003] d...  1257.482528: sched_stat_runtime: comm=rs:main Q:Reg pid=1092 runtime=197090 [ns] vruntime=52490293 [ns]
...

echo 1 > snapshot 命令的工作细节是：ftrace 分配一个空闲 buffer ，然后将 ftrace 的当前 buffer 和 空闲 buffer 交换，空闲 buffer 变成了 ftrace 的当前 buffer 。cat snapshot 命令读取 和 空闲 buffer 交换的 buffer 的内容，其内容为 ftrace 交换 buffer 时追踪内容的快照。
用完 snapshot 缓冲后，可以通过 echo 0 > snapshot 命令释放它，这里释放的是被交换出来的那个 buffer ，而不是新分配的。

# echo 0 > snapshot 释放缓冲
# cat snapshot 再次查看，内容已经为空
# tracer: nop
#
#
# * Snapshot is freed *
#
# Snapshot commands:
# echo 0 > snapshot : Clears and frees snapshot buffer
# echo 1 > snapshot : Allocates snapshot buffer, if not already allocated.
#                      Takes a snapshot of the main buffer.
# echo 2 > snapshot : Clears snapshot buffer (but does not allocate or free)
#                      (Doesn't have to be '2' works with any number that
#                       is not a '0' or '1')

3.8 ftrace 多个缓冲实例

前述所有章节中，ftrace 所有的追踪，都是使用了唯一的一个全局 ring buffer ，这是系统启动期间 ftrace 创建的。假设现在想用一个不同于全局 ring buffer 的新缓冲，来记录追踪数据，该怎么办？答案非常简单，就是用 mkdir 命令在 instances 目录 下新建一个子目录，ftrace 将为你创建一个新的 ring buffer 来记录追踪数据；如果使用完成后，想移除该缓冲，使用 rmdir 命令删除 instances 目录 下新建的子目录即可。来看一个例子：

# mkdir instances/foo
# ls instances/foo/ -l
-r--r--r--   1 root root 0 4月  13 12:39 available_tracers
-rw-r--r--   1 root root 0 4月  13 12:39 buffer_size_kb
-r--r--r--   1 root root 0 4月  13 12:39 buffer_total_size_kb
-rw-r--r--   1 root root 0 4月  13 12:39 current_tracer
drwxr-xr-x  85 root root 0 4月  13 12:39 events
--w-------   1 root root 0 4月  13 12:39 free_buffer
drwxr-xr-x   2 root root 0 4月  13 12:39 options
drwxr-xr-x 130 root root 0 4月  13 12:39 per_cpu
-rw-r--r--   1 root root 0 4月  13 12:39 set_event
-rw-r--r--   1 root root 0 4月  13 12:39 set_event_pid
-rw-r--r--   1 root root 0 4月  13 12:39 set_ftrace_filter
-rw-r--r--   1 root root 0 4月  13 12:39 set_ftrace_notrace
-rw-r--r--   1 root root 0 4月  13 12:39 set_ftrace_pid
-rw-r--r--   1 root root 0 4月  13 12:39 snapshot
-rw-r--r--   1 root root 0 4月  13 12:39 trace
-rw-r--r--   1 root root 0 4月  13 12:39 trace_clock
--w--w----   1 root root 0 4月  13 12:39 trace_marker
--w--w----   1 root root 0 4月  13 12:39 trace_marker_raw
-rw-r--r--   1 root root 0 4月  13 12:39 trace_options
-r--r--r--   1 root root 0 4月  13 12:39 trace_pipe
-rw-r--r--   1 root root 0 4月  13 12:39 tracing_cpumask
-rw-r--r--   1 root root 0 4月  13 12:39 tracing_max_latency
-rw-r--r--   1 root root 0 4月  13 12:39 tracing_on

看到了吗？和 ftrace 导出的顶层目录及其相似，用法也一样，对此处的修改，不会影响系统启动期间 ftrace 创建的全局缓冲。用完之后，删除即可：

# rmdir instances/foo
# ls instances/ -l
total 0

3.9 stack trace

要使用 stack trace 功能，首先内核要开启 CONFIG_STACK_TRACER 配置项。另外，stack trace 功能有一个开关，可以在内核命令行添加 stacktrace 开启，或者对文件 /proc/sys/kernel/stack_tracer_enabled 写 1 来开启。

# echo 1 > /proc/sys/kernel/stack_tracer_enabled
# cat stack_max_size 
2920
# # cat stack_trace
        Depth    Size   Location    (15 entries)
        -----    ----   --------
  0)     2888      64   __msecs_to_jiffies+0x5/0x30
  1)     2824      88   update_group_capacity+0x28/0x1f0
  2)     2736      40   find_busiest_group+0xfb/0xa20
  3)     2696     600   load_balance+0x195/0xa20
  4)     2096     120   pick_next_task_fair+0x419/0x580
  5)     1976     104   __schedule+0x118/0x8b0
  6)     1872      24   schedule+0x36/0x80
  7)     1848     144   schedule_hrtimeout_range_clock+0x196/0x1b0
  8)     1704      16   schedule_hrtimeout_range+0x13/0x20
  9)     1688      32   poll_schedule_timeout+0x45/0x70
 10)     1656     928   do_select+0x6eb/0x830
 11)      728     416   core_sys_select+0x1f6/0x310
 12)      312     104   SyS_select+0xba/0x110
 13)      208      32   do_syscall_64+0x73/0x130
 14)      176     176   entry_SYSCALL_64_after_hwframe+0x41/0xa6

stack_trace 的内容会随着时间的变化而变化，最大达到 stack_max_size 的深度。