Kernel trace 工具的發展曆史
Linux 跟蹤工具在核心的發展就像是肥皂劇一樣，劇情婉轉，主題反複，并且互相競争。本章試圖總結目前Linux 衆多跟蹤工具的現狀和曆史原因，并最終引出 ftrace 工具。
編者對于以下内容并非親曆者(主要來自 LWN 和 maillist)，如有歪曲請拍磚。以下部分雖屬八卦，但是，學習一些子產品的設計方案和曆史程序是我們學習方法論的一部分，從這些糾結的方案和博弈中可以看到很多權衡和利弊，幫助更好的獲得其中的思想。
Why Trace the kernel ?
很多人在接觸這類工具時可能會感到困惑，核心代碼早就已經優化的非常好了，并且基本不會有什麼 Bug，那麼為什麼還需要插入這麼多探針去檢視核心的狀态呢？
其實這種工具在生産環境中被很多人使用去跟蹤問題，比如系統此時無法了解的行為(CPU 居高，IO 忙等)，這時候系統管理者需要利用這種工具在不幹擾常系統運作的情況下去 Linux 這個龐大的核心中查找原因。
Dtrace Envy 和 SystemTap
首先，我們先來介紹 Dtrace Envy。Linux 社群中過去有一個名詞叫 DtraceEnvy，從字母上可以發現 Linux 社群對 Dtrace 的深惡痛絕。不僅是在以前的Linux 中沒有像 Dtrace 一樣如此強大的實作，而且 Dtrace 經常被 Sun 公司用來作為營銷手段的噱頭(同樣的還有 ZFS)，并用來與 Linux 進行對比。
那時還是 07 年，大家在提到 Solaris 系統時，Dtrace 總是處在人們關注的前列。而 SystemTap 當時還在幾個大公司 Red Hat、Intel、IBM 和日立内部使用。Dtrace 的擁護者會嘲諷 SystemTap 隻是個山寨貨，而 SystemTap 的粉絲認為SystemTap 是個獨立發展的項目，并且以超越 Dtrace 為目标。
這兩個工具都是在核心中插入探針，當一個線程執行碰到探針時，預先定義的腳本(D 語言腳本或者 SystemTap 腳本)就會運作。
Dtrace 使用了大量的預先定義的探針插入到 Solaris 核心中，這種方式稱為靜态探針，這些探針都在 Dtrace 的文檔中做了詳述。并且一些簡單的通配符(*)可以用來實作多個探針的選擇。Sun 宣稱無用的探針并不會增加太多的負載。
SystemTap 沒有采用 Dtrace 的方式，估計是 SystemTap 沒有人有這麼大精力去實作大量的靜态探針放到核心中(Linus 會發飙的)。SystemTap 采用的動态探針(kprobes 實作）,它是在核心運作時被動态插入。SystemTap 采用腳本語言來定義一些動作并且打開一些啟用的探針來(SystemTap 的探針庫)插入到核心中，沒有用到的探針不會插入。
從上述的差異可以看到 Dtrace 的靜态探針是有優勢的，首先 Dtrace 大量的探針是被預定義并且可以被很好的文檔化(這對于系統管理者是非常好的，它們通常不熟悉核心源碼)。而 SystemTap 是可以在核心的任意位置，這就需要開發者熟悉核心的源碼并且把探針放到合适的位置。這就可能帶來安全性的問題，一些不恰當的探針放置是會帶來系統崩潰的(這種情況非常少)，即使非常少的位置是敏感的，但也足以使使用者感到不便，需要時時擔心可能的不恰當觸發。當然，SystemTap 也有少量的預定義探針。
接着我們比較兩者的語言，Dtrace 采用的 D 語言同樣繼承了安全的原則，它運作在虛拟機中并且帶有安全檢測，并且拒絕控制語句(隻有三元操作符)，但在探針上可以附着表達式(相當于一個“if”)。而 SystemTap 同樣采取了大刀闊斧的姿态，不僅有完備的控制語句，SystemTap 腳本(STP)直接翻譯成 C，并且在SystemTap 腳本中可以嵌入 C。可以想象，在這裡面如果出現了死循環就基本意味着 crash 了。
Kernel summit 2008 的故事
2008 年，雖然 SystemTap 有了長足的發展，但是核心社群和 SystemTap 項目團隊仍然沒有一個很好的溝通和協商，SystemTap 仍然沒有進入普通使用者的工具範疇。在 kernel summit 中(Ksummit-2008-discuss DTrace)，Matthew Wilcox表示 Dtrace 已經對 Linux 造成了足夠的威脅。Linux 通常被認為是新技術的前沿，但是當 Sun 把 Solaris 開放後，一系列的新特征已經領先 Linux，比如 ZFS和 Dtrace。
即使當時 SystemTap 和 Btrfs 被認為是 Linux 對抗的利器，但是，在社群還是有人對 SystemTap 表示失望。James Bottomley(iSCSI 的貢獻者)在郵件中提到 Ksummit-2008-discuss DTrace：好比 Winodws 的使用者期望在 Linux 上有Outlook 一樣，Solaris 使用者期望 SystemTap 在 Linux 上也能成為和 DTrace 一樣的工具。同時，James Bottomley 表示 SystemTap 非常難用并且造成系統的崩潰。另外 Ted Ts’o 同樣贊成 SystemTap 非常難以使用，但是他期望在 SystemTap中增加更多的“tapsets”來幫助對核心不熟悉的人更好的使用 SystemTap。
SystemTap 的開發者 Frank Ch. Eigler 表示 SystemTap 早已考慮性能、難以使用的問題并且正在解決中，他認為核心社群缺少與 SystemTap 團隊的溝通，并且提出了一系列的建議希望核心團隊參與到 SystemTap 與 kernel 的整合中來(Frank Ch. Eigler fche at redhat.com)。
但是，Ted Ts’o 同樣回應稱 SystemTap 隻會将“tapsets”的開發任務交給核心，而不去思考如何讓 SystemTap 變得易用并且更容易與核心整合，他同時指責 SystemTap 光想着讓企業發行版使用，而不去努力改善與核心的問題(Theodore Tso tytso at mit.edu)。
Frank Ch. Eigler 表示大部分系統管理者是不會去使用 SystemTap 思考核心的性能追蹤的，SystemTap 通常是被整合到 PostgreSQL 這種基礎軟體中來使用，是以，SystemTap 更加注重對此類問題的解決。
同時，社群中有人期望把 Dtrace 移植到 Linux 中，但是這也困難重重，先不說 Dtrace 移植到 Linux 主線的技術問題，光光是 CDDL 協定就是不容于 Linux的。好吧，接下來就是各種水友開始讨論 CDDL 與 GPL 的協定問題(一群程式員開始 Google…)
最後還是 Linus 強調了最重要的一點，這個同時也是針對 utrace 的：SystemTap 的實作是不被核心開發者喜歡的，因為它創造、利用核心子產品的實作是不同于核心的，對于 SystemTap 的細節，如鎖實作和使用等等都是 off kernel的。他希望 SystemTap 在實作設計上能離核心越來越近。
ptrace
在介紹 utrace 之前首先需要介紹 ptrace，它是 Linux 核心跟蹤工具的化石。過去(07年以前)很長一段時間裡，大部分人利用它來調試應用或者核心子產品，但是它的問題也很多：低效(需要核心/使用者态切換)、實作難以維護(架構設計混亂)、使用者難以使用(接口複雜）、一個程序隻能被一個程序跟蹤(使用信号方法跟蹤程序，信号使得目标隻能 wait 一個程序)、會改變跟蹤程序的狀态(程序父子關系)、打斷系統調用并且一直有大量的安全問題存在。
ptrace 的維護者在 utrace 出現之後就已經在呼籲讓 ptrace 基于 utrace 實作，因為 ptrace 代碼是混亂的，散亂在各個架構中，維護者早已經對橫跨多個架構的代碼厭倦了。
我們需要注意到 gdb 和 strace 都是基于 ptrace，這個原因也導緻了 ustrace遲遲不能進入核心主線。
utrace
utrace 在 07 年的時候進入核心的視線(Introducing utrace)，它的目的是完全取代 ptrace 在使用者态跟蹤的作用。utrace 隻是實作了一個在核心中的engine，它提供了一個架構供更多的人基于它來實作對使用者程式的控制任務(Trace,Debug,user-mode-linux)。
utrace 的體系架構可以參考《玩轉 utrace》。
utrace 自 07 年在 LWN 中提出，然後迅速沉寂消失在視線之外，在 09 又重新希望進入核心主線中，當時 Red Hat 和 Fedora kernels 其實已經支援 utrace很多年了。utrace 進入核心最重要的問題是在核心中沒有真正的使用者(以 utrace為架構的實作)，utrace 如果隻是一個 engine 就沒有進入核心的必要。
Frank Eigler(utrace 開發者)提供了 ftrace(本文的重點)基于 utrace 的實作，但是核心認為這個實作隻是個插件罷了。而另外一個 utrace 真正的使用者ptrace-over-utrace 是被看做 utrace 進入核心的關鍵，但是有很多人以不成熟來反對。雖然 ptrace 有大量的 ugly code 并且難以維護，但是畢竟已經存在這麼多年了，取代 ptrace 是一個高風險的項目并且誰來做這個清理工作，如果不做清理工作，兩者同時進入核心會有兩個 ptrace 實作，帶來更多的問題。還有就是 utrace 并不是被所有架構支援，如果 ptrace 使用 utrace 的實作而删除自己的實作，在其他架構中(如 ARM 和 MIPS)就無法使用 ptrace 調用。并且ptrace-over-utrace 如果想替代原來的 ptrace 實作，必須有一些 killerfeatures(通過 utrace 的架構還是能實作很多的)。Nesterov 和 McGrath 這兩個ptrace 的維護者站出來表示自己更願意維護 ptrace-over-utrace 的方案，并且樂意去推出新的代碼。
問 題 之 二 是 utrace 會 阻 礙 SystemTap 進 入 内 核 ( 當 時 有 很 多 人 期 望SystemTap盡快進入核心)。因為utrace沒有一個系統調用，而是核心裡的API(核心接口會不穩定)。SystemTap 利用了 utrace 的許多 ABI 來實作使用者态的跟蹤，如果 utrace 進入核心，SystemTap 在主線外可能就導緻在使用者态跟蹤上一團糟(主線與非主線最重要的問題就是版本相容性)并且需要尋找其他的方式。(PS:現在 systemtap 可以直接使用新的主流核心中的 kprobes 和基于 inode 的uprobes 機制，不再依賴非主流的 utrace 更新檔。同時它也可以直接使用主流核心中的 perf 靜态探針 by agentzh)
在 09 年的 Linux 2.6.30 進入主線失敗後，utrace 就準備好了長期在主線外的命運，Red Hat 不得不承擔起 utrace 的維護任務并且長期在自己的核心中保持。目前來說，utrace 和 SystemTap 像是一對難兄難弟。
LTTng
LTTng 是另外一個動态跟蹤工具，它整合了核心和使用者态跟蹤，對于大量的跟蹤事件流有非常高的性能，并且有一系列的分析和抓取工具。
對于目前的 Linux 核心來說，LTTng 隻不過是衆多 Tracing 工具的一個，它制造了太多重複的工作：比如 Ring Buffer(核心中已經有兩個 Ring buffer 被perf 和 ftrace 使用)，并且有自己的系統調用接口(核心已經有此類的接口)。增加 LTTng 意味着有更混亂的 Tracing ABI 在核心中。
相比較而言，LTTng 進入核心比 SystemTap 和 utrace 更困難。
ftrace
相比前面的 SystemTap、utrace 和 LTTng，ftrace 就幸運多了。ftrace 是用來幫助開發者和系統設計者尋找系統負載的原因，它可以用來調試和分析核心中的負載和性能原因。
ftrace 之是以能順利進入核心中，主要還是因為它充分利用了核心中既有的設計和其他元件。它利用了 debugfs、kprobes、uprobes 等等，并且因為其簡單的靜态探針和安全性，ftrace 的核心之路順利而平坦。
後面我們将重點介紹這款 tracing 工具。
tracepoint
tracepoint 是在核心中預定義的一系列跟蹤點并且提供了 hook 讓使用者可以調用函數來進行分析，tracepoint 在有 probe attach 時會在每次執行到tracepoint 時調用相應的函數。
tracepoint 在 08 年的時候被置入核心中，ftrace 也同樣使用 tracepoint作為 tracer 使用。
kprobe
kprobes 在 Linux 2.6.9 主線上實作，它主要在核心子產品中被使用。在子產品init 函數中安裝 probe，然後在 exit 時釋放。
對于 kprobe 來說，更多的時候是被核心子產品開發者使用。因為 kprobe 比較麻煩且相對于 SystemTap 這類工具來說，kprobe 隻有較少的使用空間。
uprobe
實作了動态的介入使用者程式的運作并且不打斷地收集資訊。它的原理與kprobe 類似，都是在探針函數的第一個位元組用 breakpoint 指令替代，當 CPU 運作到 breakpoint 指令時，uprobes 得到通知并找到相應 uprobe 來執行對應的函數。
小結
目前 Linux 核心上衆多跟蹤工具的實作其實非常混亂，像 latencyTop、powertop、usbmon、blktrace 都是好用的工具，但是每個工具都需要自己的 hooks在核心，這對于核心而言是十分蛋疼的事情。而在 Solaris 中，powertop 這類是在 Dtrace 之上實作的，不需要改變核心。
從 Linux 性能工具的發展可以看到，upstream kernel 和商用 kernel，以及其他系統(Solaris)的博弈和權衡是十分激烈的。對于 Linux 社群而言，Linus對于代碼的把控是十分必要的，在 11 年 kernel summit 之後，開發者已經普遍贊成收斂系統調用的增加，這對于 LTTng，utrace 進入核心的希望就更小了。
ftrace 的作用是幫助開發人員了解 Linux 核心的運作時行為，以便進行故障調試或性能分析。最早 ftrace 是一個 function tracer，僅能夠記錄核心的函數調用流程。如今 ftrace 已經成為一個 framework，采用 plugin 的方式支援開發人員添加更多種類的 trace 功能。
ftrace 簡介
ftrace 支援的功能
Ftrace 是内建于 Linux 核心的跟蹤工具，從 2.6.27 開始加入主流核心。使用 ftrace 可以調試或者分析核心中發生的事情。ftrace 提供了不同的跟蹤器，以用于不同的場合。比如：跟蹤核心函數調用、對上下文切換進行跟蹤、檢視中斷被關閉的時長、跟蹤核心态中的延遲以及性能問題等。系統開發人員可以使用 ftrace 對核心進行跟蹤調試，以找到核心中出現的問題的根源，友善對其進行修複。另外，對核心感興趣的讀者還可以通過 ftrace 來觀察核心中發生的活動，了解核心的工作機制。
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，debugfs，kprobe，IRQ-Flags 等。限于篇幅，關于這些技術的介紹請讀者自行查閱相關的參考資料。
ftrace 的實作原理
研究 tracer 的實作是非常有樂趣的。了解 ftrace 的實作能夠啟發我們在自己的系統中設計更好的 trace 功能。
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 代碼：
//test.c
void foo(void)
{
printf( “ foo ” );
}
用 gcc 編譯：
gcc -S test.c
反彙編如下：
_foo:
pushl %ebp
movl %esp, %ebp
subl $8, %esp
movl $LC0, (%esp)
call _printf
leave
ret
再加入-pg 選項編譯：
gcc -pg -S test.c
得到的反彙編如下：
_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 中：
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_stub
line 10
popl %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 封裝開關中斷的宏定義：
#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 中：
#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__的實作如下：
#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 的功能配置
要使用 ftrace，首先需要将其編譯進核心。核心源碼目錄下的kernel/trace/Makefile 檔案給出了 ftrace 相關的編譯選項：
CONFIG_FUNCTION_TRACER
CONFIG_FUNCTION_GRAPH_TRACER
CONFIG_CONTEXT_SWITCH_TRACER
CONFIG_NOP_TRACER
ftrace 相關的配置選項比較多，針對不同的跟蹤器有各自對應的配置選項。不同的選項有不同的依賴關系，核心源碼目錄下的 kernel/trace/Kconfig 檔案描述了這些依賴關系。讀者可以參考 Makefile 檔案和 Konfig 檔案，然後選中自己所需要的跟蹤器。
通常在配置核心時，使用 make menuconfig 會更直覺一些。以 3.4 版本的核心為例，要将 ftrace 編譯進核心，可以選中 Kernel hacking 下的 Tracers菜單項：
進入 Tracers 菜單後，可以看到核心支援的跟蹤器清單：
在裡面選中要 ftrace 支援的功能即可。
Ftrace 依賴的配置
ftrace 通過 debugfs 向使用者态提供了通路接口，是以還需要将 debugfs編譯進核心。激活對 debugfs 的支援，可以直接編輯核心配置檔案 .config ，設定 CONFIG_DEBUG_FS=y ；或者在 make menuconfig 時到 Kernel hacking 菜單下選中對 debugfs 檔案系統的支援：
完成配置
配置完成後，編譯安裝新核心，然後啟動到新核心。 注意，激活 ftrace 支援後，編譯核心時會使用編譯器的 -pg 選項，這是在 kernel/trace/Makefile檔案中定義的：
ifdef CONFIG_FUNCTION_TRACER
ORIG_CFLAGS := $(KBUILD_CFLAGS)
KBUILD_CFLAGS = $(subst -pg,,$(ORIG_CFLAGS))
...
endif
使用 -pg 選項會在編譯得到的核心映像中加入大量的調試資訊。如果不使用 CONFIG_DYNAMIC_FTRACE 功能而開啟 ftrace 功能，則可能會嚴重影響系統性能。
目前在我們公司的方案中是使用了 CONFIG_DYNAMIC_FTRACE 功能且預設開啟了 ftrace 的。也就是說，拿到客戶的成品後，我們不用重新修改配置燒寫代碼，就可以在不破壞現場的情況下來使用 ftrace 了。
ftrace 的接口
ftrace 通過 debugfs 向使用者提供通路接口。配置核心時激活 debugfs 後會建立目錄 /sys/kernel/debug，debugfs 檔案系統就是挂載到該目錄的。要挂載該目錄，需要将如下内容添加到 /etc/fstab 檔案：
或者可以在運作時挂載：
mount -t debugfs nodev /sys/kernel/debug
激活核心對 ftrace 的支援後會在 debugfs 下建立一個 tracing 目錄(/sys/kernel/debug/tracing)。該目錄下包含了 ftrace 的控制和輸出檔案。根據編譯核心時針對 ftrace 的設定不同，該目錄下實際顯示的檔案和目錄也會不同。如下圖所示(其中/d 是/sys/kernel/debug 的軟連結)：
/sys/kernel/debug/tracing # ls -l
total 0
-r--r--r-- 1 root root 0 Jan 1 1970 README
-r--r--r-- 1 root root 0 Jan 1 1970 available_events
-r--r--r-- 1 root root 0 Jan 1 1970 available_filter_functions
-r--r--r-- 1 root root 0 Jan 1 1970 available_tracers
-rw-r--r-- 1 root root 0 Jan 1 1970 buffer_size_kb
-r--r--r-- 1 root root 0 Jan 1 1970 buffer_total_size_kb
-rw-r--r-- 1 root root 0 Jan 1 1970 current_tracer
-r--r--r-- 1 root root 0 Jan 1 1970 dyn_ftrace_total_info
-r--r--r-- 1 root root 0 Jan 1 1970 enabled_functions
drwxr-xr-x 60 root root 0 Jan 1 1970 events
--w------- 1 root root 0 Jan 1 1970 free_buffer
-rw-r--r-- 1 root root 0 Jan 1 1970 function_profile_enabled
drwxr-xr-x 2 root root 0 Jan 1 1970 instances
-rw-r--r-- 1 root root 0 Jan 1 1970 max_graph_depth
drwxr-xr-x 2 root root 0 Jan 1 1970 options
drwxr-xr-x 6 root root 0 Jan 1 1970 per_cpu
-r--r--r-- 1 root root 0 Jan 1 1970 printk_formats
-r--r--r-- 1 root root 0 Jan 1 1970 saved_cmdlines
-rw-r--r-- 1 root root 0 Jan 1 1970 saved_cmdlines_size
-r--r--r-- 1 root root 0 Jan 1 1970 saved_tgids
-rw-r--r-- 1 root root 0 Jan 1 1970 set_event
-rw-r--r-- 1 root root 0 Jan 1 1970 set_event_pid
-rw-r--r-- 1 root root 0 Jan 1 1970 set_ftrace_filter
-rw-r--r-- 1 root root 0 Jan 1 1970 set_ftrace_notrace
-rw-r--r-- 1 root root 0 Jan 1 1970 set_ftrace_pid
-r--r--r-- 1 root root 0 Jan 1 1970 set_graph_function
-r--r--r-- 1 root root 0 Jan 1 1970 set_graph_notrace
-rw-r--r-- 1 root root 0 Jan 1 1970 snapshot
-rw-r--r-- 1 root root 0 Jan 1 1970 stack_max_size
-r--r--r-- 1 root root 0 Jan 1 1970 stack_trace
-r--r--r-- 1 root root 0 Jan 1 1970 stack_trace_filter
-rw-r--r-- 1 root root 0 Jan 1 1970 trace
-rw-r--r-- 1 root root 0 Jan 1 1970 trace_clock
--w--w---- 1 root root 0 Jan 1 1970 trace_marker
-rw-r--r-- 1 root root 0 Jan 1 1970 trace_options
-r--r--r-- 1 root root 0 Jan 1 1970 trace_pipe
drwxr-xr-x 2 root root 0 Jan 1 1970 trace_stat
-rw-r--r-- 1 root root 0 Jan 1 1970 tracing_cpumask
-rw-r--r-- 1 root root 0 Jan 1 1970 tracing_max_latency
-rw-r--r-- 1 root root 0 Jan 1 1970 tracing_on
-rw-r--r-- 1 root root 0 Jan 1 1970 tracing_thresh
/sys/kernel/debug/tracing #
ftrace 的接口檔案
/sys/kernel/debug/tracing 目錄下檔案和目錄比較多，有些是各種跟蹤器共享使用的，有些是特定于某個跟蹤器使用的。在操作這些資料檔案時，通常使用 echo 指令來修改其值，也可以在程式中通過檔案讀寫相關的函數來操作這些檔案的值。下面隻對部分檔案進行描述，讀者可以參考核心源碼包中Documentation/trace 目錄下的文檔以及 kernel/trace 下的源檔案以了解其餘檔案的用途。
README 檔案提供了一個簡短的使用說明，展示了 ftrace 的操作指令序列。可以通過 cat 指令檢視該檔案以了解概要的操作流程。
current_tracer 用于設定或顯示目前使用的跟蹤器。使用 echo 将跟蹤器名字寫入該檔案可以切換到不同的跟蹤器。系統啟動後，其預設值為 nop，即不做任何跟蹤操作。在執行完一段跟蹤任務後，可以通過向該檔案寫入 nop 來重置跟蹤器。
available_tracers 記錄了目前編譯進核心的跟蹤器的清單。可以通過 cat檢視其内容，其包含的跟蹤器與4.1節的最後一幅圖中所激活的選項是對應的。寫 current_tracer 檔案時用到的跟蹤器名字必須在該檔案列出的跟蹤器名字清單中。
trace 檔案提供了檢視擷取到的跟蹤資訊的接口。可以通過 cat 等指令檢視該檔案以分析跟蹤到的核心活動記錄，也可以将其内容儲存為記錄檔案，以備後續檢視。
tracing_enabled 用于控制 current_tracer 中的跟蹤器是否可以跟蹤核心函數的調用情況。寫入 0 會關閉跟蹤活動，寫入 1 則激活跟蹤功能，其預設值為 1。
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 的值則為空。
ftrace 跟蹤器
trace 目前包含多個跟蹤器，用于跟蹤不同類型的資訊，比如程序排程、中斷關閉等。可以檢視檔案 available_tracers 擷取核心目前支援的跟蹤器清單。在編譯核心時，也可以看到核心支援的跟蹤器對應的選項。
/sys/kernel/debug/tracing # cat available_tracers
blk function_graph wakeup_dl wakeup_rt wakeup function nop
/sys/kernel/debug/tracing #
nop 跟蹤器不會跟蹤任何核心活動，将 nop 寫入 current_tracer 檔案可以删除之前所使用的跟蹤器，并清空之前收集到的跟蹤資訊，即重新整理 trace 檔案。
function 跟 蹤 器 可 以 跟 蹤 内 核 函 數 的 執 行 情 況 。 可 以 通 過 文 件set_ftrace_filter 顯示指定要跟蹤的函數。
function_graph 跟蹤器可以顯示類似 C 源碼的函數調用關系圖，這樣檢視起來比較直覺一些。可以通過檔案 set_grapch_function 顯示指定要生成調用流程圖的函數。
sched_switch 跟蹤器可以對核心中的程序排程活動進行跟蹤。
irqsoff 跟蹤器和 preemptoff 跟蹤器分别跟蹤關閉中斷的代碼和禁止程序搶占的代碼，并記錄關閉的最大時長，preemptirqsoff 跟蹤器則可以看做它們的組合。
ftrace 還支援其它一些跟蹤器，比如 initcall、ksym_tracer、mmiotrace、sysprof 等。ftrace 架構支援擴充添加新的跟蹤器。讀者可以參考核心源碼包中 Documentation/trace 目錄下的文檔以及 kernel/trace 下的源檔案，以了解其它跟蹤器的用途和如何添加新的跟蹤器。
ftrace 過濾器
前面已經提到過兩個常用的過濾器了：set_ftrace_filter/set_ftrace_notrace 和 set_graph_function。前者對function tracer 進行過濾，後者對 function_graph tracer 進行過濾。這裡隻介紹這兩種常用的過濾器。
還有一些過濾器，如 set_ftrace_pid 對程序進行過濾，stack_trace_filter對堆棧進行過濾。
過濾器的設定
有兩種方式來設定過濾器：使用“>”和“>>”。前者會先清空過濾器，再重新設定過濾器；而後者不會清空過濾器，隻會追加新的過濾資訊。注意，如果清空過濾器，則表示對所有可以跟蹤的函數進行跟蹤。
要删除過濾資訊，隻需要在需要删除的資訊前面加個“！”。例如：
/sys/kernel/debug/tracing # echo jbd2_alloc > set_ftrace_filter
/sys/kernel/debug/tracing # cat set_ftrace_filter
jbd2_alloc
/sys/kernel/debug/tracing #
/sys/kernel/debug/tracing # echo jbd2_free > set_ftrace_filter
/sys/kernel/debug/tracing # cat set_ftrace_filter
jbd2_free
/sys/kernel/debug/tracing #
/sys/kernel/debug/tracing # echo jbd2_alloc >> set_ftrace_filter
/sys/kernel/debug/tracing # cat set_ftrace_filter
jbd2_alloc
jbd2_free
/sys/kernel/debug/tracing #
/sys/kernel/debug/tracing # echo !jbd2_alloc >> set_ftrace_filter
/sys/kernel/debug/tracing # cat set_ftrace_filter
jbd2_free
/sys/kernel/debug/tracing #
除 此 之 外 ， 還 可 以 向 set_ftrace_notrace 中 添 加 過 濾 信 息 來 删 除set_ftrace_filter 中已經設定的過濾資訊。即有相同的函數同時出現在set_ftrace_filter 和 set_ftrace_notrace 中時，這些函數将不被跟蹤。
過濾資訊的适用範圍
添 加 的 過 濾 信 息 必 須 是 可 以 跟 蹤 的 ， 即 需 要 出 現 在available_filter_functions 清單中，否則會傳回添加失敗：
/sys/kernel/debug/tracing # cat available_filter_functions | grep jbd2_free
jbd2_free
/sys/kernel/debug/tracing # echo jbd2_free > set_ftrace_filter
/sys/kernel/debug/tracing # cat set_ftrace_filter
jbd2_free
/sys/kernel/debug/tracing #
/sys/kernel/debug/tracing # echo asdasd > set_ftrace_filter
ash: write error: Invalid argument
/sys/kernel/debug/tracing #
如上，添加“asdasd”到 set_ftrace_filter 過濾器時，傳回1或報“ash: write error: Invalid argument”，表示沒有添加成功，因為 available_filter_functions 清單中沒有記錄 symbol 為“asdfg”的函數。
我們可以通過 enabled_functions 視窗來檢視，目前已經被選中的過濾資訊：
/sys/kernel/debug/tracing # cat current_tracer
nop
/sys/kernel/debug/tracing # echo function_graph > current_tracer
/sys/kernel/debug/tracing # cat current_tracer
function_graph
/sys/kernel/debug/tracing # echo jbd2_free > set_ftrace_filter
/sys/kernel/debug/tracing # cat set_ftrace_filter
jbd2_free
/sys/kernel/debug/tracing # cat set_graph_function
#### all functions enabled ####
/sys/kernel/debug/tracing # cat enabled_functions
jbd2_free (1)
/sys/kernel/debug/tracing # echo function > current_tracer
/sys/kernel/debug/tracing # cat enabled_functions
jbd2_free (1)
/sys/kernel/debug/tracing # echo nop > current_tracer
/sys/kernel/debug/tracing # cat enabled_functions
/sys/kernel/debug/tracing #
如上，看上去 enabled_functions 視窗隻對 function tracer 有效。
過濾器通配符的功能
過濾器支援使用通配符來設定過濾資訊的功能，來為我們提供更方面的設定操作。有如下3種形式的通配符(使用“*”符号)：
<match>* - 将比對以 <match> 開頭的函數
*<match> - 将比對以 <match> 結尾的函數
*<match>* - 将比對包含 <match> 的函數這些是唯一受支援的通配符。
<match>*<match> 将不起作用。
使用通配符表達式時，需要用單引号将其括起來，如果使用雙引号，shell 可能會對字元‘*’進行擴充，這樣最終跟蹤的對象可能與目标函數不一樣。其使用範例在下一章中會介紹，這裡就不再羅列。
過濾器指令的功能
此外，set_ftrace_filter 過濾器還支援少量 Filter commands 的功能。
Filter commands 的格式如下：
<function>:<command>:<parameter>
支援的 command 如下：
mod
此 command 使能了每個子產品的 function 過濾。parameter 指定目标子產品（使用 lsmod 看到的子產品），若隻需要 trace ext3 子產品中的 write*函數，運作：
echo '*write*:mod:vin_io' > set_ftrace_filter
/sys/kernel/debug/tracing # lsmod
Module Size Used by Not tainted
vin_io 53757 0
sha256_generic 10905 0
/sys/kernel/debug/tracing # echo '*write*:mod:vin_io' > set_ftrace_filter
/sys/kernel/debug/tracing # cat set_ftrace_filter
cci_write_a8_d8 [vin_io]
cci_write_a8_d16 [vin_io]
cci_write_a16_d8 [vin_io]
cci_write_a16_d16 [vin_io]
cci_write_a0_d16 [vin_io]
cci_write [vin_io]
cci_write_a16_d8_continuous_helper [vin_io]
sensor_write [vin_io]
sensor_write_array [vin_io]
vin_gpio_write [vin_io]
os_gpio_write [vin_io]
/sys/kernel/debug/tracing #
向 filter 節點添加不同子產品可以使用追加的方式(>>)，移除指定的子產品functions 可以重新追加"!":
echo '*gpio*:mod:vin_io' >> set_ftrace_filter
**
traceon/traceoff
**此 command 用于在當指定的 function 命中後，開啟或關閉 tracing。parameter 确定 tracing system 的開/關次數。若沒有指定，則無限制。比如，當__schedule_bug 函數被命中後關閉 tracing，以後每次命中都會關閉 tracing，直到命中了 5 次後，traceoff 指令将失效。
/sys/kernel/debug/tracing # echo '__schedule_bug:traceoff:5' > set_ftrace_filter
值得注意的是，這些 command 是累計的，不管是否使用追加的方式添加到set_ftrace_filter。重新追加 '!'來移除相應的 command，不要帶 parameter：
/sys/kernel/debug/tracing # echo '!__schedule_bug:traceoff' > set_ftrace_filter
**
dump/cpudump
**此指令在 liunx-3.10 以上的版本才支援的：
-
dump
當該函數被命中時，它會将 ftrace 環形緩沖區的内容dump到控制台。 如果您需要調試某些内容，并希望在某個函數被命中時dump跟蹤，這将非常有用。 也許它是在發生三重故障之前調用的函數，并且不允許您獲得正常轉儲。
-
cpudump
當該函數被命中時，它會将目前 CPU 的 ftrace 環形緩沖區的内容dump到控制台。 與“dump”指令不同，它隻為執行觸發dump的函數的 CPU 列印出環形緩沖區的内容。
注意事項
一般情況下，我們都需要先設定過濾器，然後在進行 tracing。要不然，預設時，所有可以被跟蹤的函數(available_filter_functions 中記錄了接近3萬個（測試環境有23966個函數）可以被跟蹤的函數)都被跟蹤，很容易把系統弄當機。
/sys/kernel/debug/tracing # cat available_filter_functions | wc
23966 23966 463605
ftrace 的使用
ftrace 在核心态工作，使用者通過 debugfs 接口來控制和使用 ftrace 。從2.6.30 開始，ftrace 支援兩大類 tracer：傳統 tracer 和 Non-Tracer Tracer。下面将分别介紹它們的使用。
傳統 Tracer
使用傳統的 ftrace 需要如下幾個步驟：
1. 選擇一種 tracer；
選擇 tracer 的控制檔案叫作 current_tracer。選擇 tracer 就是将tracer 的名字寫入這個檔案，比如，使用者打算使用 function tracer，可輸入如下指令：
/sys/kernel/debug/tracing # echo function_graph > current_tracer
2. 使能 ftrace/tracer；
使能 ftrace 使用下面的指令：
/sys/kernel/debug/tracing # echo 1 > /proc/sys/kernel/ftrace_enabled
系統預設也是使能的。檔案 tracing_enabled 控制 tracer 的開始和結束。
/sys/kernel/debug/tracing # echo 1 > tracing_enable
上面的指令使能 tracer。同樣，将 0 寫入 tracing_enable 檔案便可以停止 tracer。
3. 執行需要 trace 的應用程式，比如需要跟蹤 ls，就執行 ls；
4. 關閉 tracer；
5. 檢視 trace 檔案；
ftrace 的輸出資訊主要儲存在 3 個檔案中：
trace，該檔案儲存 ftrace 的輸出資訊，其内容可以直接閱讀。
latency_trace，儲存與 trace 相同的資訊，不過組織方式略有不同。主要為了使用者能友善地分析系統中有關延遲的資訊。
trace_pipe，是一個管道檔案，内容與 trace 節點相同，但它以流形式儲存 trace 結果。在沒有資料可讀時，對此節點的讀會被 block 住，直到有新資料産生。與 trace 節點不同的是，它的資料是消耗型的。在此節點可以一直往下讀，進而顯示更多的目前資料，資料一旦從節點中讀出，就被消耗了，不會再被讀到。而 trace 節點是靜态的，如果沒有新的 tracing 結果，每次讀都會顯示相同的資訊。此節點很有用，因為 ring buffer 大小是有限的，隻能儲存一定量的tracing 結果，太多則前面的結果将會被覆寫，而通過此節點可以把tracing 結果持續導出，作整體分析。在 android 下可以執行以下指令把 tracing 結果實時儲存到 pc 中（ps：trace_pipe是不斷生成的資料）：
adb pull /sys/kernel/debug/tracing/trace_pipe E:\temp_file\ftrace.bin
[ ?] /sys/kernel/debug/tracing/trace_pipe: 14855445/?
使用者通過讀寫 debugfs 檔案系統中的控制檔案完成上述步驟。下面将詳細解析各種傳統 tracer 的使用方式。
function tracer執行流程
/ #
/ # mount -t debugfs null /sys/kernel/debug/ #1.挂載debugfs
/ # mkdir -p tmp/temp_file #2.建立temp_file目錄
/ # mount /dev/mmcblk0p1 tmp/temp_file/ #3.将mmcblk0p1挂載到temp_file
/ #
/ # cd sys/kernel/debug/tracing/ #4.cd到tracing目錄
/sys/kernel/debug/tracing # echo 0 > tracing_on #5.暫停tracing跟蹤
/sys/kernel/debug/tracing # cat available_tracers #6.檢視支援的支援的跟蹤器
blk function_graph wakeup_dl wakeup_rt wakeup function nop
/sys/kernel/debug/tracing # echo nop> current_tracer #7.設定目前跟蹤器為nop清空資料
/sys/kernel/debug/tracing # echo function > current_tracer #8.設定目前跟蹤器為function
/sys/kernel/debug/tracing # echo '*jbd2*' > set_ftrace_filter #9.設定要指定的跟蹤的函數，跟蹤器為function有效
/sys/kernel/debug/tracing # echo 1 > tracing_on #10.開啟tracing跟蹤
/sys/kernel/debug/tracing # cp /tmp/temp_file/bootlogo.bmp /tmp/temp_file/bootlogo.bmp.bak #10.跟蹤cp的操作
/sys/kernel/debug/tracing # echo 0 > tracing_on #12.暫停tracing跟蹤
/sys/kernel/debug/tracing # cat trace #13.檢視跟蹤情況
# tracer: function
#
# entries-in-buffer/entries-written: 110/110 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
jbd2/mmcblk0p4--886 [001] ...1 2982.905548: jbd2_journal_commit_transaction <-kjournald2
jbd2/mmcblk0p4--886 [001] ...3 2982.905559: __jbd2_journal_clean_checkpoint_list <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...2 2982.905561: jbd2_clear_buffer_revoked_flags <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...2 2982.905566: jbd2_journal_switch_revoke_table <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2982.905574: jbd2_journal_write_revoke_records <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2982.905581: jbd2_journal_get_descriptor_buffer <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2982.905583: jbd2_journal_next_log_block <-jbd2_journal_get_descriptor_buffer
jbd2/mmcblk0p4--886 [001] ...1 2982.905587: jbd2_journal_bmap <-jbd2_journal_next_log_block
jbd2/mmcblk0p4--886 [001] ...1 2982.905640: jbd2_journal_next_log_block <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2982.905642: jbd2_journal_bmap <-jbd2_journal_next_log_block
jbd2/mmcblk0p4--886 [001] ...1 2982.905663: jbd2_journal_write_metadata_buffer <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...3 2982.905681: jbd2_buffer_frozen_trigger <-jbd2_journal_write_metadata_buffer
jbd2/mmcblk0p4--886 [001] ...3 2982.905684: __jbd2_journal_file_buffer <-jbd2_journal_write_metadata_buffer
jbd2/mmcblk0p4--886 [001] ...3 2982.905686: __jbd2_journal_temp_unlink_buffer <-__jbd2_journal_file_buffer
jbd2/mmcblk0p4--886 [001] ...1 2982.905690: jbd2_block_tag_csum_set <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2982.905693: jbd2_descriptor_block_csum_set <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2982.905783: jbd2_journal_get_log_tail <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2982.907391: jbd2_journal_file_buffer <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...3 2982.907393: __jbd2_journal_file_buffer <-jbd2_journal_file_buffer
jbd2/mmcblk0p4--886 [001] ...3 2982.907395: __jbd2_journal_temp_unlink_buffer <-__jbd2_journal_file_buffer
jbd2/mmcblk0p4--886 [001] ...1 2982.907399: jbd2_journal_get_descriptor_buffer <-journal_submit_commit_record
jbd2/mmcblk0p4--886 [001] ...1 2982.907400: jbd2_journal_next_log_block <-jbd2_journal_get_descriptor_buffer
jbd2/mmcblk0p4--886 [001] ...1 2982.907402: jbd2_journal_bmap <-jbd2_journal_next_log_block
jbd2/mmcblk0p4--886 [001] ...1 2982.907484: jbd2_commit_block_csum_set.isra.1 <-journal_submit_commit_record
jbd2/mmcblk0p4--886 [001] ...3 2982.907661: __jbd2_journal_insert_checkpoint <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...3 2982.907663: jbd2_journal_grab_journal_head <-__jbd2_journal_insert_checkpoint
jbd2/mmcblk0p4--886 [001] ...3 2982.907665: __jbd2_journal_refile_buffer <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...3 2982.907666: __jbd2_journal_unfile_buffer <-__jbd2_journal_refile_buffer
jbd2/mmcblk0p4--886 [001] ...3 2982.907668: __jbd2_journal_temp_unlink_buffer <-__jbd2_journal_unfile_buffer
jbd2/mmcblk0p4--886 [001] ...3 2982.907681: jbd2_journal_put_journal_head <-__jbd2_journal_unfile_buffer
ash-1017 [001] ...1 2992.652357: jbd2__journal_start <-__ext4_journal_start_sb
ash-1017 [001] ...1 2992.652405: jbd2_journal_free_transaction <-start_this_handle
ash-1017 [001] ...1 2992.652425: jbd2_journal_get_write_access <-__ext4_journal_get_write_access
ash-1017 [001] ...1 2992.652427: jbd2_journal_add_journal_head <-jbd2_journal_get_write_access
ash-1017 [001] ...3 2992.652433: __jbd2_journal_file_buffer <-do_get_write_access
ash-1017 [001] ...3 2992.652435: jbd2_journal_grab_journal_head <-__jbd2_journal_file_buffer
ash-1017 [001] ...1 2992.652438: jbd2_journal_cancel_revoke <-do_get_write_access
ash-1017 [001] ...1 2992.652439: jbd2_journal_put_journal_head <-jbd2_journal_get_write_access
ash-1017 [001] ...1 2992.652448: jbd2_journal_dirty_metadata <-__ext4_handle_dirty_metadata
ash-1017 [001] ...3 2992.652450: __jbd2_journal_file_buffer <-jbd2_journal_dirty_metadata
ash-1017 [001] ...3 2992.652452: __jbd2_journal_temp_unlink_buffer <-__jbd2_journal_file_buffer
ash-1017 [001] ...1 2992.652456: jbd2_journal_stop <-__ext4_journal_stop
ash-1017 [001] ...1 2992.652474: jbd2__journal_start <-__ext4_journal_start_sb
ash-1017 [001] ...1 2992.652486: jbd2_journal_free_transaction <-start_this_handle
ash-1017 [001] ...1 2992.652497: jbd2_journal_get_write_access <-__ext4_journal_get_write_access
ash-1017 [001] ...1 2992.652498: jbd2_write_access_granted.isra.0.part.1 <-jbd2_journal_get_write_access
ash-1017 [001] ...1 2992.652501: jbd2_journal_dirty_metadata <-__ext4_handle_dirty_metadata
ash-1017 [001] ...1 2992.652506: jbd2__journal_start <-__ext4_journal_start_sb
ash-1017 [001] ...1 2992.652508: jbd2_journal_get_write_access <-__ext4_journal_get_write_access
ash-1017 [001] ...1 2992.652509: jbd2_write_access_granted.isra.0.part.1 <-jbd2_journal_get_write_access
ash-1017 [001] ...1 2992.652512: jbd2_journal_dirty_metadata <-__ext4_handle_dirty_metadata
ash-1017 [001] ...1 2992.652513: jbd2_journal_stop <-__ext4_journal_stop
ash-1017 [001] ...1 2992.652515: jbd2_journal_stop <-__ext4_journal_stop
jbd2/mmcblk0p4--886 [001] ...1 2998.009539: jbd2_journal_commit_transaction <-kjournald2
jbd2/mmcblk0p4--886 [001] ...3 2998.009550: __jbd2_journal_clean_checkpoint_list <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...2 2998.009553: jbd2_clear_buffer_revoked_flags <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...2 2998.009558: jbd2_journal_switch_revoke_table <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2998.009566: jbd2_journal_write_revoke_records <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2998.009573: jbd2_journal_get_descriptor_buffer <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2998.009575: jbd2_journal_next_log_block <-jbd2_journal_get_descriptor_buffer
jbd2/mmcblk0p4--886 [001] ...1 2998.009578: jbd2_journal_bmap <-jbd2_journal_next_log_block
jbd2/mmcblk0p4--886 [001] ...1 2998.009631: jbd2_journal_next_log_block <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2998.009633: jbd2_journal_bmap <-jbd2_journal_next_log_block
jbd2/mmcblk0p4--886 [001] ...1 2998.009654: jbd2_journal_write_metadata_buffer <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...3 2998.009672: jbd2_buffer_frozen_trigger <-jbd2_journal_write_metadata_buffer
jbd2/mmcblk0p4--886 [001] ...3 2998.009675: __jbd2_journal_file_buffer <-jbd2_journal_write_metadata_buffer
jbd2/mmcblk0p4--886 [001] ...3 2998.009677: __jbd2_journal_temp_unlink_buffer <-__jbd2_journal_file_buffer
jbd2/mmcblk0p4--886 [001] ...1 2998.009680: jbd2_block_tag_csum_set <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2998.009684: jbd2_descriptor_block_csum_set <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2998.009771: jbd2_journal_get_log_tail <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...1 2998.011275: jbd2_journal_file_buffer <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...3 2998.011278: __jbd2_journal_file_buffer <-jbd2_journal_file_buffer
jbd2/mmcblk0p4--886 [001] ...3 2998.011279: __jbd2_journal_temp_unlink_buffer <-__jbd2_journal_file_buffer
jbd2/mmcblk0p4--886 [001] ...1 2998.011283: jbd2_journal_get_descriptor_buffer <-journal_submit_commit_record
jbd2/mmcblk0p4--886 [001] ...1 2998.011285: jbd2_journal_next_log_block <-jbd2_journal_get_descriptor_buffer
jbd2/mmcblk0p4--886 [001] ...1 2998.011287: jbd2_journal_bmap <-jbd2_journal_next_log_block
jbd2/mmcblk0p4--886 [001] ...1 2998.011316: jbd2_commit_block_csum_set.isra.1 <-journal_submit_commit_record
jbd2/mmcblk0p4--886 [001] ...3 2998.011884: __jbd2_journal_remove_checkpoint <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...3 2998.011886: jbd2_journal_put_journal_head <-__jbd2_journal_remove_checkpoint
jbd2/mmcblk0p4--886 [001] ...3 2998.011888: __jbd2_journal_drop_transaction <-__jbd2_journal_remove_checkpoint
jbd2/mmcblk0p4--886 [001] ...3 2998.011890: jbd2_journal_free_transaction <-__jbd2_journal_remove_checkpoint
jbd2/mmcblk0p4--886 [001] ...3 2998.011904: __jbd2_journal_insert_checkpoint <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...3 2998.011905: jbd2_journal_grab_journal_head <-__jbd2_journal_insert_checkpoint
jbd2/mmcblk0p4--886 [001] ...3 2998.011907: __jbd2_journal_refile_buffer <-jbd2_journal_commit_transaction
jbd2/mmcblk0p4--886 [001] ...3 2998.011908: __jbd2_journal_unfile_buffer <-__jbd2_journal_refile_buffer
jbd2/mmcblk0p4--886 [001] ...3 2998.011909: __jbd2_journal_temp_unlink_buffer <-__jbd2_journal_unfile_buffer
jbd2/mmcblk0p4--886 [001] ...3 2998.011912: jbd2_journal_put_journal_head <-__jbd2_journal_unfile_buffer
ash-1017 [001] ...1 3001.323174: jbd2__journal_start <-__ext4_journal_start_sb
ash-1017 [001] ...1 3001.323222: jbd2_journal_free_transaction <-start_this_handle
ash-1017 [001] ...1 3001.323233: jbd2_journal_get_write_access <-__ext4_journal_get_write_access
ash-1017 [001] ...1 3001.323236: jbd2_journal_add_journal_head <-jbd2_journal_get_write_access
ash-1017 [001] ...3 3001.323242: __jbd2_journal_file_buffer <-do_get_write_access
ash-1017 [001] ...3 3001.323244: jbd2_journal_grab_journal_head <-__jbd2_journal_file_buffer
ash-1017 [001] ...1 3001.323247: jbd2_journal_cancel_revoke <-do_get_write_access
ash-1017 [001] ...1 3001.323249: jbd2_journal_put_journal_head <-jbd2_journal_get_write_access
ash-1017 [001] ...1 3001.323257: jbd2_journal_dirty_metadata <-__ext4_handle_dirty_metadata
ash-1017 [001] ...3 3001.323260: __jbd2_journal_file_buffer <-jbd2_journal_dirty_metadata
ash-1017 [001] ...3 3001.323261: __jbd2_journal_temp_unlink_buffer <-__jbd2_journal_file_buffer
ash-1017 [001] ...1 3001.323265: jbd2_journal_stop <-__ext4_journal_stop
ash-1017 [001] ...1 3001.323284: jbd2__journal_start <-__ext4_journal_start_sb
ash-1017 [001] ...1 3001.323296: jbd2_journal_free_transaction <-start_this_handle
ash-1017 [001] ...1 3001.323306: jbd2_journal_get_write_access <-__ext4_journal_get_write_access
ash-1017 [001] ...1 3001.323308: jbd2_write_access_granted.isra.0.part.1 <-jbd2_journal_get_write_access
ash-1017 [001] ...1 3001.323311: jbd2_journal_dirty_metadata <-__ext4_handle_dirty_metadata
ash-1017 [001] ...1 3001.323316: jbd2__journal_start <-__ext4_journal_start_sb
ash-1017 [001] ...1 3001.323318: jbd2_journal_get_write_access <-__ext4_journal_get_write_access
ash-1017 [001] ...1 3001.323319: jbd2_write_access_granted.isra.0.part.1 <-jbd2_journal_get_write_access
ash-1017 [001] ...1 3001.323321: jbd2_journal_dirty_metadata <-__ext4_handle_dirty_metadata
ash-1017 [001] ...1 3001.323323: jbd2_journal_stop <-__ext4_journal_stop
ash-1017 [001] ...1 3001.323324: jbd2_journal_stop <-__ext4_journal_stop
/sys/kernel/debug/tracing #
function_graph tracer執行流程
/ #
/ # mount -t debugfs null /sys/kernel/debug/ #1.挂載debugfs
/ # mkdir -p tmp/temp_file #2.建立temp_file目錄
/ # mount /dev/mmcblk0p1 tmp/temp_file/ #3.将mmcblk0p1挂載到temp_file
/ #
/ # cd sys/kernel/debug/tracing/ #4.cd到tracing目錄
/sys/kernel/debug/tracing # cat available_tracers #5.檢視支援的支援的跟蹤器
blk function_graph wakeup_dl wakeup_rt wakeup function nop
/sys/kernel/debug/tracing # echo 0 > tracing_on #6.暫停tracing跟蹤
/sys/kernel/debug/tracing # echo function_graph > current_tracer #7.設定目前跟蹤器為function_graph
/sys/kernel/debug/tracing # echo '*jbd2*' > set_graph_function #8.設定要顯示的跟蹤的函數，跟蹤器為function_graph有效
/sys/kernel/debug/tracing # echo 1 > tracing_on #9.開啟tracing跟蹤
/sys/kernel/debug/tracing # cp /tmp/temp_file/bootlogo.bmp /tmp/temp_file/bootlogo.bmp.bak #10.跟蹤cp的操作
/sys/kernel/debug/tracing # echo 0 > tracing_on #11.暫停tracing跟蹤
/sys/kernel/debug/tracing # cat trace #12.檢視跟蹤情況
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
1) 0.750 us | jbd2_buffer_frozen_trigger();
1) | __jbd2_journal_file_buffer() {
1) 1.292 us | __jbd2_journal_temp_unlink_buffer();
1) 5.000 us | }
1) | jbd2_journal_file_buffer() {
1) | __jbd2_journal_file_buffer() {
1) 0.542 us | __jbd2_journal_temp_unlink_buffer();
1) 3.625 us | }
1) 6.959 us | }
1) + 12.333 us | jbd2_journal_free_transaction();
1) | __jbd2_journal_refile_buffer() {
1) | __jbd2_journal_unfile_buffer() {
1) 1.292 us | __jbd2_journal_temp_unlink_buffer();
1) 0.375 us | jbd2_journal_put_journal_head();
1) 6.083 us | }
1) 9.042 us | }
3) | jbd2__journal_start() {
3) 0.459 us | jbd2_journal_free_transaction();
3) + 47.166 us | }
3) | jbd2_journal_get_write_access() {
3) 0.459 us | jbd2_write_access_granted.isra.0.part.1();
3) + 16.000 us | jbd2_journal_add_journal_head();
3) | __jbd2_journal_file_buffer() {
3) 0.833 us | jbd2_journal_grab_journal_head();
3) 4.750 us | }
3) 2.583 us | jbd2_journal_cancel_revoke();
3) 0.916 us | jbd2_journal_put_journal_head();
3) + 42.041 us | }
3) | jbd2_journal_get_write_access() {
3) 0.334 us | jbd2_write_access_granted.isra.0.part.1();
3) 9.833 us | jbd2_journal_add_journal_head();
3) | __jbd2_journal_file_buffer() {
3) 0.375 us | jbd2_journal_grab_journal_head();
3) 2.750 us | }
3) 0.333 us | jbd2_journal_cancel_revoke();
3) 0.417 us | jbd2_journal_put_journal_head();
3) + 25.125 us | }
3) | jbd2_journal_dirty_metadata() {
3) | __jbd2_journal_file_buffer() {
3) 0.750 us | __jbd2_journal_temp_unlink_buffer();
3) 3.542 us | }
3) 7.500 us | }
3) | jbd2_journal_dirty_metadata() {
3) | __jbd2_journal_file_buffer() {
3) 0.292 us | __jbd2_journal_temp_unlink_buffer();
3) 2.666 us | }
3) 5.500 us | }
3) | jbd2_journal_get_write_access() {
3) 0.667 us | jbd2_journal_add_journal_head();
3) | __jbd2_journal_file_buffer() {
3) 0.375 us | jbd2_journal_grab_journal_head();
3) 2.958 us | }
3) 0.334 us | jbd2_journal_cancel_revoke();
3) 0.375 us | jbd2_journal_put_journal_head();
3) + 13.959 us | }
3) | jbd2_journal_dirty_metadata() {
3) | __jbd2_journal_file_buffer() {
3) 0.375 us | __jbd2_journal_temp_unlink_buffer();
3) 2.959 us | }
3) 5.709 us | }
3) 0.292 us | jbd2__journal_start();
3) | jbd2_journal_get_write_access() {
3) 0.333 us | jbd2_write_access_granted.isra.0.part.1();
3) 2.666 us | }
3) 0.375 us | jbd2_journal_dirty_metadata();
3) 0.625 us | jbd2_journal_stop();
3) 1.333 us | jbd2_journal_file_inode();
3) | jbd2_journal_get_write_access() {
3) 0.375 us | jbd2_write_access_granted.isra.0.part.1();
3) 2.791 us | }
3) 0.291 us | jbd2_journal_dirty_metadata();
3) + 12.458 us | jbd2_journal_stop();
3) | jbd2__journal_start() {
3) 0.250 us | jbd2_journal_free_transaction();
3) + 14.209 us | }
3) 7.458 us | jbd2_journal_stop();
3) | jbd2__journal_start() {
3) 0.250 us | jbd2_journal_free_transaction();
3) + 13.084 us | }
3) 7.750 us | jbd2_journal_stop();
------------------------------------------
1) jbd2/mm-886 => ash-1017
------------------------------------------
1) | jbd2__journal_start() {
1) 0.709 us | jbd2_journal_free_transaction();
1) + 25.000 us | }
1) | jbd2_journal_get_write_access() {
3) 0.292 us | jbd2__journal_start();
3) | jbd2_journal_get_write_access() {
3) 0.333 us | jbd2_write_access_granted.isra.0.part.1();
3) 2.666 us | }
3) 0.375 us | jbd2_journal_dirty_metadata();
3) 0.625 us | jbd2_journal_stop();
3) 1.333 us | jbd2_journal_file_inode();
3) | jbd2_journal_get_write_access() {
3) 0.375 us | jbd2_write_access_granted.isra.0.part.1();
3) 2.791 us | }
3) 0.291 us | jbd2_journal_dirty_metadata();
3) + 12.458 us | jbd2_journal_stop();
3) | jbd2__journal_start() {
3) 0.250 us | jbd2_journal_free_transaction();
3) + 14.209 us | }
3) 7.458 us | jbd2_journal_stop();
3) | jbd2__journal_start() {
3) 0.250 us | jbd2_journal_free_transaction();
3) + 13.084 us | }
3) 7.750 us | jbd2_journal_stop();
1) | jbd2__journal_start() {
1) 0.709 us | jbd2_journal_free_transaction();
1) + 25.000 us | }
1) | jbd2_journal_get_write_access() {
1) 0.458 us | jbd2_write_access_granted.isra.0.part.1();
1) 3.458 us | }
1) 0.917 us | jbd2_journal_dirty_metadata();
1) 9.417 us | jbd2_journal_stop();
1) | jbd2__journal_start() {
1) 0.208 us | jbd2_journal_free_transaction();
1) + 13.833 us | }
1) | jbd2_journal_get_write_access() {
1) 0.333 us | jbd2_write_access_granted.isra.0.part.1();
1) 2.708 us | }
1) 0.291 us | jbd2_journal_dirty_metadata();
1) 0.292 us | jbd2__journal_start();
1) | jbd2_journal_get_write_access() {
1) 0.333 us | jbd2_write_access_granted.isra.0.part.1();
1) 2.625 us | }
1) 0.250 us | jbd2_journal_dirty_metadata();
1) 0.292 us | jbd2_journal_stop();
1) 7.500 us | jbd2_journal_stop();
3) | jbd2__journal_start() {
3) 0.542 us | jbd2_journal_free_transaction();
3) + 23.334 us | }
3) | jbd2_journal_stop() {
3) | jbd2_log_start_commit() {
3) + 12.375 us | __jbd2_log_start_commit();
3) + 16.334 us | }
3) + 29.167 us | }
3) | jbd2__journal_start() {
3) 0.250 us | jbd2_journal_free_transaction();
3) + 36.042 us | }
3) 7.833 us | jbd2_journal_stop();
2) 0.458 us | jbd2_buffer_frozen_trigger();
2) | __jbd2_journal_file_buffer() {
2) 1.084 us | __jbd2_journal_temp_unlink_buffer();
2) 5.167 us | }
2) 0.250 us | jbd2_buffer_frozen_trigger();
2) | __jbd2_journal_file_buffer() {
2) 0.375 us | __jbd2_journal_temp_unlink_buffer();
2) 3.042 us | }
2) 0.250 us | jbd2_buffer_frozen_trigger();
2) | __jbd2_journal_file_buffer() {
2) 0.333 us | __jbd2_journal_temp_unlink_buffer();
2) 3.000 us | }
2) | jbd2_journal_file_buffer() {
2) | __jbd2_journal_file_buffer() {
2) 0.833 us | __jbd2_journal_temp_unlink_buffer();
2) 4.625 us | }
2) 8.375 us | }
2) | jbd2_journal_file_buffer() {
2) | __jbd2_journal_file_buffer() {
2) 0.375 us | __jbd2_journal_temp_unlink_buffer();
2) 2.959 us | }
2) 5.584 us | }
2) | jbd2_journal_file_buffer() {
2) | __jbd2_journal_file_buffer() {
2) 0.375 us | __jbd2_journal_temp_unlink_buffer();
2) 3.084 us | }
2) 5.709 us | }
2) + 11.000 us | jbd2_journal_free_transaction();
2) | __jbd2_journal_refile_buffer() {
2) | __jbd2_journal_unfile_buffer() {
2) 8.917 us | __jbd2_journal_temp_unlink_buffer();
2) 0.375 us | jbd2_journal_put_journal_head();
2) + 13.792 us | }
2) + 16.958 us | }
2) | __jbd2_journal_refile_buffer() {
2) | __jbd2_journal_unfile_buffer() {
2) 3.042 us | __jbd2_journal_temp_unlink_buffer();
2) 0.375 us | __jbd2_journal_temp_unlink_buffer();
2) 3.042 us | } /* __jbd2_journal_file_buffer */
2) 0.250 us | jbd2_buffer_frozen_trigger();
2) | __jbd2_journal_file_buffer() {
2) 0.333 us | __jbd2_journal_temp_unlink_buffer();
2) 3.000 us | }
2) | jbd2_journal_file_buffer() {
2) | __jbd2_journal_file_buffer() {
2) 0.833 us | __jbd2_journal_temp_unlink_buffer();
2) 4.625 us | }
2) 8.375 us | }
2) | jbd2_journal_file_buffer() {
2) | __jbd2_journal_file_buffer() {
2) 0.375 us | __jbd2_journal_temp_unlink_buffer();
2) 2.959 us | }
2) 5.584 us | }
2) | jbd2_journal_file_buffer() {
2) | __jbd2_journal_file_buffer() {
2) 0.375 us | __jbd2_journal_temp_unlink_buffer();
2) 3.084 us | }
2) 5.709 us | }
2) + 11.000 us | jbd2_journal_free_transaction();
2) | __jbd2_journal_refile_buffer() {
2) | __jbd2_journal_unfile_buffer() {
2) 8.917 us | __jbd2_journal_temp_unlink_buffer();
2) 0.375 us | jbd2_journal_put_journal_head();
2) + 13.792 us | }
2) + 16.958 us | }
2) | __jbd2_journal_refile_buffer() {
2) | __jbd2_journal_unfile_buffer() {
2) 3.042 us | __jbd2_journal_temp_unlink_buffer();
2) 0.417 us | jbd2_journal_put_journal_head();
2) 9.042 us | }
2) + 11.250 us | }
2) | __jbd2_journal_refile_buffer() {
2) | __jbd2_journal_unfile_buffer() {
2) 3.166 us | __jbd2_journal_temp_unlink_buffer();
2) 0.375 us | jbd2_journal_put_journal_head();
2) 8.083 us | }
2) + 10.459 us | }
------------------------------------------
3) kworker-30 => jbd2/mm-886
------------------------------------------
3) + 13.292 us | jbd2_journal_free_transaction();
1) | jbd2__journal_start() {
1) 0.583 us | jbd2_journal_free_transaction();
1) + 47.583 us | }
1) | jbd2_journal_get_write_access() {
1) 1.584 us | jbd2_journal_add_journal_head();
1) | __jbd2_journal_file_buffer() {
1) 0.834 us | jbd2_journal_grab_journal_head();
1) 4.917 us | }
1) 0.708 us | jbd2_journal_cancel_revoke();
1) 0.750 us | jbd2_journal_put_journal_head();
1) + 22.750 us | }
1) | jbd2_journal_dirty_metadata() {
1) | __jbd2_journal_file_buffer() {
1) 0.750 us | __jbd2_journal_temp_unlink_buffer();
1) 3.542 us | }
1) 7.417 us | }
1) 10.000 us | jbd2_journal_stop();
1) | jbd2__journal_start() {
1) 0.250 us | jbd2_journal_free_transaction();
1) + 13.875 us | }
1) | jbd2_journal_get_write_access() {
1) 0.500 us | jbd2_write_access_granted.isra.0.part.1();
1) 3.417 us | }
1) 0.417 us | jbd2_journal_dirty_metadata();
1) 0.291 us | jbd2__journal_start();
1) | jbd2_journal_get_write_access() {
1) 0.292 us | jbd2_write_access_granted.isra.0.part.1();
1) 2.667 us | }
1) 0.250 us | jbd2_journal_dirty_metadata();
1) 0.333 us | jbd2_journal_stop();
1) 7.459 us | jbd2_journal_stop();
------------------------------------------
2) jbd2/mm-886 => ash-1017
------------------------------------------
2) | jbd2__journal_start() {
2) 0.458 us | jbd2_journal_free_transaction();
2) + 26.000 us | }
2) | jbd2_journal_get_write_access() {
2) 0.708 us | jbd2_write_access_granted.isra.0.part.1();
2) 3.917 us | }
2) 0.667 us | jbd2_journal_dirty_metadata();
2) 9.333 us | jbd2_journal_stop();
2) | jbd2__journal_start() {
2) 0.250 us | jbd2_journal_free_transaction();
2) + 13.792 us | }
2) | jbd2_journal_get_write_access() {
1) 0.500 us | jbd2_write_access_granted.isra.0.part.1();
1) 3.417 us | } /* jbd2_journal_get_write_access */
1) 0.417 us | jbd2_journal_dirty_metadata();
1) 0.291 us | jbd2__journal_start();
1) | jbd2_journal_get_write_access() {
1) 0.292 us | jbd2_write_access_granted.isra.0.part.1();
1) 2.667 us | }
1) 0.250 us | jbd2_journal_dirty_metadata();
1) 0.333 us | jbd2_journal_stop();
1) 7.459 us | jbd2_journal_stop();
2) | jbd2__journal_start() {
2) 0.458 us | jbd2_journal_free_transaction();
2) + 26.000 us | }
2) | jbd2_journal_get_write_access() {
2) 0.708 us | jbd2_write_access_granted.isra.0.part.1();
2) 3.917 us | }
2) 0.667 us | jbd2_journal_dirty_metadata();
2) 9.333 us | jbd2_journal_stop();
2) | jbd2__journal_start() {
2) 0.250 us | jbd2_journal_free_transaction();
2) + 13.792 us | }
2) | jbd2_journal_get_write_access() {
2) 0.334 us | jbd2_write_access_granted.isra.0.part.1();
2) 2.708 us | }
2) 0.292 us | jbd2_journal_dirty_metadata();
2) 0.291 us | jbd2__journal_start();
2) | jbd2_journal_get_write_access() {
2) 0.334 us | jbd2_write_access_granted.isra.0.part.1();
2) 2.625 us | }
2) 0.292 us | jbd2_journal_dirty_metadata();
2) 0.250 us | jbd2_journal_stop();
2) 7.625 us | jbd2_journal_stop();
/sys/kernel/debug/tracing #
blk tracer
Blk tracer 是用來對 block 子產品進行跟蹤的。例如，在 android 系統中插入一個 U 盤後，對此 U 盤裝置(sda1)的行為進行跟蹤，具體的執行流程，如下圖所示：
當向 sda1分區的 filetest 檔案寫入“12345”的資料後，出現一些“WS”類型的資訊被記錄下來了。輸出資訊的具體格式請參考 blktrace 的相關文檔。
blk tracer 可以很友善的跟蹤塊 IO 子系統通用塊層的資料流動線路。
可以對感興趣的 disk 或分區啟用 trace。啟用方法很簡單，舉個例子，使能對 mmcblk0p1分區的 trace。
# echo 1 > /sys/block/mmcblk0/mmcblk0p1/trace/enable
# echo blk > /d/tracing/current_tracer
# cat /d/tracing/trace：
<...>-14762 (-----) [001] ...1 354237.801020: 179,1 A W 5625185 + 1 <- (179,1)
46433
<...>-14762 (-----) [001] ...1 354237.801022: 179,1 Q W 5625185 + 1 [<...>]
<...>-14762 (-----) [001] ...1 354237.801026: 179,1 B W 5625185 + 1 [<...>]
<...>-14762 (-----) [001] ...1 354237.801028: 179,1 M W 5625185 + 1 [<...>]
<...>-14762 (-----) [001] ...2 354237.801040: 179,1 I W 5600588 + 40 [<...>]
<...>-14762 (-----) [001] ...1 354237.801046: 179,1 m N cfq122 insert_request
……
<...>-15129 (-----) [001] ...1 354237.801165: 179,1 m N cfq122 slice expired
t=1
<...>-15129 (-----) [001] ...1 354237.801169: 179,1 m N cfq122 resid=4
<...>-15129 (-----) [001] ...1 354237.801174: 179,1 m N cfq122 sl_used=1
disp=1 charge=1 iops=0 sect=40
<...>-93 (-----) [000] ...1 354237.801179: 179,1 m N cfq workload slice:10
<...>-93 (-----) [000] ...1 354237.801182: 179,1 m N cfq15129 set_active
wl_prio:0 wl_type:1
<...>-93 (-----) [000] ...2 354237.802140: 179,1 C W 5600588 + 40 [0]
通過 trace 結果可以明确看到請求添加、執行的整體流程。但列印是相當多的，要把握住一段時間的 IO 情況，需要借助工具來進行分析。
沒 有 找 到 内 核 的 說 明 文 檔 ， 需 要 看 代 碼（linux-3.4/kernel/trace/blktrace.c）來确定每一列的含義：
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID TGID CPU# |||| TIMESTAMP DEV ACT FLG
# | | | | |||| | | | |
<...>-14762 (-----) [001] ...1 354237.800897: 179,1 A W 5625175 + 1 <- (179,1) 46423
<...>-14762 (-----) [001] ...1 354237.800899: 179,1 Q W 5625175 + 1 [<...>]
第6列：裝置号
第7列：正在進行的 action
static const struct {
const char *act[2];
int (*print)(struct trace_seq *s, const struct trace_entry *ent);
} what2act[] = {
[__BLK_TA_QUEUE] = {{ "Q", "queue" }, blk_log_generic },
[__BLK_TA_BACKMERGE] = {{ "M", "backmerge" }, blk_log_generic },
[__BLK_TA_FRONTMERGE] = {{ "F", "frontmerge" }, blk_log_generic },
[__BLK_TA_GETRQ] = {{ "G", "getrq" }, blk_log_generic },
[__BLK_TA_SLEEPRQ] = {{ "S", "sleeprq" }, blk_log_generic },
[__BLK_TA_REQUEUE] = {{ "R", "requeue" }, blk_log_with_error },
[__BLK_TA_ISSUE] = {{ "D", "issue" }, blk_log_generic },
[__BLK_TA_COMPLETE] = {{ "C", "complete" }, blk_log_with_error },
[__BLK_TA_PLUG] = {{ "P", "plug" }, blk_log_plug },
[__BLK_TA_UNPLUG_IO] = {{ "U", "unplug_io" }, blk_log_unplug },
[__BLK_TA_UNPLUG_TIMER] = {{ "UT", "unplug_timer" }, blk_log_unplug },
[__BLK_TA_INSERT] = {{ "I", "insert" }, blk_log_generic },
[__BLK_TA_SPLIT] = {{ "X", "split" }, blk_log_split },
[__BLK_TA_BOUNCE] = {{ "B", "bounce" }, blk_log_generic },
[__BLK_TA_REMAP] = {{ "A", "remap" }, blk_log_remap },
};
Q: 對應 trace_block_bio_queue，添加在 generic_make_request_checks()函數末尾（linux-3.4/block/blk-core.c）
M: 對應 trace_block_bio_backmerge，添加在 bio_attempt_back_merge()函數中（linux-3.4/block/blk-core.c）
F: 對應 trace_block_bio_frontmerge，添加在 bio_attempt_front_merge()函數中（linux-3.4/block/blk-core.c）
G: 對 應 trace_block_getrq ， 添 加 在 get_request() 函 數 末 尾（linux-3.4/block/blk-core.c）
S: 對 應 trace_block_sleeprq ， 添 加 在 get_request_wait() 函 數 中（linux-3.4/block/blk-core.c）
R: 對應 trace_block_rq_requeue，添加在 blk_requeue_request()函數中（linux-3.4/block/blk-core.c）
D: 對 應 trace_block_rq_issue ， 添 加 在 blk_peek_request() 函 數 中（linux-3.4/block/blk-core.c）
C: 對應 trace_block_rq_complete，添加在 blk_update_request()函數起始位置（linux-3.4/block/blk-core.c）
P: 對應 trace_block_plug，添加在 blk_queue_bio()函數中的兩處，當plug->list 為空時，和在 blk_flush_plug_list()之後，沒有在 blk_start_plug()函數裡加，它隻是保證程序的 plug 域不為空，沒有實際的 plug 操作。（linux-3.4/block/blk-core.c）
U: 對 應 trace_block_unplug ， 添 加 在 queue_unplugged() 函 數 中 ，blk_finish_plug()會調用到（linux-3.4/block/blk-core.c）
UT:
I: 對應 trace_block_rq_insert，添加在__elv_add_request()函數起始位置（linux-3.4/block/elevator.c）
X: 對 應 trace_block_split ， 添 加 在 bio_split() 函 數 中（linux-3.4/fs/bio.c）
B: 對應 trace_block_bio_bounce，添加在__blk_queue_bounce()函數中（linux-3.4/mm/bounce.c）
A: 對應 trace_block_bio_remap，添加在 blk_partition_remap()函數中（linux-3.4/block/blk-core.c）
還有3個 trace point 沒有對應的 action：
trace_block_rq_remap
trace_block_bio_complete
trace_block_rq_abort
第8列：請求标志
void blk_fill_rwbs(char *rwbs, u32 rw, int bytes)
{
int i = 0;
if (rw & REQ_FLUSH)
rwbs[i++] = 'F';
if (rw & WRITE)
rwbs[i++] = 'W';
else if (rw & REQ_DISCARD)
rwbs[i++] = 'D';
else if (bytes)
rwbs[i++] = 'R';
else
rwbs[i++] = 'N';
if (rw & REQ_FUA)
rwbs[i++] = 'F';
if (rw & REQ_RAHEAD)
rwbs[i++] = 'A';
if (rw & REQ_SYNC)
rwbs[i++] = 'S';
if (rw & REQ_META)
rwbs[i++] = 'M';
if (rw & REQ_SECURE)
rwbs[i++] = 'E';
rwbs[i] = '\0';
}
第9列：起始扇區号
第10列：扇區數
第11列：程序名（action 是 A 時，為 “(裝置号) 相對分區位置”）
blk tracer 還提供了一些選項:
# ls -l /sys/block/mmcblk0/mmcblk0p1/trace
-rw-r--r-- root root 4096 2015-01-06 13:59 act_mask
-rw-r--r-- root root 4096 2015-01-14 13:34 enable
-rw-r--r-- root root 4096 2015-01-06 13:59 end_lba
-rw-r--r-- root root 4096 2015-01-06 13:59 pid
-rw-r--r-- root root 4096 2015-01-06 13:59 start_lba
act_mask在使能對 mmcblk0p1分區的 trace 後，
# cat act_mask
read,write,flush,sync,queue,requeue,issue,complete,fs,pc,ahead,meta,discard,drv_data,fua
static const struct {
int mask;
const char *str;
} mask_maps[] = {
{ BLK_TC_READ, "read" },
{ BLK_TC_WRITE, "write" },
{ BLK_TC_FLUSH, "flush" },
{ BLK_TC_SYNC, "sync" },
{ BLK_TC_QUEUE, "queue" },
{ BLK_TC_REQUEUE,"requeue"},
{ BLK_TC_ISSUE, "issue" },
{ BLK_TC_COMPLETE, "complete" },
{ BLK_TC_FS, "fs" },
{ BLK_TC_PC, "pc" },
{ BLK_TC_AHEAD, "ahead" },
{ BLK_TC_META, "meta" },
{ BLK_TC_DISCARD, "discard" },
{ BLK_TC_DRV_DATA, "drv_data" },
{ BLK_TC_FUA, "fua" },
};
注意在 action 數組裡有__BLK_TA_QUEUE，在此數組有 BLK_TC_QUEUE，兩者有什麼差別？TA 指的是 trace action，tc 指的是 trace category。一個 category可以包含多個 action。
可以在 linux-3.4/include/linux/blktrace_api.h 中，檢視所有 action 和category 的對應關系：
/*
* Trace actions in full. Additionally, read or write is masked
*/
#define BLK_TA_QUEUE (__BLK_TA_QUEUE | BLK_TC_ACT(BLK_TC_QUEUE))
#define BLK_TA_BACKMERGE (__BLK_TA_BACKMERGE |
BLK_TC_ACT(BLK_TC_QUEUE))
#define BLK_TA_FRONTMERGE (__BLK_TA_FRONTMERGE |
BLK_TC_ACT(BLK_TC_QUEUE))
......
read：隻跟蹤讀請求
write：隻跟蹤寫請求
queue：Q、M、F、G、S、P、U、I、A
requeue：R
issue：D
complete：C
在 blk_add_trace_rq()函數中，區分 fs 和 pc：
pc：(rq->cmd_type == REQ_TYPE_BLOCK_PC)，scsi 指令
fs：else，fs 請求
ahead：在代碼中注釋是跟蹤 readahead，但要注意的是，它不是指檔案系統的預讀（沒有往下發 REQ_RAHEAD 标志），目前隻在直接對塊裝置的 block 進行操作時有使用（ll_rw_block()和 submit_bh()，讀寫方式為 READA）。
meta：跟蹤設定了 REQ_META 标志的請求
discard：跟蹤設定了 REQ_DISCARD 标志的請求
drv_data: 與 scsi 驅動有關，暫不跟進
貌似 act_mask 的 store 代碼有點問題：
echo discard > act_mask 後，act_mask 被設定為 read,flush,sync
fua: echo fua > act_mask 後，act_mask 被設定為 read,write,flush,sync而在前面加個","，則可以正常設定，如 echo ,discard > act_mask錯誤原因，在 sysfs_blk_trace_attr_store()函數中，由以下一段代碼：
if (sscanf(buf, "%llx", &value) != 1) {
/* Assume it is a list of trace category names */
ret = blk_trace_str2mask(buf);
if (ret < 0)
goto out;
value = ret;
}
在 sscanf 階段，discard 的首字母 d 被當成是十六進制數值，是以 sscanf可以擷取到 value，不會再執行大括号中的代碼，在後面把 value 值賦給 mask，是以 mask 變為0x0d，正好對應的是 read,flush,sync。
::: note
a. 各 category 之間是"或"的關系，隻要有一個符合，請求将會被 trace。若請求不符合 act_mask 中的所有 category，那麼這個請求不會被 trace。
b. act_mask 必須包含以下 category 中的一個（__blk_add_trace()），否則将 trace 不到任何東西。
:::
what |= ddir_act[rw & WRITE];
what |= MASK_TC_BIT(rw, SYNC);
what |= MASK_TC_BIT(rw, RAHEAD);
what |= MASK_TC_BIT(rw, META);
what |= MASK_TC_BIT(rw, DISCARD);
what |= MASK_TC_BIT(rw, FLUSH);
what |= MASK_TC_BIT(rw, FUA);
若有一個"與"關系的 mask，就可以更靈活一些，比如隻 trace 寫請求的完成狀态，可以設定 write,complete 到 mask 中，但目前還沒有這個功能。echowrite,complete > act_mask 跟蹤的是寫請求的全部 action 和各類型請求（不隻是寫）的 complete 操作。
- start_lba 和 end_lba 顯然，使用兩者可以對 disk 或分區的特定區域進行 trace。若未指定start_lba，則是分區的起始位址，若未指定 end_lba，則是分區的結束位址（disk是-1ULL）。注意，它們是在整個 disk 中的絕對位址，而不是相對分區的位址。
- pid 隻對指定 pid 的程序進行跟蹤。
Non-tracer tracer
從 2.6.30 開始，ftrace 還支援幾種 Non-tracer tracer，所謂 Non-tracertracer 主要包括以下幾種：
Max Stack Tracer
Profiling (branches / unlikely / likely / Functions)
Event tracing
和傳統的 tracer 不同，Non-Tracer Tracer 并不對每個核心函數進行跟蹤，而是一種類似邏輯分析儀的模式，即對系統進行采樣，但似乎也不完全如此。無論怎樣，這些 tracer 的使用方法和前面所介紹的 tracer 的使用稍有不同。下面我将試圖描述這些 tracer 的使用方法。
function_profile
前面我們已經提到過這個 tracer 了，它可以跟蹤所有執行到的函數的調用次數，執行時間等，可以給我們呈現一個整體的 top 圖，非常有用。使用者可以使用如下指令打開該 tracer(系統預設是關閉的)：
之後拷貝了一個1.68M 的檔案到 data 分區，然後檢視結果：
結果記錄在 trace_stat 目錄下的 functionX 中，“X”代表 CPU 号，即執行在此 cpu 号中的所有函數。
由于預設也是跟蹤所有可以跟蹤的函數(available_filter_functions)，為避免資訊量太大，這裡還是設定了過濾“jbd2”。
從輸出結果來看，記錄的資訊包括：函數執行的命中次數，函數執行的總時間、平均時間和方差。方內插補點越大，離散程度越大，即函數的執行時間波動越大。
有兩個參數可以改變 function_profile 記錄的時間類型。這兩個節點在options 檔案夾裡，分别是 graph_time 和 sleep_time：
預設是打開的。
graph_time：表示所記錄的函數執行的時間，包含此函數内所有調用的子函數執行的時間，如果不使能，則隻包含本函數執行的時間；
sleep_time：表示所記錄的函數執行的時間，包含此函數在執行期間，被搶占或排程或任務切換所花掉的時間；
我們還可以看到，輸出資訊以函數執行的總時間從大到小的順序進行了sort，更友善我們分析問題。
另外，function_profile 可以和傳統 tracer 同時運作。傳統 tracer 的結果記錄在 ring buffer(trace/trace_pipe 節點)，function_profile 的結果記錄在 trace_stat/functionX 節點。
和 function tracer 不同的是，function_profile 會累積已經跟蹤過的函數(命中數，總時間等)；而 function tracer 隻記錄時間戳，如果同一個函數再次命中，則再記錄一次新的資訊(新的時間戳等)。是以 function tracer 可以跟蹤函數執行的先後順序，而 function_profile 可以統計函數執行的整體情況。
Max Stack Tracer
此功能可以檢視到核心最大的棧調用深度。通用如下的開關來使能此功能：
預設是關閉的。具體的執行流程如下：
trace_printk
核心頭檔案 include/linux/kernel.h 中描述了 ftrace 提供的工具函數的原型，這些函數包括 trace_printk、tracing_on/tracing_off 等。本節将通過示例子產品程式向讀者展示如何在代碼中使用這些工具函數。
ftrace 提供了一個用于向 ftrace 跟蹤緩沖區輸出跟蹤資訊的工具函數，叫做 trace_printk()，它的使用方式與 printk() 類似。可以通過 trace 檔案讀取該函數的輸出。從頭檔案 include/linux/kernel.h 中可以看到，在激活配置 CONFIG_TRACING 後，trace_printk()定義為宏：
#define trace_printk(fmt, ...) \
do { \
char _______STR[] = __stringify((__VA_ARGS__)); \
if (sizeof(_______STR) > 3) \
do_trace_printk(fmt, ##__VA_ARGS__); \
else
trace_puts(fmt); \
} while (0)
下面通過一個示例子產品 ftrace_demo 來示範如何使用 trace_printk() 向跟蹤緩沖區輸出資訊，以及如何檢視這些資訊。這裡的示例子產品程式中僅提供了初始化和退出函數，這樣讀者不會因為需要為子產品建立必要的通路接口比如裝置檔案而分散注意力。注意，編譯子產品時要加入 -pg 選項。
清單 1. 示例子產品 ftrace_demo：
/* ftrace_demo.c */
#include <linux/init.h>
#include <linux/module.h>
#include <linux/kernel.h>
MODULE_LICENSE("GPL");
static int ftrace_demo_init(void)
{
trace_printk("Can not see this in trace unless loaded for thesecond time\n");
return 0;
}
static void ftrace_demo_exit(void)
{
trace_printk("Module unloading\n");
}
module_init(ftrace_demo_init);
module_exit(ftrace_demo_exit);
示例子產品非常簡單，僅僅是在子產品初始化函數和退出函數中輸出資訊。接下來要對子產品的運作進行跟蹤。
清單 2. 對子產品 ftrace_demo 進行跟蹤
[[email protected] tracing]# pwd
/sys/kernel/debug/tracing
[[email protected] tracing]# echo 0 > tracing_enabled
[[email protected] tracing]# echo 1 > /proc/sys/kernel/ftrace_enabled
[[email protected] tracing]# echo function_graph > current_tracer
# insmod ftrace_demo.ko
[[email protected] tracing]# echo ':mod:ftrace_demo' > set_ftrace_filter
[[email protected] tracing]# cat set_ftrace_filter
ftrace_demo_init
ftrace_demo_exit
# rmmod ftrace_demo.ko
[[email protected] tracing]# echo 1 > tracing_enabled
# insmod ftrace_demo.ko
# rmmod ftrace_demo.ko
[[email protected] tracing]# cat trace
# tracer: function_graph
# #
CPU DURATION FUNCTION CALLS
# | | | | | | |
1) | /* Can not see this in trace unless loaded for
the second time */
0) | /* Module unloading */
在這個例子中，使用 mod 指令顯式指定跟蹤子產品 ftrace_demo 中的函數，這需要提前加載該子產品，否則在寫檔案 set_ftrace_filter 時會因為找不到該子產品報錯。
在 第 一 次 加 載 模 塊 時 ， 其 初 始 化 函 數 ftrace_demo_init 中 調 用trace_printk 列印的語句跟蹤不到，因為 tracing_enabled 還沒有打開。之後将其解除安裝，再激活跟蹤，最後重新進行子產品 ftrace_demo 的加載與解除安裝操作。最終可以從檔案 trace 中看到子產品在初始化和退出時調用 trace_printk() 輸出的資訊。
這裡僅僅是為了以簡單的子產品進行示範，故隻定義了子產品的 init/exit 函數，重複加載子產品也隻是為了擷取初始化函數輸出的跟蹤資訊。實踐中，可以在子產品的功能函數中加入對 trace_printk 的調用，這樣可以記錄子產品的運作情況，然後對其特定功能進行調試優化。還可以将對 trace_printk() 的調用通宏來控制編譯，這樣可以在調試時将其開啟，在最終釋出時将其關閉。
ftrace_dump_on_oops
Having Ftrace configured and enabling ftrace_dump_on_oops in the
kernel boot parameters, or by echoing a "1" into
/proc/sys/kernel/ftrace_dump_on_oops, will enable Ftrace to dump to the
console the entire trace buffer in ASCII format on oops or panic.
# echo 1 > /proc/sys/kernel/ftrace_dump_on_oops
ftrace_dump_on_oops 預設為0，即是關閉的。
ftrace event
Tracepoints (Documentation/trace/tracepoints.txt) 使用核心已有的event tracing 架構，而不用建立自定義的核心子產品來注冊 probe function。并不是所有的 Tracepoints 都可以用 event tracing 系統來 trace 得到。核心開發者必須提供定義 tracing 資訊儲存到 tracing buffer 的方式以及 tracing資訊的列印方式的代碼片段。
可以通過/d/tracing/available_events 節點來檢視支援的 event，每個event 的顯示格式為 GRP:EVENT，GRP 為 event 所在的子系統，EVENT 則是 event名。在 linux-3.4 上，支援的 events 有 340 個（通過 busybox wc -l/d/tracing/available_events 來檢視）
- 檢視屬于 ext4 組的所有 event
# cat /d/tracing/available_events | grep ext4
cat /d/tracing/available_events | grep ext4
ext4:ext4_free_inode
ext4:ext4_request_inode
ext4:ext4_allocate_inode
ext4:ext4_evict_inode
ext4:ext4_drop_inode
ext4:ext4_mark_inode_dirty
ext4:ext4_begin_ordered_truncate
ext4:ext4_write_begin
ext4:ext4_da_write_begin
……
/d/tracing/events/的目錄結構如下：
/d/tracing/events
|
|__enable
|__header_event
|__header_page
|__GRP
|
|__enable
|__filter
|__EVENT
|
|__enable
|__filter
|__format
-
可以通過’set_event’節點或’enable’切換鍵來啟用 event
(1) 啟用指定 event
echo [GRP:]EVENT > /d/tracing/set_event
echo [GRP2:]EVENT2 >> /d/tracing/set_event (追加)
[注意: ‘>>’ 是必要的，否則先會關閉所有 event 再作設定。]
或
echo 1 > /d/tracing/events/GRP/EVENT/enable
echo 1 > /d/tracing/events/GRP2/EVENT2/enable
(2) 啟用某個子系統
echo 1 > /d/tracing/events/GRP/enable
或
echo GRP:* > /d/tracing/set_event
(3) 啟用所有 events
echo 1 > /d/tracing/events/enable
或
echo : > /d/tracing/set_event
(4) 關閉 event
echo 0 到 enable 切換鍵
或
使用"!"來取消對 set_event 節點的輸入
/d/tracing/events/GRP/enable 和/d/tracing/events/enable，隻能輸入 0和 1，有以下幾個輸出值：
0 - 此節點影響的所有 event 都被關閉
1 - 此節點影響的所有 event 都被啟用
X - 部分 event 被啟用
? - 此節點不影響任何 event
- Event formats
每個 trace event 都有一個與之關聯的’format’節點，它包含了一個被記錄event 的每個域的描述。這資訊可用于識别二進制的 trace 流，可以從這裡找到在 event filter 中可用到的域的名稱。
它還顯示了的 event 被列印成文本時使用的格式字元串，在 profiling 時和event 名及 ID 一起列印。
每個 event 都定義了與之相關的以’common_'為字首的域。其它域在相應的event 頭檔案中使用 TRACE_EVENT 宏定義。
每個域的格式：
例子：
#cat /d/tracing/events/mmc/mmc_blk_erase_start/format
name: mmc_blk_erase_start
ID: 307
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:int common_padding; offset:8; size:4; signed:1;
field:unsigned int cmd; offset:12; size:4; signed:0;
field:unsigned int addr; offset:16; size:4; signed:0;
field:unsigned int size; offset:20; size:4; signed:0;
- Event filtering
有時候 trace 列印過多，有很多資訊是不想要的，我們可以設定 filter 表達式來過濾出需要的資訊，它傳回的是一個 boolean 值。在 event 被記錄到 tracebuffer 的同時，檢測相應的 field 值來是判斷否滿足 filter 表達式，隻有比對的 event 才會輸出，不比對的被丢棄。預設沒有設定 filter 表達式，它不會過濾任何東西。
filter 表達式的文法：
可以使用’&&’ 和’||'來連接配接多個語句
每個語句是一個簡單的比較表達式：
field-name relational-operator value
field-name 需要使用 event format 裡面的各個 field 名。
relational-operators，目前分為兩種類型：
數值可使用:
字元串可使用:
清除 event 的 filter
echo 0 > /d/tracing/events/GRP/EVENT/filter
清除整個子系統的 filter
echo 0 > /d/tracing/events/GRP/filter
有時候我們隻需關注某些參數為特定值時的情況，比如要 trace 對某個檔案的通路，或者傳入參數高于某個值時的調用情況等等。目前，對于字元串，隻支援完全比對。這個有待改進，若能使用通配符來比對，可以大大增加使用 trace的靈活性。
比如，要 trace mmc 開始發 trim/discard 指令時，扇區數少于 2048 的情況：
#cd /d/tracing/events/mmc/mmc_blk_erase_start
#echo 'size < 2048' > filter
若使用了 format 裡面沒有的名字，設定将不會成功。
#cd /d/tracing/events/mmc/mmc_blk_erase_start
#echo 'count < 2048' > filter
#cat filter
count < 2048
^
parse_error: Field not found
另外，還可以對整個子系統設定 filter 表達式，對于表達式中有非 common域的情況，隻有 event format 中包含這些域，才會進行 filter 表達式設定。
trace event 的使用方法并不複雜，但它底下包含了多個子系統，總 event數有幾百個，我們需要知道各個 event 的作用和代碼上下文，配合 fileter 的使用，才能靈活的用作性能分析和調試。
#ls /d/tracing/events
arm-ipi
asoc
binder
block
budget_cooling
compaction
cpu_autohotplug
cpufreq_interactive
enable
ext4
ftrace
gpio
header_event
header_page
irq
jbd2
kmem
mmc
module
napi
net
oom
power
printk
random
rcu
regmap
regulator
rpm
sched
scsi
signal
skb
smp
sock
sync
task
thermal
timer
udp
vmscan
workqueue
writeback
kprobe_events/kprobe_profile
使用核心的 kprobe 功能可以動态添加 event，隻需要按規定格式往/sys/kernel/debug/tracing/kprobe_events 寫入一段字元串，即可完成事件的添加。但前提是需要打開 kprobes 選項，才能使用此功能。配置選項如下：
These events are similar to tracepoint based events. Instead of
Tracepoint,
this is based on kprobes (kprobe and kretprobe). So it can probe wherever
kprobes can probe (this means, all functions body except for __kprobes
functions). Unlike the Tracepoint based event, this can be added and
removed
dynamically, on the fly.
To enable this feature, build your kernel with CONFIG_KPROBE_EVENT=y.
Similar to the events tracer, this doesn't need to be activated via
current_tracer. Instead of that, add probe points via
/sys/kernel/debug/tracing/kprobe_events, and enable it via
/sys/kernel/debug/tracing/events/kprobes/<EVENT>/enabled.
動态添加 event 的格式如下（linux-4.9/Documentation/trace/kprobetrace.txt）
p[:[GRP/]EVENT] [MOD:]SYM[+offs]|MEMADDR [FETCHARGS] : Set a probe
r[:[GRP/]EVENT] [MOD:]SYM[+0] [FETCHARGS] : Set a return probe
-:[GRP/]EVENT : Clear a probe
GRP : Group name. If omitted, use "kprobes" for it.
EVENT : Event name. If omitted, the event name is generated
based on SYM+offs or MEMADDR.
MOD : Module name which has given SYM.
SYM[+offs] : Symbol+offset where the probe is inserted.
MEMADDR : Address where the probe is inserted.
FETCHARGS : Arguments. Each probe can have up to 128 args.
%REG : Fetch register REG
@ADDR : Fetch memory at ADDR (ADDR should be in kernel)
@SYM[+|-offs] : Fetch memory at SYM +|- offs (SYM should be a data
symbol)
$stackN : Fetch Nth entry of stack (N >= 0)
$stack : Fetch stack address.
$retval : Fetch return value.(*)
+|-offs(FETCHARG) : Fetch memory at FETCHARG +|- offs address.(**)
NAME=FETCHARG : Set NAME as the argument name of FETCHARG.
FETCHARG:TYPE : Set TYPE as the type of FETCHARG. Currently, basic types
(u8/u16/u32/u64/s8/s16/s32/s64), "string" and bitfield
are supported.
(*) only for return probe.
(**) this is useful for fetching a field of data structures.
這個格式的說明太含蓄了，結合linux-4.9/Documentation/trace/kprobetrace.txt 中的一個動态添加 event 的示例來說明
echo 'p:myprobe do_sys_open dfd=%ax filename=%dx flags=%cx mode=+4($stack)' >
/sys/kernel/debug/tracing/kprobe_events
說明文檔對此示例的說明：
This sets a kprobe on the top of do_sys_open() function with recording
1st to 4th arguments as "myprobe" event. Note, which register/stack entry
is assigned to each function argument depends on arch-specific ABI.
在 do_sys_open()函數首部設定一個 kprobe，插入一個“myprobe”事件來記錄第 1~4 個參數。注意，函數的各個參數相應的寄存器或棧 entry 按照各個架
構的 ABI 來指定。
現在我們把這個傳入 kprobe_events 節點的字元串分解來看：
p:myprobe對應于 p[:[GRP/]EVENT]，這裡沒有指定組名（GRP），預設使用 kprobes 作為組名，也就是等價于：
p:kprobes/myprobe實際上事件名（EVENT）也可以不指定，即直接用一個 p 就行，EVENT 将會按照（SYM+offs 或者 MEMADDR）來命名。
可以設定“p、r”兩種類型的事件，“p”事件是放在函數的首部或一般位置，“r”事件放在函數傳回處。
do_sys_open對應于[MOD:]SYM[+offs]|MEMADDR，這裡隻指定了要跟蹤的符号，對于“p”類型事件，表示在函數入口處添加。
MOD 指定了目标 symbol 所在子產品，SYM+offs 和 MEMADDR 都可以指定 event添加的位置，這裡的 SYM 也可以當作是一個記憶體位址，offs 是相對于這個 SYM的位址偏移。
dfd=%ax filename=%dx flags=%cx mode=+4($stack)
對應于 FETCHARGS，說明文檔上的說明要用正規表達式的方式來看，并不直覺。重新解析一下 FETCHARGS 的格式：
[NAME=]%REG|@ADDR|@SYM[+|-offs]| s t a c k N ∣ stackN| stackN∣stack|$retval[:TYPE] …
或
[NAME=]+|-offs(%REG|@ADDR|@SYM[+|-offs]| s t a c k N ∣ stackN| stackN∣stack|$retval）[:TYPE] …
%REG : 取寄存器 REG 中的值（在 arm 架構中，函數的第 1~4 個參數放在寄存器 r0~r3 中，第四個之後的參數放在棧中）；
@ADDR : 取記憶體的 ADDR 位址中的值（ADDR 必須是 kernel 位址）；
@SYM[+|-offs] : 在 SYM +|- offs 位置的記憶體中取資料 (SYM 必須是一個data symbol，隻有這樣 SYM 才能轉換成記憶體位址)；
$stackN : 取棧中第 Nth 個入口中的值 (N >= 0)；
$stack : 取棧位址；
$retval : 取函數傳回值，隻能用于“r”類型事件；
+|-offs(FETCHARG) : 從 FETCHARG +|- offs 位置取資料，可用于取資料結構中的某個域的值。可以嵌套，如+0(+0($stack))。+0 等價于@；
dfd=%ax 對應于 NAME=%REG，表示在 event 相應的結構體中增加 dfd 字段，取值為寄存器 ax 中的值；
+4($stack)表示從(棧位址 + 4)位置的記憶體中取資料；
取值參數可劃分為兩類，一是取相應的值：%REG、 s t a c k 、 stack、 stack、retval，二是在指定的位置中取資料：@ADDR、@SYM[+|-offs]、$stackN、+|-offs(FETCHARG)。要注意此間的差別，如"string"類型必須要使用後一類。
示例中沒有使用 TYPE，目前支援的 TYPE 有，basic types(u8/u16/u32/u64/s8/s16/s32/s64)、“string” 和 bitfield。從後面的實驗來看，沒有指定 TYPE，則預設使用 u32 類型。
basic types:
從字面就可以看出是什麼意思了，需要留意的是’s’是用 10 進制列印，'u’是用 16 進制列印。
“string”：從指定的位置開始往後查找到’\0’為止，若超過 1 個 page（pageout）還沒找到’\0’，那麼直接存儲 NULL。
bitfield：有三個參數 bit-width、offset 和 container-size (usually 32).相應文法：
b<bit-width>@<bit-offset>/<container-size>
直接運作此示例，并不能添加成功，檢視 dmesg，發現是指定的第 0 個參數就有誤（為了确認-22 的錯誤是不是添加 event 時出現的，又重新添加了一次）
# dmesg | busybox tail -10
dmesg | busybox tail -10
<6>[ 8405.662181] healthd: battery l=95 v=4106 t=30.0 h=2 st=2 c=317 chg=u
<6>[ 8465.662195] healthd: battery l=95 v=4108 t=30.0 h=2 st=2 c=319 chg=u
<6>[ 8525.662172] healthd: battery l=95 v=4109 t=30.0 h=2 st=2 c=319 chg=u
<6>[ 8585.662181] healthd: battery l=95 v=4110 t=30.0 h=2 st=2 c=319 chg=u
<6>[ 8645.662190] healthd: battery l=95 v=4111 t=30.0 h=2 st=2 c=318 chg=u
<6>[ 8705.662187] healthd: battery l=95 v=4111 t=30.0 h=2 st=2 c=317 chg=u
<6>[ 8765.662093] healthd: battery l=95 v=4112 t=30.0 h=2 st=2 c=319 chg=u
<6>[ 8793.847914] Parse error at argument[0]. (-22)
<6>[ 8825.661289] healthd: battery l=95 v=4112 t=30.0 h=2 st=2 c=320 chg=u
<6>[ 8827.871598] Parse error at argument[0]. (-22)
但這個“argument[0]”指的是哪個？減少一些參數，保留到“dfd=%ax”，如下，問題依舊。(/d 是/sys/kernel/debug 目錄的軟連結)
echo 'p:myprobe do_sys_open dfd=%ax' > /d/tracing/kprobe_events
把“dfd=%ax”也去掉，沒有傳回錯誤。
echo 'p:myprobe do_sys_open' > /d/tracing/kprobe_events
檢視/d/tracing/events 目錄，此時會出現一個名為 kprobes 的目錄，
# ls -l /d/tracing/events
……
drwxr-xr-x root root 1970-01-01 08:00 kmem
drwxr-xr-x root root 1970-01-26 05:24 kprobes
drwxr-xr-x root root 1970-01-01 08:00 mmc
……
目錄中包含有新添加的 event，“myprobe”，至此可以确認 event 添加成功了。
# ls -l /d/tracing/events/kprobes
-rw-r--r-- root root 0 1970-01-26 05:24 enable
-rw-r--r-- root root 0 1970-01-26 05:24 filter
drwxr-xr-x root root 1970-01-26 05:24 myprobe
c如一般的 static event 一樣，myprobe 目錄下有 enable、filter、format、id 四個節點，使用方法也和 static event 相同。
# ls -l /d/tracing/events/kprobes
-rw-r--r-- root root 0 1970-01-26 05:24 enable
-rw-r--r-- root root 0 1970-01-26 05:24 filter
drwxr-xr-x root root 1970-01-26 05:24 myprobe
看看 myprobe 的列印格式，
#cat /d/tracing/events/kprobes/myprobe/format
name: myprobe
ID: 381
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:int common_padding; offset:8; size:4; signed:1;
field:unsigned long __probe_ip; offset:12; size:4; signed:0;
print fmt: "(%lx)", REC->__probe_ip
事件添加成功了，但是沒有其它資訊，我們跟蹤 do_sys_open，還希望知道檔案名、标志、打開模式等資訊，再看回示例，示例的格式是我們想要的，但是為什麼添加不成功呢？
按照示例的說明，函數參數的位置需要根據架構相應的 ABI 來指定。
在 arm 架構中，函數的第 1~4 個參數放在寄存器 r0~r3 中，第四個之後的參數放在棧中。
是以作下調整（注意"r"需要小寫），
echo 'p:myprobe do_sys_open dfd=%r0 filename=%r1 flags=%r2 mode=%r3' >
/d/tracing/kprobe_events
event 添加成功，format 發生了以下變化，event 相應的結構體增加了 dfd、filename、flags、mode 等字段，類型都是預設的 32 位無符号數（u32），printffmt 也把這些字段列印出來了。
#cat /d/tracing/events/kprobes/myprobe/format
name: myprobe
ID: 382
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:int common_padding; offset:8; size:4; signed:1;
field:unsigned long __probe_ip; offset:12; size:4; signed:0;
field:u32 dfd; offset:16; size:4; signed:0;
field:u32 filename; offset:20; size:4; signed:0;
field:u32 flags; offset:24; size:4; signed:0;
field:u32 mode; offset:28; size:4; signed:0;
print fmt: "(%lx) dfd=%lx filename=%lx flags=%lx mode=%lx", REC->__probe_ip, REC->dfd,
REC->filename, REC->flags, REC->mode
這樣一個 event 就算是添加完成了，但還是有缺陷，這裡的 filename 列印的其實是檔案名字元串的位址，而我們想知道的是這個字元串。說明文檔裡有指明可以支援"string"格式，修改傳入的字元串：
echo 'p:myprobe do_sys_open dfd=%r0 filename=%r1:string flags=%r2 mode=%r3' >
/d/tracing/kprobe_events
但 event 添加失敗，
<4>[19942.014018] CPU3: Booted secondary processor
<4>[19942.525642] CPU4: Booted secondary processor
<6>[19942.526251] CPU Budget:update CPU 4 cpufreq max to 1608000 min to 600000
<5>[19946.000928] CPU3: shutdown
<5>[19946.500756] CPU2: shutdown
<5>[19947.000720] CPU1: shutdown
<5>[19947.500839] CPU4: shutdown
<6>[19947.737994] string type has no corresponding fetch method.
<6>[19947.738030] Parse error at argument[1]. (-22)
<6>[19948.945616] healthd: battery l=99 v=4205 t=30.0 h=2 st=2 c=314 chg=u
在一個相關問題的回複中找到了答案 (Re: kprobe string, https://www.mail-archive.com/[email protected]/msg01633.html)
主要是"string"格式不能跟在直接取值的參數之後，作如下修改，則可添加
成功：
echo 'p:myprobe do_sys_open dfd=%r0 filename=+0(%r1):string flags=%r2 mode=%r3' >
/d/tracing/kprobe_events
時間對應的 format 也發生了相應的變化：
#cat /d/tracing/events/kprobes/myprobe/format
name: myprobe
ID: 384
format:
field:unsigned short common_type; offset:0; size:2; signed:0;
field:unsigned char common_flags; offset:2; size:1; signed:0;
field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
field:int common_pid; offset:4; size:4; signed:1;
field:int common_padding; offset:8; size:4; signed:1;
field:unsigned long __probe_ip; offset:12; size:4; signed:0;
field:u32 dfd; offset:16; size:4; signed:0;
field:__data_loc char[] filename; offset:20; size:4; signed:1;
field:u32 flags; offset:24; size:4; signed:0;
field:u32 mode; offset:28; size:4; signed:0;
print fmt: "(%lx) dfd=%lx filename=\"%s\" flags=%lx mode=%lx", REC->__probe_ip, REC->dfd,
__get_str(filename), REC->flags, REC->mode
event 添加成功後，還需要開始進行 trace
# echo 1 > /d/tracing/events/kprobes/myprobe/enable
# echo 1 > /d/tracing/tracing_on
得到的結果如下：
# cat trace
cat trace
# tracer: nop
# #
entries-in-buffer/entries-written: 82/82 #P:3
# #
_-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
sh-4818 [000] d... 76398.194486: myprobe: (do_sys_open+0x0/0x1d4) dfd=ffffff9c
filename="/acct/uid/0/tasks" flags=20042 mode=1b6
<...>-1540 [000] d... 76399.768099: myprobe: (do_sys_open+0x0/0x1d4) dfd=ffffff9c
filename="/sys/class/power_supply/battery/present" flags=20000 mode=0
<...>-1540 [000] d... 76399.768392: myprobe: (do_sys_open+0x0/0x1d4) dfd=ffffff9c
filename="/sys/class/power_supply/battery/capacity" flags=20000 mode=0
<...>-1540 [000] d... 76399.768566: myprobe: (do_sys_open+0x0/0x1d4) dfd=ffffff9c
filename="/sys/class/power_supply/battery/voltage_now" flags=20000 mode=0
動态添加 event 功能，在我們公司的方案中預設是關閉的(即沒有使能kprobes 選項)。要使用此功能可能要重新配置、編譯并燒寫固件。
此外，在動态添加 event 功能中，并沒有看到“能寫”或“能添加自定義代碼”的功能。
我們更多的時候，希望能通過在指點的函數内動态添加探測點來記錄我們需要的資訊，如統計寫檔案的資料量等。這可以通過另一個工具 kprobes 來完成，而 ftrace 隻是利用了 kprobes 的一小部分功能。