内核函数跟踪

最新推荐文章于 2024-07-30 21:54:04 发布

Fred_HBUT

最新推荐文章于 2024-07-30 21:54:04 发布

阅读量2.4k

点赞数

分类专栏： Kernel Hacking

Kernel Hacking 专栏收录该内容

4 篇文章 2 订阅

订阅专栏

Ftrace 的整体构架：

图 1. 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 的实现

Irqsofftracer 的实现依赖于 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 模块封装了和底层硬件的接口，主要支持两种功能：Branchtrace store(BTS) 和 precise-event based sampling (PEBS) 。 ftrace 主要使用了BTS 功能。

branch tracer 的实现

内核代码中常使用 likely 和 unlikely 提高编译器生成的代码质量。 Gcc可以通过合理安排汇编代码最大限度的利用处理器的流水线。合理的预测是 likely 能够提高性能的关键，ftrace 为此定义了 branchtracer，跟踪程序中 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 接口读取分支预测的相关信息。从而调整程序代码，优化性能。

current_tracer: 這被使用設定或者顯示現在的追蹤者那被配置。

  available_tracers: 這支撐不同類型的追蹤者哪一已經被進入核心之內編譯。追蹤者列出的這裡能藉由附和他們的名字被配置進入 current_tracer 之內。

  tracing_enabled: 這設定或者顯示是否 current_tracer被刺激而且追蹤。進入這之內附和 0申請使追蹤者失去能力或者 1 使它能夠。

  痕跡 : 這一個檔案擁有痕跡的輸出在一人類的易讀的格式.(在下面描述)

  latency_trace: 這一個檔案除了資料之外顯示相同的痕跡被組織更多顯示可能的潛伏在系統.(在下面描述)

  trace_pipe: 輸出除了這之外相同於 " 痕跡 " 檔案，檔案必須與活的追蹤一起流出。來自這一個檔案的閱讀將阻塞到新的資料被取回。不像 " 痕跡 " 和 " latency_trace"
檔案, 這一個檔案是一個消費者。這意指閱讀從這一個檔案導致繼續的閱讀顯示比較新的資料。一旦資料從這被讀檔案, 它被消耗, 而且將不是閱讀再一次以繼續的閱讀。 " 痕跡 " 和 " latency_trace" 檔案是靜態的, 而且如果那追蹤者沒有在增加更多的資料, 他們將顯示同的資料每一次，他們被讀。

  iter_ctrl: 這一個檔案讓使用者控制大量的資料那在上述輸出之一中被顯示檔案。

  trace_max_latency: 一些追蹤者記錄最大潛伏。舉例來說, 當中斷被無效的時候。這次在這一個檔案中被節省。最大痕跡也將被任一被儲存, 而且顯示 " 痕跡 " 或 " latency_trace".  新的最大痕跡意志只被記錄如果潛伏是更棒的超過在這一個檔案中的價值。 (在微秒中)

  trace_entries: 這設定或者顯示痕跡的數字進入每個中央處理器緩衝能支撐。追蹤者緩衝每個中央處理器的相同大小是。被顯示的數字是中央處理器緩衝的大小而且不總計大小。那痕跡緩衝在頁中被分派 (記憶的區段那核心為配置使用, 通常在大小方面的 4 KB). 因為每個進入比頁小, 如果最後人分派頁有房間為更多的進入超過是請求, 頁的其它部分用來分派進入。才能被更新當 current_tracer被設定成 " 沒有人 " 。

注意: 它關於改變被分派的緩衝被計畫從作為可能中央處理器的數字到線上中央處理器的數字。在指定的中央處理器上。格式是 hex 線代表中央處理器。

  tracing_cpumask:這是追蹤的只讓使用者的面具

  set_ftrace_filter: 當電動 ftrace 被配置在 (見到那部分在 " 電動 ftrace" 下面), 密碼動態地修正 (密碼本文改寫記事) 使呼叫失去能力那運作 profiler(mcount) 。這讓追蹤被配置
在與表現的實際沒有額外開銷。  這也有副作用促成或使特性功能失去能力被追蹤。附和功能的名字進入這一個檔案將限制痕跡到不過那些功能。

  set_ftrace_notrace: 這對那有一個效果相對事物set_ftrace_filter。被增加的任何的功能這裡不將被追蹤。如果一個功能在兩者的 set_ftrace_filter 中存在而且 set_ftrace_notrace, 功能將 _not_ 被追蹤。

  available_filter_functions: 當一個功能被遇到第一個根據動態追蹤者定時，它被記錄和稍後呼叫轉換成 nop 。這一個檔案目錄已經被記錄的功能   動態追蹤者和這些功能罐子
