Ftrace 是一个 Linux 内部的 trace 工具，能够帮助开发者和系统设计者知道内核当前正在进行的工作，从而更好的去分析性能问题。Ftrace 能帮我们分析内核特定的事件，譬如调度，中断等，也能帮我们去追踪动态的内核函数，以及这些函数的调用栈还有栈的使用。它也能帮我们去追踪延迟，譬如中断被屏蔽，抢占被禁止的时间，以及唤醒一个进程之后多久开始执行的时间。

ftrace 原理

Ftrace 最初是在 2.6.27 中出现，那时 SystemTap 已经开始崭露头角，然而 SystemTap 设计比较复杂，不当的使用和 SystemTap 自身的不完善都有可能导致系统崩溃，在真正的产品环境，人们依然无法放心的使用。

Ftrace 的设计目标简单，本质上是一种静态代码插装技术，不需要支持某种编程接口让用户自定义 trace 行为。静态代码插装技术更加可靠，不会因为用户的不当使用而导致内核崩溃。 ftrace 代码量很小，稳定可靠。实际上，即使是 Dtrace，大多数用户也只使用其静态 trace 功能。

  • Ftrace 主要由 ftrace framework 和 一系列 tracer两部分组成，每个 tracer 完成不同的功能，它们统一由 framework 管理
  • ftrace 的 trace 信息保存在 ring buffer 中，由 framework 负责管理。ftrace 有两种主要跟踪机制可以往缓冲区中写数据
    • 函数：即动态探针，可以跟踪内核函数的调用栈，包括 function tracer，function graph tracer 两个 tracer
    • 事件：即静态探针，包括其他大多数的 tracer
  • Framework 利用 debugfs 系统在 /debugfs 下建立 tracing 目录，对用户空间输出 trace 信息，并提供了一系列的控制文件
    • ftrace 的目录设置和 sysfs 类似，都是把目录当作对象，把里面的文件当作这个对象的属性。
    • debugfs/tracing 目录可以理解成一个独立的监控实例 instance，在 tracing 目录或者子目录创建任何目录相当于创建了一个新的 ftrace 实例，ftrace 会为这个 ftrace 实例自动创建 ring buffer 内存缓冲区，并在这个目录下创建 ftrace 实例所需的与 tracing 目录完全相同的文件。

debugfs 在大部分发行版中都 mount 在 /sys/kernel/debug 目录下，而 ftrace 就在这个目录下的 tracing 目录中。如果系统没有 mount 这个文件系统，可以手动 mount。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14

# 1. 重新挂在 debugfs
$ mount -t debugfs none /debugs

# 2. debugfs/tracing 目录
$ ll /debugs/tracing

# 3. 创建新的 ftrace trace 实例
$ mkdir /debugs/tracing/instance/python

# ftrace 会创建新的内存缓冲区并生成 ftrace 相关文件
$ ll tracing/instances/python/
available_tracers  buffer_total_size_kb  events       per_cpu        set_ftrace_filter   snapshot        trace_clock       trace_options    tracing_max_latency
buffer_percent     current_tracer        free_buffer  set_event      set_ftrace_notrace  timestamp_mode  trace_marker      trace_pipe       tracing_on
buffer_size_kb     error_log             options      set_event_pid  set_ftrace_pid      trace           trace_marker_raw  tracing_cpumask

ftrace 控制机制

在讲解 ftrace 的 tracer 之前，我们先来看看 tracing 目录下的文件，它们提供了对 ftrace trace 过程的控制。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10

$ ls
available_events            free_buffer               printk_formats       snapshot            trace_stat
available_filter_functions  function_profile_enabled  README               stack_max_size    tracing_cpumask
available_tracers           hwlat_detector            saved_cmdlines       stack_trace   tracing_max_latency
buffer_size_kb              instances                 saved_cmdlines_size  stack_trace_filter  tracing_on
buffer_total_size_kb        kprobe_events             set_event            trace              tracing_thresh
current_tracer              kprobe_profile            set_ftrace_filter    trace_clock        uprobe_events
dyn_ftrace_total_info       max_graph_depth           set_ftrace_notrace   trace_marker       uprobe_profile
enabled_functions           options                   set_ftrace_pid       trace_options
events                      per_cpu                   set_graph_function   trace_pipe

