linux ftrace原理

Linux Kernel 行為分析<工具篇>: Ftrace + KernelShark

請用繁體中文和台灣慣用技術術語！

• 努力修改ing >"<!
• 敲鍵盤可以保存傳統文化，要靠大家了

Introduction

• 原文

• 自己翻的好爛 = ="
  • Ftrace 是內建於Linux kernel的追蹤工具，從2.6.27 開始納入kernel主要發展版本。Ftrace被設計用來幫助系統開發者和系統設計者去知道kernel裡面發生甚麼事情。它可用於 debugging 或 分析 latencies and performance 發生在 user-space 之外的問題。
  • 雖然ftrace通常被視為 function tracer，但它是其實是一個 framework 包含各式的 tracing 工具集。有 latency tracing以檢查 interrupts disabled 和 enabled 之間發生了甚麼，以及用於 preemption(搶占) 從task被喚醒的時間到實際task scheduled。
  • 一個ftrace最常見用法是 event tracing。有幾百個 static event points 通過kernel 我們可以藉由enabled debugfs file system 去看到kernel中某些部份發生了甚麼事情
• ftrace 根據不同的需求提供了不同的tracer，例如：
  • trace kernel function的呼叫
  • trace context switch
  • 查看 interrupt 關閉的時間長度
  • trace kernel latency 以及性能
• 作者介紹
  • Ftrace作者為在RedHat服務的 Steven Rostedt,主要目的是為Linux Kernel提供一個系統效能分析的工具,以便用以debug或是改善/優化系統效能,Ftrace為一個以Function Trace為基礎的工具,並包含了包括行程Context-Switch,Wake-Up/Ready到執行的時間成本,中斷關閉的時間,以及是哪些函式呼叫所觸發的,這都有助於在複雜的系統執行下,提供必要資訊以便定位問題

讓kernel 支援 ftrace (若kernel預設 ftrace enable，則可跳過)

• 目前大部分比較新的Linux kernel都有把 ftrace enable，因此不用另外再進行設置，如果kernel預設ftrace沒有 enable的話，可參考連結進行kernel重新編譯。

Ftrace使用

• 若ftrace預設enable，則可在 `/sys/kernel/debug/` 此路徑下看到 tracing資料夾
  • 若看不到，請轉換為 root 進行操作

• $ sudo su 
• 

Ftrace內的檔案 (/sys/kernel/debug/tracing)

• `/sys/kernel/debug/tracing`中，有些檔案是各個tracer共享使用的，有些是特定於某個tracer使用的。在操作這些檔案時，通常使用echo 來修改檔案的值，也可以在程式中通過讀寫相關的函數來操作這些檔案的值。下面只對部分檔案進行描述，詳細可以參考kernel中Documentation/trace 目錄下的檔案以及kernel/trace 下的source以了解其他文件的用途。(註: 請勿使用 vim 編輯器對這些檔案進行編輯)
  • README
    • 提供了一個簡短的使用說明，說明了ftrace 的操作方式。
    • 可以通過`cat` 命令查看該文件以了解大概的操作流程。
  • current_tracer
    • 用於設定或顯示當前使用的tracer。
    • 使用echo 將tracer名字寫入該文件可以切換到不同的tracer。
    • 系統啟動後，其預設值為nop ，即不做任何trace操作。在執行完一段trace任務後，可以通過向該檔案寫入nop 來重置tracer。
  • available_tracers
    • 記錄了當前編譯進kernel的tracer列表，可以通過cat 查看其內容。
    • 寫current_tracer 檔案時用到的tracer必須有列在available_tracers列表中。
  • trace
    • 提供了查看獲取到的trace訊息的port(輸出追蹤結果的地方，靜態)。
    • 可以通過cat 查看該檔案以查看trace到的kernel活動記錄，也可以將其內容保存為記錄文件以備後續觀察。
  • set_graph_function
    • 設置要清晰顯示呼叫關係的函數，顯示的資訊結構類似於C 語言程式碼，這樣在分析kernel運作流程時會更加直觀一些。在使用function_graph tracer時使用
    • 預設為對所有函數都生成呼叫關係序列，可以通過寫該檔案來指定需要特別關注的函數。
  • buffer_size_kb
    • 用於設置單個CPU 所使用的trace buffer的大小。
    • tracer會將trace到的資訊寫入buffer，每個CPU 的trace buffer是一樣大的。
    • trace buffer為環形緩衝區的形式，如果trace到的訊息太多，則舊的訊息會被新的trace訊息覆蓋掉。
    • 注意，要更改此檔案的值需要先將current_tracer 設置為nop 才可以。
  • tracing_on
    • 用於控制trace的暫停追蹤或繼續追蹤。
    • 有時候在觀察到某些事件時想暫時關閉trace，可以將0 寫入該文件以停止trace，這樣trace buffer中比較新的部分是與所關注的事件相關的；寫入1 可以繼續trace。
  • available_filter_functions
    • 記錄了當前可以trace的kernel函數。對於不在該檔案中列出的函數，無法trace其活動。
  • set_ftrace_filter 和 set_ftrace_notrace
    • 在編譯kernel時配置了動態ftrace （選中CONFIG_DYNAMIC_FTRACE 選項）後使用。
    • set_ftrace_filter用於顯示指定要追蹤的函數，set_ftrace_notrace則作用相反，用於指定不追蹤的函數。
    • 如果一個函數名同時出現在這兩個文件中，則這個函數的執行狀況不會被trace。
    • 注意，要寫入這兩個文件的函數名必須可以在文件available_filter_functions 中看到。預設為可以trace所有kernel函數，檔案 set_ftrace_notrace 的值則為空。
  • events(資料夾) 
    • 可以監控的事件，例如writeback
  • trace_options
    • 控制輸出結果的資料量，也可修改追蹤器或事件的顯示資料方式

