最近遇到 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 持鎖，可以優化）
1、簡介
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 1
LTR：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
如下目錄也可以操作：
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 傳輸慢的問題。
