ftrace是Linux内核中的一种跟踪工具，用于分析和调试内核和应用程序的性能问题。它可以帮助开发人员跟踪函数调用、系统调用、中断事件、定时器事件等各种事件，并生成相应的跟踪数据。
ftrace 最常见的用途之一是事件跟踪。整个内核中有数百个静态事件点，可以通过 Tracefs 文件系统启用这些事件点，以查看内核某些部分发生的情况。
通过分析这些数据，开发人员可以了解代码执行路径、函数耗时、资源使用情况等信息，从而进行性能优化或故障排查。ftrace提供了多个功能组件，如函数图谱（function graph）、事件追踪（event tracing）和动态追踪（dynamic tracing），使得它在不同场景下都有广泛的应用价值。
ftrace功能 ：帮助了解Linux内核的运行时行为，可以查看系统调用情况，以及某个函数的调用流程。2.6内核之后引入内核的。以便进行故障调试或性能分析。
Ftrace 跟踪工具由性能分析器（profiler）和跟踪器（tracer）两部分组成
性能分析器：用来提供统计和直方图数据（需要 CONFIG_ FUNCTION_PROFILER=y）
函数性能分析
直方图
跟踪器：提供跟踪事件的详情
函数跟踪（function）
点跟踪（tracepoint）
kprobe
uprobe
函数调用关系（function_graph）
hwlat等
ftrace构成
(1)提供函数钩子的基础设施；
(2)基于tracefs文件系统的trace框架；
除了原生操作，还有一些基于ftrace的前端工具，比如perf-tools和trace-cmd，关系图如下：
Ftrace能做什么
Ftrace 可用来快速排查以下相关问题：
特定内核函数调用的频次 （function）
内核函数在被调用的过程中路径（调用栈） （function + stack）
内核函数调用的子函数流程（子调用栈）（function graph）
由于抢占导致的高延时路径等
1）内核支持ftrace
想让内核支持 ftrace 功能，需要将其编译进入内核，需要打开内核配置项：
kernel hacking ----> Tracers （执行make menuconfig）
目的：选择开启相应的追踪器功能
ftrace 通过 debugfs 向用户态提供了访问接口，所以还需要将 debugfs 编译进内核。激活对 debugfs 的支持，可以直接编辑内核配置文件 .config ，设置 CONFIG_DEBUG_FS=y
2）挂载debugfs文件系统
3）ftrace用户层接口
ftrace的目录：/sys/kernel/debug/tracing/ ，常用文件介绍：
tracing_on，启用/禁用向追踪缓冲区写入功能。1为启用，0为禁用。
trace，以文本格式输出内核中追踪缓冲区的内容，是查看trace日志的接口。
current_tracer，通过该接口指定当前ftrace要使用的tracer，也就是要追踪的函数/时间。
available_tracers，当前内核中可用的插件追踪器。
tracing_cpumask，以十六进制的位掩码指定要作为追踪对象的处理器，例如，指定0xb时仅在处理器0、1、3上进行追踪。
dynamic tracing，动态trace进行过滤的接口，是需要在编译时支持该功能，需要打开对应的宏开关：
set_ftrace_pid，指定作为追踪对象的进程的PID号。
trace_pipe，与trace相同，但是运行时像管道一样，可以在每次事件发生时读出追踪信息，但是读出的内容不能再次读出。
buffer_size_kb，以KB为单位指定各个CPU追踪缓冲区的大小。系统追踪缓冲区的总大小就是这个值乘以CPU的数量。设置buffer_size_kb时，必须设置current_tracer为nop追踪器。
set_ftrace_filter，指定要追踪的函数名称，函数名称仅可以包含一个通配符。
set_ftrace_notrace，指定不要追踪的函数名称。
4）ftrace的插件追踪器
function，函数调用追踪器，可以看出哪个函数何时调用。
function_graph，函数调用图表追踪器，可以看出哪个函数被哪个函数调用，何时返回。
mmiotrace，MMIO( Memory MappedI/O)追踪器，用于Nouveau驱动程序等逆向工程。
blk，block I/O追踪器。
wakeup，进程调度延迟追踪器。
wakeup_rt，与wakeup相同，但以实时进程为对象。
irqsoff，当中断被禁止时，系统无法响应外部事件，造成系统响应延迟，irqsoff跟踪并记录内核中哪些函数禁止了中断，对于其中禁止中断时间最长的，irqsoff将在log文件的第一行标示出来，从而可以迅速定位造成系统响应延迟的原因。
preemptoff，追踪并记录禁止内核抢占的函数，并清晰显示出禁止内核抢占时间最长的函数。
preemptirqsoff，追踪并记录禁止内核抢占和中断时间最长的函数
sched_switch，进行上下文切换的追踪，可以得知从哪个进程切换到了哪个进程。
nop，不执行任何操作。不使用插件追踪器时指定。
5）使用ftrace：分为三步
设置tracer类型
设置tracer参数
使能tracer
function trace函数调用追踪器，跟踪函数调用。默认追踪所有函数，通过设置set_ftrace_filter 来跟踪过滤函数，可以看出哪个函数何时调用
vailable_filter_functions：列出当前可以跟踪的内核函数，不在该文件中列出的函数，无法跟踪其活动
enabled_functions：显示有回调附着的函数名称。
function_profile_enabled：打开此选项，在trace_stat中就会显示function的统计信息。
set_ftrace_filter：用于指定跟踪的函数
set_ftrace_notrace：用于指定不跟踪的函数
set_ftrace_pid：用于指定要跟踪特定进程的函数
使用：echo 0 > tracing_on 清空之前的trace记录
echo function > current_tracer 设置tracer类型为function
echo xxxxxx > set_ftrace_filter 过滤要跟踪的函数，对其进行跟踪
echo 1 > tracing_on 收集调用信息
cat trace 查看对跟踪函数的调用信息
wakeup tracer 追踪普通进程从唤醒到真正得到执行之间的延迟
使用：echo wakeup > current_tracer
echo 1 > tracing_on
cat trace | hrad -40
wakeup_rt tracerfunction_graphtrace 可以提供类似 C 代码的函数调用关系信息，通过写文件 set_graph_function可以显示指定要生成调用关系的函数，缺省会对所有可追踪的内核函数生成函数调用关系图
函数图追踪器对函数的进入和退出进行跟踪，有利于观察函数的执行时间,确定代码执行流程。
使用：echo 0 > trace
echo function_graph > current_tracer 设置 tracer 类型
echo xxxxxx > set_graph_function 设置要追踪的函数
echo 1 > tracing_ontrace event实现低性能损耗，对执行流无影响的一种信息输出机制
使用：在 events 目录下有很多的event事件，可以看一下sched事件，sched目录下还有很多具体的事件，
打开sched_wakeup事件下，有：enable、filter、format、hist、id、trigger
enable：使能这个事件
filter：
查看函数调用栈：
常用方法：函数内部添加 WARN_ON(1) 、ftrace
在trace函数的时候，设置 echo 1 > options/func_stack_trace 即可在 trace 结果中获取追踪函数的调用栈
使用：echo 0 > tracing_on
echo function _ current_tracer
echo schedule > set_ftrace_filter
echo 1 > options/func_stack_trace
echo 1 > tracing_on
跟踪一个命令，但是命令执行时间很短6）前端工具
使用ftrace功能进行二次封装一些命令来操作，trace-cmd 就是ftrace封装命令的其中一种。
该软件包由两部分组成：
trace-cmd：提供数据抓取和数据分析的功能
kernelshark：用图形化的方式来详细分析数据，也可以做数据抓取
【文章福利】小编推荐自己的Linux内核技术交流群:【865977150】整理了一些个人觉得比较好的学习书籍、视频资料共享在群文件里面，有需要的可以自行添加哦！！！
1）整体流程
kernel：会有很多的桩点，function trace/trace event，每个桩点都在想要被trace的函数里边，如果某个被trace的函数桩点触发，如果该函数的桩点是使能的就会传到之前注册好 tracers 里这个回调函数中，把现场的日志写到ring buffer 里边。
而tracers 都是由ftrace 这个框架来管理的，每个tracer 都由ftrace 框架来注册。ftrace框架的功能一个是管理 tracers ，再一个是当接收到 用户态使能某个函数/event的命令，会动态修改内核的某个函数，使其使能起来。ring buffer的功能是一个 接收tracers的写入，再一个是用户通过debugfs读取ring buffer的内容。
2）以function为例进行插桩
函数插桩，利用gcc -pg选项，在每个函数入口附近插入 mconut 调用，对桩点进行管理scripts/recordmcount.c
在内核编译时，每编译完成一个.c文件，调用recordmcount：对生成的每一个 .o 文件都进行重定位，找到mcount调用的地址，先放在临时缓冲区，等recordmcount找到每个 .o文件的mcount地址后，新增一个_mcount_loc 段，并将 mcount 调用地址写到这个段中。
include/asm-generic/vmlinux.lds.h
通过 vmlinux.lds.h 这个连接脚本，将 .o 中的每个mcount进行收集，在连接脚本中定义变量：
_start_mcount_loc
_stop_mcount_loc将所有的 mcount_loc 放在 start 、stop之间，最后通过这两个变量获取中间数据
收集好这些插桩点之后，在内核初始化阶段，通过start、stop这两个变量，遍历将所有的都替换成 nop
上述是在不使能的情况下对 mcount进行的管理，接下来就需要使能某个tracer：需要考虑：首先需要知道这个函数插桩点的位置，记录某个tarce点的状态，就需建立新的控制结构
struct dyn_ ftrace {
unsigned long ip; /* address of mcount call-site */
unsigned long flags ;
struct dyn_ arch
ftrace arch;
};ip：对应的bl那个地址，可以理解成一个ip 就对应一个函数
flags：当前插桩点的状态
arch：这个在当前架构下基本上为空
通过ftrace_pages 来保存dyn_ftrace 数据（ftrace_pages的大小是根据所有的 dyn_ftrace 来分配的）
在将 _ mcount_loc 数据迁移到ftrace_pages后，将其释放
ftrace_pages中数据是有序的，便于查找（根据ip进行排序）
通过dmesg可以看到ftrace_pages 占用的内存
在ftrace_pages填好内容之后，mcount_loc释放，
在用户层 执行 ：cat available_filter_functions ,可以看到插桩的函数，这个就是通过ftrace_pages来打印的
dyn_ftrace flag：分成两部分：
在dyn_ftrace中的flag，会置位，通过
根据每个ip对应的flag，给内核函数选择不同的 bl 指令。
接下来是 ftrace_enter 的工作方式，eg：fatrace_caller的实现：当使能 ftrace的时候的过程如下：
首先：mcount_enter 进行压栈。
3）注册回调函数
调用 register_ftrace_function() 注册
提供 ftrace_ops
Static ftrace_ops
function
function graph
blk
kprobe
dynamic ftrace_ops
perf通过下面的数据结构进行回调函数的注册， private 保存 ring buffer的数据内容
到了ftrace_caller这一步时，还没有注册对应的回调函数，通过公共的一个函数 ftrace_ops_list_func() ，在该函数内部会迭代的遍历注册到ftrace 框架中的 ftrace_ops ，这些如果这些ops想对对应的函数进行trace，就会调用注册的回调函数，perf的话只是想trace 当前的函数，而 function tracer的话需要trace所有的函数
4）原理
本质上是一种静态代码插装技术，不需要支持某种编程接口让用户自定义 trace行为。静态代码插装技术更加可靠，不会因为用户的不当使用而导致内核崩溃。 ftrace 代码量很小，稳定可靠。实际上，即使是Dtrace，大多数用户也只使用其静态 trace 功能。因此 ftrace 的设计非常务实。
ftrace依赖的内核特性：tracepoint[3]，debugfs[2]，kprobe[4]，IRQ-Flags[5]
ftrace由两部分组成：framework、一系列的tracer
framework利用debugfs建立tracing目录，并提供一系列的控制文件。一系列的tarcer由framework管理，ftrace的trace信息保存在ring buffer中，也由framework管理。
function默认会记录当前运行过程中的所有函数;
如果只想跟踪某个进程，可以使用set_ftrace_pid;
如果只想跟踪某个函数，可以使用set_ftrace_filter；
(0)关闭tracer
echo 0 > tracing_on
#清空打印
echo > trace(1)设置类型：设current_tracer 类型为 function
echo blk_update_request > set_ftrace_filter设置不跟踪指定函数；
echo > set_ftrace_filter
echo blk_update_request > set_ftrace_notrace还可以用通配符"
#'*match*':匹配所有包含match的函数；
echo 'hrtimer_*' >> set_ftrace_filter #过滤所有以"hrtimer_"开头的函数还可以做基于模块的过滤：例如，过滤 ext4 module 的 write* 函数
#控制范式：<function>:<command>:<parameter>
echo 'write*:mod:ext4' > set_ftrace_filter感叹号用来移除某个函数，把多个组合过滤条件的某一个去掉：
echo '!ip_rcv' >> set_ftrace_filter遇到 __schedule_bug 函数后关闭 trace
# echo '__schedule_bug:traceoff' > set_ftrace_filter(3)打开trace开关，开始 trace
# echo 1 > tracing_on(4)提取trace结果
[root@myQEMU tracing]# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 6/6 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<idle>-0 [001] ..s. 229.298724: blk_update_request <-blk_mq_end_request
<idle>-0 [001] ..s. 229.316890: blk_update_request <-blk_mq_end_request
<idle>-0 [001] ..s. 229.317916: blk_update_request <-blk_mq_end_request
<idle>-0 [001] ..s. 229.325217: blk_update_request <-blk_mq_end_request
<idle>-0 [001] d.s. 229.325280: blk_update_request <-blk_mq_end_request
sync-620 [001] ..s. 229.330068: blk_update_request <-blk_mq_end_request
[root@myQEMU tracing]# 从 trace 信息我们可以获取很多重要信息：
进程信息，TASK-PID
进程运行的 CPU
执行函数时的系统状态，包括中断，抢占等状态信息
执行函数的时间戳
function_graph使用方法和function类似，但可以更清晰的展示函数调用关系；
开启堆栈调用:可以跟踪函数被调用流程
[root@myQEMU tracing]# echo 1 > options/func_stack_trace
[root@myQEMU tracing]# cat /cpu.info
[root@myQEMU tracing]# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 18/18 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
cat-646 [000] ..s. 548.454890: blk_update_request <-blk_mq_end_request
cat-646 [000] ..s. 548.454915: <stack trace>
=> blk_update_request
=> blk_mq_end_request
=> virtblk_request_done
=> blk_complete_reqs
=> blk_done_softirq
=> __do_softirq
=> irq_exit
=> __handle_domain_irq
=> gic_handle_irq
=> el1_irq
=> get_page_from_freelist
=> __alloc_pages
=> page_cache_ra_unbounded
=> do_page_cache_ra
=> filemap_fault
=> ext4_filemap_fault
=> __do_fault
=> __handle_mm_fault
=> handle_mm_fault
=> do_page_fault
=> do_translation_fault
=> do_mem_abort
=> el0_ia
=> el0_sync_handler
=> el0_sync使用方法和function类似，但可以更清晰的展示函数调用关系；
开启堆栈调用,可以查看函数调用子函数堆栈
echo blk_update_request > set_graph_function
echo function_graph > current_tracer
echo 1 > options/func_stack_trace
echo 1 > tracing_on
cat /cpu.info 查看trace
[root@myQEMU home]# cat /tracing/trace
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) + 24.368 us | start_backtrace();
0) 4.336 us | start_backtrace();
0) | blk_update_request() {
0) 3.200 us | start_backtrace();
0) 3.152 us | start_backtrace();
0) + 68.576 us | }
0) | blk_update_request() {
0) 4.192 us | bio_advance();
0) | bio_endio() {
0) | submit_bio_wait_endio() {
0) | complete() {
0) | swake_up_locked() {
0) | swake_up_locked.part.0() {
0) | wake_up_process() {
0) | try_to_wake_up() {
0) | select_task_rq_fair() {
0) 3.808 us | available_idle_cpu();
0) 3.856 us | rcu_read_unlock_strict();
0) + 23.696 us | }
0) 3.968 us | ttwu_queue_wakelist();
0) 4.960 us | update_rq_clock.part.0();
0) | ttwu_do_activate.isra.0() {
0) | enqueue_task_fair() {
0) | update_curr() {
0) 4.064 us | __calc_delta();
0) 4.080 us | update_min_vruntime();
0) 4.192 us | rcu_read_unlock_strict();
0) + 31.056 us | }
0) 5.104 us | __update_load_avg_se();
0) | __update_load_avg_cfs_rq() {
0) 4.208 us | __accumulate_pelt_segments();
0) + 13.840 us | }
0) 4.544 us | __enqueue_entity();
0) + 77.328 us | }
0) | ttwu_do_wakeup.isra.0() {
0) | check_preempt_curr() {
0) | check_preempt_wakeup() {
0) 4.688 us | update_curr();
0) 4.640 us | wakeup_preempt_entity.isra.0();
0) + 23.616 us | }
0) + 32.976 us | }
0) + 50.688 us | }
0) ! 141.648 us | }
0) ! 198.064 us | }
0) ! 206.528 us | }
0) ! 215.072 us | }
0) ! 223.376 us | }
0) ! 232.320 us | }
0) ! 240.960 us | }
0) ! 250.400 us | }
0) ! 269.840 us | }
[root@myQEMU tracing]# 小技巧：用vim插件Documentation/trace/function-graph-fold.vim 打开，可以方便折叠函数方便查看，za(展开)/zc（折叠）
vim ft_graph.log -S Documentation/trace/function-graph-fold.vim
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) + 24.368 us | start_backtrace();
0) 4.336 us | start_backtrace();
+ 0) | blk_update_request() {----------------------------------------------------------------------------------------------------
- 0) | blk_update_request() {
| 0) 4.192 us | bio_advance();
|- 0) | bio_endio() {
||- 0) | submit_bio_wait_endio() {
|||- 0) | complete() {
||||+ 0) | swake_up_locked() {-----------------------------------------------------------------------------------------------
|||| 0) ! 232.320 us | }
||| 0) ! 240.960 us | }
|| 0) ! 250.400 us | }
| 0) ! 269.840 us | }Ftrace的跟踪机制主要有两种：函数和tracepoint。
函数，案例1已经做了介绍；tracepoint，可以理解为linux内核的占位符号，tracepoint可以输出开发者想要的参数，局部变量等。类似于C语言的#if DEBUG部分，不开启的话，不占用任何系统开销；
内核里常遇到以"trace_"开头的函数，比如CFS调度器里de update_curr()函数
static void update_curr(struct cfs_rq *cfs_rq)
{
...
update_min_vruntime(cfs_rq);
if (entity_is_task(curr)) {
struct task_struct *curtask = task_of(curr);
trace_sched_stat_runtime(curtask, delta_exec, curr->vruntime);
}
...
}update_curr()函数使用了一个sched_stat_runtime的tracepoint, 可以在available_events看到；
查询系统支持的事件：
cat available_events |grep sched_stat_runtime
sched:sched_stat_runtime操作过程：
echo 0 > tracing_on
echo > trace
echo sched:sched_stat_runtime > set_event
echo 1 > tracing_on
#或者直接进入时间目录，等价操作：
cd /tracing/events/sched/sched_switch
echo 1 enable
cat /tracing/trace格式解析：
[root@myQEMU sched_stat_runtime]# cat format
name: sched_stat_runtime
ID: 208
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:char comm[16]; offset:8; size:16; signed:0;
field:pid_t pid; offset:24; size:4; signed:1;
field:u64 runtime; offset:32; size:8; signed:0;
field:u64 vruntime; offset:40; size:8; signed:0;
print fmt: "comm=%s pid=%d runtime=%Lu [ns] vruntime=%Lu [ns]", REC->comm, REC->pid, (unsigned long long)REC->runtime, (unsigned long long)REC->vruntime
[root@myQEMU sched_stat_runtime]# sched_stat_runtime这个tracepoint有八个域，前4个是通用域，后4个是tracepoint支持域；
cd events/sched/sched_stat_runtime
echo 'comm ~ "sh*"' > filter ///跟踪所有sh开头的进程
130 echo 'pid == 2288' >> filter ///跟踪PID=2288的进程支持类似C语言的表达式对时间进行过滤。
[root@myQEMU tracing]# cat trace
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) | /* sched_stat_runtime: comm=sh pid=2288 runtime=3255632 [ns] vruntime=110771356247804 [ns] */
0) | /* sched_stat_runtime: comm=sh pid=2288 runtime=307728 [ns] vruntime=110771356555532 [ns] */
0) | /* sched_stat_runtime: comm=sh pid=2288 runtime=359392 [ns] vruntime=110771356914924 [ns] */
0) | /* sched_stat_runtime: comm=sh pid=2288 runtime=635824 [ns] vruntime=110771357550748 [ns] */
0) | /* sched_stat_runtime: comm=sh pid=2288 runtime=976800 [ns] vruntime=110771358527548 [ns] */
0) | /* sched_stat_runtime: comm=sh pid=2288 runtime=681568 [ns] vruntime=110771359209116 [ns] */
0) | /* sched_stat_runtime: comm=sh pid=2288 runtime=896000 [ns] vruntime=110771360105116 [ns] */
0) | /* sched_stat_runtime: comm=sh pid=2288 runtime=652272 [ns] vruntime=110771360757388 [ns] */
0) | /* sched_stat_runtime: comm=sh pid=2288 runtime=795152 [ns] vruntime=110771361552540 [ns] */
0) | /* sched_stat_runtime: comm=sh pid=2288 runtime=739952 [ns] vruntime=110771362292492 [ns] */
0) | /* sched_stat_runtime: comm=sh pid=2288 runtime=812624 [ns] vruntime=110771363105116 [ns] */
0) 添加一个事件
内核各个子系统已经有大量的tracepoint，如果不够，还可以手工添加一个；
在include/trace/events/sched.h添加一个sched_stat_my_runtime的tracepoint内核提供了宏来方便添加；
DECLARE_EVENT_CLASS(sched_stat_my_runtime,
TP_PROTO(struct task_struct *tsk, u64 vruntime),
TP_ARGS(tsk, vruntime),
TP_STRUCT__entry(
__array( char, comm, TASK_COMM_LEN )
__field( pid_t, pid )
__field( u64, vruntime )
),
TP_fast_assign(
memcpy(__entry->comm, tsk->comm, TASK_COMM_LEN);
__entry->pid = tsk->pid;
__entry->vruntime = vruntime;
),
TP_printk("comm=%s pid=%d minvruntime=%Lu [ns]",
__entry->comm, __entry->pid,
(unsigned long long)__entry->vruntime)
);
DEFINE_EVENT(sched_stat_my_runtime, sched_stat_my_runtime,
TP_PROTO(struct task_struct *tsk, u64 vruntime),
TP_ARGS(tsk, vruntime));
[USER@HOSTNAME tracing]# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 239/239 #P:1
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
sh-2287 [000] d... 263.524575: sched_stat_my_runtime: comm=sh pid=2287 minvruntime=5762812735127 [ns]
rcu_sched-11 [000] d... 263.526249: sched_stat_my_runtime: comm=rcu_sched pid=11 minvruntime=5762812735127 [ns]
rcu_sched-11 [000] d... 263.530214: sched_stat_my_runtime: comm=rcu_sched pid=11 minvruntime=5762812735127 [ns]
kworker/0:1-18 [000] d... 263.978131: sched_stat_my_runtime: comm=kworker/0:1 pid=18 minvruntime=5762812735127 [ns]
kcompactd0-287 [000] d... 264.010218: sched_stat_my_runtime: comm=kcompactd0 pid=287 minvruntime=5762812735127 [ns]
kworker/u2:4-255 [000] d... 264.313158: sched_stat_my_runtime: comm=kworker/u2:4 pid=255 minvruntime=5762812735127 [ns]
kworker/u2:4-255 [000] d... 264.313242: sched_stat_my_runtime: comm=kworker/u2:4 pid=255 minvruntime=5762812735127 [ns]
sh-2287 [000] d.h. 264.313821: sched_stat_my_runtime: comm=sh pid=2287 minvruntime=5762813304551 [ns]
sh-2287 [000] d... 264.314023: sched_stat_my_runtime: comm=sh pid=2287 minvruntime=5762813514503 [ns]
kworker/u2:4-255 [000] d... 264.393391: sched_stat_my_runtime: comm=kworker/u2:4 pid=255 minvruntime=5762813514503 [ns]除了DEFINE_EVENT，还可以使用DEFINE_EVENT_CONDITION()定义一个带条件的tracepoint.
如果要定义多个格式相同的tracepoint，可以用DEFINE_EVENT_CLASS()减少代码量；
注：内核提供了一个tracepoint的例子，samples/trace_events/目录中；可以配置CONFIG_samples,CONFIG_SAMPLE_TRACE_EVENTS，编译成模块，加载测试；
当关闭中断时，CPU不能响应外部事件，如果此时有中断发生，只能在下一次开中断时，才能响应这个外部事件，这段延迟叫“中断延迟”。
ftrace提供irqsoff来跟踪这个延迟；
[root@myQEMU tracing]# echo 0 tracing_on
0 tracing_on
[root@myQEMU tracing]# echo 0 > trace
[root@myQEMU tracing]# echo 0 options/func-trace ///关闭function-trace可以减少一些延迟
0 options/func-trace
[root@myQEMU tracing]# echo irqsoff > current_tracer
[root@myQEMU tracing]# echo 1 > tracing_on
[root@myQEMU tracing]# echo 0 > tracing_on 跟踪结果：
[root@myQEMU tracing]# cat trace
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 5.13.0-rc3+
# --------------------------------------------------------------------
# latency: 2111 us, #158/158, CPU#0 | (M:server VP:0, KP:0, SP:0 HP:0 #P:1)
# -----------------
# | task: sh-2287 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: n_tty_write
# => ended at: n_tty_write
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
sh-2287 0d... 2us+: uart_write <-n_tty_write
sh-2287 0d... 14us+: start_backtrace <-return_address
sh-2287 0d... 31us+: __uart_start.isra.0 <-uart_write
sh-2287 0d... 45us+: pl011_start_tx <-__uart_start.isra.0
sh-2287 0d... 57us+: pl011_tx_chars <-pl011_start_tx
sh-2287 0d... 70us+: pl011_tx_char <-pl011_tx_chars
sh-2287 0d... 83us+: pl011_read <-pl011_tx_char
...
sh-2287 0d... 1843us+: pl011_read <-pl011_tx_char
sh-2287 0d... 1861us : pl011_tx_char <-pl011_tx_chars
sh-2287 0d... 1869us+: pl011_read <-pl011_tx_char
sh-2287 0d... 1889us : uart_write_wakeup <-pl011_tx_chars
sh-2287 0d... 1899us : tty_port_tty_wakeup <-uart_write_wakeup
sh-2287 0d... 1908us : tty_port_default_wakeup <-tty_port_tty_wakeup
sh-2287 0d... 1918us+: tty_port_tty_get <-tty_port_default_wakeup
sh-2287 0d... 1983us+: tty_wakeup <-tty_port_default_wakeup
sh-2287 0d... 1994us : __wake_up <-tty_wakeup
sh-2287 0d... 2004us : __wake_up_common_lock <-__wake_up
sh-2287 0d... 2014us : __wake_up_common <-__wake_up_common_lock
sh-2287 0d... 2024us : woken_wake_function <-__wake_up_common
sh-2287 0d... 2034us : default_wake_function <-woken_wake_function
sh-2287 0d... 2044us+: try_to_wake_up <-default_wake_function
sh-2287 0d... 2060us+: tty_kref_put <-tty_port_default_wakeup
sh-2287 0d... 2075us+: start_backtrace <-return_address
sh-2287 0d... 2090us+: start_backtrace <-return_address
sh-2287 0d... 2102us+: uart_write <-n_tty_write
sh-2287 0d... 2115us+: tracer_hardirqs_on <-n_tty_write
sh-2287 0d... 2179us : <stack trace>
=> n_tty_write
=> file_tty_write.isra.0
=> redirected_tty_write
=> new_sync_write
=> vfs_write
=> ksys_write
=> __arm64_sys_write
=> invoke_syscall.constprop.0
=> do_el0_svc
=> el0_svc
=> el0_sync_handler
=> el0_sync每个参数的实际意义，参考官网： https://www.kernel.org/doc/html/latest/trace/ftrace.html
trace_marker是一个文件节点，允许用户写入字符串，ftrace会记录写入动作的时间戳；
(1)由于trace_marker是写内存，速度很快，避免串口的长耗时；
(2)可以配合内核的event，跟踪两个trace marker之间，内核的运行状况；
这个可以用来跟踪分析应用程序；
测试代码：
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <time.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <sys/time.h>
#include <sys/unistd.h>
#include <stdarg.h>
#include <unistd.h>
#include <ctype.h>
#include <signal.h>
static int mark_fd = 1;
static __thread char buff[BUFSIZ+1];
static void setup_ftrace_marker(void)
{
struct stat st;
char *files[]={
"/sys/kernel/debug/tracing/trace_marker",
"/debug/tracing/trace_marker",
"/debugfs/tracing/trace_marker",
};
int ret;
int i=0;
for(i=0; i < (sizeof(files)/sizeof(char*));i++) {
ret = stat(files[i], &st);
if (ret >=0) {
break;
}
}
if (ret >= 0) {
mark_fd = open(files[i], O_WRONLY);
printf("cannot found the sys tracing.\n");
}
return 0;
}
static void ftrace_write(const char *fmt, ...)
{
va_list ap;
int n;
if (mark_fd < 0)
return ;
va_start(ap, fmt);
n = vsnprintf(buff, BUFSIZ, fmt, ap);
va_end(ap);
write(mark_fd, buff, n);
}
void sig_handler()
{
printf("Oops! will exit...\n");
if (mark_fd >= 0) {
close(mark_fd);
}
_exit(0);
}
int main()
{
printf("hello\n");
int count = 0;
signal(SIGINT,sig_handler);
setup_ftrace_marker();
ftrace_write("start program.\n");
while(1) {
usleep(300*1000);
count++;
ftrace_write("===test count=%d\n",count);
}
return 0;
}执行跟踪：
echo 0 > tracing_on
echo 0 > trace
echo 1 > tracing_on
/mnt/a.out
echo 0 > tracing_on
cat trace查看trace记录
[root@myQEMU tracing]# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 33/33 #P:1
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
rb_producer-428 [000] .... 125.274713: ring_buffer_producer_thread: Starting ring buffer hammer
a.out-2291 [000] .... 125.361620: tracing_mark_write: start program.
a.out-2291 [000] .... 125.667714: tracing_mark_write: ===test count=1
a.out-2291 [000] .... 125.970099: tracing_mark_write: ===test count=2
a.out-2291 [000] .... 126.280010: tracing_mark_write: ===test count=3
a.out-2291 [000] .... 126.584222: tracing_mark_write: ===test count=4
a.out-2291 [000] .... 126.886110: tracing_mark_write: ===test count=5
a.out-2291 [000] .... 127.195146: tracing_mark_write: ===test count=6
a.out-2291 [000] .... 127.498109: tracing_mark_write: ===test count=7
a.out-2291 [000] .... 127.802138: tracing_mark_write: ===test count=8
a.out-2291 [000] .... 128.112389: tracing_mark_write: ===test count=9
a.out-2291 [000] .... 128.414082: tracing_mark_write: ===test count=10PS:实际上android的atrace和Trace类，就是基于trace marker实现的；
追踪普通进程从被唤醒到真正得到执行之间的延迟。
echo wakeup > current_tracer
echo 1 > tracing_on
cat trace |head -40跟踪rt进程，从被唤醒到执行的延迟；
echo 0 > tracing_on
echo > trace
echo wakeup_rt > current_tracer
echo 1 > tracing_on
cat trace |head -40当然也可以用脚本来执行这些过程，结果保存到文本：
#!/bin/sh
TRACE_PATH=/sys/kernel/debug/tracing
echo nop > $TRACE_PATH/current_tracer
echo 0 >$TRACE_PATH/tracing_on
echo >$TRACE_PATH/trace
echo 0 > $TRACE_PATH/max_graph_depth
echo $$
#echo $$ > $TRACE_PATH/set_ftrace_pid
echo function_graph > $TRACE_PATH/current_tracer
echo 'blk_update_request' > $TRACE_PATH/set_graph_function
echo 1 > options/func_stack_trace
echo 1 > $TRACE_PATH/tracing_on
exec "$@"实用案例：跟踪某个进程的相关函数
实际调试：如果能把环形队列的数据，写入磁盘，供后续分析，更有现实意义；通过脚本实现？
案例：跟踪指定进程函数调用
#!/bin/bash
debugfs=/sys/kernel/debug
echo nop > $debugfs/tracing/current_tracer
echo 0 > $debugfs/tracing/tracing_on
echo `pidof a.out` > $debugfs/tracing/set_ftrace_pid
echo function_graph > $debugfs/tracing/current_tracer
echo vfs_read > $debugfs/tracing/set_graph_function
echo 1 > $debugfs/tracing/tracing_on案例：当内核log打印输出"min_adj 0"时，保存ftrace信息和kernel log信息到指定目录中
#!/bin/sh
mkdir -p /data/
echo 8 > /proc/sys/kernel/printk
echo -1000 > /proc/self/oom_score_adj
cd /sys/kernel/debug/tracing
echo 0 > trcing_on
echo 0 > trace
echo 1 > /sys/kernel/debug/tracing/events/oom/oom_score_adj_update/enable
echo 1 > /sys/kernel/debug/tracing/events/vmscan/mm_shrink_slab_start/enable
echo 1 > /sys/kernel/debug/tracing/events/vmscan/mm_shrink_slab_end/enable
#开始采集
echo 1 > tracing_on
TIMES=0
while true
do
dmesg |grep "min_adj 0"
if [ $? -eq 0]
then
cat /sys/kernel/debug/tracing/trace > /data/ftrace_.$TIMES
dmesg > /data/kmsg.txt.$TIMES
let TIMES+=1
dmesg -cat
echo > trace
fi
sleep 2
donetrace_cmd和kernelshark
这一组工具，实际上是将上面ftrace的过程，采集记录下来数据，然后图形展示，提供更直观的分析；
trace_cmd,使用遵循reset->record->stop->report模式，简单说用trace_cmd record采集数据，按"ctrl+c"停止采集，在当前目录生成trace.dat文件；用trace-cmd report可以解析trace.dat文件，不过是文字形式的。
下载编译trace-cmd：
git clone https://github.com/rostedt/trace-cmd.git
export CROSS_COMPILE=aarch64-linux-gnu-
export ARCH=arm64
makekernelshark，可以将trace.dat文件图形化，方便观察和分析；
联系客服
