0%

【动态追踪】Linux Ftrace

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 tracerfunction 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的数目

tracetrace_pipesnapshot 的区别:

  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 目录下的控制对象,实现对 functiontracing

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

参考资料