内核Ftrace使用案例

背景及简介

strace：用来跟踪 Linux 进程执行时的系统调用和接收所接收的信号，可以跟踪到一个进程产生的系统调用，包括参数，返回值，执行消耗的时间。
ftrace：是一个 Linux 内核函数跟踪器，function tracer，旨在帮助开发人员和系统设计者可以找到内核内部发生的事情，从 Linux-2.6 内核就支持了。
atrace：Android tracer，使用 ftrace 来跟踪 Android 上层的函数调用。
systrace：Android 的 trace 数据分析工具，将 atrace 采集上来的数据，以图形化的方式展现出来。systrace 是分析 Android 设备性能的主要工具。不过，它实际上是多种其他工具的封装容器：它是 atrace 的主机端封装容器。atrace 是用于控制用户空间跟踪和设置 ftrace 的设备端可执行文件，也是 Linux 内核中的主要跟踪机制。systrace 使用 atrace 来启用跟踪，然后读取 ftrace 缓冲区并将其全部封装到一个独立的 HTML 查看器中。
perfetto：新一代 systrace 分析工具，使用 perfetto 工具，可以通过 Android 调试桥 (ADB) 在 Android 设备上收集性能信息。perfetto 从您的设备上收集性能跟踪数据时会使用多种来源，例如：使用 ftrace 收集内核信息、使用 atrace 收集服务和应用中的用户空间注释、使用 heapprofd 收集服务和应用的本地内存使用情况信息。
在 Android 9 § 及以上版本平台都可用，但只有在 Android 11 ® 及以上的版本中才默认启用。在Android 9 § 和 10 (Q) 上，你需要执行下面的命令，以确保在一切开始之前跟踪服务正常启动：

# Needed only on Android 9 (P) and 10 (Q) on non-Pixel phones.
adb shell setprop persist.traced.enable 1

perfconv：CPU Freq 分析工具
LTR：Long Trace Recoder，可以录制长达半个小时的 trace，主要用于分析游戏场景。
因此，首先需要学习 ftrace，它是其他 trace 的基础。
在使用 ftrace 之前，需要确保内核配置编译了其配置选项。

#默认打开跟踪器，通过/boot/config_*文件查看
CONFIG_FTRACE=y
CONFIG_HAVE_FUNCTION_TRACER=y
CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y
CONFIG_HAVE_DYNAMIC_FTRACE=y
CONFIG_FUNCTION_TRACER=Y
CONFIG_IRQSOFF_TRACER=y
CONFIG_SCHED_TRACER=y
CONFIG_ENABLE_DEFAULT_TRACERS=y
CONFIG_FTRACE_SYSCALLS=y
CONFIG_PREEMPT_TRACER=y

而后在 /sys/kernel/debug/trace 目录下提供了各种跟踪器(tracer)和 event 事件，一些常用的选项如下。
(1).available_tracers：列出当前系统支持的跟踪器。
(2).available_events：列出当前系统支持的 event 事件。
(3).current_tracer：设置和显示当前正在使用的跟踪器。使用 echo 命令可以把跟踪器的名字写入该文件，即可以切换不同的跟踪器。默认为 nop，即不做任何跟踪操作。
(4).trace：读取跟踪信息。通过 cat 命令查看 ftrace 记录下来的跟踪信息。
(5).tracing_on：用于开始或暂停跟踪。
(6).trace_options：设置 ftrace 的一些相关选项。
ftrace 当前包含多个跟踪器，很方便用户用来跟踪不同类型的信息，例如进程睡眠唤醒、抢占延迟的信息。查看 available_tracers 可以知道当前系统支持哪些跟踪器，如果系统支持的跟踪器上没有用户想要的，那就必须在配置内核时自行打开，然后重新编译内核。常用的 ftrace 跟踪器如下。
(1).nop：不会跟踪任何内核活动，将 nop 写入 current_tracer 文件可以删除之前所使用的跟踪器，并清空之前收集到的跟踪信息，即刷新 trace 文件
(2).function：函数调用追踪器，可以看出哪个函数何时调用，可以通过过滤器指定要跟踪的函数。
(3).function_graph：函数调用图表追踪器，可以看出哪个函数被哪个函数调用，何时返回
(4).wakeup：跟踪进程唤醒信息，进程调度延迟追踪器(wakeup tracer追踪普通进程从被唤醒到真正得到执行之间的延迟,打开看看那些函数被跟踪)
(5).irqsoff：跟踪关闭中断信息，并记录关闭的最大时长。
(6).preemptoff：跟踪关闭禁止抢占信息，并记录关闭的最大时长。
(7).preemptirqsoff：综合了 irqoff 和 preemptoff 两个功能。
(8).sched_switch：对内核中的进程调度活动进行跟踪。
(9)blk:block I/O追踪器,blktrace用户应用程序 使用的跟踪器
(10)mmiotrace:MMIO(Memory Mapped I/O)追踪器，用于Nouveau驱动程序等逆向工程
(11)wakeup_rt:与wakeup相同，但以实时进程为对象（non-RT进程通常看平均延迟。RT进程的最大延迟非常有意义，反应了调度器的性能，命令cat trace | head -400）
(12)wakeup_dl:跟踪并记录唤醒SCHED_DEADLINE任务所需的最大延迟（如"wakeup”和"wakeup_rt”一样）
(13)hwlat:硬件延迟跟踪器。它用于检测硬件是否产生任何延迟