用來設定 ftrace 過濾器被那上述的 " set_ftrace_filter" 申請。 (見到節 " 電動 ftrace" 在為更多的細節下面).

追蹤者
-----------

可能被配置的現在追蹤者的目錄在這裡。  使用 mcount 追蹤所有的功能的 ftrace- 功能的追蹤者。

  sched_switch- 追蹤在工作之間的上下文開關。

  irqsoff- 追蹤使中斷和救援失去能力的區域

用最長的最大潛伏的痕跡。見到 tracing_max_latency 。  當一個新的最大被記錄的時候, 它替換舊的痕跡。看這最好經由 latency_trace 檔案追蹤。

  preemptoff- 類似 irqsoff 但是痕跡而且記錄數量定時為哪一個先買被無效。

  preemptirqsoff- 類似 irqsoff 和 preemptoff 、但是痕跡和記錄最大的時間為哪一個 irqs 以及/ 或先買被無效。

  wakeup- 痕跡和紀錄最大潛伏它拿最高的優先工作在變得預定之後它已經被喚醒在。上面

  沒有人 - 這不是一個追蹤者。把所有的追蹤者從追蹤移開只要簡單地附和 " 沒有人 " 進入 current_tracer 。

輸出格式:
--------------

檔案 " 痕跡 " 的輸出格式的一個例子在這裡

                           --------
# 追蹤者: ftrace
#
#          工作-PID 的中央處理器# TIMESTAMP 功能
#             ||    |       |       |
         怒毆-4251[01]10152.583854: path_put<-path_walk
         怒毆-4251[01]10152.583855: dput<-path_put
         怒毆-4251[01]10152.583855: _atomic_dec_and_lock<-dput
                           --------

一個首領與被痕跡代表的追蹤者名字一起列印。在這情況，追蹤者是 " ftrace" 。然後一個首領顯示格式。工作名字 " 怒毆 " 、工作 PID"4251",它正在流逝的中央處理器
"01", timestamp 在<秒>.<usecs> 格式, 功能名字哪一是追蹤了 " path_put" 和呼叫這功能的父母功能" path_walk". timestamp 是時間在哪一個功能是進入。

sched_switch 追蹤者也包括工作 wakeups 的追蹤和上下文轉變。

   ksoftirqd/1-7    [01]1453.070013:    7:115:R+2916:115:S
   ksoftirqd/1-7    [01]1453.070013:    7:115:R+ 10:115:S
   ksoftirqd/1-7    [01]1453.070013:    7:115:R==> 10:115:R
      事件/1-10 [01]1453.070013:    10:115:S==>  2916:115:R
   kondemand/1-2916  [01]  1453.070013: 2916:115:S ==>    7:115:R
   ksoftirqd/1-7    [01]  1453.070013:    7:115:S ==>    0:140:R

守夜提高被代表被一 "+" 和上下文開關被顯示當做"==>".  格式是:

上下文轉變:

   先前的工作             下個工作

  <pid>:<prio>:<州>  ==>  <pid>:<prio>:<州>

守夜提高:

   現在的工作             工作醒來

  <pid>:<prio>:<州> +  <pid>:<prio>:<州>

prio 是內在的核心優先, 是相反的那通常被使用者-空間工具顯示的優先。零代表最高的優先.(99) Prio 100 開始 " 美好的 " 優先與100 和美好的 -20 和 139 存在美好的 19 相等. prio"140" 是為最低的優先線 (pid 0) 的懶惰的工作保留。

潛伏追蹤格式
--------------------

因為顯示潛伏時代的痕跡, latency_trace 檔案給略微更多的資料了解一個潛伏為什麼發生。這裡是一典型的追蹤。

# 追蹤者: irqsoff
#
irqsoff 潛伏追蹤 v 1 。1.5 在 2.6.26 rc 的 8之上
--------------------------------------------------------------------
潛伏: 97 我們,#3/3 歲, 中央處理器 #0|(M:以先買權獲得 VP:0, KP:0, SP:0 HP:0#P:2)
-----------------
| 工作: 交換者-0(uid:0 美好的:0個政策:0 rt_prio:0)
-----------------
=> 開始在: apic_timer_interrupt
=> 結束在: do_softirq

#             _------=> 中央處理器#
#             /_-----=> irqs-遠的
#             |/_----=> 需要-resched
#             ||/_---=> hardirq/softirq
#             ||| / _--=> 以先買權獲得-深度
#             |||| /
#             |||||    延遲
# cmd    pid||||| 時間 |來電者
#    \/ ||||| \|/
  <懶惰的>-0    0 d。。1 0 我們+: trace_hardirqs_off_thunk(apic_timer_interrupt)
  <懶惰的>-0    0 d。s。 97 我們 : __do_softirq(do_softirq)
  <懶惰的>-0    0 d。s 198 我們 : trace_hardirqs_on(do_softirq)

