ftrace - 函式追蹤器¶
版權所有 2008 Red Hat Inc.
- 作者:
Steven Rostedt <srostedt@redhat.com>
- 許可:
GNU 自由文件許可證，版本 1.2 (雙重許可在 GPL v2 下)
- 原始審查者:
Elias Oltmanns, Randy Dunlap, Andrew Morton, John Kacur, 和 David Teigland。
為以下版本編寫: 2.6.28-rc2
為以下版本更新: 3.10
為以下版本更新: 4.13 - 版權所有 2017 VMware Inc. Steven Rostedt
轉換為 rst 格式 - Changbin Du <changbin.du@intel.com>
簡介¶
Ftrace 是一個內部追蹤器，旨在幫助系統開發人員和設計人員找到核心內部發生的情況。它可以用於除錯或分析發生在使用者空間之外的延遲和效能問題。
雖然 ftrace 通常被認為是函式追蹤器，但它實際上是一個由幾個不同的追蹤實用程式組成的框架。 有延遲追蹤來檢查中斷停用和啟用之間發生的情況，以及搶佔和從任務被喚醒到任務實際被排程進來的時間。
ftrace 最常見的用途之一是事件追蹤。 在核心中存在數百個靜態事件點，可以透過 tracefs 檔案系統啟用這些事件點，以檢視核心某些部分中發生的情況。
有關更多資訊，請參閱 事件追蹤。
實現細節¶
有關 arch 移植者等的詳細資訊，請參閱 函式追蹤器設計。
檔案系統¶
Ftrace 使用 tracefs 檔案系統來儲存控制檔案以及顯示輸出的檔案。
當 tracefs 配置到核心中時 (選擇任何 ftrace 選項都會這樣做)，將建立目錄 /sys/kernel/tracing。 要掛載此目錄，您可以將其新增到您的 /etc/fstab 檔案中
tracefs /sys/kernel/tracing tracefs defaults 0 0
或者您可以在執行時使用以下命令掛載它
mount -t tracefs nodev /sys/kernel/tracing
為了更快地訪問該目錄，您可能需要建立一個指向它的軟連結
ln -s /sys/kernel/tracing /tracing
注意
在 4.1 之前，所有 ftrace 追蹤控制檔案都位於 debugfs 檔案系統中，該檔案系統通常位於 /sys/kernel/debug/tracing。 為了向後相容，當掛載 debugfs 檔案系統時，tracefs 檔案系統將自動掛載到
/sys/kernel/debug/tracing
位於 tracefs 檔案系統中的所有檔案也將位於該 debugfs 檔案系統目錄中。
注意
任何選定的 ftrace 選項也將建立 tracefs 檔案系統。 文件的其餘部分將假設您位於 ftrace 目錄中 (cd /sys/kernel/tracing)，並且只會專注於該目錄中的檔案，而不會因擴充套件的 “/sys/kernel/tracing” 路徑名而分散內容。
就是這樣! (假設您已將 ftrace 配置到您的核心中)
掛載 tracefs 後，您將可以訪問 ftrace 的控制和輸出檔案。 以下是一些關鍵檔案的列表
注意: 所有時間值均以微秒為單位。
current_tracer
用於設定或顯示已配置的當前追蹤器。 更改當前追蹤器會清除環形緩衝區內容以及 “snapshot” 緩衝區。
available_tracers
儲存已編譯到核心中的不同型別的追蹤器。 可以透過將其名稱回顯到 current_tracer 中來配置此處列出的追蹤器。
tracing_on
設定或顯示是否啟用寫入追蹤環形緩衝區。 將 0 回顯到此檔案中以停用追蹤器，或將 1 回顯到此檔案中以啟用追蹤器。 注意，這隻會停用寫入環形緩衝區，追蹤開銷可能仍在發生。
核心函式 tracing_off() 可以在核心中使用以停用寫入環形緩衝區，這將此檔案設定為 “0”。 使用者空間可以透過將 “1” 回顯到該檔案中來重新啟用追蹤。
注意，函式和事件觸發器 “traceoff” 也會將此檔案設定為零並停止追蹤。 使用者空間也可以使用此檔案重新啟用它。
trace
此檔案以人類可讀的格式儲存追蹤的輸出 (如下所述)。 使用 O_TRUNC 標誌開啟此檔案進行寫入會清除環形緩衝區內容。 注意，此檔案不是一個消費者。 如果追蹤已關閉 (沒有追蹤器執行，或 tracing_on 為零)，則每次讀取時它都會產生相同的輸出。 當追蹤開啟時，它可能會產生不一致的結果，因為它試圖讀取整個緩衝區而不消耗它。
trace_pipe
輸出與 “trace” 檔案相同，但此檔案旨在用於即時追蹤。 從此檔案的讀取將阻塞，直到檢索到新資料。 與 “trace” 檔案不同，此檔案是一個消費者。 這意味著從此檔案的讀取會導致順序讀取以顯示更多當前資料。 從此檔案讀取資料後，它將被消耗，並且不會透過順序讀取再次讀取。 “trace” 檔案是靜態的，如果追蹤器沒有新增更多資料，則每次讀取時它都會顯示相同的資訊。
trace_options
此檔案允許使用者控制在上述輸出檔案之一中顯示的資料量。 還存在一些選項可以修改追蹤器或事件的工作方式 (堆疊追蹤、時間戳等)。
options
這是一個目錄，其中包含每個可用追蹤選項的檔案 (也在 trace_options 中)。 也可以透過將 “1” 或 “0” 分別寫入具有選項名稱的相應檔案中來設定或清除選項。
tracing_max_latency
一些追蹤器會記錄最大延遲。 例如，中斷停用的最大時間。 最大時間儲存在此檔案中。 也會儲存最大追蹤，並透過 “trace” 顯示。 僅當延遲大於此檔案中的值 (以微秒為單位) 時，才會記錄新的最大追蹤。
透過將時間回顯到此檔案中，除非延遲大於此檔案中的時間，否則不會記錄任何延遲。
tracing_thresh
每當延遲大於此檔案中的數字時，某些延遲追蹤器將記錄追蹤。 僅當檔案包含大於 0 的數字時才處於活動狀態。 (以微秒為單位)
buffer_percent
這是環形緩衝區需要在喚醒等待者之前填充的水印。 也就是說，如果應用程式在每個 CPU 的 trace_pipe_raw 檔案之一上呼叫阻塞讀取 syscall，它將阻塞，直到緩衝區百分比指定的給定資料量在環形緩衝區中，然後它才會喚醒讀取器。 這也控制了 splice 系統呼叫在此檔案上的阻塞方式
0 - means to wake up as soon as there is any data in the ring buffer. 50 - means to wake up when roughly half of the ring buffer sub-buffers are full. 100 - means to block until the ring buffer is totally full and is about to start overwriting the older data.buffer_size_kb
設定或顯示每個 CPU 緩衝區儲存的千位元組數。 預設情況下，每個 CPU 的追蹤緩衝區大小相同。 顯示的數字是 CPU 緩衝區的大小，而不是所有緩衝區的總大小。 追蹤緩衝區以頁面 (核心用於分配的記憶體塊，通常為 4 KB 大小) 分配。 可能會分配一些額外的頁面以容納緩衝區管理元資料。 如果分配的最後一個頁面有空間容納比請求的更多位元組，則將使用頁面的其餘部分，從而使實際分配大於請求或顯示的大小。 (注意，由於緩衝區管理元資料，大小可能不是頁面大小的倍數。)
各個 CPU 的緩衝區大小可能會有所不同 (請參閱下面的 “per_cpu/cpu0/buffer_size_kb”)，如果它們確實不同，則此檔案將顯示 “X”。
buffer_total_size_kb
顯示所有追蹤緩衝區的總組合大小。
buffer_subbuf_size_kb
設定或顯示子緩衝區大小。 環形緩衝區被分成幾個相同大小的 “子緩衝區”。 事件的大小不能大於子緩衝區的大小。 通常，子緩衝區的大小是架構的頁面大小 (在 x86 上為 4K)。 子緩衝區還在開始時包含元資料，這也限制了事件的大小。 這意味著當子緩衝區為頁面大小時，沒有事件可以大於頁面大小減去子緩衝區元資料。
注意，buffer_subbuf_size_kb 是使用者指定子緩衝區最小大小的一種方式。 由於實現細節，核心可能會使其更大，或者如果核心無法處理該請求，則只需使操作失敗。
更改子緩衝區大小允許事件大於頁面大小。
注意: 更改子緩衝區大小時，將停止追蹤，並且環形緩衝區和快照緩衝區中的任何資料都將被丟棄。
free_buffer
如果一個程序正在執行追蹤，並且當程序完成時，即使它被訊號殺死，環形緩衝區也應該縮小 “釋放”，則可以使用此檔案來實現該目的。 關閉此檔案時，環形緩衝區將調整為其最小大小。 讓一個正在追蹤的程序也開啟此檔案，當程序退出時，此檔案的檔案描述符將被關閉，這樣做，環形緩衝區將被 “釋放”。
如果設定了 disable_on_free 選項，它也可能會停止追蹤。
tracing_cpumask
這是一個掩碼，允許使用者僅在指定的 CPU 上進行追蹤。 格式是一個表示 CPU 的十六進位制字串。
set_ftrace_filter
當配置了動態 ftrace 時 (請參閱下面的 “動態 ftrace” 部分)，程式碼會被動態修改 (程式碼文字重寫) 以停用函式分析器 (mcount) 的呼叫。 這使得可以配置追蹤，而幾乎沒有效能開銷。 這也具有啟用或停用要追蹤的特定函式的副作用。 將函式名稱回顯到此檔案中會將追蹤限制為僅這些函式。 這會影響追蹤器 “function” 和 “function_graph”，因此也會影響函式分析 (請參閱 “function_profile_enabled”)。
“available_filter_functions” 中列出的函式是可以寫入此檔案的函式。
此介面還允許使用命令。 有關更多詳細資訊，請參閱 “過濾器命令” 部分。
為了加快速度，由於處理字串可能非常昂貴，並且需要檢查所有已註冊到追蹤的函式，因此可以將索引寫入此檔案中。 寫入的數字 (以 “1” 開頭) 將改為選擇 “available_filter_functions” 檔案中相同行位置的相應值。
set_ftrace_notrace
這具有與 set_ftrace_filter 相反的效果。 此處新增的任何函式都不會被追蹤。 如果一個函式同時存在於 set_ftrace_filter 和 set_ftrace_notrace 中，則該函式將 _不_ 被追蹤。
set_ftrace_pid
使函式追蹤器僅追蹤在此檔案中列出的 PID 的執行緒。
如果設定了 “function-fork” 選項，則當 PID 在此檔案中的任務 fork 時，子任務的 PID 將自動新增到此檔案中，並且該子任務也將被函式追蹤器追蹤。 此選項還將導致退出任務的 PID 從檔案中刪除。
set_ftrace_notrace_pid
使函式追蹤器忽略在此檔案中列出的 PID 的執行緒。
如果設定了 “function-fork” 選項，則當 PID 在此檔案中的任務 fork 時，子任務的 PID 將自動新增到此檔案中，並且該子任務也不會被函式追蹤器追蹤。 此選項還將導致退出任務的 PID 從檔案中刪除。
如果一個 PID 同時存在於此檔案和 “set_ftrace_pid” 中，則此檔案優先，並且該執行緒不會被追蹤。
set_event_pid
使事件僅追蹤在此檔案中列出的 PID 的任務。 注意，sched_switch 和 sched_wake_up 也會追蹤此檔案中列出的事件。
要在 fork 時新增 PID 在此檔案中的任務的子任務的 PID，請啟用 “event-fork” 選項。 該選項還將導致當任務退出時，任務的 PID 從此檔案中刪除。
set_event_notrace_pid
使事件不追蹤在此檔案中列出的 PID 的任務。 注意，sched_switch 和 sched_wakeup 將追蹤未在此檔案中列出的執行緒，即使執行緒的 PID 在檔案中，如果 sched_switch 或 sched_wakeup 事件也追蹤應該被追蹤的執行緒。
要在 fork 時新增 PID 在此檔案中的任務的子任務的 PID，請啟用 “event-fork” 選項。 該選項還將導致當任務退出時，任務的 PID 從此檔案中刪除。
set_graph_function
在此檔案中列出的函式將導致函式圖追蹤器僅追蹤這些函式以及它們呼叫的函式。 (有關更多詳細資訊，請參閱 “動態 ftrace” 部分)。 注意，set_ftrace_filter 和 set_ftrace_notrace 仍然會影響正在追蹤的函式。
set_graph_notrace
與 set_graph_function 類似，但是當函式被命中時，它將停用函式圖追蹤，直到它退出該函式。 這使得可以忽略由特定函式呼叫的追蹤函式。
available_filter_functions
列出 ftrace 已處理並可以追蹤的函式。 這些是您可以傳遞給 “set_ftrace_filter”、“set_ftrace_notrace”、“set_graph_function” 或 “set_graph_notrace” 的函式名稱。 (有關更多詳細資訊，請參閱下面的 “動態 ftrace” 部分。)
available_filter_functions_addrs
與 available_filter_functions 類似，但顯示每個函式的地址。 顯示的地址是補丁站點地址，可能與 /proc/kallsyms 地址不同。
dyn_ftrace_total_info
此檔案用於除錯目的。 已轉換為 nop 並且可用於追蹤的函式數量。
enabled_functions
此檔案更多的是用於除錯 ftrace，但也可以用於檢視是否有任何函式附加了回撥。 不僅追蹤基礎設施使用 ftrace 函式追蹤實用程式，而且其他子系統也可能使用。 此檔案顯示所有附加了回撥的函式以及已附加的回撥數量。 注意，回撥也可能呼叫多個函式，這些函式不會在此計數中列出。
如果回撥註冊為由具有 “save regs” 屬性 (因此開銷更大) 的函式追蹤，則將在返回暫存器的函式的同一行上顯示 “R”。
如果回撥註冊為由具有 “ip modify” 屬性 (因此可以更改 regs->ip) 的函式追蹤，則將在可以被覆蓋的函式的同一行上顯示 “I”。
如果附加了非 ftrace 蹦床 (BPF)，則將顯示 “D”。 注意，也可以附加正常的 ftrace 蹦床，但是一次只能將一個 “direct” 蹦床附加到給定的函式。
某些架構無法呼叫直接蹦床，而是將 ftrace ops 函式位於函式入口點上方。 在這種情況下，將顯示 “O”。
如果一個函式過去曾透過 “ip modify” 或直接蹦床附加到它，則將顯示 “M”。 此標誌永遠不會清除。 它用於瞭解一個函式是否曾經被 ftrace 基礎設施修改過，並且可以用於除錯。
如果架構支援它，它還會顯示該函式正在直接呼叫哪個回撥。 如果計數大於 1，則很可能是 ftrace_ops_list_func()。
如果一個函式的回撥跳轉到一個特定於回撥而不是標準蹦床的蹦床，則將列印其地址以及蹦床呼叫的函式。
touched_functions
此檔案包含所有曾經透過 ftrace 基礎設施對其進行函式回撥的函式。 它具有與 enabled_functions 相同的格式，但顯示所有曾經被追蹤的函式。
要檢視任何曾經被 “ip modify” 或直接蹦床修改的函式，可以執行以下命令
grep ‘ M ‘ /sys/kernel/tracing/touched_functions
function_profile_enabled
設定後，它將啟用函式追蹤器或如果已配置，則啟用函式圖追蹤器的所有函式。 它將保留已呼叫函式數量的直方圖，並且如果已配置函式圖追蹤器，它還將跟蹤在這些函式中花費的時間。 直方圖內容可以在檔案中顯示
trace_stat/function<cpu> ( function0, function1, 等等).
trace_stat
一個包含不同追蹤統計資訊的目錄。
kprobe_events
啟用動態追蹤點。 請參閱 基於 Kprobe 的事件追蹤。
kprobe_profile
動態追蹤點統計資訊。 請參閱 基於 Kprobe 的事件追蹤。
max_graph_depth
與函式圖追蹤器一起使用。 這是它將追蹤到函式中的最大深度。 將此值設定為 1 將僅顯示從使用者空間呼叫的第一個核心函式。
printk_formats
這適用於讀取原始格式檔案的工具。 如果環形緩衝區中的事件引用一個字串，則僅將指向該字串的指標記錄到緩衝區中，而不記錄字串本身。 這會阻止工具知道該字串是什麼。 此檔案顯示字串和字串的地址，允許工具將指標對映到字串是什麼。
saved_cmdlines
除非事件專門儲存任務 comm，否則僅任務的 pid 記錄在追蹤事件中。 Ftrace 製作 pid 到 comms 的對映快取，以嘗試顯示事件的 comms。 如果未列出 comm 的 pid，則在輸出中顯示 “<...>”。
如果選項 “record-cmd” 設定為 “0”，則在記錄期間不會儲存任務的 comms。 預設情況下，它是啟用的。
saved_cmdlines_size
預設情況下，儲存 128 個 comms (請參閱上面的 “saved_cmdlines”)。 要增加或減少快取的 comms 數量，請將要快取的 comms 數量回顯到此檔案中。
saved_tgids
如果設定了選項 “record-tgid”，則在每次排程上下文切換時，任務的任務組 ID 都儲存在一個表中，該表將執行緒的 PID 對映到其 TGID。 預設情況下，停用 “record-tgid” 選項。
snapshot
顯示 “snapshot” 緩衝區，並允許使用者獲取當前正在執行的追蹤的快照。 有關更多詳細資訊，請參閱下面的 “快照” 部分。
stack_max_size
當堆疊追蹤器被啟用時，它將顯示它遇到的最大堆疊大小。 請參閱下面的 “堆疊追蹤” 部分。
stack_trace
當堆疊追蹤器被啟用時，它將顯示遇到的最大堆疊的堆疊回溯。 請參閱下面的 “堆疊追蹤” 部分。
stack_trace_filter
這類似於 “set_ftrace_filter”，但它限制了堆疊追蹤器將檢查的函式。
trace_clock
每當一個事件被記錄到環形緩衝區中時，都會新增一個 “時間戳”。 這個戳記來自指定時鐘。 預設情況下，ftrace 使用 “local” 時鐘。 這個時鐘非常快並且嚴格按 CPU 計算，但在某些系統上，它可能與其他 CPU 不單調。 換句話說，本地時鐘可能與其他 CPU 上的本地時鐘不同步。
用於追蹤的常用時鐘
# cat trace_clock [local] global counter x86-tsc用方括號括起來的時鐘是有效的時鐘。
- local
預設時鐘，但可能在 CPU 之間不同步
- global
這個時鐘與所有 CPU 同步，但可能比本地時鐘慢一點。
- counter
這根本不是一個時鐘，而是一個字面上的原子計數器。 它一個接一個地計數，但與所有 CPU 同步。 當您需要確切地知道事件在不同 CPU 上相對於彼此發生的順序時，這非常有用。
- uptime
這使用 jiffies 計數器，並且時間戳相對於自啟動以來的時間。
- perf
這使 ftrace 使用與 perf 相同的時鐘。 最終 perf 將能夠讀取 ftrace 緩衝區，這將有助於交錯資料。
- x86-tsc
架構可以定義自己的時鐘。 例如，x86 在此處使用其自己的 TSC 週期時鐘。
- ppc-tb
這使用 powerpc 時間基址暫存器值。 這在 CPU 之間同步，並且如果知道 tb_offset，也可以用於關聯管理程式/訪客之間的事件。
- mono
這使用快速單調時鐘 (CLOCK_MONOTONIC)，它是單調的並且受 NTP 速率調整的影響。
- mono_raw
這是原始單調時鐘 (CLOCK_MONOTONIC_RAW)，它是單調的，但不受任何速率調整的影響，並且以與硬體時鐘源相同的速率滴答。
- boot
這是啟動時鐘 (CLOCK_BOOTTIME)，它基於快速單調時鐘，但也考慮了暫停期間花費的時間。 由於時鐘訪問被設計用於暫停路徑中的追蹤，因此如果在暫停時間計算完成後，在快速單聲道時鐘更新之前訪問時鐘，則可能會出現一些副作用。 在這種情況下，時鐘更新的發生似乎比正常情況略早。 此外，在 32 位系統上，64 位啟動偏移量可能會看到部分更新。 這些影響很少見，並且後期處理應該能夠處理它們。 有關更多資訊，請參閱
ktime_get_boot_fast_ns()函式中的註釋。- tai
這是 tai 時鐘 (CLOCK_TAI)，它源自掛鐘時間。 但是，此時鐘不會遇到因 NTP 插入閏秒而導致的不連續性和向後跳轉。 由於時鐘訪問被設計用於追蹤，因此可能會出現副作用。 如果內部 TAI 偏移量已更新，例如，由設定系統時間或使用帶偏移量的 adjtimex() 引起，則時鐘訪問可能會產生錯誤的讀數。 這些影響很少見，並且後期處理應該能夠處理它們。 有關更多資訊，請參閱
ktime_get_tai_fast_ns()函式中的註釋。要設定時鐘，只需將時鐘名稱回顯到此檔案中
# echo global > trace_clock設定時鐘會清除環形緩衝區內容以及 “快照” 緩衝區。
trace_marker
這是一個非常有用的檔案，用於將使用者空間與核心中發生的事件同步。 將字串寫入此檔案將被寫入 ftrace 緩衝區。
在應用程式中開啟應用程式開始時的此檔案，然後只引用該檔案的檔案描述符非常有用
void trace_write(const char *fmt, ...) { va_list ap; char buf[256]; int n; if (trace_fd < 0) return; va_start(ap, fmt); n = vsnprintf(buf, 256, fmt, ap); va_end(ap); write(trace_fd, buf, n); }開始
trace_fd = open("trace_marker", O_WRONLY);trace_marker_raw
這類似於上面的 trace_marker，但旨在將二進位制資料寫入其中，其中可以使用一個工具從 trace_pipe_raw 中解析資料。
uprobe_events
在程式中新增動態追蹤點。 請參閱 Uprobe-tracer: 基於 Uprobe 的事件追蹤
uprobe_profile
Uprobe 統計資訊。 請參閱 uprobetrace.txt
instances
這是一種建立多個追蹤緩衝區的方法，其中不同的事件可以記錄在不同的緩衝區中。 請參閱下面的 “例項” 部分。
events
這是追蹤事件目錄。 它儲存已編譯到核心中的事件追蹤點 (也稱為靜態追蹤點)。 它顯示了存在的事件追蹤點以及它們如何按系統分組。 在各個級別都有 “enable” 檔案，當向其中寫入 “1” 時，可以啟用這些追蹤點。
有關更多資訊，請參閱 事件追蹤。
set_event
透過將事件回顯到此檔案中，將啟用該事件。
有關更多資訊，請參閱 事件追蹤。
available_events
可以在追蹤中啟用的事件列表。
有關更多資訊，請參閱 事件追蹤。
timestamp_mode
某些追蹤器可能會更改在將追蹤事件記錄到事件緩衝區時使用的時間戳模式。 具有不同模式的事件可以共存於一個緩衝區中，但記錄事件時生效的模式確定用於該事件的時間戳模式。 預設時間戳模式為 “delta”。
用於追蹤的常用時間戳模式
# cat timestamp_mode [delta] absolute
用方括號括起來的時間戳模式是有效的模式。
- delta: 預設時間戳模式 - 時間戳是針對每個緩衝區時間戳的增量。
每個緩衝區時間戳。
- absolute: 時間戳是一個完整的時間戳，而不是針對其他某個值的增量。
針對其他某個值。 因此，它佔用更多空間並且效率較低。
hwlat_detector
硬體延遲檢測器的目錄。 請參閱下面的“硬體延遲檢測器”部分。
per_cpu
這是一個包含每個 CPU 跟蹤資訊的目錄。
per_cpu/cpu0/buffer_size_kb
ftrace 緩衝區是按 CPU 定義的。 也就是說，每個 CPU 都有一個單獨的緩衝區，以允許原子地完成寫入，並且免受快取抖動的影響。 這些緩衝區可能具有不同的大小。 此檔案類似於 buffer_size_kb 檔案，但它僅顯示或設定特定 CPU（此處為 cpu0）的緩衝區大小。
per_cpu/cpu0/trace
這類似於“trace”檔案，但它只會顯示 CPU 特定的資料。 如果寫入，它只會清除特定的 CPU 緩衝區。
per_cpu/cpu0/trace_pipe
這類似於“trace_pipe”檔案，並且是一個消耗性讀取，但它只會顯示（並消耗）CPU 特定的資料。
per_cpu/cpu0/trace_pipe_raw
對於可以解析 ftrace 環形緩衝區二進位制格式的工具，可以使用 trace_pipe_raw 檔案直接從環形緩衝區提取資料。 透過使用 splice() 系統呼叫，緩衝區資料可以快速傳輸到檔案或網路，伺服器可以在其中收集資料。
與 trace_pipe 類似，這是一個消耗性讀取器，多次讀取總是會產生不同的資料。
per_cpu/cpu0/snapshot
這類似於主“snapshot”檔案，但只會對當前 CPU 進行快照（如果支援）。 它只顯示給定 CPU 的快照內容，如果寫入，只會清除此 CPU 緩衝區。
per_cpu/cpu0/snapshot_raw
類似於 trace_pipe_raw，但將從給定 CPU 的快照緩衝區讀取二進位制格式。
per_cpu/cpu0/stats
這顯示了關於環形緩衝區的某些統計資訊
- entries
緩衝區中仍然存在的事件數量。
- overrun
當緩衝區已滿時，由於覆蓋而丟失的事件數量。
- commit overrun
應該總是零。 如果在一個巢狀事件（環形緩衝區是可重入的）中發生了很多事件，以至於它填滿了緩衝區並開始丟棄事件，則會設定此項。
- bytes
實際讀取（未被覆蓋）的位元組數。
- oldest event ts
緩衝區中最舊的時間戳
- now ts
當前時間戳
- dropped events
由於覆蓋選項已關閉而丟失的事件。
- read events
已讀取的事件數量。
跟蹤器¶
這是當前可以配置的跟蹤器的列表。
“function”
函式呼叫跟蹤器，用於跟蹤所有核心函式。
“function_graph”
與函式跟蹤器類似，不同之處在於函式跟蹤器探測函式是在其入口處，而函式圖跟蹤器在函式的入口和出口處都進行跟蹤。 然後，它提供了繪製類似於 C 程式碼源的函式呼叫圖的能力。
請注意，函式圖計算函式內部開始和返回的時間，以及每個例項的時間。 如果有兩個例項執行函式圖跟蹤器並跟蹤相同的函式，則時間長度可能會略有偏差，因為每個例項單獨讀取時間戳，而不是同時讀取。
“blk”
塊跟蹤器。 blktrace 使用者應用程式使用的跟蹤器。
“hwlat”
硬體延遲跟蹤器用於檢測硬體是否產生任何延遲。 請參閱下面的“硬體延遲檢測器”部分。
“irqsoff”
跟蹤停用中斷的區域，並儲存具有最長最大延遲的跟蹤。 請參閱 tracing_max_latency。 當記錄一個新的最大值時，它會替換舊的跟蹤。 最好使用啟用延遲格式選項來檢視此跟蹤，當選擇跟蹤器時會自動啟用此選項。
“preemptoff”
與 irqsoff 類似，但跟蹤和記錄停用搶佔的時間量。
“preemptirqsoff”
與 irqsoff 和 preemptoff 類似，但跟蹤和記錄停用 irq 和/或搶佔的最長時間。
“wakeup”
跟蹤並記錄最高優先順序任務在被喚醒後被排程所需的最大延遲。 以普通開發人員期望的方式跟蹤所有任務。
“wakeup_rt”
跟蹤並記錄僅 RT 任務（如當前的“wakeup”所做的那樣）被喚醒所需的最大延遲。 這對於那些對 RT 任務的喚醒時間感興趣的人很有用。
“wakeup_dl”
跟蹤並記錄 SCHED_DEADLINE 任務被喚醒所需的最大延遲（如“wakeup”和“wakeup_rt”所做的那樣）。
“mmiotrace”
一個特殊的跟蹤器，用於跟蹤二進位制模組。 它將跟蹤模組對硬體進行的所有呼叫。 以及它寫入和讀取 I/O 的所有內容。
“branch”
當跟蹤核心中的 likely/unlikely 呼叫時，可以配置此跟蹤器。 它將跟蹤何時命中 likely 和 unlikely 分支，以及它對其正確預測的正確性。
“nop”
這是“不跟蹤任何內容”的跟蹤器。 要從跟蹤中刪除所有跟蹤器，只需將“nop”回顯到 current_tracer 中。
錯誤條件¶
對於大多數 ftrace 命令，故障模式很明顯，並使用標準返回碼進行通訊。
對於其他更復雜的命令，可以透過 tracing/error_log 檔案獲得擴充套件的錯誤資訊。 對於支援它的命令，在出錯後讀取 tracing/error_log 檔案將顯示關於出錯原因的更詳細資訊（如果可用）。 tracing/error_log 檔案是一個迴圈錯誤日誌，顯示最後 (8) 個失敗命令的少量（目前為 8 個）ftrace 錯誤。
擴充套件錯誤資訊和用法採用此示例中顯示的形式
# echo xxx > /sys/kernel/tracing/events/sched/sched_wakeup/trigger echo: write error: Invalid argument # cat /sys/kernel/tracing/error_log [ 5348.887237] location: error: Couldn't yyy: zzz Command: xxx ^ [ 7517.023364] location: error: Bad rrr: sss Command: ppp qqq ^要清除錯誤日誌，請將空字串回顯到其中
# echo > /sys/kernel/tracing/error_log
使用跟蹤器的示例¶
以下是一些典型的示例，說明了僅使用 tracefs 介面（不使用任何使用者空間實用程式）控制跟蹤器時如何使用它們。
輸出格式：¶
這是檔案“trace”的輸出格式示例
# tracer: function
#
# entries-in-buffer/entries-written: 140080/250280 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
bash-1977 [000] .... 17284.993652: sys_close <-system_call_fastpath
bash-1977 [000] .... 17284.993653: __close_fd <-sys_close
bash-1977 [000] .... 17284.993653: _raw_spin_lock <-__close_fd
sshd-1974 [003] .... 17284.993653: __srcu_read_unlock <-fsnotify
bash-1977 [000] .... 17284.993654: add_preempt_count <-_raw_spin_lock
bash-1977 [000] ...1 17284.993655: _raw_spin_unlock <-__close_fd
bash-1977 [000] ...1 17284.993656: sub_preempt_count <-_raw_spin_unlock
bash-1977 [000] .... 17284.993657: filp_close <-__close_fd
bash-1977 [000] .... 17284.993657: dnotify_flush <-filp_close
sshd-1974 [003] .... 17284.993658: sys_select <-system_call_fastpath
....
標頭與由跟蹤表示的跟蹤器名稱一起列印。 在這種情況下，跟蹤器是“function”。 然後，它顯示緩衝區中的事件數以及寫入的總條目數。 差異是由於緩衝區已滿而丟失的條目數（250280 - 140080 = 丟失了 110200 個事件）。
標頭解釋了事件的內容。 任務名稱“bash”，任務 PID“1977”，它正在執行的 CPU“000”，延遲格式（如下所述），<secs>.<usecs> 格式的時間戳，被跟蹤的函式名稱“sys_close”以及呼叫此函式的父函式“system_call_fastpath”。 時間戳是進入函式的時間。
延遲跟蹤格式¶
當啟用 latency-format 選項或設定其中一個延遲跟蹤器時，跟蹤檔案會提供更多資訊來了解為什麼發生延遲。 這是一個典型的跟蹤
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 259 us, #4/4, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: ps-6143 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: __lock_task_sighand
# => ended at: _raw_spin_unlock_irqrestore
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
ps-6143 2d... 0us!: trace_hardirqs_off <-__lock_task_sighand
ps-6143 2d..1 259us+: trace_hardirqs_on <-_raw_spin_unlock_irqrestore
ps-6143 2d..1 263us+: time_hardirqs_on <-_raw_spin_unlock_irqrestore
ps-6143 2d..1 306us : <stack trace>
=> trace_hardirqs_on_caller
=> trace_hardirqs_on
=> _raw_spin_unlock_irqrestore
=> do_task_stat
=> proc_tgid_stat
=> proc_single_show
=> seq_read
=> vfs_read
=> sys_read
=> system_call_fastpath
這表明當前跟蹤器是“irqsoff”，跟蹤停用中斷的時間。 它給出了跟蹤版本（永遠不會改變）和執行它的核心版本 (3.8)。 然後，它以微秒為單位顯示最大延遲 (259 us)。 顯示的跟蹤條目數和總數（均為 4：#4/4）。 VP、KP、SP 和 HP 始終為零，保留供以後使用。 #P 是線上 CPU 的數量 (#P:4)。
任務是發生延遲時正在執行的程序。 (ps pid: 6143)。
導致延遲的開始和停止（停用和啟用中斷的函式）
__lock_task_sighand 是停用中斷的地方。
_raw_spin_unlock_irqrestore 是再次啟用中斷的地方。
標頭之後的下一行是跟蹤本身。 標頭解釋了哪個是哪個。
cmd：跟蹤中程序的名稱。
pid：該程序的 PID。
CPU#：該程序正在其上執行的 CPU。
irqs-off：'d' 中斷被停用。 否則為“.”。
- need-resched
“B”所有，設定了 TIF_NEED_RESCHED、PREEMPT_NEED_RESCHED 和 TIF_RESCHED_LAZY，
“N”同時設定了 TIF_NEED_RESCHED 和 PREEMPT_NEED_RESCHED，
“n”僅設定了 TIF_NEED_RESCHED，
“p”僅設定了 PREEMPT_NEED_RESCHED，
“L”同時設定了 PREEMPT_NEED_RESCHED 和 TIF_RESCHED_LAZY，
“b”同時設定了 TIF_NEED_RESCHED 和 TIF_RESCHED_LAZY，
“l”僅設定了 TIF_RESCHED_LAZY
否則為“.”。
- hardirq/softirq
“Z” - NMI 發生在 hardirq 內部
“z” - NMI 正在執行
“H” - hard irq 發生在 softirq 內部。
“h” - hard irq 正在執行
“s” - soft irq 正在執行
“.” - 正常上下文。
preempt-depth：preempt_disabled 的級別
以上內容主要對核心開發人員有意義。
- time
啟用 latency-format 選項後，跟蹤檔案輸出包括相對於跟蹤開始的時間戳。 這與停用 latency-format 時的輸出不同，後者包括絕對時間戳。
- delay
這只是為了更好地引起您的注意。 並且需要修復為僅相對於同一 CPU。 標記由當前跟蹤和下一個跟蹤之間的差異決定。
“$” - 大於 1 秒
“@” - 大於 100 毫秒
“*” - 大於 10 毫秒
“#” - 大於 1000 微秒
“!” - 大於 100 微秒
“+” - 大於 10 微秒
“ ” - 小於或等於 10 微秒。
其餘與“trace”檔案相同。
請注意，延遲跟蹤器通常以回溯結束，以便輕鬆找到延遲發生的位置。
trace_options¶
trace_options 檔案（或 options 目錄）用於控制在跟蹤輸出中列印的內容，或操作跟蹤器。 要檢視可用的內容，只需 cat 該檔案
cat trace_options
print-parent
nosym-offset
nosym-addr
noverbose
noraw
nohex
nobin
noblock
nofields
trace_printk
annotate
nouserstacktrace
nosym-userobj
noprintk-msg-only
context-info
nolatency-format
record-cmd
norecord-tgid
overwrite
nodisable_on_free
irq-info
markers
noevent-fork
function-trace
nofunction-fork
nodisplay-graph
nostacktrace
nobranch
要停用其中一個選項，請回顯以“no”開頭的選項
echo noprint-parent > trace_options
要啟用一個選項，請省略“no”
echo sym-offset > trace_options
以下是可用選項
- print-parent
在函式跟蹤上，顯示呼叫（父）函式以及被跟蹤的函式。
print-parent: bash-4000 [01] 1477.606694: simple_strtoul <-kstrtoul noprint-parent: bash-4000 [01] 1477.606694: simple_strtoul- sym-offset
不僅顯示函式名稱，還顯示函式中的偏移量。 例如，您將看到“ktime_get+0xb/0x20”，而不是隻看到“ktime_get”。
sym-offset: bash-4000 [01] 1477.606694: simple_strtoul+0x6/0xa0- sym-addr
這還將顯示函式地址以及函式名稱。
sym-addr: bash-4000 [01] 1477.606694: simple_strtoul <c0339346>- verbose
這處理啟用了 latency-format 選項時的跟蹤檔案。
bash 4000 1 0 00000000 00010a95 [58127d26] 1720.415ms \ (+0.000ms): simple_strtoul (kstrtoul)- raw
這將顯示原始數字。 此選項最適合與使用者應用程式一起使用，這些應用程式可以比在核心中更好地轉換原始數字。
- hex
與 raw 類似，但數字將採用十六進位制格式。
- bin
這將以原始二進位制形式列印格式。
- block
設定後，輪詢時讀取 trace_pipe 不會阻塞。
- fields
按照它們的型別描述的方式列印欄位。 這比使用十六進位制、二進位制或原始格式更好，因為它能更好地解析事件的內容。
- trace_printk
可以停用
trace_printk()寫入緩衝區。- trace_printk_dest
設定為使
trace_printk()和類似的內部跟蹤函式寫入此例項。 請注意，只有一個跟蹤例項可以設定此項。 透過設定此標誌，它會清除先前設定它的例項的 trace_printk_dest 標誌。 預設情況下，頂級跟蹤設定了此項，如果另一個例項設定了此項然後清除了它，則將再次設定此項。此標誌無法由頂級例項清除，因為它是一個預設例項。 頂級例項清除此標誌的唯一方法是在另一個例項中設定它。
- copy_trace_marker
如果有些應用程式硬編碼寫入頂級 trace_marker 檔案 (/sys/kernel/tracing/trace_marker 或 trace_marker_raw)，並且該工具希望它進入一個例項，則可以使用此選項。 建立一個例項並設定此選項，然後對頂級 trace_marker 檔案的所有寫入也將重定向到此例項。
請注意，預設情況下，頂級例項設定了此選項。 如果停用它，則對 trace_marker 或 trace_marker_raw 檔案的寫入將不會寫入頂級檔案。 如果沒有例項設定此選項，則寫入將出錯，錯誤程式碼為 ENODEV。
- annotate
當 CPU 緩衝區已滿並且一個 CPU 緩衝區最近有很多事件，因此時間範圍較短時，另一個 CPU 可能只有幾個事件，這使其具有較舊的事件，這有時會令人困惑。 當報告跟蹤時，它首先顯示最舊的事件，並且看起來可能只有一個 CPU 在執行（具有最舊事件的那個）。 設定 annotate 選項後，它將顯示何時啟動了一個新的 CPU 緩衝區
<idle>-0 [001] dNs4 21169.031481: wake_up_idle_cpu <-add_timer_on <idle>-0 [001] dNs4 21169.031482: _raw_spin_unlock_irqrestore <-add_timer_on <idle>-0 [001] .Ns4 21169.031484: sub_preempt_count <-_raw_spin_unlock_irqrestore ##### CPU 2 buffer started #### <idle>-0 [002] .N.1 21169.031484: rcu_idle_exit <-cpu_idle <idle>-0 [001] .Ns3 21169.031484: _raw_spin_unlock <-clocksource_watchdog <idle>-0 [001] .Ns3 21169.031485: sub_preempt_count <-_raw_spin_unlock- userstacktrace
此選項更改跟蹤。 它在每個跟蹤事件之後記錄當前使用者空間執行緒的堆疊跟蹤。
- sym-userobj
啟用使用者堆疊跟蹤後，查詢地址所屬的物件，並列印相對地址。 當 ASLR 啟用時，這尤其有用，否則，在應用程式不再執行後，您將無法將地址解析為物件/檔案/行
查詢在您讀取 trace,trace_pipe 時執行。 示例
a.out-1623 [000] 40874.465068: /root/a.out[+0x480] <-/root/a.out[+0 x494] <- /root/a.out[+0x4a8] <- /lib/libc-2.7.so[+0x1e1a6]- printk-msg-only
設定後，
trace_printk()s 將僅顯示格式而不顯示其引數（如果使用 trace_bprintk() 或 trace_bputs() 儲存trace_printk()）。- context-info
僅顯示事件資料。 隱藏 comm、PID、時間戳、CPU 和其他有用的資料。
- latency-format
此選項更改跟蹤輸出。 啟用後，跟蹤將顯示有關延遲的其他資訊，如“延遲跟蹤格式”中所述。
- pause-on-trace
設定後，開啟跟蹤檔案進行讀取將暫停寫入環形緩衝區（就像將 tracing_on 設定為零一樣）。 這模擬了跟蹤檔案的原始行為。 關閉檔案後，將再次啟用跟蹤。
- hash-ptr
設定後，事件 printk 格式中的“%p”將顯示雜湊指標值而不是實際地址。 如果您想找出哪個雜湊值對應於跟蹤日誌中的實際值，這將很有用。
- record-cmd
當啟用任何事件或跟蹤器時，會在 sched_switch 跟蹤點中啟用一個鉤子，以使用對映的 pid 和 comm 填充 comm 快取。 但這可能會導致一些開銷，如果您只關心 pid，而不關心任務的名稱，則停用此選項可以降低跟蹤的影響。 請參閱“saved_cmdlines”。
- record-tgid
當啟用任何事件或跟蹤器時，會在 sched_switch 跟蹤點中啟用一個鉤子，以填充對映的執行緒組 ID (TGID) 對映到 pid 的快取。 請參閱“saved_tgids”。
- overwrite
這控制著當跟蹤緩衝區已滿時會發生什麼。 如果為“1”（預設），則最舊的事件將被丟棄和覆蓋。 如果為“0”，則最新的事件將被丟棄。（請參閱 per_cpu/cpu0/stats 中的 overrun 和 dropped）
- disable_on_free
當 free_buffer 關閉時，跟蹤將停止（tracing_on 設定為 0）。
- irq-info
顯示中斷、搶佔計數、need resched 資料。 停用後，跟蹤看起來像
# tracer: function # # entries-in-buffer/entries-written: 144405/9452052 #P:4 # # TASK-PID CPU# TIMESTAMP FUNCTION # | | | | | <idle>-0 [002] 23636.756054: ttwu_do_activate.constprop.89 <-try_to_wake_up <idle>-0 [002] 23636.756054: activate_task <-ttwu_do_activate.constprop.89 <idle>-0 [002] 23636.756055: enqueue_task <-activate_task- markers
設定後，trace_marker 是可寫的（僅由 root）。 停用後，trace_marker 在寫入時將出錯，錯誤程式碼為 EINVAL。
- event-fork
設定後，當那些任務 fork 時，set_event_pid 中列出的具有 PID 的任務的子任務的 PID 將新增到 set_event_pid 中。 此外，當 set_event_pid 中的 PID 的任務退出時，它們的 PID 將從檔案中刪除。
這也影響 set_event_notrace_pid 中列出的 PID。
- function-trace
如果啟用此選項（預設情況下已啟用），延遲跟蹤器將啟用函式跟蹤。 停用後，延遲跟蹤器不會跟蹤函式。 這會在執行延遲測試時降低跟蹤器的開銷。
- function-fork
設定後，當那些任務 fork 時，set_ftrace_pid 中列出的具有 PID 的任務的子任務的 PID 將新增到 set_ftrace_pid 中。 此外，當 set_ftrace_pid 中的 PID 的任務退出時，它們的 PID 將從檔案中刪除。
這也影響 set_ftrace_notrace_pid 中的 PID。
- display-graph
設定後，延遲跟蹤器（irqsoff、wakeup 等）將使用函式圖跟蹤而不是函式跟蹤。
- stacktrace
設定後，在記錄任何跟蹤事件後，都會記錄堆疊跟蹤。
- branch
使用跟蹤器啟用分支跟蹤。 這會啟用分支跟蹤器以及當前設定的跟蹤器。 使用“nop”跟蹤器啟用此項與僅啟用“branch”跟蹤器相同。
提示
某些跟蹤器有自己的選項。 它們僅在跟蹤器處於活動狀態時才會出現在此檔案中。 它們始終出現在 options 目錄中。
以下是每個跟蹤器的選項
函式跟蹤器的選項
- func_stack_trace
設定後，在記錄的每個函式之後都會記錄堆疊跟蹤。 注意！ 在啟用此選項之前，請使用“set_ftrace_filter”限制記錄的函式，否則系統性能將嚴重下降。 在清除函式過濾器之前，請記住停用此選項。
function_graph 跟蹤器的選項
由於 function_graph 跟蹤器的輸出略有不同，因此它有自己的選項來控制顯示的內容。
- funcgraph-overrun
設定後，每次跟蹤函式後都會顯示圖堆疊的“overrun”。 overrun 是呼叫堆疊的深度大於為每個任務保留的深度時。 每個任務都有一個固定的函式陣列來跟蹤呼叫圖。 如果呼叫的深度超過了該深度，則不會跟蹤該函式。 overrun 是由於超過此陣列而錯過的函式數。
- funcgraph-cpu
設定後，將顯示發生跟蹤的 CPU 的 CPU 編號。
- funcgraph-overhead
設定後，如果函式花費的時間超過一定量，則會顯示一個延遲標記。 請參閱上面的“delay”，在標頭描述下。
- funcgraph-proc
與其他跟蹤器不同，預設情況下不顯示程序的命令列，而是僅在上下文切換期間跟蹤任務進出時才顯示。 啟用此選項會在每行顯示每個程序的命令。
- funcgraph-duration
在每個函式的末尾（返回），以微秒為單位顯示函式中的時間量。
- funcgraph-abstime
設定後，時間戳將在每行顯示。
- funcgraph-irqs
停用後，發生在中斷內部的函式將不會被跟蹤。
- funcgraph-tail
設定後，返回事件將包括它所代表的函式。 預設情況下，這是關閉的，並且僅為函式的返回顯示一個結束花括號“}”。
- funcgraph-retval
設定後，每個跟蹤函式的返回值將在等號“=”後列印。 預設情況下，這是關閉的。
- funcgraph-retval-hex
設定後，返回值將始終以十六進位制格式列印。 如果未設定該選項並且返回值是錯誤程式碼，則將以有符號十進位制格式列印；否則，它也將以十六進位制格式列印。 預設情況下，此選項是關閉的。
- sleep-time
執行函式圖跟蹤器時，包括任務在其函式中排程的out時間。 啟用後，它將把任務排程的out時間計為函式呼叫的一部分。
- graph-time
在使用函式圖跟蹤器執行函式分析器時，包括呼叫巢狀函式的時間。 如果未設定此項，則報告的函式時間將僅包括函式自身執行的時間，不包括它呼叫的函式的時間。
blk 跟蹤器的選項
- blk_classic
顯示更簡約的輸出。
irqsoff¶
當中斷被停用時，CPU 無法對任何其他外部事件做出反應（除了 NMI 和 SMI）。 這會阻止定時器中斷觸發或滑鼠中斷讓核心知道新的滑鼠事件。 結果是反應時間的延遲。
irqsoff 跟蹤器跟蹤停用中斷的時間。 當達到新的最大延遲時，跟蹤器會儲存導致該延遲點的跟蹤，以便每次達到新的最大值時，舊的儲存跟蹤將被丟棄，並儲存新的跟蹤。
要重置最大值，請將 0 回顯到 tracing_max_latency 中。 這是一個示例
# echo 0 > options/function-trace
# echo irqsoff > current_tracer
# echo 1 > tracing_on
# echo 0 > tracing_max_latency
# ls -ltr
[...]
# echo 0 > tracing_on
# cat trace
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 16 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: swapper/0-0 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: run_timer_softirq
# => ended at: run_timer_softirq
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 0d.s2 0us+: _raw_spin_lock_irq <-run_timer_softirq
<idle>-0 0dNs3 17us : _raw_spin_unlock_irq <-run_timer_softirq
<idle>-0 0dNs3 17us+: trace_hardirqs_on <-run_timer_softirq
<idle>-0 0dNs3 25us : <stack trace>
=> _raw_spin_unlock_irq
=> run_timer_softirq
=> __do_softirq
=> call_softirq
=> do_softirq
=> irq_exit
=> smp_apic_timer_interrupt
=> apic_timer_interrupt
=> rcu_idle_exit
=> cpu_idle
=> rest_init
=> start_kernel
=> x86_64_start_reservations
=> x86_64_start_kernel
在這裡，我們看到我們有 16 微秒的延遲（非常好）。 run_timer_softirq 中的 _raw_spin_lock_irq 停用了中斷。 16 和顯示的時間戳 25us 之間的差異是因為在記錄最大延遲的時間和記錄具有該延遲的函式的時間之間時鐘增加了。
請注意，上面的示例未設定 function-trace。 如果我們設定 function-trace，我們將獲得更大的輸出
with echo 1 > options/function-trace
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 71 us, #168/168, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: bash-2042 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: ata_scsi_queuecmd
# => ended at: ata_scsi_queuecmd
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
bash-2042 3d... 0us : _raw_spin_lock_irqsave <-ata_scsi_queuecmd
bash-2042 3d... 0us : add_preempt_count <-_raw_spin_lock_irqsave
bash-2042 3d..1 1us : ata_scsi_find_dev <-ata_scsi_queuecmd
bash-2042 3d..1 1us : __ata_scsi_find_dev <-ata_scsi_find_dev
bash-2042 3d..1 2us : ata_find_dev.part.14 <-__ata_scsi_find_dev
bash-2042 3d..1 2us : ata_qc_new_init <-__ata_scsi_queuecmd
bash-2042 3d..1 3us : ata_sg_init <-__ata_scsi_queuecmd
bash-2042 3d..1 4us : ata_scsi_rw_xlat <-__ata_scsi_queuecmd
bash-2042 3d..1 4us : ata_build_rw_tf <-ata_scsi_rw_xlat
[...]
bash-2042 3d..1 67us : delay_tsc <-__delay
bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
bash-2042 3d..2 67us : sub_preempt_count <-delay_tsc
bash-2042 3d..1 67us : add_preempt_count <-delay_tsc
bash-2042 3d..2 68us : sub_preempt_count <-delay_tsc
bash-2042 3d..1 68us+: ata_bmdma_start <-ata_bmdma_qc_issue
bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
bash-2042 3d..1 71us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
bash-2042 3d..1 72us+: trace_hardirqs_on <-ata_scsi_queuecmd
bash-2042 3d..1 120us : <stack trace>
=> _raw_spin_unlock_irqrestore
=> ata_scsi_queuecmd
=> scsi_dispatch_cmd
=> scsi_request_fn
=> __blk_run_queue_uncond
=> __blk_run_queue
=> blk_queue_bio
=> submit_bio_noacct
=> submit_bio
=> submit_bh
=> __ext3_get_inode_loc
=> ext3_iget
=> ext3_lookup
=> lookup_real
=> __lookup_hash
=> walk_component
=> lookup_last
=> path_lookupat
=> filename_lookup
=> user_path_at_empty
=> user_path_at
=> vfs_fstatat
=> vfs_stat
=> sys_newstat
=> system_call_fastpath
在這裡，我們跟蹤了 71 微秒的延遲。 但我們也看到了在那段時間內呼叫的所有函式。 請注意，透過啟用函式跟蹤，我們會產生額外的開銷。 此開銷可能會延長延遲時間。 但無論如何，此跟蹤提供了一些非常有用的除錯資訊。
如果我們更喜歡函式圖輸出而不是函式輸出，我們可以設定 display-graph 選項
with echo 1 > options/display-graph
# tracer: irqsoff
#
# irqsoff latency trace v1.1.5 on 4.20.0-rc6+
# --------------------------------------------------------------------
# latency: 3751 us, #274/274, CPU#0 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: bash-1507 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: free_debug_processing
# => ended at: return_to_handler
#
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| /
# REL TIME CPU TASK/PID |||| DURATION FUNCTION CALLS
# | | | | |||| | | | | | |
0 us | 0) bash-1507 | d... | 0.000 us | _raw_spin_lock_irqsave();
0 us | 0) bash-1507 | d..1 | 0.378 us | do_raw_spin_trylock();
1 us | 0) bash-1507 | d..2 | | set_track() {
2 us | 0) bash-1507 | d..2 | | save_stack_trace() {
2 us | 0) bash-1507 | d..2 | | __save_stack_trace() {
3 us | 0) bash-1507 | d..2 | | __unwind_start() {
3 us | 0) bash-1507 | d..2 | | get_stack_info() {
3 us | 0) bash-1507 | d..2 | 0.351 us | in_task_stack();
4 us | 0) bash-1507 | d..2 | 1.107 us | }
[...]
3750 us | 0) bash-1507 | d..1 | 0.516 us | do_raw_spin_unlock();
3750 us | 0) bash-1507 | d..1 | 0.000 us | _raw_spin_unlock_irqrestore();
3764 us | 0) bash-1507 | d..1 | 0.000 us | tracer_hardirqs_on();
bash-1507 0d..1 3792us : <stack trace>
=> free_debug_processing
=> __slab_free
=> kmem_cache_free
=> vm_area_free
=> remove_vma
=> exit_mmap
=> mmput
=> begin_new_exec
=> load_elf_binary
=> search_binary_handler
=> __do_execve_file.isra.32
=> __x64_sys_execve
=> do_syscall_64
=> entry_SYSCALL_64_after_hwframe
preemptoff¶
當停用搶佔時，我們可能能夠接收中斷，但無法搶佔該任務，並且優先順序更高的任務必須等待再次啟用搶佔後才能搶佔優先順序較低的任務。
preemptoff 跟蹤器跟蹤停用搶佔的位置。 與 irqsoff 跟蹤器一樣，它記錄停用搶佔的最大延遲。 preemptoff 跟蹤器的控制與 irqsoff 跟蹤器非常相似。
# echo 0 > options/function-trace
# echo preemptoff > current_tracer
# echo 1 > tracing_on
# echo 0 > tracing_max_latency
# ls -ltr
[...]
# echo 0 > tracing_on
# cat trace
# tracer: preemptoff
#
# preemptoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 46 us, #4/4, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: sshd-1991 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: do_IRQ
# => ended at: do_IRQ
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
sshd-1991 1d.h. 0us+: irq_enter <-do_IRQ
sshd-1991 1d..1 46us : irq_exit <-do_IRQ
sshd-1991 1d..1 47us+: trace_preempt_on <-do_IRQ
sshd-1991 1d..1 52us : <stack trace>
=> sub_preempt_count
=> irq_exit
=> do_IRQ
=> ret_from_intr
這有一些更多的變化。 當中斷進入時（注意“h”），搶佔被停用，並且在退出時啟用。 但我們也看到，在進入和離開搶佔關閉部分時，中斷已被停用（“d”）。 我們不知道中斷是否在此期間或之後不久被啟用。
# tracer: preemptoff
#
# preemptoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 83 us, #241/241, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: bash-1994 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: wake_up_new_task
# => ended at: task_rq_unlock
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
bash-1994 1d..1 0us : _raw_spin_lock_irqsave <-wake_up_new_task
bash-1994 1d..1 0us : select_task_rq_fair <-select_task_rq
bash-1994 1d..1 1us : __rcu_read_lock <-select_task_rq_fair
bash-1994 1d..1 1us : source_load <-select_task_rq_fair
bash-1994 1d..1 1us : source_load <-select_task_rq_fair
[...]
bash-1994 1d..1 12us : irq_enter <-smp_apic_timer_interrupt
bash-1994 1d..1 12us : rcu_irq_enter <-irq_enter
bash-1994 1d..1 13us : add_preempt_count <-irq_enter
bash-1994 1d.h1 13us : exit_idle <-smp_apic_timer_interrupt
bash-1994 1d.h1 13us : hrtimer_interrupt <-smp_apic_timer_interrupt
bash-1994 1d.h1 13us : _raw_spin_lock <-hrtimer_interrupt
bash-1994 1d.h1 14us : add_preempt_count <-_raw_spin_lock
bash-1994 1d.h2 14us : ktime_get_update_offsets <-hrtimer_interrupt
[...]
bash-1994 1d.h1 35us : lapic_next_event <-clockevents_program_event
bash-1994 1d.h1 35us : irq_exit <-smp_apic_timer_interrupt
bash-1994 1d.h1 36us : sub_preempt_count <-irq_exit
bash-1994 1d..2 36us : do_softirq <-irq_exit
bash-1994 1d..2 36us : __do_softirq <-call_softirq
bash-1994 1d..2 36us : __local_bh_disable <-__do_softirq
bash-1994 1d.s2 37us : add_preempt_count <-_raw_spin_lock_irq
bash-1994 1d.s3 38us : _raw_spin_unlock <-run_timer_softirq
bash-1994 1d.s3 39us : sub_preempt_count <-_raw_spin_unlock
bash-1994 1d.s2 39us : call_timer_fn <-run_timer_softirq
[...]
bash-1994 1dNs2 81us : cpu_needs_another_gp <-rcu_process_callbacks
bash-1994 1dNs2 82us : __local_bh_enable <-__do_softirq
bash-1994 1dNs2 82us : sub_preempt_count <-__local_bh_enable
bash-1994 1dN.2 82us : idle_cpu <-irq_exit
bash-1994 1dN.2 83us : rcu_irq_exit <-irq_exit
bash-1994 1dN.2 83us : sub_preempt_count <-irq_exit
bash-1994 1.N.1 84us : _raw_spin_unlock_irqrestore <-task_rq_unlock
bash-1994 1.N.1 84us+: trace_preempt_on <-task_rq_unlock
bash-1994 1.N.1 104us : <stack trace>
=> sub_preempt_count
=> _raw_spin_unlock_irqrestore
=> task_rq_unlock
=> wake_up_new_task
=> do_fork
=> sys_clone
=> stub_clone
以上是設定了 function-trace 的 preemptoff 跟蹤的示例。 在這裡，我們看到中斷不是在整個時間內都停用的。 irq_enter 程式碼讓我們知道我們進入了一箇中斷“h”。 在此之前，被跟蹤的函式仍然表明它不在中斷中，但我們可以從函式本身看到情況並非如此。
preemptirqsoff¶
知道具有最長時間的中斷停用或搶佔停用的位置是有幫助的。 但有時我們想知道何時停用搶佔和/或中斷。
考慮以下程式碼
local_irq_disable();
call_function_with_irqs_off();
preempt_disable();
call_function_with_irqs_and_preemption_off();
local_irq_enable();
call_function_with_preemption_off();
preempt_enable();
irqsoff 跟蹤器將記錄 call_function_with_irqs_off() 和 call_function_with_irqs_and_preemption_off() 的總長度。
preemptoff 跟蹤器將記錄 call_function_with_irqs_and_preemption_off() 和 call_function_with_preemption_off() 的總長度。
但是，兩者都不會跟蹤中斷和/或搶佔被停用的時間。 此總時間是我們無法排程的時間。 要記錄此時間，請使用 preemptirqsoff 跟蹤器。
同樣，使用此跟蹤與 irqsoff 和 preemptoff 跟蹤器非常相似。
# echo 0 > options/function-trace
# echo preemptirqsoff > current_tracer
# echo 1 > tracing_on
# echo 0 > tracing_max_latency
# ls -ltr
[...]
# echo 0 > tracing_on
# cat trace
# tracer: preemptirqsoff
#
# preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 100 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: ls-2230 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: ata_scsi_queuecmd
# => ended at: ata_scsi_queuecmd
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
ls-2230 3d... 0us+: _raw_spin_lock_irqsave <-ata_scsi_queuecmd
ls-2230 3...1 100us : _raw_spin_unlock_irqrestore <-ata_scsi_queuecmd
ls-2230 3...1 101us+: trace_preempt_on <-ata_scsi_queuecmd
ls-2230 3...1 111us : <stack trace>
=> sub_preempt_count
=> _raw_spin_unlock_irqrestore
=> ata_scsi_queuecmd
=> scsi_dispatch_cmd
=> scsi_request_fn
=> __blk_run_queue_uncond
=> __blk_run_queue
=> blk_queue_bio
=> submit_bio_noacct
=> submit_bio
=> submit_bh
=> ext3_bread
=> ext3_dir_bread
=> htree_dirblock_to_tree
=> ext3_htree_fill_tree
=> ext3_readdir
=> vfs_readdir
=> sys_getdents
=> system_call_fastpath
當在彙編程式碼中停用中斷時，trace_hardirqs_off_thunk 從 x86 上的彙編中呼叫。 如果沒有函式跟蹤，我們不知道中斷是否在搶佔點內被啟用。 我們確實看到它以啟用搶佔開始。
這是設定了 function-trace 的跟蹤
# tracer: preemptirqsoff
#
# preemptirqsoff latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 161 us, #339/339, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: ls-2269 (uid:0 nice:0 policy:0 rt_prio:0)
# -----------------
# => started at: schedule
# => ended at: mutex_unlock
#
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
kworker/-59 3...1 0us : __schedule <-schedule
kworker/-59 3d..1 0us : rcu_preempt_qs <-rcu_note_context_switch
kworker/-59 3d..1 1us : add_preempt_count <-_raw_spin_lock_irq
kworker/-59 3d..2 1us : deactivate_task <-__schedule
kworker/-59 3d..2 1us : dequeue_task <-deactivate_task
kworker/-59 3d..2 2us : update_rq_clock <-dequeue_task
kworker/-59 3d..2 2us : dequeue_task_fair <-dequeue_task
kworker/-59 3d..2 2us : update_curr <-dequeue_task_fair
kworker/-59 3d..2 2us : update_min_vruntime <-update_curr
kworker/-59 3d..2 3us : cpuacct_charge <-update_curr
kworker/-59 3d..2 3us : __rcu_read_lock <-cpuacct_charge
kworker/-59 3d..2 3us : __rcu_read_unlock <-cpuacct_charge
kworker/-59 3d..2 3us : update_cfs_rq_blocked_load <-dequeue_task_fair
kworker/-59 3d..2 4us : clear_buddies <-dequeue_task_fair
kworker/-59 3d..2 4us : account_entity_dequeue <-dequeue_task_fair
kworker/-59 3d..2 4us : update_min_vruntime <-dequeue_task_fair
kworker/-59 3d..2 4us : update_cfs_shares <-dequeue_task_fair
kworker/-59 3d..2 5us : hrtick_update <-dequeue_task_fair
kworker/-59 3d..2 5us : wq_worker_sleeping <-__schedule
kworker/-59 3d..2 5us : kthread_data <-wq_worker_sleeping
kworker/-59 3d..2 5us : put_prev_task_fair <-__schedule
kworker/-59 3d..2 6us : pick_next_task_fair <-pick_next_task
kworker/-59 3d..2 6us : clear_buddies <-pick_next_task_fair
kworker/-59 3d..2 6us : set_next_entity <-pick_next_task_fair
kworker/-59 3d..2 6us : update_stats_wait_end <-set_next_entity
ls-2269 3d..2 7us : finish_task_switch <-__schedule
ls-2269 3d..2 7us : _raw_spin_unlock_irq <-finish_task_switch
ls-2269 3d..2 8us : do_IRQ <-ret_from_intr
ls-2269 3d..2 8us : irq_enter <-do_IRQ
ls-2269 3d..2 8us : rcu_irq_enter <-irq_enter
ls-2269 3d..2 9us : add_preempt_count <-irq_enter
ls-2269 3d.h2 9us : exit_idle <-do_IRQ
[...]
ls-2269 3d.h3 20us : sub_preempt_count <-_raw_spin_unlock
ls-2269 3d.h2 20us : irq_exit <-do_IRQ
ls-2269 3d.h2 21us : sub_preempt_count <-irq_exit
ls-2269 3d..3 21us : do_softirq <-irq_exit
ls-2269 3d..3 21us : __do_softirq <-call_softirq
ls-2269 3d..3 21us+: __local_bh_disable <-__do_softirq
ls-2269 3d.s4 29us : sub_preempt_count <-_local_bh_enable_ip
ls-2269 3d.s5 29us : sub_preempt_count <-_local_bh_enable_ip
ls-2269 3d.s5 31us : do_IRQ <-ret_from_intr
ls-2269 3d.s5 31us : irq_enter <-do_IRQ
ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
[...]
ls-2269 3d.s5 31us : rcu_irq_enter <-irq_enter
ls-2269 3d.s5 32us : add_preempt_count <-irq_enter
ls-2269 3d.H5 32us : exit_idle <-do_IRQ
ls-2269 3d.H5 32us : handle_irq <-do_IRQ
ls-2269 3d.H5 32us : irq_to_desc <-handle_irq
ls-2269 3d.H5 33us : handle_fasteoi_irq <-handle_irq
[...]
ls-2269 3d.s5 158us : _raw_spin_unlock_irqrestore <-rtl8139_poll
ls-2269 3d.s3 158us : net_rps_action_and_irq_enable.isra.65 <-net_rx_action
ls-2269 3d.s3 159us : __local_bh_enable <-__do_softirq
ls-2269 3d.s3 159us : sub_preempt_count <-__local_bh_enable
ls-2269 3d..3 159us : idle_cpu <-irq_exit
ls-2269 3d..3 159us : rcu_irq_exit <-irq_exit
ls-2269 3d..3 160us : sub_preempt_count <-irq_exit
ls-2269 3d... 161us : __mutex_unlock_slowpath <-mutex_unlock
ls-2269 3d... 162us+: trace_hardirqs_on <-mutex_unlock
ls-2269 3d... 186us : <stack trace>
=> __mutex_unlock_slowpath
=> mutex_unlock
=> process_output
=> n_tty_write
=> tty_write
=> vfs_write
=> sys_write
=> system_call_fastpath
這是一個有趣的跟蹤。 它以 kworker 執行並排程 out 和 ls 接管開始。 但是，一旦 ls 釋放了 rq 鎖並啟用了中斷（但未啟用搶佔），就會觸發一箇中斷。 中斷完成後，它開始執行 softirq。 當中斷在 softirq 內部執行時，註釋為“H”。
wakeup¶
人們感興趣的常見情況之一是跟蹤一個被喚醒的任務實際喚醒所需的時間。 現在，對於非即時任務，這可以是任意的。 但無論如何，跟蹤它可能很有趣。
沒有函式跟蹤
# echo 0 > options/function-trace
# echo wakeup > current_tracer
# echo 1 > tracing_on
# echo 0 > tracing_max_latency
# chrt -f 5 sleep 1
# echo 0 > tracing_on
# cat trace
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 15 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: kworker/3:1H-312 (uid:0 nice:-20 policy:0 rt_prio:0)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 3dNs7 0us : 0:120:R + [003] 312:100:R kworker/3:1H
<idle>-0 3dNs7 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
<idle>-0 3d..3 15us : __schedule <-schedule
<idle>-0 3d..3 15us : 0:120:R ==> [003] 312:100:R kworker/3:1H
跟蹤器只跟蹤系統中優先順序最高的任務，以避免跟蹤正常情況。在這裡，我們可以看到nice優先順序為-20（不是很好）的kworker，從喚醒到執行僅花費了15微秒。
非即時任務不是那麼有趣。更有趣的跟蹤是隻專注於即時任務。
wakeup_rt¶
在即時環境中，知道優先順序最高的任務從喚醒到執行所花費的喚醒時間非常重要。 這也稱為“排程延遲”。我強調這一點是關於RT任務的。瞭解非RT任務的排程延遲也很重要，但平均排程延遲更適合非RT任務。像LatencyTop這樣的工具更適合進行此類測量。
即時環境關注的是最壞情況下的延遲。即發生某件事所花費的最長延遲，而不是平均延遲。我們可以有一個非常快速的排程程式，可能偶爾才會有很大的延遲，但這對於即時任務來說效果不好。 wakeup_rt跟蹤器旨在記錄RT任務的最壞情況喚醒。 不會記錄非RT任務，因為跟蹤器只記錄一個最壞情況，並且跟蹤不可預測的非RT任務會覆蓋RT任務的最壞情況延遲（只需執行普通的wakeup跟蹤器一段時間即可看到該效果）。
由於此跟蹤器僅處理RT任務，因此我們將以與之前跟蹤器略有不同的方式執行它。我們將在“chrt”下執行“sleep 1”，而不是執行“ls”，這會更改任務的優先順序。
# echo 0 > options/function-trace
# echo wakeup_rt > current_tracer
# echo 1 > tracing_on
# echo 0 > tracing_max_latency
# chrt -f 5 sleep 1
# echo 0 > tracing_on
# cat trace
# tracer: wakeup
#
# tracer: wakeup_rt
#
# wakeup_rt latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 5 us, #4/4, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: sleep-2389 (uid:0 nice:0 policy:1 rt_prio:5)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 3d.h4 0us : 0:120:R + [003] 2389: 94:R sleep
<idle>-0 3d.h4 1us+: ttwu_do_activate.constprop.87 <-try_to_wake_up
<idle>-0 3d..3 5us : __schedule <-schedule
<idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
在空閒系統上執行它，我們看到執行任務切換僅花費了5微秒。請注意，由於排程中的跟蹤點位於實際“切換”之前，因此當記錄的任務即將排程時，我們停止跟蹤。如果我們排程程式的末尾新增新的標記，這可能會改變。
請注意，記錄的任務是PID為2389的“sleep”，其rt_prio為5。此優先順序是使用者空間優先順序，而不是內部核心優先順序。策略1表示SCHED_FIFO，2表示SCHED_RR。
請注意，跟蹤資料顯示了內部優先順序（99 - rtprio）。
<idle>-0 3d..3 5us : 0:120:R ==> [003] 2389: 94:R sleep
0:120:R表示idle以nice優先順序0（120 - 120）執行，並且處於執行狀態“R”。 sleep任務以2389: 94:R排程進入。也就是說，優先順序是核心rtprio（99 - 5 = 94），並且它也處於執行狀態。
使用chrt -r 5並設定function-trace執行相同的操作。
echo 1 > options/function-trace
# tracer: wakeup_rt
#
# wakeup_rt latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 29 us, #85/85, CPU#3 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: sleep-2448 (uid:0 nice:0 policy:1 rt_prio:5)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 3d.h4 1us+: 0:120:R + [003] 2448: 94:R sleep
<idle>-0 3d.h4 2us : ttwu_do_activate.constprop.87 <-try_to_wake_up
<idle>-0 3d.h3 3us : check_preempt_curr <-ttwu_do_wakeup
<idle>-0 3d.h3 3us : resched_curr <-check_preempt_curr
<idle>-0 3dNh3 4us : task_woken_rt <-ttwu_do_wakeup
<idle>-0 3dNh3 4us : _raw_spin_unlock <-try_to_wake_up
<idle>-0 3dNh3 4us : sub_preempt_count <-_raw_spin_unlock
<idle>-0 3dNh2 5us : ttwu_stat <-try_to_wake_up
<idle>-0 3dNh2 5us : _raw_spin_unlock_irqrestore <-try_to_wake_up
<idle>-0 3dNh2 6us : sub_preempt_count <-_raw_spin_unlock_irqrestore
<idle>-0 3dNh1 6us : _raw_spin_lock <-__run_hrtimer
<idle>-0 3dNh1 6us : add_preempt_count <-_raw_spin_lock
<idle>-0 3dNh2 7us : _raw_spin_unlock <-hrtimer_interrupt
<idle>-0 3dNh2 7us : sub_preempt_count <-_raw_spin_unlock
<idle>-0 3dNh1 7us : tick_program_event <-hrtimer_interrupt
<idle>-0 3dNh1 7us : clockevents_program_event <-tick_program_event
<idle>-0 3dNh1 8us : ktime_get <-clockevents_program_event
<idle>-0 3dNh1 8us : lapic_next_event <-clockevents_program_event
<idle>-0 3dNh1 8us : irq_exit <-smp_apic_timer_interrupt
<idle>-0 3dNh1 9us : sub_preempt_count <-irq_exit
<idle>-0 3dN.2 9us : idle_cpu <-irq_exit
<idle>-0 3dN.2 9us : rcu_irq_exit <-irq_exit
<idle>-0 3dN.2 10us : rcu_eqs_enter_common.isra.45 <-rcu_irq_exit
<idle>-0 3dN.2 10us : sub_preempt_count <-irq_exit
<idle>-0 3.N.1 11us : rcu_idle_exit <-cpu_idle
<idle>-0 3dN.1 11us : rcu_eqs_exit_common.isra.43 <-rcu_idle_exit
<idle>-0 3.N.1 11us : tick_nohz_idle_exit <-cpu_idle
<idle>-0 3dN.1 12us : menu_hrtimer_cancel <-tick_nohz_idle_exit
<idle>-0 3dN.1 12us : ktime_get <-tick_nohz_idle_exit
<idle>-0 3dN.1 12us : tick_do_update_jiffies64 <-tick_nohz_idle_exit
<idle>-0 3dN.1 13us : cpu_load_update_nohz <-tick_nohz_idle_exit
<idle>-0 3dN.1 13us : _raw_spin_lock <-cpu_load_update_nohz
<idle>-0 3dN.1 13us : add_preempt_count <-_raw_spin_lock
<idle>-0 3dN.2 13us : __cpu_load_update <-cpu_load_update_nohz
<idle>-0 3dN.2 14us : sched_avg_update <-__cpu_load_update
<idle>-0 3dN.2 14us : _raw_spin_unlock <-cpu_load_update_nohz
<idle>-0 3dN.2 14us : sub_preempt_count <-_raw_spin_unlock
<idle>-0 3dN.1 15us : calc_load_nohz_stop <-tick_nohz_idle_exit
<idle>-0 3dN.1 15us : touch_softlockup_watchdog <-tick_nohz_idle_exit
<idle>-0 3dN.1 15us : hrtimer_cancel <-tick_nohz_idle_exit
<idle>-0 3dN.1 15us : hrtimer_try_to_cancel <-hrtimer_cancel
<idle>-0 3dN.1 16us : lock_hrtimer_base.isra.18 <-hrtimer_try_to_cancel
<idle>-0 3dN.1 16us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
<idle>-0 3dN.1 16us : add_preempt_count <-_raw_spin_lock_irqsave
<idle>-0 3dN.2 17us : __remove_hrtimer <-remove_hrtimer.part.16
<idle>-0 3dN.2 17us : hrtimer_force_reprogram <-__remove_hrtimer
<idle>-0 3dN.2 17us : tick_program_event <-hrtimer_force_reprogram
<idle>-0 3dN.2 18us : clockevents_program_event <-tick_program_event
<idle>-0 3dN.2 18us : ktime_get <-clockevents_program_event
<idle>-0 3dN.2 18us : lapic_next_event <-clockevents_program_event
<idle>-0 3dN.2 19us : _raw_spin_unlock_irqrestore <-hrtimer_try_to_cancel
<idle>-0 3dN.2 19us : sub_preempt_count <-_raw_spin_unlock_irqrestore
<idle>-0 3dN.1 19us : hrtimer_forward <-tick_nohz_idle_exit
<idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
<idle>-0 3dN.1 20us : ktime_add_safe <-hrtimer_forward
<idle>-0 3dN.1 20us : hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
<idle>-0 3dN.1 20us : __hrtimer_start_range_ns <-hrtimer_start_range_ns
<idle>-0 3dN.1 21us : lock_hrtimer_base.isra.18 <-__hrtimer_start_range_ns
<idle>-0 3dN.1 21us : _raw_spin_lock_irqsave <-lock_hrtimer_base.isra.18
<idle>-0 3dN.1 21us : add_preempt_count <-_raw_spin_lock_irqsave
<idle>-0 3dN.2 22us : ktime_add_safe <-__hrtimer_start_range_ns
<idle>-0 3dN.2 22us : enqueue_hrtimer <-__hrtimer_start_range_ns
<idle>-0 3dN.2 22us : tick_program_event <-__hrtimer_start_range_ns
<idle>-0 3dN.2 23us : clockevents_program_event <-tick_program_event
<idle>-0 3dN.2 23us : ktime_get <-clockevents_program_event
<idle>-0 3dN.2 23us : lapic_next_event <-clockevents_program_event
<idle>-0 3dN.2 24us : _raw_spin_unlock_irqrestore <-__hrtimer_start_range_ns
<idle>-0 3dN.2 24us : sub_preempt_count <-_raw_spin_unlock_irqrestore
<idle>-0 3dN.1 24us : account_idle_ticks <-tick_nohz_idle_exit
<idle>-0 3dN.1 24us : account_idle_time <-account_idle_ticks
<idle>-0 3.N.1 25us : sub_preempt_count <-cpu_idle
<idle>-0 3.N.. 25us : schedule <-cpu_idle
<idle>-0 3.N.. 25us : __schedule <-preempt_schedule
<idle>-0 3.N.. 26us : add_preempt_count <-__schedule
<idle>-0 3.N.1 26us : rcu_note_context_switch <-__schedule
<idle>-0 3.N.1 26us : rcu_sched_qs <-rcu_note_context_switch
<idle>-0 3dN.1 27us : rcu_preempt_qs <-rcu_note_context_switch
<idle>-0 3.N.1 27us : _raw_spin_lock_irq <-__schedule
<idle>-0 3dN.1 27us : add_preempt_count <-_raw_spin_lock_irq
<idle>-0 3dN.2 28us : put_prev_task_idle <-__schedule
<idle>-0 3dN.2 28us : pick_next_task_stop <-pick_next_task
<idle>-0 3dN.2 28us : pick_next_task_rt <-pick_next_task
<idle>-0 3dN.2 29us : dequeue_pushable_task <-pick_next_task_rt
<idle>-0 3d..3 29us : __schedule <-preempt_schedule
<idle>-0 3d..3 30us : 0:120:R ==> [003] 2448: 94:R sleep
即使啟用了函式跟蹤，這也不是很大的跟蹤，所以我包含了整個跟蹤。
當系統空閒時，中斷被關閉。在呼叫task_woken_rt()之前，NEED_RESCHED標誌已設定，這由“N”標誌的首次出現表示。
延遲跟蹤和事件¶
由於函式跟蹤可能會導致更大的延遲，但是如果不瞭解延遲內部發生的情況，很難知道導致延遲的原因。有一種折衷方案，那就是啟用事件。
# echo 0 > options/function-trace
# echo wakeup_rt > current_tracer
# echo 1 > events/enable
# echo 1 > tracing_on
# echo 0 > tracing_max_latency
# chrt -f 5 sleep 1
# echo 0 > tracing_on
# cat trace
# tracer: wakeup_rt
#
# wakeup_rt latency trace v1.1.5 on 3.8.0-test+
# --------------------------------------------------------------------
# latency: 6 us, #12/12, CPU#2 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:4)
# -----------------
# | task: sleep-5882 (uid:0 nice:0 policy:1 rt_prio:5)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 2d.h4 0us : 0:120:R + [002] 5882: 94:R sleep
<idle>-0 2d.h4 0us : ttwu_do_activate.constprop.87 <-try_to_wake_up
<idle>-0 2d.h4 1us : sched_wakeup: comm=sleep pid=5882 prio=94 success=1 target_cpu=002
<idle>-0 2dNh2 1us : hrtimer_expire_exit: hrtimer=ffff88007796feb8
<idle>-0 2.N.2 2us : power_end: cpu_id=2
<idle>-0 2.N.2 3us : cpu_idle: state=4294967295 cpu_id=2
<idle>-0 2dN.3 4us : hrtimer_cancel: hrtimer=ffff88007d50d5e0
<idle>-0 2dN.3 4us : hrtimer_start: hrtimer=ffff88007d50d5e0 function=tick_sched_timer expires=34311211000000 softexpires=34311211000000
<idle>-0 2.N.2 5us : rcu_utilization: Start context switch
<idle>-0 2.N.2 5us : rcu_utilization: End context switch
<idle>-0 2d..3 6us : __schedule <-schedule
<idle>-0 2d..3 6us : 0:120:R ==> [002] 5882: 94:R sleep
硬體延遲檢測器¶
硬體延遲檢測器透過啟用“hwlat”跟蹤器來執行。
請注意，此跟蹤器會影響系統的效能，因為它會定期使CPU保持繁忙且中斷停用狀態。
# echo hwlat > current_tracer
# sleep 100
# cat trace
# tracer: hwlat
#
# entries-in-buffer/entries-written: 13/13 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<...>-1729 [001] d... 678.473449: #1 inner/outer(us): 11/12 ts:1581527483.343962693 count:6
<...>-1729 [004] d... 689.556542: #2 inner/outer(us): 16/9 ts:1581527494.889008092 count:1
<...>-1729 [005] d... 714.756290: #3 inner/outer(us): 16/16 ts:1581527519.678961629 count:5
<...>-1729 [001] d... 718.788247: #4 inner/outer(us): 9/17 ts:1581527523.889012713 count:1
<...>-1729 [002] d... 719.796341: #5 inner/outer(us): 13/9 ts:1581527524.912872606 count:1
<...>-1729 [006] d... 844.787091: #6 inner/outer(us): 9/12 ts:1581527649.889048502 count:2
<...>-1729 [003] d... 849.827033: #7 inner/outer(us): 18/9 ts:1581527654.889013793 count:1
<...>-1729 [007] d... 853.859002: #8 inner/outer(us): 9/12 ts:1581527658.889065736 count:1
<...>-1729 [001] d... 855.874978: #9 inner/outer(us): 9/11 ts:1581527660.861991877 count:1
<...>-1729 [001] d... 863.938932: #10 inner/outer(us): 9/11 ts:1581527668.970010500 count:1 nmi-total:7 nmi-count:1
<...>-1729 [007] d... 878.050780: #11 inner/outer(us): 9/12 ts:1581527683.385002600 count:1 nmi-total:5 nmi-count:1
<...>-1729 [007] d... 886.114702: #12 inner/outer(us): 9/12 ts:1581527691.385001600 count:1
上面的輸出在標題中略有相同。所有事件都將停用中斷“d”。在FUNCTION標題下有
- #1
這是記錄的事件數，這些事件大於tracing_threshold（請參見下文）。
inner/outer(us): 11/11
這顯示了兩個數字，分別是“內部延遲”和“外部延遲”。該測試在一個迴圈中執行，檢查時間戳兩次。在兩個時間戳內檢測到的延遲是“內部延遲”，而在迴圈中的前一個時間戳和下一個時間戳之後檢測到的延遲是“外部延遲”。
ts:1581527483.343962693
視窗中記錄的第一個延遲的絕對時間戳。
count:6
在視窗期間檢測到延遲的次數。
nmi-total:7 nmi-count:1
在支援它的體系結構上，如果在測試期間出現NMI，則NMI中花費的時間將在“nmi-total”中報告（以微秒為單位）。
如果測試期間出現NMI，則具有NMI的所有體系結構都將顯示“nmi-count”。
hwlat 檔案
- tracing_threshold
這會自動設定為“10”以表示10微秒。 這是在記錄跟蹤之前需要檢測到的延遲閾值。
請注意，當hwlat跟蹤器完成時（將另一個跟蹤器寫入“current_tracer”），tracing_threshold的原始值將放回此檔案中。
- hwlat_detector/width
測試執行時中斷停用的時間長度。
- hwlat_detector/window
測試執行的視窗時間長度。 也就是說，測試將在每個“視窗”微秒內執行“width”微秒
- tracing_cpumask
測試何時開始。 建立一個核心執行緒來執行測試。 此執行緒將在每個週期（一個“視窗”）在tracing_cpumask中列出的CPU之間交替。 要將測試限制為特定CPU，請在此檔案中將掩碼設定為僅測試應在其上執行的CPU。
function¶
此跟蹤器是函式跟蹤器。 可以從除錯檔案系統中啟用函式跟蹤器。 確保設定了ftrace_enabled； 否則，此跟蹤器是空操作。 請參見下面的“ftrace_enabled”部分。
# sysctl kernel.ftrace_enabled=1
# echo function > current_tracer
# echo 1 > tracing_on
# usleep 1
# echo 0 > tracing_on
# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 24799/24799 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
bash-1994 [002] .... 3082.063030: mutex_unlock <-rb_simple_write
bash-1994 [002] .... 3082.063031: __mutex_unlock_slowpath <-mutex_unlock
bash-1994 [002] .... 3082.063031: __fsnotify_parent <-fsnotify_modify
bash-1994 [002] .... 3082.063032: fsnotify <-fsnotify_modify
bash-1994 [002] .... 3082.063032: __srcu_read_lock <-fsnotify
bash-1994 [002] .... 3082.063032: add_preempt_count <-__srcu_read_lock
bash-1994 [002] ...1 3082.063032: sub_preempt_count <-__srcu_read_lock
bash-1994 [002] .... 3082.063033: __srcu_read_unlock <-fsnotify
[...]
注意：函式跟蹤器使用環形緩衝區來儲存以上條目。 最新資料可能會覆蓋最舊的資料。 有時使用echo停止跟蹤是不夠的，因為跟蹤可能已覆蓋您要記錄的資料。 因此，有時最好直接從程式中停用跟蹤。 這樣，您就可以在到達您感興趣的部分時停止跟蹤。 要直接從C程式中停用跟蹤，可以使用以下程式碼片段
int trace_fd;
[...]
int main(int argc, char *argv[]) {
[...]
trace_fd = open(tracing_file("tracing_on"), O_WRONLY);
[...]
if (condition_hit()) {
write(trace_fd, "0", 1);
}
[...]
}
單執行緒跟蹤¶
透過寫入set_ftrace_pid，您可以跟蹤單個執行緒。 例如
# cat set_ftrace_pid
no pid
# echo 3111 > set_ftrace_pid
# cat set_ftrace_pid
3111
# echo function > current_tracer
# cat trace | head
# tracer: function
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
yum-updatesd-3111 [003] 1637.254676: finish_task_switch <-thread_return
yum-updatesd-3111 [003] 1637.254681: hrtimer_cancel <-schedule_hrtimeout_range
yum-updatesd-3111 [003] 1637.254682: hrtimer_try_to_cancel <-hrtimer_cancel
yum-updatesd-3111 [003] 1637.254683: lock_hrtimer_base <-hrtimer_try_to_cancel
yum-updatesd-3111 [003] 1637.254685: fget_light <-do_sys_poll
yum-updatesd-3111 [003] 1637.254686: pipe_poll <-do_sys_poll
# echo > set_ftrace_pid
# cat trace |head
# tracer: function
#
# TASK-PID CPU# TIMESTAMP FUNCTION
# | | | | |
##### CPU 3 buffer started ####
yum-updatesd-3111 [003] 1701.957688: free_poll_entry <-poll_freewait
yum-updatesd-3111 [003] 1701.957689: remove_wait_queue <-free_poll_entry
yum-updatesd-3111 [003] 1701.957691: fput <-free_poll_entry
yum-updatesd-3111 [003] 1701.957692: audit_syscall_exit <-sysret_audit
yum-updatesd-3111 [003] 1701.957693: path_put <-audit_syscall_exit
如果要執行時跟蹤函式，可以使用如下所示的簡單程式。
#include <stdio.h>
#include <stdlib.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <unistd.h>
#include <string.h>
#define _STR(x) #x
#define STR(x) _STR(x)
#define MAX_PATH 256
const char *find_tracefs(void)
{
static char tracefs[MAX_PATH+1];
static int tracefs_found;
char type[100];
FILE *fp;
if (tracefs_found)
return tracefs;
if ((fp = fopen("/proc/mounts","r")) == NULL) {
perror("/proc/mounts");
return NULL;
}
while (fscanf(fp, "%*s %"
STR(MAX_PATH)
"s %99s %*s %*d %*d\n",
tracefs, type) == 2) {
if (strcmp(type, "tracefs") == 0)
break;
}
fclose(fp);
if (strcmp(type, "tracefs") != 0) {
fprintf(stderr, "tracefs not mounted");
return NULL;
}
strcat(tracefs, "/tracing/");
tracefs_found = 1;
return tracefs;
}
const char *tracing_file(const char *file_name)
{
static char trace_file[MAX_PATH+1];
snprintf(trace_file, MAX_PATH, "%s/%s", find_tracefs(), file_name);
return trace_file;
}
int main (int argc, char **argv)
{
if (argc < 1)
exit(-1);
if (fork() > 0) {
int fd, ffd;
char line[64];
int s;
ffd = open(tracing_file("current_tracer"), O_WRONLY);
if (ffd < 0)
exit(-1);
write(ffd, "nop", 3);
fd = open(tracing_file("set_ftrace_pid"), O_WRONLY);
s = sprintf(line, "%d\n", getpid());
write(fd, line, s);
write(ffd, "function", 8);
close(fd);
close(ffd);
execvp(argv[1], argv+1);
}
return 0;
}
或者這個簡單的指令碼！
#!/bin/bash
tracefs=`sed -ne 's/^tracefs \(.*\) tracefs.*/\1/p' /proc/mounts`
echo 0 > $tracefs/tracing_on
echo $$ > $tracefs/set_ftrace_pid
echo function > $tracefs/current_tracer
echo 1 > $tracefs/tracing_on
exec "$@"
函式圖跟蹤器¶
此跟蹤器與函式跟蹤器類似，不同之處在於它在其進入和退出時探測函式。 這是透過使用每個task_struct中動態分配的返回地址堆疊來完成的。 在函式條目上，跟蹤器將跟蹤的每個函式的返回地址覆蓋設定為自定義探測。 因此，原始返回地址儲存在task_struct中返回地址的堆疊上。
在函式的兩端進行探測會導致特殊功能，例如
測量函式的執行時間
具有可靠的呼叫堆疊以繪製函式呼叫圖
此跟蹤器在以下幾種情況下很有用
您想找到奇怪的核心行為的原因，並且需要詳細瞭解任何區域（或特定區域）中發生的情況。
您遇到奇怪的延遲，但很難找到其根源。
您想快速找到特定函式採用的路徑
您只是想窺視正在執行的核心，並想看看那裡發生了什麼。
# tracer: function_graph
#
# CPU DURATION FUNCTION CALLS
# | | | | | | |
0) | sys_open() {
0) | do_sys_open() {
0) | getname() {
0) | kmem_cache_alloc() {
0) 1.382 us | __might_sleep();
0) 2.478 us | }
0) | strncpy_from_user() {
0) | might_fault() {
0) 1.389 us | __might_sleep();
0) 2.553 us | }
0) 3.807 us | }
0) 7.876 us | }
0) | alloc_fd() {
0) 0.668 us | _spin_lock();
0) 0.570 us | expand_files();
0) 0.586 us | _spin_unlock();
有幾個可以動態啟用/停用的列。 您可以根據自己的需要使用所需的每種選項組合。
預設情況下，啟用執行該功能的CPU編號。 有時最好只跟蹤一個cpu（請參見tracing_cpumask檔案），或者在cpu跟蹤切換時有時可能會看到無序的函式呼叫。
hide: echo nofuncgraph-cpu > trace_options
show: echo funcgraph-cpu > trace_options
持續時間（函式的執行時間）顯示在函式的右括號行上，或者在葉函式的情況下，顯示在與當前函式相同的行上。 預設情況下啟用。
hide: echo nofuncgraph-duration > trace_options
show: echo funcgraph-duration > trace_options
如果達到持續時間閾值，則開銷欄位位於持續時間欄位之前。
hide: echo nofuncgraph-overhead > trace_options
show: echo funcgraph-overhead > trace_options
depends on: funcgraph-duration
例如
3) # 1837.709 us | } /* __switch_to */ 3) | finish_task_switch() { 3) 0.313 us | _raw_spin_unlock_irq(); 3) 3.177 us | } 3) # 1889.063 us | } /* __schedule */ 3) ! 140.417 us | } /* __schedule */ 3) # 2034.948 us | } /* schedule */ 3) * 33998.59 us | } /* schedule_preempt_disabled */ [...] 1) 0.260 us | msecs_to_jiffies(); 1) 0.313 us | __rcu_read_unlock(); 1) + 61.770 us | } 1) + 64.479 us | } 1) 0.313 us | rcu_bh_qs(); 1) 0.313 us | __local_bh_enable(); 1) ! 217.240 us | } 1) 0.365 us | idle_cpu(); 1) | rcu_irq_exit() { 1) 0.417 us | rcu_eqs_enter_common.isra.47(); 1) 3.125 us | } 1) ! 227.812 us | } 1) ! 457.395 us | } 1) @ 119760.2 us | } [...] 2) | handle_IPI() { 1) 6.979 us | } 2) 0.417 us | scheduler_ipi(); 1) 9.791 us | } 1) + 12.917 us | } 2) 3.490 us | } 1) + 15.729 us | } 1) + 18.542 us | } 2) $ 3594274 us | }
標誌
+ means that the function exceeded 10 usecs.
! means that the function exceeded 100 usecs.
# means that the function exceeded 1000 usecs.
* means that the function exceeded 10 msecs.
@ means that the function exceeded 100 msecs.
$ means that the function exceeded 1 sec.
task/pid欄位顯示執行該函式的執行緒cmdline和pid。 預設情況下停用。
hide: echo nofuncgraph-proc > trace_options
show: echo funcgraph-proc > trace_options
例如
# tracer: function_graph # # CPU TASK/PID DURATION FUNCTION CALLS # | | | | | | | | | 0) sh-4802 | | d_free() { 0) sh-4802 | | call_rcu() { 0) sh-4802 | | __call_rcu() { 0) sh-4802 | 0.616 us | rcu_process_gp_end(); 0) sh-4802 | 0.586 us | check_for_new_grace_period(); 0) sh-4802 | 2.899 us | } 0) sh-4802 | 4.040 us | } 0) sh-4802 | 5.151 us | } 0) sh-4802 | + 49.370 us | }絕對時間欄位是自系統啟動以來系統時鐘給出的絕對時間戳。 此時間的快照在函式的每個入口/出口上給出
hide: echo nofuncgraph-abstime > trace_options
show: echo funcgraph-abstime > trace_options
例如
# # TIME CPU DURATION FUNCTION CALLS # | | | | | | | | 360.774522 | 1) 0.541 us | } 360.774522 | 1) 4.663 us | } 360.774523 | 1) 0.541 us | __wake_up_bit(); 360.774524 | 1) 6.796 us | } 360.774524 | 1) 7.952 us | } 360.774525 | 1) 9.063 us | } 360.774525 | 1) 0.615 us | journal_mark_dirty(); 360.774527 | 1) 0.578 us | __brelse(); 360.774528 | 1) | reiserfs_prepare_for_journal() { 360.774528 | 1) | unlock_buffer() { 360.774529 | 1) | wake_up_bit() { 360.774529 | 1) | bit_waitqueue() { 360.774530 | 1) 0.594 us | __phys_addr();
如果該函式的開始不在跟蹤緩衝區中，則始終在該函式的右括號後顯示該函式名稱。
可以為開始在該跟蹤緩衝區中的函式啟用在右括號後顯示函式名稱，從而可以更輕鬆地使用grep搜尋函式持續時間。 預設情況下停用。
hide: echo nofuncgraph-tail > trace_options
show: echo funcgraph-tail > trace_options
不帶nofuncgraph-tail的示例（預設）
0) | putname() { 0) | kmem_cache_free() { 0) 0.518 us | __phys_addr(); 0) 1.757 us | } 0) 2.861 us | }帶funcgraph-tail的示例
0) | putname() { 0) | kmem_cache_free() { 0) 0.518 us | __phys_addr(); 0) 1.757 us | } /* kmem_cache_free() */ 0) 2.861 us | } /* putname() */
每個跟蹤函式的返回值都可以顯示在等號“=”之後。 遇到系統呼叫失敗時，它可以非常有助於快速找到首先返回錯誤程式碼的函式。
hide: echo nofuncgraph-retval > trace_options
show: echo funcgraph-retval > trace_options
帶funcgraph-retval的示例
1) | cgroup_migrate() { 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */ 1) | cgroup_migrate_execute() { 1) | cpu_cgroup_can_attach() { 1) | cgroup_taskset_first() { 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */ 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */ 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */ 1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */ 1) 4.369 us | } /* cgroup_migrate_execute = -22 */ 1) 7.143 us | } /* cgroup_migrate = -22 */
上面的示例顯示函式cpu_cgroup_can_attach首先返回錯誤程式碼-22，然後我們可以讀取此函式的程式碼以獲取根本原因。
當未設定選項funcgraph-retval-hex時，可以以一種智慧的方式顯示返回值。 具體來說，如果是錯誤程式碼，則將以帶符號的十進位制格式列印，否則將以十六進位制格式列印。
smart: echo nofuncgraph-retval-hex > trace_options
hexadecimal: echo funcgraph-retval-hex > trace_options
帶funcgraph-retval-hex的示例
1) | cgroup_migrate() { 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */ 1) | cgroup_migrate_execute() { 1) | cpu_cgroup_can_attach() { 1) | cgroup_taskset_first() { 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */ 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */ 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */ 1) 2.335 us | } /* cpu_cgroup_can_attach = 0xffffffea */ 1) 4.369 us | } /* cgroup_migrate_execute = 0xffffffea */ 1) 7.143 us | } /* cgroup_migrate = 0xffffffea */
目前，使用funcgraph-retval選項時存在一些限制，這些限制將在將來消除
即使函式返回型別為void，仍將列印返回值，您可以忽略它。
即使返回值儲存在多個暫存器中，也只會記錄和列印第一個暫存器中包含的值。 為了說明，在x86體系結構中，eax和edx用於儲存64位返回值，較低的32位儲存在eax中，較高的32位儲存在edx中。 但是，只會記錄和列印儲存在eax中的值。
在某些過程呼叫標準中，例如arm64的AAPCS64，當型別小於GPR時，由使用者負責執行縮小，並且高位可能包含UNKNOWN值。 因此，建議檢查程式碼中是否存在此類情況。 例如，當在64位GPR中使用u8時，位[63：8]可能包含任意值，尤其是當較大的型別被截斷時，無論是顯式還是隱式。 以下是一些具體示例來說明這一點
情況一:
函式narrow_to_u8定義如下
u8 narrow_to_u8(u64 val) { // implicitly truncated return val; }它可以編譯為
narrow_to_u8: < ... ftrace instrumentation ... > RET如果您將0x123456789abcdef傳遞給此函式並想要縮小它，則可能會將其記錄為0x123456789abcdef而不是0xef。
情況二:
函式error_if_not_4g_aligned定義如下
int error_if_not_4g_aligned(u64 val) { if (val & GENMASK(31, 0)) return -EINVAL; return 0; }它可以編譯為
error_if_not_4g_aligned: CBNZ w0, .Lnot_aligned RET // bits [31:0] are zero, bits // [63:32] are UNKNOWN .Lnot_aligned: MOV x0, #-EINVAL RET當傳遞0x2_0000_0000給它時，返回值可能被記錄為0x2_0000_0000而不是0。
您可以使用trace_printk()在特定函式上新增一些註釋。 例如，如果您想在__might_sleep()函式中添加註釋，則只需包含<linux/ftrace.h>並在__might_sleep()中呼叫trace_printk()
trace_printk("I'm a comment!\n")
將產生
1) | __might_sleep() {
1) | /* I'm a comment! */
1) 1.449 us | }
您可能會在以下“動態ftrace”部分中找到此跟蹤器的其他有用功能，例如僅跟蹤特定函式或任務。
動態ftrace¶
如果設定了CONFIG_DYNAMIC_FTRACE，則當停用函式跟蹤時，系統幾乎不會產生任何開銷。 這種工作方式是mcount函式呼叫（位於每個核心函式的開頭，由gcc中的-pg開關產生），從指向簡單返回開始。 （啟用FTRACE將在核心的編譯中包括-pg開關。）
在編譯時，每個C檔案物件都透過recordmcount程式（位於scripts目錄中）執行。 此程式將解析C物件中的ELF標頭，以查詢.text節中呼叫mcount的所有位置。 從gcc 4.6版開始，為x86添加了-mfentry，該版本呼叫“__fentry__”而不是“mcount”。 這在建立堆疊幀之前被呼叫。
請注意，並非所有節都被跟蹤。 它們可能會因notrace阻止，或以另一種方式阻止，並且所有行內函數都不會被跟蹤。 檢查“available_filter_functions”檔案以檢視可以跟蹤哪些函式。
建立一個名為“__mcount_loc”的節，該節儲存對.text節中所有mcount/fentry呼叫站點的引用。 recordmcount程式將此節重新連結回原始物件。 核心的最終連結階段會將所有這些引用新增到單個表中。
在啟動時，在SMP初始化之前，動態ftrace程式碼會掃描此表並將所有位置更新為nops。 它還記錄了這些位置，這些位置已新增到available_filter_functions列表中。 模組在載入時以及在執行之前進行處理。 解除安裝模組時，它還會從ftrace函式列表中刪除其函式。 這在模組解除安裝程式碼中是自動的，並且模組作者無需擔心它。
啟用跟蹤後，修改函式跟蹤點的過程取決於體系結構。 舊方法是使用kstop_machine來防止與正在修改的程式碼執行的CPU發生爭用（這可能導致CPU執行不希望的操作，尤其是在修改後的程式碼跨越快取（或頁面）邊界時），並且將nops補丁回撥用。 但是這次，它們不會呼叫mcount（這只是一個函式存根）。 現在，它們呼叫ftrace基礎結構。
修改函式跟蹤點的新方法是在要修改的位置放置一個斷點，同步所有CPU，修改未被斷點覆蓋的指令的其餘部分。 再次同步所有CPU，然後刪除斷點，並將完成的版本新增到ftrace呼叫站點。
某些arch甚至不需要使用同步來解決，並且可以簡單地將新程式碼拍到舊程式碼的頂部，而不會與其他CPU同時執行它發生任何問題。
記錄被跟蹤函式的特殊副作用是，我們現在可以選擇性地選擇我們要跟蹤哪些函式以及我們希望mcount呼叫保持為nops的函式。
使用了兩個檔案，一個用於啟用，一個用於停用指定函式的跟蹤。 它們是
set_ftrace_filter
和
set_ftrace_notrace
您可以新增到這些檔案的可用函式列表在
available_filter_functions
# cat available_filter_functions
put_prev_task_idle
kmem_cache_create
pick_next_task_rt
cpus_read_lock
pick_next_task_fair
mutex_lock
[...]
如果我只對sys_nanosleep和hrtimer_interrupt感興趣
# echo sys_nanosleep hrtimer_interrupt > set_ftrace_filter
# echo function > current_tracer
# echo 1 > tracing_on
# usleep 1
# echo 0 > tracing_on
# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 5/5 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
usleep-2665 [001] .... 4186.475355: sys_nanosleep <-system_call_fastpath
<idle>-0 [001] d.h1 4186.475409: hrtimer_interrupt <-smp_apic_timer_interrupt
usleep-2665 [001] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
<idle>-0 [003] d.h1 4186.475426: hrtimer_interrupt <-smp_apic_timer_interrupt
<idle>-0 [002] d.h1 4186.475427: hrtimer_interrupt <-smp_apic_timer_interrupt
要檢視正在跟蹤哪些函式，您可以cat檔案
# cat set_ftrace_filter
hrtimer_interrupt
sys_nanosleep
也許這還不夠。 過濾器還允許glob(7)匹配。
<match>*將匹配以<match>開頭的函式
*<match>將匹配以<match>結尾的函式
*<match>*將匹配具有<match>的函式
<match1>*<match2>將匹配以<match1>開頭並以<match2>結尾的函式
注意
最好使用引號將萬用字元括起來，否則shell可能會將引數擴充套件為本地目錄中的檔名。
# echo 'hrtimer_*' > set_ftrace_filter
產生
# tracer: function
#
# entries-in-buffer/entries-written: 897/897 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<idle>-0 [003] dN.1 4228.547803: hrtimer_cancel <-tick_nohz_idle_exit
<idle>-0 [003] dN.1 4228.547804: hrtimer_try_to_cancel <-hrtimer_cancel
<idle>-0 [003] dN.2 4228.547805: hrtimer_force_reprogram <-__remove_hrtimer
<idle>-0 [003] dN.1 4228.547805: hrtimer_forward <-tick_nohz_idle_exit
<idle>-0 [003] dN.1 4228.547805: hrtimer_start_range_ns <-hrtimer_start_expires.constprop.11
<idle>-0 [003] d..1 4228.547858: hrtimer_get_next_event <-get_next_timer_interrupt
<idle>-0 [003] d..1 4228.547859: hrtimer_start <-__tick_nohz_idle_enter
<idle>-0 [003] d..2 4228.547860: hrtimer_force_reprogram <-__rem
請注意，我們丟失了sys_nanosleep。
# cat set_ftrace_filter
hrtimer_run_queues
hrtimer_run_pending
hrtimer_setup
hrtimer_cancel
hrtimer_try_to_cancel
hrtimer_forward
hrtimer_start
hrtimer_reprogram
hrtimer_force_reprogram
hrtimer_get_next_event
hrtimer_interrupt
hrtimer_nanosleep
hrtimer_wakeup
hrtimer_get_remaining
hrtimer_get_res
hrtimer_init_sleeper
這是因為“>”和“>>”的作用與在bash中的作用完全相同。 要重寫過濾器，請使用“>”。 要附加到過濾器，請使用“>>”。
要清除過濾器，以便再次記錄所有函式
# echo > set_ftrace_filter
# cat set_ftrace_filter
#
同樣，現在我們要附加。
# echo sys_nanosleep > set_ftrace_filter
# cat set_ftrace_filter
sys_nanosleep
# echo 'hrtimer_*' >> set_ftrace_filter
# cat set_ftrace_filter
hrtimer_run_queues
hrtimer_run_pending
hrtimer_setup
hrtimer_cancel
hrtimer_try_to_cancel
hrtimer_forward
hrtimer_start
hrtimer_reprogram
hrtimer_force_reprogram
hrtimer_get_next_event
hrtimer_interrupt
sys_nanosleep
hrtimer_nanosleep
hrtimer_wakeup
hrtimer_get_remaining
hrtimer_get_res
hrtimer_init_sleeper
set_ftrace_notrace可防止這些函式被跟蹤。
# echo '*preempt*' '*lock*' > set_ftrace_notrace
產生
# tracer: function
#
# entries-in-buffer/entries-written: 39608/39608 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
bash-1994 [000] .... 4342.324896: file_ra_state_init <-do_dentry_open
bash-1994 [000] .... 4342.324897: open_check_o_direct <-do_last
bash-1994 [000] .... 4342.324897: ima_file_check <-do_last
bash-1994 [000] .... 4342.324898: process_measurement <-ima_file_check
bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement
bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action
bash-1994 [000] .... 4342.324899: do_truncate <-do_last
bash-1994 [000] .... 4342.324899: setattr_should_drop_suidgid <-do_truncate
bash-1994 [000] .... 4342.324899: notify_change <-do_truncate
bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change
bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time
bash-1994 [000] .... 4342.324900: timespec_trunc <-current_fs_time
我們可以看到不再有鎖或搶佔跟蹤。
透過索引選擇函式過濾器¶
由於字串的處理成本很高（在與傳入的字串進行比較之前，需要查詢函式的地址），因此也可以使用索引來啟用函式。這在一次設定數千個特定函式的情況下非常有用。透過傳入數字列表，不會發生字串處理。而是選擇內部陣列中特定位置的函式（該函式對應於“available_filter_functions”檔案中的函式）。
# echo 1 > set_ftrace_filter
將選擇“available_filter_functions”中列出的第一個函式
# head -1 available_filter_functions
trace_initcall_finish_cb
# cat set_ftrace_filter
trace_initcall_finish_cb
# head -50 available_filter_functions | tail -1
x86_pmu_commit_txn
# echo 1 50 > set_ftrace_filter
# cat set_ftrace_filter
trace_initcall_finish_cb
x86_pmu_commit_txn
帶函式圖跟蹤器的動態ftrace¶
雖然上面解釋的內容涉及函式跟蹤器和函式圖跟蹤器，但某些特殊功能僅在函式圖跟蹤器中可用。
如果您只想跟蹤一個函式及其所有子函式，只需將其名稱回顯到set_graph_function中
echo __do_fault > set_graph_function
將產生以下__do_fault()函式的“展開”跟蹤
0) | __do_fault() {
0) | filemap_fault() {
0) | find_lock_page() {
0) 0.804 us | find_get_page();
0) | __might_sleep() {
0) 1.329 us | }
0) 3.904 us | }
0) 4.979 us | }
0) 0.653 us | _spin_lock();
0) 0.578 us | page_add_file_rmap();
0) 0.525 us | native_set_pte_at();
0) 0.585 us | _spin_unlock();
0) | unlock_page() {
0) 0.541 us | page_waitqueue();
0) 0.639 us | __wake_up_bit();
0) 2.786 us | }
0) + 14.237 us | }
0) | __do_fault() {
0) | filemap_fault() {
0) | find_lock_page() {
0) 0.698 us | find_get_page();
0) | __might_sleep() {
0) 1.412 us | }
0) 3.950 us | }
0) 5.098 us | }
0) 0.631 us | _spin_lock();
0) 0.571 us | page_add_file_rmap();
0) 0.526 us | native_set_pte_at();
0) 0.586 us | _spin_unlock();
0) | unlock_page() {
0) 0.533 us | page_waitqueue();
0) 0.638 us | __wake_up_bit();
0) 2.793 us | }
0) + 14.012 us | }
您也可以一次展開多個函式
echo sys_open > set_graph_function
echo sys_close >> set_graph_function
現在，如果要返回以跟蹤所有函式，可以透過以下方式清除此特殊過濾器
echo > set_graph_function
ftrace_enabled¶
請注意，proc sysctl ftrace_enable是函式跟蹤器的一個大的開啟/關閉開關。 預設情況下，它是啟用的（當在核心中啟用函式跟蹤時）。 如果停用它，則所有函式跟蹤都將被停用。 這不僅包括ftrace的函式跟蹤器，還包括任何其他用途（perf，kprobes，堆疊跟蹤，分析等）。 如果註冊了具有FTRACE_OPS_FL_PERMANENT設定的回撥，則無法將其停用。
請謹慎停用此功能。
可以使用
sysctl kernel.ftrace_enabled=0
sysctl kernel.ftrace_enabled=1
or
echo 0 > /proc/sys/kernel/ftrace_enabled
echo 1 > /proc/sys/kernel/ftrace_enabled
過濾器命令¶
set_ftrace_filter介面支援一些命令。 跟蹤命令的格式如下
<function>:<command>:<parameter>
支援以下命令
mod: 此命令啟用每個模組的函式過濾。 引數定義模組。 例如，如果僅需要ext3模組中的write*函式，請執行
echo ‘write*:mod:ext3’ > set_ftrace_filter
此命令與過濾器互動的方式與基於函式名稱進行過濾的方式相同。 因此，透過附加（>>）到過濾器檔案來新增另一個模組中的更多函式。 透過在前面加上“！”來刪除特定的模組函式
echo '!writeback*:mod:ext3' >> set_ftrace_filter
Mod命令支援模組globbing。 停用除特定模組之外的所有功能的跟蹤
echo '!*:mod:!ext3' >> set_ftrace_filter
停用所有模組的跟蹤，但仍跟蹤核心
echo '!*:mod:*' >> set_ftrace_filter
僅為核心啟用過濾器
echo '*write*:mod:!*' >> set_ftrace_filter
為模組globbing啟用過濾器
echo '*write*:mod:*snd*' >> set_ftrace_filter
traceon/traceoff: 這些命令在指定的函式被命中時開啟和關閉跟蹤。 引數確定跟蹤系統開啟和關閉的次數。 如果未指定，則沒有限制。 例如，要在首次命中排程錯誤的前5次停用跟蹤，請執行
echo '__schedule_bug:traceoff:5' > set_ftrace_filter
始終在命中__schedule_bug時停用跟蹤
echo '__schedule_bug:traceoff' > set_ftrace_filter
這些命令是累積的，無論它們是否附加到set_ftrace_filter。 要刪除命令，請在其前面加上“！”並刪除引數
echo '!__schedule_bug:traceoff:0' > set_ftrace_filter
以上操作會刪除具有計數器的__schedule_bug的traceoff命令。 要刪除沒有計數器的命令
echo '!__schedule_bug:traceoff' > set_ftrace_filter
snapshot: 將在命中該函式時觸發快照。
echo 'native_flush_tlb_others:snapshot' > set_ftrace_filter
僅快照一次
echo 'native_flush_tlb_others:snapshot:1' > set_ftrace_filter
刪除以上命令
echo '!native_flush_tlb_others:snapshot' > set_ftrace_filter echo '!native_flush_tlb_others:snapshot:0' > set_ftrace_filter
enable_event/disable_event: 這些命令可以啟用或停用跟蹤事件。 請注意，由於函式跟蹤回撥非常敏感，因此在註冊這些命令時，跟蹤點將被啟用，但在“軟”模式下被停用。 也就是說，將呼叫跟蹤點，但只是不會被跟蹤。 只要有觸發它的命令，事件跟蹤點就會保持在此模式下。
echo 'try_to_wake_up:enable_event:sched:sched_switch:2' > \ set_ftrace_filter格式為
<function>:enable_event:<system>:<event>[:count] <function>:disable_event:<system>:<event>[:count]
刪除事件命令
echo '!try_to_wake_up:enable_event:sched:sched_switch:0' > \ set_ftrace_filter echo '!schedule:disable_event:sched:sched_switch' > \ set_ftrace_filterdump: 命中函式時，它會將ftrace環形緩衝區的內容轉儲到控制檯。 如果您需要除錯某些內容，並且希望在命中某個函式時轉儲跟蹤，這將非常有用。 也許它是在發生三重故障之前呼叫的函式，並且不允許您獲得常規轉儲。
cpudump: 命中該函式時，它會將當前CPU的ftrace環形緩衝區的內容轉儲到控制檯。 與“dump”命令不同，它僅打印出執行觸發轉儲的函式的CPU的環形緩衝區的內容。
stacktrace: 命中該函式時，將記錄堆疊跟蹤。
trace_pipe¶
trace_pipe輸出與trace檔案相同的內容，但是對跟蹤的影響不同。 從trace_pipe的每次讀取都會被消耗掉。 這意味著後續的讀取將不同。 跟蹤是即時的。
# echo function > current_tracer
# cat trace_pipe > /tmp/trace.out &
[1] 4153
# echo 1 > tracing_on
# usleep 1
# echo 0 > tracing_on
# cat trace
# tracer: function
#
# entries-in-buffer/entries-written: 0/0 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
#
# cat /tmp/trace.out
bash-1994 [000] .... 5281.568961: mutex_unlock <-rb_simple_write
bash-1994 [000] .... 5281.568963: __mutex_unlock_slowpath <-mutex_unlock
bash-1994 [000] .... 5281.568963: __fsnotify_parent <-fsnotify_modify
bash-1994 [000] .... 5281.568964: fsnotify <-fsnotify_modify
bash-1994 [000] .... 5281.568964: __srcu_read_lock <-fsnotify
bash-1994 [000] .... 5281.568964: add_preempt_count <-__srcu_read_lock
bash-1994 [000] ...1 5281.568965: sub_preempt_count <-__srcu_read_lock
bash-1994 [000] .... 5281.568965: __srcu_read_unlock <-fsnotify
bash-1994 [000] .... 5281.568967: sys_dup2 <-system_call_fastpath
請注意，讀取trace_pipe檔案將阻塞，直到新增更多輸入。 這與trace檔案相反。 如果任何程序打開了trace檔案進行讀取，它實際上將停用跟蹤並阻止新增新條目。 trace_pipe檔案沒有此限制。
跟蹤條目¶
資料過多或不足在診斷核心中的問題時可能會很麻煩。 檔案buffer_size_kb用於修改內部跟蹤緩衝區的大小。 列出的數字是每個CPU可以記錄的條目數。 要知道完整大小，請將可能的CPU數量乘以條目數量。
# cat buffer_size_kb
1408 (units kilobytes)
或者只是讀取buffer_total_size_kb
# cat buffer_total_size_kb
5632
要修改緩衝區，只需回顯一個數字（以1024位元組為單位）。
# echo 10000 > buffer_size_kb
# cat buffer_size_kb
10000 (units kilobytes)
它將嘗試分配儘可能多的空間。 如果分配過多，可能會導致觸發記憶體不足。
# echo 1000000000000 > buffer_size_kb
-bash: echo: write error: Cannot allocate memory
# cat buffer_size_kb
85
也可以單獨更改每個cpu緩衝區
# echo 10000 > per_cpu/cpu0/buffer_size_kb
# echo 100 > per_cpu/cpu1/buffer_size_kb
當每個cpu緩衝區不相同時，頂層的buffer_size_kb將僅顯示X
# cat buffer_size_kb
X
這是buffer_total_size_kb有用的地方
# cat buffer_total_size_kb
12916
寫入頂層buffer_size_kb將再次將所有緩衝區重置為相同。
快照¶
CONFIG_TRACER_SNAPSHOT使所有非延遲跟蹤器都可以使用通用的快照功能。 （記錄最大延遲的延遲跟蹤器，例如“irqsoff”或“wakeup”，不能使用此功能，因為這些跟蹤器已經在內部使用快照機制。）
快照在特定時間點保留當前跟蹤緩衝區，而無需停止跟蹤。 Ftrace將當前緩衝區與備用緩衝區交換，並且跟蹤在新的當前（=先前的備用）緩衝區中繼續。
“tracing”中的以下tracefs檔案與此功能有關
snapshot
這用於拍攝快照並讀取快照的輸出。 將1回顯到此檔案中以分配備用緩衝區並拍攝快照（交換），然後從該檔案中以與“trace”相同的格式讀取快照（如上面的“檔案系統”部分所述）。 讀取快照和跟蹤都可以並行執行。 分配備用緩衝區後，回顯0會釋放它，而回顯其他（正）值會清除快照內容。 下表中顯示了更多詳細資訊。
狀態\輸入
0
1
其他
未分配
（不執行任何操作）
分配+交換
（不執行任何操作）
已分配
釋放
交換
清除
這是使用快照功能的示例。
# echo 1 > events/sched/enable
# echo 1 > snapshot
# cat snapshot
# tracer: nop
#
# entries-in-buffer/entries-written: 71/71 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<idle>-0 [005] d... 2440.603828: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2242 next_prio=120
sleep-2242 [005] d... 2440.603846: sched_switch: prev_comm=snapshot-test-2 prev_pid=2242 prev_prio=120 prev_state=R ==> next_comm=kworker/5:1 next_pid=60 next_prio=120
[...]
<idle>-0 [002] d... 2440.707230: sched_switch: prev_comm=swapper/2 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2229 next_prio=120
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 77/77 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
<idle>-0 [007] d... 2440.707395: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=snapshot-test-2 next_pid=2243 next_prio=120
snapshot-test-2-2229 [002] d... 2440.707438: sched_switch: prev_comm=snapshot-test-2 prev_pid=2229 prev_prio=120 prev_state=S ==> next_comm=swapper/2 next_pid=0 next_prio=120
[...]
如果您嘗試在當前跟蹤器是延遲跟蹤器之一時使用此快照功能，您將獲得以下結果。
# echo wakeup > current_tracer
# echo 1 > snapshot
bash: echo: write error: Device or resource busy
# cat snapshot
cat: snapshot: Device or resource busy
例項¶
在tracefs跟蹤目錄中，有一個名為“instances”的目錄。 可以使用mkdir在該目錄內部建立新目錄，並使用rmdir刪除目錄。 在此目錄中使用mkdir建立的目錄在建立後已經包含檔案和其他目錄。
# mkdir instances/foo
# ls instances/foo
buffer_size_kb buffer_total_size_kb events free_buffer per_cpu
set_event snapshot trace trace_clock trace_marker trace_options
trace_pipe tracing_on
如您所見，新目錄看起來與跟蹤目錄本身相似。 實際上，它非常相似，不同之處在於緩衝區和事件與主目錄或建立的任何其他例項無關。
新目錄中的檔案的工作方式與跟蹤目錄中具有相同名稱的檔案的工作方式相同，只是使用的緩衝區是單獨的新緩衝區。 這些檔案會影響該緩衝區，但不會影響主緩衝區，但trace_options除外。 目前，trace_options會以相同的方式影響所有例項和頂級緩衝區，但這在將來的版本中可能會發生變化。 也就是說，選項可能會變得特定於它們所在的例項。
請注意，函式跟蹤器檔案都不在那裡，current_tracer和available_tracers也不在那裡。 這是因為緩衝區當前只能為它們啟用事件。
# mkdir instances/foo
# mkdir instances/bar
# mkdir instances/zoot
# echo 100000 > buffer_size_kb
# echo 1000 > instances/foo/buffer_size_kb
# echo 5000 > instances/bar/per_cpu/cpu1/buffer_size_kb
# echo function > current_trace
# echo 1 > instances/foo/events/sched/sched_wakeup/enable
# echo 1 > instances/foo/events/sched/sched_wakeup_new/enable
# echo 1 > instances/foo/events/sched/sched_switch/enable
# echo 1 > instances/bar/events/irq/enable
# echo 1 > instances/zoot/events/syscalls/enable
# cat trace_pipe
CPU:2 [LOST 11745 EVENTS]
bash-2044 [002] .... 10594.481032: _raw_spin_lock_irqsave <-get_page_from_freelist
bash-2044 [002] d... 10594.481032: add_preempt_count <-_raw_spin_lock_irqsave
bash-2044 [002] d..1 10594.481032: __rmqueue <-get_page_from_freelist
bash-2044 [002] d..1 10594.481033: _raw_spin_unlock <-get_page_from_freelist
bash-2044 [002] d..1 10594.481033: sub_preempt_count <-_raw_spin_unlock
bash-2044 [002] d... 10594.481033: get_pageblock_flags_group <-get_pageblock_migratetype
bash-2044 [002] d... 10594.481034: __mod_zone_page_state <-get_page_from_freelist
bash-2044 [002] d... 10594.481034: zone_statistics <-get_page_from_freelist
bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
bash-2044 [002] d... 10594.481034: __inc_zone_state <-zone_statistics
bash-2044 [002] .... 10594.481035: arch_dup_task_struct <-copy_process
[...]
# cat instances/foo/trace_pipe
bash-1998 [000] d..4 136.676759: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000
bash-1998 [000] dN.4 136.676760: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000
<idle>-0 [003] d.h3 136.676906: sched_wakeup: comm=rcu_preempt pid=9 prio=120 success=1 target_cpu=003
<idle>-0 [003] d..3 136.676909: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=rcu_preempt next_pid=9 next_prio=120
rcu_preempt-9 [003] d..3 136.676916: sched_switch: prev_comm=rcu_preempt prev_pid=9 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120
bash-1998 [000] d..4 136.677014: sched_wakeup: comm=kworker/0:1 pid=59 prio=120 success=1 target_cpu=000
bash-1998 [000] dN.4 136.677016: sched_wakeup: comm=bash pid=1998 prio=120 success=1 target_cpu=000
bash-1998 [000] d..3 136.677018: sched_switch: prev_comm=bash prev_pid=1998 prev_prio=120 prev_state=R+ ==> next_comm=kworker/0:1 next_pid=59 next_prio=120
kworker/0:1-59 [000] d..4 136.677022: sched_wakeup: comm=sshd pid=1995 prio=120 success=1 target_cpu=001
kworker/0:1-59 [000] d..3 136.677025: sched_switch: prev_comm=kworker/0:1 prev_pid=59 prev_prio=120 prev_state=S ==> next_comm=bash next_pid=1998 next_prio=120
[...]
# cat instances/bar/trace_pipe
migration/1-14 [001] d.h3 138.732674: softirq_raise: vec=3 [action=NET_RX]
<idle>-0 [001] dNh3 138.732725: softirq_raise: vec=3 [action=NET_RX]
bash-1998 [000] d.h1 138.733101: softirq_raise: vec=1 [action=TIMER]
bash-1998 [000] d.h1 138.733102: softirq_raise: vec=9 [action=RCU]
bash-1998 [000] ..s2 138.733105: softirq_entry: vec=1 [action=TIMER]
bash-1998 [000] ..s2 138.733106: softirq_exit: vec=1 [action=TIMER]
bash-1998 [000] ..s2 138.733106: softirq_entry: vec=9 [action=RCU]
bash-1998 [000] ..s2 138.733109: softirq_exit: vec=9 [action=RCU]
sshd-1995 [001] d.h1 138.733278: irq_handler_entry: irq=21 name=uhci_hcd:usb4
sshd-1995 [001] d.h1 138.733280: irq_handler_exit: irq=21 ret=unhandled
sshd-1995 [001] d.h1 138.733281: irq_handler_entry: irq=21 name=eth0
sshd-1995 [001] d.h1 138.733283: irq_handler_exit: irq=21 ret=handled
[...]
# cat instances/zoot/trace
# tracer: nop
#
# entries-in-buffer/entries-written: 18996/18996 #P:4
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
bash-1998 [000] d... 140.733501: sys_write -> 0x2
bash-1998 [000] d... 140.733504: sys_dup2(oldfd: a, newfd: 1)
bash-1998 [000] d... 140.733506: sys_dup2 -> 0x1
bash-1998 [000] d... 140.733508: sys_fcntl(fd: a, cmd: 1, arg: 0)
bash-1998 [000] d... 140.733509: sys_fcntl -> 0x1
bash-1998 [000] d... 140.733510: sys_close(fd: a)
bash-1998 [000] d... 140.733510: sys_close -> 0x0
bash-1998 [000] d... 140.733514: sys_rt_sigprocmask(how: 0, nset: 0, oset: 6e2768, sigsetsize: 8)
bash-1998 [000] d... 140.733515: sys_rt_sigprocmask -> 0x0
bash-1998 [000] d... 140.733516: sys_rt_sigaction(sig: 2, act: 7fff718846f0, oact: 7fff71884650, sigsetsize: 8)
bash-1998 [000] d... 140.733516: sys_rt_sigaction -> 0x0
您可以看到，最頂層跟蹤緩衝區的跟蹤僅顯示函式跟蹤。 foo例項顯示喚醒和任務切換。
要刪除例項，只需刪除它們的目錄
# rmdir instances/foo
# rmdir instances/bar
# rmdir instances/zoot
請注意，如果程序在其中一個例項目錄中打開了跟蹤檔案，則rmdir將失敗並顯示EBUSY。
堆疊跟蹤¶
由於核心具有固定大小的堆疊，因此重要的是不要在函式中浪費它。 核心開發人員必須瞭解他們在堆疊上分配的內容。 如果他們新增太多內容，則系統可能會面臨堆疊溢位的危險，並且會發生損壞，通常會導致系統崩潰。
有一些工具可以檢查此問題，通常使用中斷定期檢查使用情況。 但是，如果您可以在每次函式呼叫時執行檢查，那將非常有用。 由於ftrace提供了函式跟蹤器，因此可以方便地在每次函式呼叫時檢查堆疊大小。 這可以透過堆疊跟蹤器啟用。
CONFIG_STACK_TRACER啟用ftrace堆疊跟蹤功能。 要啟用它，請將“1”寫入/proc/sys/kernel/stack_tracer_enabled。
# echo 1 > /proc/sys/kernel/stack_tracer_enabled
您也可以從核心命令列啟用它，以在啟動期間跟蹤核心的堆疊大小，方法是將“stacktrace”新增到核心命令列引數中。
執行幾分鐘後，輸出如下所示
# cat stack_max_size
2928
# cat stack_trace
Depth Size Location (18 entries)
----- ---- --------
0) 2928 224 update_sd_lb_stats+0xbc/0x4ac
1) 2704 160 find_busiest_group+0x31/0x1f1
2) 2544 256 load_balance+0xd9/0x662
3) 2288 80 idle_balance+0xbb/0x130
4) 2208 128 __schedule+0x26e/0x5b9
5) 2080 16 schedule+0x64/0x66
6) 2064 128 schedule_timeout+0x34/0xe0
7) 1936 112 wait_for_common+0x97/0xf1
8) 1824 16 wait_for_completion+0x1d/0x1f
9) 1808 128 flush_work+0xfe/0x119
10) 1680 16 tty_flush_to_ldisc+0x1e/0x20
11) 1664 48 input_available_p+0x1d/0x5c
12) 1616 48 n_tty_poll+0x6d/0x134
13) 1568 64 tty_poll+0x64/0x7f
14) 1504 880 do_select+0x31e/0x511
15) 624 400 core_sys_select+0x177/0x216
16) 224 96 sys_select+0x91/0xb9
17) 128 128 system_call_fastpath+0x16/0x1b
請注意，如果gcc正在使用-mfentry，則會在函式設定堆疊幀之前對其進行跟蹤。 這意味著當使用-mfentry時，葉級函式不會被堆疊跟蹤器測試。
當前，僅x86上的gcc 4.6.0及更高版本使用-mfentry。
更多¶
更多詳細資訊可以在原始碼中的kernel/trace/*.c檔案中找到。