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
  • 在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. 第一手資料
  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 有一个全面的了解。

刘 明 (ovis_poly@sina.com), 软件工程师, 上海交通大学电子与通信工程系

2009 年 10 月 15 日

  • expand内容

ftrace 简介

ftrace 的作用是帮助开发人员了解 Linux 内核的运行时行为,以便进行故障调试或性能分析。

最早 ftrace 是一个 function tracer,仅能够记录内核的函数调用流程。如今 ftrace 已经成为一个 framework,采用 plugin 的方式支持开发人员添加更多种类的 trace 功能。

Ftrace 由 RedHat 的 Steve Rostedt 负责维护。到 2.6.30 为止,已经支持的 tracer 包括:

Function tracer 和 Function graph tracer: 跟踪函数调用。

Schedule switch tracer: 跟踪进程调度情况。

Wakeup tracer:跟踪进程的调度延迟,即高优先级进程从进入 ready 状态到获得 CPU 的延迟时间。该 tracer 只针对实时进程。

Irqsoff tracer:当中断被禁止时,系统无法相应外部事件,比如键盘和鼠标,时钟也无法产生 tick 中断。这意味着系统响应延迟,irqsoff 这个 tracer 能够跟踪并记录内核中哪些函数禁止了中断,对于其中中断禁止时间最长的,irqsoff 将在 log 文件的第一行标示出来,从而使开发人员可以迅速定位造成响应延迟的罪魁祸首。

Preemptoff tracer:和前一个 tracer 类似,preemptoff tracer 跟踪并记录禁止内核抢占的函数,并清晰地显示出禁止抢占时间最长的内核函数。

Preemptirqsoff tracer: 同上,跟踪和记录禁止中断或者禁止抢占的内核函数,以及禁止时间最长的函数。

Branch tracer: 跟踪内核程序中的 likely/unlikely 分支预测命中率情况。 Branch tracer 能够记录这些分支语句有多少次预测成功。从而为优化程序提供线索。

Hardware branch tracer:利用处理器的分支跟踪能力,实现硬件级别的指令跳转记录。在 x86 上,主要利用了 BTS 这个特性。

Initcall tracer:记录系统在 boot 阶段所调用的 init call 。

Mmiotrace tracer:记录 memory map IO 的相关信息。

Power tracer:记录系统电源管理相关的信息。

Sysprof tracer:缺省情况下,sysprof tracer 每隔 1 msec 对内核进行一次采样,记录函数调用和堆栈信息。

Kernel memory tracer: 内存 tracer 主要用来跟踪 slab allocator 的分配情况。包括 kfree,kmem_cache_alloc 等 API 的调用情况,用户程序可以根据 tracer 收集到的信息分析内部碎片情况,找出内存分配最频繁的代码片断,等等。

Workqueue statistical tracer:这是一个 statistic tracer,统计系统中所有的 workqueue 的工作情况,比如有多少个 work 被插入 workqueue,多少个已经被执行等。开发人员可以以此来决定具体的 workqueue 实现,比如是使用 single threaded workqueue 还是 per cpu workqueue.

Event tracer: 跟踪系统事件,比如 timer,系统调用,中断等。

这里还没有列出所有的 tracer,ftrace 是目前非常活跃的开发领域,新的 tracer 将不断被加入内核。

ftrace 与其他 trace 工具的关系和比较

Ftrace 最初是在 2.6.27 中出现的,那个时候,systemTap 已经开始崭露头角,其他的 trace 工具包括 LTTng 等也已经发展多年。那为什么人们还要再开发一个 trace 工具呢?

SystemTap 项目是 Linux 社区对 SUN Dtrace 的反应,目标是达到甚至超越 Dtrace 。因此 SystemTap 设计比较复杂,Dtrace 作为 SUN 公司的一个项目开发了多年才最终稳定发布,况且得到了 Solaris 内核中每个子系统开发人员的大力支持。 SystemTap 想要赶超 Dtrace,困难不仅是一样,而且更大,因此她始终处在不断完善自身的状态下,在真正的产品环境,人们依然无法放心的使用她。不当的使用和 SystemTap 自身的不完善都有可能导致系统崩溃。