例如对i2c进行跟踪

adb root
echo nop > /sys/kernel/debug/tracing/current_tracer  //清空以前的跟踪信息
echo 1 > /sys/kernel/debug/tracing/events/i2c/enable
echo 1 > /sys/kernel/debug/tracing/trasing_on  //打开跟踪器
操作设备，复现问题。
echo 0 > /sys/kernel/debug/tracing/tracing_on//关闭跟踪器
adb pull /sys/kernel/debug/tracing/trace

如下目录也可以操作：

/sys/kernel/tracing/

adb pull 出来的 trace 文件如下：

# tracer: nop
#
# entries-in-buffer/entries-written: 1203/1087390   #P:6
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
   kworker/u12:0-6     [003] ...1   253.195437: i2c_reply: i2c-1 #1 a=038 f=0001 l=63 [00-00-01-81-68-03-72-00-00-ff-ff-ff-ff-00-00-ff-ff-ff-ff-00-00-ff-ff-ff-ff-00-00-ff-ff-ff-ff-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00]
   kworker/u12:0-6     [003] ...1   253.195440: i2c_result: i2c-1 n=2 ret=2
   kworker/u12:0-6     [003] ...1   253.257546: i2c_write: i2c-1 #0 a=038 f=0000 l=1 [00]
   kworker/u12:0-6     [003] ...1   253.257550: i2c_read: i2c-1 #1 a=038 f=0001 l=63
   kworker/u12:0-6     [003] ...1   253.263708: i2c_reply: i2c-1 #1 a=038 f=0001 l=63 [00-00-01-81-68-02-d0-00-00-ff-ff-ff-ff-00-00-ff-ff-ff-ff-00-00-ff-ff-ff-ff-00-00-ff-ff-ff-ff-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00-00]
   kworker/u12:0-6     [003] ...1   253.263711: i2c_result: i2c-1 n=2 ret=2
   kworker/u12:5-223   [003] ...1   254.632061: i2c_write: i2c-1 #0 a=038 f=0000 l=1 [00]
   kworker/u12:5-223   [003] ...1   254.632064: i2c_read: i2c-1 #1 a=038 f=0001 l=63
   kworker/u12:5-223   [003] ...1   255.728473: i2c_result: i2c-1 n=1 ret=1
   kworker/u12:5-223   [003] ...1   255.728499: i2c_write: i2c-1 #0 a=01a f=0000 l=3 [63-a8-10]
   kworker/u12:4-222   [003] ...1   266.944488: i2c_write: i2c-1 #0 a=038 f=0000 l=1 [00]
   kworker/u12:4-222   [003] .n.1   266.944492: i2c_read: i2c-1 #1 a=038 f=0001 l=63

这里看出，是哪个 task，PID 是多少，用的 I2C-1 进行通信，传输过程是跑在 CPU3 上面，并且有 kernel 时间戳。
i2c_write、i2c_read、i2c_reply、i2c_result 是一个循环，i2c_reply 是 i2c 传输完成，并且重新被 CPU 调度，返回到调用线程的时间点，i2c_result 则是两次 i2c 传输的时间间隔。
每一笔 i2c 传输的长度，内容，也都会打印出来。
因为博主一开始只在 events 里面 enable 了 i2c，因此只抓除了 i2c 部分，我们可以同时 enable 其他事件。
如果我们同时 enable i2c 和 irq ，我们将在 trace 中看到更详细的内容，足够分析 i2c 传输慢的问题。
详细的 ftrace 原理和使用方法，请参考**《奔跑吧 Linux 内核 入门篇》11.3节，或者《奔跑吧 Linux 内核基于 Linux4.x 内核源代码问题分析》**6.2节。

基本用法

ftrace 通过 debugfs 向用户态提供访问接口。配置内核时激活 debugfs 后会创建目录 /sys/kernel/debug ，debugfs 文件系统就是挂载到该目录。要挂载该目录，需要将如下内容添加到 /etc/fstab 文件：

debugfs  /sys/kernel/debug  debugfs  defaults  0  0

或者可以在运行时挂载：

mount  -t  debugfs  debugfs  /sys/kernel/debug

激活内核对 ftrace 的支持后会在 debugfs 下创建一个 tracing 目录 /sys/kernel/debug/tracing

sudo su 
cd /sys/kernel/debug/tracing/ #或者/sys/kernel/tracing/

1.查看当前可以使用的跟踪器

cat available_tracers
hwlat blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup function nop

2.设置跟踪器

echo nop >current_tracer #清除跟踪器操作,也可以使用echo function >current_tracer
cat current_tracer
nop 

3.打开/关闭跟踪器

