轉自：https://blog.csdn.net/Guet_Kite/article/details/101791125

你好！這裡是風箏的部落格，
歡迎和我一起交流。
trace是核心自帶的工具，相比於perf工具，trace只管抓trace資料並沒有分析，perf在trace資料分析方面做出了很多成果。
但是我們現在就想看一下底層多呼叫關係，所以使用trace抓一下資料是非常有必要的，還可以分析一下驅動效能。

因為trace工具是核心自帶的，所以我們配置一下核心就可以使用了：

Kernel hacking —>
         [*] Tracers —>
                 [
 
*] Kernel Function Tracer
                 [*] Kernel Function Graph Tracer
                 [*] Trace syscalls
                 [*] enable/disable function tracing dynamically
                 [*] Kernel function profiler
                [*] Interrupts-off Latency Tracer

trace 通過 debugfs 向用戶態提供了訪問介面，所以還需要將 debugfs 編譯進核心。啟用對 debugfs 的支援，在 make menuconfig 時到 Kernel hacking 選單下選中對 debugfs 檔案系統的支援：
Kernel hacking —
 
>
         -*- Debug Filesystem

系統啟動後，進入檔案系統，執行：

mount -t debugfs none /sys/kernel/debug/
cd /sys/kernel/debug/tracing/
1
2
掛載debugfs後即可使用trace。

tracing 目錄下檔案和目錄比較多，有些是各種跟蹤器共享使用的，有些是特定於某個跟蹤器使用的。在操作這些資料檔案時，使用 echo 命令來修改其值，也可以在程式中通過檔案讀寫相關的函式來操作這些檔案的值。

README檔案提供了一個簡短的使用說明，展示了 ftrace 的操作命令序列。可以通過 cat 命令檢視該檔案以瞭解概要的操作流程。
current_tracer用於設定或顯示當前使用的跟蹤器；使用 echo 將跟蹤器名字寫入該檔案可以切換到不同的跟蹤器。系統啟動後，其預設值為 nop ，即不做任何跟蹤操作。在執行完一段跟蹤任務後，可以通過向該檔案寫入 nop 來重置跟蹤器。
available_tracers記錄了當前編譯進核心的跟蹤器的列表，可以通過 cat 檢視其內容；寫 current_tracer 檔案時用到的跟蹤器名字必須在該檔案列出的跟蹤器名字列表中。
trace檔案提供了檢視獲取到的跟蹤資訊的介面。可以通過 cat 等命令檢視該檔案以檢視跟蹤到的核心活動記錄，也可以將其內容儲存為記錄檔案以備後續檢視。
set_graph_function設定要清晰顯示呼叫關係的函式，顯示的資訊結構類似於 C 語言程式碼，這樣在分析核心運作流程時會更加直觀一些。在使用 function_graph 跟蹤器時使用；預設為對所有函式都生成呼叫關係序列，可以通過寫該檔案來指定需要特別關注的函式。
buffer_size_kb用於設定單個 CPU 所使用的跟蹤快取的大小。跟蹤器會將跟蹤到的資訊寫入快取，每個 CPU 的跟蹤快取是一樣大的。跟蹤快取實現為環形緩衝區的形式，如果跟蹤到的資訊太多，則舊的資訊會被新的跟蹤資訊覆蓋掉。注意，要更改該檔案的值需要先將 current_tracer 設定為 nop 才可以。
tracing_on用於控制跟蹤的暫停。有時候在觀察到某些事件時想暫時關閉跟蹤，可以將 
 
