> 文章列表 > linux: ftrace使用手册

linux: ftrace使用手册

linux: ftrace使用手册

文章目录

  • 1. 前言
  • 2. 背景
  • 3. ftrace
    • 3.1 简介
    • 3.2 ftrace 文件系统
    • 3.3 ftrace 使用
      • 3.3.1 current_tracer
      • 3.3.2 available_tracers
      • 3.3.3 tracing_on
      • 3.3.4 trace
      • 3.3.5 trace_pipe
      • 3.3.5 trace_options
      • 3.3.6 options
      • 3.3.7 tracing_max_latency
      • 3.3.8 tracing_thresh
      • 3.3.9 buffer_size_kb
      • 3.3.10 buffer_total_size_kb
      • 3.3.11 free_buffer
      • 3.3.12 tracing_cpumask???
      • 3.3.13 set_ftrace_filter
      • 3.3.14 set_ftrace_notrace
      • 3.3.15 set_ftrace_pid
      • 3.3.16 set_ftrace_notrace_pid
      • 3.3.17 set_event_pid
      • 3.3.18 set_event_notrace_pid
      • 3.3.19 set_graph_function
      • 3.3.20 set_graph_notrace
      • 3.3.21 available_filter_functions
      • 3.3.22 dyn_ftrace_total_info
      • 3.3.23 enabled_functions
      • 3.3.24 function_profile_enabled
      • 3.3.25 trace_stat
      • 3.3.26 kprobe_events
      • 3.3.27 kprobe_profile
      • 3.3.28 max_graph_depth
      • 3.3.29 printk_formats
      • 3.3.29 saved_cmdlines
      • 3.3.30 saved_cmdlines_size
      • 3.3.31 saved_tgids
      • 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
      • 3.3.37 trace_marker
      • 3.3.38 trace_marker_raw
      • 3.3.39 uprobe_events
      • 3.3.40 uprobe_profile
      • 3.3.41 instances
      • 3.3.42 events
      • 3.3.43 set_event
      • 3.3.44 available_events
      • 3.3.45 timestamp_mode
      • 3.3.46 hwlat_detector
      • 3.3.47 per_cpu
  • 4. 各类 tracer
    • 4.1 简介
      • 4.1.1 function
      • 4.1.2 function_graph
      • 4.1.3 blk
      • 4.1.4 hwlat
      • 4.1.5 irqsoff
      • 4.1.6 preemptoff
      • 4.1.7 preemptirqsoff
      • 4.1.8 wakeup
      • 4.1.9 wakeup_rt
      • 4.1.10 wakeup_dl
      • 4.1.11 mmiotrace
      • 4.1.12 branch
      • 4.1.13 nop
  • 5. tracer 使用示例
    • 5.1 function
    • 5.2 wakeup
    • 5.3 function_graph
  • 6. 追踪选项
    • 6.1 print-parent
    • 6.2 sym-offset
    • 6.3 sym-addr
    • 6.4 trace_printk
    • 6.5 annotate
    • 6.6 userstacktrace
    • 6.7 sym-userobj
    • 6.8 其它
  • 7. 过滤命令
    • 7.1 mod 过滤命令
    • 7.2 traceon/traceoff 过滤命令
    • 7.3 snapshot 过滤命令
    • 7.4 启用/关闭事件过滤命令
    • 7.5 其它

1. 前言

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

2. 背景

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

3. ftrace

3.1 简介

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

3.2 ftrace 文件系统

ftrace 通过 sysfs 向用户空间导出接口:

# 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,停止追踪。追踪使用 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_pipetrace 一样,都是记录当前的追踪内容,但它和 trace 不一样的是:
o 对 trace_pipe 的读操作将会阻塞,直到有新的追踪数据进来为止;
o 当前从trace_pipe 读取的内容将被消耗掉,再次读 trace_pipe 又会阻塞到新数据进来为止。

3.3.5 trace_options

trace_options 列举可以用来控制追踪系统写入到 tracetrace_pipe 中内容的选项。trace_options 中列举的每一个选项名,在 options 目录 下都有一个对应文件,对 options 目录 下的文件写 0 或 1 来关闭或启用对应的选项,以达到控制追踪系统写入到 tracetrace_pipe 的内容。我们在 set_ftrace_pid 文件说明中,对此选项做进一步说明。

3.3.6 options

trace_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 的大小,单位为 KBper_cpu/cpuX/buffer_size_kb 记录 每个CPU buffer 大小,单位为 KB 。可通过写 buffer_size_kb 来改变 CPU buffer 的大小。

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。

3.3.13 set_ftrace_filter