echo 1 > tracing_on #打开
echo 0 > tracing_on #关闭

4.查看/跟踪函数

cat trace | head -20  #查看前20行
cat trace_pipe #查看实时打印的函数
echo 0 >trace 或者echo >  trace #清空跟踪文件

进阶用法

1.跟踪的函数

set_ftrace_filter 表示要跟踪的函数，dev_attr_show 要根据具体哪个函数
echo dev_attr_show > set_ftrace_filter 
echo "ip_rcv" > set_ftrace_filter 或者 echo ip_rcv > set_ftrace_filter #两种写法都可以,并且该方式，>>可以同时跟踪多条，追加跟踪的方式

2.查看函数调用栈

WARN_ON(1) #在函数内部添加,加入到对应的代码当中
#在/sys/kernel/debug/tracing中
echo 1 > options/func_stack_trace  #打开函数调用栈跟踪

例子

以 schedule 函数为例(在该函数中加入WARN_ON(1))，看看 ftrace 如何帮我们获取调用栈：

#cd /sys/kernel/debug/tracing
#echo 0 > tracing_on
#echo function > current_tracer
#echo schedule > set_ftrace_filter
// 设置 func_stack_trace
#echo 1 > options/func_stack_trace
#echo 1 > tracing_on

3.跟踪执行时间短的命令
ftrace过滤控制相关文件

set_ftrace_filter #针对function跟踪器 只跟踪某个函数
set_ftrace_notrace #针对function跟踪器  不跟踪某个函数
set_graph_function #针对function_graph跟踪器 只跟踪某个函数
set_graph_notrace #针对function_graph跟踪器 不跟踪某个函数
set_event_pid #针对于跟踪event事件，不依赖于具体的跟踪器，只跟踪某个进程
set_ftrace_pid #针对function/function_graph跟踪 只跟踪某个进程

调试 kill 的内核执行流程，如何办呢？
因为 kill 运行时间很短，我们不能知道它的 pid，所以就没法过滤了。

echo $$ #是显示当前会话进程号
echo $? #是返回上一条命令是否正确
echo > 2.txt 或者 >2.txt #插入空
sh -c #非交互式运行
sh -c "echo $$ > set_ftrace_pid; echo 1 > tracing_on; kill xxx; echo 0 > tracing_on"

4.跟踪过滤多个进程 及多个函数
(1) 使用通配符跟踪函数

echo 'dev_attr_*' > set_ftrace_filter
cat set_ftrace_filter
dev_attr_store
dev_attr_show

(2) 追加跟踪函数

echo ip_rcv >> set_ftrace_filter 或者 echo "ip_rcv" >> set_ftrace_filter
cat set_ftrace_filter
dev_attr_store
dev_attr_show
ip_rcv

(3)模块过滤

格式为：<function>:<command>:<parameter>，**例如，过滤 ext3 module 的 write* 函数：**
echo 'write*:mod:ext3' > set_ftrace_filter

(4)从过滤列表中删除某个函数
感叹号用来移除某个函数，把上面追加的 ip_rcv 去掉：

cd /sys/kernel/debug/tracing
cat set_ftrace_filter
dev_attr_store
dev_attr_show
ip_rcv
echo '!ip_rcv' >> set_ftrace_filter
cat set_ftrace_filter
dev_attr_store
dev_attr_show
echo 0 > set_ftrace_filter

几种常用的前端工具

手工操作/sys/kernel/debug/tracing路径下的大量的配置文件接口，来使用ftrace的强大功能。但是这些接口对普通用户来说太多太复杂了，我们可以使用对ftrace功能进行二次封装的一些命令来操作。

trace-cmd就是ftrace封装命令其中的一种。该软件包由两部分组成

(1)trace-cmd：提供了数据抓取和数据分析的功能
(2)kernelshark：可以用图形化的方式来详细分析数据，也可以做数据抓取

1.trace-cmd

下载编译ARM64 trace-cmd方法

git clone [https://github.com/rostedt/trace-cmd.git](https://github.com/rostedt/trace-cmd.git)
export CROSS_COMPILE=aarch64-linux-gnu-
export ARCH=arm64
make

先通过 record 子命令将结果记录到 trace.dat，再通过 report 命令进行结果提取。命令解释：
-p：指定当前的 tracer，类似 echo function > current_tracer，可以是支持的 tracer 中的任意一个
-l：指定跟踪的函数，可以设置多个，类似 echo function_name > set_ftrace_filter
–func-stack：记录被跟踪函数的调用栈
在很有情况下不能使用函数追踪，需要依赖事件追踪 的支持，例如：

2.kernelshark图形化分析数据

trace-cmd report主要是使用统计的方式来找出热点。如果要看vfs_read()一个具体的调用过程，除了使用上一节的trace-cmd report命令，还可以使用kernelshark图形化的形式来查看，可以在板子上使用trace-cmd record 记录事件，把得到的trace.data放到linux 桌面系统，用kernelshark打开，看到图形化的信息

#参考网站
linux性能工具–ftrace使用