Ftrace tracer

• ftrace 目前包含多個tracer，用於trace不同類型的訊息，比如process  scheduling、中斷關閉等。
• 可以查看available_tracers 獲取kernel目前支持的tracer列表(如下圖)。在編譯kernel時，也可以看到kernel有設定的tracer對應的選項。

• 所以要增加新的tracer應該要重編
• 下圖為 PC上有支援的的 tracer
• 下面介紹中有黃色標記為BBB中可使用的tracer

• nop
  • 不會trace任何kernel活動，將nop 寫入current_tracer 文件可以刪除之前所使用的trace，並清空之前收集到的trace訊息，即刷新trace 文件。
• function
  • 可以trace kenel函數的執行情況；可以通過文件set_ftrace_filter 顯示指定要trace的函數
• function_graph
  • 可以顯示類似C code的函數呼叫關係圖，這樣查看起來比較直覺一些；
  • 可以通過文件set_grapch_function 顯示指定要生成呼叫流程圖的函數。
  • BBB kernel 無
• sched_switch
  • 可以對kernel中的process scheduling活動進行trace。
  • BBB kernel 無
    • 考慮從 event/sched中找到 process scheduling
    • 或找新增追蹤器的方法
    • 或是更換有支援的 kernel版本
• irqsoff是追蹤關閉中斷的code，並記錄關閉的最大時間長度(latency)。
• ftrace 還支持其它一些追蹤器，比如initcall、ksym_tracer、mmiotrace、sysprof 等。
  • ftrace 支援增加新的追蹤器。
  • 可參考kernel source中Documentation/trace 目錄下的檔案以及kernel/trace 下的source (code)，以了解其它追踪器的用途和如何添加新的追踪器。

Ftrace Code

位置: kernel/kernel/trace

Ftrace tracer 操作 : 使用

使用ftrace 提供的tracer來偵錯或者分析kernel時需要如下操作：

• 切換到目錄 /sys/kernel/debug/tracing/ 下
• 查看available_tracers ，獲取當前kernel支持的追蹤器列表
• 將所選擇的追蹤器的名字寫入current_tracer
• 通過將0 寫入tracing_on 來暫停追蹤訊息的記錄，此時追蹤器還在追蹤kernel的運行，只是不再向文件trace 中寫入追蹤信息
• 通過將0 寫入trace來刪除追蹤訊息的輸出
• 將要追蹤的函數寫入set_ftrace_filter ，將不希望追蹤的函數寫入set_ftrace_notrace。通常直接操作set_ftrace_filter 就可以了
• 激活ftrace 追蹤，即將1 寫入文件tracing_on。
• 如果是對應用程序進行分析的話，啟動應用程序的執行，ftrace 會追蹤應用程序運行期間kernel的運作情況
• 通過將0 寫入文件tracing_on 來暫停追蹤信息的記錄，此時追蹤器還在追蹤kernel的運行，只是不再向文件trace 中寫入追蹤信息
• 查看文件trace 獲取追蹤信息，對kernel的運行進行分析偵錯