tracing 目录下的文件分成了下面四类:

  • 提示类：显示当前系统可用的 event，tracer 列表
  • 控制类：控制 ftrace 的跟踪参数
  • 显示类：显示 trace 信息
  • 辅助类：一些不明或者不重要的辅助信息

提示类

ftrace 文件 作用
available_events 可用事件列表，也可查看 events/ 目录
available_filter_functions 当前内核导出的可以跟踪的函数
dyn_ftrace_total_info 显示 available_filter_functins 中跟中函数的数目
available_tracers 可用的 tracer，不同的 tracer 有不同的功能
events 1. 查看可用事件列表以及事件参数(事件包含的内核上下文信息) cat events/sched/sched_switch/format 2.设置事件的过滤条件 echo ‘next_comm ~ “cs”‘ > events/sched/sched_switch/filter

控制类

适用 tracer ftrace 文件 作用
通用 tracing_on 用于控制跟踪打开或停止，0 停止跟踪，1 继续跟踪
通用 tracing_cpumask 设置允许跟踪特定 CPU
通用 tracing_max_latency 记录 Tracer 的最大延时
通用 tracing_thresh 延时记录 Trace 的阈值，当延时超过此值时才开始记录 Trace。单位是 ms，只有非 0 才起作用
通用 events 1. 查看可用事件列表以及事件参数(事件包含的内核上下文信息) cat events/sched/sched_switch/format 2.设置事件的过滤条件 echo ‘next_comm ~ “cs”‘ > events/sched/sched_switch/filter
通用 set_event 设置跟踪的 event 事件，与通过 events 目录内的 filter 文件设置一致
通用 current_tracer 1. 设置或者显示当前使用的跟踪器列表 2. 系统缺省为 nop，可以通过写入 nop 重置跟踪器 3. 使用 echo 将跟踪器名字写入即可打开 echo function_graph > current_tracer
通用 buffer_size_kb 设置单个 CPU 所使用的跟踪缓存的大小 如果跟踪太多，旧的信息会被新的跟踪信息覆盖掉 不想被覆盖需要先将 current_trace 设置为 nop 才可以
通用 buffer_total_size_kb 显示所有 CPU ring buffer 大小之和
通用 trace_options trace 过程的复杂控制选项 控制 Trace 打印内容或者操作跟踪器 也可通过 options/目录设置
通用 options/ 显示 trace_option 的设置结果 也可以直接设置，作用同 trace_options
func function_profile_enabled 打开此选项，trace_stat 就会显示 function 的统计信息 echo 0/1 > function_profile_enabled
func set_ftrace_pid 设置跟踪的 pid
func set_ftrace_filter 用于显示指定要跟踪的函数
func set_ftrace_notrace 用于指定不跟踪的函数，缺省为空
graph max_graph_depth 函数嵌套的最大深度
graph set_graph_function 设置要清晰显示调用关系的函数 缺省对所有函数都生成调用关系
Stack stack_max_size 当使用 stack 跟踪器时，记录产生过的最大 stack size
Stack stack_trace 显示 stack 的 back trace
Stack stack_trace_filter 设置 stack tracer 不检查的函数名称

输出类

