為了方便大家抓 trace，博主寫(xiě)了一個(gè) bat 腳本，大家在 windows 環(huán)境下，直接雙擊運(yùn)行，按照提示三次回車即可，抓到的 trace 會(huì)輸出在當(dāng)前文件，名字是 SYS_TRACE。
博主示例用的 RK3399，跑的 Android 8.1。
為了方便大家抓 trace，博主寫(xiě)了一個(gè) bat 腳本，大家在 windows 環(huán)境下，直接雙擊運(yùn)行，按照提示三次回車即可，抓到的 trace 會(huì)輸出在當(dāng)前文件，名字是 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
這個(gè)腳本重要的地方都有注釋，rem 開(kāi)頭的都是注釋，請(qǐng)注意看第一個(gè)注釋。
大概框架就是先把每個(gè) CPU 的 buffer 設(shè)置為 65536，然后把想要抓取的 events 通過(guò) for 循環(huán)設(shè)置進(jìn)去，然后開(kāi)啟抓取，這時(shí)候你可以在設(shè)備上操作，復(fù)現(xiàn)問(wèn)題，復(fù)現(xiàn)出來(lái)后，再停止抓取，并且把抓到的 trace 拉出來(lái)。
運(yùn)行完畢后目錄如下：
SYS_TRACE 如下：
本次我們只分析 i2c 問(wèn)題，因此通過(guò) grep 工具把 i2c 相關(guān)的提取出來(lái)。博主在 i2c4 上掛載了三個(gè)設(shè)備，通過(guò) cat /proc/interrputs 確認(rèn) i2c4 的軟件中斷號(hào)是 41，則提取命令如下：
grep -e "irq=41" -e "i2c-4" SYS_FTRACE > i2c4-20221106.txt
則提取出來(lái)的內(nèi)容只包含 i2c4 部分，截取一部分分析：
i2c_read 到 irq_handler_entry 慢：
該路 I2C4 掛載設(shè)備過(guò)多，同時(shí)發(fā)起通信會(huì)搶占。
發(fā)起 i2c 傳輸?shù)?user 線程優(yōu)先級(jí)低，當(dāng)多個(gè)設(shè)備同時(shí)發(fā)起 i2c 傳輸，或者前面已經(jīng)有幾個(gè)設(shè)備在等待，你的設(shè)備就拿不到鎖，就一直排在后面。
硬件傳輸耗時(shí)久：比如從機(jī)有問(wèn)題，或者 i2c 速率設(shè)置不對(duì)，用示波器可以抓到。
irq_handler_exit 到 i2c_reply 慢：
- 發(fā)起 i2c 傳輸?shù)?user 線程優(yōu)先級(jí)低，i2c 中斷來(lái)了以后叫起 user 線程，但是被高優(yōu)先級(jí)線程搶占，user 線程一直得不到 CPU 調(diào)度。
- 很多時(shí)候?yàn)榱斯?，?huì)設(shè)置 i2c 中斷無(wú)法打醒 CPU。比如在 CPU0 發(fā)起一次 i2c 通信，CPU0 并沒(méi)有等其返回，沒(méi)事做就進(jìn)入了 idle 狀態(tài)，i2c 中斷來(lái)了以后喚醒不了 CPU0，導(dǎo)致慢?！驹撛蚝驼{(diào)度策略也有關(guān)系，當(dāng)其他 CPU 空閑時(shí)候，user 線程應(yīng)該調(diào)度到其他 CPU 處理才對(duì)】
總結(jié)來(lái)講：
- 如果是 user 線程優(yōu)先級(jí)低，則你觀察到的 i2c 傳輸耗時(shí)是整體慢。
- 如果是 CPU 進(jìn)入 idle 導(dǎo)致你的 i2c 傳輸耗時(shí)，則是概率性出現(xiàn)，并且耗時(shí)偶爾會(huì)出現(xiàn) 15-25ms 這種級(jí)別，無(wú)法忍受。
