轉自：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