手把手教你使用 Ftrace，你会了吗？
source link: https://www.51cto.com/article/721585.html
Go to the source link to view the article. You can view the picture content, updated content and better typesetting reading experience. If the link is broken, please click the button below to view the snapshot at that time.
手把手教你使用 Ftrace，你会了吗？
最近遇到 i2c 传输慢的问题，正常一笔 i2c 传输 52 bytes 应该在 1ms 内返回，但是偶尔出现 6 ~ 7ms 才返回，不满足要求，因此研究一下 ftrace 工具，分析 i2c 传输到底慢在哪里。怀疑：
- 同一路 i2c bus 挂载设备多，可能同时发起传输，导致抢占。（解决方法：重要器件独占一路 i2c bus）
- i2c 硬件传输慢。一般不太可能，因为这是硬件行为，除非从机返回慢。（研究从机为什么慢）
- i2c 传输完成后返回，i2c 控制器发传输完成的信号给 cpu，但 cpu 忙 loading 重，没有及时调用 i2c_reply 通知调用者；或者是 i2c 传输完成后，CPU 处于睡眠状态，由于 i2c 中断无法唤醒系统，系统醒了以后才返回，导致慢。（提升 user 线程优先级 + 让这一路 i2c bus 持锁，可以优化）
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 (P) 及以上版本平台都可用，但只有在 Android 11 (R) 及以上的版本中才默认启用。在Android 9 (P) 和 10 (Q) 上，你需要执行下面的命令，以确保在一切开始之前跟踪服务正常启动：
# Needed only on Android 9 (P) and 10 (Q) on non-Pixel phones.
adb shell setprop persist.traced.enable 1LTR：Long Trace Recoder，可以录制长达半个小时的 trace，主要用于分析游戏场景。
因此，首先需要学习 ftrace，它是其他 trace 的基础。
2、宏定义
在使用 ftrace 之前，需要确保内核配置编译了其配置选项。
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 事件，一些常用的选项如下。
- available_tracers：列出当前系统支持的跟踪器。
- available_events：列出当前系统支持的 event 事件。
- current_tracer：设置和显示当前正在使用的跟踪器。使用 echo 命令可以把跟踪器的名字写入该文件，即可以切换不同的跟踪器。默认为 nop，即不做任何跟踪操作。
- trace：读取跟踪信息。通过 cat 命令查看 ftrace 记录下来的跟踪信息。
- tracing_on：用于开始或暂停跟踪。
- trace_options：设置 ftrace 的一些相关选项。
nop：不跟踪任何信息。将 nop 写入 current_tracer 文件可以清空之前收集到的跟踪信息。 function：跟踪内核函数执行情况。 function_graph：可以显示类似 C 语言的函数调用关系图，比较直观。 wakeup：跟踪进程唤醒信息。 irqsoff：跟踪关闭中断信息，并记录关闭的最大时长。 preemptoff：跟踪关闭禁止抢占信息，并记录关闭的最大时长。 preemptirqsoff：综合了 irqoff 和 preemptoff 两个功能。 sched_switch：对内核中的进程调度活动进行跟踪。
3、抓 i2c traceadb root
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
kworker/u12:1-53 [003] ...1 268.822588: i2c_reply: i2c-1 #1 a=038 f=0001 l=63 [00-00-00-40-00-01-c4-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:1-53 [003] ...1 268.822591: i2c_result: i2c-1 n=2 ret=2
kworker/u12:1-53 [003] ...1 268.822650: i2c_write: i2c-1 #0 a=038 f=0000 l=1 [00]
kworker/u12:1-53 [003] ...1 268.822651: i2c_read: i2c-1 #1 a=038 f=0001 l=63
kworker/u12:0-6 [003] ...1 271.457514: i2c_write: i2c-1 #0 a=038 f=0000 l=1 [00]
kworker/u12:0-6 [003] ...1 271.457518: 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 传输慢的问题。
Recommend
About Joyk
Aggregate valuable and interesting links.
Joyk means Joy of geeK