為了方便大家抓 trace,博主寫了一個 bat 腳本,大家在 windows 環境下,直接雙擊運行,按照提示三次回車即可,抓到的 trace 會輸出在當前文件,名字是 SYS_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 這種級別,無法忍受。