0 寫入該檔案以停止跟蹤，這樣跟蹤緩衝區中比較新的部分是與所關注的事件相關的；寫入 1 可以繼續跟蹤。
available_filter_functions記錄了當前可以跟蹤的核心函式。對於不在該檔案中列出的函式，無法跟蹤其活動。
set_ftrace_filter和 set_ftrace_notrace在編譯核心時配置了動態 ftrace （選中CONFIG_DYNAMIC_FTRACE 選項）後使用。前者用於顯示指定要跟蹤的函式，後者則作用相反，用於指定不跟蹤的函式。如果一個函式名同時出現在這兩個檔案中，則這個函式的執行狀況不會被跟蹤。這些檔案還支援簡單形式的含有萬用字元的表示式，這樣可以用一個表示式一次指定多個目標函式；注意，要寫入這兩個檔案的函式名必須可以在檔案 available_filter_functions 中看到。預設為可以跟蹤所有核心函式，檔案 set_ftrace_notrace 的值則為空。
available_events 當前編譯進核心的可以監控的事件。
set_event 跟蹤的事件型別，名字必須在available_events列出的跟蹤器名字列表中。
trace 當前包含多個跟蹤器，用於跟蹤不同型別的資訊，比如程序排程、中斷關閉等。可以檢視檔案 available_tracers 獲取核心當前支援的跟蹤器列表。在編譯核心時，也可以看到核心支援的跟蹤器對應的選項

nop跟蹤器不會跟蹤任何核心活動，將 nop 寫入 current_tracer
檔案可以刪除之前所使用的跟蹤器，並清空之前收集到的跟蹤資訊，即重新整理 trace 檔案。
function跟蹤器可以跟蹤核心函式的執行情況；可以通過檔案 set_ftrace_filter 顯示指定要跟蹤的函式。
function_graph跟蹤器可以顯示類似 C 原始碼的函式呼叫關係圖，這樣檢視起來比較直觀一些；可以通過檔案
set_grapch_function 顯示指定要生成呼叫流程圖的函式。 sched_switch跟蹤器可以對核心中的程序排程活動進行跟蹤。
irqsoff跟蹤器和preemptoff跟蹤器分別跟蹤關閉中斷的程式碼和禁止程序搶佔的程式碼，並記錄關閉的最大時長，preemptirqsoff跟蹤器則可以看做它們的組合。
以上目錄內容參考了：如何使用ftrace進行核心除錯

那具體怎麼用呢？

一、抓取函式呼叫流程關係
比如我們抓一次spi輸出傳輸，驅動用的是kernel自帶的spidev驅動：

echo 0 > tracing_on
echo function_graph > current_tracer
echo spidev_ioctl> set_graph_function 
echo 1 > tracing_on
./spidev_test
echo 0 > tracing_on
cat trace

spidev_ioctrl 被echo到set_grapch_function 屬性裡面，就可以檢視整個spidev_ioctrl 函式的呼叫流程，但是實際上我們執行的時候會發現一個事情，抓取來的資料太多了，許多無關的、我們不太關心的函式呼叫關係也被抓進去了，導致抓出來的資料非常亂！
所以最好是利用set_ftrace_filter進行一些過濾。
所以針對這種情況，我們應該這樣設定：

echo 0 > tracing_on
echo function_graph > current_tracer
echo *spi* > set_ftrace_filter
echo *dma* >> set_ftrace_filter
echo *spin* >> set_ftrace_notrace
echo 1 > tracing_on
./spidev_test
echo 0 > tracing_on
cat trace