只对文件 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_notraceset_ftrace_filter 刚好相反,系统禁用对其中列举函数的追踪。

3.3.15 set_ftrace_pid

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

3.3.16 set_ftrace_notrace_pid

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

3.3.17 set_event_pid

仅跟踪 set_event_pid 中 PID 指定进程的 event 。如果开启了 options/event-fork 选项,fork 的子进程的 PID 也会自动加入文件,同时该选项也会引起系统自动将退出进程的 PID 从文件中移除。

3.3.18 set_event_notrace_pid

不跟踪 set_event_pid 中 PID 指定进程的 event 。如果开启了 options/event-fork 选项,fork 的子进程的 PID 也会自动加入文件,同时该选项也会引起系统自动将退出进程的 PID 从文件中移除。

3.3.19 set_graph_function

function_graph tracer 追踪文件中列举的函数。注意,set_ftrace_filterset_ftrace_notrace 仍会影响 被追踪不被追踪 的函数列表。

3.3.20 set_graph_notrace

set_graph_notraceset_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 ,将启用对所有支持函数的 function 追踪,如果启用了 graph_function tracer ,也将启用对所有支持函数的 graph_function 追踪。同时也会保留调用的函数数量的直方图,还将跟踪在这些函数中花费的时间。直方图内容可以显示在文件中:trace_stat/function[cpu] 。如:

# echo 1 > function_profile_enabled
# cat trace_stat/function0Function                               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
...

3.3.25 trace_stat

包含各种追踪系统统计数据的目录,为每个 CPU buffer 建立1个目录:trace_stat/function[cpu]

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

3.3.26 kprobe_events

kprobe 追踪相关,见后面的叙述。

3.3.27 kprobe_profile

kprobe 追踪相关,见后面的叙述。

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

文件记录 进程 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

文件记录 进程 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

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

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

有时候可能有需求,要形成全局的参照,这时候使用 CPU 本地时钟 local ,可能就不合适了。我们可以通过命令:

# 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

写这个文件,将写入到 ftrace buffer ???

3.3.38 trace_marker_raw

TODO:

3.3.39 uprobe_events

见后面的叙述。

3.3.40 uprobe_profile

TODO:

3.3.41 instances

TODO:

3.3.42 events

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

3.3.43 set_event

写文件 set_event 将启用指定的 trace event 。可写入的 trace event 名,查看文件 available_events

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 包含的信息。

4. 各类 tracer

4.1 简介

4.1.1 function

跟踪所有内核函数的 tracer。

4.1.2 function_graph

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

4.1.3 blk

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

4.1.4 hwlat

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

4.1.5 irqsoff

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

4.1.6 preemptoff

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

4.1.7 preemptirqsoff

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

4.1.8 wakeup

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

4.1.9 wakeup_rt

类似于 wakeup tracer ,但仅追踪记录 RT 任务。

4.1.10 wakeup_dl

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

4.1.11 mmiotrace

TODO:

4.1.12 branch

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

4.1.13 nop

关闭 tracer 。

5. tracer 使用示例

5.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_writebackvmtoolsd-1512  (-----) [000] .... 29892.117923: bit_waitqueue <-__inode_wait_for_writeback
...

5.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

5.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.

6. 追踪选项

# 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/选项名 文件。

6.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_statirqbalance-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 traceupdate-notifier-2727  [003] .... 32315.372687: copy_msghdr_from_userupdate-notifier-2727  [003] .... 32315.372689: rw_copy_check_uvectorupdate-notifier-2727  [003] .... 32315.372689: __check_object_sizeupdate-notifier-2727  [003] .... 32315.372690: check_stack_objectupdate-notifier-2727  [003] .... 32315.372691: sock_recvmsg

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

6.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
...

6.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>
...

6.4 trace_printk

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

6.5 annotate

有些时候,当 CPU 的 buffer 被填满时,其中一个 CPU 的 buffer 有很多新近的事件数据,因此其包含的事件数据时间范围更短;而另一个 CPU 的 buffer 可能只有几个新近的事件数据,这使得其包含的事件数据的时间范围较前一个CPU更早。当报告事件数据时,会先显示时间上更靠前的数据,看起来就像是只有包含时间上更早事件数据的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 选项的作用。

6.6 userstacktrace

在每个 trace event 后记录当前用户间线程的堆栈。

6.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]

6.8 其它

TODO

7. 过滤命令

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

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

7.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 禁用对所有模块的追踪
...

7.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 移除上一条过滤规则

7.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 移除上一条过滤规则

7.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

7.5 其它

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

命令的格式同前面一样:

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

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