Function tracer

function 追蹤器可以追蹤kernel函數的調用情況，可用於偵錯或者分析bug ，還可用於了解和觀察Linux kernel 的執行過程。

•  [root@linux tracing]# cat trace | head -10 
•  # tracer: function 
•  # 
•  #         TASK-PID    CPU#    TIMESTAMP  FUNCTION 
•  #            | |       |          |         | 
•           <idle>-0     [000] 20654.426521: _raw_spin_lock <-scheduler_tick 
•           <idle>-0     [000] 20654.426522: task_tick_idle <-scheduler_tick 
•           <idle>-0     [000] 20654.426522: cpumask_weight <-scheduler_tick 
•           <idle>-0     [000] 20654.426523: cpumask_weight <-scheduler_tick 
•           <idle>-0     [000] 20654.426523: run_posix_cpu_timers <-update_process_times 
•  <idle>-0 [000] 20654.426524: hrtimer_forward <-tick_sched_timer

• trace 文件給出的訊息格式說明如下
  • 首先，“tracer:”給出了當前所使用的追蹤器的名字，這裡為function 追蹤器。
  • 然後是追蹤訊息記錄的格式，TASK 對應任務的名稱，PID 則給出了任務的Process ID，CPU# 表示運行被追蹤函數的CPU ，這裡可以看到idle 運行在0 號CPU 上，其PID 是0 
  • TIMESTAMP 是時間標記，其格式為“<secs>.<usecs>”，表示執行該函數時對應的時間標記
  • FUNCTION 一列則顯示了被追蹤的函數，函數的呼叫(call)者通過符號“<-” 標明，這樣可以觀察到函數的呼叫關係。

Function_graph tracer

• 在function tracer給出的訊息中，可以通過FUNCTION 列中的符號“<-” 來查看函數呼叫關係，但是由於中間會混合不同函數的呼叫，導致看起來非常混亂，十分不方便。 
• function_graph 追蹤器則可以提供類似C code的函數呼叫關係訊息。
  • 通過檔案 set_graph_function 可以顯示指定要生成呼叫關係的函數，預設會對所有可追蹤的kernel函數生成函數呼叫關係圖。
• 下圖以kernel函數 __do_fault 作為觀察對象，該函數在kernel運作過程中會被頻繁呼叫。

•  [root@linux tracing]# cat trace | head -20 
•  # tracer: function_graph 
•  # 
•  # CPU  DURATION                  FUNCTION CALLS 
•  # |     |   |                     |   |   |   | 
•  1)   9.936 us    |    } 
•  1)   0.714 us    |    put_prev_task_fair(); 
•  1)               |    pick_next_task_fair() { 
•  1)               |      set_next_entity() { 
•  1)   0.647 us    |        update_stats_wait_end(); 
•  1)   0.699 us    |        __dequeue_entity(); 
•  1)   3.322 us    |      } 
•  1)   0.865 us    |      hrtick_start_fair(); 
•  1)   6.313 us    |    } 
•  1)               |    __switch_to_xtra() { 
•  1)   1.601 us    |      memcpy(); 
•  1)   3.938 us    |    } 
•  [root@linux tracing]# echo > set_graph_function

• 在trace 的輸出訊息中，首先可看到目前使用的追蹤器，這裡是function_graph 。
• 接下來是詳細的追蹤信息，可以看到，函數的調用關係以類似C 代碼的形式組織。
  • CPU 給出了執行函數的CPU 號，上圖為1 號CPU。
  •  DURATION 給出了函數執行的時間長度，以us 為單位。
    • DURATION 給出的時間並不是精確的，它還包含了執行ftrace 自身的code所耗費的時間，所以上圖中將內部函數時間累加得到的結果會與對應的外圍呼叫函數的執行時長並不一致；不過通過DURATION還是可以大致知道函數在時間上的運行成本
  •  FUNCTION CALLS 則給出了呼叫的函數，並顯示了呼叫流程。
    • 注意，對於不呼叫其它函數的函數，其對應行以“;”結尾，而且對應的DURATION 字段給出其運行時長；
    • 對於調用其它函數的函數，則在其“}”對應行給出了運行時長，該時間是一個累加值，包括了其內部調用的函數的執行時長。
  • 最後通過echo 命令重置了檔案 set_graph_function (所有function的追蹤)。

