事件直方圖¶
Tom Zanussi 編寫的文件
1. 簡介¶
直方圖觸發器是一種特殊的事件觸發器，可用於將追蹤事件資料聚合到直方圖中。有關追蹤事件和事件觸發器的資訊，請參閱事件追蹤。
2. 直方圖觸發器命令¶
直方圖觸發器命令是一種事件觸發器命令，它將事件命中聚合到一個雜湊表中，該雜湊表以一個或多個追蹤事件格式欄位（或堆疊跟蹤）以及一組從一個或多個追蹤事件格式欄位和/或事件計數（命中計數）派生的執行總計為鍵。
hist 觸發器的格式如下
hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>] [:sort=<field1[,field2,...]>][:size=#entries][:pause][:continue] [:clear][:name=histname1][:nohitcount][:<handler>.<action>] [if <filter>]當命中匹配事件時，將使用命名的鍵和值將條目新增到雜湊表中。鍵和值對應於事件格式描述中的欄位。值必須對應於數值欄位 - 在事件命中時，值將新增到為該欄位保留的總和中。特殊字串“hitcount”可以代替顯式值欄位使用 - 這只是事件命中的計數。如果未指定“values”，則會自動建立並使用隱式“hitcount”值作為唯一值。鍵可以是任何欄位，也可以是特殊字串“common_stacktrace”，它將使用事件的核心堆疊跟蹤作為鍵。可以使用關鍵字“keys”或“key”來指定鍵，可以使用關鍵字“values”、“vals”或“val”來指定值。可以使用“keys”關鍵字指定最多包含三個欄位的複合鍵。雜湊複合鍵會在表中為每個元件鍵的唯一組合生成一個唯一的條目，並且可用於提供更細粒度的事件資料摘要。此外，最多包含兩個欄位的排序鍵可以使用“sort”關鍵字指定。如果指定了多個欄位，則結果將是“在排序中排序”：第一個鍵被視為主排序鍵，第二個鍵被視為輔助鍵。如果使用“name”引數為 hist 觸發器命名，則其直方圖資料將與其他具有相同名稱的觸發器共享，並且觸發器命中將更新此公共資料。只有具有“相容”欄位的觸發器才能以這種方式組合；如果觸發器中命名的欄位共享相同數量和型別的欄位，並且這些欄位也具有相同的名稱，則觸發器是“相容的”。請注意，任何兩個事件始終共享相容的“hitcount”和“common_stacktrace”欄位，因此可以使用這些欄位進行組合，無論這可能多麼毫無意義。
“hist”觸發器會將“hist”檔案新增到每個事件的子目錄中。讀取事件的“hist”檔案會將整個雜湊錶轉儲到 stdout。如果一個事件附加了多個 hist 觸發器，則輸出中將為每個觸發器提供一個表。為命名觸發器顯示的表將與任何其他具有相同名稱的例項相同。每個列印的雜湊表條目都是組成該條目的鍵和值的簡單列表；鍵首先列印，並用花括號分隔，後跟該條目的值欄位集。預設情況下，數值欄位顯示為十進位制整數。可以透過將以下任何修飾符附加到欄位名稱來修改此設定
.hex
將數字顯示為十六進位制值
.sym
將地址顯示為符號
.sym-offset
將地址顯示為符號和偏移量
.syscall
將 syscall id 顯示為系統呼叫名稱
.execname
將 common_pid 顯示為程式名稱
.log2
顯示 log2 值而不是原始數字
.buckets=size
顯示值的分組而不是原始數字
.usecs
以微秒為單位顯示 common_timestamp
.percent
將數字顯示為百分比值
.graph
顯示值的條形圖
.stacktrace
顯示為堆疊跟蹤（必須是 long[] 型別）
請注意，通常在將修飾符應用於給定欄位時，不會解釋該欄位的語義，但在此方面需要注意一些限制
只有“hex”修飾符可用於值（因為值本質上是總和，而其他修飾符在這種上下文中沒有意義）。
“execname”修飾符只能在“common_pid”上使用。原因是 execname 只是在觸發事件時為“當前”程序儲存的“comm”值，這與事件跟蹤程式碼儲存的 common_pid 值相同。嘗試將該 comm 值應用於其他 pid 值是不正確的，並且通常關注的事件會在事件本身中儲存特定於 pid 的 comm 欄位。
典型的使用場景是啟用 hist 觸發器，讀取其當前內容，然後將其關閉，如下所示
# echo 'hist:keys=skbaddr.hex:vals=len' > \ /sys/kernel/tracing/events/net/netif_rx/trigger # cat /sys/kernel/tracing/events/net/netif_rx/hist # echo '!hist:keys=skbaddr.hex:vals=len' > \ /sys/kernel/tracing/events/net/netif_rx/trigger可以讀取觸發器檔案本身以顯示當前附加的 hist 觸發器的詳細資訊。此資訊也會在讀取“hist”檔案時顯示在頂部。
預設情況下，雜湊表的大小為 2048 個條目。“size”引數可用於指定更多或更少。單位以雜湊表條目表示 - 如果執行使用的條目多於指定的條目，則結果將顯示“drops”的數量，即忽略的命中次數。該大小應為 128 到 131072 之間的 2 的冪（指定的任何非 2 的冪的數字都將向上舍入）。
“sort”引數可用於指定要排序的值欄位。如果未指定，則預設為“hitcount”，預設排序順序為“ascending”。要按相反方向排序，請將“.descending”附加到排序鍵。
“pause”引數可用於暫停現有的 hist 觸發器，或啟動 hist 觸發器，但在被告知之前不記錄任何事件。“continue”或“cont”可用於啟動或重新啟動暫停的 hist 觸發器。
“clear”引數將清除正在執行的 hist 觸發器的內容，並保持其當前的暫停/活動狀態。
請注意，“pause”、“cont”和“clear”引數應使用“append”shell 運算子（“>>”）應用於現有觸發器，而不是透過“>”運算子，這將導致觸發器透過截斷被刪除。
“nohitcount”（或 NOHC）引數將禁止在直方圖中顯示原始命中計數。此選項需要至少一個非“原始命中計數”的值欄位。例如，“hist:…:vals=hitcount:nohitcount”被拒絕，但“hist:…:vals=hitcount.percent:nohitcount”是可以的。
enable_hist/disable_hist
enable_hist 和 disable_hist 觸發器可用於使一個事件有條件地啟動和停止另一個事件的已附加的 hist 觸發器。可以將任意數量的 enable_hist 和 disable_hist 觸發器附加到給定事件，從而允許該事件啟動和停止主機上其他事件的聚合。
格式與 enable/disable_event 觸發器非常相似
enable_hist:<system>:<event>[:count] disable_hist:<system>:<event>[:count]
與 enable/disable_event 觸發器一樣，enable/disable_hist 觸發器不會將目標事件的跟蹤啟用或停用到跟蹤緩衝區中，而是啟用或停用目標事件到雜湊表中的聚合。
enable_hist/disable_hist 觸發器的典型使用場景是首先在某個事件上設定一個暫停的 hist 觸發器，然後使用一個 enable_hist/disable_hist 對，當命中感興趣的條件時開啟和關閉 hist 聚合
# echo 'hist:keys=skbaddr.hex:vals=len:pause' > \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ /sys/kernel/tracing/events/sched/sched_process_exec/trigger # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ /sys/kernel/tracing/events/sched/sched_process_exit/trigger
上面的設定首先設定了一個最初暫停的 hist 觸發器，當執行給定的程式時，該觸發器被取消暫停並開始聚合事件，當程序退出並且 hist 觸發器再次暫停時，該觸發器停止聚合。
下面的示例提供了對上述討論的概念和典型使用模式的更具體的說明。
“特殊”事件欄位¶
有許多“特殊事件欄位”可用於 hist 觸發器中的鍵或值。這些看起來像實際的事件欄位並以相同的方式執行，但實際上並不是事件欄位定義或格式檔案的一部分。但是，它們可用於任何事件，並且可以在實際事件欄位可以使用的任何地方使用。它們是
common_timestamp
u64
與事件關聯的時間戳（來自環形緩衝區），以納秒為單位。可以由 .usecs 修改為將時間戳解釋為微秒。
common_cpu
int
事件發生的 cpu。
擴充套件錯誤資訊¶
對於呼叫 hist 觸發器命令時遇到的一些錯誤情況，可以透過 tracing/error_log 檔案獲得擴充套件錯誤資訊。有關詳細資訊，請參閱
Documentation/trace/ftrace.rst中的錯誤情況。
6.2 “hist”觸發器示例¶
第一組示例使用 kmalloc 事件建立聚合。可用於 hist 觸發器的欄位在 kmalloc 事件的格式檔案中列出
# cat /sys/kernel/tracing/events/kmem/kmalloc/format name: kmalloc ID: 374 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:unsigned long call_site; offset:8; size:8; signed:0; field:const void * ptr; offset:16; size:8; signed:0; field:size_t bytes_req; offset:24; size:8; signed:0; field:size_t bytes_alloc; offset:32; size:8; signed:0; field:gfp_t gfp_flags; offset:40; size:4; signed:0;我們將首先建立一個 hist 觸發器，該觸發器生成一個簡單的表，其中列出了核心中一個或多個呼叫 kmalloc 的每個函式請求的總位元組數
# echo 'hist:key=call_site:val=bytes_req.buckets=32' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger這告訴跟蹤系統使用 kmalloc 事件的 call_site 欄位作為表的鍵建立一個“hist”觸發器，這僅意味著每個唯一的 call_site 地址都會在該表中建立一個條目。“val=bytes_req”引數告訴 hist 觸發器，對於表中的每個唯一條目 (call_site)，它應該保留該 call_site 請求的位元組數的執行總計。
我們讓它執行一段時間，然後轉儲 kmalloc 事件子目錄中“hist”檔案的內容（為了便於閱讀，已省略了許多條目）
# cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active] { call_site: 18446744072106379007 } hitcount: 1 bytes_req: 176 { call_site: 18446744071579557049 } hitcount: 1 bytes_req: 1024 { call_site: 18446744071580608289 } hitcount: 1 bytes_req: 16384 { call_site: 18446744071581827654 } hitcount: 1 bytes_req: 24 { call_site: 18446744071580700980 } hitcount: 1 bytes_req: 8 { call_site: 18446744071579359876 } hitcount: 1 bytes_req: 152 { call_site: 18446744071580795365 } hitcount: 3 bytes_req: 144 { call_site: 18446744071581303129 } hitcount: 3 bytes_req: 144 { call_site: 18446744071580713234 } hitcount: 4 bytes_req: 2560 { call_site: 18446744071580933750 } hitcount: 4 bytes_req: 736 . . . { call_site: 18446744072106047046 } hitcount: 69 bytes_req: 5576 { call_site: 18446744071582116407 } hitcount: 73 bytes_req: 2336 { call_site: 18446744072106054684 } hitcount: 136 bytes_req: 140504 { call_site: 18446744072106224230 } hitcount: 136 bytes_req: 19584 { call_site: 18446744072106078074 } hitcount: 153 bytes_req: 2448 { call_site: 18446744072106062406 } hitcount: 153 bytes_req: 36720 { call_site: 18446744071582507929 } hitcount: 153 bytes_req: 37088 { call_site: 18446744072102520590 } hitcount: 273 bytes_req: 10920 { call_site: 18446744071582143559 } hitcount: 358 bytes_req: 716 { call_site: 18446744072106465852 } hitcount: 417 bytes_req: 56712 { call_site: 18446744072102523378 } hitcount: 485 bytes_req: 27160 { call_site: 18446744072099568646 } hitcount: 1676 bytes_req: 33520 Totals: Hits: 4610 Entries: 45 Dropped: 0輸出為每個條目顯示一行，從觸發器中指定的鍵開始，後跟觸發器中還指定的值。輸出的開頭是一行，用於顯示觸發器資訊，也可以透過讀取“trigger”檔案來顯示觸發器資訊
# cat /sys/kernel/tracing/events/kmem/kmalloc/trigger hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]輸出的末尾是幾行，顯示了執行的總計。“Hits”欄位顯示事件觸發器命中的總次數，“Entries”欄位顯示雜湊表中使用的條目總數，“Dropped”欄位顯示由於執行中使用的條目數超過了表允許的最大條目數而丟棄的命中次數（通常為 0，但如果沒有提示，您可能想要使用“size”引數來增加表的大小）。
請注意，在上面的輸出中，有一個額外的欄位“hitcount”，該欄位未在觸發器中指定。另請注意，在觸發器資訊輸出中，有一個引數“sort=hitcount”，該引數也未在觸發器中指定。原因是每個觸發器都隱式地保留一個歸因於給定條目的總命中次數的計數，稱為“hitcount”。該命中計數資訊在輸出中顯式顯示，並且在沒有使用者指定的排序引數的情況下，將用作預設排序欄位。
如果您實際上不需要對任何特定欄位求和，而主要對命中頻率感興趣，則可以使用值“hitcount”代替“values”引數中的顯式值。
要關閉 hist 觸發器，只需呼叫命令歷史記錄中的觸發器並使用“!”字首重新執行它
# echo '!hist:key=call_site:val=bytes_req' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger最後，請注意，上面輸出中顯示的 call_site 實際上不是很有用。它是一個地址，但通常地址以十六進位制顯示。要使數值欄位顯示為十六進位制值，只需在觸發器中將“.hex”附加到欄位名稱
# echo 'hist:key=call_site.hex:val=bytes_req' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger # cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=call_site.hex:vals=bytes_req:sort=hitcount:size=2048 [active] { call_site: ffffffffa026b291 } hitcount: 1 bytes_req: 433 { call_site: ffffffffa07186ff } hitcount: 1 bytes_req: 176 { call_site: ffffffff811ae721 } hitcount: 1 bytes_req: 16384 { call_site: ffffffff811c5134 } hitcount: 1 bytes_req: 8 { call_site: ffffffffa04a9ebb } hitcount: 1 bytes_req: 511 { call_site: ffffffff8122e0a6 } hitcount: 1 bytes_req: 12 { call_site: ffffffff8107da84 } hitcount: 1 bytes_req: 152 { call_site: ffffffff812d8246 } hitcount: 1 bytes_req: 24 { call_site: ffffffff811dc1e5 } hitcount: 3 bytes_req: 144 { call_site: ffffffffa02515e8 } hitcount: 3 bytes_req: 648 { call_site: ffffffff81258159 } hitcount: 3 bytes_req: 144 { call_site: ffffffff811c80f4 } hitcount: 4 bytes_req: 544 . . . { call_site: ffffffffa06c7646 } hitcount: 106 bytes_req: 8024 { call_site: ffffffffa06cb246 } hitcount: 132 bytes_req: 31680 { call_site: ffffffffa06cef7a } hitcount: 132 bytes_req: 2112 { call_site: ffffffff8137e399 } hitcount: 132 bytes_req: 23232 { call_site: ffffffffa06c941c } hitcount: 185 bytes_req: 171360 { call_site: ffffffffa06f2a66 } hitcount: 185 bytes_req: 26640 { call_site: ffffffffa036a70e } hitcount: 265 bytes_req: 10600 { call_site: ffffffff81325447 } hitcount: 292 bytes_req: 584 { call_site: ffffffffa072da3c } hitcount: 446 bytes_req: 60656 { call_site: ffffffffa036b1f2 } hitcount: 526 bytes_req: 29456 { call_site: ffffffffa0099c06 } hitcount: 1780 bytes_req: 35600 Totals: Hits: 4775 Entries: 46 Dropped: 0即使這樣也只是稍微有用一些 - 雖然十六進位制值看起來更像地址，但使用者通常更感興趣的是文字地址對應的符號。要使地址顯示為符號值，只需將“.sym”或“.sym-offset”附加到觸發器中的欄位名稱
# echo 'hist:key=call_site.sym:val=bytes_req' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger # cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=hitcount:size=2048 [active] { call_site: [ffffffff810adcb9] syslog_print_all } hitcount: 1 bytes_req: 1024 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 { call_site: [ffffffff8154acbe] usb_alloc_urb } hitcount: 1 bytes_req: 192 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40 { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 { call_site: [ffffffff811febd5] fsnotify_alloc_group } hitcount: 2 bytes_req: 528 { call_site: [ffffffff81440f58] __tty_buffer_request_room } hitcount: 2 bytes_req: 2624 { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 2 bytes_req: 96 { call_site: [ffffffffa05e19af] ieee80211_start_tx_ba_session [mac80211] } hitcount: 2 bytes_req: 464 { call_site: [ffffffff81672406] tcp_get_metrics } hitcount: 2 bytes_req: 304 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 { call_site: [ffffffff81089b05] sched_create_group } hitcount: 2 bytes_req: 1424 . . . { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1185 bytes_req: 123240 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 1185 bytes_req: 104280 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 1402 bytes_req: 190672 { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 1518 bytes_req: 146208 { call_site: [ffffffffa029070e] drm_vma_node_allow [drm] } hitcount: 1746 bytes_req: 69840 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 2021 bytes_req: 792312 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 2592 bytes_req: 145152 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2629 bytes_req: 378576 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2629 bytes_req: 3783248 { call_site: [ffffffff81325607] apparmor_file_alloc_security } hitcount: 5192 bytes_req: 10384 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 5529 bytes_req: 110584 { call_site: [ffffffff8131ebf7] aa_alloc_task_context } hitcount: 21943 bytes_req: 702176 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 55759 bytes_req: 5074265 Totals: Hits: 109928 Entries: 71 Dropped: 0因為上面的預設排序鍵是“hitcount”，所以上面顯示了按增加的命中計數排序的 call_site 列表，因此在底部我們看到在該執行期間進行最多 kmalloc 呼叫的函式。如果相反，我們想要檢視就請求的位元組數而不是呼叫次數而言的頂級 kmalloc 呼叫者，並且我們希望頂級呼叫者出現在頂部，我們可以使用“sort”引數以及“descending”修飾符
# echo 'hist:key=call_site.sym:val=bytes_req:sort=bytes_req.descending' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger # cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2186 bytes_req: 3397464 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1790 bytes_req: 712176 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 8132 bytes_req: 513135 { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 106 bytes_req: 440128 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2186 bytes_req: 314784 { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 2174 bytes_req: 208992 { call_site: [ffffffff811ae8e1] __kmalloc } hitcount: 8 bytes_req: 131072 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 859 bytes_req: 116824 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 1834 bytes_req: 102704 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 972 bytes_req: 101088 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 972 bytes_req: 85536 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 3333 bytes_req: 66664 { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 209 bytes_req: 61632 . . . { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 { call_site: [ffffffff812d8406] copy_semundo } hitcount: 2 bytes_req: 48 { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 1 bytes_req: 48 { call_site: [ffffffffa027121a] drm_getmagic [drm] } hitcount: 1 bytes_req: 48 { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40 { call_site: [ffffffff811c52f4] bprm_change_interp } hitcount: 2 bytes_req: 16 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 Totals: Hits: 32133 Entries: 81 Dropped: 0要顯示偏移量和大小資訊以及符號名稱，只需使用“sym-offset”代替
# echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger # cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=call_site.sym-offset:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] { call_site: [ffffffffa046041c] i915_gem_execbuffer2+0x6c/0x2c0 [i915] } hitcount: 4569 bytes_req: 3163720 { call_site: [ffffffffa0489a66] intel_ring_begin+0xc6/0x1f0 [i915] } hitcount: 4569 bytes_req: 657936 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23+0x694/0x1020 [i915] } hitcount: 1519 bytes_req: 472936 { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23+0x516/0x1020 [i915] } hitcount: 3050 bytes_req: 211832 { call_site: [ffffffff811e2a1b] seq_buf_alloc+0x1b/0x50 } hitcount: 34 bytes_req: 148384 { call_site: [ffffffffa04a580c] intel_crtc_page_flip+0xbc/0x870 [i915] } hitcount: 1385 bytes_req: 144040 { call_site: [ffffffff811ae8e1] __kmalloc+0x191/0x1b0 } hitcount: 8 bytes_req: 131072 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl+0x282/0x360 [drm] } hitcount: 1385 bytes_req: 121880 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc+0x32/0x100 [drm] } hitcount: 1848 bytes_req: 103488 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state+0x2c/0xa0 [i915] } hitcount: 461 bytes_req: 62696 { call_site: [ffffffffa029070e] drm_vma_node_allow+0x2e/0xd0 [drm] } hitcount: 1541 bytes_req: 61640 { call_site: [ffffffff815f8d7b] sk_prot_alloc+0xcb/0x1b0 } hitcount: 57 bytes_req: 57456 . . . { call_site: [ffffffff8109524a] alloc_fair_sched_group+0x5a/0x1a0 } hitcount: 2 bytes_req: 128 { call_site: [ffffffffa027b921] drm_vm_open_locked+0x31/0xa0 [drm] } hitcount: 3 bytes_req: 96 { call_site: [ffffffff8122e266] proc_self_follow_link+0x76/0xb0 } hitcount: 8 bytes_req: 96 { call_site: [ffffffff81213e80] load_elf_binary+0x240/0x1650 } hitcount: 3 bytes_req: 84 { call_site: [ffffffff8154bc62] usb_control_msg+0x42/0x110 } hitcount: 1 bytes_req: 8 { call_site: [ffffffffa00bf6fe] hidraw_send_report+0x7e/0x1a0 [hid] } hitcount: 1 bytes_req: 7 { call_site: [ffffffffa00bf1ca] hidraw_report_event+0x8a/0x120 [hid] } hitcount: 1 bytes_req: 7 Totals: Hits: 26098 Entries: 64 Dropped: 0我們還可以將多個欄位新增到“values”引數中。例如，我們可能想檢視分配的總位元組數以及請求的位元組數，並按降序顯示按已分配的位元組數排序的結果
# echo 'hist:keys=call_site.sym:values=bytes_req,bytes_alloc:sort=bytes_alloc.descending' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger # cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=call_site.sym:vals=bytes_req,bytes_alloc:sort=bytes_alloc.descending:size=2048 [active] { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 7403 bytes_req: 4084360 bytes_alloc: 5958016 { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 541 bytes_req: 2213968 bytes_alloc: 2228224 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 7404 bytes_req: 1066176 bytes_alloc: 1421568 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1565 bytes_req: 557368 bytes_alloc: 1037760 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 9557 bytes_req: 595778 bytes_alloc: 695744 { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 5839 bytes_req: 430680 bytes_alloc: 470400 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 2388 bytes_req: 324768 bytes_alloc: 458496 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 3911 bytes_req: 219016 bytes_alloc: 250304 { call_site: [ffffffff815f8d7b] sk_prot_alloc } hitcount: 235 bytes_req: 236880 bytes_alloc: 240640 { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 557 bytes_req: 169024 bytes_alloc: 221760 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 9378 bytes_req: 187548 bytes_alloc: 206312 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1519 bytes_req: 157976 bytes_alloc: 194432 . . . { call_site: [ffffffff8109bd3b] sched_autogroup_create_attach } hitcount: 2 bytes_req: 144 bytes_alloc: 192 { call_site: [ffffffff81097ee8] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 { call_site: [ffffffff81213e80] load_elf_binary } hitcount: 3 bytes_req: 84 bytes_alloc: 96 { call_site: [ffffffff81079a2e] kthread_create_on_node } hitcount: 1 bytes_req: 56 bytes_alloc: 64 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 bytes_alloc: 8 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8 Totals: Hits: 66598 Entries: 65 Dropped: 0最後，為了完成我們的 kmalloc 示例，我們可以讓 hist 觸發器額外顯示導致每個 call_site 的完整核心堆疊跟蹤集，而不是簡單地讓 hist 觸發器顯示符號 call_site。為此，我們只需將特殊值“common_stacktrace”用於鍵引數
# echo 'hist:keys=common_stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger上面的觸發器將使用觸發事件時生效的核心堆疊跟蹤作為雜湊表的鍵。這允許列舉導致特定事件的每個核心呼叫路徑，以及該事件的任何事件欄位的執行總計。在這裡，我們統計了系統中導致 kmalloc 的每個呼叫路徑的請求位元組數和已分配位元組數（在本例中，是核心編譯的每個 kmalloc 的呼叫路徑）
# cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=common_stacktrace:vals=bytes_req,bytes_alloc:sort=bytes_alloc:size=2048 [active] { common_stacktrace: __kmalloc_track_caller+0x10b/0x1a0 kmemdup+0x20/0x50 hidraw_report_event+0x8a/0x120 [hid] hid_report_raw_event+0x3ea/0x440 [hid] hid_input_report+0x112/0x190 [hid] hid_irq_in+0xc2/0x260 [usbhid] __usb_hcd_giveback_urb+0x72/0x120 usb_giveback_urb_bh+0x9e/0xe0 tasklet_hi_action+0xf8/0x100 __do_softirq+0x114/0x2c0 irq_exit+0xa5/0xb0 do_IRQ+0x5a/0xf0 ret_from_intr+0x0/0x30 cpuidle_enter+0x17/0x20 cpu_startup_entry+0x315/0x3e0 rest_init+0x7c/0x80 } hitcount: 3 bytes_req: 21 bytes_alloc: 24 { common_stacktrace: __kmalloc_track_caller+0x10b/0x1a0 kmemdup+0x20/0x50 hidraw_report_event+0x8a/0x120 [hid] hid_report_raw_event+0x3ea/0x440 [hid] hid_input_report+0x112/0x190 [hid] hid_irq_in+0xc2/0x260 [usbhid] __usb_hcd_giveback_urb+0x72/0x120 usb_giveback_urb_bh+0x9e/0xe0 tasklet_hi_action+0xf8/0x100 __do_softirq+0x114/0x2c0 irq_exit+0xa5/0xb0 do_IRQ+0x5a/0xf0 ret_from_intr+0x0/0x30 } hitcount: 3 bytes_req: 21 bytes_alloc: 24 { common_stacktrace: kmem_cache_alloc_trace+0xeb/0x150 aa_alloc_task_context+0x27/0x40 apparmor_cred_prepare+0x1f/0x50 security_prepare_creds+0x16/0x20 prepare_creds+0xdf/0x1a0 SyS_capset+0xb5/0x200 system_call_fastpath+0x12/0x6a } hitcount: 1 bytes_req: 32 bytes_alloc: 32 . . . { common_stacktrace: __kmalloc+0x11b/0x1b0 i915_gem_execbuffer2+0x6c/0x2c0 [i915] drm_ioctl+0x349/0x670 [drm] do_vfs_ioctl+0x2f0/0x4f0 SyS_ioctl+0x81/0xa0 system_call_fastpath+0x12/0x6a } hitcount: 17726 bytes_req: 13944120 bytes_alloc: 19593808 { common_stacktrace: __kmalloc+0x11b/0x1b0 load_elf_phdrs+0x76/0xa0 load_elf_binary+0x102/0x1650 search_binary_handler+0x97/0x1d0 do_execveat_common.isra.34+0x551/0x6e0 SyS_execve+0x3a/0x50 return_from_execve+0x0/0x23 } hitcount: 33348 bytes_req: 17152128 bytes_alloc: 20226048 { common_stacktrace: kmem_cache_alloc_trace+0xeb/0x150 apparmor_file_alloc_security+0x27/0x40 security_file_alloc+0x16/0x20 get_empty_filp+0x93/0x1c0 path_openat+0x31/0x5f0 do_filp_open+0x3a/0x90 do_sys_open+0x128/0x220 SyS_open+0x1e/0x20 system_call_fastpath+0x12/0x6a } hitcount: 4766422 bytes_req: 9532844 bytes_alloc: 38131376 { common_stacktrace: __kmalloc+0x11b/0x1b0 seq_buf_alloc+0x1b/0x50 seq_read+0x2cc/0x370 proc_reg_read+0x3d/0x80 __vfs_read+0x28/0xe0 vfs_read+0x86/0x140 SyS_read+0x46/0xb0 system_call_fastpath+0x12/0x6a } hitcount: 19133 bytes_req: 78368768 bytes_alloc: 78368768 Totals: Hits: 6085872 Entries: 253 Dropped: 0如果您在 common_pid 上鍵入 hist 觸發器，例如為了收集和顯示每個程序的排序總計，您可以使用特殊的 .execname 修飾符來顯示錶中程序的可執行檔名，而不是原始 pid。下面的示例保留了每個程序讀取的總位元組數的總和
# echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \ /sys/kernel/tracing/events/syscalls/sys_enter_read/trigger # cat /sys/kernel/tracing/events/syscalls/sys_enter_read/hist # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active] { common_pid: gnome-terminal [ 3196] } hitcount: 280 count: 1093512 { common_pid: Xorg [ 1309] } hitcount: 525 count: 256640 { common_pid: compiz [ 2889] } hitcount: 59 count: 254400 { common_pid: bash [ 8710] } hitcount: 3 count: 66369 { common_pid: dbus-daemon-lau [ 8703] } hitcount: 49 count: 47739 { common_pid: irqbalance [ 1252] } hitcount: 27 count: 27648 { common_pid: 01ifupdown [ 8705] } hitcount: 3 count: 17216 { common_pid: dbus-daemon [ 772] } hitcount: 10 count: 12396 { common_pid: Socket Thread [ 8342] } hitcount: 11 count: 11264 { common_pid: nm-dhcp-client. [ 8701] } hitcount: 6 count: 7424 { common_pid: gmain [ 1315] } hitcount: 18 count: 6336 . . . { common_pid: postgres [ 1892] } hitcount: 2 count: 32 { common_pid: postgres [ 1891] } hitcount: 2 count: 32 { common_pid: gmain [ 8704] } hitcount: 2 count: 32 { common_pid: upstart-dbus-br [ 2740] } hitcount: 21 count: 21 { common_pid: nm-dispatcher.a [ 8696] } hitcount: 1 count: 16 { common_pid: indicator-datet [ 2904] } hitcount: 1 count: 16 { common_pid: gdbus [ 2998] } hitcount: 1 count: 16 { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8 { common_pid: init [ 1] } hitcount: 2 count: 2 Totals: Hits: 2116 Entries: 51 Dropped: 0類似地，如果您在 syscall id 上鍵入 hist 觸發器，例如為了收集和顯示系統範圍內 syscall 命中的列表，您可以使用特殊的 .syscall 修飾符來顯示 syscall 名稱而不是原始 id。下面的示例在執行期間保留系統中 syscall 計數的執行總計
# echo 'hist:key=id.syscall:val=hitcount' > \ /sys/kernel/tracing/events/raw_syscalls/sys_enter/trigger # cat /sys/kernel/tracing/events/raw_syscalls/sys_enter/hist # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active] { id: sys_fsync [ 74] } hitcount: 1 { id: sys_newuname [ 63] } hitcount: 1 { id: sys_prctl [157] } hitcount: 1 { id: sys_statfs [137] } hitcount: 1 { id: sys_symlink [ 88] } hitcount: 1 { id: sys_sendmmsg [307] } hitcount: 1 { id: sys_semctl [ 66] } hitcount: 1 { id: sys_readlink [ 89] } hitcount: 3 { id: sys_bind [ 49] } hitcount: 3 { id: sys_getsockname [ 51] } hitcount: 3 { id: sys_unlink [ 87] } hitcount: 3 { id: sys_rename [ 82] } hitcount: 4 { id: unknown_syscall [ 58] } hitcount: 4 { id: sys_connect [ 42] } hitcount: 4 { id: sys_getpid [ 39] } hitcount: 4 . . . { id: sys_rt_sigprocmask [ 14] } hitcount: 952 { id: sys_futex [202] } hitcount: 1534 { id: sys_write [ 1] } hitcount: 2689 { id: sys_setitimer [ 38] } hitcount: 2797 { id: sys_read [ 0] } hitcount: 3202 { id: sys_select [ 23] } hitcount: 3773 { id: sys_writev [ 20] } hitcount: 4531 { id: sys_poll [ 7] } hitcount: 8314 { id: sys_recvmsg [ 47] } hitcount: 13738 { id: sys_ioctl [ 16] } hitcount: 21843 Totals: Hits: 67612 Entries: 72 Dropped: 0上面的 syscall 計數提供了系統上系統呼叫活動的大致總體情況；例如，我們可以看到該系統上最受歡迎的系統呼叫是“sys_ioctl”系統呼叫。
我們可以使用“複合”鍵來最佳化該數字，並進一步瞭解哪些程序對整體 ioctl 計數有貢獻。
下面的命令保留每個系統呼叫 id 和 pid 的唯一組合的命中計數 - 最終結果本質上是一個保留每個 pid 的系統呼叫命中總和的表。結果使用系統呼叫 id 作為主鍵，命中計數總和作為輔助鍵進行排序
# echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' > \ /sys/kernel/tracing/events/raw_syscalls/sys_enter/trigger # cat /sys/kernel/tracing/events/raw_syscalls/sys_enter/hist # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active] { id: sys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: 1 { id: sys_read [ 0], common_pid: gdbus [ 2976] } hitcount: 1 { id: sys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: 1 { id: sys_read [ 0], common_pid: postgres [ 1865] } hitcount: 1 { id: sys_read [ 0], common_pid: deja-dup-monito [ 3543] } hitcount: 2 { id: sys_read [ 0], common_pid: NetworkManager [ 890] } hitcount: 2 { id: sys_read [ 0], common_pid: evolution-calen [ 3048] } hitcount: 2 { id: sys_read [ 0], common_pid: postgres [ 1864] } hitcount: 2 { id: sys_read [ 0], common_pid: nm-applet [ 3022] } hitcount: 2 { id: sys_read [ 0], common_pid: whoopsie [ 1212] } hitcount: 2 . . . { id: sys_ioctl [ 16], common_pid: bash [ 8479] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: bash [ 3472] } hitcount: 12 { id: sys_ioctl [ 16], common_pid: gnome-terminal [ 3199] } hitcount: 16 { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 1808 { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 5580 . . . { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2690] } hitcount: 3 { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2688] } hitcount: 16 { id: sys_inotify_add_watch [254], common_pid: gmain [ 975] } hitcount: 2 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3204] } hitcount: 4 { id: sys_inotify_add_watch [254], common_pid: gmain [ 2888] } hitcount: 4 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3003] } hitcount: 4 { id: sys_inotify_add_watch [254], common_pid: gmain [ 2873] } hitcount: 4 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3196] } hitcount: 6 { id: sys_openat [257], common_pid: java [ 2623] } hitcount: 2 { id: sys_eventfd2 [290], common_pid: ibus-ui-gtk3 [ 2760] } hitcount: 4 { id: sys_eventfd2 [290], common_pid: compiz [ 2994] } hitcount: 6 Totals: Hits: 31536 Entries: 323 Dropped: 0上面的列表確實為我們提供了按 pid 分解的 ioctl syscall，但它也為我們提供了更多的資訊，我們目前並不關心這些資訊。由於我們知道 sys_ioctl 的 syscall id（16，顯示在 sys_ioctl 名稱旁邊），我們可以使用它來過濾掉所有其他 syscall
# echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount if id == 16' > \ /sys/kernel/tracing/events/raw_syscalls/sys_enter/trigger # cat /sys/kernel/tracing/events/raw_syscalls/sys_enter/hist # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 if id == 16 [active] { id: sys_ioctl [ 16], common_pid: gmain [ 2769] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: gmain [ 3003] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: gmain [ 2781] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: gmain [ 2829] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: bash [ 8726] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: bash [ 8508] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: gmain [ 2970] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: gmain [ 2768] } hitcount: 1 . . . { id: sys_ioctl [ 16], common_pid: pool [ 8559] } hitcount: 45 { id: sys_ioctl [ 16], common_pid: pool [ 8555] } hitcount: 48 { id: sys_ioctl [ 16], common_pid: pool [ 8551] } hitcount: 48 { id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: 66 { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 26674 { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 73443 Totals: Hits: 101162 Entries: 103 Dropped: 0上面的輸出顯示，“compiz”和“Xorg”是迄今為止最重的 ioctl 呼叫者（這可能會導致人們質疑他們是否真的需要進行所有這些呼叫以及進一步調查的可能途徑。）
複合鍵示例使用鍵和總和值（命中計數）對輸出進行排序，但我們也可以輕鬆地使用兩個鍵。這是一個示例，其中我們使用由 common_pid 和 size 事件欄位組成的複合鍵。使用 pid 作為主鍵，“size”作為輔助鍵進行排序，使我們能夠顯示 recvfrom 大小的有序摘要，以及每個程序接收的計數
# echo 'hist:key=common_pid.execname,size:val=hitcount:sort=common_pid,size' > \ /sys/kernel/tracing/events/syscalls/sys_enter_recvfrom/trigger # cat /sys/kernel/tracing/events/syscalls/sys_enter_recvfrom/hist # trigger info: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:size=2048 [active] { common_pid: smbd [ 784], size: 4 } hitcount: 1 { common_pid: dnsmasq [ 1412], size: 4096 } hitcount: 672 { common_pid: postgres [ 1796], size: 1000 } hitcount: 6 { common_pid: postgres [ 1867], size: 1000 } hitcount: 10 { common_pid: bamfdaemon [ 2787], size: 28 } hitcount: 2 { common_pid: bamfdaemon [ 2787], size: 14360 } hitcount: 1 { common_pid: compiz [ 2994], size: 8 } hitcount: 1 { common_pid: compiz [ 2994], size: 20 } hitcount: 11 { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2 { common_pid: firefox [ 8817], size: 4 } hitcount: 1 { common_pid: firefox [ 8817], size: 8 } hitcount: 5 { common_pid: firefox [ 8817], size: 588 } hitcount: 2 { common_pid: firefox [ 8817], size: 628 } hitcount: 1 { common_pid: firefox [ 8817], size: 6944 } hitcount: 1 { common_pid: firefox [ 8817], size: 408880 } hitcount: 2 { common_pid: firefox [ 8822], size: 8 } hitcount: 2 { common_pid: firefox [ 8822], size: 160 } hitcount: 2 { common_pid: firefox [ 8822], size: 320 } hitcount: 2 { common_pid: firefox [ 8822], size: 352 } hitcount: 1 . . . { common_pid: pool [ 8923], size: 1960 } hitcount: 10 { common_pid: pool [ 8923], size: 2048 } hitcount: 10 { common_pid: pool [ 8924], size: 1960 } hitcount: 10 { common_pid: pool [ 8924], size: 2048 } hitcount: 10 { common_pid: pool [ 8928], size: 1964 } hitcount: 4 { common_pid: pool [ 8928], size: 1965 } hitcount: 2 { common_pid: pool [ 8928], size: 2048 } hitcount: 6 { common_pid: pool [ 8929], size: 1982 } hitcount: 1 { common_pid: pool [ 8929], size: 2048 } hitcount: 1 Totals: Hits: 2016 Entries: 224 Dropped: 0上面的示例還說明了這樣一個事實，即雖然複合鍵被視為單個實體以進行雜湊處理，但它可以獨立訪問它組成的子鍵。
下一個示例使用字串欄位作為雜湊鍵，並演示如何手動暫停和繼續 hist 觸發器。在此示例中，我們將聚合 fork 計數，並且不期望雜湊表中有大量條目，因此我們將將其減少到更小的數字，例如 256
# echo 'hist:key=child_comm:val=hitcount:size=256' > \ /sys/kernel/tracing/events/sched/sched_process_fork/trigger # cat /sys/kernel/tracing/events/sched/sched_process_fork/hist # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] { child_comm: dconf worker } hitcount: 1 { child_comm: ibus-daemon } hitcount: 1 { child_comm: whoopsie } hitcount: 1 { child_comm: smbd } hitcount: 1 { child_comm: gdbus } hitcount: 1 { child_comm: kthreadd } hitcount: 1 { child_comm: dconf worker } hitcount: 1 { child_comm: evolution-alarm } hitcount: 2 { child_comm: Socket Thread } hitcount: 2 { child_comm: postgres } hitcount: 2 { child_comm: bash } hitcount: 3 { child_comm: compiz } hitcount: 3 { child_comm: evolution-sourc } hitcount: 4 { child_comm: dhclient } hitcount: 4 { child_comm: pool } hitcount: 5 { child_comm: nm-dispatcher.a } hitcount: 8 { child_comm: firefox } hitcount: 8 { child_comm: dbus-daemon } hitcount: 8 { child_comm: glib-pacrunner } hitcount: 10 { child_comm: evolution } hitcount: 23 Totals: Hits: 89 Entries: 20 Dropped: 0如果我們想暫停 hist 觸發器，我們可以簡單地將 :pause 附加到啟動觸發器的命令。請注意，觸發器資訊顯示為 [paused]
# echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \ /sys/kernel/tracing/events/sched/sched_process_fork/trigger # cat /sys/kernel/tracing/events/sched/sched_process_fork/hist # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [paused] { child_comm: dconf worker } hitcount: 1 { child_comm: kthreadd } hitcount: 1 { child_comm: dconf worker } hitcount: 1 { child_comm: gdbus } hitcount: 1 { child_comm: ibus-daemon } hitcount: 1 { child_comm: Socket Thread } hitcount: 2 { child_comm: evolution-alarm } hitcount: 2 { child_comm: smbd } hitcount: 2 { child_comm: bash } hitcount: 3 { child_comm: whoopsie } hitcount: 3 { child_comm: compiz } hitcount: 3 { child_comm: evolution-sourc } hitcount: 4 { child_comm: pool } hitcount: 5 { child_comm: postgres } hitcount: 6 { child_comm: firefox } hitcount: 8 { child_comm: dhclient } hitcount: 10 { child_comm: emacs } hitcount: 12 { child_comm: dbus-daemon } hitcount: 20 { child_comm: nm-dispatcher.a } hitcount: 20 { child_comm: evolution } hitcount: 35 { child_comm: glib-pacrunner } hitcount: 59 Totals: Hits: 199 Entries: 21 Dropped: 0要手動繼續讓觸發器聚合事件，請附加 :cont 代替。請注意，觸發器資訊再次顯示為 [active]，並且資料已更改
# echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \ /sys/kernel/tracing/events/sched/sched_process_fork/trigger # cat /sys/kernel/tracing/events/sched/sched_process_fork/hist # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] { child_comm: dconf worker } hitcount: 1 { child_comm: dconf worker } hitcount: 1 { child_comm: kthreadd } hitcount: 1 { child_comm: gdbus } hitcount: 1 { child_comm: ibus-daemon } hitcount: 1 { child_comm: Socket Thread } hitcount: 2 { child_comm: evolution-alarm } hitcount: 2 { child_comm: smbd } hitcount: 2 { child_comm: whoopsie } hitcount: 3 { child_comm: compiz } hitcount: 3 { child_comm: evolution-sourc } hitcount: 4 { child_comm: bash } hitcount: 5 { child_comm: pool } hitcount: 5 { child_comm: postgres } hitcount: 6 { child_comm: firefox } hitcount: 8 { child_comm: dhclient } hitcount: 11 { child_comm: emacs } hitcount: 12 { child_comm: dbus-daemon } hitcount: 22 { child_comm: nm-dispatcher.a } hitcount: 22 { child_comm: evolution } hitcount: 35 { child_comm: glib-pacrunner } hitcount: 59 Totals: Hits: 206 Entries: 21 Dropped: 0前面的示例顯示瞭如何透過將“pause”和“continue”附加到 hist 觸發器命令來啟動和停止 hist 觸發器。也可以透過最初啟動附加了“:pause”的觸發器，以暫停狀態啟動 hist 觸發器。這允許您僅在準備好開始收集資料時才啟動觸發器，而不是在此之前。例如，您可以在暫停狀態下啟動觸發器，然後取消暫停並執行您想要測量的操作，然後在完成後再次暫停觸發器。
當然，手動執行此操作可能很困難並且容易出錯，但可以透過 enable_hist 和 disable_hist 觸發器根據某些條件自動啟動和停止 hist 觸發器。
例如，假設我們想看看使用 wget 下載一個大小合適的檔案時，每個導致 netif_receive_skb 事件的呼叫路徑的 skb 長度的相對權重。
首先，我們在 netif_receive_skb 事件上設定一個最初暫停的堆疊跟蹤觸發器
# echo 'hist:key=common_stacktrace:vals=len:pause' > \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger接下來，我們在 sched_process_exec 事件上設定一個“enable_hist”觸發器，其中包含“if filename==/usr/bin/wget”過濾器。此新觸發器的效果是，如果且僅當它看到檔名為“/usr/bin/wget”的 sched_process_exec 事件，它才會“取消暫停”我們剛剛在 netif_receive_skb 上設定的 hist 觸發器。發生這種情況時，所有 netif_receive_skb 事件都會聚合到以堆疊跟蹤為鍵的雜湊表中
# echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ /sys/kernel/tracing/events/sched/sched_process_exec/trigger聚合會持續進行，直到 netif_receive_skb 再次暫停，這是以下 disable_hist 事件透過在 sched_process_exit 事件上建立類似的設定（使用過濾器“comm==wget”）所做的事情
# echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ /sys/kernel/tracing/events/sched/sched_process_exit/trigger每當程序退出並且 disable_hist 觸發器過濾器的 comm 欄位與“comm==wget”匹配時，netif_receive_skb hist 觸發器將被停用。
總體效果是，僅在 wget 期間，netif_receive_skb 事件才會聚合到雜湊表中。執行 wget 命令然後列出“hist”檔案將顯示 wget 命令生成的輸出
$ wget https://kernel.linux.club.tw/pub/linux/kernel/v3.x/patch-3.19.xz # cat /sys/kernel/tracing/events/net/netif_receive_skb/hist # trigger info: hist:keys=common_stacktrace:vals=len:sort=hitcount:size=2048 [paused] { common_stacktrace: __netif_receive_skb_core+0x46d/0x990 __netif_receive_skb+0x18/0x60 netif_receive_skb_internal+0x23/0x90 napi_gro_receive+0xc8/0x100 ieee80211_deliver_skb+0xd6/0x270 [mac80211] ieee80211_rx_handlers+0xccf/0x22f0 [mac80211] ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211] ieee80211_rx+0x31d/0x900 [mac80211] iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm] iwl_rx_dispatch+0x8e/0xf0 [iwldvm] iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi] irq_thread_fn+0x20/0x50 irq_thread+0x11f/0x150 kthread+0xd2/0xf0 ret_from_fork+0x42/0x70 } hitcount: 85 len: 28884 { common_stacktrace: __netif_receive_skb_core+0x46d/0x990 __netif_receive_skb+0x18/0x60 netif_receive_skb_internal+0x23/0x90 napi_gro_complete+0xa4/0xe0 dev_gro_receive+0x23a/0x360 napi_gro_receive+0x30/0x100 ieee80211_deliver_skb+0xd6/0x270 [mac80211] ieee80211_rx_handlers+0xccf/0x22f0 [mac80211] ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211] ieee80211_rx+0x31d/0x900 [mac80211] iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm] iwl_rx_dispatch+0x8e/0xf0 [iwldvm] iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi] irq_thread_fn+0x20/0x50 irq_thread+0x11f/0x150 kthread+0xd2/0xf0 } hitcount: 98 len: 664329 { common_stacktrace: __netif_receive_skb_core+0x46d/0x990 __netif_receive_skb+0x18/0x60 process_backlog+0xa8/0x150 net_rx_action+0x15d/0x340 __do_softirq+0x114/0x2c0 do_softirq_own_stack+0x1c/0x30 do_softirq+0x65/0x70 __local_bh_enable_ip+0xb5/0xc0 ip_finish_output+0x1f4/0x840 ip_output+0x6b/0xc0 ip_local_out_sk+0x31/0x40 ip_send_skb+0x1a/0x50 udp_send_skb+0x173/0x2a0 udp_sendmsg+0x2bf/0x9f0 inet_sendmsg+0x64/0xa0 sock_sendmsg+0x3d/0x50 } hitcount: 115 len: 13030 { common_stacktrace: __netif_receive_skb_core+0x46d/0x990 __netif_receive_skb+0x18/0x60 netif_receive_skb_internal+0x23/0x90 napi_gro_complete+0xa4/0xe0 napi_gro_flush+0x6d/0x90 iwl_pcie_irq_handler+0x92a/0x12f0 [iwlwifi] irq_thread_fn+0x20/0x50 irq_thread+0x11f/0x150 kthread+0xd2/0xf0 ret_from_fork+0x42/0x70 } hitcount: 934 len: 5512212 Totals: Hits: 1232 Entries: 4 Dropped: 0上面顯示了 wget 命令期間的所有 netif_receive_skb 呼叫路徑及其總長度。
“clear”hist 觸發器引數可用於清除雜湊表。假設我們想嘗試再次執行前面的示例，但這次也想檢視進入直方圖的完整事件列表。為了避免不得不再次設定所有內容，我們可以先清除直方圖
# echo 'hist:key=common_stacktrace:vals=len:clear' >> \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger只是為了驗證它實際上已被清除，這是我們現在在 hist 檔案中看到的內容
# cat /sys/kernel/tracing/events/net/netif_receive_skb/hist # trigger info: hist:keys=common_stacktrace:vals=len:sort=hitcount:size=2048 [paused] Totals: Hits: 0 Entries: 0 Dropped: 0由於我們想檢視在新執行期間發生的每個 netif_receive_skb 事件的詳細列表，這些事件實際上是聚合到雜湊表中的相同事件，因此我們將一些額外的“enable_event”事件新增到觸發 sched_process_exec 和 sched_process_exit 事件，如下所示
# echo 'enable_event:net:netif_receive_skb if filename==/usr/bin/wget' > \ /sys/kernel/tracing/events/sched/sched_process_exec/trigger # echo 'disable_event:net:netif_receive_skb if comm==wget' > \ /sys/kernel/tracing/events/sched/sched_process_exit/trigger如果您讀取 sched_process_exec 和 sched_process_exit 觸發器的觸發器檔案，您應該看到每個觸發器有兩個觸發器：一個啟用/停用 hist 聚合，另一個啟用/停用事件日誌記錄
# cat /sys/kernel/tracing/events/sched/sched_process_exec/trigger enable_event:net:netif_receive_skb:unlimited if filename==/usr/bin/wget enable_hist:net:netif_receive_skb:unlimited if filename==/usr/bin/wget # cat /sys/kernel/tracing/events/sched/sched_process_exit/trigger enable_event:net:netif_receive_skb:unlimited if comm==wget disable_hist:net:netif_receive_skb:unlimited if comm==wget換句話說，每當命中 sched_process_exec 或 sched_process_exit 事件並且與“wget”匹配時，它都會啟用或停用直方圖和事件日誌，最終得到的是一個僅覆蓋指定持續時間的雜湊表和一組事件。再次執行 wget 命令
$ wget https://kernel.linux.club.tw/pub/linux/kernel/v3.x/patch-3.19.xz顯示“hist”檔案應顯示與您在上一次執行中看到的內容類似的內容，但這次您還應該在跟蹤檔案中看到各個事件
# cat /sys/kernel/tracing/trace # tracer: nop # # entries-in-buffer/entries-written: 183/1426 #P:4 # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | wget-15108 [000] ..s1 31769.606929: netif_receive_skb: dev=lo skbaddr=ffff88009c353100 len=60 wget-15108 [000] ..s1 31769.606999: netif_receive_skb: dev=lo skbaddr=ffff88009c353200 len=60 dnsmasq-1382 [000] ..s1 31769.677652: netif_receive_skb: dev=lo skbaddr=ffff88009c352b00 len=130 dnsmasq-1382 [000] ..s1 31769.685917: netif_receive_skb: dev=lo skbaddr=ffff88009c352200 len=138 ##### CPU 2 buffer started #### irq/29-iwlwifi-559 [002] ..s. 31772.031529: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433d00 len=2948 irq/29-iwlwifi-559 [002] ..s. 31772.031572: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432200 len=1500 irq/29-iwlwifi-559 [002] ..s. 31772.032196: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433100 len=2948 irq/29-iwlwifi-559 [002] ..s. 31772.032761: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433000 len=2948 irq/29-iwlwifi-559 [002] ..s. 31772.033220: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432e00 len=1500 . . .以下示例演示瞭如何將多個 hist 觸發器附加到給定的事件。此功能可用於建立一組從同一組事件派生的不同摘要，或用於比較不同過濾器的效果等
# echo 'hist:keys=skbaddr.hex:vals=len if len < 0' >> \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger # echo 'hist:keys=skbaddr.hex:vals=len if len > 4096' >> \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger # echo 'hist:keys=skbaddr.hex:vals=len if len == 256' >> \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger # echo 'hist:keys=skbaddr.hex:vals=len' >> \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger # echo 'hist:keys=len:vals=common_preempt_count' >> \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger上面的命令集建立了四個僅在其過濾器中不同的觸發器，以及一個完全不同但相當荒謬的觸發器。請注意，為了將多個 hist 觸發器附加到同一檔案，您應該使用“>>”運算子來附加它們（“>”也會新增新的 hist 觸發器，但會預先刪除任何現有的 hist 觸發器）。
顯示事件的“hist”檔案的內容會顯示所有五個直方圖的內容
# cat /sys/kernel/tracing/events/net/netif_receive_skb/hist # event histogram # # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active] # { len: 176 } hitcount: 1 common_preempt_count: 0 { len: 223 } hitcount: 1 common_preempt_count: 0 { len: 4854 } hitcount: 1 common_preempt_count: 0 { len: 395 } hitcount: 1 common_preempt_count: 0 { len: 177 } hitcount: 1 common_preempt_count: 0 { len: 446 } hitcount: 1 common_preempt_count: 0 { len: 1601 } hitcount: 1 common_preempt_count: 0 . . . { len: 1280 } hitcount: 66 common_preempt_count: 0 { len: 116 } hitcount: 81 common_preempt_count: 40 { len: 708 } hitcount: 112 common_preempt_count: 0 { len: 46 } hitcount: 221 common_preempt_count: 0 { len: 1264 } hitcount: 458 common_preempt_count: 0 Totals: Hits: 1428 Entries: 147 Dropped: 0 # event histogram # # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] # { skbaddr: ffff8800baee5e00 } hitcount: 1 len: 130 { skbaddr: ffff88005f3d5600 } hitcount: 1 len: 1280 { skbaddr: ffff88005f3d4900 } hitcount: 1 len: 1280 { skbaddr: ffff88009fed6300 } hitcount: 1 len: 115 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 115 { skbaddr: ffff88008cdb1900 } hitcount: 1 len: 46 { skbaddr: ffff880064b5ef00 } hitcount: 1 len: 118 { skbaddr: ffff880044e3c700 } hitcount: 1 len: 60 { skbaddr: ffff880100065900 } hitcount: 1 len: 46 { skbaddr: ffff8800d46bd500 } hitcount: 1 len: 116 { skbaddr: ffff88005f3d5f00 } hitcount: 1 len: 1280 { skbaddr: ffff880100064700 } hitcount: 1 len: 365 { skbaddr: ffff8800badb6f00 } hitcount: 1 len: 60 . . . { skbaddr: ffff88009fe0be00 } hitcount: 27 len: 24677 { skbaddr: ffff88009fe0a400 } hitcount: 27 len: 23052 { skbaddr: ffff88009fe0b700 } hitcount: 31 len: 25589 { skbaddr: ffff88009fe0b600 } hitcount: 32 len: 27326 { skbaddr: ffff88006a462800 } hitcount: 68 len: 71678 { skbaddr: ffff88006a463700 } hitcount: 70 len: 72678 { skbaddr: ffff88006a462b00 } hitcount: 71 len: 77589 { skbaddr: ffff88006a463600 } hitcount: 73 len: 71307 { skbaddr: ffff88006a462200 } hitcount: 81 len: 81032 Totals: Hits: 1451 Entries: 318 Dropped: 0 # event histogram # # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [active] # Totals: Hits: 0 Entries: 0 Dropped: 0 # event histogram # # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [active] # { skbaddr: ffff88009fd2c300 } hitcount: 1 len: 7212 { skbaddr: ffff8800d2bcce00 } hitcount: 1 len: 7212 { skbaddr: ffff8800d2bcd700 } hitcount: 1 len: 7212 { skbaddr: ffff8800d2bcda00 } hitcount: 1 len: 21492 { skbaddr: ffff8800ae2e2d00 } hitcount: 1 len: 7212 { skbaddr: ffff8800d2bcdb00 } hitcount: 1 len: 7212 { skbaddr: ffff88006a4df500 } hitcount: 1 len: 4854 { skbaddr: ffff88008ce47b00 } hitcount: 1 len: 18636 { skbaddr: ffff8800ae2e2200 } hitcount: 1 len: 12924 { skbaddr: ffff88005f3e1000 } hitcount: 1 len: 4356 { skbaddr: ffff8800d2bcdc00 } hitcount: 2 len: 24420 { skbaddr: ffff8800d2bcc200 } hitcount: 2 len: 12996 Totals: Hits: 14 Entries: 12 Dropped: 0 # event histogram # # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active] # Totals: Hits: 0 Entries: 0 Dropped: 0可以使用命名觸發器來使觸發器共享一組公共的直方圖資料。此功能主要用於組合由行內函數中包含的追蹤點生成的事件的輸出，但名稱可以用於任何事件上的 hist 觸發器。例如，這兩個觸發器在命中時將更新共享的“foo”直方圖資料中的相同“len”欄位
# echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ /sys/kernel/tracing/events/net/netif_rx/trigger您可以透過同時讀取每個事件的 hist 檔案來檢視它們是否正在更新公共直方圖資料
# cat /sys/kernel/tracing/events/net/netif_receive_skb/hist; cat /sys/kernel/tracing/events/net/netif_rx/hist # event histogram # # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] # { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260 { skbaddr: ffff880064505000 } hitcount: 1 len: 46 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44 { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676 { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107 { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92 { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142 { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220 { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92 { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92 { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675 { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138 { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138 { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184 { skbaddr: ffff880064504400 } hitcount: 4 len: 184 { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184 { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230 { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196 { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276 { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276 Totals: Hits: 81 Entries: 42 Dropped: 0 # event histogram # # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] # { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260 { skbaddr: ffff880064505000 } hitcount: 1 len: 46 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44 { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676 { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107 { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92 { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142 { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220 { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92 { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92 { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675 { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138 { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138 { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184 { skbaddr: ffff880064504400 } hitcount: 4 len: 184 { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184 { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230 { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196 { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276 { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276 Totals: Hits: 81 Entries: 42 Dropped: 0這是一個示例，演示瞭如何組合來自任何兩個事件的直方圖資料，即使它們除了“hitcount”和“common_stacktrace”之外沒有任何“相容”欄位。這些命令使用這些欄位建立幾個名為“bar”的觸發器
# echo 'hist:name=bar:key=common_stacktrace:val=hitcount' > \ /sys/kernel/tracing/events/sched/sched_process_fork/trigger # echo 'hist:name=bar:key=common_stacktrace:val=hitcount' > \ /sys/kernel/tracing/events/net/netif_rx/trigger顯示任一觸發器的輸出會顯示一些有趣的，如果有點令人困惑的輸出
# cat /sys/kernel/tracing/events/sched/sched_process_fork/hist # cat /sys/kernel/tracing/events/net/netif_rx/hist # event histogram # # trigger info: hist:name=bar:keys=common_stacktrace:vals=hitcount:sort=hitcount:size=2048 [active] # { common_stacktrace: kernel_clone+0x18e/0x330 kernel_thread+0x29/0x30 kthreadd+0x154/0x1b0 ret_from_fork+0x3f/0x70 } hitcount: 1 { common_stacktrace: netif_rx_internal+0xb2/0xd0 netif_rx_ni+0x20/0x70 dev_loopback_xmit+0xaa/0xd0 ip_mc_output+0x126/0x240 ip_local_out_sk+0x31/0x40 igmp_send_report+0x1e9/0x230 igmp_timer_expire+0xe9/0x120 call_timer_fn+0x39/0xf0 run_timer_softirq+0x1e1/0x290 __do_softirq+0xfd/0x290 irq_exit+0x98/0xb0 smp_apic_timer_interrupt+0x4a/0x60 apic_timer_interrupt+0x6d/0x80 cpuidle_enter+0x17/0x20 call_cpuidle+0x3b/0x60 cpu_startup_entry+0x22d/0x310 } hitcount: 1 { common_stacktrace: netif_rx_internal+0xb2/0xd0 netif_rx_ni+0x20/0x70 dev_loopback_xmit+0xaa/0xd0 ip_mc_output+0x17f/0x240 ip_local_out_sk+0x31/0x40 ip_send_skb+0x1a/0x50 udp_send_skb+0x13e/0x270 udp_sendmsg+0x2bf/0x980 inet_sendmsg+0x67/0xa0 sock_sendmsg+0x38/0x50 SYSC_sendto+0xef/0x170 SyS_sendto+0xe/0x10 entry_SYSCALL_64_fastpath+0x12/0x6a } hitcount: 2 { common_stacktrace: netif_rx_internal+0xb2/0xd0 netif_rx+0x1c/0x60 loopback_xmit+0x6c/0xb0 dev_hard_start_xmit+0x219/0x3a0 __dev_queue_xmit+0x415/0x4f0 dev_queue_xmit_sk+0x13/0x20 ip_finish_output2+0x237/0x340 ip_finish_output+0x113/0x1d0 ip_output+0x66/0xc0 ip_local_out_sk+0x31/0x40 ip_send_skb+0x1a/0x50 udp_send_skb+0x16d/0x270 udp_sendmsg+0x2bf/0x980 inet_sendmsg+0x67/0xa0 sock_sendmsg+0x38/0x50 ___sys_sendmsg+0x14e/0x270 } hitcount: 76 { common_stacktrace: netif_rx_internal+0xb2/0xd0 netif_rx+0x1c/0x60 loopback_xmit+0x6c/0xb0 dev_hard_start_xmit+0x219/0x3a0 __dev_queue_xmit+0x415/0x4f0 dev_queue_xmit_sk+0x13/0x20 ip_finish_output2+0x237/0x340 ip_finish_output+0x113/0x1d0 ip_output+0x66/0xc0 ip_local_out_sk+0x31/0x40 ip_send_skb+0x1a/0x50 udp_send_skb+0x16d/0x270 udp_sendmsg+0x2bf/0x980 inet_sendmsg+0x67/0xa0 sock_sendmsg+0x38/0x50 ___sys_sendmsg+0x269/0x270 } hitcount: 77 { common_stacktrace: netif_rx_internal+0xb2/0xd0 netif_rx+0x1c/0x60 loopback_xmit+0x6c/0xb0 dev_hard_start_xmit+0x219/0x3a0 __dev_queue_xmit+0x415/0x4f0 dev_queue_xmit_sk+0x13/0x20 ip_finish_output2+0x237/0x340 ip_finish_output+0x113/0x1d0 ip_output+0x66/0xc0 ip_local_out_sk+0x31/0x40 ip_send_skb+0x1a/0x50 udp_send_skb+0x16d/0x270 udp_sendmsg+0x2bf/0x980 inet_sendmsg+0x67/0xa0 sock_sendmsg+0x38/0x50 SYSC_sendto+0xef/0x170 } hitcount: 88 { common_stacktrace: kernel_clone+0x18e/0x330 SyS_clone+0x19/0x20 entry_SYSCALL_64_fastpath+0x12/0x6a } hitcount: 244 Totals: Hits: 489 Entries: 7 Dropped: 0
2.2 事件間 hist 觸發器¶
事件間 hist 觸發器是 hist 觸發器，它組合來自一個或多個其他事件的值，並使用該資料建立直方圖。來自事件間直方圖的資料反過來可以成為進一步組合的直方圖的來源，從而提供相關的直方圖鏈，這對於某些應用程式很重要。
可以在此方式中使用的一個事件間量的最重要示例是延遲，這只是兩個事件之間的時間戳差異。雖然延遲是最重要的事件間量，但請注意，由於支援在整個追蹤事件子系統中完全通用，因此任何事件欄位都可以用於事件間量。
將來自其他直方圖的資料組合到有用鏈中的直方圖的一個示例是“喚醒切換延遲”直方圖，它組合了“喚醒延遲”直方圖和“切換延遲”直方圖。
通常，hist 觸發器規範由一個（可能複合的）鍵以及一個或多個數值組成，這些數值是與該鍵關聯的不斷更新的總和。在這種情況下，直方圖規範由引用與單個事件型別關聯的追蹤事件欄位的單個鍵和值規範組成。
事件間 hist 觸發器擴充套件允許引用和組合來自多個事件的欄位，從而形成多事件直方圖規範。為了支援這個總體目標，hist 觸發器支援添加了一些啟用功能
為了計算事件間量，需要儲存來自一個事件的值，然後從另一個事件引用該值。這需要引入對直方圖“變數”的支援。
事件間量的計算及其組合需要對將簡單表示式 (+ 和 -) 應用於變數的一些最小支援。
由事件間量組成的直方圖在邏輯上不是任何一個事件的直方圖（因此，讓任何一個事件的“hist”檔案託管直方圖輸出實際上沒有意義）。為了解決直方圖與事件組合相關聯的想法，添加了允許建立“合成”事件的支援，這些事件是從其他事件派生的事件。這些合成事件是像任何其他事件一樣的完全成熟的事件，並且可以像這樣使用，例如建立前面提到的“組合”直方圖。
一組“操作”可以與直方圖條目關聯 - 這些操作可用於生成前面提到的合成事件，但也可用於其他目的，例如在命中“最大”延遲時儲存上下文。
追蹤事件沒有與其關聯的“時間戳”，但是有一個隱式時間戳與底層 ftrace 環形緩衝區中的事件一起儲存。此時間戳現在作為名為“common_timestamp”的合成欄位公開，可以在直方圖中使用，就像它是任何其他事件欄位一樣；它不是跟蹤格式中的實際欄位，而是一個合成值，但仍然可以像實際欄位一樣使用。預設情況下，它的單位是納秒；將“.usecs”附加到 common_timestamp 欄位會將單位更改為微秒。
關於事件間時間戳的說明：如果在直方圖中使用 common_timestamp，則跟蹤緩衝區會自動切換為使用絕對時間戳和“全域性”跟蹤時鐘，以避免與其他 CPU 上不一致的時鐘的虛假時間戳差異。可以使用“clock=XXX”hist 觸發器屬性覆蓋此設定，其中 XXX 是 tracing/trace_clock 偽檔案中列出的任何時鐘。
以下部分更詳細地描述了這些功能。
2.2.1 直方圖變數¶
變數只是用於在匹配事件之間儲存和檢索值的命名位置。“匹配”事件定義為具有匹配鍵的事件 - 如果為與該鍵對應的直方圖條目儲存了變數，則任何具有匹配鍵的後續事件都可以訪問該變數。
變數的值通常可用於任何後續事件，直到後續事件將其設定為其他值。該規則的一個例外是，表示式中使用的任何變數本質上都是“只讀一次” - 一旦它被後續事件中的表示式使用，它就會重置為“未設定”狀態，這意味著除非再次設定，否則無法再次使用。這不僅確保事件不會在計算中使用未初始化的變數，而且該變數僅使用一次，而不是用於任何不相關的後續匹配。
儲存變數的基本語法是簡單地將不對應於任何關鍵字的唯一變數名稱與“=”符號一起字首到任何事件欄位。
這會為鍵為“next_pid”的直方圖條目建立一個名為“ts0”的變數
# echo 'hist:keys=next_pid:vals=$ts0:ts0=common_timestamp ... >> \
event/trigger
任何具有與“next_pid”相同 pid 的後續事件都可以訪問 ts0 變數。
變數引用是透過在變數名稱前面加上“$”符號形成的。因此，例如，上面的 ts0 變數在表示式中將引用為“$ts0”。
因為使用了“vals=”，所以上面的 common_timestamp 變數值也會像正常的直方圖值一樣求和（儘管對於時間戳來說，這沒什麼意義）。
下面顯示了也可以以相同的方式儲存鍵值
# echo 'hist:timer_pid=common_pid:key=timer_pid ...' >> event/trigger
如果變數不是鍵變數或以“vals=”為字首，則關聯的事件欄位將儲存在變數中，但不會作為值求和
# echo 'hist:keys=next_pid:ts1=common_timestamp ...' >> event/trigger
可以同時分配多個變數。下面將導致 ts0 和 b 都建立為變數，common_timestamp 和 field1 也會額外地作為值求和
# echo 'hist:keys=pid:vals=$ts0,$b:ts0=common_timestamp,b=field1 ...' >> \
event/trigger
請注意，變數賦值可以出現在它們的使用之前或之後。下面的命令的行為與上面的命令相同
# echo 'hist:keys=pid:ts0=common_timestamp,b=field1:vals=$ts0,$b ...' >> \
event/trigger
還可以透過簡單地用冒號分隔來分配任意數量的未繫結到“vals=”字首的變數。下面是相同的事情，但沒有在直方圖中求和值
# echo 'hist:keys=pid:ts0=common_timestamp:b=field1 ...' >> event/trigger
如上所述設定的變數可以在另一個事件中引用並在表示式中使用。
例如，以下是如何計算延遲
# echo 'hist:keys=pid,prio:ts0=common_timestamp ...' >> event1/trigger
# echo 'hist:keys=next_pid:wakeup_lat=common_timestamp-$ts0 ...' >> event2/trigger
在上面的第一行中，事件的時間戳被儲存到變數 ts0 中。在下一行中，ts0 從第二個事件的時間戳中減去以產生延遲，然後將其分配到另一個變數“wakeup_lat”中。下面的 hist 觸發器反過來利用 wakeup_lat 變數來使用來自另一個事件的相同鍵和變數來計算組合延遲
# echo 'hist:key=pid:wakeupswitch_lat=$wakeup_lat+$switchtime_lat ...' >> event3/trigger
表示式支援使用加法、減法、乘法和除法運算子 (+-*/)。
請注意，如果在解析時無法檢測到除以零的情況（即除數不是常數），則結果將為 -1。
數值常量也可以直接在表示式中使用
# echo 'hist:keys=next_pid:timestamp_secs=common_timestamp/1000000 ...' >> event/trigger
或分配給變數並在後續表示式中引用
# echo 'hist:keys=next_pid:us_per_sec=1000000 ...' >> event/trigger
# echo 'hist:keys=next_pid:timestamp_secs=common_timestamp/$us_per_sec ...' >> event/trigger
變數甚至可以儲存堆疊跟蹤，這對於合成事件很有用。
2.2.2 合成事件¶
合成事件是使用者定義的事件，由與一個或多個其他事件關聯的 hist 觸發器變數或欄位生成。它們的目的是提供一種機制，用於顯示跨多個事件的資料，與現有和已經熟悉的普通事件用法一致。
要定義合成事件，使用者需要將一個簡單的規範寫入 tracing/synthetic_events 檔案，該規範包含新事件的名稱以及一個或多個變數及其型別，這些變數及其型別可以是任何有效欄位型別，並用分號分隔。
有關可用型別，請參閱 synth_field_size()。
如果 field_name 包含 [n]，則該欄位被認為是靜態陣列。
如果 field_names 包含 []（沒有下標），則該欄位被視為動態陣列，它在事件中只佔用容納陣列所需的空間。
可以使用靜態符號指定字串欄位
char name[32];
或動態符號
char name[];
兩者的尺寸限制均為 256。
例如，以下程式碼建立一個名為“wakeup_latency”的新事件，其中包含 3 個欄位：lat、pid 和 prio。 這些欄位中的每一個都只是對另一個事件中的變數的變數引用
# echo 'wakeup_latency \
u64 lat; \
pid_t pid; \
int prio' >> \
/sys/kernel/tracing/synthetic_events
讀取 tracing/synthetic_events 檔案會列出所有當前定義的合成事件，在本例中是上面定義的事件
# cat /sys/kernel/tracing/synthetic_events
wakeup_latency u64 lat; pid_t pid; int prio
可以透過在定義現有合成事件的命令前新增“！”來刪除該定義
# echo '!wakeup_latency u64 lat pid_t pid int prio' >> \
/sys/kernel/tracing/synthetic_events
此時，事件子系統中還沒有例項化實際的“wakeup_latency”事件 - 要使其發生，需要例項化一個“hist trigger action”並將其繫結到在其他事件上定義的實際欄位和變數（有關如何使用 hist trigger "onmatch" action 執行此操作，請參見下面的 2.2.3 節）。 完成此操作後，將建立“wakeup_latency”合成事件例項。
新事件在 tracing/events/synthetic/ 目錄下建立，並且看起來和行為方式與任何其他事件一樣
# ls /sys/kernel/tracing/events/synthetic/wakeup_latency
enable filter format hist id trigger
現在可以為新合成事件定義直方圖
# echo 'hist:keys=pid,prio,lat.log2:sort=lat' >> \
/sys/kernel/tracing/events/synthetic/wakeup_latency/trigger
上面顯示了以 2 的冪分組的延遲“lat”。
與任何其他事件一樣，一旦為事件啟用了直方圖，就可以透過讀取事件的“hist”檔案來顯示輸出
# cat /sys/kernel/tracing/events/synthetic/wakeup_latency/hist
# event histogram
#
# trigger info: hist:keys=pid,prio,lat.log2:vals=hitcount:sort=lat.log2:size=2048 [active]
#
{ pid: 2035, prio: 9, lat: ~ 2^2 } hitcount: 43
{ pid: 2034, prio: 9, lat: ~ 2^2 } hitcount: 60
{ pid: 2029, prio: 9, lat: ~ 2^2 } hitcount: 965
{ pid: 2034, prio: 120, lat: ~ 2^2 } hitcount: 9
{ pid: 2033, prio: 120, lat: ~ 2^2 } hitcount: 5
{ pid: 2030, prio: 9, lat: ~ 2^2 } hitcount: 335
{ pid: 2030, prio: 120, lat: ~ 2^2 } hitcount: 10
{ pid: 2032, prio: 120, lat: ~ 2^2 } hitcount: 1
{ pid: 2035, prio: 120, lat: ~ 2^2 } hitcount: 2
{ pid: 2031, prio: 9, lat: ~ 2^2 } hitcount: 176
{ pid: 2028, prio: 120, lat: ~ 2^2 } hitcount: 15
{ pid: 2033, prio: 9, lat: ~ 2^2 } hitcount: 91
{ pid: 2032, prio: 9, lat: ~ 2^2 } hitcount: 125
{ pid: 2029, prio: 120, lat: ~ 2^2 } hitcount: 4
{ pid: 2031, prio: 120, lat: ~ 2^2 } hitcount: 3
{ pid: 2029, prio: 120, lat: ~ 2^3 } hitcount: 2
{ pid: 2035, prio: 9, lat: ~ 2^3 } hitcount: 41
{ pid: 2030, prio: 120, lat: ~ 2^3 } hitcount: 1
{ pid: 2032, prio: 9, lat: ~ 2^3 } hitcount: 32
{ pid: 2031, prio: 9, lat: ~ 2^3 } hitcount: 44
{ pid: 2034, prio: 9, lat: ~ 2^3 } hitcount: 40
{ pid: 2030, prio: 9, lat: ~ 2^3 } hitcount: 29
{ pid: 2033, prio: 9, lat: ~ 2^3 } hitcount: 31
{ pid: 2029, prio: 9, lat: ~ 2^3 } hitcount: 31
{ pid: 2028, prio: 120, lat: ~ 2^3 } hitcount: 18
{ pid: 2031, prio: 120, lat: ~ 2^3 } hitcount: 2
{ pid: 2028, prio: 120, lat: ~ 2^4 } hitcount: 1
{ pid: 2029, prio: 9, lat: ~ 2^4 } hitcount: 4
{ pid: 2031, prio: 120, lat: ~ 2^7 } hitcount: 1
{ pid: 2032, prio: 120, lat: ~ 2^7 } hitcount: 1
Totals:
Hits: 2122
Entries: 30
Dropped: 0
延遲值也可以按給定大小線性分組，使用“.buckets”修飾符並指定大小（在本例中為 10 個一組）
# echo 'hist:keys=pid,prio,lat.buckets=10:sort=lat' >> \
/sys/kernel/tracing/events/synthetic/wakeup_latency/trigger
# event histogram
#
# trigger info: hist:keys=pid,prio,lat.buckets=10:vals=hitcount:sort=lat.buckets=10:size=2048 [active]
#
{ pid: 2067, prio: 9, lat: ~ 0-9 } hitcount: 220
{ pid: 2068, prio: 9, lat: ~ 0-9 } hitcount: 157
{ pid: 2070, prio: 9, lat: ~ 0-9 } hitcount: 100
{ pid: 2067, prio: 120, lat: ~ 0-9 } hitcount: 6
{ pid: 2065, prio: 120, lat: ~ 0-9 } hitcount: 2
{ pid: 2066, prio: 120, lat: ~ 0-9 } hitcount: 2
{ pid: 2069, prio: 9, lat: ~ 0-9 } hitcount: 122
{ pid: 2069, prio: 120, lat: ~ 0-9 } hitcount: 8
{ pid: 2070, prio: 120, lat: ~ 0-9 } hitcount: 1
{ pid: 2068, prio: 120, lat: ~ 0-9 } hitcount: 7
{ pid: 2066, prio: 9, lat: ~ 0-9 } hitcount: 365
{ pid: 2064, prio: 120, lat: ~ 0-9 } hitcount: 35
{ pid: 2065, prio: 9, lat: ~ 0-9 } hitcount: 998
{ pid: 2071, prio: 9, lat: ~ 0-9 } hitcount: 85
{ pid: 2065, prio: 9, lat: ~ 10-19 } hitcount: 2
{ pid: 2064, prio: 120, lat: ~ 10-19 } hitcount: 2
Totals:
Hits: 2112
Entries: 16
Dropped: 0
要儲存堆疊跟蹤，請建立具有型別為“unsigned long[]”甚至只是“long[]”欄位的合成事件。 例如，要檢視任務在不可中斷狀態下被阻塞的時間
# cd /sys/kernel/tracing
# echo 's:block_lat pid_t pid; u64 delta; unsigned long[] stack;' > dynamic_events
# echo 'hist:keys=next_pid:ts=common_timestamp.usecs,st=common_stacktrace if prev_state == 2' >> events/sched/sched_switch/trigger
# echo 'hist:keys=prev_pid:delta=common_timestamp.usecs-$ts,s=$st:onmax($delta).trace(block_lat,prev_pid,$delta,$s)' >> events/sched/sched_switch/trigger
# echo 1 > events/synthetic/block_lat/enable
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 2/2 #P:8
#
# _-----=> irqs-off/BH-disabled
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
<idle>-0 [005] d..4. 521.164922: block_lat: pid=0 delta=8322 stack=STACK:
=> __schedule+0x448/0x7b0
=> schedule+0x5a/0xb0
=> io_schedule+0x42/0x70
=> bit_wait_io+0xd/0x60
=> __wait_on_bit+0x4b/0x140
=> out_of_line_wait_on_bit+0x91/0xb0
=> jbd2_journal_commit_transaction+0x1679/0x1a70
=> kjournald2+0xa9/0x280
=> kthread+0xe9/0x110
=> ret_from_fork+0x2c/0x50
<...>-2 [004] d..4. 525.184257: block_lat: pid=2 delta=76 stack=STACK:
=> __schedule+0x448/0x7b0
=> schedule+0x5a/0xb0
=> schedule_timeout+0x11a/0x150
=> wait_for_completion_killable+0x144/0x1f0
=> __kthread_create_on_node+0xe7/0x1e0
=> kthread_create_on_node+0x51/0x70
=> create_worker+0xcc/0x1a0
=> worker_thread+0x2ad/0x380
=> kthread+0xe9/0x110
=> ret_from_fork+0x2c/0x50
具有堆疊跟蹤欄位的合成事件可以將其用作直方圖中的鍵
# echo 'hist:keys=delta.buckets=100,stack.stacktrace:sort=delta' > events/synthetic/block_lat/trigger
# cat events/synthetic/block_lat/hist
# event histogram
#
# trigger info: hist:keys=delta.buckets=100,stack.stacktrace:vals=hitcount:sort=delta.buckets=100:size=2048 [active]
#
{ delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
schedule+0x6b/0x110
io_schedule+0x46/0x80
bit_wait_io+0x11/0x80
__wait_on_bit+0x4e/0x120
out_of_line_wait_on_bit+0x8d/0xb0
__wait_on_buffer+0x33/0x40
jbd2_journal_commit_transaction+0x155a/0x19b0
kjournald2+0xab/0x270
kthread+0xfa/0x130
ret_from_fork+0x29/0x50
} hitcount: 1
{ delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
schedule+0x6b/0x110
io_schedule+0x46/0x80
rq_qos_wait+0xd0/0x170
wbt_wait+0x9e/0xf0
__rq_qos_throttle+0x25/0x40
blk_mq_submit_bio+0x2c3/0x5b0
__submit_bio+0xff/0x190
submit_bio_noacct_nocheck+0x25b/0x2b0
submit_bio_noacct+0x20b/0x600
submit_bio+0x28/0x90
ext4_bio_write_page+0x1e0/0x8c0
mpage_submit_page+0x60/0x80
mpage_process_page_bufs+0x16c/0x180
mpage_prepare_extent_to_map+0x23f/0x530
} hitcount: 1
{ delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
schedule+0x6b/0x110
schedule_hrtimeout_range_clock+0x97/0x110
schedule_hrtimeout_range+0x13/0x20
usleep_range_state+0x65/0x90
__intel_wait_for_register+0x1c1/0x230 [i915]
intel_psr_wait_for_idle_locked+0x171/0x2a0 [i915]
intel_pipe_update_start+0x169/0x360 [i915]
intel_update_crtc+0x112/0x490 [i915]
skl_commit_modeset_enables+0x199/0x600 [i915]
intel_atomic_commit_tail+0x7c4/0x1080 [i915]
intel_atomic_commit_work+0x12/0x20 [i915]
process_one_work+0x21c/0x3f0
worker_thread+0x50/0x3e0
kthread+0xfa/0x130
} hitcount: 3
{ delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
schedule+0x6b/0x110
schedule_timeout+0x11e/0x160
__wait_for_common+0x8f/0x190
wait_for_completion+0x24/0x30
__flush_work.isra.0+0x1cc/0x360
flush_work+0xe/0x20
drm_mode_rmfb+0x18b/0x1d0 [drm]
drm_mode_rmfb_ioctl+0x10/0x20 [drm]
drm_ioctl_kernel+0xb8/0x150 [drm]
drm_ioctl+0x243/0x560 [drm]
__x64_sys_ioctl+0x92/0xd0
do_syscall_64+0x59/0x90
entry_SYSCALL_64_after_hwframe+0x72/0xdc
} hitcount: 1
{ delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
schedule+0x6b/0x110
schedule_timeout+0x87/0x160
__wait_for_common+0x8f/0x190
wait_for_completion_timeout+0x1d/0x30
drm_atomic_helper_wait_for_flip_done+0x57/0x90 [drm_kms_helper]
intel_atomic_commit_tail+0x8ce/0x1080 [i915]
intel_atomic_commit_work+0x12/0x20 [i915]
process_one_work+0x21c/0x3f0
worker_thread+0x50/0x3e0
kthread+0xfa/0x130
ret_from_fork+0x29/0x50
} hitcount: 1
{ delta: ~ 100-199, stack.stacktrace __schedule+0xa19/0x1520
schedule+0x6b/0x110
schedule_hrtimeout_range_clock+0x97/0x110
schedule_hrtimeout_range+0x13/0x20
usleep_range_state+0x65/0x90
pci_set_low_power_state+0x17f/0x1f0
pci_set_power_state+0x49/0x250
pci_finish_runtime_suspend+0x4a/0x90
pci_pm_runtime_suspend+0xcb/0x1b0
__rpm_callback+0x48/0x120
rpm_callback+0x67/0x70
rpm_suspend+0x167/0x780
rpm_idle+0x25a/0x380
pm_runtime_work+0x93/0xc0
process_one_work+0x21c/0x3f0
} hitcount: 1
Totals:
Hits: 10
Entries: 7
Dropped: 0
2.2.3 Hist 觸發器“handlers”和“actions”¶
hist 觸發器“action”是一個函式，它在新增或更新直方圖條目時執行（在大多數情況下是有條件地執行）。
當新增或更新直方圖條目時，hist 觸發器“handler”決定是否實際呼叫相應的 action。
Hist 觸發器 handlers 和 actions 以通用形式配對在一起
<handler>.<action>
要為給定事件指定 handler.action 對，只需在 hist 觸發器規範中的冒號之間指定該 handler.action 對即可。
理論上，任何 handler 都可以與任何 action 組合，但實際上，並非支援所有 handler.action 組合； 如果不支援給定的 handler.action 組合，則 hist 觸發器將失敗並顯示 -EINVAL;
如果沒有明確指定，則預設的“handler.action”與一直以來的相同，只是簡單地更新與條目關聯的值集。 但是，某些應用程式可能希望在此時執行其他操作，例如生成另一個事件或比較並儲存最大值。
下面列出了支援的 handlers 和 actions，並在以下段落中更詳細地描述了每個 handler 和 action，並結合了一些常見且有用的 handler.action 組合的描述。
可用的 handlers 是
onmatch(matching.event) - 在任何新增或更新時呼叫 action
onmax(var) - 如果 var 超過當前最大值，則呼叫 action
onchange(var) - 如果 var 發生更改，則呼叫 action
可用的 actions 是
trace(<synthetic_event_name>,param list) - 生成合成事件
save(field,...) - 儲存當前事件欄位
snapshot() - 快照跟蹤緩衝區
以下常用的 handler.action 對可用
onmatch(matching.event).trace(<synthetic_event_name>,param list)
每當事件匹配並且直方圖條目將被新增或更新時，都會呼叫“onmatch(matching.event).trace(<synthetic_event_name>,param list)” hist 觸發器 action。 它會導致使用“param list”中給出的值生成命名的合成事件。 結果是生成一個合成事件，該事件由呼叫事件發生時這些變數中包含的值組成。 例如，如果合成事件名稱為“wakeup_latency”，則使用 onmatch(event).trace(wakeup_latency,arg1,arg2) 生成一個 wakeup_latency 事件。
還有一種等效的替代形式可用於生成合成事件。 在這種形式中，合成事件名稱被用作函式名稱。 例如，再次使用“wakeup_latency”合成事件名稱，將透過呼叫 wakeup_latency 事件（就像它是函式呼叫一樣）來生成該事件，並將事件欄位值作為引數傳入：onmatch(event).wakeup_latency(arg1,arg2)。 這種形式的語法是
onmatch(matching.event).<synthetic_event_name>(param list)
在任何一種情況下，“param list”都由一個或多個引數組成，這些引數可以是“matching.event”或目標事件上定義的變數或欄位。 在 param list 中指定的變數或欄位可以是完全限定的，也可以是不合格的。 如果變數指定為不合格的，則它必須在兩個事件之間是唯一的。 如果用作 param 的欄位名稱引用目標事件，則可以是不合格的，但如果它引用匹配事件，則必須是完全限定的。 完全限定名稱的形式為“system.event_name.$var_name”或“system.event_name.field”。
“matching.event”規範只是 onmatch() 功能的目標事件匹配的事件的完全限定事件名稱，形式為“system.event_name”。 比較兩個事件的直方圖鍵，以查詢事件是否匹配。 如果使用多個直方圖鍵，則所有鍵都必須按指定的順序匹配。
最後，“param list”中變數/欄位的數量和型別必須與正在生成的合成事件中欄位的數量和型別相匹配。
例如，下面定義了一個簡單的合成事件，並在呼叫合成事件時使用了在 sched_wakeup_new 事件上定義的變數作為引數。 在這裡，我們定義了合成事件
# echo 'wakeup_new_test pid_t pid' >> \ /sys/kernel/tracing/synthetic_events # cat /sys/kernel/tracing/synthetic_events wakeup_new_test pid_t pid以下 hist 觸發器既定義了缺失的 testpid 變數，又指定了一個 onmatch() action，該 action 在每次發生 sched_wakeup_new 事件時都會生成一個 wakeup_new_test 合成事件，由於“if comm == "cyclictest"”過濾器，這僅在可執行檔案是 cyclictest 時才會發生
# echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\ wakeup_new_test($testpid) if comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_wakeup_new/trigger或者，等效地，使用“trace”關鍵字語法
# echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\ trace(wakeup_new_test,$testpid) if comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_wakeup_new/trigger現在，基於這些事件建立和顯示直方圖只是在 tracing/events/synthetic 目錄中使用欄位和新合成事件的問題，與往常一樣
# echo 'hist:keys=pid:sort=pid' >> \ /sys/kernel/tracing/events/synthetic/wakeup_new_test/trigger執行“cyclictest”應導致 wakeup_new 事件生成 wakeup_new_test 合成事件，這應導致 wakeup_new_test 事件的 hist 檔案中出現直方圖輸出
# cat /sys/kernel/tracing/events/synthetic/wakeup_new_test/hist更典型的用法是使用兩個事件來計算延遲。 以下示例使用一組 hist 觸發器來生成“wakeup_latency”直方圖。
首先，我們定義一個“wakeup_latency”合成事件
# echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> \ /sys/kernel/tracing/synthetic_events接下來，我們指定每當看到 cyclictest 執行緒的 sched_waking 事件時，將時間戳儲存在“ts0”變數中
# echo 'hist:keys=$saved_pid:saved_pid=pid:ts0=common_timestamp.usecs \ if comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_waking/trigger然後，當相應的執行緒實際透過 sched_switch 事件排程到 CPU 上時（saved_pid 匹配 next_pid），計算延遲並將其與另一個變數和一個事件欄位一起使用，以生成一個 wakeup_latency 合成事件
# echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\ onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,\ $saved_pid,next_prio) if next_comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_switch/trigger我們還需要在 wakeup_latency 合成事件上建立一個直方圖，以便聚合生成的合成事件資料
# echo 'hist:keys=pid,prio,lat:sort=pid,lat' >> \ /sys/kernel/tracing/events/synthetic/wakeup_latency/trigger最後，一旦我們執行 cyclictest 以實際生成一些事件，我們就可以透過檢視 wakeup_latency 合成事件的 hist 檔案來檢視輸出
# cat /sys/kernel/tracing/events/synthetic/wakeup_latency/histonmax(var).save(field,...)
每當與直方圖條目關聯的“var”的值超過該變數中包含的當前最大值時，都會呼叫“onmax(var).save(field,...)” hist 觸發器 action。
最終結果是，如果“var”超過該 hist 觸發器條目的當前最大值，則將儲存指定為 onmax.save() params 的跟蹤事件欄位。 這允許儲存來自顯示新最大值的事件的上下文，以供以後參考。 顯示直方圖時，將列印顯示已儲存值的其他欄位。
例如，下面定義了幾個 hist 觸發器，一個用於 sched_waking，另一個用於 sched_switch，鍵為 pid。 每當發生 sched_waking 時，時間戳將儲存在與當前 pid 對應的條目中，並且當排程程式切換回該 pid 時，將計算時間戳差異。 如果結果延遲（儲存在 wakeup_lat 中）超過當前最大延遲，則會記錄在 save() 欄位中指定的值
# echo 'hist:keys=pid:ts0=common_timestamp.usecs \ if comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_waking/trigger # echo 'hist:keys=next_pid:\ wakeup_lat=common_timestamp.usecs-$ts0:\ onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) \ if next_comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_switch/trigger顯示直方圖時，最大值和與最大值對應的已儲存值將顯示在其餘欄位之後
# cat /sys/kernel/tracing/events/sched/sched_switch/hist { next_pid: 2255 } hitcount: 239 common_timestamp-ts0: 0 max: 27 next_comm: cyclictest prev_pid: 0 prev_prio: 120 prev_comm: swapper/1 { next_pid: 2256 } hitcount: 2355 common_timestamp-ts0: 0 max: 49 next_comm: cyclictest prev_pid: 0 prev_prio: 120 prev_comm: swapper/0 Totals: Hits: 12970 Entries: 2 Dropped: 0onmax(var).snapshot()
每當與直方圖條目關聯的“var”的值超過該變數中包含的當前最大值時，都會呼叫“onmax(var).snapshot()” hist 觸發器 action。
最終結果是，如果“var”超過任何 hist 觸發器條目的當前最大值，則跟蹤緩衝區的全域性快照將儲存在 tracing/snapshot 檔案中。
請注意，在這種情況下，最大值是當前跟蹤例項的全域性最大值，它是直方圖的所有 bucket 中的最大值。 顯示導致全域性最大值的特定跟蹤事件的鍵和全域性最大值本身，以及一條訊息，說明已拍攝快照以及在何處找到它。 使用者可以使用顯示的鍵資訊在直方圖中找到相應的 bucket，以獲取更多詳細資訊。
例如，下面定義了幾個 hist 觸發器，一個用於 sched_waking，另一個用於 sched_switch，鍵為 pid。 每當發生 sched_waking 事件時，時間戳將儲存在與當前 pid 對應的條目中，並且當排程程式切換回該 pid 時，將計算時間戳差異。 如果結果延遲（儲存在 wakeup_lat 中）超過當前最大延遲，則會拍攝快照。 作為設定的一部分，還會啟用所有排程程式事件，這些事件將在某個時間拍攝快照時顯示在快照中
# echo 1 > /sys/kernel/tracing/events/sched/enable # echo 'hist:keys=pid:ts0=common_timestamp.usecs \ if comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_waking/trigger # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \ onmax($wakeup_lat).save(next_prio,next_comm,prev_pid,prev_prio, \ prev_comm):onmax($wakeup_lat).snapshot() \ if next_comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_switch/trigger顯示直方圖時，對於每個 bucket，最大值和與最大值對應的已儲存值將顯示在其餘欄位之後。
如果拍攝了快照，還會有一條訊息指示，以及觸發全域性最大值的值和事件
# cat /sys/kernel/tracing/events/sched/sched_switch/hist { next_pid: 2101 } hitcount: 200 max: 52 next_prio: 120 next_comm: cyclictest \ prev_pid: 0 prev_prio: 120 prev_comm: swapper/6 { next_pid: 2103 } hitcount: 1326 max: 572 next_prio: 19 next_comm: cyclictest \ prev_pid: 0 prev_prio: 120 prev_comm: swapper/1 { next_pid: 2102 } hitcount: 1982 \ max: 74 next_prio: 19 next_comm: cyclictest \ prev_pid: 0 prev_prio: 120 prev_comm: swapper/5 Snapshot taken (see tracing/snapshot). Details: triggering value { onmax($wakeup_lat) }: 572 \ triggered by event with key: { next_pid: 2103 } Totals: Hits: 3508 Entries: 3 Dropped: 0在上面的例子中，觸發全域性最大值的事件的鍵為 next_pid == 2103。如果檢視以 2103 為鍵的 bucket，你將找到與該 bucket 的區域性最大值一起 save() 的附加值，該值應與全域性最大值相同（因為它是觸發全域性快照的相同值）。
最後，檢視快照資料應在結尾處或附近顯示觸發快照的事件（在本例中，您可以驗證 sched_waking 和 sched_switch 事件之間的時間戳，該時間戳應與全域性最大值中顯示的時間匹配）
# cat /sys/kernel/tracing/snapshot <...>-2103 [005] d..3 309.873125: sched_switch: prev_comm=cyclictest prev_pid=2103 prev_prio=19 prev_state=D ==> next_comm=swapper/5 next_pid=0 next_prio=120 <idle>-0 [005] d.h3 309.873611: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005 <idle>-0 [005] dNh4 309.873613: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005 <idle>-0 [005] d..3 309.873616: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=cyclictest next_pid=2102 next_prio=19 <...>-2102 [005] d..3 309.873625: sched_switch: prev_comm=cyclictest prev_pid=2102 prev_prio=19 prev_state=D ==> next_comm=swapper/5 next_pid=0 next_prio=120 <idle>-0 [005] d.h3 309.874624: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005 <idle>-0 [005] dNh4 309.874626: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005 <idle>-0 [005] dNh3 309.874628: sched_waking: comm=cyclictest pid=2103 prio=19 target_cpu=005 <idle>-0 [005] dNh4 309.874630: sched_wakeup: comm=cyclictest pid=2103 prio=19 target_cpu=005 <idle>-0 [005] d..3 309.874633: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=cyclictest next_pid=2102 next_prio=19 <idle>-0 [004] d.h3 309.874757: sched_waking: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004 <idle>-0 [004] dNh4 309.874762: sched_wakeup: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004 <idle>-0 [004] d..3 309.874766: sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=gnome-terminal- next_pid=1699 next_prio=120 gnome-terminal--1699 [004] d.h2 309.874941: sched_stat_runtime: comm=gnome-terminal- pid=1699 runtime=180706 [ns] vruntime=1126870572 [ns] <idle>-0 [003] d.s4 309.874956: sched_waking: comm=rcu_sched pid=9 prio=120 target_cpu=007 <idle>-0 [003] d.s5 309.874960: sched_wake_idle_without_ipi: cpu=7 <idle>-0 [003] d.s5 309.874961: sched_wakeup: comm=rcu_sched pid=9 prio=120 target_cpu=007 <idle>-0 [007] d..3 309.874963: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=rcu_sched next_pid=9 next_prio=120 rcu_sched-9 [007] d..3 309.874973: sched_stat_runtime: comm=rcu_sched pid=9 runtime=13646 [ns] vruntime=22531430286 [ns] rcu_sched-9 [007] d..3 309.874978: sched_switch: prev_comm=rcu_sched prev_pid=9 prev_prio=120 prev_state=R+ ==> next_comm=swapper/7 next_pid=0 next_prio=120 <...>-2102 [005] d..4 309.874994: sched_migrate_task: comm=cyclictest pid=2103 prio=19 orig_cpu=5 dest_cpu=1 <...>-2102 [005] d..4 309.875185: sched_wake_idle_without_ipi: cpu=1 <idle>-0 [001] d..3 309.875200: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=cyclictest next_pid=2103 next_prio=19onchange(var).save(field,...)
每當與直方圖條目關聯的“var”的值發生更改時，都會呼叫“onchange(var).save(field,...)” hist 觸發器 action。
最終結果是，如果“var”針對該 hist 觸發器條目發生更改，則將儲存指定為 onchange.save() params 的跟蹤事件欄位。 這允許儲存來自更改值的事件的上下文，以供以後參考。 顯示直方圖時，將列印顯示已儲存值的其他欄位。
onchange(var).snapshot()
每當與直方圖條目關聯的“var”的值發生更改時，都會呼叫“onchange(var).snapshot()” hist 觸發器 action。
最終結果是，如果“var”針對任何 hist 觸發器條目發生更改，則跟蹤緩衝區的全域性快照將儲存在 tracing/snapshot 檔案中。
請注意，在這種情況下，更改的值是與當前跟蹤例項關聯的全域性變數。 顯示導致值更改的特定跟蹤事件的鍵和全域性值本身，以及一條訊息，說明已拍攝快照以及在何處找到它。 使用者可以使用顯示的鍵資訊在直方圖中找到相應的 bucket，以獲取更多詳細資訊。
例如，下面在 tcp_probe 事件上定義了一個 hist 觸發器，鍵為 dport。 每當發生 tcp_probe 事件時，都會根據儲存在 $cwnd 變數中的當前值檢查 cwnd 欄位。 如果值已更改，則會拍攝快照。 作為設定的一部分，還會啟用所有排程程式和 tcp 事件，這些事件將在某個時間拍攝快照時顯示在快照中
# echo 1 > /sys/kernel/tracing/events/sched/enable # echo 1 > /sys/kernel/tracing/events/tcp/enable # echo 'hist:keys=dport:cwnd=snd_cwnd: \ onchange($cwnd).save(snd_wnd,srtt,rcv_wnd): \ onchange($cwnd).snapshot()' >> \ /sys/kernel/tracing/events/tcp/tcp_probe/trigger顯示直方圖時，對於每個 bucket，跟蹤的值和與該值對應的已儲存值將顯示在其餘欄位之後。
如果拍攝了快照，還會有一條訊息指示，以及觸發快照的值和事件
# cat /sys/kernel/tracing/events/tcp/tcp_probe/hist { dport: 1521 } hitcount: 8 changed: 10 snd_wnd: 35456 srtt: 154262 rcv_wnd: 42112 { dport: 80 } hitcount: 23 changed: 10 snd_wnd: 28960 srtt: 19604 rcv_wnd: 29312 { dport: 9001 } hitcount: 172 changed: 10 snd_wnd: 48384 srtt: 260444 rcv_wnd: 55168 { dport: 443 } hitcount: 211 changed: 10 snd_wnd: 26960 srtt: 17379 rcv_wnd: 28800 Snapshot taken (see tracing/snapshot). Details: triggering value { onchange($cwnd) }: 10 triggered by event with key: { dport: 80 } Totals: Hits: 414 Entries: 4 Dropped: 0在上面的例子中，觸發快照的事件的鍵為 dport == 80。如果檢視以 80 為鍵的 bucket，你將找到與該 bucket 的更改值一起 save() 的附加值，該值應與全域性更改值相同（因為它是觸發全域性快照的相同值）。
最後，檢視快照資料應在結尾處或附近顯示觸發快照的事件
# cat /sys/kernel/tracing/snapshot gnome-shell-1261 [006] dN.3 49.823113: sched_stat_runtime: comm=gnome-shell pid=1261 runtime=49347 [ns] vruntime=1835730389 [ns] kworker/u16:4-773 [003] d..3 49.823114: sched_switch: prev_comm=kworker/u16:4 prev_pid=773 prev_prio=120 prev_state=R+ ==> next_comm=kworker/3:2 next_pid=135 next_prio=120 gnome-shell-1261 [006] d..3 49.823114: sched_switch: prev_comm=gnome-shell prev_pid=1261 prev_prio=120 prev_state=R+ ==> next_comm=kworker/6:2 next_pid=387 next_prio=120 kworker/3:2-135 [003] d..3 49.823118: sched_stat_runtime: comm=kworker/3:2 pid=135 runtime=5339 [ns] vruntime=17815800388 [ns] kworker/6:2-387 [006] d..3 49.823120: sched_stat_runtime: comm=kworker/6:2 pid=387 runtime=9594 [ns] vruntime=14589605367 [ns] kworker/6:2-387 [006] d..3 49.823122: sched_switch: prev_comm=kworker/6:2 prev_pid=387 prev_prio=120 prev_state=R+ ==> next_comm=gnome-shell next_pid=1261 next_prio=120 kworker/3:2-135 [003] d..3 49.823123: sched_switch: prev_comm=kworker/3:2 prev_pid=135 prev_prio=120 prev_state=T ==> next_comm=swapper/3 next_pid=0 next_prio=120 <idle>-0 [004] ..s7 49.823798: tcp_probe: src=10.0.0.10:54326 dest=23.215.104.193:80 mark=0x0 length=32 snd_nxt=0xe3ae2ff5 snd_una=0xe3ae2ecd snd_cwnd=10 ssthresh=2147483647 snd_wnd=28960 srtt=19604 rcv_wnd=29312
3. 使用者空間建立觸發器¶
寫入 /sys/kernel/tracing/trace_marker 會寫入 ftrace 環形緩衝區。 透過寫入 /sys/kernel/tracing/events/ftrace/print/ 中的觸發器檔案，這也可以像一個事件一樣工作
在 cyclictest 休眠之前和喚醒之後修改它以寫入 trace_marker 檔案，如下所示
static void traceputs(char *str)
{
/* tracemark_fd is the trace_marker file descriptor */
if (tracemark_fd < 0)
return;
/* write the tracemark message */
write(tracemark_fd, str, strlen(str));
}
稍後新增類似的內容
traceputs("start");
clock_nanosleep(...);
traceputs("end");
我們可以從中製作直方圖
# cd /sys/kernel/tracing
# echo 'latency u64 lat' > synthetic_events
# echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/trigger
# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) if buf == "end"' >> events/ftrace/print/trigger
# echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
上面建立了一個名為“latency”的合成事件和兩個針對 trace_marker 的直方圖，一個在“start”寫入 trace_marker 檔案時觸發，另一個在“end”寫入時觸發。 如果 pids 匹配，則它將呼叫“latency”合成事件，並將計算出的延遲作為其引數。 最後，將直方圖新增到延遲合成事件，以記錄計算出的延遲以及 pid。
現在使用以下命令執行 cyclictest
# ./cyclictest -p80 -d0 -i250 -n -a -t --tracemark -b 1000
-p80 : run threads at priority 80
-d0 : have all threads run at the same interval
-i250 : start the interval at 250 microseconds (all threads will do this)
-n : sleep with nanosleep
-a : affine all threads to a separate CPU
-t : one thread per available CPU
--tracemark : enable trace mark writing
-b 1000 : stop if any latency is greater than 1000 microseconds
注意，-b 1000 僅用於使 --tracemark 可用。
然後，我們可以使用以下命令檢視由此建立的直方圖
# cat events/synthetic/latency/hist
# event histogram
#
# trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
#
{ lat: 107, common_pid: 2039 } hitcount: 1
{ lat: 122, common_pid: 2041 } hitcount: 1
{ lat: 166, common_pid: 2039 } hitcount: 1
{ lat: 174, common_pid: 2039 } hitcount: 1
{ lat: 194, common_pid: 2041 } hitcount: 1
{ lat: 196, common_pid: 2036 } hitcount: 1
{ lat: 197, common_pid: 2038 } hitcount: 1
{ lat: 198, common_pid: 2039 } hitcount: 1
{ lat: 199, common_pid: 2039 } hitcount: 1
{ lat: 200, common_pid: 2041 } hitcount: 1
{ lat: 201, common_pid: 2039 } hitcount: 2
{ lat: 202, common_pid: 2038 } hitcount: 1
{ lat: 202, common_pid: 2043 } hitcount: 1
{ lat: 203, common_pid: 2039 } hitcount: 1
{ lat: 203, common_pid: 2036 } hitcount: 1
{ lat: 203, common_pid: 2041 } hitcount: 1
{ lat: 206, common_pid: 2038 } hitcount: 2
{ lat: 207, common_pid: 2039 } hitcount: 1
{ lat: 207, common_pid: 2036 } hitcount: 1
{ lat: 208, common_pid: 2040 } hitcount: 1
{ lat: 209, common_pid: 2043 } hitcount: 1
{ lat: 210, common_pid: 2039 } hitcount: 1
{ lat: 211, common_pid: 2039 } hitcount: 4
{ lat: 212, common_pid: 2043 } hitcount: 1
{ lat: 212, common_pid: 2039 } hitcount: 2
{ lat: 213, common_pid: 2039 } hitcount: 1
{ lat: 214, common_pid: 2038 } hitcount: 1
{ lat: 214, common_pid: 2039 } hitcount: 2
{ lat: 214, common_pid: 2042 } hitcount: 1
{ lat: 215, common_pid: 2039 } hitcount: 1
{ lat: 217, common_pid: 2036 } hitcount: 1
{ lat: 217, common_pid: 2040 } hitcount: 1
{ lat: 217, common_pid: 2039 } hitcount: 1
{ lat: 218, common_pid: 2039 } hitcount: 6
{ lat: 219, common_pid: 2039 } hitcount: 9
{ lat: 220, common_pid: 2039 } hitcount: 11
{ lat: 221, common_pid: 2039 } hitcount: 5
{ lat: 221, common_pid: 2042 } hitcount: 1
{ lat: 222, common_pid: 2039 } hitcount: 7
{ lat: 223, common_pid: 2036 } hitcount: 1
{ lat: 223, common_pid: 2039 } hitcount: 3
{ lat: 224, common_pid: 2039 } hitcount: 4
{ lat: 224, common_pid: 2037 } hitcount: 1
{ lat: 224, common_pid: 2036 } hitcount: 2
{ lat: 225, common_pid: 2039 } hitcount: 5
{ lat: 225, common_pid: 2042 } hitcount: 1
{ lat: 226, common_pid: 2039 } hitcount: 7
{ lat: 226, common_pid: 2036 } hitcount: 4
{ lat: 227, common_pid: 2039 } hitcount: 6
{ lat: 227, common_pid: 2036 } hitcount: 12
{ lat: 227, common_pid: 2043 } hitcount: 1
{ lat: 228, common_pid: 2039 } hitcount: 7
{ lat: 228, common_pid: 2036 } hitcount: 14
{ lat: 229, common_pid: 2039 } hitcount: 9
{ lat: 229, common_pid: 2036 } hitcount: 8
{ lat: 229, common_pid: 2038 } hitcount: 1
{ lat: 230, common_pid: 2039 } hitcount: 11
{ lat: 230, common_pid: 2036 } hitcount: 6
{ lat: 230, common_pid: 2043 } hitcount: 1
{ lat: 230, common_pid: 2042 } hitcount: 2
{ lat: 231, common_pid: 2041 } hitcount: 1
{ lat: 231, common_pid: 2036 } hitcount: 6
{ lat: 231, common_pid: 2043 } hitcount: 1
{ lat: 231, common_pid: 2039 } hitcount: 8
{ lat: 232, common_pid: 2037 } hitcount: 1
{ lat: 232, common_pid: 2039 } hitcount: 6
{ lat: 232, common_pid: 2040 } hitcount: 2
{ lat: 232, common_pid: 2036 } hitcount: 5
{ lat: 232, common_pid: 2043 } hitcount: 1
{ lat: 233, common_pid: 2036 } hitcount: 5
{ lat: 233, common_pid: 2039 } hitcount: 11
{ lat: 234, common_pid: 2039 } hitcount: 4
{ lat: 234, common_pid: 2038 } hitcount: 2
{ lat: 234, common_pid: 2043 } hitcount: 2
{ lat: 234, common_pid: 2036 } hitcount: 11
{ lat: 234, common_pid: 2040 } hitcount: 1
{ lat: 235, common_pid: 2037 } hitcount: 2
{ lat: 235, common_pid: 2036 } hitcount: 8
{ lat: 235, common_pid: 2043 } hitcount: 2
{ lat: 235, common_pid: 2039 } hitcount: 5
{ lat: 235, common_pid: 2042 } hitcount: 2
{ lat: 235, common_pid: 2040 } hitcount: 4
{ lat: 235, common_pid: 2041 } hitcount: 1
{ lat: 236, common_pid: 2036 } hitcount: 7
{ lat: 236, common_pid: 2037 } hitcount: 1
{ lat: 236, common_pid: 2041 } hitcount: 5
{ lat: 236, common_pid: 2039 } hitcount: 3
{ lat: 236, common_pid: 2043 } hitcount: 9
{ lat: 236, common_pid: 2040 } hitcount: 7
{ lat: 237, common_pid: 2037 } hitcount: 1
{ lat: 237, common_pid: 2040 } hitcount: 1
{ lat: 237, common_pid: 2036 } hitcount: 9
{ lat: 237, common_pid: 2039 } hitcount: 3
{ lat: 237, common_pid: 2043 } hitcount: 8
{ lat: 237, common_pid: 2042 } hitcount: 2
{ lat: 237, common_pid: 2041 } hitcount: 2
{ lat: 238, common_pid: 2043 } hitcount: 10
{ lat: 238, common_pid: 2040 } hitcount: 1
{ lat: 238, common_pid: 2037 } hitcount: 9
{ lat: 238, common_pid: 2038 } hitcount: 1
{ lat: 238, common_pid: 2039 } hitcount: 1
{ lat: 238, common_pid: 2042 } hitcount: 3
{ lat: 238, common_pid: 2036 } hitcount: 7
{ lat: 239, common_pid: 2041 } hitcount: 1
{ lat: 239, common_pid: 2043 } hitcount: 11
{ lat: 239, common_pid: 2037 } hitcount: 11
{ lat: 239, common_pid: 2038 } hitcount: 6
{ lat: 239, common_pid: 2036 } hitcount: 7
{ lat: 239, common_pid: 2040 } hitcount: 1
{ lat: 239, common_pid: 2042 } hitcount: 9
{ lat: 240, common_pid: 2037 } hitcount: 29
{ lat: 240, common_pid: 2043 } hitcount: 15
{ lat: 240, common_pid: 2040 } hitcount: 44
{ lat: 240, common_pid: 2039 } hitcount: 1
{ lat: 240, common_pid: 2041 } hitcount: 2
{ lat: 240, common_pid: 2038 } hitcount: 1
{ lat: 240, common_pid: 2036 } hitcount: 10
{ lat: 240, common_pid: 2042 } hitcount: 13
{ lat: 241, common_pid: 2036 } hitcount: 21
{ lat: 241, common_pid: 2041 } hitcount: 36
{ lat: 241, common_pid: 2037 } hitcount: 34
{ lat: 241, common_pid: 2042 } hitcount: 14
{ lat: 241, common_pid: 2040 } hitcount: 94
{ lat: 241, common_pid: 2039 } hitcount: 12
{ lat: 241, common_pid: 2038 } hitcount: 2
{ lat: 241, common_pid: 2043 } hitcount: 28
{ lat: 242, common_pid: 2040 } hitcount: 109
{ lat: 242, common_pid: 2041 } hitcount: 506
{ lat: 242, common_pid: 2039 } hitcount: 155
{ lat: 242, common_pid: 2042 } hitcount: 21
{ lat: 242, common_pid: 2037 } hitcount: 52
{ lat: 242, common_pid: 2043 } hitcount: 21
{ lat: 242, common_pid: 2036 } hitcount: 16
{ lat: 242, common_pid: 2038 } hitcount: 156
{ lat: 243, common_pid: 2037 } hitcount: 46
{ lat: 243, common_pid: 2039 } hitcount: 40
{ lat: 243, common_pid: 2042 } hitcount: 119
{ lat: 243, common_pid: 2041 } hitcount: 611
{ lat: 243, common_pid: 2036 } hitcount: 69
{ lat: 243, common_pid: 2038 } hitcount: 784
{ lat: 243, common_pid: 2040 } hitcount: 323
{ lat: 243, common_pid: 2043 } hitcount: 14
{ lat: 244, common_pid: 2043 } hitcount: 35
{ lat: 244, common_pid: 2042 } hitcount: 305
{ lat: 244, common_pid: 2039 } hitcount: 8
{ lat: 244, common_pid: 2040 } hitcount: 4515
{ lat: 244, common_pid: 2038 } hitcount: 371
{ lat: 244, common_pid: 2037 } hitcount: 31
{ lat: 244, common_pid: 2036 } hitcount: 114
{ lat: 244, common_pid: 2041 } hitcount: 3396
{ lat: 245, common_pid: 2036 } hitcount: 700
{ lat: 245, common_pid: 2041 } hitcount: 2772
{ lat: 245, common_pid: 2037 } hitcount: 268
{ lat: 245, common_pid: 2039 } hitcount: 472
{ lat: 245, common_pid: 2038 } hitcount: 2758
{ lat: 245, common_pid: 2042 } hitcount: 3833
{ lat: 245, common_pid: 2040 } hitcount: 3105
{ lat: 245, common_pid: 2043 } hitcount: 645
{ lat: 246, common_pid: 2038 } hitcount: 3451
{ lat: 246, common_pid: 2041 } hitcount: 142
{ lat: 246, common_pid: 2037 } hitcount: 5101
{ lat: 246, common_pid: 2040 } hitcount: 68
{ lat: 246, common_pid: 2043 } hitcount: 5099
{ lat: 246, common_pid: 2039 } hitcount: 5608
{ lat: 246, common_pid: 2042 } hitcount: 3723
{ lat: 246, common_pid: 2036 } hitcount: 4738
{ lat: 247, common_pid: 2042 } hitcount: 312
{ lat: 247, common_pid: 2043 } hitcount: 2385
{ lat: 247, common_pid: 2041 } hitcount: 452
{ lat: 247, common_pid: 2038 } hitcount: 792
{ lat: 247, common_pid: 2040 } hitcount: 78
{ lat: 247, common_pid: 2036 } hitcount: 2375
{ lat: 247, common_pid: 2039 } hitcount: 1834
{ lat: 247, common_pid: 2037 } hitcount: 2655
{ lat: 248, common_pid: 2037 } hitcount: 36
{ lat: 248, common_pid: 2042 } hitcount: 11
{ lat: 248, common_pid: 2038 } hitcount: 122
{ lat: 248, common_pid: 2036 } hitcount: 135
{ lat: 248, common_pid: 2039 } hitcount: 26
{ lat: 248, common_pid: 2041 } hitcount: 503
{ lat: 248, common_pid: 2043 } hitcount: 66
{ lat: 248, common_pid: 2040 } hitcount: 46
{ lat: 249, common_pid: 2037 } hitcount: 29
{ lat: 249, common_pid: 2038 } hitcount: 1
{ lat: 249, common_pid: 2043 } hitcount: 29
{ lat: 249, common_pid: 2039 } hitcount: 8
{ lat: 249, common_pid: 2042 } hitcount: 56
{ lat: 249, common_pid: 2040 } hitcount: 27
{ lat: 249, common_pid: 2041 } hitcount: 11
{ lat: 249, common_pid: 2036 } hitcount: 27
{ lat: 250, common_pid: 2038 } hitcount: 1
{ lat: 250, common_pid: 2036 } hitcount: 30
{ lat: 250, common_pid: 2040 } hitcount: 19
{ lat: 250, common_pid: 2043 } hitcount: 22
{ lat: 250, common_pid: 2042 } hitcount: 20
{ lat: 250, common_pid: 2041 } hitcount: 1
{ lat: 250, common_pid: 2039 } hitcount: 6
{ lat: 250, common_pid: 2037 } hitcount: 48
{ lat: 251, common_pid: 2037 } hitcount: 43
{ lat: 251, common_pid: 2039 } hitcount: 1
{ lat: 251, common_pid: 2036 } hitcount: 12
{ lat: 251, common_pid: 2042 } hitcount: 2
{ lat: 251, common_pid: 2041 } hitcount: 1
{ lat: 251, common_pid: 2043 } hitcount: 15
{ lat: 251, common_pid: 2040 } hitcount: 3
{ lat: 252, common_pid: 2040 } hitcount: 1
{ lat: 252, common_pid: 2036 } hitcount: 12
{ lat: 252, common_pid: 2037 } hitcount: 21
{ lat: 252, common_pid: 2043 } hitcount: 14
{ lat: 253, common_pid: 2037 } hitcount: 21
{ lat: 253, common_pid: 2039 } hitcount: 2
{ lat: 253, common_pid: 2036 } hitcount: 9
{ lat: 253, common_pid: 2043 } hitcount: 6
{ lat: 253, common_pid: 2040 } hitcount: 1
{ lat: 254, common_pid: 2036 } hitcount: 8
{ lat: 254, common_pid: 2043 } hitcount: 3
{ lat: 254, common_pid: 2041 } hitcount: 1
{ lat: 254, common_pid: 2042 } hitcount: 1
{ lat: 254, common_pid: 2039 } hitcount: 1
{ lat: 254, common_pid: 2037 } hitcount: 12
{ lat: 255, common_pid: 2043 } hitcount: 1
{ lat: 255, common_pid: 2037 } hitcount: 2
{ lat: 255, common_pid: 2036 } hitcount: 2
{ lat: 255, common_pid: 2039 } hitcount: 8
{ lat: 256, common_pid: 2043 } hitcount: 1
{ lat: 256, common_pid: 2036 } hitcount: 4
{ lat: 256, common_pid: 2039 } hitcount: 6
{ lat: 257, common_pid: 2039 } hitcount: 5
{ lat: 257, common_pid: 2036 } hitcount: 4
{ lat: 258, common_pid: 2039 } hitcount: 5
{ lat: 258, common_pid: 2036 } hitcount: 2
{ lat: 259, common_pid: 2036 } hitcount: 7
{ lat: 259, common_pid: 2039 } hitcount: 7
{ lat: 260, common_pid: 2036 } hitcount: 8
{ lat: 260, common_pid: 2039 } hitcount: 6
{ lat: 261, common_pid: 2036 } hitcount: 5
{ lat: 261, common_pid: 2039 } hitcount: 7
{ lat: 262, common_pid: 2039 } hitcount: 5
{ lat: 262, common_pid: 2036 } hitcount: 5
{ lat: 263, common_pid: 2039 } hitcount: 7
{ lat: 263, common_pid: 2036 } hitcount: 7
{ lat: 264, common_pid: 2039 } hitcount: 9
{ lat: 264, common_pid: 2036 } hitcount: 9
{ lat: 265, common_pid: 2036 } hitcount: 5
{ lat: 265, common_pid: 2039 } hitcount: 1
{ lat: 266, common_pid: 2036 } hitcount: 1
{ lat: 266, common_pid: 2039 } hitcount: 3
{ lat: 267, common_pid: 2036 } hitcount: 1
{ lat: 267, common_pid: 2039 } hitcount: 3
{ lat: 268, common_pid: 2036 } hitcount: 1
{ lat: 268, common_pid: 2039 } hitcount: 6
{ lat: 269, common_pid: 2036 } hitcount: 1
{ lat: 269, common_pid: 2043 } hitcount: 1
{ lat: 269, common_pid: 2039 } hitcount: 2
{ lat: 270, common_pid: 2040 } hitcount: 1
{ lat: 270, common_pid: 2039 } hitcount: 6
{ lat: 271, common_pid: 2041 } hitcount: 1
{ lat: 271, common_pid: 2039 } hitcount: 5
{ lat: 272, common_pid: 2039 } hitcount: 10
{ lat: 273, common_pid: 2039 } hitcount: 8
{ lat: 274, common_pid: 2039 } hitcount: 2
{ lat: 275, common_pid: 2039 } hitcount: 1
{ lat: 276, common_pid: 2039 } hitcount: 2
{ lat: 276, common_pid: 2037 } hitcount: 1
{ lat: 276, common_pid: 2038 } hitcount: 1
{ lat: 277, common_pid: 2039 } hitcount: 1
{ lat: 277, common_pid: 2042 } hitcount: 1
{ lat: 278, common_pid: 2039 } hitcount: 1
{ lat: 279, common_pid: 2039 } hitcount: 4
{ lat: 279, common_pid: 2043 } hitcount: 1
{ lat: 280, common_pid: 2039 } hitcount: 3
{ lat: 283, common_pid: 2036 } hitcount: 2
{ lat: 284, common_pid: 2039 } hitcount: 1
{ lat: 284, common_pid: 2043 } hitcount: 1
{ lat: 288, common_pid: 2039 } hitcount: 1
{ lat: 289, common_pid: 2039 } hitcount: 1
{ lat: 300, common_pid: 2039 } hitcount: 1
{ lat: 384, common_pid: 2039 } hitcount: 1
Totals:
Hits: 67625
Entries: 278
Dropped: 0
請注意，寫入操作是在休眠周圍進行的，因此理想情況下，它們都將是 250 微秒。 如果您想知道為什麼有幾個小於 250 微秒，那是因為 cyclictest 的工作方式是，如果一個迭代延遲到達，下一個迭代會將計時器設定為小於 250 的值來喚醒。 也就是說，如果一個迭代延遲了 50 微秒，則下一次喚醒將在 200 微秒時進行。
但這可以很容易地在使用者空間中完成。 為了使它更有趣，我們可以將核心中發生的事件與 trace_marker 混合在一起的直方圖
# cd /sys/kernel/tracing
# echo 'latency u64 lat' > synthetic_events
# echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat) if buf == "end"' > events/ftrace/print/trigger
# echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
這次的不同之處在於，不使用 trace_marker 來啟動延遲，而是使用 sched_waking 事件，將 trace_marker 寫入的 common_pid 與 sched_waking 喚醒的 pid 匹配。
使用相同的引數再次執行 cyclictest 後，我們現在有
# cat events/synthetic/latency/hist
# event histogram
#
# trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
#
{ lat: 7, common_pid: 2302 } hitcount: 640
{ lat: 7, common_pid: 2299 } hitcount: 42
{ lat: 7, common_pid: 2303 } hitcount: 18
{ lat: 7, common_pid: 2305 } hitcount: 166
{ lat: 7, common_pid: 2306 } hitcount: 1
{ lat: 7, common_pid: 2301 } hitcount: 91
{ lat: 7, common_pid: 2300 } hitcount: 17
{ lat: 8, common_pid: 2303 } hitcount: 8296
{ lat: 8, common_pid: 2304 } hitcount: 6864
{ lat: 8, common_pid: 2305 } hitcount: 9464
{ lat: 8, common_pid: 2301 } hitcount: 9213
{ lat: 8, common_pid: 2306 } hitcount: 6246
{ lat: 8, common_pid: 2302 } hitcount: 8797
{ lat: 8, common_pid: 2299 } hitcount: 8771
{ lat: 8, common_pid: 2300 } hitcount: 8119
{ lat: 9, common_pid: 2305 } hitcount: 1519
{ lat: 9, common_pid: 2299 } hitcount: 2346
{ lat: 9, common_pid: 2303 } hitcount: 2841
{ lat: 9, common_pid: 2301 } hitcount: 1846
{ lat: 9, common_pid: 2304 } hitcount: 3861
{ lat: 9, common_pid: 2302 } hitcount: 1210
{ lat: 9, common_pid: 2300 } hitcount: 2762
{ lat: 9, common_pid: 2306 } hitcount: 4247
{ lat: 10, common_pid: 2299 } hitcount: 16
{ lat: 10, common_pid: 2306 } hitcount: 333
{ lat: 10, common_pid: 2303 } hitcount: 16
{ lat: 10, common_pid: 2304 } hitcount: 168
{ lat: 10, common_pid: 2302 } hitcount: 240
{ lat: 10, common_pid: 2301 } hitcount: 28
{ lat: 10, common_pid: 2300 } hitcount: 95
{ lat: 10, common_pid: 2305 } hitcount: 18
{ lat: 11, common_pid: 2303 } hitcount: 5
{ lat: 11, common_pid: 2305 } hitcount: 8
{ lat: 11, common_pid: 2306 } hitcount: 221
{ lat: 11, common_pid: 2302 } hitcount: 76
{ lat: 11, common_pid: 2304 } hitcount: 26
{ lat: 11, common_pid: 2300 } hitcount: 125
{ lat: 11, common_pid: 2299 } hitcount: 2
{ lat: 12, common_pid: 2305 } hitcount: 3
{ lat: 12, common_pid: 2300 } hitcount: 6
{ lat: 12, common_pid: 2306 } hitcount: 90
{ lat: 12, common_pid: 2302 } hitcount: 4
{ lat: 12, common_pid: 2303 } hitcount: 1
{ lat: 12, common_pid: 2304 } hitcount: 122
{ lat: 13, common_pid: 2300 } hitcount: 12
{ lat: 13, common_pid: 2301 } hitcount: 1
{ lat: 13, common_pid: 2306 } hitcount: 32
{ lat: 13, common_pid: 2302 } hitcount: 5
{ lat: 13, common_pid: 2305 } hitcount: 1
{ lat: 13, common_pid: 2303 } hitcount: 1
{ lat: 13, common_pid: 2304 } hitcount: 61
{ lat: 14, common_pid: 2303 } hitcount: 4
{ lat: 14, common_pid: 2306 } hitcount: 5
{ lat: 14, common_pid: 2305 } hitcount: 4
{ lat: 14, common_pid: 2304 } hitcount: 62
{ lat: 14, common_pid: 2302 } hitcount: 19
{ lat: 14, common_pid: 2300 } hitcount: 33
{ lat: 14, common_pid: 2299 } hitcount: 1
{ lat: 14, common_pid: 2301 } hitcount: 4
{ lat: 15, common_pid: 2305 } hitcount: 1
{ lat: 15, common_pid: 2302 } hitcount: 25
{ lat: 15, common_pid: 2300 } hitcount: 11
{ lat: 15, common_pid: 2299 } hitcount: 5
{ lat: 15, common_pid: 2301 } hitcount: 1
{ lat: 15, common_pid: 2304 } hitcount: 8
{ lat: 15, common_pid: 2303 } hitcount: 1
{ lat: 15, common_pid: 2306 } hitcount: 6
{ lat: 16, common_pid: 2302 } hitcount: 31
{ lat: 16, common_pid: 2306 } hitcount: 3
{ lat: 16, common_pid: 2300 } hitcount: 5
{ lat: 17, common_pid: 2302 } hitcount: 6
{ lat: 17, common_pid: 2303 } hitcount: 1
{ lat: 18, common_pid: 2304 } hitcount: 1
{ lat: 18, common_pid: 2302 } hitcount: 8
{ lat: 18, common_pid: 2299 } hitcount: 1
{ lat: 18, common_pid: 2301 } hitcount: 1
{ lat: 19, common_pid: 2303 } hitcount: 4
{ lat: 19, common_pid: 2304 } hitcount: 5
{ lat: 19, common_pid: 2302 } hitcount: 4
{ lat: 19, common_pid: 2299 } hitcount: 3
{ lat: 19, common_pid: 2306 } hitcount: 1
{ lat: 19, common_pid: 2300 } hitcount: 4
{ lat: 19, common_pid: 2305 } hitcount: 5
{ lat: 20, common_pid: 2299 } hitcount: 2
{ lat: 20, common_pid: 2302 } hitcount: 3
{ lat: 20, common_pid: 2305 } hitcount: 1
{ lat: 20, common_pid: 2300 } hitcount: 2
{ lat: 20, common_pid: 2301 } hitcount: 2
{ lat: 20, common_pid: 2303 } hitcount: 3
{ lat: 21, common_pid: 2305 } hitcount: 1
{ lat: 21, common_pid: 2299 } hitcount: 5
{ lat: 21, common_pid: 2303 } hitcount: 4
{ lat: 21, common_pid: 2302 } hitcount: 7
{ lat: 21, common_pid: 2300 } hitcount: 1
{ lat: 21, common_pid: 2301 } hitcount: 5
{ lat: 21, common_pid: 2304 } hitcount: 2
{ lat: 22, common_pid: 2302 } hitcount: 5
{ lat: 22, common_pid: 2303 } hitcount: 1
{ lat: 22, common_pid: 2306 } hitcount: 3
{ lat: 22, common_pid: 2301 } hitcount: 2
{ lat: 22, common_pid: 2300 } hitcount: 1
{ lat: 22, common_pid: 2299 } hitcount: 1
{ lat: 22, common_pid: 2305 } hitcount: 1
{ lat: 22, common_pid: 2304 } hitcount: 1
{ lat: 23, common_pid: 2299 } hitcount: 1
{ lat: 23, common_pid: 2306 } hitcount: 2
{ lat: 23, common_pid: 2302 } hitcount: 6
{ lat: 24, common_pid: 2302 } hitcount: 3
{ lat: 24, common_pid: 2300 } hitcount: 1
{ lat: 24, common_pid: 2306 } hitcount: 2
{ lat: 24, common_pid: 2305 } hitcount: 1
{ lat: 24, common_pid: 2299 } hitcount: 1
{ lat: 25, common_pid: 2300 } hitcount: 1
{ lat: 25, common_pid: 2302 } hitcount: 4
{ lat: 26, common_pid: 2302 } hitcount: 2
{ lat: 27, common_pid: 2305 } hitcount: 1
{ lat: 27, common_pid: 2300 } hitcount: 1
{ lat: 27, common_pid: 2302 } hitcount: 3
{ lat: 28, common_pid: 2306 } hitcount: 1
{ lat: 28, common_pid: 2302 } hitcount: 4
{ lat: 29, common_pid: 2302 } hitcount: 1
{ lat: 29, common_pid: 2300 } hitcount: 2
{ lat: 29, common_pid: 2306 } hitcount: 1
{ lat: 29, common_pid: 2304 } hitcount: 1
{ lat: 30, common_pid: 2302 } hitcount: 4
{ lat: 31, common_pid: 2302 } hitcount: 6
{ lat: 32, common_pid: 2302 } hitcount: 1
{ lat: 33, common_pid: 2299 } hitcount: 1
{ lat: 33, common_pid: 2302 } hitcount: 3
{ lat: 34, common_pid: 2302 } hitcount: 2
{ lat: 35, common_pid: 2302 } hitcount: 1
{ lat: 35, common_pid: 2304 } hitcount: 1
{ lat: 36, common_pid: 2302 } hitcount: 4
{ lat: 37, common_pid: 2302 } hitcount: 6
{ lat: 38, common_pid: 2302 } hitcount: 2
{ lat: 39, common_pid: 2302 } hitcount: 2
{ lat: 39, common_pid: 2304 } hitcount: 1
{ lat: 40, common_pid: 2304 } hitcount: 2
{ lat: 40, common_pid: 2302 } hitcount: 5
{ lat: 41, common_pid: 2304 } hitcount: 1
{ lat: 41, common_pid: 2302 } hitcount: 8
{ lat: 42, common_pid: 2302 } hitcount: 6
{ lat: 42, common_pid: 2304 } hitcount: 1
{ lat: 43, common_pid: 2302 } hitcount: 3
{ lat: 43, common_pid: 2304 } hitcount: 4
{ lat: 44, common_pid: 2302 } hitcount: 6
{ lat: 45, common_pid: 2302 } hitcount: 5
{ lat: 46, common_pid: 2302 } hitcount: 5
{ lat: 47, common_pid: 2302 } hitcount: 7
{ lat: 48, common_pid: 2301 } hitcount: 1
{ lat: 48, common_pid: 2302 } hitcount: 9
{ lat: 49, common_pid: 2302 } hitcount: 3
{ lat: 50, common_pid: 2302 } hitcount: 1
{ lat: 50, common_pid: 2301 } hitcount: 1
{ lat: 51, common_pid: 2302 } hitcount: 2
{ lat: 51, common_pid: 2301 } hitcount: 1
{ lat: 61, common_pid: 2302 } hitcount: 1
{ lat: 110, common_pid: 2302 } hitcount: 1
Totals:
Hits: 89565
Entries: 158
Dropped: 0
這不會告訴我們任何關於 cyclictest 可能延遲喚醒的資訊，但它確實向我們展示了一個很好的直方圖，顯示了從 cyclictest 被喚醒到它進入使用者空間的時間。