事件直方图¶
Tom Zanussi 编写的文档
1. 简介¶
直方图触发器是一种特殊的事件触发器，可用于将追踪事件数据聚合到直方图中。有关追踪事件和事件触发器的信息，请参阅事件追踪。
2. 直方图触发器命令¶
直方图触发器命令是一种事件触发器命令，它将事件命中聚合到一个哈希表中，该哈希表以一个或多个追踪事件格式字段（或堆栈跟踪）以及一组从一个或多个追踪事件格式字段和/或事件计数（命中计数）派生的运行总计为键。
hist 触发器的格式如下
hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>] [:sort=<field1[,field2,...]>][:size=#entries][:pause][:continue] [:clear][:name=histname1][:nohitcount][:<handler>.<action>] [if <filter>]当命中匹配事件时，将使用命名的键和值将条目添加到哈希表中。键和值对应于事件格式描述中的字段。值必须对应于数值字段 - 在事件命中时，值将添加到为该字段保留的总和中。特殊字符串“hitcount”可以代替显式值字段使用 - 这只是事件命中的计数。如果未指定“values”，则会自动创建并使用隐式“hitcount”值作为唯一值。键可以是任何字段，也可以是特殊字符串“common_stacktrace”，它将使用事件的内核堆栈跟踪作为键。可以使用关键字“keys”或“key”来指定键，可以使用关键字“values”、“vals”或“val”来指定值。可以使用“keys”关键字指定最多包含三个字段的复合键。哈希复合键会在表中为每个组件键的唯一组合生成一个唯一的条目，并且可用于提供更细粒度的事件数据摘要。此外，最多包含两个字段的排序键可以使用“sort”关键字指定。如果指定了多个字段，则结果将是“在排序中排序”：第一个键被视为主排序键，第二个键被视为辅助键。如果使用“name”参数为 hist 触发器命名，则其直方图数据将与其他具有相同名称的触发器共享，并且触发器命中将更新此公共数据。只有具有“兼容”字段的触发器才能以这种方式组合；如果触发器中命名的字段共享相同数量和类型的字段，并且这些字段也具有相同的名称，则触发器是“兼容的”。请注意，任何两个事件始终共享兼容的“hitcount”和“common_stacktrace”字段，因此可以使用这些字段进行组合，无论这可能多么毫无意义。
“hist”触发器会将“hist”文件添加到每个事件的子目录中。读取事件的“hist”文件会将整个哈希表转储到 stdout。如果一个事件附加了多个 hist 触发器，则输出中将为每个触发器提供一个表。为命名触发器显示的表将与任何其他具有相同名称的实例相同。每个打印的哈希表条目都是组成该条目的键和值的简单列表；键首先打印，并用花括号分隔，后跟该条目的值字段集。默认情况下，数值字段显示为十进制整数。可以通过将以下任何修饰符附加到字段名称来修改此设置
.hex
将数字显示为十六进制值
.sym
将地址显示为符号
.sym-offset
将地址显示为符号和偏移量
.syscall
将 syscall id 显示为系统调用名称
.execname
将 common_pid 显示为程序名称
.log2
显示 log2 值而不是原始数字
.buckets=size
显示值的分组而不是原始数字
.usecs
以微秒为单位显示 common_timestamp
.percent
将数字显示为百分比值
.graph
显示值的条形图
.stacktrace
显示为堆栈跟踪（必须是 long[] 类型）
请注意，通常在将修饰符应用于给定字段时，不会解释该字段的语义，但在此方面需要注意一些限制
只有“hex”修饰符可用于值（因为值本质上是总和，而其他修饰符在这种上下文中没有意义）。
“execname”修饰符只能在“common_pid”上使用。原因是 execname 只是在触发事件时为“当前”进程保存的“comm”值，这与事件跟踪代码保存的 common_pid 值相同。尝试将该 comm 值应用于其他 pid 值是不正确的，并且通常关注的事件会在事件本身中保存特定于 pid 的 comm 字段。
典型的使用场景是启用 hist 触发器，读取其当前内容，然后将其关闭，如下所示
# echo 'hist:keys=skbaddr.hex:vals=len' > \ /sys/kernel/tracing/events/net/netif_rx/trigger # cat /sys/kernel/tracing/events/net/netif_rx/hist # echo '!hist:keys=skbaddr.hex:vals=len' > \ /sys/kernel/tracing/events/net/netif_rx/trigger可以读取触发器文件本身以显示当前附加的 hist 触发器的详细信息。此信息也会在读取“hist”文件时显示在顶部。
默认情况下，哈希表的大小为 2048 个条目。“size”参数可用于指定更多或更少。单位以哈希表条目表示 - 如果运行使用的条目多于指定的条目，则结果将显示“drops”的数量，即忽略的命中次数。该大小应为 128 到 131072 之间的 2 的幂（指定的任何非 2 的幂的数字都将向上舍入）。
“sort”参数可用于指定要排序的值字段。如果未指定，则默认为“hitcount”，默认排序顺序为“ascending”。要按相反方向排序，请将“.descending”附加到排序键。
“pause”参数可用于暂停现有的 hist 触发器，或启动 hist 触发器，但在被告知之前不记录任何事件。“continue”或“cont”可用于启动或重新启动暂停的 hist 触发器。
“clear”参数将清除正在运行的 hist 触发器的内容，并保持其当前的暂停/活动状态。
请注意，“pause”、“cont”和“clear”参数应使用“append”shell 运算符（“>>”）应用于现有触发器，而不是通过“>”运算符，这将导致触发器通过截断被删除。
“nohitcount”（或 NOHC）参数将禁止在直方图中显示原始命中计数。此选项需要至少一个非“原始命中计数”的值字段。例如，“hist:…:vals=hitcount:nohitcount”被拒绝，但“hist:…:vals=hitcount.percent:nohitcount”是可以的。
enable_hist/disable_hist
enable_hist 和 disable_hist 触发器可用于使一个事件有条件地启动和停止另一个事件的已附加的 hist 触发器。可以将任意数量的 enable_hist 和 disable_hist 触发器附加到给定事件，从而允许该事件启动和停止主机上其他事件的聚合。
格式与 enable/disable_event 触发器非常相似
enable_hist:<system>:<event>[:count] disable_hist:<system>:<event>[:count]
与 enable/disable_event 触发器一样，enable/disable_hist 触发器不会将目标事件的跟踪启用或禁用到跟踪缓冲区中，而是启用或禁用目标事件到哈希表中的聚合。
enable_hist/disable_hist 触发器的典型使用场景是首先在某个事件上设置一个暂停的 hist 触发器，然后使用一个 enable_hist/disable_hist 对，当命中感兴趣的条件时打开和关闭 hist 聚合
# echo 'hist:keys=skbaddr.hex:vals=len:pause' > \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ /sys/kernel/tracing/events/sched/sched_process_exec/trigger # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ /sys/kernel/tracing/events/sched/sched_process_exit/trigger
上面的设置首先设置了一个最初暂停的 hist 触发器，当执行给定的程序时，该触发器被取消暂停并开始聚合事件，当进程退出并且 hist 触发器再次暂停时，该触发器停止聚合。
下面的示例提供了对上述讨论的概念和典型使用模式的更具体的说明。
“特殊”事件字段¶
有许多“特殊事件字段”可用于 hist 触发器中的键或值。这些看起来像实际的事件字段并以相同的方式运行，但实际上并不是事件字段定义或格式文件的一部分。但是，它们可用于任何事件，并且可以在实际事件字段可以使用的任何地方使用。它们是
common_timestamp
u64
与事件关联的时间戳（来自环形缓冲区），以纳秒为单位。可以由 .usecs 修改为将时间戳解释为微秒。
common_cpu
int
事件发生的 cpu。
扩展错误信息¶
对于调用 hist 触发器命令时遇到的一些错误情况，可以通过 tracing/error_log 文件获得扩展错误信息。有关详细信息，请参阅
Documentation/trace/ftrace.rst中的错误情况。
6.2 “hist”触发器示例¶
第一组示例使用 kmalloc 事件创建聚合。可用于 hist 触发器的字段在 kmalloc 事件的格式文件中列出
# cat /sys/kernel/tracing/events/kmem/kmalloc/format name: kmalloc ID: 374 format: field:unsigned short common_type; offset:0; size:2; signed:0; field:unsigned char common_flags; offset:2; size:1; signed:0; field:unsigned char common_preempt_count; offset:3; size:1; signed:0; field:int common_pid; offset:4; size:4; signed:1; field:unsigned long call_site; offset:8; size:8; signed:0; field:const void * ptr; offset:16; size:8; signed:0; field:size_t bytes_req; offset:24; size:8; signed:0; field:size_t bytes_alloc; offset:32; size:8; signed:0; field:gfp_t gfp_flags; offset:40; size:4; signed:0;我们将首先创建一个 hist 触发器，该触发器生成一个简单的表，其中列出了内核中一个或多个调用 kmalloc 的每个函数请求的总字节数
# echo 'hist:key=call_site:val=bytes_req.buckets=32' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger这告诉跟踪系统使用 kmalloc 事件的 call_site 字段作为表的键创建一个“hist”触发器，这仅意味着每个唯一的 call_site 地址都会在该表中创建一个条目。“val=bytes_req”参数告诉 hist 触发器，对于表中的每个唯一条目 (call_site)，它应该保留该 call_site 请求的字节数的运行总计。
我们让它运行一段时间，然后转储 kmalloc 事件子目录中“hist”文件的内容（为了便于阅读，已省略了许多条目）
# cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active] { call_site: 18446744072106379007 } hitcount: 1 bytes_req: 176 { call_site: 18446744071579557049 } hitcount: 1 bytes_req: 1024 { call_site: 18446744071580608289 } hitcount: 1 bytes_req: 16384 { call_site: 18446744071581827654 } hitcount: 1 bytes_req: 24 { call_site: 18446744071580700980 } hitcount: 1 bytes_req: 8 { call_site: 18446744071579359876 } hitcount: 1 bytes_req: 152 { call_site: 18446744071580795365 } hitcount: 3 bytes_req: 144 { call_site: 18446744071581303129 } hitcount: 3 bytes_req: 144 { call_site: 18446744071580713234 } hitcount: 4 bytes_req: 2560 { call_site: 18446744071580933750 } hitcount: 4 bytes_req: 736 . . . { call_site: 18446744072106047046 } hitcount: 69 bytes_req: 5576 { call_site: 18446744071582116407 } hitcount: 73 bytes_req: 2336 { call_site: 18446744072106054684 } hitcount: 136 bytes_req: 140504 { call_site: 18446744072106224230 } hitcount: 136 bytes_req: 19584 { call_site: 18446744072106078074 } hitcount: 153 bytes_req: 2448 { call_site: 18446744072106062406 } hitcount: 153 bytes_req: 36720 { call_site: 18446744071582507929 } hitcount: 153 bytes_req: 37088 { call_site: 18446744072102520590 } hitcount: 273 bytes_req: 10920 { call_site: 18446744071582143559 } hitcount: 358 bytes_req: 716 { call_site: 18446744072106465852 } hitcount: 417 bytes_req: 56712 { call_site: 18446744072102523378 } hitcount: 485 bytes_req: 27160 { call_site: 18446744072099568646 } hitcount: 1676 bytes_req: 33520 Totals: Hits: 4610 Entries: 45 Dropped: 0输出为每个条目显示一行，从触发器中指定的键开始，后跟触发器中还指定的值。输出的开头是一行，用于显示触发器信息，也可以通过读取“trigger”文件来显示触发器信息
# cat /sys/kernel/tracing/events/kmem/kmalloc/trigger hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]输出的末尾是几行，显示了运行的总计。“Hits”字段显示事件触发器命中的总次数，“Entries”字段显示哈希表中使用的条目总数，“Dropped”字段显示由于运行中使用的条目数超过了表允许的最大条目数而丢弃的命中次数（通常为 0，但如果没有提示，您可能想要使用“size”参数来增加表的大小）。
请注意，在上面的输出中，有一个额外的字段“hitcount”，该字段未在触发器中指定。另请注意，在触发器信息输出中，有一个参数“sort=hitcount”，该参数也未在触发器中指定。原因是每个触发器都隐式地保留一个归因于给定条目的总命中次数的计数，称为“hitcount”。该命中计数信息在输出中显式显示，并且在没有用户指定的排序参数的情况下，将用作默认排序字段。
如果您实际上不需要对任何特定字段求和，而主要对命中频率感兴趣，则可以使用值“hitcount”代替“values”参数中的显式值。
要关闭 hist 触发器，只需调用命令历史记录中的触发器并使用“!”前缀重新执行它
# echo '!hist:key=call_site:val=bytes_req' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger最后，请注意，上面输出中显示的 call_site 实际上不是很有用。它是一个地址，但通常地址以十六进制显示。要使数值字段显示为十六进制值，只需在触发器中将“.hex”附加到字段名称
# echo 'hist:key=call_site.hex:val=bytes_req' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger # cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=call_site.hex:vals=bytes_req:sort=hitcount:size=2048 [active] { call_site: ffffffffa026b291 } hitcount: 1 bytes_req: 433 { call_site: ffffffffa07186ff } hitcount: 1 bytes_req: 176 { call_site: ffffffff811ae721 } hitcount: 1 bytes_req: 16384 { call_site: ffffffff811c5134 } hitcount: 1 bytes_req: 8 { call_site: ffffffffa04a9ebb } hitcount: 1 bytes_req: 511 { call_site: ffffffff8122e0a6 } hitcount: 1 bytes_req: 12 { call_site: ffffffff8107da84 } hitcount: 1 bytes_req: 152 { call_site: ffffffff812d8246 } hitcount: 1 bytes_req: 24 { call_site: ffffffff811dc1e5 } hitcount: 3 bytes_req: 144 { call_site: ffffffffa02515e8 } hitcount: 3 bytes_req: 648 { call_site: ffffffff81258159 } hitcount: 3 bytes_req: 144 { call_site: ffffffff811c80f4 } hitcount: 4 bytes_req: 544 . . . { call_site: ffffffffa06c7646 } hitcount: 106 bytes_req: 8024 { call_site: ffffffffa06cb246 } hitcount: 132 bytes_req: 31680 { call_site: ffffffffa06cef7a } hitcount: 132 bytes_req: 2112 { call_site: ffffffff8137e399 } hitcount: 132 bytes_req: 23232 { call_site: ffffffffa06c941c } hitcount: 185 bytes_req: 171360 { call_site: ffffffffa06f2a66 } hitcount: 185 bytes_req: 26640 { call_site: ffffffffa036a70e } hitcount: 265 bytes_req: 10600 { call_site: ffffffff81325447 } hitcount: 292 bytes_req: 584 { call_site: ffffffffa072da3c } hitcount: 446 bytes_req: 60656 { call_site: ffffffffa036b1f2 } hitcount: 526 bytes_req: 29456 { call_site: ffffffffa0099c06 } hitcount: 1780 bytes_req: 35600 Totals: Hits: 4775 Entries: 46 Dropped: 0即使这样也只是稍微有用一些 - 虽然十六进制值看起来更像地址，但用户通常更感兴趣的是文本地址对应的符号。要使地址显示为符号值，只需将“.sym”或“.sym-offset”附加到触发器中的字段名称
# echo 'hist:key=call_site.sym:val=bytes_req' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger # cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=hitcount:size=2048 [active] { call_site: [ffffffff810adcb9] syslog_print_all } hitcount: 1 bytes_req: 1024 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 { call_site: [ffffffff8154acbe] usb_alloc_urb } hitcount: 1 bytes_req: 192 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40 { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 { call_site: [ffffffff811febd5] fsnotify_alloc_group } hitcount: 2 bytes_req: 528 { call_site: [ffffffff81440f58] __tty_buffer_request_room } hitcount: 2 bytes_req: 2624 { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 2 bytes_req: 96 { call_site: [ffffffffa05e19af] ieee80211_start_tx_ba_session [mac80211] } hitcount: 2 bytes_req: 464 { call_site: [ffffffff81672406] tcp_get_metrics } hitcount: 2 bytes_req: 304 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 { call_site: [ffffffff81089b05] sched_create_group } hitcount: 2 bytes_req: 1424 . . . { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1185 bytes_req: 123240 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 1185 bytes_req: 104280 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 1402 bytes_req: 190672 { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 1518 bytes_req: 146208 { call_site: [ffffffffa029070e] drm_vma_node_allow [drm] } hitcount: 1746 bytes_req: 69840 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 2021 bytes_req: 792312 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 2592 bytes_req: 145152 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2629 bytes_req: 378576 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2629 bytes_req: 3783248 { call_site: [ffffffff81325607] apparmor_file_alloc_security } hitcount: 5192 bytes_req: 10384 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 5529 bytes_req: 110584 { call_site: [ffffffff8131ebf7] aa_alloc_task_context } hitcount: 21943 bytes_req: 702176 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 55759 bytes_req: 5074265 Totals: Hits: 109928 Entries: 71 Dropped: 0因为上面的默认排序键是“hitcount”，所以上面显示了按增加的命中计数排序的 call_site 列表，因此在底部我们看到在该运行期间进行最多 kmalloc 调用的函数。如果相反，我们想要查看就请求的字节数而不是调用次数而言的顶级 kmalloc 调用者，并且我们希望顶级调用者出现在顶部，我们可以使用“sort”参数以及“descending”修饰符
# echo 'hist:key=call_site.sym:val=bytes_req:sort=bytes_req.descending' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger # cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2186 bytes_req: 3397464 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1790 bytes_req: 712176 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 8132 bytes_req: 513135 { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 106 bytes_req: 440128 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2186 bytes_req: 314784 { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 2174 bytes_req: 208992 { call_site: [ffffffff811ae8e1] __kmalloc } hitcount: 8 bytes_req: 131072 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 859 bytes_req: 116824 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 1834 bytes_req: 102704 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 972 bytes_req: 101088 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 972 bytes_req: 85536 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 3333 bytes_req: 66664 { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 209 bytes_req: 61632 . . . { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 { call_site: [ffffffff812d8406] copy_semundo } hitcount: 2 bytes_req: 48 { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 1 bytes_req: 48 { call_site: [ffffffffa027121a] drm_getmagic [drm] } hitcount: 1 bytes_req: 48 { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40 { call_site: [ffffffff811c52f4] bprm_change_interp } hitcount: 2 bytes_req: 16 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 Totals: Hits: 32133 Entries: 81 Dropped: 0要显示偏移量和大小信息以及符号名称，只需使用“sym-offset”代替
# echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger # cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=call_site.sym-offset:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] { call_site: [ffffffffa046041c] i915_gem_execbuffer2+0x6c/0x2c0 [i915] } hitcount: 4569 bytes_req: 3163720 { call_site: [ffffffffa0489a66] intel_ring_begin+0xc6/0x1f0 [i915] } hitcount: 4569 bytes_req: 657936 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23+0x694/0x1020 [i915] } hitcount: 1519 bytes_req: 472936 { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23+0x516/0x1020 [i915] } hitcount: 3050 bytes_req: 211832 { call_site: [ffffffff811e2a1b] seq_buf_alloc+0x1b/0x50 } hitcount: 34 bytes_req: 148384 { call_site: [ffffffffa04a580c] intel_crtc_page_flip+0xbc/0x870 [i915] } hitcount: 1385 bytes_req: 144040 { call_site: [ffffffff811ae8e1] __kmalloc+0x191/0x1b0 } hitcount: 8 bytes_req: 131072 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl+0x282/0x360 [drm] } hitcount: 1385 bytes_req: 121880 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc+0x32/0x100 [drm] } hitcount: 1848 bytes_req: 103488 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state+0x2c/0xa0 [i915] } hitcount: 461 bytes_req: 62696 { call_site: [ffffffffa029070e] drm_vma_node_allow+0x2e/0xd0 [drm] } hitcount: 1541 bytes_req: 61640 { call_site: [ffffffff815f8d7b] sk_prot_alloc+0xcb/0x1b0 } hitcount: 57 bytes_req: 57456 . . . { call_site: [ffffffff8109524a] alloc_fair_sched_group+0x5a/0x1a0 } hitcount: 2 bytes_req: 128 { call_site: [ffffffffa027b921] drm_vm_open_locked+0x31/0xa0 [drm] } hitcount: 3 bytes_req: 96 { call_site: [ffffffff8122e266] proc_self_follow_link+0x76/0xb0 } hitcount: 8 bytes_req: 96 { call_site: [ffffffff81213e80] load_elf_binary+0x240/0x1650 } hitcount: 3 bytes_req: 84 { call_site: [ffffffff8154bc62] usb_control_msg+0x42/0x110 } hitcount: 1 bytes_req: 8 { call_site: [ffffffffa00bf6fe] hidraw_send_report+0x7e/0x1a0 [hid] } hitcount: 1 bytes_req: 7 { call_site: [ffffffffa00bf1ca] hidraw_report_event+0x8a/0x120 [hid] } hitcount: 1 bytes_req: 7 Totals: Hits: 26098 Entries: 64 Dropped: 0我们还可以将多个字段添加到“values”参数中。例如，我们可能想查看分配的总字节数以及请求的字节数，并按降序显示按已分配的字节数排序的结果
# echo 'hist:keys=call_site.sym:values=bytes_req,bytes_alloc:sort=bytes_alloc.descending' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger # cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=call_site.sym:vals=bytes_req,bytes_alloc:sort=bytes_alloc.descending:size=2048 [active] { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 7403 bytes_req: 4084360 bytes_alloc: 5958016 { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 541 bytes_req: 2213968 bytes_alloc: 2228224 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 7404 bytes_req: 1066176 bytes_alloc: 1421568 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1565 bytes_req: 557368 bytes_alloc: 1037760 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 9557 bytes_req: 595778 bytes_alloc: 695744 { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 5839 bytes_req: 430680 bytes_alloc: 470400 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 2388 bytes_req: 324768 bytes_alloc: 458496 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 3911 bytes_req: 219016 bytes_alloc: 250304 { call_site: [ffffffff815f8d7b] sk_prot_alloc } hitcount: 235 bytes_req: 236880 bytes_alloc: 240640 { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 557 bytes_req: 169024 bytes_alloc: 221760 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 9378 bytes_req: 187548 bytes_alloc: 206312 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1519 bytes_req: 157976 bytes_alloc: 194432 . . . { call_site: [ffffffff8109bd3b] sched_autogroup_create_attach } hitcount: 2 bytes_req: 144 bytes_alloc: 192 { call_site: [ffffffff81097ee8] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 { call_site: [ffffffff81213e80] load_elf_binary } hitcount: 3 bytes_req: 84 bytes_alloc: 96 { call_site: [ffffffff81079a2e] kthread_create_on_node } hitcount: 1 bytes_req: 56 bytes_alloc: 64 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 bytes_alloc: 8 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8 Totals: Hits: 66598 Entries: 65 Dropped: 0最后，为了完成我们的 kmalloc 示例，我们可以让 hist 触发器额外显示导致每个 call_site 的完整内核堆栈跟踪集，而不是简单地让 hist 触发器显示符号 call_site。为此，我们只需将特殊值“common_stacktrace”用于键参数
# echo 'hist:keys=common_stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' > \ /sys/kernel/tracing/events/kmem/kmalloc/trigger上面的触发器将使用触发事件时生效的内核堆栈跟踪作为哈希表的键。这允许枚举导致特定事件的每个内核调用路径，以及该事件的任何事件字段的运行总计。在这里，我们统计了系统中导致 kmalloc 的每个调用路径的请求字节数和已分配字节数（在本例中，是内核编译的每个 kmalloc 的调用路径）
# cat /sys/kernel/tracing/events/kmem/kmalloc/hist # trigger info: hist:keys=common_stacktrace:vals=bytes_req,bytes_alloc:sort=bytes_alloc:size=2048 [active] { common_stacktrace: __kmalloc_track_caller+0x10b/0x1a0 kmemdup+0x20/0x50 hidraw_report_event+0x8a/0x120 [hid] hid_report_raw_event+0x3ea/0x440 [hid] hid_input_report+0x112/0x190 [hid] hid_irq_in+0xc2/0x260 [usbhid] __usb_hcd_giveback_urb+0x72/0x120 usb_giveback_urb_bh+0x9e/0xe0 tasklet_hi_action+0xf8/0x100 __do_softirq+0x114/0x2c0 irq_exit+0xa5/0xb0 do_IRQ+0x5a/0xf0 ret_from_intr+0x0/0x30 cpuidle_enter+0x17/0x20 cpu_startup_entry+0x315/0x3e0 rest_init+0x7c/0x80 } hitcount: 3 bytes_req: 21 bytes_alloc: 24 { common_stacktrace: __kmalloc_track_caller+0x10b/0x1a0 kmemdup+0x20/0x50 hidraw_report_event+0x8a/0x120 [hid] hid_report_raw_event+0x3ea/0x440 [hid] hid_input_report+0x112/0x190 [hid] hid_irq_in+0xc2/0x260 [usbhid] __usb_hcd_giveback_urb+0x72/0x120 usb_giveback_urb_bh+0x9e/0xe0 tasklet_hi_action+0xf8/0x100 __do_softirq+0x114/0x2c0 irq_exit+0xa5/0xb0 do_IRQ+0x5a/0xf0 ret_from_intr+0x0/0x30 } hitcount: 3 bytes_req: 21 bytes_alloc: 24 { common_stacktrace: kmem_cache_alloc_trace+0xeb/0x150 aa_alloc_task_context+0x27/0x40 apparmor_cred_prepare+0x1f/0x50 security_prepare_creds+0x16/0x20 prepare_creds+0xdf/0x1a0 SyS_capset+0xb5/0x200 system_call_fastpath+0x12/0x6a } hitcount: 1 bytes_req: 32 bytes_alloc: 32 . . . { common_stacktrace: __kmalloc+0x11b/0x1b0 i915_gem_execbuffer2+0x6c/0x2c0 [i915] drm_ioctl+0x349/0x670 [drm] do_vfs_ioctl+0x2f0/0x4f0 SyS_ioctl+0x81/0xa0 system_call_fastpath+0x12/0x6a } hitcount: 17726 bytes_req: 13944120 bytes_alloc: 19593808 { common_stacktrace: __kmalloc+0x11b/0x1b0 load_elf_phdrs+0x76/0xa0 load_elf_binary+0x102/0x1650 search_binary_handler+0x97/0x1d0 do_execveat_common.isra.34+0x551/0x6e0 SyS_execve+0x3a/0x50 return_from_execve+0x0/0x23 } hitcount: 33348 bytes_req: 17152128 bytes_alloc: 20226048 { common_stacktrace: kmem_cache_alloc_trace+0xeb/0x150 apparmor_file_alloc_security+0x27/0x40 security_file_alloc+0x16/0x20 get_empty_filp+0x93/0x1c0 path_openat+0x31/0x5f0 do_filp_open+0x3a/0x90 do_sys_open+0x128/0x220 SyS_open+0x1e/0x20 system_call_fastpath+0x12/0x6a } hitcount: 4766422 bytes_req: 9532844 bytes_alloc: 38131376 { common_stacktrace: __kmalloc+0x11b/0x1b0 seq_buf_alloc+0x1b/0x50 seq_read+0x2cc/0x370 proc_reg_read+0x3d/0x80 __vfs_read+0x28/0xe0 vfs_read+0x86/0x140 SyS_read+0x46/0xb0 system_call_fastpath+0x12/0x6a } hitcount: 19133 bytes_req: 78368768 bytes_alloc: 78368768 Totals: Hits: 6085872 Entries: 253 Dropped: 0如果您在 common_pid 上键入 hist 触发器，例如为了收集和显示每个进程的排序总计，您可以使用特殊的 .execname 修饰符来显示表中进程的可执行文件名，而不是原始 pid。下面的示例保留了每个进程读取的总字节数的总和
# echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \ /sys/kernel/tracing/events/syscalls/sys_enter_read/trigger # cat /sys/kernel/tracing/events/syscalls/sys_enter_read/hist # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active] { common_pid: gnome-terminal [ 3196] } hitcount: 280 count: 1093512 { common_pid: Xorg [ 1309] } hitcount: 525 count: 256640 { common_pid: compiz [ 2889] } hitcount: 59 count: 254400 { common_pid: bash [ 8710] } hitcount: 3 count: 66369 { common_pid: dbus-daemon-lau [ 8703] } hitcount: 49 count: 47739 { common_pid: irqbalance [ 1252] } hitcount: 27 count: 27648 { common_pid: 01ifupdown [ 8705] } hitcount: 3 count: 17216 { common_pid: dbus-daemon [ 772] } hitcount: 10 count: 12396 { common_pid: Socket Thread [ 8342] } hitcount: 11 count: 11264 { common_pid: nm-dhcp-client. [ 8701] } hitcount: 6 count: 7424 { common_pid: gmain [ 1315] } hitcount: 18 count: 6336 . . . { common_pid: postgres [ 1892] } hitcount: 2 count: 32 { common_pid: postgres [ 1891] } hitcount: 2 count: 32 { common_pid: gmain [ 8704] } hitcount: 2 count: 32 { common_pid: upstart-dbus-br [ 2740] } hitcount: 21 count: 21 { common_pid: nm-dispatcher.a [ 8696] } hitcount: 1 count: 16 { common_pid: indicator-datet [ 2904] } hitcount: 1 count: 16 { common_pid: gdbus [ 2998] } hitcount: 1 count: 16 { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8 { common_pid: init [ 1] } hitcount: 2 count: 2 Totals: Hits: 2116 Entries: 51 Dropped: 0类似地，如果您在 syscall id 上键入 hist 触发器，例如为了收集和显示系统范围内 syscall 命中的列表，您可以使用特殊的 .syscall 修饰符来显示 syscall 名称而不是原始 id。下面的示例在运行期间保留系统中 syscall 计数的运行总计
# echo 'hist:key=id.syscall:val=hitcount' > \ /sys/kernel/tracing/events/raw_syscalls/sys_enter/trigger # cat /sys/kernel/tracing/events/raw_syscalls/sys_enter/hist # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active] { id: sys_fsync [ 74] } hitcount: 1 { id: sys_newuname [ 63] } hitcount: 1 { id: sys_prctl [157] } hitcount: 1 { id: sys_statfs [137] } hitcount: 1 { id: sys_symlink [ 88] } hitcount: 1 { id: sys_sendmmsg [307] } hitcount: 1 { id: sys_semctl [ 66] } hitcount: 1 { id: sys_readlink [ 89] } hitcount: 3 { id: sys_bind [ 49] } hitcount: 3 { id: sys_getsockname [ 51] } hitcount: 3 { id: sys_unlink [ 87] } hitcount: 3 { id: sys_rename [ 82] } hitcount: 4 { id: unknown_syscall [ 58] } hitcount: 4 { id: sys_connect [ 42] } hitcount: 4 { id: sys_getpid [ 39] } hitcount: 4 . . . { id: sys_rt_sigprocmask [ 14] } hitcount: 952 { id: sys_futex [202] } hitcount: 1534 { id: sys_write [ 1] } hitcount: 2689 { id: sys_setitimer [ 38] } hitcount: 2797 { id: sys_read [ 0] } hitcount: 3202 { id: sys_select [ 23] } hitcount: 3773 { id: sys_writev [ 20] } hitcount: 4531 { id: sys_poll [ 7] } hitcount: 8314 { id: sys_recvmsg [ 47] } hitcount: 13738 { id: sys_ioctl [ 16] } hitcount: 21843 Totals: Hits: 67612 Entries: 72 Dropped: 0上面的 syscall 计数提供了系统上系统调用活动的大致总体情况；例如，我们可以看到该系统上最受欢迎的系统调用是“sys_ioctl”系统调用。
我们可以使用“复合”键来优化该数字，并进一步了解哪些进程对整体 ioctl 计数有贡献。
下面的命令保留每个系统调用 id 和 pid 的唯一组合的命中计数 - 最终结果本质上是一个保留每个 pid 的系统调用命中总和的表。结果使用系统调用 id 作为主键，命中计数总和作为辅助键进行排序
# echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' > \ /sys/kernel/tracing/events/raw_syscalls/sys_enter/trigger # cat /sys/kernel/tracing/events/raw_syscalls/sys_enter/hist # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active] { id: sys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: 1 { id: sys_read [ 0], common_pid: gdbus [ 2976] } hitcount: 1 { id: sys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: 1 { id: sys_read [ 0], common_pid: postgres [ 1865] } hitcount: 1 { id: sys_read [ 0], common_pid: deja-dup-monito [ 3543] } hitcount: 2 { id: sys_read [ 0], common_pid: NetworkManager [ 890] } hitcount: 2 { id: sys_read [ 0], common_pid: evolution-calen [ 3048] } hitcount: 2 { id: sys_read [ 0], common_pid: postgres [ 1864] } hitcount: 2 { id: sys_read [ 0], common_pid: nm-applet [ 3022] } hitcount: 2 { id: sys_read [ 0], common_pid: whoopsie [ 1212] } hitcount: 2 . . . { id: sys_ioctl [ 16], common_pid: bash [ 8479] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: bash [ 3472] } hitcount: 12 { id: sys_ioctl [ 16], common_pid: gnome-terminal [ 3199] } hitcount: 16 { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 1808 { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 5580 . . . { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2690] } hitcount: 3 { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2688] } hitcount: 16 { id: sys_inotify_add_watch [254], common_pid: gmain [ 975] } hitcount: 2 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3204] } hitcount: 4 { id: sys_inotify_add_watch [254], common_pid: gmain [ 2888] } hitcount: 4 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3003] } hitcount: 4 { id: sys_inotify_add_watch [254], common_pid: gmain [ 2873] } hitcount: 4 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3196] } hitcount: 6 { id: sys_openat [257], common_pid: java [ 2623] } hitcount: 2 { id: sys_eventfd2 [290], common_pid: ibus-ui-gtk3 [ 2760] } hitcount: 4 { id: sys_eventfd2 [290], common_pid: compiz [ 2994] } hitcount: 6 Totals: Hits: 31536 Entries: 323 Dropped: 0上面的列表确实为我们提供了按 pid 分解的 ioctl syscall，但它也为我们提供了更多的信息，我们目前并不关心这些信息。由于我们知道 sys_ioctl 的 syscall id（16，显示在 sys_ioctl 名称旁边），我们可以使用它来过滤掉所有其他 syscall
# echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount if id == 16' > \ /sys/kernel/tracing/events/raw_syscalls/sys_enter/trigger # cat /sys/kernel/tracing/events/raw_syscalls/sys_enter/hist # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 if id == 16 [active] { id: sys_ioctl [ 16], common_pid: gmain [ 2769] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: gmain [ 3003] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: gmain [ 2781] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: gmain [ 2829] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: bash [ 8726] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: bash [ 8508] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: gmain [ 2970] } hitcount: 1 { id: sys_ioctl [ 16], common_pid: gmain [ 2768] } hitcount: 1 . . . { id: sys_ioctl [ 16], common_pid: pool [ 8559] } hitcount: 45 { id: sys_ioctl [ 16], common_pid: pool [ 8555] } hitcount: 48 { id: sys_ioctl [ 16], common_pid: pool [ 8551] } hitcount: 48 { id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: 66 { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 26674 { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 73443 Totals: Hits: 101162 Entries: 103 Dropped: 0上面的输出显示，“compiz”和“Xorg”是迄今为止最重的 ioctl 调用者（这可能会导致人们质疑他们是否真的需要进行所有这些调用以及进一步调查的可能途径。）
复合键示例使用键和总和值（命中计数）对输出进行排序，但我们也可以轻松地使用两个键。这是一个示例，其中我们使用由 common_pid 和 size 事件字段组成的复合键。使用 pid 作为主键，“size”作为辅助键进行排序，使我们能够显示 recvfrom 大小的有序摘要，以及每个进程接收的计数
# echo 'hist:key=common_pid.execname,size:val=hitcount:sort=common_pid,size' > \ /sys/kernel/tracing/events/syscalls/sys_enter_recvfrom/trigger # cat /sys/kernel/tracing/events/syscalls/sys_enter_recvfrom/hist # trigger info: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:size=2048 [active] { common_pid: smbd [ 784], size: 4 } hitcount: 1 { common_pid: dnsmasq [ 1412], size: 4096 } hitcount: 672 { common_pid: postgres [ 1796], size: 1000 } hitcount: 6 { common_pid: postgres [ 1867], size: 1000 } hitcount: 10 { common_pid: bamfdaemon [ 2787], size: 28 } hitcount: 2 { common_pid: bamfdaemon [ 2787], size: 14360 } hitcount: 1 { common_pid: compiz [ 2994], size: 8 } hitcount: 1 { common_pid: compiz [ 2994], size: 20 } hitcount: 11 { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2 { common_pid: firefox [ 8817], size: 4 } hitcount: 1 { common_pid: firefox [ 8817], size: 8 } hitcount: 5 { common_pid: firefox [ 8817], size: 588 } hitcount: 2 { common_pid: firefox [ 8817], size: 628 } hitcount: 1 { common_pid: firefox [ 8817], size: 6944 } hitcount: 1 { common_pid: firefox [ 8817], size: 408880 } hitcount: 2 { common_pid: firefox [ 8822], size: 8 } hitcount: 2 { common_pid: firefox [ 8822], size: 160 } hitcount: 2 { common_pid: firefox [ 8822], size: 320 } hitcount: 2 { common_pid: firefox [ 8822], size: 352 } hitcount: 1 . . . { common_pid: pool [ 8923], size: 1960 } hitcount: 10 { common_pid: pool [ 8923], size: 2048 } hitcount: 10 { common_pid: pool [ 8924], size: 1960 } hitcount: 10 { common_pid: pool [ 8924], size: 2048 } hitcount: 10 { common_pid: pool [ 8928], size: 1964 } hitcount: 4 { common_pid: pool [ 8928], size: 1965 } hitcount: 2 { common_pid: pool [ 8928], size: 2048 } hitcount: 6 { common_pid: pool [ 8929], size: 1982 } hitcount: 1 { common_pid: pool [ 8929], size: 2048 } hitcount: 1 Totals: Hits: 2016 Entries: 224 Dropped: 0上面的示例还说明了这样一个事实，即虽然复合键被视为单个实体以进行哈希处理，但它可以独立访问它组成的子键。
下一个示例使用字符串字段作为哈希键，并演示如何手动暂停和继续 hist 触发器。在此示例中，我们将聚合 fork 计数，并且不期望哈希表中有大量条目，因此我们将将其减少到更小的数字，例如 256
# echo 'hist:key=child_comm:val=hitcount:size=256' > \ /sys/kernel/tracing/events/sched/sched_process_fork/trigger # cat /sys/kernel/tracing/events/sched/sched_process_fork/hist # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] { child_comm: dconf worker } hitcount: 1 { child_comm: ibus-daemon } hitcount: 1 { child_comm: whoopsie } hitcount: 1 { child_comm: smbd } hitcount: 1 { child_comm: gdbus } hitcount: 1 { child_comm: kthreadd } hitcount: 1 { child_comm: dconf worker } hitcount: 1 { child_comm: evolution-alarm } hitcount: 2 { child_comm: Socket Thread } hitcount: 2 { child_comm: postgres } hitcount: 2 { child_comm: bash } hitcount: 3 { child_comm: compiz } hitcount: 3 { child_comm: evolution-sourc } hitcount: 4 { child_comm: dhclient } hitcount: 4 { child_comm: pool } hitcount: 5 { child_comm: nm-dispatcher.a } hitcount: 8 { child_comm: firefox } hitcount: 8 { child_comm: dbus-daemon } hitcount: 8 { child_comm: glib-pacrunner } hitcount: 10 { child_comm: evolution } hitcount: 23 Totals: Hits: 89 Entries: 20 Dropped: 0如果我们想暂停 hist 触发器，我们可以简单地将 :pause 附加到启动触发器的命令。请注意，触发器信息显示为 [paused]
# echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \ /sys/kernel/tracing/events/sched/sched_process_fork/trigger # cat /sys/kernel/tracing/events/sched/sched_process_fork/hist # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [paused] { child_comm: dconf worker } hitcount: 1 { child_comm: kthreadd } hitcount: 1 { child_comm: dconf worker } hitcount: 1 { child_comm: gdbus } hitcount: 1 { child_comm: ibus-daemon } hitcount: 1 { child_comm: Socket Thread } hitcount: 2 { child_comm: evolution-alarm } hitcount: 2 { child_comm: smbd } hitcount: 2 { child_comm: bash } hitcount: 3 { child_comm: whoopsie } hitcount: 3 { child_comm: compiz } hitcount: 3 { child_comm: evolution-sourc } hitcount: 4 { child_comm: pool } hitcount: 5 { child_comm: postgres } hitcount: 6 { child_comm: firefox } hitcount: 8 { child_comm: dhclient } hitcount: 10 { child_comm: emacs } hitcount: 12 { child_comm: dbus-daemon } hitcount: 20 { child_comm: nm-dispatcher.a } hitcount: 20 { child_comm: evolution } hitcount: 35 { child_comm: glib-pacrunner } hitcount: 59 Totals: Hits: 199 Entries: 21 Dropped: 0要手动继续让触发器聚合事件，请附加 :cont 代替。请注意，触发器信息再次显示为 [active]，并且数据已更改
# echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \ /sys/kernel/tracing/events/sched/sched_process_fork/trigger # cat /sys/kernel/tracing/events/sched/sched_process_fork/hist # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] { child_comm: dconf worker } hitcount: 1 { child_comm: dconf worker } hitcount: 1 { child_comm: kthreadd } hitcount: 1 { child_comm: gdbus } hitcount: 1 { child_comm: ibus-daemon } hitcount: 1 { child_comm: Socket Thread } hitcount: 2 { child_comm: evolution-alarm } hitcount: 2 { child_comm: smbd } hitcount: 2 { child_comm: whoopsie } hitcount: 3 { child_comm: compiz } hitcount: 3 { child_comm: evolution-sourc } hitcount: 4 { child_comm: bash } hitcount: 5 { child_comm: pool } hitcount: 5 { child_comm: postgres } hitcount: 6 { child_comm: firefox } hitcount: 8 { child_comm: dhclient } hitcount: 11 { child_comm: emacs } hitcount: 12 { child_comm: dbus-daemon } hitcount: 22 { child_comm: nm-dispatcher.a } hitcount: 22 { child_comm: evolution } hitcount: 35 { child_comm: glib-pacrunner } hitcount: 59 Totals: Hits: 206 Entries: 21 Dropped: 0前面的示例显示了如何通过将“pause”和“continue”附加到 hist 触发器命令来启动和停止 hist 触发器。也可以通过最初启动附加了“:pause”的触发器，以暂停状态启动 hist 触发器。这允许您仅在准备好开始收集数据时才启动触发器，而不是在此之前。例如，您可以在暂停状态下启动触发器，然后取消暂停并执行您想要测量的操作，然后在完成后再次暂停触发器。
当然，手动执行此操作可能很困难并且容易出错，但可以通过 enable_hist 和 disable_hist 触发器根据某些条件自动启动和停止 hist 触发器。
例如，假设我们想看看使用 wget 下载一个大小合适的文件时，每个导致 netif_receive_skb 事件的调用路径的 skb 长度的相对权重。
首先，我们在 netif_receive_skb 事件上设置一个最初暂停的堆栈跟踪触发器
# echo 'hist:key=common_stacktrace:vals=len:pause' > \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger接下来，我们在 sched_process_exec 事件上设置一个“enable_hist”触发器，其中包含“if filename==/usr/bin/wget”过滤器。此新触发器的效果是，如果且仅当它看到文件名为“/usr/bin/wget”的 sched_process_exec 事件，它才会“取消暂停”我们刚刚在 netif_receive_skb 上设置的 hist 触发器。发生这种情况时，所有 netif_receive_skb 事件都会聚合到以堆栈跟踪为键的哈希表中
# echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ /sys/kernel/tracing/events/sched/sched_process_exec/trigger聚合会持续进行，直到 netif_receive_skb 再次暂停，这是以下 disable_hist 事件通过在 sched_process_exit 事件上创建类似的设置（使用过滤器“comm==wget”）所做的事情
# echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ /sys/kernel/tracing/events/sched/sched_process_exit/trigger每当进程退出并且 disable_hist 触发器过滤器的 comm 字段与“comm==wget”匹配时，netif_receive_skb hist 触发器将被禁用。
总体效果是，仅在 wget 期间，netif_receive_skb 事件才会聚合到哈希表中。执行 wget 命令然后列出“hist”文件将显示 wget 命令生成的输出
$ wget https://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上面显示了 wget 命令期间的所有 netif_receive_skb 调用路径及其总长度。
“clear”hist 触发器参数可用于清除哈希表。假设我们想尝试再次运行前面的示例，但这次也想查看进入直方图的完整事件列表。为了避免不得不再次设置所有内容，我们可以先清除直方图
# echo 'hist:key=common_stacktrace:vals=len:clear' >> \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger只是为了验证它实际上已被清除，这是我们现在在 hist 文件中看到的内容
# cat /sys/kernel/tracing/events/net/netif_receive_skb/hist # trigger info: hist:keys=common_stacktrace:vals=len:sort=hitcount:size=2048 [paused] Totals: Hits: 0 Entries: 0 Dropped: 0由于我们想查看在新运行期间发生的每个 netif_receive_skb 事件的详细列表，这些事件实际上是聚合到哈希表中的相同事件，因此我们将一些额外的“enable_event”事件添加到触发 sched_process_exec 和 sched_process_exit 事件，如下所示
# echo 'enable_event:net:netif_receive_skb if filename==/usr/bin/wget' > \ /sys/kernel/tracing/events/sched/sched_process_exec/trigger # echo 'disable_event:net:netif_receive_skb if comm==wget' > \ /sys/kernel/tracing/events/sched/sched_process_exit/trigger如果您读取 sched_process_exec 和 sched_process_exit 触发器的触发器文件，您应该看到每个触发器有两个触发器：一个启用/禁用 hist 聚合，另一个启用/禁用事件日志记录
# cat /sys/kernel/tracing/events/sched/sched_process_exec/trigger enable_event:net:netif_receive_skb:unlimited if filename==/usr/bin/wget enable_hist:net:netif_receive_skb:unlimited if filename==/usr/bin/wget # cat /sys/kernel/tracing/events/sched/sched_process_exit/trigger enable_event:net:netif_receive_skb:unlimited if comm==wget disable_hist:net:netif_receive_skb:unlimited if comm==wget换句话说，每当命中 sched_process_exec 或 sched_process_exit 事件并且与“wget”匹配时，它都会启用或禁用直方图和事件日志，最终得到的是一个仅覆盖指定持续时间的哈希表和一组事件。再次运行 wget 命令
$ wget https://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 . . .以下示例演示了如何将多个 hist 触发器附加到给定的事件。此功能可用于创建一组从同一组事件派生的不同摘要，或用于比较不同过滤器的效果等
# echo 'hist:keys=skbaddr.hex:vals=len if len < 0' >> \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger # echo 'hist:keys=skbaddr.hex:vals=len if len > 4096' >> \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger # echo 'hist:keys=skbaddr.hex:vals=len if len == 256' >> \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger # echo 'hist:keys=skbaddr.hex:vals=len' >> \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger # echo 'hist:keys=len:vals=common_preempt_count' >> \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger上面的命令集创建了四个仅在其过滤器中不同的触发器，以及一个完全不同但相当荒谬的触发器。请注意，为了将多个 hist 触发器附加到同一文件，您应该使用“>>”运算符来附加它们（“>”也会添加新的 hist 触发器，但会预先删除任何现有的 hist 触发器）。
显示事件的“hist”文件的内容会显示所有五个直方图的内容
# cat /sys/kernel/tracing/events/net/netif_receive_skb/hist # event histogram # # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active] # { len: 176 } hitcount: 1 common_preempt_count: 0 { len: 223 } hitcount: 1 common_preempt_count: 0 { len: 4854 } hitcount: 1 common_preempt_count: 0 { len: 395 } hitcount: 1 common_preempt_count: 0 { len: 177 } hitcount: 1 common_preempt_count: 0 { len: 446 } hitcount: 1 common_preempt_count: 0 { len: 1601 } hitcount: 1 common_preempt_count: 0 . . . { len: 1280 } hitcount: 66 common_preempt_count: 0 { len: 116 } hitcount: 81 common_preempt_count: 40 { len: 708 } hitcount: 112 common_preempt_count: 0 { len: 46 } hitcount: 221 common_preempt_count: 0 { len: 1264 } hitcount: 458 common_preempt_count: 0 Totals: Hits: 1428 Entries: 147 Dropped: 0 # event histogram # # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] # { skbaddr: ffff8800baee5e00 } hitcount: 1 len: 130 { skbaddr: ffff88005f3d5600 } hitcount: 1 len: 1280 { skbaddr: ffff88005f3d4900 } hitcount: 1 len: 1280 { skbaddr: ffff88009fed6300 } hitcount: 1 len: 115 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 115 { skbaddr: ffff88008cdb1900 } hitcount: 1 len: 46 { skbaddr: ffff880064b5ef00 } hitcount: 1 len: 118 { skbaddr: ffff880044e3c700 } hitcount: 1 len: 60 { skbaddr: ffff880100065900 } hitcount: 1 len: 46 { skbaddr: ffff8800d46bd500 } hitcount: 1 len: 116 { skbaddr: ffff88005f3d5f00 } hitcount: 1 len: 1280 { skbaddr: ffff880100064700 } hitcount: 1 len: 365 { skbaddr: ffff8800badb6f00 } hitcount: 1 len: 60 . . . { skbaddr: ffff88009fe0be00 } hitcount: 27 len: 24677 { skbaddr: ffff88009fe0a400 } hitcount: 27 len: 23052 { skbaddr: ffff88009fe0b700 } hitcount: 31 len: 25589 { skbaddr: ffff88009fe0b600 } hitcount: 32 len: 27326 { skbaddr: ffff88006a462800 } hitcount: 68 len: 71678 { skbaddr: ffff88006a463700 } hitcount: 70 len: 72678 { skbaddr: ffff88006a462b00 } hitcount: 71 len: 77589 { skbaddr: ffff88006a463600 } hitcount: 73 len: 71307 { skbaddr: ffff88006a462200 } hitcount: 81 len: 81032 Totals: Hits: 1451 Entries: 318 Dropped: 0 # event histogram # # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [active] # Totals: Hits: 0 Entries: 0 Dropped: 0 # event histogram # # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [active] # { skbaddr: ffff88009fd2c300 } hitcount: 1 len: 7212 { skbaddr: ffff8800d2bcce00 } hitcount: 1 len: 7212 { skbaddr: ffff8800d2bcd700 } hitcount: 1 len: 7212 { skbaddr: ffff8800d2bcda00 } hitcount: 1 len: 21492 { skbaddr: ffff8800ae2e2d00 } hitcount: 1 len: 7212 { skbaddr: ffff8800d2bcdb00 } hitcount: 1 len: 7212 { skbaddr: ffff88006a4df500 } hitcount: 1 len: 4854 { skbaddr: ffff88008ce47b00 } hitcount: 1 len: 18636 { skbaddr: ffff8800ae2e2200 } hitcount: 1 len: 12924 { skbaddr: ffff88005f3e1000 } hitcount: 1 len: 4356 { skbaddr: ffff8800d2bcdc00 } hitcount: 2 len: 24420 { skbaddr: ffff8800d2bcc200 } hitcount: 2 len: 12996 Totals: Hits: 14 Entries: 12 Dropped: 0 # event histogram # # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active] # Totals: Hits: 0 Entries: 0 Dropped: 0可以使用命名触发器来使触发器共享一组公共的直方图数据。此功能主要用于组合由内联函数中包含的追踪点生成的事件的输出，但名称可以用于任何事件上的 hist 触发器。例如，这两个触发器在命中时将更新共享的“foo”直方图数据中的相同“len”字段
# echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ /sys/kernel/tracing/events/net/netif_receive_skb/trigger # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ /sys/kernel/tracing/events/net/netif_rx/trigger您可以通过同时读取每个事件的 hist 文件来查看它们是否正在更新公共直方图数据
# cat /sys/kernel/tracing/events/net/netif_receive_skb/hist; cat /sys/kernel/tracing/events/net/netif_rx/hist # event histogram # # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] # { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260 { skbaddr: ffff880064505000 } hitcount: 1 len: 46 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44 { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676 { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107 { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92 { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142 { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220 { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92 { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92 { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675 { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138 { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138 { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184 { skbaddr: ffff880064504400 } hitcount: 4 len: 184 { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184 { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230 { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196 { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276 { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276 Totals: Hits: 81 Entries: 42 Dropped: 0 # event histogram # # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] # { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260 { skbaddr: ffff880064505000 } hitcount: 1 len: 46 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44 { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676 { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107 { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92 { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142 { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220 { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92 { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92 { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675 { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138 { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138 { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184 { skbaddr: ffff880064504400 } hitcount: 4 len: 184 { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184 { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230 { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196 { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276 { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276 Totals: Hits: 81 Entries: 42 Dropped: 0这是一个示例，演示了如何组合来自任何两个事件的直方图数据，即使它们除了“hitcount”和“common_stacktrace”之外没有任何“兼容”字段。这些命令使用这些字段创建几个名为“bar”的触发器
# echo 'hist:name=bar:key=common_stacktrace:val=hitcount' > \ /sys/kernel/tracing/events/sched/sched_process_fork/trigger # echo 'hist:name=bar:key=common_stacktrace:val=hitcount' > \ /sys/kernel/tracing/events/net/netif_rx/trigger显示任一触发器的输出会显示一些有趣的，如果有点令人困惑的输出
# cat /sys/kernel/tracing/events/sched/sched_process_fork/hist # cat /sys/kernel/tracing/events/net/netif_rx/hist # event histogram # # trigger info: hist:name=bar:keys=common_stacktrace:vals=hitcount:sort=hitcount:size=2048 [active] # { common_stacktrace: kernel_clone+0x18e/0x330 kernel_thread+0x29/0x30 kthreadd+0x154/0x1b0 ret_from_fork+0x3f/0x70 } hitcount: 1 { common_stacktrace: netif_rx_internal+0xb2/0xd0 netif_rx_ni+0x20/0x70 dev_loopback_xmit+0xaa/0xd0 ip_mc_output+0x126/0x240 ip_local_out_sk+0x31/0x40 igmp_send_report+0x1e9/0x230 igmp_timer_expire+0xe9/0x120 call_timer_fn+0x39/0xf0 run_timer_softirq+0x1e1/0x290 __do_softirq+0xfd/0x290 irq_exit+0x98/0xb0 smp_apic_timer_interrupt+0x4a/0x60 apic_timer_interrupt+0x6d/0x80 cpuidle_enter+0x17/0x20 call_cpuidle+0x3b/0x60 cpu_startup_entry+0x22d/0x310 } hitcount: 1 { common_stacktrace: netif_rx_internal+0xb2/0xd0 netif_rx_ni+0x20/0x70 dev_loopback_xmit+0xaa/0xd0 ip_mc_output+0x17f/0x240 ip_local_out_sk+0x31/0x40 ip_send_skb+0x1a/0x50 udp_send_skb+0x13e/0x270 udp_sendmsg+0x2bf/0x980 inet_sendmsg+0x67/0xa0 sock_sendmsg+0x38/0x50 SYSC_sendto+0xef/0x170 SyS_sendto+0xe/0x10 entry_SYSCALL_64_fastpath+0x12/0x6a } hitcount: 2 { common_stacktrace: netif_rx_internal+0xb2/0xd0 netif_rx+0x1c/0x60 loopback_xmit+0x6c/0xb0 dev_hard_start_xmit+0x219/0x3a0 __dev_queue_xmit+0x415/0x4f0 dev_queue_xmit_sk+0x13/0x20 ip_finish_output2+0x237/0x340 ip_finish_output+0x113/0x1d0 ip_output+0x66/0xc0 ip_local_out_sk+0x31/0x40 ip_send_skb+0x1a/0x50 udp_send_skb+0x16d/0x270 udp_sendmsg+0x2bf/0x980 inet_sendmsg+0x67/0xa0 sock_sendmsg+0x38/0x50 ___sys_sendmsg+0x14e/0x270 } hitcount: 76 { common_stacktrace: netif_rx_internal+0xb2/0xd0 netif_rx+0x1c/0x60 loopback_xmit+0x6c/0xb0 dev_hard_start_xmit+0x219/0x3a0 __dev_queue_xmit+0x415/0x4f0 dev_queue_xmit_sk+0x13/0x20 ip_finish_output2+0x237/0x340 ip_finish_output+0x113/0x1d0 ip_output+0x66/0xc0 ip_local_out_sk+0x31/0x40 ip_send_skb+0x1a/0x50 udp_send_skb+0x16d/0x270 udp_sendmsg+0x2bf/0x980 inet_sendmsg+0x67/0xa0 sock_sendmsg+0x38/0x50 ___sys_sendmsg+0x269/0x270 } hitcount: 77 { common_stacktrace: netif_rx_internal+0xb2/0xd0 netif_rx+0x1c/0x60 loopback_xmit+0x6c/0xb0 dev_hard_start_xmit+0x219/0x3a0 __dev_queue_xmit+0x415/0x4f0 dev_queue_xmit_sk+0x13/0x20 ip_finish_output2+0x237/0x340 ip_finish_output+0x113/0x1d0 ip_output+0x66/0xc0 ip_local_out_sk+0x31/0x40 ip_send_skb+0x1a/0x50 udp_send_skb+0x16d/0x270 udp_sendmsg+0x2bf/0x980 inet_sendmsg+0x67/0xa0 sock_sendmsg+0x38/0x50 SYSC_sendto+0xef/0x170 } hitcount: 88 { common_stacktrace: kernel_clone+0x18e/0x330 SyS_clone+0x19/0x20 entry_SYSCALL_64_fastpath+0x12/0x6a } hitcount: 244 Totals: Hits: 489 Entries: 7 Dropped: 0
2.2 事件间 hist 触发器¶
事件间 hist 触发器是 hist 触发器，它组合来自一个或多个其他事件的值，并使用该数据创建直方图。来自事件间直方图的数据反过来可以成为进一步组合的直方图的来源，从而提供相关的直方图链，这对于某些应用程序很重要。
可以在此方式中使用的一个事件间量的最重要示例是延迟，这只是两个事件之间的时间戳差异。虽然延迟是最重要的事件间量，但请注意，由于支持在整个追踪事件子系统中完全通用，因此任何事件字段都可以用于事件间量。
将来自其他直方图的数据组合到有用链中的直方图的一个示例是“唤醒切换延迟”直方图，它组合了“唤醒延迟”直方图和“切换延迟”直方图。
通常，hist 触发器规范由一个（可能复合的）键以及一个或多个数值组成，这些数值是与该键关联的不断更新的总和。在这种情况下，直方图规范由引用与单个事件类型关联的追踪事件字段的单个键和值规范组成。
事件间 hist 触发器扩展允许引用和组合来自多个事件的字段，从而形成多事件直方图规范。为了支持这个总体目标，hist 触发器支持添加了一些启用功能
为了计算事件间量，需要保存来自一个事件的值，然后从另一个事件引用该值。这需要引入对直方图“变量”的支持。
事件间量的计算及其组合需要对将简单表达式 (+ 和 -) 应用于变量的一些最小支持。
由事件间量组成的直方图在逻辑上不是任何一个事件的直方图（因此，让任何一个事件的“hist”文件托管直方图输出实际上没有意义）。为了解决直方图与事件组合相关联的想法，添加了允许创建“合成”事件的支持，这些事件是从其他事件派生的事件。这些合成事件是像任何其他事件一样的完全成熟的事件，并且可以像这样使用，例如创建前面提到的“组合”直方图。
一组“操作”可以与直方图条目关联 - 这些操作可用于生成前面提到的合成事件，但也可用于其他目的，例如在命中“最大”延迟时保存上下文。
追踪事件没有与其关联的“时间戳”，但是有一个隐式时间戳与底层 ftrace 环形缓冲区中的事件一起保存。此时间戳现在作为名为“common_timestamp”的合成字段公开，可以在直方图中使用，就像它是任何其他事件字段一样；它不是跟踪格式中的实际字段，而是一个合成值，但仍然可以像实际字段一样使用。默认情况下，它的单位是纳秒；将“.usecs”附加到 common_timestamp 字段会将单位更改为微秒。
关于事件间时间戳的说明：如果在直方图中使用 common_timestamp，则跟踪缓冲区会自动切换为使用绝对时间戳和“全局”跟踪时钟，以避免与其他 CPU 上不一致的时钟的虚假时间戳差异。可以使用“clock=XXX”hist 触发器属性覆盖此设置，其中 XXX 是 tracing/trace_clock 伪文件中列出的任何时钟。
以下部分更详细地描述了这些功能。
2.2.1 直方图变量¶
变量只是用于在匹配事件之间保存和检索值的命名位置。“匹配”事件定义为具有匹配键的事件 - 如果为与该键对应的直方图条目保存了变量，则任何具有匹配键的后续事件都可以访问该变量。
变量的值通常可用于任何后续事件，直到后续事件将其设置为其他值。该规则的一个例外是，表达式中使用的任何变量本质上都是“只读一次” - 一旦它被后续事件中的表达式使用，它就会重置为“未设置”状态，这意味着除非再次设置，否则无法再次使用。这不仅确保事件不会在计算中使用未初始化的变量，而且该变量仅使用一次，而不是用于任何不相关的后续匹配。
保存变量的基本语法是简单地将不对应于任何关键字的唯一变量名称与“=”符号一起前缀到任何事件字段。
这会为键为“next_pid”的直方图条目创建一个名为“ts0”的变量
# echo 'hist:keys=next_pid:vals=$ts0:ts0=common_timestamp ... >> \
event/trigger
任何具有与“next_pid”相同 pid 的后续事件都可以访问 ts0 变量。
变量引用是通过在变量名称前面加上“$”符号形成的。因此，例如，上面的 ts0 变量在表达式中将引用为“$ts0”。
因为使用了“vals=”，所以上面的 common_timestamp 变量值也会像正常的直方图值一样求和（尽管对于时间戳来说，这没什么意义）。
下面显示了也可以以相同的方式保存键值
# echo 'hist:timer_pid=common_pid:key=timer_pid ...' >> event/trigger
如果变量不是键变量或以“vals=”为前缀，则关联的事件字段将保存在变量中，但不会作为值求和
# echo 'hist:keys=next_pid:ts1=common_timestamp ...' >> event/trigger
可以同时分配多个变量。下面将导致 ts0 和 b 都创建为变量，common_timestamp 和 field1 也会额外地作为值求和
# echo 'hist:keys=pid:vals=$ts0,$b:ts0=common_timestamp,b=field1 ...' >> \
event/trigger
请注意，变量赋值可以出现在它们的使用之前或之后。下面的命令的行为与上面的命令相同
# echo 'hist:keys=pid:ts0=common_timestamp,b=field1:vals=$ts0,$b ...' >> \
event/trigger
还可以通过简单地用冒号分隔来分配任意数量的未绑定到“vals=”前缀的变量。下面是相同的事情，但没有在直方图中求和值
# echo 'hist:keys=pid:ts0=common_timestamp:b=field1 ...' >> event/trigger
如上所述设置的变量可以在另一个事件中引用并在表达式中使用。
例如，以下是如何计算延迟
# echo 'hist:keys=pid,prio:ts0=common_timestamp ...' >> event1/trigger
# echo 'hist:keys=next_pid:wakeup_lat=common_timestamp-$ts0 ...' >> event2/trigger
在上面的第一行中，事件的时间戳被保存到变量 ts0 中。在下一行中，ts0 从第二个事件的时间戳中减去以产生延迟，然后将其分配到另一个变量“wakeup_lat”中。下面的 hist 触发器反过来利用 wakeup_lat 变量来使用来自另一个事件的相同键和变量来计算组合延迟
# echo 'hist:key=pid:wakeupswitch_lat=$wakeup_lat+$switchtime_lat ...' >> event3/trigger
表达式支持使用加法、减法、乘法和除法运算符 (+-*/)。
请注意，如果在解析时无法检测到除以零的情况（即除数不是常数），则结果将为 -1。
数值常量也可以直接在表达式中使用
# echo 'hist:keys=next_pid:timestamp_secs=common_timestamp/1000000 ...' >> event/trigger
或分配给变量并在后续表达式中引用
# echo 'hist:keys=next_pid:us_per_sec=1000000 ...' >> event/trigger
# echo 'hist:keys=next_pid:timestamp_secs=common_timestamp/$us_per_sec ...' >> event/trigger
变量甚至可以保存堆栈跟踪，这对于合成事件很有用。
2.2.2 合成事件¶
合成事件是用户定义的事件，由与一个或多个其他事件关联的 hist 触发器变量或字段生成。它们的目的是提供一种机制，用于显示跨多个事件的数据，与现有和已经熟悉的普通事件用法一致。
要定义合成事件，用户需要将一个简单的规范写入 tracing/synthetic_events 文件，该规范包含新事件的名称以及一个或多个变量及其类型，这些变量及其类型可以是任何有效字段类型，并用分号分隔。
有关可用类型，请参阅 synth_field_size()。
如果 field_name 包含 [n]，则该字段被认为是静态数组。
如果 field_names 包含 []（没有下标），则该字段被视为动态数组，它在事件中只占用容纳数组所需的空间。
可以使用静态符号指定字符串字段
char name[32];
或动态符号
char name[];
两者的尺寸限制均为 256。
例如，以下代码创建一个名为“wakeup_latency”的新事件，其中包含 3 个字段：lat、pid 和 prio。 这些字段中的每一个都只是对另一个事件中的变量的变量引用
# echo 'wakeup_latency \
u64 lat; \
pid_t pid; \
int prio' >> \
/sys/kernel/tracing/synthetic_events
读取 tracing/synthetic_events 文件会列出所有当前定义的合成事件，在本例中是上面定义的事件
# cat /sys/kernel/tracing/synthetic_events
wakeup_latency u64 lat; pid_t pid; int prio
可以通过在定义现有合成事件的命令前添加“！”来删除该定义
# echo '!wakeup_latency u64 lat pid_t pid int prio' >> \
/sys/kernel/tracing/synthetic_events
此时，事件子系统中还没有实例化实际的“wakeup_latency”事件 - 要使其发生，需要实例化一个“hist trigger action”并将其绑定到在其他事件上定义的实际字段和变量（有关如何使用 hist trigger "onmatch" action 执行此操作，请参见下面的 2.2.3 节）。 完成此操作后，将创建“wakeup_latency”合成事件实例。
新事件在 tracing/events/synthetic/ 目录下创建，并且看起来和行为方式与任何其他事件一样
# ls /sys/kernel/tracing/events/synthetic/wakeup_latency
enable filter format hist id trigger
现在可以为新合成事件定义直方图
# echo 'hist:keys=pid,prio,lat.log2:sort=lat' >> \
/sys/kernel/tracing/events/synthetic/wakeup_latency/trigger
上面显示了以 2 的幂分组的延迟“lat”。
与任何其他事件一样，一旦为事件启用了直方图，就可以通过读取事件的“hist”文件来显示输出
# cat /sys/kernel/tracing/events/synthetic/wakeup_latency/hist
# event histogram
#
# trigger info: hist:keys=pid,prio,lat.log2:vals=hitcount:sort=lat.log2:size=2048 [active]
#
{ pid: 2035, prio: 9, lat: ~ 2^2 } hitcount: 43
{ pid: 2034, prio: 9, lat: ~ 2^2 } hitcount: 60
{ pid: 2029, prio: 9, lat: ~ 2^2 } hitcount: 965
{ pid: 2034, prio: 120, lat: ~ 2^2 } hitcount: 9
{ pid: 2033, prio: 120, lat: ~ 2^2 } hitcount: 5
{ pid: 2030, prio: 9, lat: ~ 2^2 } hitcount: 335
{ pid: 2030, prio: 120, lat: ~ 2^2 } hitcount: 10
{ pid: 2032, prio: 120, lat: ~ 2^2 } hitcount: 1
{ pid: 2035, prio: 120, lat: ~ 2^2 } hitcount: 2
{ pid: 2031, prio: 9, lat: ~ 2^2 } hitcount: 176
{ pid: 2028, prio: 120, lat: ~ 2^2 } hitcount: 15
{ pid: 2033, prio: 9, lat: ~ 2^2 } hitcount: 91
{ pid: 2032, prio: 9, lat: ~ 2^2 } hitcount: 125
{ pid: 2029, prio: 120, lat: ~ 2^2 } hitcount: 4
{ pid: 2031, prio: 120, lat: ~ 2^2 } hitcount: 3
{ pid: 2029, prio: 120, lat: ~ 2^3 } hitcount: 2
{ pid: 2035, prio: 9, lat: ~ 2^3 } hitcount: 41
{ pid: 2030, prio: 120, lat: ~ 2^3 } hitcount: 1
{ pid: 2032, prio: 9, lat: ~ 2^3 } hitcount: 32
{ pid: 2031, prio: 9, lat: ~ 2^3 } hitcount: 44
{ pid: 2034, prio: 9, lat: ~ 2^3 } hitcount: 40
{ pid: 2030, prio: 9, lat: ~ 2^3 } hitcount: 29
{ pid: 2033, prio: 9, lat: ~ 2^3 } hitcount: 31
{ pid: 2029, prio: 9, lat: ~ 2^3 } hitcount: 31
{ pid: 2028, prio: 120, lat: ~ 2^3 } hitcount: 18
{ pid: 2031, prio: 120, lat: ~ 2^3 } hitcount: 2
{ pid: 2028, prio: 120, lat: ~ 2^4 } hitcount: 1
{ pid: 2029, prio: 9, lat: ~ 2^4 } hitcount: 4
{ pid: 2031, prio: 120, lat: ~ 2^7 } hitcount: 1
{ pid: 2032, prio: 120, lat: ~ 2^7 } hitcount: 1
Totals:
Hits: 2122
Entries: 30
Dropped: 0
延迟值也可以按给定大小线性分组，使用“.buckets”修饰符并指定大小（在本例中为 10 个一组）
# echo 'hist:keys=pid,prio,lat.buckets=10:sort=lat' >> \
/sys/kernel/tracing/events/synthetic/wakeup_latency/trigger
# event histogram
#
# trigger info: hist:keys=pid,prio,lat.buckets=10:vals=hitcount:sort=lat.buckets=10:size=2048 [active]
#
{ pid: 2067, prio: 9, lat: ~ 0-9 } hitcount: 220
{ pid: 2068, prio: 9, lat: ~ 0-9 } hitcount: 157
{ pid: 2070, prio: 9, lat: ~ 0-9 } hitcount: 100
{ pid: 2067, prio: 120, lat: ~ 0-9 } hitcount: 6
{ pid: 2065, prio: 120, lat: ~ 0-9 } hitcount: 2
{ pid: 2066, prio: 120, lat: ~ 0-9 } hitcount: 2
{ pid: 2069, prio: 9, lat: ~ 0-9 } hitcount: 122
{ pid: 2069, prio: 120, lat: ~ 0-9 } hitcount: 8
{ pid: 2070, prio: 120, lat: ~ 0-9 } hitcount: 1
{ pid: 2068, prio: 120, lat: ~ 0-9 } hitcount: 7
{ pid: 2066, prio: 9, lat: ~ 0-9 } hitcount: 365
{ pid: 2064, prio: 120, lat: ~ 0-9 } hitcount: 35
{ pid: 2065, prio: 9, lat: ~ 0-9 } hitcount: 998
{ pid: 2071, prio: 9, lat: ~ 0-9 } hitcount: 85
{ pid: 2065, prio: 9, lat: ~ 10-19 } hitcount: 2
{ pid: 2064, prio: 120, lat: ~ 10-19 } hitcount: 2
Totals:
Hits: 2112
Entries: 16
Dropped: 0
要保存堆栈跟踪，请创建具有类型为“unsigned long[]”甚至只是“long[]”字段的合成事件。 例如，要查看任务在不可中断状态下被阻塞的时间
# cd /sys/kernel/tracing
# echo 's:block_lat pid_t pid; u64 delta; unsigned long[] stack;' > dynamic_events
# echo 'hist:keys=next_pid:ts=common_timestamp.usecs,st=common_stacktrace if prev_state == 2' >> events/sched/sched_switch/trigger
# echo 'hist:keys=prev_pid:delta=common_timestamp.usecs-$ts,s=$st:onmax($delta).trace(block_lat,prev_pid,$delta,$s)' >> events/sched/sched_switch/trigger
# echo 1 > events/synthetic/block_lat/enable
# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 2/2 #P:8
#
# _-----=> irqs-off/BH-disabled
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / _-=> migrate-disable
# |||| / delay
# TASK-PID CPU# ||||| TIMESTAMP FUNCTION
# | | | ||||| | |
<idle>-0 [005] d..4. 521.164922: block_lat: pid=0 delta=8322 stack=STACK:
=> __schedule+0x448/0x7b0
=> schedule+0x5a/0xb0
=> io_schedule+0x42/0x70
=> bit_wait_io+0xd/0x60
=> __wait_on_bit+0x4b/0x140
=> out_of_line_wait_on_bit+0x91/0xb0
=> jbd2_journal_commit_transaction+0x1679/0x1a70
=> kjournald2+0xa9/0x280
=> kthread+0xe9/0x110
=> ret_from_fork+0x2c/0x50
<...>-2 [004] d..4. 525.184257: block_lat: pid=2 delta=76 stack=STACK:
=> __schedule+0x448/0x7b0
=> schedule+0x5a/0xb0
=> schedule_timeout+0x11a/0x150
=> wait_for_completion_killable+0x144/0x1f0
=> __kthread_create_on_node+0xe7/0x1e0
=> kthread_create_on_node+0x51/0x70
=> create_worker+0xcc/0x1a0
=> worker_thread+0x2ad/0x380
=> kthread+0xe9/0x110
=> ret_from_fork+0x2c/0x50
具有堆栈跟踪字段的合成事件可以将其用作直方图中的键
# echo 'hist:keys=delta.buckets=100,stack.stacktrace:sort=delta' > events/synthetic/block_lat/trigger
# cat events/synthetic/block_lat/hist
# event histogram
#
# trigger info: hist:keys=delta.buckets=100,stack.stacktrace:vals=hitcount:sort=delta.buckets=100:size=2048 [active]
#
{ delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
schedule+0x6b/0x110
io_schedule+0x46/0x80
bit_wait_io+0x11/0x80
__wait_on_bit+0x4e/0x120
out_of_line_wait_on_bit+0x8d/0xb0
__wait_on_buffer+0x33/0x40
jbd2_journal_commit_transaction+0x155a/0x19b0
kjournald2+0xab/0x270
kthread+0xfa/0x130
ret_from_fork+0x29/0x50
} hitcount: 1
{ delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
schedule+0x6b/0x110
io_schedule+0x46/0x80
rq_qos_wait+0xd0/0x170
wbt_wait+0x9e/0xf0
__rq_qos_throttle+0x25/0x40
blk_mq_submit_bio+0x2c3/0x5b0
__submit_bio+0xff/0x190
submit_bio_noacct_nocheck+0x25b/0x2b0
submit_bio_noacct+0x20b/0x600
submit_bio+0x28/0x90
ext4_bio_write_page+0x1e0/0x8c0
mpage_submit_page+0x60/0x80
mpage_process_page_bufs+0x16c/0x180
mpage_prepare_extent_to_map+0x23f/0x530
} hitcount: 1
{ delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
schedule+0x6b/0x110
schedule_hrtimeout_range_clock+0x97/0x110
schedule_hrtimeout_range+0x13/0x20
usleep_range_state+0x65/0x90
__intel_wait_for_register+0x1c1/0x230 [i915]
intel_psr_wait_for_idle_locked+0x171/0x2a0 [i915]
intel_pipe_update_start+0x169/0x360 [i915]
intel_update_crtc+0x112/0x490 [i915]
skl_commit_modeset_enables+0x199/0x600 [i915]
intel_atomic_commit_tail+0x7c4/0x1080 [i915]
intel_atomic_commit_work+0x12/0x20 [i915]
process_one_work+0x21c/0x3f0
worker_thread+0x50/0x3e0
kthread+0xfa/0x130
} hitcount: 3
{ delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
schedule+0x6b/0x110
schedule_timeout+0x11e/0x160
__wait_for_common+0x8f/0x190
wait_for_completion+0x24/0x30
__flush_work.isra.0+0x1cc/0x360
flush_work+0xe/0x20
drm_mode_rmfb+0x18b/0x1d0 [drm]
drm_mode_rmfb_ioctl+0x10/0x20 [drm]
drm_ioctl_kernel+0xb8/0x150 [drm]
drm_ioctl+0x243/0x560 [drm]
__x64_sys_ioctl+0x92/0xd0
do_syscall_64+0x59/0x90
entry_SYSCALL_64_after_hwframe+0x72/0xdc
} hitcount: 1
{ delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
schedule+0x6b/0x110
schedule_timeout+0x87/0x160
__wait_for_common+0x8f/0x190
wait_for_completion_timeout+0x1d/0x30
drm_atomic_helper_wait_for_flip_done+0x57/0x90 [drm_kms_helper]
intel_atomic_commit_tail+0x8ce/0x1080 [i915]
intel_atomic_commit_work+0x12/0x20 [i915]
process_one_work+0x21c/0x3f0
worker_thread+0x50/0x3e0
kthread+0xfa/0x130
ret_from_fork+0x29/0x50
} hitcount: 1
{ delta: ~ 100-199, stack.stacktrace __schedule+0xa19/0x1520
schedule+0x6b/0x110
schedule_hrtimeout_range_clock+0x97/0x110
schedule_hrtimeout_range+0x13/0x20
usleep_range_state+0x65/0x90
pci_set_low_power_state+0x17f/0x1f0
pci_set_power_state+0x49/0x250
pci_finish_runtime_suspend+0x4a/0x90
pci_pm_runtime_suspend+0xcb/0x1b0
__rpm_callback+0x48/0x120
rpm_callback+0x67/0x70
rpm_suspend+0x167/0x780
rpm_idle+0x25a/0x380
pm_runtime_work+0x93/0xc0
process_one_work+0x21c/0x3f0
} hitcount: 1
Totals:
Hits: 10
Entries: 7
Dropped: 0
2.2.3 Hist 触发器“handlers”和“actions”¶
hist 触发器“action”是一个函数，它在添加或更新直方图条目时执行（在大多数情况下是有条件地执行）。
当添加或更新直方图条目时，hist 触发器“handler”决定是否实际调用相应的 action。
Hist 触发器 handlers 和 actions 以通用形式配对在一起
<handler>.<action>
要为给定事件指定 handler.action 对，只需在 hist 触发器规范中的冒号之间指定该 handler.action 对即可。
理论上，任何 handler 都可以与任何 action 组合，但实际上，并非支持所有 handler.action 组合； 如果不支持给定的 handler.action 组合，则 hist 触发器将失败并显示 -EINVAL;
如果没有明确指定，则默认的“handler.action”与一直以来的相同，只是简单地更新与条目关联的值集。 但是，某些应用程序可能希望在此时执行其他操作，例如生成另一个事件或比较并保存最大值。
下面列出了支持的 handlers 和 actions，并在以下段落中更详细地描述了每个 handler 和 action，并结合了一些常见且有用的 handler.action 组合的描述。
可用的 handlers 是
onmatch(matching.event) - 在任何添加或更新时调用 action
onmax(var) - 如果 var 超过当前最大值，则调用 action
onchange(var) - 如果 var 发生更改，则调用 action
可用的 actions 是
trace(<synthetic_event_name>,param list) - 生成合成事件
save(field,...) - 保存当前事件字段
snapshot() - 快照跟踪缓冲区
以下常用的 handler.action 对可用
onmatch(matching.event).trace(<synthetic_event_name>,param list)
每当事件匹配并且直方图条目将被添加或更新时，都会调用“onmatch(matching.event).trace(<synthetic_event_name>,param list)” hist 触发器 action。 它会导致使用“param list”中给出的值生成命名的合成事件。 结果是生成一个合成事件，该事件由调用事件发生时这些变量中包含的值组成。 例如，如果合成事件名称为“wakeup_latency”，则使用 onmatch(event).trace(wakeup_latency,arg1,arg2) 生成一个 wakeup_latency 事件。
还有一种等效的替代形式可用于生成合成事件。 在这种形式中，合成事件名称被用作函数名称。 例如，再次使用“wakeup_latency”合成事件名称，将通过调用 wakeup_latency 事件（就像它是函数调用一样）来生成该事件，并将事件字段值作为参数传入：onmatch(event).wakeup_latency(arg1,arg2)。 这种形式的语法是
onmatch(matching.event).<synthetic_event_name>(param list)
在任何一种情况下，“param list”都由一个或多个参数组成，这些参数可以是“matching.event”或目标事件上定义的变量或字段。 在 param list 中指定的变量或字段可以是完全限定的，也可以是不合格的。 如果变量指定为不合格的，则它必须在两个事件之间是唯一的。 如果用作 param 的字段名称引用目标事件，则可以是不合格的，但如果它引用匹配事件，则必须是完全限定的。 完全限定名称的形式为“system.event_name.$var_name”或“system.event_name.field”。
“matching.event”规范只是 onmatch() 功能的目标事件匹配的事件的完全限定事件名称，形式为“system.event_name”。 比较两个事件的直方图键，以查找事件是否匹配。 如果使用多个直方图键，则所有键都必须按指定的顺序匹配。
最后，“param list”中变量/字段的数量和类型必须与正在生成的合成事件中字段的数量和类型相匹配。
例如，下面定义了一个简单的合成事件，并在调用合成事件时使用了在 sched_wakeup_new 事件上定义的变量作为参数。 在这里，我们定义了合成事件
# echo 'wakeup_new_test pid_t pid' >> \ /sys/kernel/tracing/synthetic_events # cat /sys/kernel/tracing/synthetic_events wakeup_new_test pid_t pid以下 hist 触发器既定义了缺失的 testpid 变量，又指定了一个 onmatch() action，该 action 在每次发生 sched_wakeup_new 事件时都会生成一个 wakeup_new_test 合成事件，由于“if comm == "cyclictest"”过滤器，这仅在可执行文件是 cyclictest 时才会发生
# echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\ wakeup_new_test($testpid) if comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_wakeup_new/trigger或者，等效地，使用“trace”关键字语法
# echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\ trace(wakeup_new_test,$testpid) if comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_wakeup_new/trigger现在，基于这些事件创建和显示直方图只是在 tracing/events/synthetic 目录中使用字段和新合成事件的问题，与往常一样
# echo 'hist:keys=pid:sort=pid' >> \ /sys/kernel/tracing/events/synthetic/wakeup_new_test/trigger运行“cyclictest”应导致 wakeup_new 事件生成 wakeup_new_test 合成事件，这应导致 wakeup_new_test 事件的 hist 文件中出现直方图输出
# cat /sys/kernel/tracing/events/synthetic/wakeup_new_test/hist更典型的用法是使用两个事件来计算延迟。 以下示例使用一组 hist 触发器来生成“wakeup_latency”直方图。
首先，我们定义一个“wakeup_latency”合成事件
# echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> \ /sys/kernel/tracing/synthetic_events接下来，我们指定每当看到 cyclictest 线程的 sched_waking 事件时，将时间戳保存在“ts0”变量中
# echo 'hist:keys=$saved_pid:saved_pid=pid:ts0=common_timestamp.usecs \ if comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_waking/trigger然后，当相应的线程实际通过 sched_switch 事件调度到 CPU 上时（saved_pid 匹配 next_pid），计算延迟并将其与另一个变量和一个事件字段一起使用，以生成一个 wakeup_latency 合成事件
# echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\ onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,\ $saved_pid,next_prio) if next_comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_switch/trigger我们还需要在 wakeup_latency 合成事件上创建一个直方图，以便聚合生成的合成事件数据
# echo 'hist:keys=pid,prio,lat:sort=pid,lat' >> \ /sys/kernel/tracing/events/synthetic/wakeup_latency/trigger最后，一旦我们运行 cyclictest 以实际生成一些事件，我们就可以通过查看 wakeup_latency 合成事件的 hist 文件来查看输出
# cat /sys/kernel/tracing/events/synthetic/wakeup_latency/histonmax(var).save(field,...)
每当与直方图条目关联的“var”的值超过该变量中包含的当前最大值时，都会调用“onmax(var).save(field,...)” hist 触发器 action。
最终结果是，如果“var”超过该 hist 触发器条目的当前最大值，则将保存指定为 onmax.save() params 的跟踪事件字段。 这允许保存来自显示新最大值的事件的上下文，以供以后参考。 显示直方图时，将打印显示已保存值的其他字段。
例如，下面定义了几个 hist 触发器，一个用于 sched_waking，另一个用于 sched_switch，键为 pid。 每当发生 sched_waking 时，时间戳将保存在与当前 pid 对应的条目中，并且当调度程序切换回该 pid 时，将计算时间戳差异。 如果结果延迟（存储在 wakeup_lat 中）超过当前最大延迟，则会记录在 save() 字段中指定的值
# echo 'hist:keys=pid:ts0=common_timestamp.usecs \ if comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_waking/trigger # echo 'hist:keys=next_pid:\ wakeup_lat=common_timestamp.usecs-$ts0:\ onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) \ if next_comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_switch/trigger显示直方图时，最大值和与最大值对应的已保存值将显示在其余字段之后
# cat /sys/kernel/tracing/events/sched/sched_switch/hist { next_pid: 2255 } hitcount: 239 common_timestamp-ts0: 0 max: 27 next_comm: cyclictest prev_pid: 0 prev_prio: 120 prev_comm: swapper/1 { next_pid: 2256 } hitcount: 2355 common_timestamp-ts0: 0 max: 49 next_comm: cyclictest prev_pid: 0 prev_prio: 120 prev_comm: swapper/0 Totals: Hits: 12970 Entries: 2 Dropped: 0onmax(var).snapshot()
每当与直方图条目关联的“var”的值超过该变量中包含的当前最大值时，都会调用“onmax(var).snapshot()” hist 触发器 action。
最终结果是，如果“var”超过任何 hist 触发器条目的当前最大值，则跟踪缓冲区的全局快照将保存在 tracing/snapshot 文件中。
请注意，在这种情况下，最大值是当前跟踪实例的全局最大值，它是直方图的所有 bucket 中的最大值。 显示导致全局最大值的特定跟踪事件的键和全局最大值本身，以及一条消息，说明已拍摄快照以及在何处找到它。 用户可以使用显示的键信息在直方图中找到相应的 bucket，以获取更多详细信息。
例如，下面定义了几个 hist 触发器，一个用于 sched_waking，另一个用于 sched_switch，键为 pid。 每当发生 sched_waking 事件时，时间戳将保存在与当前 pid 对应的条目中，并且当调度程序切换回该 pid 时，将计算时间戳差异。 如果结果延迟（存储在 wakeup_lat 中）超过当前最大延迟，则会拍摄快照。 作为设置的一部分，还会启用所有调度程序事件，这些事件将在某个时间拍摄快照时显示在快照中
# echo 1 > /sys/kernel/tracing/events/sched/enable # echo 'hist:keys=pid:ts0=common_timestamp.usecs \ if comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_waking/trigger # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \ onmax($wakeup_lat).save(next_prio,next_comm,prev_pid,prev_prio, \ prev_comm):onmax($wakeup_lat).snapshot() \ if next_comm=="cyclictest"' >> \ /sys/kernel/tracing/events/sched/sched_switch/trigger显示直方图时，对于每个 bucket，最大值和与最大值对应的已保存值将显示在其余字段之后。
如果拍摄了快照，还会有一条消息指示，以及触发全局最大值的值和事件
# cat /sys/kernel/tracing/events/sched/sched_switch/hist { next_pid: 2101 } hitcount: 200 max: 52 next_prio: 120 next_comm: cyclictest \ prev_pid: 0 prev_prio: 120 prev_comm: swapper/6 { next_pid: 2103 } hitcount: 1326 max: 572 next_prio: 19 next_comm: cyclictest \ prev_pid: 0 prev_prio: 120 prev_comm: swapper/1 { next_pid: 2102 } hitcount: 1982 \ max: 74 next_prio: 19 next_comm: cyclictest \ prev_pid: 0 prev_prio: 120 prev_comm: swapper/5 Snapshot taken (see tracing/snapshot). Details: triggering value { onmax($wakeup_lat) }: 572 \ triggered by event with key: { next_pid: 2103 } Totals: Hits: 3508 Entries: 3 Dropped: 0在上面的例子中，触发全局最大值的事件的键为 next_pid == 2103。如果查看以 2103 为键的 bucket，你将找到与该 bucket 的局部最大值一起 save() 的附加值，该值应与全局最大值相同（因为它是触发全局快照的相同值）。
最后，查看快照数据应在结尾处或附近显示触发快照的事件（在本例中，您可以验证 sched_waking 和 sched_switch 事件之间的时间戳，该时间戳应与全局最大值中显示的时间匹配）
# cat /sys/kernel/tracing/snapshot <...>-2103 [005] d..3 309.873125: sched_switch: prev_comm=cyclictest prev_pid=2103 prev_prio=19 prev_state=D ==> next_comm=swapper/5 next_pid=0 next_prio=120 <idle>-0 [005] d.h3 309.873611: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005 <idle>-0 [005] dNh4 309.873613: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005 <idle>-0 [005] d..3 309.873616: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=cyclictest next_pid=2102 next_prio=19 <...>-2102 [005] d..3 309.873625: sched_switch: prev_comm=cyclictest prev_pid=2102 prev_prio=19 prev_state=D ==> next_comm=swapper/5 next_pid=0 next_prio=120 <idle>-0 [005] d.h3 309.874624: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005 <idle>-0 [005] dNh4 309.874626: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005 <idle>-0 [005] dNh3 309.874628: sched_waking: comm=cyclictest pid=2103 prio=19 target_cpu=005 <idle>-0 [005] dNh4 309.874630: sched_wakeup: comm=cyclictest pid=2103 prio=19 target_cpu=005 <idle>-0 [005] d..3 309.874633: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=cyclictest next_pid=2102 next_prio=19 <idle>-0 [004] d.h3 309.874757: sched_waking: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004 <idle>-0 [004] dNh4 309.874762: sched_wakeup: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004 <idle>-0 [004] d..3 309.874766: sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=gnome-terminal- next_pid=1699 next_prio=120 gnome-terminal--1699 [004] d.h2 309.874941: sched_stat_runtime: comm=gnome-terminal- pid=1699 runtime=180706 [ns] vruntime=1126870572 [ns] <idle>-0 [003] d.s4 309.874956: sched_waking: comm=rcu_sched pid=9 prio=120 target_cpu=007 <idle>-0 [003] d.s5 309.874960: sched_wake_idle_without_ipi: cpu=7 <idle>-0 [003] d.s5 309.874961: sched_wakeup: comm=rcu_sched pid=9 prio=120 target_cpu=007 <idle>-0 [007] d..3 309.874963: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=rcu_sched next_pid=9 next_prio=120 rcu_sched-9 [007] d..3 309.874973: sched_stat_runtime: comm=rcu_sched pid=9 runtime=13646 [ns] vruntime=22531430286 [ns] rcu_sched-9 [007] d..3 309.874978: sched_switch: prev_comm=rcu_sched prev_pid=9 prev_prio=120 prev_state=R+ ==> next_comm=swapper/7 next_pid=0 next_prio=120 <...>-2102 [005] d..4 309.874994: sched_migrate_task: comm=cyclictest pid=2103 prio=19 orig_cpu=5 dest_cpu=1 <...>-2102 [005] d..4 309.875185: sched_wake_idle_without_ipi: cpu=1 <idle>-0 [001] d..3 309.875200: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=cyclictest next_pid=2103 next_prio=19onchange(var).save(field,...)
每当与直方图条目关联的“var”的值发生更改时，都会调用“onchange(var).save(field,...)” hist 触发器 action。
最终结果是，如果“var”针对该 hist 触发器条目发生更改，则将保存指定为 onchange.save() params 的跟踪事件字段。 这允许保存来自更改值的事件的上下文，以供以后参考。 显示直方图时，将打印显示已保存值的其他字段。
onchange(var).snapshot()
每当与直方图条目关联的“var”的值发生更改时，都会调用“onchange(var).snapshot()” hist 触发器 action。
最终结果是，如果“var”针对任何 hist 触发器条目发生更改，则跟踪缓冲区的全局快照将保存在 tracing/snapshot 文件中。
请注意，在这种情况下，更改的值是与当前跟踪实例关联的全局变量。 显示导致值更改的特定跟踪事件的键和全局值本身，以及一条消息，说明已拍摄快照以及在何处找到它。 用户可以使用显示的键信息在直方图中找到相应的 bucket，以获取更多详细信息。
例如，下面在 tcp_probe 事件上定义了一个 hist 触发器，键为 dport。 每当发生 tcp_probe 事件时，都会根据存储在 $cwnd 变量中的当前值检查 cwnd 字段。 如果值已更改，则会拍摄快照。 作为设置的一部分，还会启用所有调度程序和 tcp 事件，这些事件将在某个时间拍摄快照时显示在快照中
# echo 1 > /sys/kernel/tracing/events/sched/enable # echo 1 > /sys/kernel/tracing/events/tcp/enable # echo 'hist:keys=dport:cwnd=snd_cwnd: \ onchange($cwnd).save(snd_wnd,srtt,rcv_wnd): \ onchange($cwnd).snapshot()' >> \ /sys/kernel/tracing/events/tcp/tcp_probe/trigger显示直方图时，对于每个 bucket，跟踪的值和与该值对应的已保存值将显示在其余字段之后。
如果拍摄了快照，还会有一条消息指示，以及触发快照的值和事件
# cat /sys/kernel/tracing/events/tcp/tcp_probe/hist { dport: 1521 } hitcount: 8 changed: 10 snd_wnd: 35456 srtt: 154262 rcv_wnd: 42112 { dport: 80 } hitcount: 23 changed: 10 snd_wnd: 28960 srtt: 19604 rcv_wnd: 29312 { dport: 9001 } hitcount: 172 changed: 10 snd_wnd: 48384 srtt: 260444 rcv_wnd: 55168 { dport: 443 } hitcount: 211 changed: 10 snd_wnd: 26960 srtt: 17379 rcv_wnd: 28800 Snapshot taken (see tracing/snapshot). Details: triggering value { onchange($cwnd) }: 10 triggered by event with key: { dport: 80 } Totals: Hits: 414 Entries: 4 Dropped: 0在上面的例子中，触发快照的事件的键为 dport == 80。如果查看以 80 为键的 bucket，你将找到与该 bucket 的更改值一起 save() 的附加值，该值应与全局更改值相同（因为它是触发全局快照的相同值）。
最后，查看快照数据应在结尾处或附近显示触发快照的事件
# cat /sys/kernel/tracing/snapshot gnome-shell-1261 [006] dN.3 49.823113: sched_stat_runtime: comm=gnome-shell pid=1261 runtime=49347 [ns] vruntime=1835730389 [ns] kworker/u16:4-773 [003] d..3 49.823114: sched_switch: prev_comm=kworker/u16:4 prev_pid=773 prev_prio=120 prev_state=R+ ==> next_comm=kworker/3:2 next_pid=135 next_prio=120 gnome-shell-1261 [006] d..3 49.823114: sched_switch: prev_comm=gnome-shell prev_pid=1261 prev_prio=120 prev_state=R+ ==> next_comm=kworker/6:2 next_pid=387 next_prio=120 kworker/3:2-135 [003] d..3 49.823118: sched_stat_runtime: comm=kworker/3:2 pid=135 runtime=5339 [ns] vruntime=17815800388 [ns] kworker/6:2-387 [006] d..3 49.823120: sched_stat_runtime: comm=kworker/6:2 pid=387 runtime=9594 [ns] vruntime=14589605367 [ns] kworker/6:2-387 [006] d..3 49.823122: sched_switch: prev_comm=kworker/6:2 prev_pid=387 prev_prio=120 prev_state=R+ ==> next_comm=gnome-shell next_pid=1261 next_prio=120 kworker/3:2-135 [003] d..3 49.823123: sched_switch: prev_comm=kworker/3:2 prev_pid=135 prev_prio=120 prev_state=T ==> next_comm=swapper/3 next_pid=0 next_prio=120 <idle>-0 [004] ..s7 49.823798: tcp_probe: src=10.0.0.10:54326 dest=23.215.104.193:80 mark=0x0 length=32 snd_nxt=0xe3ae2ff5 snd_una=0xe3ae2ecd snd_cwnd=10 ssthresh=2147483647 snd_wnd=28960 srtt=19604 rcv_wnd=29312
3. 用户空间创建触发器¶
写入 /sys/kernel/tracing/trace_marker 会写入 ftrace 环形缓冲区。 通过写入 /sys/kernel/tracing/events/ftrace/print/ 中的触发器文件，这也可以像一个事件一样工作
在 cyclictest 休眠之前和唤醒之后修改它以写入 trace_marker 文件，如下所示
static void traceputs(char *str)
{
/* tracemark_fd is the trace_marker file descriptor */
if (tracemark_fd < 0)
return;
/* write the tracemark message */
write(tracemark_fd, str, strlen(str));
}
稍后添加类似的内容
traceputs("start");
clock_nanosleep(...);
traceputs("end");
我们可以从中制作直方图
# cd /sys/kernel/tracing
# echo 'latency u64 lat' > synthetic_events
# echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/trigger
# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) if buf == "end"' >> events/ftrace/print/trigger
# echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
上面创建了一个名为“latency”的合成事件和两个针对 trace_marker 的直方图，一个在“start”写入 trace_marker 文件时触发，另一个在“end”写入时触发。 如果 pids 匹配，则它将调用“latency”合成事件，并将计算出的延迟作为其参数。 最后，将直方图添加到延迟合成事件，以记录计算出的延迟以及 pid。
现在使用以下命令运行 cyclictest
# ./cyclictest -p80 -d0 -i250 -n -a -t --tracemark -b 1000
-p80 : run threads at priority 80
-d0 : have all threads run at the same interval
-i250 : start the interval at 250 microseconds (all threads will do this)
-n : sleep with nanosleep
-a : affine all threads to a separate CPU
-t : one thread per available CPU
--tracemark : enable trace mark writing
-b 1000 : stop if any latency is greater than 1000 microseconds
注意，-b 1000 仅用于使 --tracemark 可用。
然后，我们可以使用以下命令查看由此创建的直方图
# cat events/synthetic/latency/hist
# event histogram
#
# trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
#
{ lat: 107, common_pid: 2039 } hitcount: 1
{ lat: 122, common_pid: 2041 } hitcount: 1
{ lat: 166, common_pid: 2039 } hitcount: 1
{ lat: 174, common_pid: 2039 } hitcount: 1
{ lat: 194, common_pid: 2041 } hitcount: 1
{ lat: 196, common_pid: 2036 } hitcount: 1
{ lat: 197, common_pid: 2038 } hitcount: 1
{ lat: 198, common_pid: 2039 } hitcount: 1
{ lat: 199, common_pid: 2039 } hitcount: 1
{ lat: 200, common_pid: 2041 } hitcount: 1
{ lat: 201, common_pid: 2039 } hitcount: 2
{ lat: 202, common_pid: 2038 } hitcount: 1
{ lat: 202, common_pid: 2043 } hitcount: 1
{ lat: 203, common_pid: 2039 } hitcount: 1
{ lat: 203, common_pid: 2036 } hitcount: 1
{ lat: 203, common_pid: 2041 } hitcount: 1
{ lat: 206, common_pid: 2038 } hitcount: 2
{ lat: 207, common_pid: 2039 } hitcount: 1
{ lat: 207, common_pid: 2036 } hitcount: 1
{ lat: 208, common_pid: 2040 } hitcount: 1
{ lat: 209, common_pid: 2043 } hitcount: 1
{ lat: 210, common_pid: 2039 } hitcount: 1
{ lat: 211, common_pid: 2039 } hitcount: 4
{ lat: 212, common_pid: 2043 } hitcount: 1
{ lat: 212, common_pid: 2039 } hitcount: 2
{ lat: 213, common_pid: 2039 } hitcount: 1
{ lat: 214, common_pid: 2038 } hitcount: 1
{ lat: 214, common_pid: 2039 } hitcount: 2
{ lat: 214, common_pid: 2042 } hitcount: 1
{ lat: 215, common_pid: 2039 } hitcount: 1
{ lat: 217, common_pid: 2036 } hitcount: 1
{ lat: 217, common_pid: 2040 } hitcount: 1
{ lat: 217, common_pid: 2039 } hitcount: 1
{ lat: 218, common_pid: 2039 } hitcount: 6
{ lat: 219, common_pid: 2039 } hitcount: 9
{ lat: 220, common_pid: 2039 } hitcount: 11
{ lat: 221, common_pid: 2039 } hitcount: 5
{ lat: 221, common_pid: 2042 } hitcount: 1
{ lat: 222, common_pid: 2039 } hitcount: 7
{ lat: 223, common_pid: 2036 } hitcount: 1
{ lat: 223, common_pid: 2039 } hitcount: 3
{ lat: 224, common_pid: 2039 } hitcount: 4
{ lat: 224, common_pid: 2037 } hitcount: 1
{ lat: 224, common_pid: 2036 } hitcount: 2
{ lat: 225, common_pid: 2039 } hitcount: 5
{ lat: 225, common_pid: 2042 } hitcount: 1
{ lat: 226, common_pid: 2039 } hitcount: 7
{ lat: 226, common_pid: 2036 } hitcount: 4
{ lat: 227, common_pid: 2039 } hitcount: 6
{ lat: 227, common_pid: 2036 } hitcount: 12
{ lat: 227, common_pid: 2043 } hitcount: 1
{ lat: 228, common_pid: 2039 } hitcount: 7
{ lat: 228, common_pid: 2036 } hitcount: 14
{ lat: 229, common_pid: 2039 } hitcount: 9
{ lat: 229, common_pid: 2036 } hitcount: 8
{ lat: 229, common_pid: 2038 } hitcount: 1
{ lat: 230, common_pid: 2039 } hitcount: 11
{ lat: 230, common_pid: 2036 } hitcount: 6
{ lat: 230, common_pid: 2043 } hitcount: 1
{ lat: 230, common_pid: 2042 } hitcount: 2
{ lat: 231, common_pid: 2041 } hitcount: 1
{ lat: 231, common_pid: 2036 } hitcount: 6
{ lat: 231, common_pid: 2043 } hitcount: 1
{ lat: 231, common_pid: 2039 } hitcount: 8
{ lat: 232, common_pid: 2037 } hitcount: 1
{ lat: 232, common_pid: 2039 } hitcount: 6
{ lat: 232, common_pid: 2040 } hitcount: 2
{ lat: 232, common_pid: 2036 } hitcount: 5
{ lat: 232, common_pid: 2043 } hitcount: 1
{ lat: 233, common_pid: 2036 } hitcount: 5
{ lat: 233, common_pid: 2039 } hitcount: 11
{ lat: 234, common_pid: 2039 } hitcount: 4
{ lat: 234, common_pid: 2038 } hitcount: 2
{ lat: 234, common_pid: 2043 } hitcount: 2
{ lat: 234, common_pid: 2036 } hitcount: 11
{ lat: 234, common_pid: 2040 } hitcount: 1
{ lat: 235, common_pid: 2037 } hitcount: 2
{ lat: 235, common_pid: 2036 } hitcount: 8
{ lat: 235, common_pid: 2043 } hitcount: 2
{ lat: 235, common_pid: 2039 } hitcount: 5
{ lat: 235, common_pid: 2042 } hitcount: 2
{ lat: 235, common_pid: 2040 } hitcount: 4
{ lat: 235, common_pid: 2041 } hitcount: 1
{ lat: 236, common_pid: 2036 } hitcount: 7
{ lat: 236, common_pid: 2037 } hitcount: 1
{ lat: 236, common_pid: 2041 } hitcount: 5
{ lat: 236, common_pid: 2039 } hitcount: 3
{ lat: 236, common_pid: 2043 } hitcount: 9
{ lat: 236, common_pid: 2040 } hitcount: 7
{ lat: 237, common_pid: 2037 } hitcount: 1
{ lat: 237, common_pid: 2040 } hitcount: 1
{ lat: 237, common_pid: 2036 } hitcount: 9
{ lat: 237, common_pid: 2039 } hitcount: 3
{ lat: 237, common_pid: 2043 } hitcount: 8
{ lat: 237, common_pid: 2042 } hitcount: 2
{ lat: 237, common_pid: 2041 } hitcount: 2
{ lat: 238, common_pid: 2043 } hitcount: 10
{ lat: 238, common_pid: 2040 } hitcount: 1
{ lat: 238, common_pid: 2037 } hitcount: 9
{ lat: 238, common_pid: 2038 } hitcount: 1
{ lat: 238, common_pid: 2039 } hitcount: 1
{ lat: 238, common_pid: 2042 } hitcount: 3
{ lat: 238, common_pid: 2036 } hitcount: 7
{ lat: 239, common_pid: 2041 } hitcount: 1
{ lat: 239, common_pid: 2043 } hitcount: 11
{ lat: 239, common_pid: 2037 } hitcount: 11
{ lat: 239, common_pid: 2038 } hitcount: 6
{ lat: 239, common_pid: 2036 } hitcount: 7
{ lat: 239, common_pid: 2040 } hitcount: 1
{ lat: 239, common_pid: 2042 } hitcount: 9
{ lat: 240, common_pid: 2037 } hitcount: 29
{ lat: 240, common_pid: 2043 } hitcount: 15
{ lat: 240, common_pid: 2040 } hitcount: 44
{ lat: 240, common_pid: 2039 } hitcount: 1
{ lat: 240, common_pid: 2041 } hitcount: 2
{ lat: 240, common_pid: 2038 } hitcount: 1
{ lat: 240, common_pid: 2036 } hitcount: 10
{ lat: 240, common_pid: 2042 } hitcount: 13
{ lat: 241, common_pid: 2036 } hitcount: 21
{ lat: 241, common_pid: 2041 } hitcount: 36
{ lat: 241, common_pid: 2037 } hitcount: 34
{ lat: 241, common_pid: 2042 } hitcount: 14
{ lat: 241, common_pid: 2040 } hitcount: 94
{ lat: 241, common_pid: 2039 } hitcount: 12
{ lat: 241, common_pid: 2038 } hitcount: 2
{ lat: 241, common_pid: 2043 } hitcount: 28
{ lat: 242, common_pid: 2040 } hitcount: 109
{ lat: 242, common_pid: 2041 } hitcount: 506
{ lat: 242, common_pid: 2039 } hitcount: 155
{ lat: 242, common_pid: 2042 } hitcount: 21
{ lat: 242, common_pid: 2037 } hitcount: 52
{ lat: 242, common_pid: 2043 } hitcount: 21
{ lat: 242, common_pid: 2036 } hitcount: 16
{ lat: 242, common_pid: 2038 } hitcount: 156
{ lat: 243, common_pid: 2037 } hitcount: 46
{ lat: 243, common_pid: 2039 } hitcount: 40
{ lat: 243, common_pid: 2042 } hitcount: 119
{ lat: 243, common_pid: 2041 } hitcount: 611
{ lat: 243, common_pid: 2036 } hitcount: 69
{ lat: 243, common_pid: 2038 } hitcount: 784
{ lat: 243, common_pid: 2040 } hitcount: 323
{ lat: 243, common_pid: 2043 } hitcount: 14
{ lat: 244, common_pid: 2043 } hitcount: 35
{ lat: 244, common_pid: 2042 } hitcount: 305
{ lat: 244, common_pid: 2039 } hitcount: 8
{ lat: 244, common_pid: 2040 } hitcount: 4515
{ lat: 244, common_pid: 2038 } hitcount: 371
{ lat: 244, common_pid: 2037 } hitcount: 31
{ lat: 244, common_pid: 2036 } hitcount: 114
{ lat: 244, common_pid: 2041 } hitcount: 3396
{ lat: 245, common_pid: 2036 } hitcount: 700
{ lat: 245, common_pid: 2041 } hitcount: 2772
{ lat: 245, common_pid: 2037 } hitcount: 268
{ lat: 245, common_pid: 2039 } hitcount: 472
{ lat: 245, common_pid: 2038 } hitcount: 2758
{ lat: 245, common_pid: 2042 } hitcount: 3833
{ lat: 245, common_pid: 2040 } hitcount: 3105
{ lat: 245, common_pid: 2043 } hitcount: 645
{ lat: 246, common_pid: 2038 } hitcount: 3451
{ lat: 246, common_pid: 2041 } hitcount: 142
{ lat: 246, common_pid: 2037 } hitcount: 5101
{ lat: 246, common_pid: 2040 } hitcount: 68
{ lat: 246, common_pid: 2043 } hitcount: 5099
{ lat: 246, common_pid: 2039 } hitcount: 5608
{ lat: 246, common_pid: 2042 } hitcount: 3723
{ lat: 246, common_pid: 2036 } hitcount: 4738
{ lat: 247, common_pid: 2042 } hitcount: 312
{ lat: 247, common_pid: 2043 } hitcount: 2385
{ lat: 247, common_pid: 2041 } hitcount: 452
{ lat: 247, common_pid: 2038 } hitcount: 792
{ lat: 247, common_pid: 2040 } hitcount: 78
{ lat: 247, common_pid: 2036 } hitcount: 2375
{ lat: 247, common_pid: 2039 } hitcount: 1834
{ lat: 247, common_pid: 2037 } hitcount: 2655
{ lat: 248, common_pid: 2037 } hitcount: 36
{ lat: 248, common_pid: 2042 } hitcount: 11
{ lat: 248, common_pid: 2038 } hitcount: 122
{ lat: 248, common_pid: 2036 } hitcount: 135
{ lat: 248, common_pid: 2039 } hitcount: 26
{ lat: 248, common_pid: 2041 } hitcount: 503
{ lat: 248, common_pid: 2043 } hitcount: 66
{ lat: 248, common_pid: 2040 } hitcount: 46
{ lat: 249, common_pid: 2037 } hitcount: 29
{ lat: 249, common_pid: 2038 } hitcount: 1
{ lat: 249, common_pid: 2043 } hitcount: 29
{ lat: 249, common_pid: 2039 } hitcount: 8
{ lat: 249, common_pid: 2042 } hitcount: 56
{ lat: 249, common_pid: 2040 } hitcount: 27
{ lat: 249, common_pid: 2041 } hitcount: 11
{ lat: 249, common_pid: 2036 } hitcount: 27
{ lat: 250, common_pid: 2038 } hitcount: 1
{ lat: 250, common_pid: 2036 } hitcount: 30
{ lat: 250, common_pid: 2040 } hitcount: 19
{ lat: 250, common_pid: 2043 } hitcount: 22
{ lat: 250, common_pid: 2042 } hitcount: 20
{ lat: 250, common_pid: 2041 } hitcount: 1
{ lat: 250, common_pid: 2039 } hitcount: 6
{ lat: 250, common_pid: 2037 } hitcount: 48
{ lat: 251, common_pid: 2037 } hitcount: 43
{ lat: 251, common_pid: 2039 } hitcount: 1
{ lat: 251, common_pid: 2036 } hitcount: 12
{ lat: 251, common_pid: 2042 } hitcount: 2
{ lat: 251, common_pid: 2041 } hitcount: 1
{ lat: 251, common_pid: 2043 } hitcount: 15
{ lat: 251, common_pid: 2040 } hitcount: 3
{ lat: 252, common_pid: 2040 } hitcount: 1
{ lat: 252, common_pid: 2036 } hitcount: 12
{ lat: 252, common_pid: 2037 } hitcount: 21
{ lat: 252, common_pid: 2043 } hitcount: 14
{ lat: 253, common_pid: 2037 } hitcount: 21
{ lat: 253, common_pid: 2039 } hitcount: 2
{ lat: 253, common_pid: 2036 } hitcount: 9
{ lat: 253, common_pid: 2043 } hitcount: 6
{ lat: 253, common_pid: 2040 } hitcount: 1
{ lat: 254, common_pid: 2036 } hitcount: 8
{ lat: 254, common_pid: 2043 } hitcount: 3
{ lat: 254, common_pid: 2041 } hitcount: 1
{ lat: 254, common_pid: 2042 } hitcount: 1
{ lat: 254, common_pid: 2039 } hitcount: 1
{ lat: 254, common_pid: 2037 } hitcount: 12
{ lat: 255, common_pid: 2043 } hitcount: 1
{ lat: 255, common_pid: 2037 } hitcount: 2
{ lat: 255, common_pid: 2036 } hitcount: 2
{ lat: 255, common_pid: 2039 } hitcount: 8
{ lat: 256, common_pid: 2043 } hitcount: 1
{ lat: 256, common_pid: 2036 } hitcount: 4
{ lat: 256, common_pid: 2039 } hitcount: 6
{ lat: 257, common_pid: 2039 } hitcount: 5
{ lat: 257, common_pid: 2036 } hitcount: 4
{ lat: 258, common_pid: 2039 } hitcount: 5
{ lat: 258, common_pid: 2036 } hitcount: 2
{ lat: 259, common_pid: 2036 } hitcount: 7
{ lat: 259, common_pid: 2039 } hitcount: 7
{ lat: 260, common_pid: 2036 } hitcount: 8
{ lat: 260, common_pid: 2039 } hitcount: 6
{ lat: 261, common_pid: 2036 } hitcount: 5
{ lat: 261, common_pid: 2039 } hitcount: 7
{ lat: 262, common_pid: 2039 } hitcount: 5
{ lat: 262, common_pid: 2036 } hitcount: 5
{ lat: 263, common_pid: 2039 } hitcount: 7
{ lat: 263, common_pid: 2036 } hitcount: 7
{ lat: 264, common_pid: 2039 } hitcount: 9
{ lat: 264, common_pid: 2036 } hitcount: 9
{ lat: 265, common_pid: 2036 } hitcount: 5
{ lat: 265, common_pid: 2039 } hitcount: 1
{ lat: 266, common_pid: 2036 } hitcount: 1
{ lat: 266, common_pid: 2039 } hitcount: 3
{ lat: 267, common_pid: 2036 } hitcount: 1
{ lat: 267, common_pid: 2039 } hitcount: 3
{ lat: 268, common_pid: 2036 } hitcount: 1
{ lat: 268, common_pid: 2039 } hitcount: 6
{ lat: 269, common_pid: 2036 } hitcount: 1
{ lat: 269, common_pid: 2043 } hitcount: 1
{ lat: 269, common_pid: 2039 } hitcount: 2
{ lat: 270, common_pid: 2040 } hitcount: 1
{ lat: 270, common_pid: 2039 } hitcount: 6
{ lat: 271, common_pid: 2041 } hitcount: 1
{ lat: 271, common_pid: 2039 } hitcount: 5
{ lat: 272, common_pid: 2039 } hitcount: 10
{ lat: 273, common_pid: 2039 } hitcount: 8
{ lat: 274, common_pid: 2039 } hitcount: 2
{ lat: 275, common_pid: 2039 } hitcount: 1
{ lat: 276, common_pid: 2039 } hitcount: 2
{ lat: 276, common_pid: 2037 } hitcount: 1
{ lat: 276, common_pid: 2038 } hitcount: 1
{ lat: 277, common_pid: 2039 } hitcount: 1
{ lat: 277, common_pid: 2042 } hitcount: 1
{ lat: 278, common_pid: 2039 } hitcount: 1
{ lat: 279, common_pid: 2039 } hitcount: 4
{ lat: 279, common_pid: 2043 } hitcount: 1
{ lat: 280, common_pid: 2039 } hitcount: 3
{ lat: 283, common_pid: 2036 } hitcount: 2
{ lat: 284, common_pid: 2039 } hitcount: 1
{ lat: 284, common_pid: 2043 } hitcount: 1
{ lat: 288, common_pid: 2039 } hitcount: 1
{ lat: 289, common_pid: 2039 } hitcount: 1
{ lat: 300, common_pid: 2039 } hitcount: 1
{ lat: 384, common_pid: 2039 } hitcount: 1
Totals:
Hits: 67625
Entries: 278
Dropped: 0
请注意，写入操作是在休眠周围进行的，因此理想情况下，它们都将是 250 微秒。 如果您想知道为什么有几个小于 250 微秒，那是因为 cyclictest 的工作方式是，如果一个迭代延迟到达，下一个迭代会将计时器设置为小于 250 的值来唤醒。 也就是说，如果一个迭代延迟了 50 微秒，则下一次唤醒将在 200 微秒时进行。
但这可以很容易地在用户空间中完成。 为了使它更有趣，我们可以将内核中发生的事件与 trace_marker 混合在一起的直方图
# cd /sys/kernel/tracing
# echo 'latency u64 lat' > synthetic_events
# echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat) if buf == "end"' > events/ftrace/print/trigger
# echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
这次的不同之处在于，不使用 trace_marker 来启动延迟，而是使用 sched_waking 事件，将 trace_marker 写入的 common_pid 与 sched_waking 唤醒的 pid 匹配。
使用相同的参数再次运行 cyclictest 后，我们现在有
# cat events/synthetic/latency/hist
# event histogram
#
# trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
#
{ lat: 7, common_pid: 2302 } hitcount: 640
{ lat: 7, common_pid: 2299 } hitcount: 42
{ lat: 7, common_pid: 2303 } hitcount: 18
{ lat: 7, common_pid: 2305 } hitcount: 166
{ lat: 7, common_pid: 2306 } hitcount: 1
{ lat: 7, common_pid: 2301 } hitcount: 91
{ lat: 7, common_pid: 2300 } hitcount: 17
{ lat: 8, common_pid: 2303 } hitcount: 8296
{ lat: 8, common_pid: 2304 } hitcount: 6864
{ lat: 8, common_pid: 2305 } hitcount: 9464
{ lat: 8, common_pid: 2301 } hitcount: 9213
{ lat: 8, common_pid: 2306 } hitcount: 6246
{ lat: 8, common_pid: 2302 } hitcount: 8797
{ lat: 8, common_pid: 2299 } hitcount: 8771
{ lat: 8, common_pid: 2300 } hitcount: 8119
{ lat: 9, common_pid: 2305 } hitcount: 1519
{ lat: 9, common_pid: 2299 } hitcount: 2346
{ lat: 9, common_pid: 2303 } hitcount: 2841
{ lat: 9, common_pid: 2301 } hitcount: 1846
{ lat: 9, common_pid: 2304 } hitcount: 3861
{ lat: 9, common_pid: 2302 } hitcount: 1210
{ lat: 9, common_pid: 2300 } hitcount: 2762
{ lat: 9, common_pid: 2306 } hitcount: 4247
{ lat: 10, common_pid: 2299 } hitcount: 16
{ lat: 10, common_pid: 2306 } hitcount: 333
{ lat: 10, common_pid: 2303 } hitcount: 16
{ lat: 10, common_pid: 2304 } hitcount: 168
{ lat: 10, common_pid: 2302 } hitcount: 240
{ lat: 10, common_pid: 2301 } hitcount: 28
{ lat: 10, common_pid: 2300 } hitcount: 95
{ lat: 10, common_pid: 2305 } hitcount: 18
{ lat: 11, common_pid: 2303 } hitcount: 5
{ lat: 11, common_pid: 2305 } hitcount: 8
{ lat: 11, common_pid: 2306 } hitcount: 221
{ lat: 11, common_pid: 2302 } hitcount: 76
{ lat: 11, common_pid: 2304 } hitcount: 26
{ lat: 11, common_pid: 2300 } hitcount: 125
{ lat: 11, common_pid: 2299 } hitcount: 2
{ lat: 12, common_pid: 2305 } hitcount: 3
{ lat: 12, common_pid: 2300 } hitcount: 6
{ lat: 12, common_pid: 2306 } hitcount: 90
{ lat: 12, common_pid: 2302 } hitcount: 4
{ lat: 12, common_pid: 2303 } hitcount: 1
{ lat: 12, common_pid: 2304 } hitcount: 122
{ lat: 13, common_pid: 2300 } hitcount: 12
{ lat: 13, common_pid: 2301 } hitcount: 1
{ lat: 13, common_pid: 2306 } hitcount: 32
{ lat: 13, common_pid: 2302 } hitcount: 5
{ lat: 13, common_pid: 2305 } hitcount: 1
{ lat: 13, common_pid: 2303 } hitcount: 1
{ lat: 13, common_pid: 2304 } hitcount: 61
{ lat: 14, common_pid: 2303 } hitcount: 4
{ lat: 14, common_pid: 2306 } hitcount: 5
{ lat: 14, common_pid: 2305 } hitcount: 4
{ lat: 14, common_pid: 2304 } hitcount: 62
{ lat: 14, common_pid: 2302 } hitcount: 19
{ lat: 14, common_pid: 2300 } hitcount: 33
{ lat: 14, common_pid: 2299 } hitcount: 1
{ lat: 14, common_pid: 2301 } hitcount: 4
{ lat: 15, common_pid: 2305 } hitcount: 1
{ lat: 15, common_pid: 2302 } hitcount: 25
{ lat: 15, common_pid: 2300 } hitcount: 11
{ lat: 15, common_pid: 2299 } hitcount: 5
{ lat: 15, common_pid: 2301 } hitcount: 1
{ lat: 15, common_pid: 2304 } hitcount: 8
{ lat: 15, common_pid: 2303 } hitcount: 1
{ lat: 15, common_pid: 2306 } hitcount: 6
{ lat: 16, common_pid: 2302 } hitcount: 31
{ lat: 16, common_pid: 2306 } hitcount: 3
{ lat: 16, common_pid: 2300 } hitcount: 5
{ lat: 17, common_pid: 2302 } hitcount: 6
{ lat: 17, common_pid: 2303 } hitcount: 1
{ lat: 18, common_pid: 2304 } hitcount: 1
{ lat: 18, common_pid: 2302 } hitcount: 8
{ lat: 18, common_pid: 2299 } hitcount: 1
{ lat: 18, common_pid: 2301 } hitcount: 1
{ lat: 19, common_pid: 2303 } hitcount: 4
{ lat: 19, common_pid: 2304 } hitcount: 5
{ lat: 19, common_pid: 2302 } hitcount: 4
{ lat: 19, common_pid: 2299 } hitcount: 3
{ lat: 19, common_pid: 2306 } hitcount: 1
{ lat: 19, common_pid: 2300 } hitcount: 4
{ lat: 19, common_pid: 2305 } hitcount: 5
{ lat: 20, common_pid: 2299 } hitcount: 2
{ lat: 20, common_pid: 2302 } hitcount: 3
{ lat: 20, common_pid: 2305 } hitcount: 1
{ lat: 20, common_pid: 2300 } hitcount: 2
{ lat: 20, common_pid: 2301 } hitcount: 2
{ lat: 20, common_pid: 2303 } hitcount: 3
{ lat: 21, common_pid: 2305 } hitcount: 1
{ lat: 21, common_pid: 2299 } hitcount: 5
{ lat: 21, common_pid: 2303 } hitcount: 4
{ lat: 21, common_pid: 2302 } hitcount: 7
{ lat: 21, common_pid: 2300 } hitcount: 1
{ lat: 21, common_pid: 2301 } hitcount: 5
{ lat: 21, common_pid: 2304 } hitcount: 2
{ lat: 22, common_pid: 2302 } hitcount: 5
{ lat: 22, common_pid: 2303 } hitcount: 1
{ lat: 22, common_pid: 2306 } hitcount: 3
{ lat: 22, common_pid: 2301 } hitcount: 2
{ lat: 22, common_pid: 2300 } hitcount: 1
{ lat: 22, common_pid: 2299 } hitcount: 1
{ lat: 22, common_pid: 2305 } hitcount: 1
{ lat: 22, common_pid: 2304 } hitcount: 1
{ lat: 23, common_pid: 2299 } hitcount: 1
{ lat: 23, common_pid: 2306 } hitcount: 2
{ lat: 23, common_pid: 2302 } hitcount: 6
{ lat: 24, common_pid: 2302 } hitcount: 3
{ lat: 24, common_pid: 2300 } hitcount: 1
{ lat: 24, common_pid: 2306 } hitcount: 2
{ lat: 24, common_pid: 2305 } hitcount: 1
{ lat: 24, common_pid: 2299 } hitcount: 1
{ lat: 25, common_pid: 2300 } hitcount: 1
{ lat: 25, common_pid: 2302 } hitcount: 4
{ lat: 26, common_pid: 2302 } hitcount: 2
{ lat: 27, common_pid: 2305 } hitcount: 1
{ lat: 27, common_pid: 2300 } hitcount: 1
{ lat: 27, common_pid: 2302 } hitcount: 3
{ lat: 28, common_pid: 2306 } hitcount: 1
{ lat: 28, common_pid: 2302 } hitcount: 4
{ lat: 29, common_pid: 2302 } hitcount: 1
{ lat: 29, common_pid: 2300 } hitcount: 2
{ lat: 29, common_pid: 2306 } hitcount: 1
{ lat: 29, common_pid: 2304 } hitcount: 1
{ lat: 30, common_pid: 2302 } hitcount: 4
{ lat: 31, common_pid: 2302 } hitcount: 6
{ lat: 32, common_pid: 2302 } hitcount: 1
{ lat: 33, common_pid: 2299 } hitcount: 1
{ lat: 33, common_pid: 2302 } hitcount: 3
{ lat: 34, common_pid: 2302 } hitcount: 2
{ lat: 35, common_pid: 2302 } hitcount: 1
{ lat: 35, common_pid: 2304 } hitcount: 1
{ lat: 36, common_pid: 2302 } hitcount: 4
{ lat: 37, common_pid: 2302 } hitcount: 6
{ lat: 38, common_pid: 2302 } hitcount: 2
{ lat: 39, common_pid: 2302 } hitcount: 2
{ lat: 39, common_pid: 2304 } hitcount: 1
{ lat: 40, common_pid: 2304 } hitcount: 2
{ lat: 40, common_pid: 2302 } hitcount: 5
{ lat: 41, common_pid: 2304 } hitcount: 1
{ lat: 41, common_pid: 2302 } hitcount: 8
{ lat: 42, common_pid: 2302 } hitcount: 6
{ lat: 42, common_pid: 2304 } hitcount: 1
{ lat: 43, common_pid: 2302 } hitcount: 3
{ lat: 43, common_pid: 2304 } hitcount: 4
{ lat: 44, common_pid: 2302 } hitcount: 6
{ lat: 45, common_pid: 2302 } hitcount: 5
{ lat: 46, common_pid: 2302 } hitcount: 5
{ lat: 47, common_pid: 2302 } hitcount: 7
{ lat: 48, common_pid: 2301 } hitcount: 1
{ lat: 48, common_pid: 2302 } hitcount: 9
{ lat: 49, common_pid: 2302 } hitcount: 3
{ lat: 50, common_pid: 2302 } hitcount: 1
{ lat: 50, common_pid: 2301 } hitcount: 1
{ lat: 51, common_pid: 2302 } hitcount: 2
{ lat: 51, common_pid: 2301 } hitcount: 1
{ lat: 61, common_pid: 2302 } hitcount: 1
{ lat: 110, common_pid: 2302 } hitcount: 1
Totals:
Hits: 89565
Entries: 158
Dropped: 0
这不会告诉我们任何关于 cyclictest 可能延迟唤醒的信息，但它确实向我们展示了一个很好的直方图，显示了从 cyclictest 被唤醒到它进入用户空间的时间。