Ftrace 的设计目标简单,本质上是一种静态代码插装技术,不需要支持某种编程接口让用户自定义 trace 行为。静态代码插装技术更加可靠,不会因为用户的不当使用而导致内核崩溃。 ftrace 代码量很小,稳定可靠。实际上,即使是 Dtrace,大多数用户也只使用其静态 trace 功能。因此 ftrace 的设计非常务实。

从 2.6.30 开始,ftrace 支持 event tracer,其实现和功能与 LTTng 非常类似,或许将来 ftrace 会同 LTTng 进一步融合,各自取长补短。 ftrace 有定义良好的 ASCII 接口,可以直接阅读,这对于内核开发人员非常具有吸引力,因为只需内核代码加上 cat 命令就可以工作了,相当方便; LTTng 则采用 binary 接口,更利于专门工具分析使用。此外他们内部 ring buffer 的实现不相同,ftrace 对所有 tracer 都采用同一个 ring buffer,而 LTTng 则使用各自不同的 ring buffer 。

目前,或许将来 LTTng 都只能是内核主分支之外的工具。她主要受到嵌入式工程师的欢迎,而内核开发人员则更喜欢 ftrace 。

Ftrace 的实现依赖于其他很多内核特性,比如 tracepoint[3],debugfs[2],kprobe[4],IRQ-Flags[5] 等。限于篇幅,关于这些技术的介绍请读者自行查阅相关的参考资料。

ftrace 的使用

ftrace 在内核态工作,用户通过 debugfs 接口来控制和使用 ftrace 。从 2.6.30 开始,ftrace 支持两大类 tracer:传统 tracer 和 Non-Tracer Tracer 。下面将分别介绍他们的使用。

传统 Tracer 的使用

使用传统的 ftrace 需要如下几个步骤:

  • 选择一种 tracer
  • 使能 ftrace
  • 执行需要 trace 的应用程序,比如需要跟踪 ls,就执行 ls
  • 关闭 ftrace
  • 查看 trace 文件

用户通过读写 debugfs 文件系统中的控制文件完成上述步骤。使用 debugfs,首先要挂载她。命令如下:

# mkdir /debug 
 # mount -t debugfs nodev /debug

此时您将在 /debug 目录下看到 tracing 目录。 Ftrace 的控制接口就是该目录下的文件。

选择 tracer 的控制文件叫作 current_tracer 。选择 tracer 就是将 tracer 的名字写入这个文件,比如,用户打算使用 function tracer,可输入如下命令:

#echo ftrace > /debug/tracing/current_tracer

文件 tracing_enabled 控制 ftrace 的开始和结束。

#echo 1 >/debug/tracing/tracing_enable

上面的命令使能 ftrace 。同样,将 0 写入 tracing_enable 文件便可以停止 ftrace 。

ftrace 的输出信息主要保存在 3 个文件中。

  • Trace,该文件保存 ftrace 的输出信息,其内容可以直接阅读。
  • latency_trace,保存与 trace 相同的信息,不过组织方式略有不同。主要为了用户能方便地分析系统中有关延迟的信息。
  • trace_pipe 是一个管道文件,主要为了方便应用程序读取 trace 内容。算是扩展接口吧。

下面详细解析各种 tracer 的输出信息。

Function tracer 的输出

Function tracer 跟踪函数调用流程,其 trace 文件格式如下:

# tracer: function 
 # 
 #  TASK-PID   CPU#    TIMESTAMP        FUNCTION 
 #   |  |       |          |                | 
  bash-4251  [01]  10152.583854:    path_put <-path_walk 
  bash-4251  [01] 10152.583855: dput <-path_put 
  bash-4251  [01] 10152.583855: _atomic_dec_and_lock <-dput

