手把手教你分析 trace【附脚本】

Jasonangel

发布于 2023-01-03 19:16:21

1.2K00

代码可运行

运行总次数：0

代码可运行

手把手教你使用 ftrace

上篇文章给大家介绍了背景，讲解了 i2c 传输慢的原因，这篇文章手把手教大家分析。

博主示例用的 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 处理才对】

总结来讲：