Linux ftrace工具抓 i2c trace

抓 i2c trace

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

如下目录也可以操作：

/sys/kernel/tracing/

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 传输慢的问题。