在spi傳輸裡，我們主要關係spi的函式和dma的函式，所以大概抓一下這些字眼即可，還可以按需自己新增過濾語句。
ps：因為spin_lock語句也帶了spi字眼，也會被誤抓進來，所以最後也把他剔除掉。
最後得出的資料就正常多了：

 1) + 41.292 us   |  spidev_open();
 1)               |  spidev_ioctl() {
 1)               |    spi_setup() {
 1)   0.417 us    |      __spi_validate_bits_per_word.isra.0();
 1)               |      sunxi_spi_setup() {
 1)   0.834 us    |        sunxi_spi_check_cs();
 1)   0.875 us    |        spi_set_cs();
 1)   0.625 us    |        sunxi_spi_cs_control();
 1) + 17.125 us   |      }
 1)   0.833 us    |      spi_set_cs();
 1) + 30.458 us   |    }
 1) ! 699.875 us  |  }
 1)   6.916 us    |  spidev_ioctl();
 1)               |  spidev_ioctl() {
 1)               |    spi_setup() {
 1)   0.291 us    |      __spi_validate_bits_per_word.isra.0();
 1)               |      sunxi_spi_setup() {
 1)   0.250 us    |        sunxi_spi_check_cs();
 1)   0.459 us    |        spi_set_cs();
 1)   0.375 us    |        sunxi_spi_cs_control();
 1) + 12.209 us   |      }
 1)   0.291 us    |      spi_set_cs();
 1) + 21.042 us   |    }
 1) + 30.000 us   |  }
 1)   5.750 us    |  spidev_ioctl();
 1)               |  spidev_ioctl() {
 1)               |    spi_setup() {
 1)   0.250 us    |      __spi_validate_bits_per_word.isra.0();
 1)               |      sunxi_spi_setup() {
 1)   0.292 us    |        sunxi_spi_check_cs();
 1)   0.375 us    |        spi_set_cs();
 1)   0.416 us    |        sunxi_spi_cs_control();
 1) + 11.750 us   |      }
 1)   0.291 us    |      spi_set_cs();
 1) + 20.750 us   |    }
 1) + 29.666 us   |  }

以上僅列舉部分資訊，有興趣的小夥伴可以自行嘗試。

二、抓取函式耗時
有時候，也許我們也要通過程式的耗時來分析程式的效能，可以這麼做：
同樣也是以spidev驅動為例：

echo 0 > tracing_on
echo function_graph > current_tracer
echo spidev_ioctl> set_ftrace_filter
echo 1 > tracing_on
./spidev_test
echo 0 > tracing_on
cat trace

這樣可以非常直觀的看到spidev_ioctrl 執行的耗時。

/sys/kernel/debug/tracing # cat trace
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 2) ! 665.584 us  |  spidev_ioctl();
 2)   8.125 us    |  spidev_ioctl();
 2)   9.042 us    |  spidev_ioctl();
 2)   5.750 us    |  spidev_ioctl();
 2)   8.791 us    |  spidev_ioctl();
 2)   5.667 us    |  spidev_ioctl();
 2)               |  spidev_ioctl() {
 0) # 1385.625 us |  } /* spidev_ioctl */

其中， 帶左側時間顯示一塊：
延遲比較大的部分，會有+、#等特殊標號：

‘$’ - greater than 1 second
‘@’ - greater than 100 milisecond
‘*’ - greater than 10 milisecond
‘#’ - greater than 1000 microsecond
‘!’ - greater than 100 microsecond
‘+’ - greater than 10 microsecond
’ ’ - less than or equal to 10 microsecond.

三、抓取程式碼片耗時
有時，我們需要抓取一大片多個函式耗時。可以這麼做：
以i2c傳輸為例，抓取twi_set_start到sunxi_i2c_handler函式的時間：

echo 0 > tracing_on
echo function > current_tracer
echo twi_set_start sunxi_i2c_handler > set_ftrace_filter
echo 1 > tracing_on
i2cget -y 1 0x50 0x01
echo 0 > tracing_on
cat trace

這樣我們即可抓取Linux裡面執行i2cget的時候去讀取0x50地址器件時i2c傳輸 twi_set_start 函式到 sunxi_i2c_handler 函式的耗時，即兩個時間戳相減：

# tracer: function
#
# entries-in-buffer/entries-written: 4/4   #P:1
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
          i2cget-810   [000] ...1    21.434049: twi_set_start <-twi_start
          i2cget-810   [000] d.h1    21.434073: sunxi_i2c_handler <-__handle_irq_event_percpu

可以看得出耗時為24us。

當然，我們也可以使用do_gettimeofday函式來統計耗時，不過比較麻煩，需要在檢測的地方手動新增：

#include <linux/time.h> 
struct timeval old_tv;
struct timeval new_tv;

do_gettimeofday(&old_tv);
xxx_functions();
do_gettimeofday(&new_tv);
printk("time is %d us\n", (new_tv.tv_usec-old_tv.tv_usec) + (new_tv.tv_sec-old_tv.tv_sec) * 1000000);