ftrace 文件 作用
printk_formats 提供给工具读取原始格式 trace 的文件
trace 查看 ring buffer 内跟踪信息 echo > trace 可以清空当前 RingBuffer
trace_pipe 输出和 trace 一样的内容，但输出 Trace 同时将 RingBuffer 清空 可避免 RingBuffer 的溢出 保存文件内容: cat trace_pipe > trace.txt &
snapshot 是对 trace 的 snapshot echo 0 清空缓存，并释放对应内存 echo 1 进行对当前 trace 进行 snapshot，如没有内存则分配 echo 2 清空缓存，不释放也不分配内存
trace_clock 显示当前 Trace 的 timestamp 所基于的时钟，默认使用 local 时钟 local：默认时钟；可能无法在不同 CPU 间同步 global：不同 CUP 间同步，但是可能比 local 慢 counter：跨 CPU 计数器，需要分析不同 CPU 间 event 顺序比较有效
trace_marker 从用户空间写入标记到 trace 中，用于用户空间行为和内核时间同步
trace_stat 每个 CPU 的 Trace 统计信息
per_cpu/ trace 等文件的输出是综合所有 CPU 的，如果你关心单个 CPU 可以进入 per_cpu 目录，里面有这些文件的分 CPU 版本
enabled_functions 显示有回调附着的函数名称
saved_cmdlines 放 pid 对应的 comm 名称作为 ftrace 的 cache，这样 ftrace 中不光能显示 pid 还能显示 comm
saved_cmdlines_size saved_cmdlines 的数目

trace、trace_pipe 和 snapshot 的区别:

  1. trace 是从 RingBuffer 中取出内容
  2. trace_pipe 会一直读取 Buffer 流
  3. snapshot 是 trace 的一个瞬间快照

辅助类

ftrace 文件 作用
free_buffer 此文件用于在一个进程被关闭后，同时释放 RingBuffer 内存，并将调整大小到最小值
instances 空目录，可在此目录创建新的 ftrace 实例
hwlat_detector
kprobe_events
kprobe_profile
uprobe_events
uprobe_profile

ftrace tracer

下面是 ftrace tracer 的不完全列表，每一个 tracer 输出的内容和格式都不一样，对于我们比较常用的是 Function，Graph，Schedule switch，softirq。

ftrace 作用
Function 跟踪函数调用
Function graph tracer 跟踪函数调用，显示调用关系
Schedule switch 跟踪进程调度情况
Wakeup 跟踪进程的调度延迟，即高优先级进程从进入 ready 状态到获得 CPU 的延迟时间。该 tracer 只针对实时进程
Irqsoff 当中断被禁止时，系统无法相应外部事件，比如键盘和鼠标，时钟也无法产生 tick 中断。这意味着系统响应延迟，irqsoff 这个 tracer 能够跟踪并记录内核中哪些函数禁止了中断，对于其中中断禁止时间最长的，irqsoff 将在 log 文件的第一行标示出来，从而使开发人员可以迅速定位造成响应延迟的罪魁祸首
Preemptoff 和前一个 tracer 类似，preemptoff tracer 跟踪并记录禁止内核抢占的函数，并清晰地显示出禁止抢占时间最长的内核函数
Preemptirqsoff 同上，跟踪和记录禁止中断或者禁止抢占的内核函数，以及禁止时间最长的函数
Branch 跟踪内核程序中的 likely/unlikely 分支预测命中率情况。 Branch tracer 能够记录这些分支语句有多少次预测成功。从而为优化程序提供线索
Hardware branch 利用处理器的分支跟踪能力，实现硬件级别的指令跳转记录。在 x86 上，主要利用了 BTS 这个特性
Initcall 记录系统在 boot 阶段所调用的 init call
Mmiotrace 记录 memory map IO 的相关信息
Power 记录系统电源管理相关的信息
Sysprof 缺省情况下，sysprof tracer 每隔 1 msec 对内核进行一次采样，记录函数调用和堆栈信息
Kernel memory 内存 tracer 主要用来跟踪 slab allocator 的分配情况。包括 kfree，kmem_cache_alloc 等 API 的调用情况，用户程序可以根据 tracer 收集到的信息分析内部碎片情况，找出内存分配最频繁的代码片断，等等
Workqueue statistical 这是一个 statistic tracer，统计系统中所有的 workqueue 的工作情况，比如有多少个 work 被插入 workqueue，多少个已经被执行等。开发人员可以以此来决定具体的 workqueue 实现，比如是使用 single threaded workqueue 还是 per cpu workqueue
Event 跟踪系统事件，比如 timer，系统调用，中断等

