事件直方图¶
由 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”文件会将整个哈希表转储到标准输出。如果一个事件附加了多个 hist 触发器，则输出中将为每个触发器显示一个表。为命名触发器显示的表将与任何其他具有相同名称的实例相同。每个打印的哈希表条目都是一个简单的键和值列表；首先打印键，并用花括号分隔，后跟条目的值字段集。默认情况下，数值字段显示为十进制整数。可以通过将以下任何修饰符附加到字段名称来修改此设置
.hex
将数字显示为十六进制值
.sym
将地址显示为符号
.sym-offset
将地址显示为符号和偏移量
.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 的事件会将特定于 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”参数可用于指定大于或小于该值的值。单位以哈希表条目为单位 - 如果运行使用的条目多于指定的条目，则结果将显示“drop”的数量，即被忽略的命中数。大小应为 128 到 131072 之间的 2 的幂（任何指定的非 2 的幂的数字都将向上舍入）。
“sort”参数可用于指定要排序的值字段。如果未指定，则默认为“hitcount”，默认排序顺序为“ascending”。要按相反方向排序，请将“.descending”附加到排序键。
“pause”参数可用于暂停现有的 hist 触发器，或启动 hist 触发器，但在收到指令之前不记录任何事件。“continue”或“cont”可用于启动或重新启动暂停的 hist 触发器。
“clear”参数将清除正在运行的 hist 触发器的内容，并保留其当前的暂停/活动状态。
请注意，如果将“pause”、“cont”和“clear”参数应用于现有触发器，则应使用“append”shell 运算符（“>>”）而不是通过“>”运算符应用，这将导致触发器通过截断被删除。
“nohitcount”（或 NOHC）参数将禁止在直方图中显示原始 hitcount。此选项需要至少一个不是“原始 hitcount”的值字段。例如，“hist:...:vals=hitcount:nohitcount”被拒绝，但“hist:...:vals=hitcount.percent:nohitcount”是 OK 的。
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_hist 触发器不是像 enable/disable_event 触发器那样启用或禁用目标事件到跟踪缓冲区的跟踪，而是启用或禁用目标事件到哈希表中的聚合。
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这会告诉跟踪系统创建一个 ‘hist’ 触发器，使用 kmalloc 事件的 call_site 字段作为表格的键，这仅仅意味着每个唯一的 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，但如果不为 0，则提示您可能需要使用 ‘size’ 参数增加表格的大小）。
请注意，在上面的输出中，有一个额外的字段 ‘hitcount’，它没有在触发器中指定。另请注意，在触发器信息输出中，有一个参数 ‘sort=hitcount’，它也没有在触发器中指定。原因在于，每个触发器都会隐式地保留一个给定条目的总命中次数的计数，称为 ‘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’，所以上面显示了按 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 触发器显示完整的内核堆栈跟踪，而不是简单地让 hist 触发器显示符号 call_site，从而导致每个 call_site。为此，我们只需将特殊值 ‘common_stacktrace’ 用于 key 参数即可。
# 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如果将 hist 触发器的键设置为 common_pid，例如为了收集和显示每个进程的排序总数，则可以使用特殊的 .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同样，如果将 hist 触发器的键设置为 syscall id，例如为了收集和显示系统范围内 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’ 系统调用。
我们可以使用 ‘compound’ 键来优化该数字，并进一步了解哪些进程确切地导致了总体 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 系统调用的细分，但是它也给出了很多我们目前并不真正关心的东西。由于我们知道 sys_ioctl 的系统调用 id（16，显示在 sys_ioctl 名称旁边），因此我们可以使用它来过滤掉所有其他系统调用。
# 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 调用者（这可能会导致一些问题，例如他们是否真的需要进行所有这些调用以及进一步调查的可能途径）。
复合键示例使用键和求和值 (hitcount) 对输出进行排序，但是我们可以很容易地使用两个键代替。这是一个示例，其中我们使用由 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 触发器将被禁用。
总体效果是，netif_receive_skb 事件仅在 wget 期间聚合到哈希表中。执行 wget 命令，然后列出 ‘hist’ 文件将显示 wget 命令生成的输出。
$ wget https://linuxkernel.org.cn/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上面显示了所有 netif_receive_skb 调用路径及其在 wget 命令期间的总长度。
‘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` 触发器的触发文件，您应该看到每个触发器有两个触发器：一个启用/禁用直方图聚合，另一个启用/禁用事件日志记录。
# 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://linuxkernel.org.cn/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 . . .以下示例演示了如何将多个直方图触发器附加到给定事件。此功能可用于创建一组来自同一组事件的不同摘要，或用于比较不同过滤器的效果等。
# 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' 文件的内容会显示所有五个直方图的内容。
# 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命名触发器可用于让触发器共享一组公共的直方图数据。此功能主要用于合并由内联函数中包含的跟踪点生成的事件输出，但名称可以用于任何事件的直方图触发器。例如，当触发时，这两个触发器将更新共享的 '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您可以通过同时读取每个事件的直方图文件来看到它们正在更新公共的直方图数据。
# 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 事件间直方图触发器¶
事件间直方图触发器是使用来自一个或多个其他事件的值并使用该数据创建直方图的直方图触发器。来自事件间直方图的数据反过来可以成为进一步组合直方图的来源，从而提供相关的直方图链，这对于某些应用程序非常重要。
可以以这种方式使用的事件间量最重要的例子是延迟，它只是两个事件之间的时间戳差异。虽然延迟是最重要的事件间量，但请注意，由于支持完全通用地跨越跟踪事件子系统，因此任何事件字段都可以在事件间量中使用。
将其他直方图的数据组合成有用链的直方图的示例是 “wakeupswitch 延迟” 直方图，它组合了 “唤醒延迟” 直方图和 “切换延迟” 直方图。
通常，直方图触发器规范由一个（可能是复合的）键以及一个或多个数值组成，这些数值是与该键关联的持续更新的总和。在这种情况下，直方图规范由引用与单个事件类型关联的跟踪事件字段的单个键和值规范组成。
事件间直方图触发器扩展允许引用多个事件中的字段并将它们组合成多事件直方图规范。为了支持这一总体目标，已向直方图触发器支持添加了一些启用功能。
为了计算事件间量，需要保存一个事件的值，然后从另一个事件中引用它。这需要引入对直方图“变量”的支持。
事件间量的计算及其组合需要少量支持，以将简单的表达式应用于变量（+ 和 -）。
由事件间量组成的直方图在逻辑上不是任何一个事件的直方图（因此让任何一个事件的 ‘hist’ 文件托管直方图输出并没有真正的意义）。为了解决直方图与事件组合相关联的想法，添加了支持，允许创建从其他事件派生的“合成”事件。这些合成事件是完全成熟的事件，就像任何其他事件一样，可以像使用其他事件一样使用它们，例如，创建前面提到的“组合”直方图。
一组“操作”可以与直方图条目关联 - 这些操作可以用于生成前面提到的合成事件，但也可以用于其他目的，例如在达到 “最大” 延迟时保存上下文。
跟踪事件没有与之关联的“时间戳”，但有一个隐式时间戳与底层 ftrace 环形缓冲区中的事件一起保存。此时间戳现在公开为一个名为 “common_timestamp” 的合成字段，该字段可以在直方图中使用，就像它是任何其他事件字段一样；它不是跟踪格式中的实际字段，而是一个合成值，但仍可以像实际字段一样使用。默认情况下，单位为纳秒；将 '.usecs' 追加到 common_timestamp 字段会将单位更改为微秒。
关于事件间时间戳的说明：如果在直方图中使用 common_timestamp，则跟踪缓冲区会自动切换为使用绝对时间戳和 “全局” 跟踪时钟，以避免与其他 CPU 之间不一致的时钟产生错误的时间戳差异。可以使用 “clock=XXX” 直方图触发器属性覆盖此设置，其中 XXX 是跟踪/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'。下面的直方图触发器反过来利用 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 合成事件¶
合成事件是用户定义的事件，由直方图触发器变量或与一个或多个其他事件关联的字段生成。它们的目的是提供一种机制，用于显示跨越多个事件的数据，与现有且已经熟悉的普通事件用法一致。
要定义合成事件，用户需要编写一个简单的规范，该规范由新事件的名称以及一个或多个变量及其类型组成，类型可以是任何有效字段类型，并以分号分隔，写入 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’ 事件 - 为此，需要实例化一个 “直方图触发器操作” 并绑定到在其他事件上定义的实际字段和变量（请参阅下面 2.2.3 节，了解如何使用直方图触发器 ‘onmatch’ 操作来完成此操作）。完成此操作后，将创建 ‘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 直方图触发器 ‘处理程序’ 和 ‘操作’¶
直方图触发器 ‘操作’ 是一个函数，每当添加或更新直方图条目时（在大多数情况下是有条件地）执行该函数。
当添加或更新直方图条目时，由直方图触发器的“处理程序”决定是否实际调用相应的操作。
直方图触发器处理程序和操作以以下通用形式配对：
<处理程序>.<操作>
要为给定事件指定处理程序.操作对，只需在直方图触发器规范中用冒号分隔指定该处理程序.操作对即可。
理论上，任何处理程序都可以与任何操作组合，但实际上，并非每个处理程序.操作组合都受到当前支持；如果给定的处理程序.操作组合不受支持，则直方图触发器将失败并返回 -EINVAL；
如果没有明确指定，则默认的“处理程序.操作”与以往一样，只是简单地更新与条目关联的值集。但是，某些应用程序可能希望在此时执行其他操作，例如生成另一个事件，或比较并保存最大值。
下面列出了支持的处理程序和操作，并在以下段落中更详细地描述了每个处理程序和操作，并在一些常见且有用的处理程序.操作组合的上下文中进行了描述。
可用的处理程序包括：
onmatch(匹配.事件) - 在任何添加或更新时调用操作
onmax(变量) - 如果变量超过当前最大值，则调用操作
onchange(变量) - 如果变量更改，则调用操作
可用的操作包括：
trace(<合成事件名称>, 参数列表) - 生成合成事件
save(字段,...) - 保存当前事件字段
snapshot() - 快照跟踪缓冲区
以下是常用的处理程序.操作对：
onmatch(匹配.事件).trace(<合成事件名称>, 参数列表)
当事件匹配且将添加或更新直方图条目时，将调用“onmatch(匹配.事件).trace(<合成事件名称>, 参数列表)”直方图触发器操作。它会导致生成指定的合成事件，并带有“参数列表”中给定的值。结果是生成一个合成事件，该事件由调用事件发生时这些变量中包含的值组成。例如，如果合成事件名称为“wakeup_latency”，则会使用 onmatch(event).trace(wakeup_latency,arg1,arg2) 生成一个 wakeup_latency 事件。
还有一种等效的替代形式可用于生成合成事件。在这种形式中，合成事件名称就像函数名称一样使用。例如，再次使用“wakeup_latency”合成事件名称，将通过将其作为函数调用来生成 wakeup_latency 事件，并将事件字段值作为参数传递：onmatch(event).wakeup_latency(arg1,arg2)。此形式的语法为：
onmatch(匹配.事件).<合成事件名称>(参数列表)
在任何一种情况下，“参数列表”都由一个或多个参数组成，这些参数可以是“匹配.事件”或目标事件上定义的变量或字段。“参数列表”中指定的变量或字段可以是完全限定的，也可以是不限定的。如果变量指定为不限定的，则它在两个事件之间必须是唯一的。如果用作参数的字段名称引用目标事件，则可以是不限定的，但如果引用匹配事件，则必须是完全限定的。完全限定的名称的形式为“system.event_name.$var_name”或“system.event_name.field”。
“匹配.事件”规范只是 onmatch() 功能的匹配目标事件的事件的完全限定事件名称，形式为“system.event_name”。比较两个事件的直方图键，以查找事件是否匹配。如果使用多个直方图键，则它们都必须按指定的顺序匹配。
最后，“参数列表”中变量/字段的数量和类型必须与所生成的合成事件中字段的数量和类型相匹配。
例如，以下定义一个简单的合成事件，并在调用合成事件时使用 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以下直方图触发器既定义了缺失的 testpid 变量，又指定了一个 onmatch() 操作，该操作会在发生 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一个更典型的用法是使用两个事件来计算延迟。以下示例使用一组直方图触发器来生成“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(变量).save(字段,...)
每当与直方图条目关联的“变量”的值超过该变量中包含的当前最大值时，将调用“onmax(变量).save(字段,...)”直方图触发器操作。
最终结果是，如果“变量”超过该直方图触发器条目的当前最大值，则会保存指定为 onmax.save() 参数的跟踪事件字段。这允许保存展示新最大值的事件的上下文，以供稍后参考。显示直方图时，将打印显示已保存值的附加字段。
例如，以下定义了几个直方图触发器，一个用于 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(变量).snapshot()
每当与直方图条目关联的“变量”的值超过该变量中包含的当前最大值时，将调用“onmax(变量).snapshot()”直方图触发器操作。
最终结果是，如果“变量”超过任何直方图触发器条目的当前最大值，则会在 tracing/snapshot 文件中保存跟踪缓冲区的全局快照。
请注意，在这种情况下，最大值是当前跟踪实例的全局最大值，它是直方图所有存储桶中的最大值。将显示导致全局最大值的特定跟踪事件的键和全局最大值本身，以及一条消息，指出已拍摄快照以及在哪里可以找到它。用户可以使用显示的键信息在直方图中找到对应的存储桶，以获得更多详细信息。
例如，以下定义了几个直方图触发器，一个用于 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显示直方图时，对于每个存储桶，最大值和与最大值对应的已保存值将显示在其余字段之后。
如果已拍摄快照，还会有一条消息指示已拍摄快照，以及触发全局最大值的值和事件：
# 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 的存储桶，您会发现已 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(变量).save(字段,...)
每当与直方图条目关联的“变量”的值更改时，将调用“onchange(变量).save(字段,...)”直方图触发器操作。
最终结果是，如果该直方图触发器条目的“变量”发生更改，则会保存指定为 onchange.save() 参数的跟踪事件字段。这允许保存更改该值的事件的上下文，以供稍后参考。显示直方图时，将打印显示已保存值的附加字段。
onchange(变量).snapshot()
每当与直方图条目关联的“变量”的值更改时，将调用“onchange(变量).snapshot()”直方图触发器操作。
最终结果是，如果任何直方图触发器条目的“变量”发生更改，则会在 tracing/snapshot 文件中保存跟踪缓冲区的全局快照。
请注意，在这种情况下，更改的值是与当前跟踪实例关联的全局变量。将显示导致该值更改的特定跟踪事件的键和全局值本身，以及一条消息，指出已拍摄快照以及在哪里可以找到它。用户可以使用显示的键信息在直方图中找到对应的存储桶，以获得更多详细信息。
例如，以下在 tcp_probe 事件上定义了一个直方图触发器，以 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显示直方图时，对于每个存储桶，跟踪的值和与该值对应的已保存值将显示在其余字段之后。
如果已拍摄快照，还会有一条消息指示已拍摄快照，以及触发快照的值和事件：
# 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 的存储桶，您会发现已 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”时触发。如果 pid 匹配，则它将使用计算出的延迟作为其参数调用“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 被唤醒到进入用户空间所花费的时间。