[置顶] 泰晓 RISC-V 实验箱,配套 30+ 讲嵌入式 Linux 系统开发公开课
[置顶] Linux Lab v1.4 升级部分内核到 v6.10,新增泰晓 RISC-V 实验箱支持,新增最小化内核配置支持大幅提升内核编译速度,在单终端内新增多窗口调试功能等Linux Lab 发布 v1.4 正式版,升级部分内核到 v6.10,新增泰晓实验箱支持
[置顶] 泰晓社区近日发布了一款儿童益智版 Linux 系统盘,集成了数十个教育类与益智游戏类开源软件国内首个儿童 Linux 系统来了,既可打字编程学习数理化,还能下棋研究数独提升智力
Ftrace 基本用法
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元 | 微信打赏 | |
请作者喝杯咖啡吧 |