ftrace 的实战

跟踪函数

下面这个脚本演示了 ftrace 简单实用 ftrace 的方法，它通过操作 tracing 目录下的控制对象，实现对 function 的 tracing ：

1
2
3
4
5
6
7
8

#!/bin/sh
dir=/sys/kernel/debug/tracing
sysctl kernel.ftrace_enabled=1
echo function > ${dir}/current_tracer
echo 1 > ${dir}/tracing_on
sleep 1
echo 0 > ${dir}/tracing_on
less ${dir}/trace

一旦脚本运行完成后，我们将看到下列的输出（这里只列出了一个小片断）：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28

# tracer: function
#
# entries-in-buffer/entries-written: 29571/29571   #P:2
#
#                           _-----=> irqs-off
#                           / _----=> need-resched
#                           | / _---=> hardirq/softirq
#                           || / _--=> preempt-depth
#                           ||| /   delay
#           TASK-PID   CPU#  ||||   TIMESTAMP  FUNCTION
#           | |     |   ||||    |       |
        trace.sh-1295  [000] ....   90.502874: mutex_unlock <-rb_simple_write
        trace.sh-1295  [000] ....   90.502875: __fsnotify_parent <-vfs_write
        trace.sh-1295  [000] ....   90.502876: fsnotify <-vfs_write
        trace.sh-1295  [000] ....   90.502876: __srcu_read_lock <-fsnotify
        trace.sh-1295  [000] ....   90.502876: __srcu_read_unlock <-fsnotify
        trace.sh-1295  [000] ....   90.502877: __sb_end_write <-vfs_write
        trace.sh-1295  [000] ....   90.502877: syscall_trace_leave <-int_check_syscall_exit_work
        trace.sh-1295  [000] ....   90.502878: context_tracking_user_exit <-syscall_trace_leave
        trace.sh-1295  [000] ....   90.502878: context_tracking_user_enter <-syscall_trace_leave
        trace.sh-1295  [000] d...   90.502878: vtime_user_enter <-context_tracking_user_enter
        trace.sh-1295  [000] d...   90.502878: _raw_spin_lock <-vtime_user_enter
        trace.sh-1295  [000] d...   90.502878: __vtime_account_system <-vtime_user_enter
        trace.sh-1295  [000] d...   90.502878: get_vtime_delta <-__vtime_account_system
        trace.sh-1295  [000] d...   90.502879: account_system_time <-__vtime_account_system
        trace.sh-1295  [000] d...   90.502879: cpuacct_account_field <-account_system_time
        trace.sh-1295  [000] d...   90.502879: acct_account_cputime <-account_system_time
        trace.sh-1295  [000] d...   90.502879: __acct_update_integrals <-acct_account_cputime

在这里有一个包含下列信息的函数列表：

  • 进程标识符（PID）
  • 运行这个进程的 CPU（CPU#）
  • 进程开始时间（TIMESTAMP）
  • 被跟踪函数的名字以及调用它的父级函数；例如，在我们输出的第一行，rb_simple_write 调用了 mutex-unlock 函数。

追踪系统调用

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37