irqsoff tracer

• 看不懂，中斷關閉，CPU就會產生latency?

• 當關閉中斷時，CPU 會延遲對設備的狀態變化做出反應，有時候這樣做會對系統性能造成比較大的影響。 
• irqsoff 追蹤器可以對中斷被關閉的狀況進行追蹤，有助於發現導致較大延遲的code；當出現最大延遲時，追蹤器會記錄導致延遲的追蹤信息，tracing_max_latency 則記錄中斷被關閉的最大延時。
• 原文:

•   "irqsoff"
• 
  
•         Traces the areas that disable interrupts and saves
•         the trace with the longest max latency.
•         See tracing_max_latency. When a new max is recorded,
•         it replaces the old trace. It is best to view this
•         trace with the latency-format option enabled.

•  [root@linux tracing]# cat trace | head -35 
•  # tracer: irqsoff 
•  # 
•  # irqsoff latency trace v1.1.5 on 2.6.33.1 
•  # -------------------------------------------------------------------- 
•  # latency: 34380 us, #6/6, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:2) 
•  #    ----------------- 
•  #    | task: -0 (uid:0 nice:0 policy:0 rt_prio:0) 
•  #    ----------------- 
•  #  => started at: reschedule_interrupt 
•  #  => ended at:   restore_all_notrace 
•  # 
•  # 
•  #                  _------=> CPU#            
•  #                 / _-----=> irqs-off        
•  #                | / _----=> need-resched    
•  #                || / _---=> hardirq/softirq 
•  #                ||| / _--=> preempt-depth   
•  #                |||| /_--=> lock-depth       
•  #                |||||/     delay             
•  #  cmd    pid    |||||| time  |   caller      
•  #    \   /       ||||||   \   |   /           
•   <idle>-0       1dN... 4285us!: trace_hardirqs_off_thunk <-reschedule_interrupt 
•   <idle>-0       1dN... 34373us+: smp_reschedule_interrupt <-reschedule_interrupt 
•   <idle>-0       1dN... 34375us+: native_apic_mem_write <-smp_reschedule_interrupt 
•   <idle>-0       1dN... 34380us+: trace_hardirqs_on_thunk <-restore_all_notrace 
•   <idle>-0       1dN... 34384us : trace_hardirqs_on_caller <-restore_all_notrace 
•   <idle>-0       1dN... 34384us : <stack trace> 
•  => trace_hardirqs_on_thunk 
•  [root@linux tracing]# cat tracing_max_latency 
•  34380
•  

Trace指定Module中的函數

• 實際情況是: 不知道要去 trace 哪個 function?

• 通過 set_ftrace_filter 可以指定要trace的函數，預設目標為所有可trace的kernel函數
  • 使用 echo 進行寫入
  • set_ftrace_filter 文件支援簡單的萬用字元
    • begin* 選擇所有名字以begin 字串開頭的函數
    • *middle* 選擇所有名字中包含middle 字串的函數
    • *end 選擇所有名字以end 字串結尾的函數
    • 這三種形式不能組合使用，比如“begin*middle*end”實際的效果與“begin”相同。另外，使用萬用字元表達式時，需要用單引號將其括起來，如果使用雙引號，shell 可能會對字符’ * ’進行擴展，這樣最終trace的對象可能與目標函數不一樣。
  • set_ftrace_filter 還可以指定屬於特定Module的函數，這要用到mod 指令。指定Module的格式為：

•    echo ’:mod:[module_name]’ > set_ftrace_filter

Trace Event

• Ref: Trace event 簡介 
• 一個 Ftrace 最常見用法是 event tracing
  • 有幾百個 static event points 通過kernel 我們可以藉由enabled debugfs file system 去看到kernel中某些部份發生了甚麼事情
• debugfs默認是掛載在/sys/kernel/debug下，可以通過debugfs下的tracing/events查看各個event。

• 以下是跟scheduling相關的event

• 操作步驟範例