可以看到,tracer 文件类似一张报表,前 4 行是表头。第一行显示当前 tracer 的类型。第三行是 header 。

对于 function tracer,该表将显示 4 列信息。首先是进程信息,包括进程名和 PID ;第二列是 CPU,在 SMP 体系下,该列显示内核函数具体在哪一个 CPU 上执行;第三列是时间戳;第四列是函数信息,缺省情况下,这里将显示内核函数名以及它的上一层调用函数。

通过对这张报表的解读,用户便可以获得完整的内核运行时流程。这对于理解内核代码也有很大的帮助。有志于精读内核代码的读者,或许可以考虑考虑 ftrace 。

如上例所示,path_walk() 调用了 path_put 。此后 path_put 又调用了 dput,进而 dput 再调用 _atomic_dec_and_lock 。

Schedule switch tracer 的输出

Schedule switch tracer 记录系统中的进程切换信息。在其输出文件 trace 中 , 输出行的格式有两种:

第一种表示进程切换信息:

Context switches: 
       Previous task              Next Task 
  <pid>:<prio>:<state>  ==>  <pid>:<prio>:<state>

第二种表示进程 wakeup 的信息:

	Wake ups: 
       Current task               Task waking up 
  <pid>:<prio>:<state>    +  <pid>:<prio>:<state>

这里举一个实例:

# tracer: sched_switch 
 # 
 #  TASK_PID   CPU#     TIMESTAMP             FUNCTION 
 #     |         |            |                  | 
   fon-6263  [000] 4154504638.932214:  6263:120:R +   2717:120:S 
   fon-6263  [000] 4154504638.932214:  6263:120:? ==> 2717:120:R 
   bash-2717 [000] 4154504638.932214:  2717:120:S +   2714:120:S

第一行表示进程 fon 进程 wakeup 了 bash 进程。其中 fon 进程的 pid 为 6263,优先级为 120,进程状态为 Ready 。她将进程 ID 为 2717 的 bash 进程唤醒。

第二行表示进程切换发生,从 fon 切换到 bash 。

irqsoff tracer 输出

有四个 tracer 记录内核在某种状态下最长的时延,irqsoff 记录系统在哪里关中断的时间最长; preemptoff/preemptirqsoff 以及 wakeup 分别记录禁止抢占时间最长的函数,或者系统在哪里调度延迟最长 (wakeup) 。这些 tracer 信息对于实时应用具有很高的参考价值。

为了更好的表示延迟,ftrace 提供了和 trace 类似的 latency_trace 文件。以 irqsoff 为例演示如何解读该文件的内容。

# tracer: irqsoff 
 irqsoff latency trace v1.1.5 on 2.6.26 
 -------------------------------------------------------------------- 
 latency: 12 us, #3/3, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2) 
    ----------------- 
    | task: bash-3730 (uid:0 nice:0 policy:0 rt_prio:0) 
    ----------------- 
 => started at: sys_setpgid 
 => ended at:   sys_setpgid 
 #                _------=> CPU# 
 #               / _-----=> irqs-off 
 #              | / _----=> need-resched 
 #              || / _---=> hardirq/softirq 
 #              ||| / _--=> preempt-depth 
 #              |||| / 
 #              |||||     delay 
 #  cmd     pid ||||| time  |   caller 
 #     \   /    |||||   \   |   / 
    bash-3730  1d...    0us : _write_lock_irq (sys_setpgid) 
    bash-3730  1d..1    1us+: _write_unlock_irq (sys_setpgid) 
    bash-3730  1d..2   14us : trace_hardirqs_on (sys_setpgid)

在文件的头部,irqsoff tracer 记录了中断禁止时间最长的函数。在本例中,函数 trace_hardirqs_on 将中断禁止了 12us 。

文件中的每一行代表一次函数调用。 Cmd 代表进程名,pid 是进程 ID 。中间有 5 个字符,分别代表了 CPU#,irqs-off 等信息,具体含义如下:

CPU# 表示 CPU ID ;