這顯示現在的追蹤者是追蹤時間的 " irqsoff" 為哪一個中斷被無效。它給痕跡版本和版本核心在哪一個之上這被執行了在.之上 (2.6.26 rc 的然後它顯示在 microsecs 中的最大潛伏.(97 我們)顯示的痕跡進入的數字而且記錄的總數 (兩者是三: #3/3). 類型被使用了的先買.(以先買權獲得) VP 、 KP 、 SP 和 HP 總是零的而且為較後的使用被保留。 #P 是線上中央處理器的數字。 (#P:2)當潛伏發生了的時候，工作是正在跑的程序。(交換者 pid: 0)。開始而且停止 (功能在哪一個中斷被無效了和分別地能夠) 哪一引起了潛伏:

  apic_timer_interrupt 是中斷被無效了的地方。  do_softirq 是他們再一次能夠了的地方。

首領後的下一條行是痕跡本身。首領解釋哪一個是。

  cmd: 在痕跡中的程序的名字。

  pid: 那一個程序的 PID。

  中央處理器#: 程序是流逝的中央處理器。

  irqs-遠的: 'd' 中斷被無效。 '.' 另外。

  需要-resched: 'N' 工作 need_resched 被設定,'.' 另外。

  hardirq/softirq:
'H'- 難的 irq 發生進 softirq了。
'h'- 難的 irq 正在跑
's'- 軟的 irq 正在跑
'.'- 常態上下文。

  以先買權獲得-深度: preempt_disabled 的水準上述者對核心開發者是大部份有意義。

  時間: 這不同於痕跡檔案輸出。痕跡申請輸出包括絕對的 timestamp 。被使用的 timestamp 被那latency_trace 檔案相對於痕跡的開始。

  延遲:這剛好將更好幫助引起你的注意有一點。而且需要被修理相對於相同的中央處理器是唯一的。標誌在這之間被不同決定現在的痕跡和下一個追蹤。
   '!'- 比 preempt_mark_thresh 棒 (假設值 100)       '+'- 比 1 微秒大  ''- 更少的超過或等於至 1 微秒。  其餘者是相同於那 '痕跡' 檔案。

iter_ctrl
---------

iter_ctrl 檔案用來控制什麼在痕跡中變得印刷輸出。了解什麼是可得的, 只是貓檔案:

  貓 /偵錯/追蹤/iter_ctrl
  印刷-父母的 nosym-抵銷的 nosym-addr 的 noverbose noraw nohex nobin\noblock nostacktrace nosched-樹使選擇之一," 不 " 一起預先考慮的選擇的回聲失去能力。
  回聲 noprint-父母> /除錯/追蹤/iter_ctrl為了要使選擇能夠, 停止那 " 不 ".
  回聲 sym-抵銷> /除錯/追蹤/iter_ctrl

可得的選擇在這裡:

  印刷-父母 - 在功能痕跡上，顯示召集功能像功能一樣的好被追蹤。

  印刷-父母:
怒毆-4000[01]1477.606694: simple_strtoul<-strict_strtoul

  noprint-父母:
怒毆-4000[01]1477.606694: simple_strtoul

  sym-抵銷 - 顯示不只有功能名字, 但是也抵銷   在功能中。舉例來說, 而非僅僅見到
" ktime_get", 你將見到 " ktime_get+0 xb/0 x 20".

  sym-抵銷:
怒毆-4000[01]1477.606694: simple_strtoul+0 x 6/0 xa 0

  sym-addr- 這也將顯示功能住址和
功能命名。

  sym-addr:
怒毆-4000[01]1477.606694: simple_strtoul<c0339346>  用字多的 - 這處理 latency_trace 檔案。

怒毆 4000100000000000010 一 95[58127 d 26]1720.415 ms\    (+0.000 ms): simple_strtoul(strict_strtoul)

  生的肉 - 這將顯示生的數字。這選擇對使用是最好的與能翻譯生的數字更多的使用者申請超過核心中做它。

  hex- 類似生的肉, 但是數字將以一個十六進位格式。

  箱櫃 - 這將的生二進中列印格式。

  區段 - TBD(需要更新)

  stacktrace- 這是改變痕跡本身的選擇之一。當痕跡被記錄的時候，功能的堆疊也是。這考慮到痕跡位置的後面痕跡。

  sched-樹 - TBD(任何的使用者??)

sched_switch
------------

這一個追蹤者只是記錄時間表開關。一個例子在這裡該如何使用它。

# 回聲 sched_switch> /除錯/追蹤/current_tracer
# 附和 1> /除錯/追蹤/tracing_enabled
# 睡覺 1
# 附和 0> /除錯/追蹤/tracing_enabled
# 貓 /偵錯/追蹤/痕跡

# 追蹤者: sched_switch
#
#          工作-PID 的中央處理器# TIMESTAMP 功能
#             ||    |       |       |
         怒毆-3997[01]240.132281: 3997:120:R+4055:120:R
         怒毆-3997[01]240.132284: 3997:120:R==>  4055:120:R
         睡眠-4055[01]240.132371: 4055:120:S==>  3997:120:R
         怒毆-3997[01]240.132454: 3997:120:R+4055:120:S
         怒毆-3997[01]240.132457: 3997:120:R==>  4055:120:R
         睡眠-4055[01]240.132460: 4055:120==>  3997:120:R
         怒毆-3997[01]240.132463: 3997:120:R+4055:120
         怒毆-3997[01]240.132465: 3997:120:R==>  4055:120:R
      <懶惰的>-0    [00] 240.132589:    0:140:R +    4:115:S
      <懶惰的>-0    [00] 240.132591:    0:140:R ==>    4:115:R
   ksoftirqd/0-4    [00] 240.132595:    4:115:S ==>    0:140:R
      <懶惰的>-0    [00] 240.132598:    0:140:R +    4:115:S
      <懶惰的>-0    [00] 240.132599:    0:140:R ==>    4:115:R
   ksoftirqd/0-4    [00] 240.132603:    4:115:S ==>    0:140:R
         睡眠-4055[01]240.133058: 4055:120:S==>  3997:120:R
[.。。]

當我們先前已經討論大約這一個格式,首領表演對選擇的痕跡的名字和點。 " 功能 "因為在這裡它代表守夜是一個錯誤的名字提高和上下文開關。

sched_switch 申請唯一的目錄守夜提高 (以 '+' 代表)而且上下文開關 ('==>') 與先前的工作或現在的工作，首先根據醒來的下一件工作或工作跟隨。格式為兩者
這些是 PID:核心-PRIO:工作-州。記得那核心-PRIO真實優先的相反的與作為最高的零 (0)優先和美好的價值出發在 100.(美好的 -20) 在下面是快的圖解把核心優先映射到使用者土地優先。

  核心優先: 0-99 ==> 使用者 RT 優先 99-0
  核心優先: 100-139==> 使用者美好的 -20-19
  核心優先: 140       ==> 懶惰的工作優先

工作州是:

R- 賽跑 : 需要跑, 可能不實際上跑
S- 睡眠 : 程序正在等候被喚醒在 (柄信號)
D- 磁碟片睡眠 (不中斷的睡眠): 程序一定要被喚醒在
(忽視指述信號)
T- 停止 : 程序中斷
t- 追蹤 : 程序正在被追蹤 (與某事喜歡 gdb)
Z- 殭屍 :處理等候被清除
X- 未知者

ftrace_enabled
--------------

下列的追蹤者 (列出的在下面) 提供靠的不同的輸出在是否之上 sysctl ftrace_enabled 被設定。設定 ftrace_enabled,一個罐子或使用 sysctl 功能或固定的它經由 proc
申請系統界面。  sysctl kernel.ftrace_enabled=1或附和 1> /proc/sys/核心/ftrace_enabled 只是使 ftrace_enabled 失去能力以 '0' 替換 '1' 在上述的指令。

當 ftrace_enabled 也被設定追蹤者的時候將記錄功能那在痕跡裡面。追蹤者的描述意志也用被能夠的 ftrace 顯示一個例子。

irqsoff
-------

當中斷被無效的時候，中央處理器不能產生反應任何另外地外部的事件.(除 NMIs 和 SMIs 之外) 這避免定時器從讓從觸發或老鼠中斷打斷那核心知道新老鼠事件。結果是一個潛伏與那反應時間。

irqsoff 追蹤者為哪些中斷被無效追蹤時間。當一個新的最大潛伏是碰撞的時候, 追蹤者解救痕跡領先在至那一個潛伏指出，以便每一次新的極大被達成, 老年人被解救的痕跡被丟棄，而且新的痕跡被解救。

為了要重新設定極大,進入 tracing_max_latency 之內附和 0 。這裡是一
例子:

# 回聲 irqsoff> /除錯/追蹤/current_tracer
# 附和 0> /除錯/追蹤/tracing_max_latency
# 附和 1> /除錯/追蹤/tracing_enabled
# ls-ltr
[.。。]
# 附和 0> /除錯/追蹤/tracing_enabled
# 貓 /偵錯/追蹤/latency_trace
# 追蹤者: irqsoff
#
irqsoff 潛伏追蹤 v 1 。1.5 在 2.6.26之上
--------------------------------------------------------------------
潛伏: 12 我們,#3/3 歲, 中央處理器 #1|(M:以先買權獲得 VP:0, KP:0, SP:0 HP:0#P:2)
-----------------
| 工作: 怒毆-3730(uid:0 美好的:0個政策:0 rt_prio:0)
-----------------
=> 開始在: sys_setpgid
=> 結束在: sys_setpgid

#             _------=> 中央處理器#
#             /_-----=> irqs-遠的
#             |/_----=> 需要-resched
#             ||/_---=> hardirq/softirq
#             ||| / _--=> 以先買權獲得-深度
#             |||| /
#             |||||    延遲
# cmd    pid||||| 時間 |來電者
#    \/ ||||| \|/
怒毆-37301 d。。。 0 我們 : _write_lock_irq(sys_setpgid)
怒毆-37301 d。。1 1 我們+: _write_unlock_irq(sys_setpgid)
怒毆-37301 d。。214 我們 : trace_hardirqs_on(sys_setpgid)

在這裡我們見到我們有了 12 的潛伏 microsecs(是非常好的). 那 _在 sys_setpgid 殘廢的中斷中的 write_lock_irq。12 和被顯示的 timestamp 14 之間的不同我們發生
因為時鐘在記錄最大的時候之間被增量潛伏和記錄有了那一個潛伏的功能的時候。

注意上述的例子有了沒被設定的 ftrace_enabled。如果我們設定那ftrace_enabled, 我們得到非常大的輸出:

# 追蹤者: irqsoff
#
irqsoff 潛伏追蹤 v 1 。1.5 在 2.6.26 rc 的 8之上
--------------------------------------------------------------------
潛伏: 50 我們,#101/101 歲, 中央處理器 #0|(M:以先買權獲得 VP:0, KP:0, SP:0 HP:0#P:2)
-----------------
| 工作: ls-4339(uid:0 美好的:0個政策:0 rt_prio:0)
-----------------
=> 開始在: __alloc_pages_internal
=> 結束在: __alloc_pages_internal

#             _------=> 中央處理器#
#             /_-----=> irqs-遠的
#             |/_----=> 需要-resched
#             ||/_---=> hardirq/softirq
#             ||| / _--=> 以先買權獲得-深度
#             |||| /
#             |||||    延遲
# cmd    pid||||| 時間 |來電者
#    \/ ||||| \|/
   ls-43390.。。1 0 我們+: get_page_from_freelist(__alloc_pages_internal)
   ls-43390 d。。1 3 我們 : rmqueue_bulk(get_page_from_freelist)
   ls-43390 d。。1 3 我們 : _spin_lock(rmqueue_bulk)
   ls-43390 d。。1 4 我們 : add_preempt_count(_spin_lock)
   ls-43390 d。。2 4 我們 : __rmqueue(rmqueue_bulk)
   ls-43390 d。。2 5 我們 : __rmqueue_smallest(__rmqueue)
   ls-43390 d。。2 5 我們 : __mod_zone_page_state(__rmqueue_smallest)
   ls-43390 d。。2 6 我們 : __rmqueue(rmqueue_bulk)
   ls-43390 d。。2 6 我們 : __rmqueue_smallest(__rmqueue)
   ls-43390 d。。2 7 我們 : __mod_zone_page_state(__rmqueue_smallest)
   ls-43390 d。。2 7 我們 : __rmqueue(rmqueue_bulk)
   ls-43390 d。。2 8 我們 : __rmqueue_smallest(__rmqueue)
[.。。]
   ls-43390 d。。246 我們 : __rmqueue_smallest(__rmqueue)
   ls-43390 d。。247 我們 : __mod_zone_page_state(__rmqueue_smallest)
   ls-43390 d。。247 我們 : __rmqueue(rmqueue_bulk)
   ls-43390 d。。248 我們 : __rmqueue_smallest(__rmqueue)
   ls-43390 d。。248 我們 : __mod_zone_page_state(__rmqueue_smallest)
   ls-43390 d。。249 我們 : _spin_unlock(rmqueue_bulk)
   ls-43390 d。。249 我們 : sub_preempt_count(_spin_unlock)
   ls-43390 d。。150 我們 : get_page_from_freelist(__alloc_pages_internal)
   ls-43390 d。。251 我們 : trace_hardirqs_on(__alloc_pages_internal)

在這裡我們追蹤了一個 50 微秒潛伏。但是我們也見到所有的那在那期間被呼叫的功能。注意那被促成功能追蹤, 我們招致一附加的在高處。這一項額外開銷可能
延伸潛伏時代。但是然而, 這一痕跡已經提供一些非常有幫助的除錯資料。

preemptoff
----------

當先買被無效的時候, 我們可能能夠除了接受中斷工作不能夠被以先買權獲得和一件較高的優先工作一定要等候因為先買再一次被能夠在它之前能以先買權獲得一比較低的
優先工作。

preemptoff 追蹤者追蹤使先買失去能力的地方。像 irqsoff 追蹤者, 它記錄最大的潛伏為哪一個先買被無效了。 preemptoff 追蹤者的控制多像 irqsoff追蹤者。

# 回聲 preemptoff> /除錯/追蹤/current_tracer
# 附和 0> /除錯/追蹤/tracing_max_latency
# 附和 1> /除錯/追蹤/tracing_enabled
# ls-ltr
[.。。]
# 附和 0> /除錯/追蹤/tracing_enabled
# 貓 /偵錯/追蹤/latency_trace
# 追蹤者: preemptoff
#
preemptoff 潛伏追蹤 v 1 。1.5 在 2.6.26 rc 的 8之上
--------------------------------------------------------------------
潛伏: 29 我們,#3/3 歲, 中央處理器 #0|(M:以先買權獲得 VP:0, KP:0, SP:0 HP:0#P:2)
-----------------
| 工作: sshd-4261(uid:0 美好的:0個政策:0 rt_prio:0)
-----------------
=> 開始在: do_IRQ
=> 結束在: __do_softirq

#             _------=> 中央處理器#
#             /_-----=> irqs-遠的
#             |/_----=> 需要-resched
#             ||/_---=> hardirq/softirq
#             ||| / _--=> 以先買權獲得-深度
#             |||| /
#             |||||    延遲
# cmd    pid||||| 時間 |來電者
#    \/ ||||| \|/
sshd-42610 d。h。 0 我們+: irq_enter(do_IRQ)
sshd-42610 d。s。 29 我們 : _local_bh_enable(__do_softirq)
sshd-42610 d。s 130 我們 : trace_preempt_on(__do_softirq)

为了抓住一个自定义的内核函数是如何被执行的，需要一定的调试手段，其实就需要一种跟踪手段就可以了，理论上不太复杂，可是Linux内核的调试接口太多了，始终找不到一个方便的，直到遇到了ftrace，它简单的使用文件系统作为接口，不需要安装任何用户态程序，和杂乱的发行版毫无关系，这正合我意，相比SystemTap等复杂的前置设置等调试手段，简直棒极了。因为我很讨厌为了做一件理论上很简单的事而去花去大量的时间去做前置工作。
使用文件系统作为接口的优势自然不必多说，它可以将任意复杂的操作映射到既有的简单的读，写，控制，打开，关闭等简单操作上，ftrace的另一个妙点在于其动态二进制修正技术。其实kprobe也是使用了二进制修正技术，然而它做的很硬，而ftrace则使用了GCC内置的mcount机制，通过重载mcount函数来完成对任意函数调用的统计。
mcount机制是GCC的一个特性，在任何函数调用时，会纪录关于该函数的一些信息。比如以下的程序：
mcount.c：

[plain] view plain copy print ?

#include <stdio.h>
void mcount()
{
printf("@@@@\n");
}

#include <stdio.h>
void  mcount()
{        
    printf("@@@@\n");
}

gcc -c mcount.c

main.c：

[plain] view plain copy print ?

#include <stdlib.h>
#include <stdio.h>
extern void mcount(void);
void b(int i)
{
printf("b:%d\n", i);
}
int a(int i)
{
b(i);
return 3;
}
int main()
{
int i = 3;
int k = a(i);
return k;
}

#include <stdlib.h>
#include <stdio.h>
extern void mcount(void);
void b(int i)
{
        printf("b:%d\n", i);
}
int a(int i)
{
        b(i);
        return 3;
}
int main()
{
        int i = 3;
        int k = a(i);
        return k;
}

gcc -c main.c -pg
gcc mcount.o main.o -o test
执行test，则会发现每个函数调用都会打印出@@@，这说明我们重载mcount成功了。如果能将mcount做成一个只执行ret的stub函数，或者连call mcount一起都执行nop的stub，那么相当于没有这个mcount函数，如果某个时间用户启用了ftrace，则将上述stub替换为真正的trace函数，那不就可以动态开启/关闭trace功能了么？Linux kernel正是这么做的。要想这么做，stub函数要做的足够灵活，以上面的mcount.c/main.c为例，一个比较灵活但不绝对灵活的设计框架如下：

[plain] view plain copy print ?

char code[] = {0xc3, 0x90, 0x90...} //0xc3为直接ret
void mcount()
{
int (*pf)(void);
pf = &code[0];
pf();
}

char code[] = {0xc3, 0x90, 0x90...} //0xc3为直接ret

void mcount()
{
    int (*pf)(void);
    pf = &code[0];
    pf();
}

如果用户开启了trace，则将code进行替换，替换成call real_func的操作码，而real_func不止一个固定的函数，而是可以register的，那么我们就可以根据自己的爱好来任意替换trace函数进而实现任意的trace风格了。Linux内核的做法比我这个要灵活的多，通过回调func的机制，它甚至可以画出一副函数调用图，十分强大。顺便说一句，trace回调函数的实现利用了内核编译时产生的内核函数位置表，它的条目就是函数名和位置这一对映射，trace回调函数会根据当前的地址查到函数名。
我上述的框架只是一个框架，如果你真的去编译运行了，会发现出现了恶心的segment fault，这是因为如今大多数的内核都实施了data section不可执行，text section不可写的保护功能，如果你硬要那么做，会出现通用保护异常，因此还要做大量的链接脚本的工作。这个费力的事就不说了，说多了都是泪！
ftrace的核心在于利用了mcount机制以及文件系统机制，它的使用非常简单，只需要挂载debugfs，你就可以任意调试了：
mount -t debugfs debugfs /debug
然后进入/debug/tracing目录，检查available_tracers，看看你当前的kernel支持的trace功能都有哪些，如果有function，说明你的内核支持函数跟踪功能，ftrace支持过滤功能，比如按照内核函数过滤，按照进程过滤。下面是对于一个长ping的trace结果片断：
0)               | sys_socketcall() {
0)               |    copy_from_user() {
0)               |      _copy_from_user() {
0)   0.137 us    |        _cond_resched();
0)   0.457 us    |      }
0)   0.806 us    |    }
0)   0.130 us    |    audit_socketcall();
0)               |    sys_recvmsg() {
0)               |      sockfd_lookup_light() {
0)   0.228 us    |        fget_light();
0)   0.558 us    |      }
0)               |      __sys_recvmsg() {
0)               |        _copy_from_user() {
0)   0.130 us    |          _cond_resched();
0)   0.405 us    |        }
0)               |        verify_iovec() {
0)               |          _copy_from_user() {
0)   0.129 us    |            _cond_resched();
0)   0.429 us    |          }
0)   0.736 us    |        }
0)               |        sock_recvmsg() {
0)               |          security_socket_recvmsg() {
0)               |            apparmor_socket_recvmsg() {
0)   0.179 us    |              aa_revalidate_sk();
0)   0.482 us    |            }
0)   0.945 us    |          }
0)   0.210 us    |          sock_update_classid();
0)               |          inet_recvmsg() {
不光可以绘制出函数调用图，其计时统计信息对于性能分析也是很有参考意义的。
      ftrace很强大，不需要你对系统做任何额外的配置，不需要安装额外的软件，直接使用文件系统接口即可。我十分喜欢这个机制，因为我讨厌需要额外配置的机制，那样促使很多人走偏了路，他们在炫耀敲命令的技巧的同时，给了别人很大的压力，其实行内人士都知道，他们的大部分命令都是为了搭建这个trace环境，而不是解决真正的问题，因此这种命令也包括apt-get，你不懂，你就会觉得他很猛！

linux中大量使用函数指针钩子，导致阅读代码困难。比如想知道一个函数的调用路径，那么就只能用source insight之类的工具看代码了。有没有办法可以迅速获得调用关系的整体印象？ftrace是内核提供的一种调试工具，可以对内核中发生的事情进行跟踪。比如函数的调用，进程的切换，中断的开关等等。这里利用这个工具来跟踪函数的调用。
# cat /boot/config-2.6.36 | grep FTRACE
CONFIG_HAVE_FTRACE_NMI_ENTER=y
CONFIG_HAVE_DYNAMIC_FTRACE=y
CONFIG_HAVE_FTRACE_MCOUNT_RECORD=y
CONFIG_FTRACE_NMI_ENTER=y
CONFIG_FTRACE=y #FTRACE打开后，编译内核时会打开-pg选项。
CONFIG_FTRACE_SYSCALLS=y
CONFIG_DYNAMIC_FTRACE=y
CONFIG_FTRACE_MCOUNT_RECORD=y
# CONFIG_FTRACE_STARTUP_TEST is not set

mkdir /debug
mount -t debugfs nodev /debug #挂载debugfs。ftrace使用debugfs作为配置工具
cd tracing #检查是否存在tracing文件夹。如果不存在，当前内核不支持ftrace，需要重新编译。参考文档
tracing文件夹中有很多文件用于配置ftrace工具。

echo nop > current_tracer #清楚当前tracer。执行该操作，会将pid等清空。
echo function > current_tracer #跟踪函数调用
echo 1 > tracing_enabled #打开ftrace开始跟踪
echo 0 > tracing_enabled #关闭ftrace停止跟踪
cat trace | less # 读trace文件。可以使用vim等工具。

echo 1 > set_ftrace_pid #跟踪单个进程(内核线程)的函数调用。有效值大于0。如果echo > set_ftrace_pid则清空该选项。

echo function_graph > current_tracer #以图形化的方式跟踪函数调用。如下图所示。效果非常好。

默认情况下，会捕获所有的内核函数调用。可以使用下面的命令进行过滤，只捕获关心的函数调用。
echo sys_socket > set_graph_function #可以写多个函数。也可以使用通配符*，如sys_*。
cat available_filter_functions | grep sys_ #查询ftrace支持的包含sys_字符的函数。注意，内核中使用EXPORT_SYMBOL声明的函数才能使用ftrace跟踪

对一个名为epl.ko的内核模块进行trace的过程如下：

1 首先确保你打开相应的内核选项： kernel_hacking/Trace下面。如果需要重编内核。

注意重编内核后重编你的模块。

2 设置ftrace

mount -t debugfs debugfs /sys/kernel/debug #要使用 ftrace首先需要mount这个debugfs

ln -s /sys/kernel/debug /debug #方便期间做个链接

cd /debug

echo function_graph > current_tracer #输出函数调用图，需要打开内核选项FUNCTION_GRAPH_TRACER

3 提取模块里的函数列表

如果没有设置过滤表（默认加载debugfs后），available_filter_functions文件包含了所有可追踪的函数名称，默认情况下这个链表覆盖了所有内核的可trace函数。如果我们插入一个模块，那么ftrace会自动把我们我们这个模块的函数符号加到available_filter_functions中。提取一个内核模块的函数可以有两种方法，一种是用nm命令，一种是比较插入模块前后available_filter_functions的差异，两种方法都提供给读者如下：

1）比较插入模块前后available_filter_functions的差异

    cat available_filter_functions > /tmp/funcs_without_epl
    insmod epl.ko
    cat available_filter_functions > /tmp/funcs_with_epl
    diff /tmp/funcs_without_epl /tmp/funcs_with_epl > epl_funcs
    删除 epl_funcs文件里由diff产生的无用信息。

    2) 使用nm命令导出epl.ko里的符号