• echo 0 > /sys/kernel/debug/tracing/tracing_on
• echo 0 > /sys/kernel/debug/tracing/trace
• echo nop > /sys/kernel/debug/tracing/current_tracer
• echo 1 > /sys/kernel/debug/tracing/events/sched/enable
• echo 0 > /sys/kernel/debug/tracing/events/syscalls/enable
• echo 1 > /sys/kernel/debug/tracing/tracing_on
• nohup chrt -r 90 ./matrix_mul &
• pid1=$!
• nohup chrt -r 90 ./matrix_mul &
• pid2=$!
• wait $pid1 $pid2
• echo 0 > /sys/kernel/debug/tracing/tracing_on
• cat /sys/kernel/debug/tracing/trace 

• 結果

• 下面就第三列的字段進行簡介： 
  • – irqs-off選項可能出現這些值：
    • ’d’ : 關中斷
    • ’.’ : 其他
  • – need-resched選項可能出現這些值：
    • ’N’ : need_resched標誌被設置
    • ’.’ : 其他
  • – hardirq/softirq選項可能出現這些值：
    • ’H’ : 在softirq中發生了一次中斷(hard irq) 
    • ’h’ : 正在處理中斷(hard irq) 
    • ’s’ : 正在處理soft irq 
    • ’.’ : 其他
  • – preempt-depth : preempt_disabled的深度

Ftrace on x86 PC

測試環境的 Linux kernel version

• 使用以下指令得到 kernel的資訊

• $ uname -r
• $ uname -a
• $ cat /proc/version

• Kuro’s PC  Ubuntu 15.04
  • 3.19.0-15-generic
  • Linux jared14-5480 3.16.0-23-generic #31-Ubuntu SMP Tue Oct 21 17:57:39 UTC 2014 armv7l GNU/Linux
  • Linux version 3.19.0-15-generic (buildd@komainu) (gcc version 4.9.2 (Ubuntu 4.9.2-10ubuntu13) ) #15-Ubuntu SMP Thu Apr 16 23:32:37 UTC 2015

• QEMU/ARM環境
  • Linux kuro-BM6630-BM6330-BP6230 3.19.0-15-generic #15-Ubuntu SMP Thu Apr 16 23:32:37 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
  • Linux version 3.16.0-23-generic (buildd@kishi01) (gcc version 4.9.1 (Ubuntu/Linaro 4.9.1-16ubuntu6) ) #31-Ubuntu SMP Tue Oct 21 17:57:39 UTC 2014
  • 使用 trace-cmd 做關於中斷的分析

Ftrace on BeagleBone Black (ARM)

• 硬體平台: BeagleBone Black(BBB) Rev.C
  • Core Architecture: ARM
  • Core Sub-Architecture: Cortex-A8
  • Silicon Core Number:  AM335x 1GHz ARM® Cortex-A8
• 在BBB上安裝的Linux Kernel version:  .config - Linux/arm 3.8.13 Kernel 

• Rebuild kernel in BBB
  • 由於我們要在BBB上使用Linux，因此在重編Kernel之後可以使用以下 tracer
  • 到kernel資料夾底下，重編指令，`make menuconfig ARCH=arm -j4`，即可進入config畫面
    • wakeup_rt 
    • wakeup 
    • irqsoff 
    • function 

trace-cmd

他是user space front end command line tool for ftrace，有一些distribution將trace-cmd裝成package，就ubuntu 14.10來講，可以透過`apt-get install`安裝，裝完就可以使用了

• sudo apt-get install trace-cmd

基本使用方式

簡單的方式就是先紀錄後報告

下面的這個指令是，enables the ext4 tracepoints for Ftrace，然後用`ls`指令是因為紀錄ftrace data進入trace.dat，然後在透過report指令參數，讀取trace.dat的結果，然後輸出