# 这次使用系统默认挂载的 debugfs
$ cd /sys/kernel/debug/tracing/
# 1. 设置要显示调用栈的函数
$ echo do_sys_open > set_graph_function
# 2. 配置跟踪选项，开启函数调用跟踪，并跟踪调用进程
$ echo function_graph > current_tracer
$ echo funcgraph-proc > trace_options
# 3. 开启追踪
$ echo 1 > tracing_on
# 4. 执行一个 ls 命令后，再关闭跟踪：
$ ls
$ echo 0 > tracing_on
# 5.查看追踪结果
$ cat trace
# tracer: function_graph
#
# CPU  TASK/PID         DURATION                  FUNCTION CALLS
# |     |    |           |   |                     |   |   |   |
 0)    ls-12276    |               |  do_sys_open() {
 0)    ls-12276    |               |    getname() {
 0)    ls-12276    |               |      getname_flags() {
 0)    ls-12276    |               |        kmem_cache_alloc() {
 0)    ls-12276    |               |          _cond_resched() {
 0)    ls-12276    |   0.049 us    |            rcu_all_qs();
 0)    ls-12276    |   0.791 us    |          }
 0)    ls-12276    |   0.041 us    |          should_failslab();
 0)    ls-12276    |   0.040 us    |          prefetch_freepointer();
 0)    ls-12276    |   0.039 us    |          memcg_kmem_put_cache();
 0)    ls-12276    |   2.895 us    |        }
 0)    ls-12276    |               |        __check_object_size() {
 0)    ls-12276    |   0.067 us    |          __virt_addr_valid();
 0)    ls-12276    |   0.044 us    |          __check_heap_object();
 0)    ls-12276    |   0.039 us    |          check_stack_object();
 0)    ls-12276    |   1.570 us    |        }
 0)    ls-12276    |   5.790 us    |      }
 0)    ls-12276    |   6.325 us    |    }
...

输出：第三列是函数执行延迟；最后一列，则是函数调用关系图。

基于 ftrace 使用 kprobe

在 kprobe 这篇文章中，我介绍了通过内核模块使用 kprobe 实现追踪系统调用的方法，如果每次追踪都需要去编写内核模块比较麻烦，ftrace 也可以和 kprobe 来使用，可以对内核进行配置，然后添加探测点、进行探测、查看结果。

Kprobe 配置

打开 "General setup"->"Kprobes"，以及 "Kernel hacking"->"Tracers"->"Enable kprobes-based dynamic events"。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10

CONFIG_KPROBES=y
CONFIG_OPTPROBES=y
CONFIG_KPROBES_ON_FTRACE=y
CONFIG_UPROBES=y
CONFIG_KRETPROBES=y
CONFIG_HAVE_KPROBES=y
CONFIG_HAVE_KRETPROBES=y
CONFIG_HAVE_OPTPROBES=y
CONFIG_HAVE_KPROBES_ON_FTRACE=y
CONFIG_KPROBE_EVENT=y

kprobe 事件在 debugfs 中相关目录如下：

1
2
3
4
5

/sys/kernel/debug/tracing/kprobe_events                 # 配置kprobe事件属性，增加事件之后会在kprobes下面生成对应目录。
/sys/kernel/debug/tracing/kprobe_profile                # kprobe事件统计属性文件。
/sys/kernel/debug/tracing/kprobes/<GRP>/<EVENT>/enabled # 使能kprobe事件
/sys/kernel/debug/tracing/kprobes/<GRP>/<EVENT>/filter  # 过滤kprobe事件
/sys/kernel/debug/tracing/kprobes/<GRP>/<EVENT>/format  # 查询kprobe事件显示格式

kprobe 事件配置

新增一个 kprobe 事件，通过写 kprobe_events 来设置。

1
2
3

p[:[GRP/]EVENT] [MOD:]SYM[+offs]|MEMADDR [FETCHARGS]      # 设置一个probe探测点
r[:[GRP/]EVENT] [MOD:]SYM[+0] [FETCHARGS]                 # 设置一个return probe探测点
-:[GRP/]EVENT                                             # 删除一个探测点

解释如下：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19

