手把手教你分析 Trace，你学会了吗？-can trace分析

博主示例用的 RK3399，跑的 Android 8.1。

为了方便大家抓 trace，博主写了一个 bat 脚本，大家在 windows 环境下，直接双击运行，按照提示三次回车即可，抓到的 trace 会输出在当前文件，名字是 SYS_TRACE。

my_trace.bat

@echo off

rem in /sys/kernel/debug/tracing/ or /sys/kernel/tracing/ , please confirm by yourself

adb root

adb shell "echo 65536 > /sys/kernel/debug/tracing/buffer_size_kb"
echo "buffer_size_kb(per cpu): "
adb shell "cat /sys/kernel/debug/tracing/buffer_size_kb"

adb shell "echo nop > /sys/kernel/debug/tracing/current_tracer" >nul 2>&1
adb shell "echo 'noprint-tgid' > /sys/kernel/tracing/trace_options" >nul 2>&1

rem clear ftrace events
adb shell "echo > /sys/kernel/debug/tracing/set_event"

rem enable profiling events here,with loop
for %%x in (
  sched_switch
  sched_wakeup
  sched_wakeup_new
  sched_migrate_task
  softirq_raise
  softirq_entry
  softirq_exit
  ipi
  irq
  irq_handler_entry
  irq_handler_exit
  cpu_frequency
  workqueue_execute_start
  workqueue_execute_end
  timer
  clk
  suspend_resume
  device_pm_callback_start
  device_pm_callback_end
  cpu_idle
  pm_qos_update_request
  i2c
  f2fs
  suspend_resume
) do (
  adb shell "echo %%x >> /sys/kernel/debug/tracing/set_event"
)

rem just in case tracing_enabled is disabled by user or other debugging tool
adb shell "echo 1 > /sys/kernel/debug/tracing/tracing_enabled" >nul 2>&1
adb shell "echo 0 > /sys/kernel/debug/tracing/tracing_on"

rem erase previous recorded trace
adb shell "echo > /sys/kernel/debug/tracing/trace"
echo press any key to start capturing...
pause

adb shell "echo 1 > /sys/kernel/debug/tracing/tracing_on"
echo "Start recordng ftrace data"
echo "Press any key to stop..."
pause

adb wait-for-device
adb shell "echo 0 > /sys/kernel/debug/tracing/tracing_on"
echo "Recording stopped..."

adb shell "ps -AT" > ps_1.txt
adb shell cat /sys/kernel/debug/tracing/trace > SYS_FTRACE
adb shell "ps -AT" > ps_2.txt
adb shell "echo noprint-tgid > /sys/kernel/debug/tracing/trace_options" >nul 2>&1

rem default size
adb shell "echo 4096 > /sys/kernel/debug/tracing/buffer_size_kb"
pause

这个脚本重要的地方都有注释，rem 开头的都是注释，请注意看第一个注释。

大概框架就是先把每个 CPU 的 buffer 设置为 65536，然后把想要抓取的 events 通过 for 循环设置进去，然后开启抓取，这时候你可以在设备上操作，复现问题，复现出来后，再停止抓取，并且把抓到的 trace 拉出来。

运行完毕后目录如下：

SYS_TRACE 如下：

本次我们只分析 i2c 问题，因此通过 grep 工具把 i2c 相关的提取出来。博主在 i2c4 上挂载了三个设备，通过 cat /proc/interrputs 确认 i2c4 的软件中断号是 41，则提取命令如下：

grep -e "irq=41" -e "i2c-4" SYS_FTRACE > i2c4-20221106.txt

则提取出来的内容只包含 i2c4 部分，截取一部分分析：

i2c_read 到 irq_handler_entry 慢：

该路 I2C4 挂载设备过多，同时发起通信会抢占。

发起 i2c 传输的 user 线程优先级低，当多个设备同时发起 i2c 传输，或者前面已经有几个设备在等待，你的设备就拿不到锁，就一直排在后面。

硬件传输耗时久：比如从机有问题，或者 i2c 速率设置不对，用示波器可以抓到。

irq_handler_exit 到 i2c_reply 慢：

发起 i2c 传输的 user 线程优先级低，i2c 中断来了以后叫起 user 线程，但是被高优先级线程抢占，user 线程一直得不到 CPU 调度。
很多时候为了功耗，会设置 i2c 中断无法打醒 CPU。比如在 CPU0 发起一次 i2c 通信，CPU0 并没有等其返回，没事做就进入了 idle 状态，i2c 中断来了以后唤醒不了 CPU0，导致慢。【该原因和调度策略也有关系，当其他 CPU 空闲时候，user 线程应该调度到其他 CPU 处理才对】

总结来讲：

如果是 user 线程优先级低，则你观察到的 i2c 传输耗时是整体慢。
如果是 CPU 进入 idle 导致你的 i2c 传输耗时，则是概率性出现，并且耗时偶尔会出现 15-25ms 这种级别，无法忍受。