• root@garygu-Aspire-4830TG:~# trace-cmd record -e ext4 ls
• /sys/kernel/debug/tracing/events/ext4/filter
• /sys/kernel/debug/tracing/events/*/ext4/filter
• trace.dat.cpu0        trace.dat.cpu1        trace.dat.cpu2        trace.dat.cpu3
• Kernel buffer statistics:
•   Note: "entries" are the entries left in the kernel ring buffer and are not
•         recorded in the trace data. They should all be zero.
• 
  
• CPU: 0
• entries: 0
• overrun: 0
• commit overrun: 0
• bytes: 444
• oldest event ts: 12041.827184
• now ts: 12041.829362
• dropped events: 0
• read events: 11
• 
  
• CPU: 1
• entries: 0
• overrun: 0
• commit overrun: 0
• bytes: 756
• oldest event ts: 12041.826906
• now ts: 12041.829397
• dropped events: 0
• read events: 19
• 
  
• CPU: 2
• entries: 0
• overrun: 0
• commit overrun: 0
• bytes: 604
• oldest event ts: 12041.827041
• now ts: 12041.829426
• dropped events: 0
• read events: 15
• 
  
• CPU: 3
• entries: 0
• overrun: 0
• commit overrun: 0
• bytes: 0
• oldest event ts: 11939.099107
• now ts: 12041.829453
• dropped events: 0
• read events: 0
• 
  
• CPU0 data recorded at offset=0x4ee000
•     4096 bytes in size
• CPU1 data recorded at offset=0x4ef000
•     4096 bytes in size
• CPU2 data recorded at offset=0x4f0000
•     4096 bytes in size
• CPU3 data recorded at offset=0x4f1000
•     0 bytes in size
• root@garygu-Aspire-4830TG:~# trace-cmd report
• version = 6
• CPU 3 is empty
• cpus=4
•        trace-cmd-26790 [001] 12041.826906: ext4_journal_start:   dev 8,1 blocks, 35 rsv_blocks, 0 caller __ext4_new_inode+0x595
•        trace-cmd-26790 [001] 12041.826941: ext4_mark_inode_dirty: dev 8,1 ino 26214438 caller ext4_ext_tree_init+0x3a
•        trace-cmd-26790 [001] 12041.826949: ext4_mark_inode_dirty: dev 8,1 ino 26214438 caller __ext4_new_inode+0xff1
•        trace-cmd-26790 [001] 12041.826952: ext4_allocate_inode:  dev 8,1 ino 26214438 dir 26214401 mode 0>o<
•        trace-cmd-26790 [001] 12041.826955: ext4_es_lookup_extent_enter: dev 8,1 ino 26214401 lblk 0
•        trace-cmd-26790 [001] 12041.826956: ext4_es_lookup_extent_exit: dev 8,1 ino 26214401 found 1 [0/1) 10486

KernelShark

kernelshark是trace-cmd的前端讀取工具，他專門讀取trace.dat的資料，然後將結果用圖形化的方式呈現出來，他預設讀取檔案就是trace.dat，然後這個kernelshark也是ubuntu可以安裝的套件，裝完就可以使用了，只需要下達`kernelshark`就可以自動讀取trace.dat的資料，然後圖示化結果

• sudo apt-get install kernelshark

下圖就是我將上面trace ext4的結果，圖像畫出來

Graph info area的介紹

Pointer表示目前我滑鼠所移到的位置，他是表示這前游標指的timestamp

Cursor表示目前游標位置的timestamp，透過double click left mouse

MarkerA，可以在圖上標明標記，markerA標記方式是透過click on the graph

MarkerB，標記方式是透過left mouse click while holding down the shift key

A,B Delta，是算這兩個marker之間的差距，單位是秒，精確度可以到microseconds

在圖示的部份，可以切開成兩個部份，上圖是顯示，CPU或是TASK，另一部份就是對應的TRACE data plot出來的結果，如下圖

如果將游標移向圖表上，可以顯示目前這依區段是什麼task和相關的information，如下圖

另外在下面有一個區塊是list area，這依區塊其實就是上面的圖形資料，只是比較詳細，所以通常是搭配看，還有可以看到Page這個選項，是因為每一個最大可以放的資料有限，所以需要分頁放(1 million)，還有也可以作search，我們可以在Column選一個欄位出來，在選match的標準，有`contains` `all match` `does not have`那選完之後就可以在後面的控格填入你要的資訊，後面一個graph follows是當我點選list中一個選項，我圖形的marker就會移到對應的位置

• 有一點值得提醒的事，這邊的timestamp是以秒為單位，但是精準度可以到microseconds
• latency欄位
• Latency -  The latency is broken into 5 fields:   
  • Interrupts disabled - ’d’ if interrupts are disabled, otherwise ’.’     
  • Need reschedule - ’N’ if the kernel was notified that a schedule is needed, otherwise ’.’     
  • In IRQ - ’h’ if in a hard IRQ (hardware triggered), ’s’ if in a soft IRQ       (context where the kernel initiated a the IRQ handler) or if soft IRQs       are disabled, ’H’ if in a hard IRQ and soft IRQs are disabled or the hard IRQ       triggered while processing a soft IRQ, otherwise ’.’     
  • Preemption counter - The index of the preemption counter. If it is other       than zero, then the kernel will not preempt the running tasks, even       if a schedule has been requested by some event. If the counter is zero,       then ’.’ is shown.     
  • Lock depth - The depth of the big kernel lock being held. The big kernel       lock is recursive (same task may acquire it multiple times). On the first       acquisition, the depth is zero. This field will be zero or greater, or       ’.’ if the big kernel lock is not held. When the big kernel lock is       finally removed from the kernel, this field will go away as well.   

工具的使用

• Zooming in

• 將滑鼠左鍵按下再向右邊移動就可以做到zoom in的動作，好處是可以看到細部的資料

• Zooming out

• 將滑鼠左鍵按下再像左移動就可以做到zoom out的動作

我們可能想要針對某個CPU或是某個task去看他的data plot，這時可以透過Plot menu去作選擇，點選了之後就可以選擇想要觀察的task或是cpu最後在apply就行了，這些步驟都相當容易，所以就不放圖示說明了

關於task plot的顏色變換，主要是看那時候是哪個cpu執行的，還有CPU顏色的變換，也是看當時是在處理哪一個task，有一個比較特別的顏色是hollow green，如下圖

這種是表示某一個task他從sleep state被喚醒到running state，那如果是hollow red，則表示這個task他被其他task給搶佔了

那從這邊就可以看出這個工具的好處，我們可以搭配A,B marker來幫助我們set up出某個task他的wake up latency section，計算出時間

Ftrace和Trace-cmd + KernelShark 綜合使用方式

• event tracer: 當需要對對特定事件去觀察時, 使用event tracer較能看出事件發生的影響.  而且只trace特定事件, tracer開啟時對於系統效能的影響較小

• 使用方式: 
  • mount -t debugfs debugfs /sys/kernel/debug/
  • cd /sys/kernel/debug/tracing
  • cat available_events (列出目前能使用的event)
  • echo "irq==21" > events/irq/irq_handler_entry/filter (設定irq_handler_entry事件的 filter條件)
  • echo "irq==21" > events/irq/irq_handler_exit/filter (設定irq_handler_exit事件的 filter條件)
  • echo 1 > events/irq/irq_handler_entry/enable (開啟irq_handler_entry event)
  • echo 1 > events/irq/irq_handler_exit/enable (開啟irq_handler_entry event)

• trace-cmd + kernelshark: 利用trace-cmd擷取trace資料並用kernelshark圖形化表示

• 以trace-cmd record持續紀錄trace data
  • ./trace-cmd record -e irq_handler_entry -f "irq==21"  -e irq_handler_exit -f "irq==21"
• 按ctrl + c 中止紀錄
• 使用kernelshark載入trace.data

Reference

1. 第一手資料
   • Ftrace
     • Linux Kernel原始碼中位於Documentation/ftrace.txt的文件
   • Event Tracing
   • Ftrace-design
   • Finding Origins of Latencies Using Ftrace

1. ftrace - Wikipedia
2. ftrace - elinux
3. Android筆記-Linux Kernel Ftrace (Function Trace)解析
   1. 感覺看這有點幫助!!在這找到 討論有關利用工具來分析linux系統資訊
4. Debugging the kernel using Ftrace
   1. part 1
   2. part 2
   3. trace-cmd: A front-end for Ftrace 
5. 大陸資料參考
   1. 使用 ftrace 调试 Linux 内核(詳細，但資料較舊，僅供參考)
      1. part1
      2. part2
      3. part3
   2. 内核性能调试–ftrace
   3. 如何使用ftrace进行内核调试
   4. 调试利器trace event简介
6. Kernel基礎複習 - 鳥哥
   1. 第二十六章、Linux 核心編譯與管理
   2. 核心( kernel )編譯與模組管理 - vbird
   3. 核心編譯(kernel)
7. 其他共筆
   1. ARM Linux Kernel 基礎知識(待補)
   2. Linux Scheduling(待補)

Trace 对于软件的维护和性能分析至关重要，ftrace 是当前 Linux 内核中一种新的 trace 工具。本文介绍 ftrace 的使用和实现原理，并将 ftrace 和 systemTap，LTTng 等软件进行对比，希望读者能够对 ftrace 有一个全面的了解。

2 评论：