GRP     : Group name. If omitted, use "kprobes" for it.         # 设置后会在events/kprobes下创建<GRP>目录
EVENT      : Event name. If omitted, the event name is generated based on SYM+offs or MEMADDR. # 指定后在events/kprobes/<GRP>生成<EVENT>目录。
MOD        : Module name which has given SYM                    # 模块名，一般不设
SYM[+offs]    : Symbol+offset where the probe is inserted       # 被探测函数名和偏移
MEMADDR    : Address where the probe is inserted                # 指定被探测的内存绝对地址
FETCHARGS    : Arguments. Each probe can have up to 128 args    # 指定要获取的参数信息。
 %REG        : Fetch register REG                               # 获取指定寄存器值
 @ADDR        : Fetch memory at ADDR (ADDR should be in kernel) # 获取指定内存地址的值
 @SYM[+|-offs]    : Fetch memory at SYM +|- offs (SYM should be a data symbol) # 获取全局变量的值
 $stackN    : Fetch Nth entry of stack (N >= 0)                 # 获取指定栈空间值，即sp寄存器+N后的位置值
 $stack    : Fetch stack address.                               # 获取sp寄存器值
 $retval    : Fetch return value.(*)                            # 获取返回值，用户return kprobe
 $comm        : Fetch current task comm.                        # 获取对应进程名称。
 +|-offs(FETCHARG) : Fetch memory at FETCHARG +|- offs address.(**) #
 NAME=FETCHARG : Set NAME as the argument name of FETCHARG.
 FETCHARG:TYPE : Set TYPE as the type of FETCHARG. Currently, basic types (u8/u16/u32/u64/s8/s16/s32/s64), hexadecimal types
          (x8/x16/x32/x64), "string" and bitfield are supported.  # 设置参数的类型，可以支持字符串和比特类型
  (*) only for return probe.
  (**) this is useful for fetching a field of data structures.

执行如下两条命令就会生成目录 /sys/kernel/debug/tracing/events/kprobes/myprobe；第三条命令则可以删除指定 kprobe 事件，如果要全部删除则 echo > /sys/kernel/debug/tracing/kprobe_events。

1
2
3
4
5

$ echo 'p:myprobe do_sys_open dfd=%ax filename=%dx flags=%cx mode=+4($stack)' > /sys/kernel/debug/tracing/kprobe_events
# 这里面一定要用">>"，不然就会覆盖前面的设置。
$ echo 'r:myretprobe do_sys_open ret=$retval' >> /sys/kernel/debug/tracing/kprobe_events
$ echo '-:myprobe' >> /sys/kernel/debug/tracing/kprobe_events
$ echo '-:myretprobe' >> /sys/kernel/debug/tracing/kprobe_events

参数后面的寄存器是跟架构相关的，%ax、%dx、%cx 表示第 1/2/3 个参数，超出部分使用 $stack 来存储参数。函数返回值保存在 $retval 中。

查看 format，也就是 trace_pipe 的打印格式

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16

[root@VM-4-27-centos kprobes]# cat /sys/kernel/debug/tracing/events/kprobes/myprobe/format
name: myprobe
ID: 1731
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:unsigned long __probe_ip;	offset:8;	size:8;	signed:0;
	field:u64 dfd;	offset:16;	size:8;	signed:0;
	field:u64 filename;	offset:24;	size:8;	signed:0;
	field:u64 flags;	offset:32;	size:8;	signed:0;
	field:u64 mode;	offset:40;	size:8;	signed:0;

print fmt: "(%lx) dfd=0x%Lx filename=0x%Lx flags=0x%Lx mode=0x%Lx", REC->__probe_ip, REC->dfd, REC->filename, REC->flags, REC->mode

kprobe 使能

对 kprobe 事件的是能通过往对应事件的 enable 写 1 开启探测；写 0 暂停探测。在 enable 专辑后，就可以在 /sys/kernel/debug/tracing/trace 看到结果了。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17