irqs-off 这个字符的含义如下:’ d ’表示中断被 disabled 。’ . ’表示中断没有关闭;

need-resched 字符的含义:’ N ’表示 need_resched 被设置,’ . ’表示 need-reched 没有被设置,中断返回不会进行进程切换;

hardirq/softirq 字符的含义 : 'H' 在 softirq 中发生了硬件中断, 'h' – 硬件中断,’ s ’表示 softirq,’ . ’不在中断上下文中,普通状态。

preempt-depth: 当抢占中断使能后,该域代表 preempt_disabled 的级别。

在每一行的中间,还有两个域:time 和 delay 。 time: 表示从 trace 开始到当前的相对时间。 Delay 突出显示那些有高延迟的地方以便引起用户注意。当其显示为 ! 时,表示需要引起注意。

function graph tracer 输出

Function graph tracer 和 function tracer 类似,但输出为函数调用图,更加容易阅读:

# tracer: function_graph 
 # 
 # CPU  OVERHEAD/DURATION      FUNCTION CALLS 
 # |     |   |                 |   |   |   | 
 0)               |  sys_open() { 
 0)               |    do_sys_open() { 
 0)               |      getname() { 
 0)               |        kmem_cache_alloc() { 
 0)   1.382 us    |          __might_sleep(); 
 0)   2.478 us    |        } 
 0)               |        strncpy_from_user() { 
 0)               |          might_fault() { 
 0)   1.389 us    |            __might_sleep(); 
 0)   2.553 us    |          } 
 0)   3.807 us    |        } 
 0)   7.876 us    |      } 
 0)                |      alloc_fd() { 
 0)   0.668 us    |        _spin_lock(); 
 0)   0.570 us    |        expand_files(); 
 0)   0.586 us    |        _spin_unlock();

OVERHEAD 为 ! 时提醒用户注意,该函数的性能比较差。上面的例子中可以看到 sys_open 调用了 do_sys_open,依次又调用了 getname(),依此类推。

Sysprof tracer 的输出

Sysprof tracer 定时对内核进行采样,她的输出文件中记录了每次采样时内核正在执行哪些内核函数,以及当时的内核堆栈情况。

每一行前半部分的格式和 3.1.1 中介绍的 function tracer 一样,只是,最后一部分 FUNCTION 有所不同。

Sysprof tracer 中,FUNCTION 列格式如下:

Identifier  address frame_pointer/pid

当 identifier 为 0 时,代表一次采样的开始,此时第三个数字代表当前进程的 PID ;

Identifier 为 1 代表内核态的堆栈信息;当 identifier 为 2 时,代表用户态堆栈信息;显示堆栈信息时,第三列显示的是 frame_pointer,用户可能需要打开 system map 文件查找具体的符号,这是 ftrace 有待改进的一个地方吧。

当 identifier 为 3 时,代表一次采样结束。

Non-Tracer Tracer 的使用

从 2.6.30 开始,ftrace 还支持几种 Non-tracer tracer,所谓 Non-tracer tracer 主要包括以下几种:

  • Max Stack Tracer
  • Profiling (branches / unlikely / likely / Functions)
  • Event tracing

和传统的 tracer 不同,Non-Tracer Tracer 并不对每个内核函数进行跟踪,而是一种类似逻辑分析仪的模式,即对系统进行采样,但似乎也不完全如此。无论怎样,这些 tracer 的使用方法和前面所介绍的 tracer 的使用稍有不同。下面我将试图描述这些 tracer 的使用方法。

Max Stack Tracer 的使用

这个 tracer 记录内核函数的堆栈使用情况,用户可以使用如下命令打开该 tracer:

# echo 1 > /proc/sys/kernel/stack_tracer_enabled

从此,ftrace 便留心记录内核函数的堆栈使用。 Max Stack Tracer 的输出在 stack_trace 文件中:

# cat /debug/tracing/stack_trace 
 Depth Size Location (44 entries) 
 ----- ---- -------- 
 0) 3088 64 update_curr+0x64/0x136 
 1) 3024 64 enqueue_task_fair+0x59/0x2a1 
 2) 2960 32 enqueue_task+0x60/0x6b 
 3) 2928 32 activate_task+0x27/0x30 
 4) 2896 80 try_to_wake_up+0x186/0x27f 
…
 42)  80 80 sysenter_do_call+0x12/0x32

从上例中可以看到内核堆栈最满的情况如下,有 43 层函数调用,堆栈使用大小为 3088 字节。此外还可以在 Location 这列中看到整个的 calling stack 情况。这在某些情况下,可以提供额外的 debug 信息,帮助开发人员定位问题。

Branch tracer

Branch tracer 比较特殊,她有两种模式,即是传统 tracer,又实现了 profiling tracer 模式。

作为传统 tracer 。其输出文件为 trace,格式如下:

# tracer: branch 
 # 
 #  TASK-PID   CPU#    TIMESTAMP        FUNCTION 
 #    |   |        |          |                | 
  Xorg-2491   [000] 688.561593: [ ok ] fput_light:file.h:29 
  Xorg-2491   [000] 688.561594: [ ok ] fput_light:file_table.c:330

在 FUNCTION 列中,显示了 4 类信息:

函数名,文件和行号,用中括号引起来的部分,显示了分支的信息,假如该字符串为 ok,表明 likely/unlikely 返回为真,否则字符串为 MISS 。举例来说,在文件 file.h 的第 29 行,函数 fput_light 中,有一个 likely 分支在运行时解析为真。我们看看 file.h 的第 29 行:

static inline void fput_light(struct file *file, int fput_needed) 
 {LINE29:    if (unlikely(fput_needed)) 
                  fput(file); 
 }

Trace 结果告诉我们,在 688 秒的时候,第 29 行代码被执行,且预测结果为 ok,即 unlikely 成功。

Branch tracer 作为 profiling tracer 时,其输出文件为 profile_annotated_branch,其中记录了 likely/unlikely 语句完整的统计结果。

#cat trace_stat/branch_ annotated 
 correct incorrect    %      function            file        line 
 ------- ----------  ---- ------------------ -------------- ----- 
 0      46             100   pre_schedule_rt    sched_rt.c     1449

下面是文件 sched_rt.c 的第 1449 行的代码:

	if (unlikely(rt_task(prev)) && rq->rt.highest_prio.curr > prev->prio) 
    pull_rt_task(rq);

记录表明,unlikely 在这里有 46 次为假,命中率为 100% 。假如为真的次数更多,则说明这里应该改成 likely 。

Workqueue profiling

假如您在内核编译时选中该 tracer,ftrace 便会统计 workqueue 使用情况。您只需使用下面的命令查看结果即可:

#cat /debug/tracing/trace_stat/workqueue

典型输出如下:

# CPU INSERTED  EXECUTED  NAME 
 #  |     |         |           | 
   0   38044    38044    events/0 
   0     426      426    khelper 
   0    9853     9853    kblockd/0 
   0       0        0    kacpid 
…

可以看到 workqueue events 在 CPU 0 上有 38044 个 worker 被插入并执行。

Event tracer

Event tracer 不间断地记录内核中的重要事件。用户可以用下面的命令查看 ftrace 支持的事件。

#cat /debug/tracing/available_event

下面以跟踪进程切换为例讲述 event tracer 的使用。首先打开 event tracer,并记录进程切换:

# echo sched:sched_switch >> /debug/tracing/set_event 
 # echo sched_switch >> /debug/tracing/set_event 
 # echo 1 > /debug/tracing/events/sched/sched_switch/enable

上面三个命令的作用是一样的,您可以任选一种。

此时可以查看 ftrace 的输出文件 trace:

>head trace 
 # tracer: nop 
 # 
 #   TASK-PID CPU#  TIMESTAMP FUNCTION 
 #    | |      |     |             | 
 <idle>-0 [000] 12093.091053: sched_switch: task swapper:0 [140] ==> 
  /user/bin/sealer:2612 [120]

