[置顶] 泰晓 RISC-V 实验箱，配套 30+ 讲嵌入式 Linux 系统开发公开课
Ftrace 基本用法
Liu Lichao 创作于 2021/02/24
By 法海 of [TinyLab.org][1] Jan 16, 2021
前言
计划撰写 Ftrace 系列文章，会描述 Ftrace 基本用法，进阶用法，trace-cmd 等前端工具。
本文是 Ftrace 系统文章第一篇: Ftrace 基本用法。
概述
Ftrace 是内核自带的调试工具，从久远的 2.6 内核就支持了，可以辅助定位内核问题。
从名字来看，ftrace = function trace，表示可以进行函数级 trace，随着发展，Ftrace 已经进化成通用的调试框架，可以实现多种 trace 目的。
根据官方文档，目前支持的 trace 类型：
- function
- function_graph
- blk
- hwlat
- irqsoff
- preemptoff
- preemptirqsoff
- wakeup
- wakeup_rt
- wakeup_dl
- mmiotrace
- branch
- nop
具体每个 trace 类型是做什么的，可以查询 官方文档
Ftrace 最全面的学习文档还是官方文档。
Ftrace 基础用法
内核配置
几乎所有的发行版都自带 ftrace 支持，相关内核配置位于如下目录下:
-> Kernel hacking
-> Tracers
Ftrace 三板斧
- 设置 tracer 类型
- 设置 tracer 参数
- 使能 tracer
Function trace 实例
下面是跟踪 dev_attrs_show 函数所需要的所有命令，并且有注释。
进入 ftrace 工作目录：
# cd /sys/kernel/debug/tracing
查看系统支持的 tracer 类型：
# cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
Disable tracer：
# echo 0 > tracing_on
设置 tracer 类型为 function：
# echo function > current_tracer
set_ftrace_filter 表示要跟踪的函数，这里我们只跟踪 dev_attr_show 函数：
# echo dev_attr_show > set_ftrace_filter
Enable tracer：
# echo 1 > tracing_on
提取 trace 结果：
# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 3/3 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
thermald-961 [000] .... 345.540878: dev_attr_show <-sysfs_kf_seq_show
thermald-961 [000] .... 345.540905: dev_attr_show <-sysfs_kf_seq_show
thermald-961 [000] .... 345.540927: dev_attr_show <-sysfs_kf_seq_show
从上图可以看到 function trace 一个函数的方法基本就是三板斧：
- 设置 current_tracer 为 function
- 设置要 trace 的函数
- 打开 trace 开关，开始 trace
- 提取 trace 结果
从 trace 信息我们可以获取很多重要信息：
- 进程信息，TASK-PID
- 进程运行的 CPU
- 执行函数时的系统状态，包括中断，抢占等状态信息
- 执行函数的时间辍
function_graph Trace 实例
与 function tracer 类似，设置 function_graph 的方式如下：
# cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop
# echo function_graph > current_tracer
set_graph_function 表示要跟踪的函数
# echo dev_attr_show > set_graph_function
# echo 1 > tracing_on
捕捉到的 trace 内容：
# cat trace
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) | dev_attr_show() {
0) | energy_uj_show() {
0) | get_energy_counter [intel_rapl_common]() {
0) | cpus_read_lock() {
0) | _cond_resched() {
0) 0.283 us | rcu_all_qs();
0) 0.880 us | }
0) 1.521 us | }
0) | rapl_read_data_raw [intel_rapl_common]() {
0) | rapl_msr_read_raw [intel_rapl_msr]() {
0) | rdmsrl_safe_on_cpu() {
0) | rdmsr_safe_on_cpu() {
0) 0.271 us | __init_waitqueue_head();
0) | smp_call_function_single_async() {
0) | generic_exec_single() {
0) | __rdmsr_safe_on_cpu() {
0) | complete() {
0) 0.268 us | _raw_spin_lock_irqsave();
0) | __wake_up_locked() {
0) 0.298 us | __wake_up_common();
0) 0.836 us | }
0) 0.281 us | _raw_spin_unlock_irqrestore();
0) 2.476 us | }
0) 3.610 us | }
0) 4.315 us | }
0) 4.941 us | }
0) | wait_for_completion() {
0) | _cond_resched() {
0) 0.270 us | rcu_all_qs();
0) 0.800 us | }
0) 0.271 us | _raw_spin_lock_irq();
0) 1.920 us | }
0) 8.231 us | }
0) 8.824 us | }
0) 9.413 us | }
0) + 10.670 us | }
0) 0.269 us | cpus_read_unlock();
0) + 13.757 us | }
0) + 15.976 us | }
0) + 17.029 us | }
我们跟踪的是 dev_attr_show 函数，但是 function_graph tracer 会跟踪函数内的调用关系和函数执行时间，可以协助我们确定代码执行流程。比如一个函数内部执行了很多函数指针，不能确定到底执行的是什么函数，可以用 function_graph tracer 跟踪一下。
trace event 用法
trace event 简介
trace event 就是利用 ftrace 框架，实现低性能损耗，对执行流无影响的一种信息输出机制。相比 printk，trace event：
- 不开启没有性能损耗
- 开启后不影响代码流程
- 不需要重新编译内核即可获取 debug 信息
系统支持的所有 trace event 都位于 /sys/kernel/debug/tracing/events 目录。
使用实例
- 设置需要的 trace event
这里我们打开 sched_switch event。顾名思义，sched_switch 可以监控系统内进程切换事件。
# cd /sys/kernel/debug/tracing/events/sched/sched_switch
# echo 1 > enable
- 提取进程切换信息
下面的进程切换信息还是很直观的，看不懂的请私信。:)。
# echo 0 > trace
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 221/221 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<idle>-0 [003] d... 3408.075314: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=chrome next_pid=4737 next_prio=120
chrome-4737 [003] d... 3408.075465: sched_switch: prev_comm=chrome prev_pid=4737 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
<idle>-0 [003] d... 3408.100181: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=chrome next_pid=4737 next_prio=120
chrome-4737 [003] d... 3408.100333: sched_switch: prev_comm=chrome prev_pid=4737 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
<idle>-0 [003] d... 3408.125190: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=chrome next_pid=4737 next_prio=120
chrome-4737 [003] d... 3408.125339: sched_switch: prev_comm=chrome prev_pid=4737 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
<idle>-0 [003] d... 3408.150474: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=chrome next_pid=4737 next_prio=120
chrome-4737 [003] d... 3408.150680: sched_switch: prev_comm=chrome prev_pid=4737 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
<idle>-0 [003] d... 3408.175599: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=chrome next_pid=4737 next_prio=120
- 过滤信息
# cd /sys/kernel/debug/tracing/events/sched/sched_switch
# cat format
name: sched_switch
...
print fmt: "prev_comm=%s prev_pid=%d prev_prio=%d prev_state=%s%s ==> next_comm=%s next_pid=%d next_prio=%d", REC->prev_comm, REC->prev_pid, REC->prev_prio, (REC->prev_state & ((((0x0000 | 0x0001 | 0x0002 | 0x0004 | 0x0008 | 0x0010 | 0x0020 | 0x0040) + 1) << 1) - 1)) ? __print_flags(REC->prev_state & ((((0x0000 | 0x0001 | 0x0002 | 0x0004 | 0x0008 | 0x0010 | 0x0020 | 0x0040) + 1) << 1) - 1), "|", { 0x0001, "S" }, { 0x0002, "D" }, { 0x0004, "T" }, { 0x0008, "t" }, { 0x0010, "X" }, { 0x0020, "Z" }, { 0x0040, "P" }, { 0x0080, "I" }) : "R", REC->prev_state & (((0x0000 | 0x0001 | 0x0002 | 0x0004 | 0x0008 | 0x0010 | 0x0020 | 0x0040) + 1) << 1) ? "+" : "", REC->next_comm, REC->next_pid, REC->next_prio
从上面的 format 信息可以看出 sched_switch 打印的信息格式，基于上面提供的关键字可以实现信息过滤，比如下面的过滤命令可以只显示 chrome 进程的切换信息。
# cd /sys/kernel/debug/tracing/events/sched/sched_switch
# echo "prev_comm == 'chrome' || next_comm == 'chrome'" > filter
- 从捕捉信息中过滤
如果事先不知道要过滤什么信息，只能捕获全部信息，然后通过文本分析，过滤有效信息。比如，通过正则表达式过滤并提取每个进程的切换次数。
添加自己的 trace 信息
trace event
trace event 的添加是有固定范式的，就不贴具体代码了，具体可以参考
samples/trace_events实现自己的 trace event.trace_printk
trace_printk是一个函数，它的调用方式与printk一模一样，只是trace_printk输出信息到 trace 文件，而printk输出到终端或者其它的缓存 buffer 中。trace_printk延迟更短，几乎不影响原代码流程，而printk的延迟要大很多，且它的实现体系中也比trace_printk流程长，在中断、调度系统中调用printk几乎不可行。如果添加
printk后问题消失了，那么请试试trace_printk。
总结
通过简单的例子，看到了 function/function_graph tracer 的基本用法，但是在实际应用中会有比较棘手的问题和需求。比如：
- 某个函数被谁调用？调用栈是什么？
- 如何跟踪某个进程？如何跟踪一个命令，但是这个命令执行时间很短？
- 用户态的行为轨迹如何与内核中的 trace 联系到一起？
- 如何跟踪过滤多个进程？多个函数？
- 如何灵活控制 trace 的开关？
通过本篇文章先初步认识下 ftrace，下一篇文章会介绍上述问题。
猜你喜欢：
- 我要投稿：发表原创技术文章，收获福利、挚友与行业影响力
- 知识星球：独家 Linux 实战经验与技巧，订阅「Linux知识星球」
- 视频频道：泰晓学院，B 站，发布各类 Linux 视频课
- 开源小店：欢迎光临泰晓科技自营店，购物支持泰晓原创
- 技术交流：Linux 用户技术交流微信群，联系微信号：tinylab
| 支付宝打赏 ￥9.68元 | 微信打赏 | |
 |  请作者喝杯咖啡吧 |  |