[root@VM-4-27-centos tracing]# echo > /sys/kernel/debug/tracing/trace
[root@VM-4-27-centos tracing]# ls events/kprobes/
ls: cannot access 'events/kprobes/': No such file or directory
[root@VM-4-27-centos tracing]# echo 'p:myprobe do_sys_open dfd=%ax filename=%dx flags=%cx mode=+4($stack)' > /sys/kernel/debug/tracing/kprobe_events
[root@VM-4-27-centos tracing]# ls events/kprobes/
enable  filter  myprobe
[root@VM-4-27-centos tracing]# echo 'r:myretprobe do_sys_open ret=$retval' >> /sys/kernel/debug/tracing/kprobe_events
[root@VM-4-27-centos tracing]# ls events/kprobes/
enable  filter  myprobe  myretprobe

[root@VM-4-27-centos tracing]# echo 1 > /sys/kernel/debug/tracing/events/kprobes/myprobe/enable
[root@VM-4-27-centos tracing]# echo 1 > /sys/kernel/debug/tracing/events/kprobes/myretprobe/enable
[root@VM-4-27-centos tracing]# ls
[root@VM-4-27-centos tracing]# echo 0 > /sys/kernel/debug/tracing/events/kprobes/myprobe/enable
[root@VM-4-27-centos tracing]# echo 0 > /sys/kernel/debug/tracing/events/kprobes/myretprobe/enable

$ cat /sys/kernel/debug/tracing/trace

在/sys/kernel/debug/tracing/trace 中可以看到结果。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19

[root@VM-4-27-centos tracing]# head -n 30 /sys/kernel/debug/tracing/trace
# tracer: nop
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
           <...>-3459299 [043] .... 1798044.685097: myprobe: (do_sys_open+0x0/0x220) dfd=0xffffffff88d16170 filename=0x8401 flags=0x0 mode=0xffffffff
           <...>-29058 [022] .... 1798044.749807: myprobe: (do_sys_open+0x0/0x220) dfd=0xffffffff88d16170 filename=0x88000 flags=0x0 mode=0xffffffff
           <...>-29058 [022] .... 1798044.749894: myprobe: (do_sys_open+0x0/0x220) dfd=0xffffffff88d16170 filename=0x88000 flags=0x0 mode=0xffffffff
           <...>-29058 [022] .... 1798044.749917: myprobe: (do_sys_open+0x0/0x220) dfd=0xffffffff88d16170 filename=0x88000 flags=0x0 mode=0xffffffff
           <...>-29058 [022] .... 1798044.749930: myprobe: (do_sys_open+0x0/0x220) dfd=0xffffffff88d16170 filename=0x88000 flags=0x0 mode=0xffffffff
           <...>-29058 [022] .... 1798044.749943: myprobe: (do_sys_open+0x0/0x220) dfd=0xffffffff88d16170 filename=0x88000 flags=0x0 mode=0xffffffff
           <...>-29058 [022] .... 1798044.749956: myprobe: (do_sys_open+0x0/0x220) dfd=0xffffffff88d16170 filename=0x88000 flags=0x0 mode=0xffffffff
           <...>-29058 [022] .... 1798044.749971: myprobe: (do_sys_open+0x0/0x220) dfd=0xffffffff88d16170 filename=0x88000 flags=0x0 mode=0xffffffff
# ...

kprobe 事件过滤

跟踪函数需要通过 filter 进行过滤，可以有效过滤掉冗余信息。

filter 文件用于设置过滤条件，可以减少 trace 中输出的信息，它支持的格式和 c 语言的表达式类似，支持 ==，!=，>，<，>=，<=判断，并且支持与&&，或||，还有()。

1

$ echo 'filename==0x8241' > /sys/kernel/debug/tracing/events/kprobes/myprobe/filter

kprobe 和栈配合使用

如果要在显示函数的同时显示其栈信息，可以通过配置 trace_options 来达到。

1

echo stacktrace > /sys/kernel/debug/tracing/trace_options

kprobe_profile 统计信息

获取一段 kprobe 时间之后，可以在 kprobe_profile 中查看统计信息。

后面两列分别表示命中和未命中的次数。

1
2
3

cat /sys/kernel/debug/tracing/kprobe_profile
  myprobe                                                   11               0
  myretprobe                                                11               0