我想您会发现该文件很容易解读。如上例,表示一个进程切换 event,从 idle 进程切换到 sealer 进程。

ftrace 的实现

研究 tracer 的实现是非常有乐趣的。理解 ftrace 的实现能够启发我们在自己的系统中设计更好的 trace 功能。

ftrace 的整体构架

Ftrace 的整体构架:

图 1. ftrace 组成
ftrace 组成

Ftrace 有两大组成部分,一是 framework,另外就是一系列的 tracer 。每个 tracer 完成不同的功能,它们统一由 framework 管理。 ftrace 的 trace 信息保存在 ring buffer 中,由 framework 负责管理。 Framework 利用 debugfs 系统在 /debugfs 下建立 tracing 目录,并提供了一系列的控制文件。

本文并不打算系统介绍 tracer 和 ftrace framework 之间的接口,只是打算从纯粹理论的角度,简单剖析几种具体 tracer 的实现原理。假如读者需要开发新的 tracer,可以参考某个 tracer 的源代码。

Function tracer 的实现

Ftrace 采用 GCC 的 profile 特性在所有内核函数的开始部分加入一段 stub 代码,ftrace 重载这段代码来实现 trace 功能。

gcc 的 -pg 选项将在每个函数入口处加入对 mcount 的调用代码。比如下面的 C 代码。

清单 1. test.c
//test.c 
 void foo(void) 
 { 
   printf( “ foo ” ); 
 }

用 gcc 编译:

gcc – S test.c

反汇编如下:

清单 2. test.c 不加入 pg 选项的汇编代码
	_foo: 
        pushl   %ebp 
        movl    %esp, %ebp 
        subl    $8, %esp 
        movl    $LC0, (%esp) 
        call    _printf 
        leave 
        ret

再加入 -gp 选项编译:

gcc – pg – S test.c

得到的汇编如下:

清单 3. test.c 加入 pg 选项后的汇编代码
_foo: 
        pushl   %ebp 
        movl    %esp, %ebp 
        subl    $8, %esp 
 LP3: 
        movl    $LP3,%edx 
        call    _mcount 
        movl    $LC0, (%esp) 
        call    _printf 
        leave 
        ret

增加 pg 选项后,gcc 在函数 foo 的入口处加入了对 mcount 的调用:call _mcount 。原本 mcount 由 libc 实现,但您知道内核不会连接 libc 库,因此 ftrace 编写了自己的 mcount stub 函数,并借此实现 trace 功能。

在每个内核函数入口加入 trace 代码,必然会影响内核的性能,为了减小对内核性能的影响,ftrace 支持动态 trace 功能。

当 CONFIG_DYNAMIC_FTRACE 被选中后,内核编译时会调用一个 perl 脚本:recordmcount.pl 将每个函数的地址写入一个特殊的段:__mcount_loc

在内核初始化的初期,ftrace 查询 __mcount_loc 段,得到每个函数的入口地址,并将 mcount 替换为 nop 指令。这样在默认情况下,ftrace 不会对内核性能产生影响。

当用户打开 ftrace 功能时,ftrace 将这些 nop 指令动态替换为 ftrace_caller,该函数将调用用户注册的 trace 函数。其具体的实现在相应 arch 的汇编代码中,以 x86 为例,在 entry_32.s 中:

清单 4. entry_32.s
	ENTRY(ftrace_caller) 
       cmpl $0, function_trace_stop 
       jne  ftrace_stub 
       pushl %eax 
       pushl %ecx 
       pushl %edx 
       movl 0xc(%esp), %eax 
       movl 0x4(%ebp), %edx 
       subl $MCOUNT_INSN_SIZE, %eax 
 .globl ftrace_call 
 ftrace_call: 
       call ftrace_stubline 10popl %edx 
       popl %ecx 
       popl %eax 

 .globl ftrace_stub 
 ftrace_stub: 
       ret 
 END(ftrace_caller)