timeval 結構體定義：

struct timeval { 

　　time_t tv_sec;       /* seconds */
　　suseconds_t tv_usec; /* microseconds */ 
};

甚至也可以用ktime_to_us來實現：

s64 before, after;

before = ktime_to_us(ktime_get());
xxx_functions();
after = ktime_to_us(ktime_get());
printk("regu ad time: %d us\n", (u32)(after - before));
1
2
3
4
5
6
方法是多種多樣的。

四、抓取函式裡每個子函式時間戳
在第一點裡面，抓取函式呼叫流程裡面只能看到每個子函式的耗時，不能看到時間戳，那麼如何能看到每個子函式的時間戳呢？和第一點的手段類似：

echo 0 > tracing_on
echo function_graph > current_tracer
echo spidev_ioctl > set_graph_function 
echo funcgraph-tail > trace_options
echo 1 > tracing_on
./spidev_test
echo 0 > tracing_on
cat trace

區別操作就是添加了：echo funcgraph-tail > trace_options
主要是在函式結束顯示函式名。這樣方便使用grep找出函式的執行時間，預設disable：
hide: echo nofuncgraph-tail > trace_options
show: echo funcgraph-tail > trace_options
最後結果非常直觀：

# tracer: function_graph
#
# entries-in-buffer/entries-written: 408/408   #P:1
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
     spidev_test-1818  [000] ....   221.614092: graph_ent: func=spidev_ioctl
     spidev_test-1818  [000] d...   221.614101: graph_ent: func=preempt_count_add
     spidev_test-1818  [000] d..1   221.614104: graph_ret: func=preempt_count_add
     spidev_test-1818  [000] d..1   221.614107: graph_ent: func=get_device
     spidev_test-1818  [000] d..1   221.614108: graph_ret: func=get_device

graph_ent代表函式開始執行
graph_ret代表函式結束

五、抓取事件資訊
有時候我們需要根據事件來抓取資訊，就可以使用set_event了：
可以 cat available_events 檢視獲得支援的跟蹤event列表，這個支援的比較多，配置相對簡單，只需向set_event寫相應值即可。
比如我們要檢視spi的事件，可以先看下available_event 裡有無spi事件：

/sys/kernel/debug/tracing # cat available_events  | grep spi
spi:spi_transfer_stop
spi:spi_transfer_start
spi:spi_message_done
spi:spi_message_start
spi:spi_message_submit
spi:spi_master_busy
spi:spi_master_idle

可以看出，我們這裡支援七個spi事件，其對應的標頭檔案在：Linux-4.9/include/trace/events/spi.h檔案。
感興趣的可以檢視裡面的內容實現。
這裡我們把所有的spi事件都打印出來：

echo 0 > tracing_on
echo spi > set_event
echo 1 > tracing_on
./spidev_test
echo 0 > tracing_on
cat trace
1
2
3
4
5
6
即可看到我們需要跟蹤的spi事件：

/sys/kernel/debug/tracing # cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 24/24   #P:1
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
              sh-811   [000] d..1    20.800876: spi_message_submit: spi0.0 de49faf4
              sh-811   [000] d..1    20.801005: spi_message_submit: spi0.0 de49fab0
              sh-811   [000] d..1    20.801196: spi_message_submit: spi0.0 de49fa18
              sh-811   [000] d..1    20.801346: spi_message_submit: spi0.0 de49fa18
              sh-811   [000] d..1    20.801437: spi_message_submit: spi0.0 de49faf4

參考：
Linux ftrace 1.2、trace event
Linux ftrace 2.1、ftrace的使用
https://blog.csdn.net/pwl999/article/category/7733476
Linux ftrace框架介紹及運用
————————————————
版權宣告：本文為CSDN博主「風箏丶」的原創文章，遵循CC 4.0 BY-SA版權協議，轉載請附上原文出處連結及本宣告。
原文連結：https://blog.csdn.net/Guet_Kite/article/details/101791125