参考［附表：nm基本用法］

nm导出的是ko里的所有符号，我们只需要函数符号

nm -s epl.ko | grep " T " | awk '{ print $3 }' > nm_funcs
nm -s epl.ko | grep " t " | awk '{ print $3 }' >> nm_funcs

为了比较两者产生的差别，首先排下序

    sort nm_funcs > nm_funcs_sorted
    sort epl_funcs > epl_funcs_sorted
    diff -Nur nm_funcs_sorted epl_funcs_sorted

我们可能发现nm_funcs包含了一些epl_funcs没有的函数，这些函数正式kernel里面本来有的内核函数，所以如果你只想trace你的模块的函数，那么推荐使用方法1。

4 开始trace

insmod epl.ko

    cat /tmp/epl_funcs > set_ftrace_filter
    echo 1 >tracing_enabled                           #开始trace
    cat trace_pipe > /tmp/ftrace_result.txt &    #设置一个管道重定向，防止溢出

tracing & waiting....

echo 0 >tracing_enabled #结束trace

说明：一个ko插入kernel以后才可以给 set_ftrace_filter设置函数过滤表，因为没插入以前内核没有epl.ko的函数符号，故设置set_ftrace_filter失败，所以需要先插入模块以后再enable trace，但是这样又有一个问题：我们也想trace模块插入时候的执行情况时，我们还不能在插入模块前设置过滤表，那么怎么办呢？需要得到这个答案需要首先确认：在默认情况下，也就是设置ftrace为trace所有可trace的函数后，我们插入模块时候ftrace是不是马上把这个ko的函数表加进可trace列表，同时也能够trace这些函数？如果可以，那我们可以先预先准备好filter list（即我们文中所述的epl_funcs)，插入模块后然后再设置set_ftrace_filter过滤表，这样会在ftrace的结果的前一段会有我们不希望trace的函数（内核函数），或者删除，或者提取出我们模块初始化部分即可。作者在实践过程中发现有时候ftrace的结果输出没有显示函数符号表，这个问题还有待进一步确认...希望对这方便有深入了解的网友不吝赐教，mqyoung at gmail.com。