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

输出:第三列是函数执行延迟;最后一列,则是函数调用关系图。

perf-tools

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

参考资料