Debugfs 抓 kprobe event 实现原理

接下来我们初略的分析下 debugfs 中 kprobe event 的实现过程。

根据代码 kernel/trace/trace_kprobe.c 可知在 kernel 初始化的 fs_initcall 阶段，就调用了 init_kprobe_trace 来实现 kprobe_events，并指定了 kprobe_events_ops 这个 file_operation。当用 echo 操作 kprobe_events 这个节点时，调用 probe_write，注册 kprobe event。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44

static const struct seq_operations probes_seq_op = {
  .start	= probes_seq_start,
	.next	= probes_seq_next,
	.stop	= probes_seq_stop,
	.show	= probes_seq_show
};
static int probes_open(struct inode *inode, struct file *file)
{
	int ret;
	if ((file->f_mode & FMODE_WRITE) && (file->f_flags & O_TRUNC)) {
		ret = release_all_trace_kprobes();
		if (ret < 0)
			return ret;
	}
	return seq_open(file, &probes_seq_op);
}
static const struct file_operations kprobe_events_ops = {
	.owner		= THIS_MODULE,
	.open		= probes_open,
	.read		= seq_read,
	.llseek 	= seq_lseek,
	.release	= seq_release,
	.write		= probes_write,
};
/* Make a tracefs interface for controlling probe points */
static __init int init_kprobe_trace(void)
{
	struct dentry *d_tracer;
	struct dentry *entry;
	if (register_module_notifier(&trace_kprobe_module_nb))
		return -EINVAL;
	d_tracer = tracing_init_dentry();
	if (IS_ERR(d_tracer))
		return 0;
	entry = tracefs_create_file("kprobe_events", 0644, d_tracer,
				    NULL, &kprobe_events_ops);
    ... ...
	/* Profile interface */
	entry = tracefs_create_file("kprobe_profile", 0444, d_tracer,
				    NULL, &kprobe_profile_ops);
    ... ...
	return 0;
}
fs_initcall(init_kprobe_trace);

注册 kprobe events 相关调用顺序如下所示，最终调用的是 __register_trace_kprobe 来实现真正的注册过程。

1
2
3
4

probes_write
  create_trace_kprobe
     register_trace_kprobe
	     __register_trace_kprobe

__register_trace_kprobe 的实现细节如下所示，其中令人醒目的是调用了 register_kprobe ，这个就到了注册 kprobe 过程，这个可以参看内核目录下的一个样例 kprobe_example.c，看看注册要哪些参数，这里可以猜测到 struct trace_kprobe 结构体中的 rp.kp 指定了探测符号和偏移量，这里就不一一分析了，读者可根据这个看看详细 kprobe events 怎么注册的。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24

/* Internal register function - just handle k*probes and flags */
static int __register_trace_kprobe(struct trace_kprobe *tk)
{
	int i, ret;
	if (trace_probe_is_registered(&tk->tp))
		return -EINVAL;
	for (i = 0; i < tk->tp.nr_args; i++)
		traceprobe_update_arg(&tk->tp.args[i]);
	/* Set/clear disabled flag according to tp->flag */
	if (trace_probe_is_enabled(&tk->tp))
		tk->rp.kp.flags &= ~KPROBE_FLAG_DISABLED;
	else
		tk->rp.kp.flags |= KPROBE_FLAG_DISABLED;
	if (trace_kprobe_is_return(tk))
		ret = register_kretprobe(&tk->rp);
	else
		ret = register_kprobe(&tk->rp.kp);
	if (ret == 0)
		tk->tp.flags |= TP_FLAG_REGISTERED;
	else {
	... ...
	}
	return ret;
}

perf-tools

ftrace 一个比较明显的缺点是没有用户态的跟踪点支持。perf-tools 对 Ftrace 的功能进行了很好的封装和集成，建议大家用 perf-tools 来使用 Ftrace，则效果更佳更简单，关于 perf-tools 的实用可以参考 Github: perf-tools。

参考资料