Function tracer 将 line10 这行代码替换为 function_trace_call() 。这样每个内核函数都将调用 function_trace_call() 。

在 function_trace_call() 函数内,ftrace 记录函数调用堆栈信息,并将结果写入 ring buffer,稍后,用户可以通过 debugfs 的 trace 文件读取该 ring buffer 中的内容。

Irqsoff tracer 的实现

Irqsoff tracer 的实现依赖于 IRQ-Flags 。 IRQ-Flags 是 Ingo Molnar 维护的一个内核特性。使得用户能够在中断关闭和打开时得到通知,ftrace 重载了其通知函数,从而能够记录中断禁止时间。即,中断被关闭时,记录下当时的时间戳。此后,中断被打开时,再计算时间差,由此便可得到中断禁止时间。

IRQ-Flags 封装开关中断的宏定义:

清单 5. IRQ-Flags 中断代码
#define local_irq_enable() \ 
    do { trace_hardirqs_on (); raw_local_irq_enable(); } while (0)

ftrace 在文件 ftrace_irqsoff.c 中重载了 trace_hardirqs_on 。具体代码不再罗列,主要是使用了 sched_clock()函数来获得时间戳。

hw-branch 的实现

Hw-branch 只在 IA 处理器上实现,依赖于 x86 的 BTS 功能。 BTS 将 CPU 实际执行到的分支指令的相关信息保存下来,即每个分支指令的源地址和目标地址。

软件可以指定一块 buffer,处理器将每个分支指令的执行情况写入这块 buffer,之后,软件便可以分析这块 buffer 中的功能。

Linux 内核的 DS 模块封装了 x86 的 BTS 功能。 Debug Support 模块封装了和底层硬件的接口,主要支持两种功能:Branch trace store(BTS) 和 precise-event based sampling (PEBS) 。 ftrace 主要使用了 BTS 功能。

branch tracer 的实现

内核代码中常使用 likely 和 unlikely 提高编译器生成的代码质量。 Gcc 可以通过合理安排汇编代码最大限度的利用处理器的流水线。合理的预测是 likely 能够提高性能的关键,ftrace 为此定义了 branch tracer,跟踪程序中 likely 预测的正确率。

为了实现 branch tracer,重新定义了 likely 和 unlikely 。具体的代码在 compiler.h 中。

清单 6. likely/unlikely 的 trace 实现
# ifndef likely 
 #  define likely(x) (__builtin_constant_p(x) ? !!(x) : __branch_check__(x, 1)) 
 # endif 
 # ifndef unlikely 
 #  define unlikely(x) (__builtin_constant_p(x) ? !!(x) : __branch_check__(x, 0)) 
 # endif

其中 __branch_check 的实现如下:

清单 7. _branch_check_ 的实现
#define __branch_check__(x, expect) ({\ 
    int ______r;    \ 
    static struct ftrace_branch_data \ 
    __attribute__((__aligned__(4)))  \ 
    __attribute__((section("_ftrace_annotated_branch"))) \ 
                         ______f = { \ 
                           .func = __func__, \ 
                           .file = __FILE__, \ 
                           .line = __LINE__, \ 
                    }; \ 
              ______r = likely_notrace(x);\ 
              ftrace_likely_update(&______f, ______r, expect); \ 
              ______r; \ 
  })

ftrace_likely_update() 将记录 likely 判断的正确性,并将结果保存在 ring buffer 中,之后用户可以通过 ftrace 的 debugfs 接口读取分支预测的相关信息。从而调整程序代码,优化性能。

总结

本文讲解了 ftrace 的基本使用。在实践中,ftrace 是一个非常有效的性能调优和 debug 分析工具,每个人使用她的方法和角度都不相同,一定有很多 best practice,这非本文所能涉及。但希望通过本文的讲解,能让读者对 ftrace 形成一个基本的了解,进而在具体工作中使用她。

评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值