| blob | 8408670d0328272d65967ddf0abf19a4c6828d68 |
1 ================
2 Event Histograms
3 ================
5 Documentation written by Tom Zanussi
7 1. Introduction
8 ===============
10 Histogram triggers are special event triggers that can be used to
11 aggregate trace event data into histograms. For information on
12 trace events and event triggers, see Documentation/trace/events.rst.
15 2. Histogram Trigger Command
16 ============================
18 A histogram trigger command is an event trigger command that
19 aggregates event hits into a hash table keyed on one or more trace
20 event format fields (or stacktrace) and a set of running totals
21 derived from one or more trace event format fields and/or event
22 counts (hitcount).
24 The format of a hist trigger is as follows::
26 hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>]
27 [:sort=<field1[,field2,...]>][:size=#entries][:pause][:continue]
28 [:clear][:name=histname1][:<handler>.<action>] [if <filter>]
30 When a matching event is hit, an entry is added to a hash table
31 using the key(s) and value(s) named. Keys and values correspond to
32 fields in the event's format description. Values must correspond to
33 numeric fields - on an event hit, the value(s) will be added to a
34 sum kept for that field. The special string 'hitcount' can be used
35 in place of an explicit value field - this is simply a count of
36 event hits. If 'values' isn't specified, an implicit 'hitcount'
37 value will be automatically created and used as the only value.
38 Keys can be any field, or the special string 'stacktrace', which
39 will use the event's kernel stacktrace as the key. The keywords
40 'keys' or 'key' can be used to specify keys, and the keywords
41 'values', 'vals', or 'val' can be used to specify values. Compound
42 keys consisting of up to two fields can be specified by the 'keys'
43 keyword. Hashing a compound key produces a unique entry in the
44 table for each unique combination of component keys, and can be
45 useful for providing more fine-grained summaries of event data.
46 Additionally, sort keys consisting of up to two fields can be
47 specified by the 'sort' keyword. If more than one field is
48 specified, the result will be a 'sort within a sort': the first key
49 is taken to be the primary sort key and the second the secondary
50 key. If a hist trigger is given a name using the 'name' parameter,
51 its histogram data will be shared with other triggers of the same
52 name, and trigger hits will update this common data. Only triggers
53 with 'compatible' fields can be combined in this way; triggers are
54 'compatible' if the fields named in the trigger share the same
55 number and type of fields and those fields also have the same names.
56 Note that any two events always share the compatible 'hitcount' and
57 'stacktrace' fields and can therefore be combined using those
58 fields, however pointless that may be.
60 'hist' triggers add a 'hist' file to each event's subdirectory.
61 Reading the 'hist' file for the event will dump the hash table in
62 its entirety to stdout. If there are multiple hist triggers
63 attached to an event, there will be a table for each trigger in the
64 output. The table displayed for a named trigger will be the same as
65 any other instance having the same name. Each printed hash table
66 entry is a simple list of the keys and values comprising the entry;
67 keys are printed first and are delineated by curly braces, and are
68 followed by the set of value fields for the entry. By default,
69 numeric fields are displayed as base-10 integers. This can be
70 modified by appending any of the following modifiers to the field
71 name:
73 =========== ==========================================
74 .hex display a number as a hex value
75 .sym display an address as a symbol
76 .sym-offset display an address as a symbol and offset
77 .syscall display a syscall id as a system call name
78 .execname display a common_pid as a program name
79 .log2 display log2 value rather than raw number
80 .usecs display a common_timestamp in microseconds
81 =========== ==========================================
83 Note that in general the semantics of a given field aren't
84 interpreted when applying a modifier to it, but there are some
85 restrictions to be aware of in this regard:
87 - only the 'hex' modifier can be used for values (because values
88 are essentially sums, and the other modifiers don't make sense
89 in that context).
90 - the 'execname' modifier can only be used on a 'common_pid'. The
91 reason for this is that the execname is simply the 'comm' value
92 saved for the 'current' process when an event was triggered,
93 which is the same as the common_pid value saved by the event
94 tracing code. Trying to apply that comm value to other pid
95 values wouldn't be correct, and typically events that care save
96 pid-specific comm fields in the event itself.
98 A typical usage scenario would be the following to enable a hist
99 trigger, read its current contents, and then turn it off::
101 # echo 'hist:keys=skbaddr.hex:vals=len' > \
102 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
104 # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
106 # echo '!hist:keys=skbaddr.hex:vals=len' > \
107 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
109 The trigger file itself can be read to show the details of the
110 currently attached hist trigger. This information is also displayed
111 at the top of the 'hist' file when read.
113 By default, the size of the hash table is 2048 entries. The 'size'
114 parameter can be used to specify more or fewer than that. The units
115 are in terms of hashtable entries - if a run uses more entries than
116 specified, the results will show the number of 'drops', the number
117 of hits that were ignored. The size should be a power of 2 between
118 128 and 131072 (any non- power-of-2 number specified will be rounded
119 up).
121 The 'sort' parameter can be used to specify a value field to sort
122 on. The default if unspecified is 'hitcount' and the default sort
123 order is 'ascending'. To sort in the opposite direction, append
124 .descending' to the sort key.
126 The 'pause' parameter can be used to pause an existing hist trigger
127 or to start a hist trigger but not log any events until told to do
128 so. 'continue' or 'cont' can be used to start or restart a paused
129 hist trigger.
131 The 'clear' parameter will clear the contents of a running hist
132 trigger and leave its current paused/active state.
134 Note that the 'pause', 'cont', and 'clear' parameters should be
135 applied using 'append' shell operator ('>>') if applied to an
136 existing trigger, rather than via the '>' operator, which will cause
137 the trigger to be removed through truncation.
139 - enable_hist/disable_hist
141 The enable_hist and disable_hist triggers can be used to have one
142 event conditionally start and stop another event's already-attached
143 hist trigger. Any number of enable_hist and disable_hist triggers
144 can be attached to a given event, allowing that event to kick off
145 and stop aggregations on a host of other events.
147 The format is very similar to the enable/disable_event triggers::
149 enable_hist:<system>:<event>[:count]
150 disable_hist:<system>:<event>[:count]
152 Instead of enabling or disabling the tracing of the target event
153 into the trace buffer as the enable/disable_event triggers do, the
154 enable/disable_hist triggers enable or disable the aggregation of
155 the target event into a hash table.
157 A typical usage scenario for the enable_hist/disable_hist triggers
158 would be to first set up a paused hist trigger on some event,
159 followed by an enable_hist/disable_hist pair that turns the hist
160 aggregation on and off when conditions of interest are hit::
162 # echo 'hist:keys=skbaddr.hex:vals=len:pause' > \
163 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
165 # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \
166 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
168 # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \
169 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
171 The above sets up an initially paused hist trigger which is unpaused
172 and starts aggregating events when a given program is executed, and
173 which stops aggregating when the process exits and the hist trigger
174 is paused again.
176 The examples below provide a more concrete illustration of the
177 concepts and typical usage patterns discussed above.
179 'special' event fields
180 ------------------------
182 There are a number of 'special event fields' available for use as
183 keys or values in a hist trigger. These look like and behave as if
184 they were actual event fields, but aren't really part of the event's
185 field definition or format file. They are however available for any
186 event, and can be used anywhere an actual event field could be.
187 They are:
189 ====================== ==== =======================================
190 common_timestamp u64 timestamp (from ring buffer) associated
191 with the event, in nanoseconds. May be
192 modified by .usecs to have timestamps
193 interpreted as microseconds.
194 cpu int the cpu on which the event occurred.
195 ====================== ==== =======================================
197 Extended error information
198 --------------------------
200 For some error conditions encountered when invoking a hist trigger
201 command, extended error information is available via the
202 tracing/error_log file. See Error Conditions in
203 :file:`Documentation/trace/ftrace.rst` for details.
205 6.2 'hist' trigger examples
206 ---------------------------
208 The first set of examples creates aggregations using the kmalloc
209 event. The fields that can be used for the hist trigger are listed
210 in the kmalloc event's format file::
212 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format
213 name: kmalloc
214 ID: 374
215 format:
216 field:unsigned short common_type; offset:0; size:2; signed:0;
217 field:unsigned char common_flags; offset:2; size:1; signed:0;
218 field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
219 field:int common_pid; offset:4; size:4; signed:1;
221 field:unsigned long call_site; offset:8; size:8; signed:0;
222 field:const void * ptr; offset:16; size:8; signed:0;
223 field:size_t bytes_req; offset:24; size:8; signed:0;
224 field:size_t bytes_alloc; offset:32; size:8; signed:0;
225 field:gfp_t gfp_flags; offset:40; size:4; signed:0;
227 We'll start by creating a hist trigger that generates a simple table
228 that lists the total number of bytes requested for each function in
229 the kernel that made one or more calls to kmalloc::
231 # echo 'hist:key=call_site:val=bytes_req' > \
232 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
234 This tells the tracing system to create a 'hist' trigger using the
235 call_site field of the kmalloc event as the key for the table, which
236 just means that each unique call_site address will have an entry
237 created for it in the table. The 'val=bytes_req' parameter tells
238 the hist trigger that for each unique entry (call_site) in the
239 table, it should keep a running total of the number of bytes
240 requested by that call_site.
242 We'll let it run for awhile and then dump the contents of the 'hist'
243 file in the kmalloc event's subdirectory (for readability, a number
244 of entries have been omitted)::
246 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
247 # trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
249 { call_site: 18446744072106379007 } hitcount: 1 bytes_req: 176
250 { call_site: 18446744071579557049 } hitcount: 1 bytes_req: 1024
251 { call_site: 18446744071580608289 } hitcount: 1 bytes_req: 16384
252 { call_site: 18446744071581827654 } hitcount: 1 bytes_req: 24
253 { call_site: 18446744071580700980 } hitcount: 1 bytes_req: 8
254 { call_site: 18446744071579359876 } hitcount: 1 bytes_req: 152
255 { call_site: 18446744071580795365 } hitcount: 3 bytes_req: 144
256 { call_site: 18446744071581303129 } hitcount: 3 bytes_req: 144
257 { call_site: 18446744071580713234 } hitcount: 4 bytes_req: 2560
258 { call_site: 18446744071580933750 } hitcount: 4 bytes_req: 736
259 .
260 .
261 .
262 { call_site: 18446744072106047046 } hitcount: 69 bytes_req: 5576
263 { call_site: 18446744071582116407 } hitcount: 73 bytes_req: 2336
264 { call_site: 18446744072106054684 } hitcount: 136 bytes_req: 140504
265 { call_site: 18446744072106224230 } hitcount: 136 bytes_req: 19584
266 { call_site: 18446744072106078074 } hitcount: 153 bytes_req: 2448
267 { call_site: 18446744072106062406 } hitcount: 153 bytes_req: 36720
268 { call_site: 18446744071582507929 } hitcount: 153 bytes_req: 37088
269 { call_site: 18446744072102520590 } hitcount: 273 bytes_req: 10920
270 { call_site: 18446744071582143559 } hitcount: 358 bytes_req: 716
271 { call_site: 18446744072106465852 } hitcount: 417 bytes_req: 56712
272 { call_site: 18446744072102523378 } hitcount: 485 bytes_req: 27160
273 { call_site: 18446744072099568646 } hitcount: 1676 bytes_req: 33520
275 Totals:
276 Hits: 4610
277 Entries: 45
278 Dropped: 0
280 The output displays a line for each entry, beginning with the key
281 specified in the trigger, followed by the value(s) also specified in
282 the trigger. At the beginning of the output is a line that displays
283 the trigger info, which can also be displayed by reading the
284 'trigger' file::
286 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
287 hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
289 At the end of the output are a few lines that display the overall
290 totals for the run. The 'Hits' field shows the total number of
291 times the event trigger was hit, the 'Entries' field shows the total
292 number of used entries in the hash table, and the 'Dropped' field
293 shows the number of hits that were dropped because the number of
294 used entries for the run exceeded the maximum number of entries
295 allowed for the table (normally 0, but if not a hint that you may
296 want to increase the size of the table using the 'size' parameter).
298 Notice in the above output that there's an extra field, 'hitcount',
299 which wasn't specified in the trigger. Also notice that in the
300 trigger info output, there's a parameter, 'sort=hitcount', which
301 wasn't specified in the trigger either. The reason for that is that
302 every trigger implicitly keeps a count of the total number of hits
303 attributed to a given entry, called the 'hitcount'. That hitcount
304 information is explicitly displayed in the output, and in the
305 absence of a user-specified sort parameter, is used as the default
306 sort field.
308 The value 'hitcount' can be used in place of an explicit value in
309 the 'values' parameter if you don't really need to have any
310 particular field summed and are mainly interested in hit
311 frequencies.
313 To turn the hist trigger off, simply call up the trigger in the
314 command history and re-execute it with a '!' prepended::
316 # echo '!hist:key=call_site:val=bytes_req' > \
317 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
319 Finally, notice that the call_site as displayed in the output above
320 isn't really very useful. It's an address, but normally addresses
321 are displayed in hex. To have a numeric field displayed as a hex
322 value, simply append '.hex' to the field name in the trigger::
324 # echo 'hist:key=call_site.hex:val=bytes_req' > \
325 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
327 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
328 # trigger info: hist:keys=call_site.hex:vals=bytes_req:sort=hitcount:size=2048 [active]
330 { call_site: ffffffffa026b291 } hitcount: 1 bytes_req: 433
331 { call_site: ffffffffa07186ff } hitcount: 1 bytes_req: 176
332 { call_site: ffffffff811ae721 } hitcount: 1 bytes_req: 16384
333 { call_site: ffffffff811c5134 } hitcount: 1 bytes_req: 8
334 { call_site: ffffffffa04a9ebb } hitcount: 1 bytes_req: 511
335 { call_site: ffffffff8122e0a6 } hitcount: 1 bytes_req: 12
336 { call_site: ffffffff8107da84 } hitcount: 1 bytes_req: 152
337 { call_site: ffffffff812d8246 } hitcount: 1 bytes_req: 24
338 { call_site: ffffffff811dc1e5 } hitcount: 3 bytes_req: 144
339 { call_site: ffffffffa02515e8 } hitcount: 3 bytes_req: 648
340 { call_site: ffffffff81258159 } hitcount: 3 bytes_req: 144
341 { call_site: ffffffff811c80f4 } hitcount: 4 bytes_req: 544
342 .
343 .
344 .
345 { call_site: ffffffffa06c7646 } hitcount: 106 bytes_req: 8024
346 { call_site: ffffffffa06cb246 } hitcount: 132 bytes_req: 31680
347 { call_site: ffffffffa06cef7a } hitcount: 132 bytes_req: 2112
348 { call_site: ffffffff8137e399 } hitcount: 132 bytes_req: 23232
349 { call_site: ffffffffa06c941c } hitcount: 185 bytes_req: 171360
350 { call_site: ffffffffa06f2a66 } hitcount: 185 bytes_req: 26640
351 { call_site: ffffffffa036a70e } hitcount: 265 bytes_req: 10600
352 { call_site: ffffffff81325447 } hitcount: 292 bytes_req: 584
353 { call_site: ffffffffa072da3c } hitcount: 446 bytes_req: 60656
354 { call_site: ffffffffa036b1f2 } hitcount: 526 bytes_req: 29456
355 { call_site: ffffffffa0099c06 } hitcount: 1780 bytes_req: 35600
357 Totals:
358 Hits: 4775
359 Entries: 46
360 Dropped: 0
362 Even that's only marginally more useful - while hex values do look
363 more like addresses, what users are typically more interested in
364 when looking at text addresses are the corresponding symbols
365 instead. To have an address displayed as symbolic value instead,
366 simply append '.sym' or '.sym-offset' to the field name in the
367 trigger::
369 # echo 'hist:key=call_site.sym:val=bytes_req' > \
370 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
372 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
373 # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=hitcount:size=2048 [active]
375 { call_site: [ffffffff810adcb9] syslog_print_all } hitcount: 1 bytes_req: 1024
376 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8
377 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7
378 { call_site: [ffffffff8154acbe] usb_alloc_urb } hitcount: 1 bytes_req: 192
379 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7
380 { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40
381 { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128
382 { call_site: [ffffffff811febd5] fsnotify_alloc_group } hitcount: 2 bytes_req: 528
383 { call_site: [ffffffff81440f58] __tty_buffer_request_room } hitcount: 2 bytes_req: 2624
384 { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 2 bytes_req: 96
385 { call_site: [ffffffffa05e19af] ieee80211_start_tx_ba_session [mac80211] } hitcount: 2 bytes_req: 464
386 { call_site: [ffffffff81672406] tcp_get_metrics } hitcount: 2 bytes_req: 304
387 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128
388 { call_site: [ffffffff81089b05] sched_create_group } hitcount: 2 bytes_req: 1424
389 .
390 .
391 .
392 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1185 bytes_req: 123240
393 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 1185 bytes_req: 104280
394 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 1402 bytes_req: 190672
395 { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 1518 bytes_req: 146208
396 { call_site: [ffffffffa029070e] drm_vma_node_allow [drm] } hitcount: 1746 bytes_req: 69840
397 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 2021 bytes_req: 792312
398 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 2592 bytes_req: 145152
399 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2629 bytes_req: 378576
400 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2629 bytes_req: 3783248
401 { call_site: [ffffffff81325607] apparmor_file_alloc_security } hitcount: 5192 bytes_req: 10384
402 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 5529 bytes_req: 110584
403 { call_site: [ffffffff8131ebf7] aa_alloc_task_context } hitcount: 21943 bytes_req: 702176
404 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 55759 bytes_req: 5074265
406 Totals:
407 Hits: 109928
408 Entries: 71
409 Dropped: 0
411 Because the default sort key above is 'hitcount', the above shows a
412 the list of call_sites by increasing hitcount, so that at the bottom
413 we see the functions that made the most kmalloc calls during the
414 run. If instead we we wanted to see the top kmalloc callers in
415 terms of the number of bytes requested rather than the number of
416 calls, and we wanted the top caller to appear at the top, we can use
417 the 'sort' parameter, along with the 'descending' modifier::
419 # echo 'hist:key=call_site.sym:val=bytes_req:sort=bytes_req.descending' > \
420 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
422 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
423 # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=bytes_req.descending:size=2048 [active]
425 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2186 bytes_req: 3397464
426 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1790 bytes_req: 712176
427 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 8132 bytes_req: 513135
428 { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 106 bytes_req: 440128
429 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2186 bytes_req: 314784
430 { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 2174 bytes_req: 208992
431 { call_site: [ffffffff811ae8e1] __kmalloc } hitcount: 8 bytes_req: 131072
432 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 859 bytes_req: 116824
433 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 1834 bytes_req: 102704
434 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 972 bytes_req: 101088
435 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 972 bytes_req: 85536
436 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 3333 bytes_req: 66664
437 { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 209 bytes_req: 61632
438 .
439 .
440 .
441 { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128
442 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128
443 { call_site: [ffffffff812d8406] copy_semundo } hitcount: 2 bytes_req: 48
444 { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 1 bytes_req: 48
445 { call_site: [ffffffffa027121a] drm_getmagic [drm] } hitcount: 1 bytes_req: 48
446 { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40
447 { call_site: [ffffffff811c52f4] bprm_change_interp } hitcount: 2 bytes_req: 16
448 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8
449 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7
450 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7
452 Totals:
453 Hits: 32133
454 Entries: 81
455 Dropped: 0
457 To display the offset and size information in addition to the symbol
458 name, just use 'sym-offset' instead::
460 # echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \
461 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
463 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
464 # trigger info: hist:keys=call_site.sym-offset:vals=bytes_req:sort=bytes_req.descending:size=2048 [active]
466 { call_site: [ffffffffa046041c] i915_gem_execbuffer2+0x6c/0x2c0 [i915] } hitcount: 4569 bytes_req: 3163720
467 { call_site: [ffffffffa0489a66] intel_ring_begin+0xc6/0x1f0 [i915] } hitcount: 4569 bytes_req: 657936
468 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23+0x694/0x1020 [i915] } hitcount: 1519 bytes_req: 472936
469 { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23+0x516/0x1020 [i915] } hitcount: 3050 bytes_req: 211832
470 { call_site: [ffffffff811e2a1b] seq_buf_alloc+0x1b/0x50 } hitcount: 34 bytes_req: 148384
471 { call_site: [ffffffffa04a580c] intel_crtc_page_flip+0xbc/0x870 [i915] } hitcount: 1385 bytes_req: 144040
472 { call_site: [ffffffff811ae8e1] __kmalloc+0x191/0x1b0 } hitcount: 8 bytes_req: 131072
473 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl+0x282/0x360 [drm] } hitcount: 1385 bytes_req: 121880
474 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc+0x32/0x100 [drm] } hitcount: 1848 bytes_req: 103488
475 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state+0x2c/0xa0 [i915] } hitcount: 461 bytes_req: 62696
476 { call_site: [ffffffffa029070e] drm_vma_node_allow+0x2e/0xd0 [drm] } hitcount: 1541 bytes_req: 61640
477 { call_site: [ffffffff815f8d7b] sk_prot_alloc+0xcb/0x1b0 } hitcount: 57 bytes_req: 57456
478 .
479 .
480 .
481 { call_site: [ffffffff8109524a] alloc_fair_sched_group+0x5a/0x1a0 } hitcount: 2 bytes_req: 128
482 { call_site: [ffffffffa027b921] drm_vm_open_locked+0x31/0xa0 [drm] } hitcount: 3 bytes_req: 96
483 { call_site: [ffffffff8122e266] proc_self_follow_link+0x76/0xb0 } hitcount: 8 bytes_req: 96
484 { call_site: [ffffffff81213e80] load_elf_binary+0x240/0x1650 } hitcount: 3 bytes_req: 84
485 { call_site: [ffffffff8154bc62] usb_control_msg+0x42/0x110 } hitcount: 1 bytes_req: 8
486 { call_site: [ffffffffa00bf6fe] hidraw_send_report+0x7e/0x1a0 [hid] } hitcount: 1 bytes_req: 7
487 { call_site: [ffffffffa00bf1ca] hidraw_report_event+0x8a/0x120 [hid] } hitcount: 1 bytes_req: 7
489 Totals:
490 Hits: 26098
491 Entries: 64
492 Dropped: 0
494 We can also add multiple fields to the 'values' parameter. For
495 example, we might want to see the total number of bytes allocated
496 alongside bytes requested, and display the result sorted by bytes
497 allocated in a descending order::
499 # echo 'hist:keys=call_site.sym:values=bytes_req,bytes_alloc:sort=bytes_alloc.descending' > \
500 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
502 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
503 # trigger info: hist:keys=call_site.sym:vals=bytes_req,bytes_alloc:sort=bytes_alloc.descending:size=2048 [active]
505 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 7403 bytes_req: 4084360 bytes_alloc: 5958016
506 { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 541 bytes_req: 2213968 bytes_alloc: 2228224
507 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 7404 bytes_req: 1066176 bytes_alloc: 1421568
508 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1565 bytes_req: 557368 bytes_alloc: 1037760
509 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 9557 bytes_req: 595778 bytes_alloc: 695744
510 { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 5839 bytes_req: 430680 bytes_alloc: 470400
511 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 2388 bytes_req: 324768 bytes_alloc: 458496
512 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 3911 bytes_req: 219016 bytes_alloc: 250304
513 { call_site: [ffffffff815f8d7b] sk_prot_alloc } hitcount: 235 bytes_req: 236880 bytes_alloc: 240640
514 { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 557 bytes_req: 169024 bytes_alloc: 221760
515 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 9378 bytes_req: 187548 bytes_alloc: 206312
516 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1519 bytes_req: 157976 bytes_alloc: 194432
517 .
518 .
519 .
520 { call_site: [ffffffff8109bd3b] sched_autogroup_create_attach } hitcount: 2 bytes_req: 144 bytes_alloc: 192
521 { call_site: [ffffffff81097ee8] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128
522 { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128
523 { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128
524 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128
525 { call_site: [ffffffff81213e80] load_elf_binary } hitcount: 3 bytes_req: 84 bytes_alloc: 96
526 { call_site: [ffffffff81079a2e] kthread_create_on_node } hitcount: 1 bytes_req: 56 bytes_alloc: 64
527 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8
528 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 bytes_alloc: 8
529 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8
531 Totals:
532 Hits: 66598
533 Entries: 65
534 Dropped: 0
536 Finally, to finish off our kmalloc example, instead of simply having
537 the hist trigger display symbolic call_sites, we can have the hist
538 trigger additionally display the complete set of kernel stack traces
539 that led to each call_site. To do that, we simply use the special
540 value 'stacktrace' for the key parameter::
542 # echo 'hist:keys=stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' > \
543 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
545 The above trigger will use the kernel stack trace in effect when an
546 event is triggered as the key for the hash table. This allows the
547 enumeration of every kernel callpath that led up to a particular
548 event, along with a running total of any of the event fields for
549 that event. Here we tally bytes requested and bytes allocated for
550 every callpath in the system that led up to a kmalloc (in this case
551 every callpath to a kmalloc for a kernel compile)::
553 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
554 # trigger info: hist:keys=stacktrace:vals=bytes_req,bytes_alloc:sort=bytes_alloc:size=2048 [active]
556 { stacktrace:
557 __kmalloc_track_caller+0x10b/0x1a0
558 kmemdup+0x20/0x50
559 hidraw_report_event+0x8a/0x120 [hid]
560 hid_report_raw_event+0x3ea/0x440 [hid]
561 hid_input_report+0x112/0x190 [hid]
562 hid_irq_in+0xc2/0x260 [usbhid]
563 __usb_hcd_giveback_urb+0x72/0x120
564 usb_giveback_urb_bh+0x9e/0xe0
565 tasklet_hi_action+0xf8/0x100
566 __do_softirq+0x114/0x2c0
567 irq_exit+0xa5/0xb0
568 do_IRQ+0x5a/0xf0
569 ret_from_intr+0x0/0x30
570 cpuidle_enter+0x17/0x20
571 cpu_startup_entry+0x315/0x3e0
572 rest_init+0x7c/0x80
573 } hitcount: 3 bytes_req: 21 bytes_alloc: 24
574 { stacktrace:
575 __kmalloc_track_caller+0x10b/0x1a0
576 kmemdup+0x20/0x50
577 hidraw_report_event+0x8a/0x120 [hid]
578 hid_report_raw_event+0x3ea/0x440 [hid]
579 hid_input_report+0x112/0x190 [hid]
580 hid_irq_in+0xc2/0x260 [usbhid]
581 __usb_hcd_giveback_urb+0x72/0x120
582 usb_giveback_urb_bh+0x9e/0xe0
583 tasklet_hi_action+0xf8/0x100
584 __do_softirq+0x114/0x2c0
585 irq_exit+0xa5/0xb0
586 do_IRQ+0x5a/0xf0
587 ret_from_intr+0x0/0x30
588 } hitcount: 3 bytes_req: 21 bytes_alloc: 24
589 { stacktrace:
590 kmem_cache_alloc_trace+0xeb/0x150
591 aa_alloc_task_context+0x27/0x40
592 apparmor_cred_prepare+0x1f/0x50
593 security_prepare_creds+0x16/0x20
594 prepare_creds+0xdf/0x1a0
595 SyS_capset+0xb5/0x200
596 system_call_fastpath+0x12/0x6a
597 } hitcount: 1 bytes_req: 32 bytes_alloc: 32
598 .
599 .
600 .
601 { stacktrace:
602 __kmalloc+0x11b/0x1b0
603 i915_gem_execbuffer2+0x6c/0x2c0 [i915]
604 drm_ioctl+0x349/0x670 [drm]
605 do_vfs_ioctl+0x2f0/0x4f0
606 SyS_ioctl+0x81/0xa0
607 system_call_fastpath+0x12/0x6a
608 } hitcount: 17726 bytes_req: 13944120 bytes_alloc: 19593808
609 { stacktrace:
610 __kmalloc+0x11b/0x1b0
611 load_elf_phdrs+0x76/0xa0
612 load_elf_binary+0x102/0x1650
613 search_binary_handler+0x97/0x1d0
614 do_execveat_common.isra.34+0x551/0x6e0
615 SyS_execve+0x3a/0x50
616 return_from_execve+0x0/0x23
617 } hitcount: 33348 bytes_req: 17152128 bytes_alloc: 20226048
618 { stacktrace:
619 kmem_cache_alloc_trace+0xeb/0x150
620 apparmor_file_alloc_security+0x27/0x40
621 security_file_alloc+0x16/0x20
622 get_empty_filp+0x93/0x1c0
623 path_openat+0x31/0x5f0
624 do_filp_open+0x3a/0x90
625 do_sys_open+0x128/0x220
626 SyS_open+0x1e/0x20
627 system_call_fastpath+0x12/0x6a
628 } hitcount: 4766422 bytes_req: 9532844 bytes_alloc: 38131376
629 { stacktrace:
630 __kmalloc+0x11b/0x1b0
631 seq_buf_alloc+0x1b/0x50
632 seq_read+0x2cc/0x370
633 proc_reg_read+0x3d/0x80
634 __vfs_read+0x28/0xe0
635 vfs_read+0x86/0x140
636 SyS_read+0x46/0xb0
637 system_call_fastpath+0x12/0x6a
638 } hitcount: 19133 bytes_req: 78368768 bytes_alloc: 78368768
640 Totals:
641 Hits: 6085872
642 Entries: 253
643 Dropped: 0
645 If you key a hist trigger on common_pid, in order for example to
646 gather and display sorted totals for each process, you can use the
647 special .execname modifier to display the executable names for the
648 processes in the table rather than raw pids. The example below
649 keeps a per-process sum of total bytes read::
651 # echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \
652 /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
654 # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/hist
655 # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active]
657 { common_pid: gnome-terminal [ 3196] } hitcount: 280 count: 1093512
658 { common_pid: Xorg [ 1309] } hitcount: 525 count: 256640
659 { common_pid: compiz [ 2889] } hitcount: 59 count: 254400
660 { common_pid: bash [ 8710] } hitcount: 3 count: 66369
661 { common_pid: dbus-daemon-lau [ 8703] } hitcount: 49 count: 47739
662 { common_pid: irqbalance [ 1252] } hitcount: 27 count: 27648
663 { common_pid: 01ifupdown [ 8705] } hitcount: 3 count: 17216
664 { common_pid: dbus-daemon [ 772] } hitcount: 10 count: 12396
665 { common_pid: Socket Thread [ 8342] } hitcount: 11 count: 11264
666 { common_pid: nm-dhcp-client. [ 8701] } hitcount: 6 count: 7424
667 { common_pid: gmain [ 1315] } hitcount: 18 count: 6336
668 .
669 .
670 .
671 { common_pid: postgres [ 1892] } hitcount: 2 count: 32
672 { common_pid: postgres [ 1891] } hitcount: 2 count: 32
673 { common_pid: gmain [ 8704] } hitcount: 2 count: 32
674 { common_pid: upstart-dbus-br [ 2740] } hitcount: 21 count: 21
675 { common_pid: nm-dispatcher.a [ 8696] } hitcount: 1 count: 16
676 { common_pid: indicator-datet [ 2904] } hitcount: 1 count: 16
677 { common_pid: gdbus [ 2998] } hitcount: 1 count: 16
678 { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8
679 { common_pid: init [ 1] } hitcount: 2 count: 2
681 Totals:
682 Hits: 2116
683 Entries: 51
684 Dropped: 0
686 Similarly, if you key a hist trigger on syscall id, for example to
687 gather and display a list of systemwide syscall hits, you can use
688 the special .syscall modifier to display the syscall names rather
689 than raw ids. The example below keeps a running total of syscall
690 counts for the system during the run::
692 # echo 'hist:key=id.syscall:val=hitcount' > \
693 /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
695 # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist
696 # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active]
698 { id: sys_fsync [ 74] } hitcount: 1
699 { id: sys_newuname [ 63] } hitcount: 1
700 { id: sys_prctl [157] } hitcount: 1
701 { id: sys_statfs [137] } hitcount: 1
702 { id: sys_symlink [ 88] } hitcount: 1
703 { id: sys_sendmmsg [307] } hitcount: 1
704 { id: sys_semctl [ 66] } hitcount: 1
705 { id: sys_readlink [ 89] } hitcount: 3
706 { id: sys_bind [ 49] } hitcount: 3
707 { id: sys_getsockname [ 51] } hitcount: 3
708 { id: sys_unlink [ 87] } hitcount: 3
709 { id: sys_rename [ 82] } hitcount: 4
710 { id: unknown_syscall [ 58] } hitcount: 4
711 { id: sys_connect [ 42] } hitcount: 4
712 { id: sys_getpid [ 39] } hitcount: 4
713 .
714 .
715 .
716 { id: sys_rt_sigprocmask [ 14] } hitcount: 952
717 { id: sys_futex [202] } hitcount: 1534
718 { id: sys_write [ 1] } hitcount: 2689
719 { id: sys_setitimer [ 38] } hitcount: 2797
720 { id: sys_read [ 0] } hitcount: 3202
721 { id: sys_select [ 23] } hitcount: 3773
722 { id: sys_writev [ 20] } hitcount: 4531
723 { id: sys_poll [ 7] } hitcount: 8314
724 { id: sys_recvmsg [ 47] } hitcount: 13738
725 { id: sys_ioctl [ 16] } hitcount: 21843
727 Totals:
728 Hits: 67612
729 Entries: 72
730 Dropped: 0
732 The syscall counts above provide a rough overall picture of system
733 call activity on the system; we can see for example that the most
734 popular system call on this system was the 'sys_ioctl' system call.
736 We can use 'compound' keys to refine that number and provide some
737 further insight as to which processes exactly contribute to the
738 overall ioctl count.
740 The command below keeps a hitcount for every unique combination of
741 system call id and pid - the end result is essentially a table
742 that keeps a per-pid sum of system call hits. The results are
743 sorted using the system call id as the primary key, and the
744 hitcount sum as the secondary key::
746 # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' > \
747 /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
749 # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist
750 # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active]
752 { id: sys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: 1
753 { id: sys_read [ 0], common_pid: gdbus [ 2976] } hitcount: 1
754 { id: sys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: 1
755 { id: sys_read [ 0], common_pid: postgres [ 1865] } hitcount: 1
756 { id: sys_read [ 0], common_pid: deja-dup-monito [ 3543] } hitcount: 2
757 { id: sys_read [ 0], common_pid: NetworkManager [ 890] } hitcount: 2
758 { id: sys_read [ 0], common_pid: evolution-calen [ 3048] } hitcount: 2
759 { id: sys_read [ 0], common_pid: postgres [ 1864] } hitcount: 2
760 { id: sys_read [ 0], common_pid: nm-applet [ 3022] } hitcount: 2
761 { id: sys_read [ 0], common_pid: whoopsie [ 1212] } hitcount: 2
762 .
763 .
764 .
765 { id: sys_ioctl [ 16], common_pid: bash [ 8479] } hitcount: 1
766 { id: sys_ioctl [ 16], common_pid: bash [ 3472] } hitcount: 12
767 { id: sys_ioctl [ 16], common_pid: gnome-terminal [ 3199] } hitcount: 16
768 { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 1808
769 { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 5580
770 .
771 .
772 .
773 { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2690] } hitcount: 3
774 { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2688] } hitcount: 16
775 { id: sys_inotify_add_watch [254], common_pid: gmain [ 975] } hitcount: 2
776 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3204] } hitcount: 4
777 { id: sys_inotify_add_watch [254], common_pid: gmain [ 2888] } hitcount: 4
778 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3003] } hitcount: 4
779 { id: sys_inotify_add_watch [254], common_pid: gmain [ 2873] } hitcount: 4
780 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3196] } hitcount: 6
781 { id: sys_openat [257], common_pid: java [ 2623] } hitcount: 2
782 { id: sys_eventfd2 [290], common_pid: ibus-ui-gtk3 [ 2760] } hitcount: 4
783 { id: sys_eventfd2 [290], common_pid: compiz [ 2994] } hitcount: 6
785 Totals:
786 Hits: 31536
787 Entries: 323
788 Dropped: 0
790 The above list does give us a breakdown of the ioctl syscall by
791 pid, but it also gives us quite a bit more than that, which we
792 don't really care about at the moment. Since we know the syscall
793 id for sys_ioctl (16, displayed next to the sys_ioctl name), we
794 can use that to filter out all the other syscalls::
796 # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount if id == 16' > \
797 /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
799 # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist
800 # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 if id == 16 [active]
802 { id: sys_ioctl [ 16], common_pid: gmain [ 2769] } hitcount: 1
803 { id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: 1
804 { id: sys_ioctl [ 16], common_pid: gmain [ 3003] } hitcount: 1
805 { id: sys_ioctl [ 16], common_pid: gmain [ 2781] } hitcount: 1
806 { id: sys_ioctl [ 16], common_pid: gmain [ 2829] } hitcount: 1
807 { id: sys_ioctl [ 16], common_pid: bash [ 8726] } hitcount: 1
808 { id: sys_ioctl [ 16], common_pid: bash [ 8508] } hitcount: 1
809 { id: sys_ioctl [ 16], common_pid: gmain [ 2970] } hitcount: 1
810 { id: sys_ioctl [ 16], common_pid: gmain [ 2768] } hitcount: 1
811 .
812 .
813 .
814 { id: sys_ioctl [ 16], common_pid: pool [ 8559] } hitcount: 45
815 { id: sys_ioctl [ 16], common_pid: pool [ 8555] } hitcount: 48
816 { id: sys_ioctl [ 16], common_pid: pool [ 8551] } hitcount: 48
817 { id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: 66
818 { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 26674
819 { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 73443
821 Totals:
822 Hits: 101162
823 Entries: 103
824 Dropped: 0
826 The above output shows that 'compiz' and 'Xorg' are far and away
827 the heaviest ioctl callers (which might lead to questions about
828 whether they really need to be making all those calls and to
829 possible avenues for further investigation.)
831 The compound key examples used a key and a sum value (hitcount) to
832 sort the output, but we can just as easily use two keys instead.
833 Here's an example where we use a compound key composed of the the
834 common_pid and size event fields. Sorting with pid as the primary
835 key and 'size' as the secondary key allows us to display an
836 ordered summary of the recvfrom sizes, with counts, received by
837 each process::
839 # echo 'hist:key=common_pid.execname,size:val=hitcount:sort=common_pid,size' > \
840 /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/trigger
842 # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/hist
843 # trigger info: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:size=2048 [active]
845 { common_pid: smbd [ 784], size: 4 } hitcount: 1
846 { common_pid: dnsmasq [ 1412], size: 4096 } hitcount: 672
847 { common_pid: postgres [ 1796], size: 1000 } hitcount: 6
848 { common_pid: postgres [ 1867], size: 1000 } hitcount: 10
849 { common_pid: bamfdaemon [ 2787], size: 28 } hitcount: 2
850 { common_pid: bamfdaemon [ 2787], size: 14360 } hitcount: 1
851 { common_pid: compiz [ 2994], size: 8 } hitcount: 1
852 { common_pid: compiz [ 2994], size: 20 } hitcount: 11
853 { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2
854 { common_pid: firefox [ 8817], size: 4 } hitcount: 1
855 { common_pid: firefox [ 8817], size: 8 } hitcount: 5
856 { common_pid: firefox [ 8817], size: 588 } hitcount: 2
857 { common_pid: firefox [ 8817], size: 628 } hitcount: 1
858 { common_pid: firefox [ 8817], size: 6944 } hitcount: 1
859 { common_pid: firefox [ 8817], size: 408880 } hitcount: 2
860 { common_pid: firefox [ 8822], size: 8 } hitcount: 2
861 { common_pid: firefox [ 8822], size: 160 } hitcount: 2
862 { common_pid: firefox [ 8822], size: 320 } hitcount: 2
863 { common_pid: firefox [ 8822], size: 352 } hitcount: 1
864 .
865 .
866 .
867 { common_pid: pool [ 8923], size: 1960 } hitcount: 10
868 { common_pid: pool [ 8923], size: 2048 } hitcount: 10
869 { common_pid: pool [ 8924], size: 1960 } hitcount: 10
870 { common_pid: pool [ 8924], size: 2048 } hitcount: 10
871 { common_pid: pool [ 8928], size: 1964 } hitcount: 4
872 { common_pid: pool [ 8928], size: 1965 } hitcount: 2
873 { common_pid: pool [ 8928], size: 2048 } hitcount: 6
874 { common_pid: pool [ 8929], size: 1982 } hitcount: 1
875 { common_pid: pool [ 8929], size: 2048 } hitcount: 1
877 Totals:
878 Hits: 2016
879 Entries: 224
880 Dropped: 0
882 The above example also illustrates the fact that although a compound
883 key is treated as a single entity for hashing purposes, the sub-keys
884 it's composed of can be accessed independently.
886 The next example uses a string field as the hash key and
887 demonstrates how you can manually pause and continue a hist trigger.
888 In this example, we'll aggregate fork counts and don't expect a
889 large number of entries in the hash table, so we'll drop it to a
890 much smaller number, say 256::
892 # echo 'hist:key=child_comm:val=hitcount:size=256' > \
893 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
895 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
896 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active]
898 { child_comm: dconf worker } hitcount: 1
899 { child_comm: ibus-daemon } hitcount: 1
900 { child_comm: whoopsie } hitcount: 1
901 { child_comm: smbd } hitcount: 1
902 { child_comm: gdbus } hitcount: 1
903 { child_comm: kthreadd } hitcount: 1
904 { child_comm: dconf worker } hitcount: 1
905 { child_comm: evolution-alarm } hitcount: 2
906 { child_comm: Socket Thread } hitcount: 2
907 { child_comm: postgres } hitcount: 2
908 { child_comm: bash } hitcount: 3
909 { child_comm: compiz } hitcount: 3
910 { child_comm: evolution-sourc } hitcount: 4
911 { child_comm: dhclient } hitcount: 4
912 { child_comm: pool } hitcount: 5
913 { child_comm: nm-dispatcher.a } hitcount: 8
914 { child_comm: firefox } hitcount: 8
915 { child_comm: dbus-daemon } hitcount: 8
916 { child_comm: glib-pacrunner } hitcount: 10
917 { child_comm: evolution } hitcount: 23
919 Totals:
920 Hits: 89
921 Entries: 20
922 Dropped: 0
924 If we want to pause the hist trigger, we can simply append :pause to
925 the command that started the trigger. Notice that the trigger info
926 displays as [paused]::
928 # echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \
929 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
931 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
932 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [paused]
934 { child_comm: dconf worker } hitcount: 1
935 { child_comm: kthreadd } hitcount: 1
936 { child_comm: dconf worker } hitcount: 1
937 { child_comm: gdbus } hitcount: 1
938 { child_comm: ibus-daemon } hitcount: 1
939 { child_comm: Socket Thread } hitcount: 2
940 { child_comm: evolution-alarm } hitcount: 2
941 { child_comm: smbd } hitcount: 2
942 { child_comm: bash } hitcount: 3
943 { child_comm: whoopsie } hitcount: 3
944 { child_comm: compiz } hitcount: 3
945 { child_comm: evolution-sourc } hitcount: 4
946 { child_comm: pool } hitcount: 5
947 { child_comm: postgres } hitcount: 6
948 { child_comm: firefox } hitcount: 8
949 { child_comm: dhclient } hitcount: 10
950 { child_comm: emacs } hitcount: 12
951 { child_comm: dbus-daemon } hitcount: 20
952 { child_comm: nm-dispatcher.a } hitcount: 20
953 { child_comm: evolution } hitcount: 35
954 { child_comm: glib-pacrunner } hitcount: 59
956 Totals:
957 Hits: 199
958 Entries: 21
959 Dropped: 0
961 To manually continue having the trigger aggregate events, append
962 :cont instead. Notice that the trigger info displays as [active]
963 again, and the data has changed::
965 # echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \
966 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
968 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
969 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active]
971 { child_comm: dconf worker } hitcount: 1
972 { child_comm: dconf worker } hitcount: 1
973 { child_comm: kthreadd } hitcount: 1
974 { child_comm: gdbus } hitcount: 1
975 { child_comm: ibus-daemon } hitcount: 1
976 { child_comm: Socket Thread } hitcount: 2
977 { child_comm: evolution-alarm } hitcount: 2
978 { child_comm: smbd } hitcount: 2
979 { child_comm: whoopsie } hitcount: 3
980 { child_comm: compiz } hitcount: 3
981 { child_comm: evolution-sourc } hitcount: 4
982 { child_comm: bash } hitcount: 5
983 { child_comm: pool } hitcount: 5
984 { child_comm: postgres } hitcount: 6
985 { child_comm: firefox } hitcount: 8
986 { child_comm: dhclient } hitcount: 11
987 { child_comm: emacs } hitcount: 12
988 { child_comm: dbus-daemon } hitcount: 22
989 { child_comm: nm-dispatcher.a } hitcount: 22
990 { child_comm: evolution } hitcount: 35
991 { child_comm: glib-pacrunner } hitcount: 59
993 Totals:
994 Hits: 206
995 Entries: 21
996 Dropped: 0
998 The previous example showed how to start and stop a hist trigger by
999 appending 'pause' and 'continue' to the hist trigger command. A
1000 hist trigger can also be started in a paused state by initially
1001 starting the trigger with ':pause' appended. This allows you to
1002 start the trigger only when you're ready to start collecting data
1003 and not before. For example, you could start the trigger in a
1004 paused state, then unpause it and do something you want to measure,
1005 then pause the trigger again when done.
1007 Of course, doing this manually can be difficult and error-prone, but
1008 it is possible to automatically start and stop a hist trigger based
1009 on some condition, via the enable_hist and disable_hist triggers.
1011 For example, suppose we wanted to take a look at the relative
1012 weights in terms of skb length for each callpath that leads to a
1013 netif_receive_skb event when downloading a decent-sized file using
1014 wget.
1016 First we set up an initially paused stacktrace trigger on the
1017 netif_receive_skb event::
1019 # echo 'hist:key=stacktrace:vals=len:pause' > \
1020 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1022 Next, we set up an 'enable_hist' trigger on the sched_process_exec
1023 event, with an 'if filename==/usr/bin/wget' filter. The effect of
1024 this new trigger is that it will 'unpause' the hist trigger we just
1025 set up on netif_receive_skb if and only if it sees a
1026 sched_process_exec event with a filename of '/usr/bin/wget'. When
1027 that happens, all netif_receive_skb events are aggregated into a
1028 hash table keyed on stacktrace::
1030 # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \
1031 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
1033 The aggregation continues until the netif_receive_skb is paused
1034 again, which is what the following disable_hist event does by
1035 creating a similar setup on the sched_process_exit event, using the
1036 filter 'comm==wget'::
1038 # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \
1039 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
1041 Whenever a process exits and the comm field of the disable_hist
1042 trigger filter matches 'comm==wget', the netif_receive_skb hist
1043 trigger is disabled.
1045 The overall effect is that netif_receive_skb events are aggregated
1046 into the hash table for only the duration of the wget. Executing a
1047 wget command and then listing the 'hist' file will display the
1048 output generated by the wget command::
1050 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1052 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
1053 # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused]
1055 { stacktrace:
1056 __netif_receive_skb_core+0x46d/0x990
1057 __netif_receive_skb+0x18/0x60
1058 netif_receive_skb_internal+0x23/0x90
1059 napi_gro_receive+0xc8/0x100
1060 ieee80211_deliver_skb+0xd6/0x270 [mac80211]
1061 ieee80211_rx_handlers+0xccf/0x22f0 [mac80211]
1062 ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211]
1063 ieee80211_rx+0x31d/0x900 [mac80211]
1064 iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm]
1065 iwl_rx_dispatch+0x8e/0xf0 [iwldvm]
1066 iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi]
1067 irq_thread_fn+0x20/0x50
1068 irq_thread+0x11f/0x150
1069 kthread+0xd2/0xf0
1070 ret_from_fork+0x42/0x70
1071 } hitcount: 85 len: 28884
1072 { stacktrace:
1073 __netif_receive_skb_core+0x46d/0x990
1074 __netif_receive_skb+0x18/0x60
1075 netif_receive_skb_internal+0x23/0x90
1076 napi_gro_complete+0xa4/0xe0
1077 dev_gro_receive+0x23a/0x360
1078 napi_gro_receive+0x30/0x100
1079 ieee80211_deliver_skb+0xd6/0x270 [mac80211]
1080 ieee80211_rx_handlers+0xccf/0x22f0 [mac80211]
1081 ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211]
1082 ieee80211_rx+0x31d/0x900 [mac80211]
1083 iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm]
1084 iwl_rx_dispatch+0x8e/0xf0 [iwldvm]
1085 iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi]
1086 irq_thread_fn+0x20/0x50
1087 irq_thread+0x11f/0x150
1088 kthread+0xd2/0xf0
1089 } hitcount: 98 len: 664329
1090 { stacktrace:
1091 __netif_receive_skb_core+0x46d/0x990
1092 __netif_receive_skb+0x18/0x60
1093 process_backlog+0xa8/0x150
1094 net_rx_action+0x15d/0x340
1095 __do_softirq+0x114/0x2c0
1096 do_softirq_own_stack+0x1c/0x30
1097 do_softirq+0x65/0x70
1098 __local_bh_enable_ip+0xb5/0xc0
1099 ip_finish_output+0x1f4/0x840
1100 ip_output+0x6b/0xc0
1101 ip_local_out_sk+0x31/0x40
1102 ip_send_skb+0x1a/0x50
1103 udp_send_skb+0x173/0x2a0
1104 udp_sendmsg+0x2bf/0x9f0
1105 inet_sendmsg+0x64/0xa0
1106 sock_sendmsg+0x3d/0x50
1107 } hitcount: 115 len: 13030
1108 { stacktrace:
1109 __netif_receive_skb_core+0x46d/0x990
1110 __netif_receive_skb+0x18/0x60
1111 netif_receive_skb_internal+0x23/0x90
1112 napi_gro_complete+0xa4/0xe0
1113 napi_gro_flush+0x6d/0x90
1114 iwl_pcie_irq_handler+0x92a/0x12f0 [iwlwifi]
1115 irq_thread_fn+0x20/0x50
1116 irq_thread+0x11f/0x150
1117 kthread+0xd2/0xf0
1118 ret_from_fork+0x42/0x70
1119 } hitcount: 934 len: 5512212
1121 Totals:
1122 Hits: 1232
1123 Entries: 4
1124 Dropped: 0
1126 The above shows all the netif_receive_skb callpaths and their total
1127 lengths for the duration of the wget command.
1129 The 'clear' hist trigger param can be used to clear the hash table.
1130 Suppose we wanted to try another run of the previous example but
1131 this time also wanted to see the complete list of events that went
1132 into the histogram. In order to avoid having to set everything up
1133 again, we can just clear the histogram first::
1135 # echo 'hist:key=stacktrace:vals=len:clear' >> \
1136 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1138 Just to verify that it is in fact cleared, here's what we now see in
1139 the hist file::
1141 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
1142 # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused]
1144 Totals:
1145 Hits: 0
1146 Entries: 0
1147 Dropped: 0
1149 Since we want to see the detailed list of every netif_receive_skb
1150 event occurring during the new run, which are in fact the same
1151 events being aggregated into the hash table, we add some additional
1152 'enable_event' events to the triggering sched_process_exec and
1153 sched_process_exit events as such::
1155 # echo 'enable_event:net:netif_receive_skb if filename==/usr/bin/wget' > \
1156 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
1158 # echo 'disable_event:net:netif_receive_skb if comm==wget' > \
1159 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
1161 If you read the trigger files for the sched_process_exec and
1162 sched_process_exit triggers, you should see two triggers for each:
1163 one enabling/disabling the hist aggregation and the other
1164 enabling/disabling the logging of events::
1166 # cat /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
1167 enable_event:net:netif_receive_skb:unlimited if filename==/usr/bin/wget
1168 enable_hist:net:netif_receive_skb:unlimited if filename==/usr/bin/wget
1170 # cat /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
1171 enable_event:net:netif_receive_skb:unlimited if comm==wget
1172 disable_hist:net:netif_receive_skb:unlimited if comm==wget
1174 In other words, whenever either of the sched_process_exec or
1175 sched_process_exit events is hit and matches 'wget', it enables or
1176 disables both the histogram and the event log, and what you end up
1177 with is a hash table and set of events just covering the specified
1178 duration. Run the wget command again::
1180 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1182 Displaying the 'hist' file should show something similar to what you
1183 saw in the last run, but this time you should also see the
1184 individual events in the trace file::
1186 # cat /sys/kernel/debug/tracing/trace
1188 # tracer: nop
1189 #
1190 # entries-in-buffer/entries-written: 183/1426 #P:4
1191 #
1192 # _-----=> irqs-off
1193 # / _----=> need-resched
1194 # | / _---=> hardirq/softirq
1195 # || / _--=> preempt-depth
1196 # ||| / delay
1197 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
1198 # | | | |||| | |
1199 wget-15108 [000] ..s1 31769.606929: netif_receive_skb: dev=lo skbaddr=ffff88009c353100 len=60
1200 wget-15108 [000] ..s1 31769.606999: netif_receive_skb: dev=lo skbaddr=ffff88009c353200 len=60
1201 dnsmasq-1382 [000] ..s1 31769.677652: netif_receive_skb: dev=lo skbaddr=ffff88009c352b00 len=130
1202 dnsmasq-1382 [000] ..s1 31769.685917: netif_receive_skb: dev=lo skbaddr=ffff88009c352200 len=138
1203 ##### CPU 2 buffer started ####
1204 irq/29-iwlwifi-559 [002] ..s. 31772.031529: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433d00 len=2948
1205 irq/29-iwlwifi-559 [002] ..s. 31772.031572: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432200 len=1500
1206 irq/29-iwlwifi-559 [002] ..s. 31772.032196: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433100 len=2948
1207 irq/29-iwlwifi-559 [002] ..s. 31772.032761: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433000 len=2948
1208 irq/29-iwlwifi-559 [002] ..s. 31772.033220: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432e00 len=1500
1209 .
1210 .
1211 .
1213 The following example demonstrates how multiple hist triggers can be
1214 attached to a given event. This capability can be useful for
1215 creating a set of different summaries derived from the same set of
1216 events, or for comparing the effects of different filters, among
1217 other things::
1219 # echo 'hist:keys=skbaddr.hex:vals=len if len < 0' >> \
1220 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1221 # echo 'hist:keys=skbaddr.hex:vals=len if len > 4096' >> \
1222 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1223 # echo 'hist:keys=skbaddr.hex:vals=len if len == 256' >> \
1224 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1225 # echo 'hist:keys=skbaddr.hex:vals=len' >> \
1226 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1227 # echo 'hist:keys=len:vals=common_preempt_count' >> \
1228 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1230 The above set of commands create four triggers differing only in
1231 their filters, along with a completely different though fairly
1232 nonsensical trigger. Note that in order to append multiple hist
1233 triggers to the same file, you should use the '>>' operator to
1234 append them ('>' will also add the new hist trigger, but will remove
1235 any existing hist triggers beforehand).
1237 Displaying the contents of the 'hist' file for the event shows the
1238 contents of all five histograms::
1240 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
1242 # event histogram
1243 #
1244 # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active]
1245 #
1247 { len: 176 } hitcount: 1 common_preempt_count: 0
1248 { len: 223 } hitcount: 1 common_preempt_count: 0
1249 { len: 4854 } hitcount: 1 common_preempt_count: 0
1250 { len: 395 } hitcount: 1 common_preempt_count: 0
1251 { len: 177 } hitcount: 1 common_preempt_count: 0
1252 { len: 446 } hitcount: 1 common_preempt_count: 0
1253 { len: 1601 } hitcount: 1 common_preempt_count: 0
1254 .
1255 .
1256 .
1257 { len: 1280 } hitcount: 66 common_preempt_count: 0
1258 { len: 116 } hitcount: 81 common_preempt_count: 40
1259 { len: 708 } hitcount: 112 common_preempt_count: 0
1260 { len: 46 } hitcount: 221 common_preempt_count: 0
1261 { len: 1264 } hitcount: 458 common_preempt_count: 0
1263 Totals:
1264 Hits: 1428
1265 Entries: 147
1266 Dropped: 0
1269 # event histogram
1270 #
1271 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1272 #
1274 { skbaddr: ffff8800baee5e00 } hitcount: 1 len: 130
1275 { skbaddr: ffff88005f3d5600 } hitcount: 1 len: 1280
1276 { skbaddr: ffff88005f3d4900 } hitcount: 1 len: 1280
1277 { skbaddr: ffff88009fed6300 } hitcount: 1 len: 115
1278 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 115
1279 { skbaddr: ffff88008cdb1900 } hitcount: 1 len: 46
1280 { skbaddr: ffff880064b5ef00 } hitcount: 1 len: 118
1281 { skbaddr: ffff880044e3c700 } hitcount: 1 len: 60
1282 { skbaddr: ffff880100065900 } hitcount: 1 len: 46
1283 { skbaddr: ffff8800d46bd500 } hitcount: 1 len: 116
1284 { skbaddr: ffff88005f3d5f00 } hitcount: 1 len: 1280
1285 { skbaddr: ffff880100064700 } hitcount: 1 len: 365
1286 { skbaddr: ffff8800badb6f00 } hitcount: 1 len: 60
1287 .
1288 .
1289 .
1290 { skbaddr: ffff88009fe0be00 } hitcount: 27 len: 24677
1291 { skbaddr: ffff88009fe0a400 } hitcount: 27 len: 23052
1292 { skbaddr: ffff88009fe0b700 } hitcount: 31 len: 25589
1293 { skbaddr: ffff88009fe0b600 } hitcount: 32 len: 27326
1294 { skbaddr: ffff88006a462800 } hitcount: 68 len: 71678
1295 { skbaddr: ffff88006a463700 } hitcount: 70 len: 72678
1296 { skbaddr: ffff88006a462b00 } hitcount: 71 len: 77589
1297 { skbaddr: ffff88006a463600 } hitcount: 73 len: 71307
1298 { skbaddr: ffff88006a462200 } hitcount: 81 len: 81032
1300 Totals:
1301 Hits: 1451
1302 Entries: 318
1303 Dropped: 0
1306 # event histogram
1307 #
1308 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [active]
1309 #
1312 Totals:
1313 Hits: 0
1314 Entries: 0
1315 Dropped: 0
1318 # event histogram
1319 #
1320 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [active]
1321 #
1323 { skbaddr: ffff88009fd2c300 } hitcount: 1 len: 7212
1324 { skbaddr: ffff8800d2bcce00 } hitcount: 1 len: 7212
1325 { skbaddr: ffff8800d2bcd700 } hitcount: 1 len: 7212
1326 { skbaddr: ffff8800d2bcda00 } hitcount: 1 len: 21492
1327 { skbaddr: ffff8800ae2e2d00 } hitcount: 1 len: 7212
1328 { skbaddr: ffff8800d2bcdb00 } hitcount: 1 len: 7212
1329 { skbaddr: ffff88006a4df500 } hitcount: 1 len: 4854
1330 { skbaddr: ffff88008ce47b00 } hitcount: 1 len: 18636
1331 { skbaddr: ffff8800ae2e2200 } hitcount: 1 len: 12924
1332 { skbaddr: ffff88005f3e1000 } hitcount: 1 len: 4356
1333 { skbaddr: ffff8800d2bcdc00 } hitcount: 2 len: 24420
1334 { skbaddr: ffff8800d2bcc200 } hitcount: 2 len: 12996
1336 Totals:
1337 Hits: 14
1338 Entries: 12
1339 Dropped: 0
1342 # event histogram
1343 #
1344 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active]
1345 #
1348 Totals:
1349 Hits: 0
1350 Entries: 0
1351 Dropped: 0
1353 Named triggers can be used to have triggers share a common set of
1354 histogram data. This capability is mostly useful for combining the
1355 output of events generated by tracepoints contained inside inline
1356 functions, but names can be used in a hist trigger on any event.
1357 For example, these two triggers when hit will update the same 'len'
1358 field in the shared 'foo' histogram data::
1360 # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \
1361 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1362 # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \
1363 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
1365 You can see that they're updating common histogram data by reading
1366 each event's hist files at the same time::
1368 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist;
1369 cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
1371 # event histogram
1372 #
1373 # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1374 #
1376 { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46
1377 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76
1378 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46
1379 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468
1380 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46
1381 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52
1382 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168
1383 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46
1384 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260
1385 { skbaddr: ffff880064505000 } hitcount: 1 len: 46
1386 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32
1387 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46
1388 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44
1389 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168
1390 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40
1391 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40
1392 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174
1393 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160
1394 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76
1395 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46
1396 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32
1397 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46
1398 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988
1399 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46
1400 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44
1401 { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676
1402 { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107
1403 { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92
1404 { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142
1405 { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220
1406 { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92
1407 { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92
1408 { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675
1409 { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138
1410 { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138
1411 { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184
1412 { skbaddr: ffff880064504400 } hitcount: 4 len: 184
1413 { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184
1414 { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230
1415 { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196
1416 { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276
1417 { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276
1419 Totals:
1420 Hits: 81
1421 Entries: 42
1422 Dropped: 0
1423 # event histogram
1424 #
1425 # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1426 #
1428 { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46
1429 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76
1430 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46
1431 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468
1432 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46
1433 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52
1434 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168
1435 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46
1436 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260
1437 { skbaddr: ffff880064505000 } hitcount: 1 len: 46
1438 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32
1439 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46
1440 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44
1441 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168
1442 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40
1443 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40
1444 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174
1445 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160
1446 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76
1447 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46
1448 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32
1449 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46
1450 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988
1451 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46
1452 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44
1453 { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676
1454 { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107
1455 { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92
1456 { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142
1457 { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220
1458 { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92
1459 { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92
1460 { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675
1461 { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138
1462 { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138
1463 { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184
1464 { skbaddr: ffff880064504400 } hitcount: 4 len: 184
1465 { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184
1466 { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230
1467 { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196
1468 { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276
1469 { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276
1471 Totals:
1472 Hits: 81
1473 Entries: 42
1474 Dropped: 0
1476 And here's an example that shows how to combine histogram data from
1477 any two events even if they don't share any 'compatible' fields
1478 other than 'hitcount' and 'stacktrace'. These commands create a
1479 couple of triggers named 'bar' using those fields::
1481 # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \
1482 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
1483 # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \
1484 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
1486 And displaying the output of either shows some interesting if
1487 somewhat confusing output::
1489 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
1490 # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
1492 # event histogram
1493 #
1494 # trigger info: hist:name=bar:keys=stacktrace:vals=hitcount:sort=hitcount:size=2048 [active]
1495 #
1497 { stacktrace:
1498 _do_fork+0x18e/0x330
1499 kernel_thread+0x29/0x30
1500 kthreadd+0x154/0x1b0
1501 ret_from_fork+0x3f/0x70
1502 } hitcount: 1
1503 { stacktrace:
1504 netif_rx_internal+0xb2/0xd0
1505 netif_rx_ni+0x20/0x70
1506 dev_loopback_xmit+0xaa/0xd0
1507 ip_mc_output+0x126/0x240
1508 ip_local_out_sk+0x31/0x40
1509 igmp_send_report+0x1e9/0x230
1510 igmp_timer_expire+0xe9/0x120
1511 call_timer_fn+0x39/0xf0
1512 run_timer_softirq+0x1e1/0x290
1513 __do_softirq+0xfd/0x290
1514 irq_exit+0x98/0xb0
1515 smp_apic_timer_interrupt+0x4a/0x60
1516 apic_timer_interrupt+0x6d/0x80
1517 cpuidle_enter+0x17/0x20
1518 call_cpuidle+0x3b/0x60
1519 cpu_startup_entry+0x22d/0x310
1520 } hitcount: 1
1521 { stacktrace:
1522 netif_rx_internal+0xb2/0xd0
1523 netif_rx_ni+0x20/0x70
1524 dev_loopback_xmit+0xaa/0xd0
1525 ip_mc_output+0x17f/0x240
1526 ip_local_out_sk+0x31/0x40
1527 ip_send_skb+0x1a/0x50
1528 udp_send_skb+0x13e/0x270
1529 udp_sendmsg+0x2bf/0x980
1530 inet_sendmsg+0x67/0xa0
1531 sock_sendmsg+0x38/0x50
1532 SYSC_sendto+0xef/0x170
1533 SyS_sendto+0xe/0x10
1534 entry_SYSCALL_64_fastpath+0x12/0x6a
1535 } hitcount: 2
1536 { stacktrace:
1537 netif_rx_internal+0xb2/0xd0
1538 netif_rx+0x1c/0x60
1539 loopback_xmit+0x6c/0xb0
1540 dev_hard_start_xmit+0x219/0x3a0
1541 __dev_queue_xmit+0x415/0x4f0
1542 dev_queue_xmit_sk+0x13/0x20
1543 ip_finish_output2+0x237/0x340
1544 ip_finish_output+0x113/0x1d0
1545 ip_output+0x66/0xc0
1546 ip_local_out_sk+0x31/0x40
1547 ip_send_skb+0x1a/0x50
1548 udp_send_skb+0x16d/0x270
1549 udp_sendmsg+0x2bf/0x980
1550 inet_sendmsg+0x67/0xa0
1551 sock_sendmsg+0x38/0x50
1552 ___sys_sendmsg+0x14e/0x270
1553 } hitcount: 76
1554 { stacktrace:
1555 netif_rx_internal+0xb2/0xd0
1556 netif_rx+0x1c/0x60
1557 loopback_xmit+0x6c/0xb0
1558 dev_hard_start_xmit+0x219/0x3a0
1559 __dev_queue_xmit+0x415/0x4f0
1560 dev_queue_xmit_sk+0x13/0x20
1561 ip_finish_output2+0x237/0x340
1562 ip_finish_output+0x113/0x1d0
1563 ip_output+0x66/0xc0
1564 ip_local_out_sk+0x31/0x40
1565 ip_send_skb+0x1a/0x50
1566 udp_send_skb+0x16d/0x270
1567 udp_sendmsg+0x2bf/0x980
1568 inet_sendmsg+0x67/0xa0
1569 sock_sendmsg+0x38/0x50
1570 ___sys_sendmsg+0x269/0x270
1571 } hitcount: 77
1572 { stacktrace:
1573 netif_rx_internal+0xb2/0xd0
1574 netif_rx+0x1c/0x60
1575 loopback_xmit+0x6c/0xb0
1576 dev_hard_start_xmit+0x219/0x3a0
1577 __dev_queue_xmit+0x415/0x4f0
1578 dev_queue_xmit_sk+0x13/0x20
1579 ip_finish_output2+0x237/0x340
1580 ip_finish_output+0x113/0x1d0
1581 ip_output+0x66/0xc0
1582 ip_local_out_sk+0x31/0x40
1583 ip_send_skb+0x1a/0x50
1584 udp_send_skb+0x16d/0x270
1585 udp_sendmsg+0x2bf/0x980
1586 inet_sendmsg+0x67/0xa0
1587 sock_sendmsg+0x38/0x50
1588 SYSC_sendto+0xef/0x170
1589 } hitcount: 88
1590 { stacktrace:
1591 _do_fork+0x18e/0x330
1592 SyS_clone+0x19/0x20
1593 entry_SYSCALL_64_fastpath+0x12/0x6a
1594 } hitcount: 244
1596 Totals:
1597 Hits: 489
1598 Entries: 7
1599 Dropped: 0
1601 2.2 Inter-event hist triggers
1602 -----------------------------
1604 Inter-event hist triggers are hist triggers that combine values from
1605 one or more other events and create a histogram using that data. Data
1606 from an inter-event histogram can in turn become the source for
1607 further combined histograms, thus providing a chain of related
1608 histograms, which is important for some applications.
1610 The most important example of an inter-event quantity that can be used
1611 in this manner is latency, which is simply a difference in timestamps
1612 between two events. Although latency is the most important
1613 inter-event quantity, note that because the support is completely
1614 general across the trace event subsystem, any event field can be used
1615 in an inter-event quantity.
1617 An example of a histogram that combines data from other histograms
1618 into a useful chain would be a 'wakeupswitch latency' histogram that
1619 combines a 'wakeup latency' histogram and a 'switch latency'
1620 histogram.
1622 Normally, a hist trigger specification consists of a (possibly
1623 compound) key along with one or more numeric values, which are
1624 continually updated sums associated with that key. A histogram
1625 specification in this case consists of individual key and value
1626 specifications that refer to trace event fields associated with a
1627 single event type.
1629 The inter-event hist trigger extension allows fields from multiple
1630 events to be referenced and combined into a multi-event histogram
1631 specification. In support of this overall goal, a few enabling
1632 features have been added to the hist trigger support:
1634 - In order to compute an inter-event quantity, a value from one
1635 event needs to saved and then referenced from another event. This
1636 requires the introduction of support for histogram 'variables'.
1638 - The computation of inter-event quantities and their combination
1639 require some minimal amount of support for applying simple
1640 expressions to variables (+ and -).
1642 - A histogram consisting of inter-event quantities isn't logically a
1643 histogram on either event (so having the 'hist' file for either
1644 event host the histogram output doesn't really make sense). To
1645 address the idea that the histogram is associated with a
1646 combination of events, support is added allowing the creation of
1647 'synthetic' events that are events derived from other events.
1648 These synthetic events are full-fledged events just like any other
1649 and can be used as such, as for instance to create the
1650 'combination' histograms mentioned previously.
1652 - A set of 'actions' can be associated with histogram entries -
1653 these can be used to generate the previously mentioned synthetic
1654 events, but can also be used for other purposes, such as for
1655 example saving context when a 'max' latency has been hit.
1657 - Trace events don't have a 'timestamp' associated with them, but
1658 there is an implicit timestamp saved along with an event in the
1659 underlying ftrace ring buffer. This timestamp is now exposed as a
1660 a synthetic field named 'common_timestamp' which can be used in
1661 histograms as if it were any other event field; it isn't an actual
1662 field in the trace format but rather is a synthesized value that
1663 nonetheless can be used as if it were an actual field. By default
1664 it is in units of nanoseconds; appending '.usecs' to a
1665 common_timestamp field changes the units to microseconds.
1667 A note on inter-event timestamps: If common_timestamp is used in a
1668 histogram, the trace buffer is automatically switched over to using
1669 absolute timestamps and the "global" trace clock, in order to avoid
1670 bogus timestamp differences with other clocks that aren't coherent
1671 across CPUs. This can be overridden by specifying one of the other
1672 trace clocks instead, using the "clock=XXX" hist trigger attribute,
1673 where XXX is any of the clocks listed in the tracing/trace_clock
1674 pseudo-file.
1676 These features are described in more detail in the following sections.
1678 2.2.1 Histogram Variables
1679 -------------------------
1681 Variables are simply named locations used for saving and retrieving
1682 values between matching events. A 'matching' event is defined as an
1683 event that has a matching key - if a variable is saved for a histogram
1684 entry corresponding to that key, any subsequent event with a matching
1685 key can access that variable.
1687 A variable's value is normally available to any subsequent event until
1688 it is set to something else by a subsequent event. The one exception
1689 to that rule is that any variable used in an expression is essentially
1690 'read-once' - once it's used by an expression in a subsequent event,
1691 it's reset to its 'unset' state, which means it can't be used again
1692 unless it's set again. This ensures not only that an event doesn't
1693 use an uninitialized variable in a calculation, but that that variable
1694 is used only once and not for any unrelated subsequent match.
1696 The basic syntax for saving a variable is to simply prefix a unique
1697 variable name not corresponding to any keyword along with an '=' sign
1698 to any event field.
1700 Either keys or values can be saved and retrieved in this way. This
1701 creates a variable named 'ts0' for a histogram entry with the key
1702 'next_pid'::
1704 # echo 'hist:keys=next_pid:vals=$ts0:ts0=common_timestamp ... >> \
1705 event/trigger
1707 The ts0 variable can be accessed by any subsequent event having the
1708 same pid as 'next_pid'.
1710 Variable references are formed by prepending the variable name with
1711 the '$' sign. Thus for example, the ts0 variable above would be
1712 referenced as '$ts0' in expressions.
1714 Because 'vals=' is used, the common_timestamp variable value above
1715 will also be summed as a normal histogram value would (though for a
1716 timestamp it makes little sense).
1718 The below shows that a key value can also be saved in the same way::
1720 # echo 'hist:timer_pid=common_pid:key=timer_pid ...' >> event/trigger
1722 If a variable isn't a key variable or prefixed with 'vals=', the
1723 associated event field will be saved in a variable but won't be summed
1724 as a value::
1726 # echo 'hist:keys=next_pid:ts1=common_timestamp ...' >> event/trigger
1728 Multiple variables can be assigned at the same time. The below would
1729 result in both ts0 and b being created as variables, with both
1730 common_timestamp and field1 additionally being summed as values::
1732 # echo 'hist:keys=pid:vals=$ts0,$b:ts0=common_timestamp,b=field1 ...' >> \
1733 event/trigger
1735 Note that variable assignments can appear either preceding or
1736 following their use. The command below behaves identically to the
1737 command above::
1739 # echo 'hist:keys=pid:ts0=common_timestamp,b=field1:vals=$ts0,$b ...' >> \
1740 event/trigger
1742 Any number of variables not bound to a 'vals=' prefix can also be
1743 assigned by simply separating them with colons. Below is the same
1744 thing but without the values being summed in the histogram::
1746 # echo 'hist:keys=pid:ts0=common_timestamp:b=field1 ...' >> event/trigger
1748 Variables set as above can be referenced and used in expressions on
1749 another event.
1751 For example, here's how a latency can be calculated::
1753 # echo 'hist:keys=pid,prio:ts0=common_timestamp ...' >> event1/trigger
1754 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp-$ts0 ...' >> event2/trigger
1756 In the first line above, the event's timestamp is saved into the
1757 variable ts0. In the next line, ts0 is subtracted from the second
1758 event's timestamp to produce the latency, which is then assigned into
1759 yet another variable, 'wakeup_lat'. The hist trigger below in turn
1760 makes use of the wakeup_lat variable to compute a combined latency
1761 using the same key and variable from yet another event::
1763 # echo 'hist:key=pid:wakeupswitch_lat=$wakeup_lat+$switchtime_lat ...' >> event3/trigger
1765 2.2.2 Synthetic Events
1766 ----------------------
1768 Synthetic events are user-defined events generated from hist trigger
1769 variables or fields associated with one or more other events. Their
1770 purpose is to provide a mechanism for displaying data spanning
1771 multiple events consistent with the existing and already familiar
1772 usage for normal events.
1774 To define a synthetic event, the user writes a simple specification
1775 consisting of the name of the new event along with one or more
1776 variables and their types, which can be any valid field type,
1777 separated by semicolons, to the tracing/synthetic_events file.
1779 For instance, the following creates a new event named 'wakeup_latency'
1780 with 3 fields: lat, pid, and prio. Each of those fields is simply a
1781 variable reference to a variable on another event::
1783 # echo 'wakeup_latency \
1784 u64 lat; \
1785 pid_t pid; \
1786 int prio' >> \
1787 /sys/kernel/debug/tracing/synthetic_events
1789 Reading the tracing/synthetic_events file lists all the currently
1790 defined synthetic events, in this case the event defined above::
1792 # cat /sys/kernel/debug/tracing/synthetic_events
1793 wakeup_latency u64 lat; pid_t pid; int prio
1795 An existing synthetic event definition can be removed by prepending
1796 the command that defined it with a '!'::
1798 # echo '!wakeup_latency u64 lat pid_t pid int prio' >> \
1799 /sys/kernel/debug/tracing/synthetic_events
1801 At this point, there isn't yet an actual 'wakeup_latency' event
1802 instantiated in the event subsystem - for this to happen, a 'hist
1803 trigger action' needs to be instantiated and bound to actual fields
1804 and variables defined on other events (see Section 2.2.3 below on
1805 how that is done using hist trigger 'onmatch' action). Once that is
1806 done, the 'wakeup_latency' synthetic event instance is created.
1808 A histogram can now be defined for the new synthetic event::
1810 # echo 'hist:keys=pid,prio,lat.log2:sort=pid,lat' >> \
1811 /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
1813 The new event is created under the tracing/events/synthetic/ directory
1814 and looks and behaves just like any other event::
1816 # ls /sys/kernel/debug/tracing/events/synthetic/wakeup_latency
1817 enable filter format hist id trigger
1819 Like any other event, once a histogram is enabled for the event, the
1820 output can be displayed by reading the event's 'hist' file.
1822 2.2.3 Hist trigger 'handlers' and 'actions'
1823 -------------------------------------------
1825 A hist trigger 'action' is a function that's executed (in most cases
1826 conditionally) whenever a histogram entry is added or updated.
1828 When a histogram entry is added or updated, a hist trigger 'handler'
1829 is what decides whether the corresponding action is actually invoked
1830 or not.
1832 Hist trigger handlers and actions are paired together in the general
1833 form:
1835 <handler>.<action>
1837 To specify a handler.action pair for a given event, simply specify
1838 that handler.action pair between colons in the hist trigger
1839 specification.
1841 In theory, any handler can be combined with any action, but in
1842 practice, not every handler.action combination is currently supported;
1843 if a given handler.action combination isn't supported, the hist
1844 trigger will fail with -EINVAL;
1846 The default 'handler.action' if none is explicitly specified is as it
1847 always has been, to simply update the set of values associated with an
1848 entry. Some applications, however, may want to perform additional
1849 actions at that point, such as generate another event, or compare and
1850 save a maximum.
1852 The supported handlers and actions are listed below, and each is
1853 described in more detail in the following paragraphs, in the context
1854 of descriptions of some common and useful handler.action combinations.
1856 The available handlers are:
1858 - onmatch(matching.event) - invoke action on any addition or update
1859 - onmax(var) - invoke action if var exceeds current max
1860 - onchange(var) - invoke action if var changes
1862 The available actions are:
1864 - trace(<synthetic_event_name>,param list) - generate synthetic event
1865 - save(field,...) - save current event fields
1866 - snapshot() - snapshot the trace buffer
1868 The following commonly-used handler.action pairs are available:
1870 - onmatch(matching.event).trace(<synthetic_event_name>,param list)
1872 The 'onmatch(matching.event).trace(<synthetic_event_name>,param
1873 list)' hist trigger action is invoked whenever an event matches
1874 and the histogram entry would be added or updated. It causes the
1875 named synthetic event to be generated with the values given in the
1876 'param list'. The result is the generation of a synthetic event
1877 that consists of the values contained in those variables at the
1878 time the invoking event was hit. For example, if the synthetic
1879 event name is 'wakeup_latency', a wakeup_latency event is
1880 generated using onmatch(event).trace(wakeup_latency,arg1,arg2).
1882 There is also an equivalent alternative form available for
1883 generating synthetic events. In this form, the synthetic event
1884 name is used as if it were a function name. For example, using
1885 the 'wakeup_latency' synthetic event name again, the
1886 wakeup_latency event would be generated by invoking it as if it
1887 were a function call, with the event field values passed in as
1888 arguments: onmatch(event).wakeup_latency(arg1,arg2). The syntax
1889 for this form is:
1891 onmatch(matching.event).<synthetic_event_name>(param list)
1893 In either case, the 'param list' consists of one or more
1894 parameters which may be either variables or fields defined on
1895 either the 'matching.event' or the target event. The variables or
1896 fields specified in the param list may be either fully-qualified
1897 or unqualified. If a variable is specified as unqualified, it
1898 must be unique between the two events. A field name used as a
1899 param can be unqualified if it refers to the target event, but
1900 must be fully qualified if it refers to the matching event. A
1901 fully-qualified name is of the form 'system.event_name.$var_name'
1902 or 'system.event_name.field'.
1904 The 'matching.event' specification is simply the fully qualified
1905 event name of the event that matches the target event for the
1906 onmatch() functionality, in the form 'system.event_name'. Histogram
1907 keys of both events are compared to find if events match. In case
1908 multiple histogram keys are used, they all must match in the specified
1909 order.
1911 Finally, the number and type of variables/fields in the 'param
1912 list' must match the number and types of the fields in the
1913 synthetic event being generated.
1915 As an example the below defines a simple synthetic event and uses
1916 a variable defined on the sched_wakeup_new event as a parameter
1917 when invoking the synthetic event. Here we define the synthetic
1918 event::
1920 # echo 'wakeup_new_test pid_t pid' >> \
1921 /sys/kernel/debug/tracing/synthetic_events
1923 # cat /sys/kernel/debug/tracing/synthetic_events
1924 wakeup_new_test pid_t pid
1926 The following hist trigger both defines the missing testpid
1927 variable and specifies an onmatch() action that generates a
1928 wakeup_new_test synthetic event whenever a sched_wakeup_new event
1929 occurs, which because of the 'if comm == "cyclictest"' filter only
1930 happens when the executable is cyclictest::
1932 # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\
1933 wakeup_new_test($testpid) if comm=="cyclictest"' >> \
1934 /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger
1936 Or, equivalently, using the 'trace' keyword syntax:
1938 # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\
1939 trace(wakeup_new_test,$testpid) if comm=="cyclictest"' >> \
1940 /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger
1942 Creating and displaying a histogram based on those events is now
1943 just a matter of using the fields and new synthetic event in the
1944 tracing/events/synthetic directory, as usual::
1946 # echo 'hist:keys=pid:sort=pid' >> \
1947 /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/trigger
1949 Running 'cyclictest' should cause wakeup_new events to generate
1950 wakeup_new_test synthetic events which should result in histogram
1951 output in the wakeup_new_test event's hist file::
1953 # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/hist
1955 A more typical usage would be to use two events to calculate a
1956 latency. The following example uses a set of hist triggers to
1957 produce a 'wakeup_latency' histogram.
1959 First, we define a 'wakeup_latency' synthetic event::
1961 # echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> \
1962 /sys/kernel/debug/tracing/synthetic_events
1964 Next, we specify that whenever we see a sched_waking event for a
1965 cyclictest thread, save the timestamp in a 'ts0' variable::
1967 # echo 'hist:keys=$saved_pid:saved_pid=pid:ts0=common_timestamp.usecs \
1968 if comm=="cyclictest"' >> \
1969 /sys/kernel/debug/tracing/events/sched/sched_waking/trigger
1971 Then, when the corresponding thread is actually scheduled onto the
1972 CPU by a sched_switch event (saved_pid matches next_pid), calculate
1973 the latency and use that along with another variable and an event field
1974 to generate a wakeup_latency synthetic event::
1976 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\
1977 onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,\
1978 $saved_pid,next_prio) if next_comm=="cyclictest"' >> \
1979 /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
1981 We also need to create a histogram on the wakeup_latency synthetic
1982 event in order to aggregate the generated synthetic event data::
1984 # echo 'hist:keys=pid,prio,lat:sort=pid,lat' >> \
1985 /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
1987 Finally, once we've run cyclictest to actually generate some
1988 events, we can see the output by looking at the wakeup_latency
1989 synthetic event's hist file::
1991 # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist
1993 - onmax(var).save(field,.. .)
1995 The 'onmax(var).save(field,...)' hist trigger action is invoked
1996 whenever the value of 'var' associated with a histogram entry
1997 exceeds the current maximum contained in that variable.
1999 The end result is that the trace event fields specified as the
2000 onmax.save() params will be saved if 'var' exceeds the current
2001 maximum for that hist trigger entry. This allows context from the
2002 event that exhibited the new maximum to be saved for later
2003 reference. When the histogram is displayed, additional fields
2004 displaying the saved values will be printed.
2006 As an example the below defines a couple of hist triggers, one for
2007 sched_waking and another for sched_switch, keyed on pid. Whenever
2008 a sched_waking occurs, the timestamp is saved in the entry
2009 corresponding to the current pid, and when the scheduler switches
2010 back to that pid, the timestamp difference is calculated. If the
2011 resulting latency, stored in wakeup_lat, exceeds the current
2012 maximum latency, the values specified in the save() fields are
2013 recorded::
2015 # echo 'hist:keys=pid:ts0=common_timestamp.usecs \
2016 if comm=="cyclictest"' >> \
2017 /sys/kernel/debug/tracing/events/sched/sched_waking/trigger
2019 # echo 'hist:keys=next_pid:\
2020 wakeup_lat=common_timestamp.usecs-$ts0:\
2021 onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) \
2022 if next_comm=="cyclictest"' >> \
2023 /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
2025 When the histogram is displayed, the max value and the saved
2026 values corresponding to the max are displayed following the rest
2027 of the fields::
2029 # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
2030 { next_pid: 2255 } hitcount: 239
2031 common_timestamp-ts0: 0
2032 max: 27
2033 next_comm: cyclictest
2034 prev_pid: 0 prev_prio: 120 prev_comm: swapper/1
2036 { next_pid: 2256 } hitcount: 2355
2037 common_timestamp-ts0: 0
2038 max: 49 next_comm: cyclictest
2039 prev_pid: 0 prev_prio: 120 prev_comm: swapper/0
2041 Totals:
2042 Hits: 12970
2043 Entries: 2
2044 Dropped: 0
2046 - onmax(var).snapshot()
2048 The 'onmax(var).snapshot()' hist trigger action is invoked
2049 whenever the value of 'var' associated with a histogram entry
2050 exceeds the current maximum contained in that variable.
2052 The end result is that a global snapshot of the trace buffer will
2053 be saved in the tracing/snapshot file if 'var' exceeds the current
2054 maximum for any hist trigger entry.
2056 Note that in this case the maximum is a global maximum for the
2057 current trace instance, which is the maximum across all buckets of
2058 the histogram. The key of the specific trace event that caused
2059 the global maximum and the global maximum itself are displayed,
2060 along with a message stating that a snapshot has been taken and
2061 where to find it. The user can use the key information displayed
2062 to locate the corresponding bucket in the histogram for even more
2063 detail.
2065 As an example the below defines a couple of hist triggers, one for
2066 sched_waking and another for sched_switch, keyed on pid. Whenever
2067 a sched_waking event occurs, the timestamp is saved in the entry
2068 corresponding to the current pid, and when the scheduler switches
2069 back to that pid, the timestamp difference is calculated. If the
2070 resulting latency, stored in wakeup_lat, exceeds the current
2071 maximum latency, a snapshot is taken. As part of the setup, all
2072 the scheduler events are also enabled, which are the events that
2073 will show up in the snapshot when it is taken at some point:
2075 # echo 1 > /sys/kernel/debug/tracing/events/sched/enable
2077 # echo 'hist:keys=pid:ts0=common_timestamp.usecs \
2078 if comm=="cyclictest"' >> \
2079 /sys/kernel/debug/tracing/events/sched/sched_waking/trigger
2081 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \
2082 onmax($wakeup_lat).save(next_prio,next_comm,prev_pid,prev_prio, \
2083 prev_comm):onmax($wakeup_lat).snapshot() \
2084 if next_comm=="cyclictest"' >> \
2085 /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
2087 When the histogram is displayed, for each bucket the max value
2088 and the saved values corresponding to the max are displayed
2089 following the rest of the fields.
2091 If a snapshot was taken, there is also a message indicating that,
2092 along with the value and event that triggered the global maximum:
2094 # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
2095 { next_pid: 2101 } hitcount: 200
2096 max: 52 next_prio: 120 next_comm: cyclictest \
2097 prev_pid: 0 prev_prio: 120 prev_comm: swapper/6
2099 { next_pid: 2103 } hitcount: 1326
2100 max: 572 next_prio: 19 next_comm: cyclictest \
2101 prev_pid: 0 prev_prio: 120 prev_comm: swapper/1
2103 { next_pid: 2102 } hitcount: 1982 \
2104 max: 74 next_prio: 19 next_comm: cyclictest \
2105 prev_pid: 0 prev_prio: 120 prev_comm: swapper/5
2107 Snapshot taken (see tracing/snapshot). Details:
2108 triggering value { onmax($wakeup_lat) }: 572 \
2109 triggered by event with key: { next_pid: 2103 }
2111 Totals:
2112 Hits: 3508
2113 Entries: 3
2114 Dropped: 0
2116 In the above case, the event that triggered the global maximum has
2117 the key with next_pid == 2103. If you look at the bucket that has
2118 2103 as the key, you'll find the additional values save()'d along
2119 with the local maximum for that bucket, which should be the same
2120 as the global maximum (since that was the same value that
2121 triggered the global snapshot).
2123 And finally, looking at the snapshot data should show at or near
2124 the end the event that triggered the snapshot (in this case you
2125 can verify the timestamps between the sched_waking and
2126 sched_switch events, which should match the time displayed in the
2127 global maximum)::
2129 # cat /sys/kernel/debug/tracing/snapshot
2131 <...>-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
2132 <idle>-0 [005] d.h3 309.873611: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005
2133 <idle>-0 [005] dNh4 309.873613: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005
2134 <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
2135 <...>-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
2136 <idle>-0 [005] d.h3 309.874624: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005
2137 <idle>-0 [005] dNh4 309.874626: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005
2138 <idle>-0 [005] dNh3 309.874628: sched_waking: comm=cyclictest pid=2103 prio=19 target_cpu=005
2139 <idle>-0 [005] dNh4 309.874630: sched_wakeup: comm=cyclictest pid=2103 prio=19 target_cpu=005
2140 <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
2141 <idle>-0 [004] d.h3 309.874757: sched_waking: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004
2142 <idle>-0 [004] dNh4 309.874762: sched_wakeup: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004
2143 <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
2144 gnome-terminal--1699 [004] d.h2 309.874941: sched_stat_runtime: comm=gnome-terminal- pid=1699 runtime=180706 [ns] vruntime=1126870572 [ns]
2145 <idle>-0 [003] d.s4 309.874956: sched_waking: comm=rcu_sched pid=9 prio=120 target_cpu=007
2146 <idle>-0 [003] d.s5 309.874960: sched_wake_idle_without_ipi: cpu=7
2147 <idle>-0 [003] d.s5 309.874961: sched_wakeup: comm=rcu_sched pid=9 prio=120 target_cpu=007
2148 <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
2149 rcu_sched-9 [007] d..3 309.874973: sched_stat_runtime: comm=rcu_sched pid=9 runtime=13646 [ns] vruntime=22531430286 [ns]
2150 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
2151 <...>-2102 [005] d..4 309.874994: sched_migrate_task: comm=cyclictest pid=2103 prio=19 orig_cpu=5 dest_cpu=1
2152 <...>-2102 [005] d..4 309.875185: sched_wake_idle_without_ipi: cpu=1
2153 <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=19
2155 - onchange(var).save(field,.. .)
2157 The 'onchange(var).save(field,...)' hist trigger action is invoked
2158 whenever the value of 'var' associated with a histogram entry
2159 changes.
2161 The end result is that the trace event fields specified as the
2162 onchange.save() params will be saved if 'var' changes for that
2163 hist trigger entry. This allows context from the event that
2164 changed the value to be saved for later reference. When the
2165 histogram is displayed, additional fields displaying the saved
2166 values will be printed.
2168 - onchange(var).snapshot()
2170 The 'onchange(var).snapshot()' hist trigger action is invoked
2171 whenever the value of 'var' associated with a histogram entry
2172 changes.
2174 The end result is that a global snapshot of the trace buffer will
2175 be saved in the tracing/snapshot file if 'var' changes for any
2176 hist trigger entry.
2178 Note that in this case the changed value is a global variable
2179 associated with current trace instance. The key of the specific
2180 trace event that caused the value to change and the global value
2181 itself are displayed, along with a message stating that a snapshot
2182 has been taken and where to find it. The user can use the key
2183 information displayed to locate the corresponding bucket in the
2184 histogram for even more detail.
2186 As an example the below defines a hist trigger on the tcp_probe
2187 event, keyed on dport. Whenever a tcp_probe event occurs, the
2188 cwnd field is checked against the current value stored in the
2189 $cwnd variable. If the value has changed, a snapshot is taken.
2190 As part of the setup, all the scheduler and tcp events are also
2191 enabled, which are the events that will show up in the snapshot
2192 when it is taken at some point:
2194 # echo 1 > /sys/kernel/debug/tracing/events/sched/enable
2195 # echo 1 > /sys/kernel/debug/tracing/events/tcp/enable
2197 # echo 'hist:keys=dport:cwnd=snd_cwnd: \
2198 onchange($cwnd).save(snd_wnd,srtt,rcv_wnd): \
2199 onchange($cwnd).snapshot()' >> \
2200 /sys/kernel/debug/tracing/events/tcp/tcp_probe/trigger
2202 When the histogram is displayed, for each bucket the tracked value
2203 and the saved values corresponding to that value are displayed
2204 following the rest of the fields.
2206 If a snapshot was taken, there is also a message indicating that,
2207 along with the value and event that triggered the snapshot::
2209 # cat /sys/kernel/debug/tracing/events/tcp/tcp_probe/hist
2211 { dport: 1521 } hitcount: 8
2212 changed: 10 snd_wnd: 35456 srtt: 154262 rcv_wnd: 42112
2214 { dport: 80 } hitcount: 23
2215 changed: 10 snd_wnd: 28960 srtt: 19604 rcv_wnd: 29312
2217 { dport: 9001 } hitcount: 172
2218 changed: 10 snd_wnd: 48384 srtt: 260444 rcv_wnd: 55168
2220 { dport: 443 } hitcount: 211
2221 changed: 10 snd_wnd: 26960 srtt: 17379 rcv_wnd: 28800
2223 Snapshot taken (see tracing/snapshot). Details::
2225 triggering value { onchange($cwnd) }: 10
2226 triggered by event with key: { dport: 80 }
2228 Totals:
2229 Hits: 414
2230 Entries: 4
2231 Dropped: 0
2233 In the above case, the event that triggered the snapshot has the
2234 key with dport == 80. If you look at the bucket that has 80 as
2235 the key, you'll find the additional values save()'d along with the
2236 changed value for that bucket, which should be the same as the
2237 global changed value (since that was the same value that triggered
2238 the global snapshot).
2240 And finally, looking at the snapshot data should show at or near
2241 the end the event that triggered the snapshot::
2243 # cat /sys/kernel/debug/tracing/snapshot
2245 gnome-shell-1261 [006] dN.3 49.823113: sched_stat_runtime: comm=gnome-shell pid=1261 runtime=49347 [ns] vruntime=1835730389 [ns]
2246 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
2247 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
2248 kworker/3:2-135 [003] d..3 49.823118: sched_stat_runtime: comm=kworker/3:2 pid=135 runtime=5339 [ns] vruntime=17815800388 [ns]
2249 kworker/6:2-387 [006] d..3 49.823120: sched_stat_runtime: comm=kworker/6:2 pid=387 runtime=9594 [ns] vruntime=14589605367 [ns]
2250 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
2251 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
2252 <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
2254 3. User space creating a trigger
2255 --------------------------------
2257 Writing into /sys/kernel/tracing/trace_marker writes into the ftrace
2258 ring buffer. This can also act like an event, by writing into the trigger
2259 file located in /sys/kernel/tracing/events/ftrace/print/
2261 Modifying cyclictest to write into the trace_marker file before it sleeps
2262 and after it wakes up, something like this::
2264 static void traceputs(char *str)
2265 {
2266 /* tracemark_fd is the trace_marker file descriptor */
2267 if (tracemark_fd < 0)
2268 return;
2269 /* write the tracemark message */
2270 write(tracemark_fd, str, strlen(str));
2271 }
2273 And later add something like::
2275 traceputs("start");
2276 clock_nanosleep(...);
2277 traceputs("end");
2279 We can make a histogram from this::
2281 # cd /sys/kernel/tracing
2282 # echo 'latency u64 lat' > synthetic_events
2283 # echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/trigger
2284 # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) if buf == "end"' >> events/ftrace/print/trigger
2285 # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
2287 The above created a synthetic event called "latency" and two histograms
2288 against the trace_marker, one gets triggered when "start" is written into the
2289 trace_marker file and the other when "end" is written. If the pids match, then
2290 it will call the "latency" synthetic event with the calculated latency as its
2291 parameter. Finally, a histogram is added to the latency synthetic event to
2292 record the calculated latency along with the pid.
2294 Now running cyclictest with::
2296 # ./cyclictest -p80 -d0 -i250 -n -a -t --tracemark -b 1000
2298 -p80 : run threads at priority 80
2299 -d0 : have all threads run at the same interval
2300 -i250 : start the interval at 250 microseconds (all threads will do this)
2301 -n : sleep with nanosleep
2302 -a : affine all threads to a separate CPU
2303 -t : one thread per available CPU
2304 --tracemark : enable trace mark writing
2305 -b 1000 : stop if any latency is greater than 1000 microseconds
2307 Note, the -b 1000 is used just to make --tracemark available.
2309 Then we can see the histogram created by this with::
2311 # cat events/synthetic/latency/hist
2312 # event histogram
2313 #
2314 # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
2315 #
2317 { lat: 107, common_pid: 2039 } hitcount: 1
2318 { lat: 122, common_pid: 2041 } hitcount: 1
2319 { lat: 166, common_pid: 2039 } hitcount: 1
2320 { lat: 174, common_pid: 2039 } hitcount: 1
2321 { lat: 194, common_pid: 2041 } hitcount: 1
2322 { lat: 196, common_pid: 2036 } hitcount: 1
2323 { lat: 197, common_pid: 2038 } hitcount: 1
2324 { lat: 198, common_pid: 2039 } hitcount: 1
2325 { lat: 199, common_pid: 2039 } hitcount: 1
2326 { lat: 200, common_pid: 2041 } hitcount: 1
2327 { lat: 201, common_pid: 2039 } hitcount: 2
2328 { lat: 202, common_pid: 2038 } hitcount: 1
2329 { lat: 202, common_pid: 2043 } hitcount: 1
2330 { lat: 203, common_pid: 2039 } hitcount: 1
2331 { lat: 203, common_pid: 2036 } hitcount: 1
2332 { lat: 203, common_pid: 2041 } hitcount: 1
2333 { lat: 206, common_pid: 2038 } hitcount: 2
2334 { lat: 207, common_pid: 2039 } hitcount: 1
2335 { lat: 207, common_pid: 2036 } hitcount: 1
2336 { lat: 208, common_pid: 2040 } hitcount: 1
2337 { lat: 209, common_pid: 2043 } hitcount: 1
2338 { lat: 210, common_pid: 2039 } hitcount: 1
2339 { lat: 211, common_pid: 2039 } hitcount: 4
2340 { lat: 212, common_pid: 2043 } hitcount: 1
2341 { lat: 212, common_pid: 2039 } hitcount: 2
2342 { lat: 213, common_pid: 2039 } hitcount: 1
2343 { lat: 214, common_pid: 2038 } hitcount: 1
2344 { lat: 214, common_pid: 2039 } hitcount: 2
2345 { lat: 214, common_pid: 2042 } hitcount: 1
2346 { lat: 215, common_pid: 2039 } hitcount: 1
2347 { lat: 217, common_pid: 2036 } hitcount: 1
2348 { lat: 217, common_pid: 2040 } hitcount: 1
2349 { lat: 217, common_pid: 2039 } hitcount: 1
2350 { lat: 218, common_pid: 2039 } hitcount: 6
2351 { lat: 219, common_pid: 2039 } hitcount: 9
2352 { lat: 220, common_pid: 2039 } hitcount: 11
2353 { lat: 221, common_pid: 2039 } hitcount: 5
2354 { lat: 221, common_pid: 2042 } hitcount: 1
2355 { lat: 222, common_pid: 2039 } hitcount: 7
2356 { lat: 223, common_pid: 2036 } hitcount: 1
2357 { lat: 223, common_pid: 2039 } hitcount: 3
2358 { lat: 224, common_pid: 2039 } hitcount: 4
2359 { lat: 224, common_pid: 2037 } hitcount: 1
2360 { lat: 224, common_pid: 2036 } hitcount: 2
2361 { lat: 225, common_pid: 2039 } hitcount: 5
2362 { lat: 225, common_pid: 2042 } hitcount: 1
2363 { lat: 226, common_pid: 2039 } hitcount: 7
2364 { lat: 226, common_pid: 2036 } hitcount: 4
2365 { lat: 227, common_pid: 2039 } hitcount: 6
2366 { lat: 227, common_pid: 2036 } hitcount: 12
2367 { lat: 227, common_pid: 2043 } hitcount: 1
2368 { lat: 228, common_pid: 2039 } hitcount: 7
2369 { lat: 228, common_pid: 2036 } hitcount: 14
2370 { lat: 229, common_pid: 2039 } hitcount: 9
2371 { lat: 229, common_pid: 2036 } hitcount: 8
2372 { lat: 229, common_pid: 2038 } hitcount: 1
2373 { lat: 230, common_pid: 2039 } hitcount: 11
2374 { lat: 230, common_pid: 2036 } hitcount: 6
2375 { lat: 230, common_pid: 2043 } hitcount: 1
2376 { lat: 230, common_pid: 2042 } hitcount: 2
2377 { lat: 231, common_pid: 2041 } hitcount: 1
2378 { lat: 231, common_pid: 2036 } hitcount: 6
2379 { lat: 231, common_pid: 2043 } hitcount: 1
2380 { lat: 231, common_pid: 2039 } hitcount: 8
2381 { lat: 232, common_pid: 2037 } hitcount: 1
2382 { lat: 232, common_pid: 2039 } hitcount: 6
2383 { lat: 232, common_pid: 2040 } hitcount: 2
2384 { lat: 232, common_pid: 2036 } hitcount: 5
2385 { lat: 232, common_pid: 2043 } hitcount: 1
2386 { lat: 233, common_pid: 2036 } hitcount: 5
2387 { lat: 233, common_pid: 2039 } hitcount: 11
2388 { lat: 234, common_pid: 2039 } hitcount: 4
2389 { lat: 234, common_pid: 2038 } hitcount: 2
2390 { lat: 234, common_pid: 2043 } hitcount: 2
2391 { lat: 234, common_pid: 2036 } hitcount: 11
2392 { lat: 234, common_pid: 2040 } hitcount: 1
2393 { lat: 235, common_pid: 2037 } hitcount: 2
2394 { lat: 235, common_pid: 2036 } hitcount: 8
2395 { lat: 235, common_pid: 2043 } hitcount: 2
2396 { lat: 235, common_pid: 2039 } hitcount: 5
2397 { lat: 235, common_pid: 2042 } hitcount: 2
2398 { lat: 235, common_pid: 2040 } hitcount: 4
2399 { lat: 235, common_pid: 2041 } hitcount: 1
2400 { lat: 236, common_pid: 2036 } hitcount: 7
2401 { lat: 236, common_pid: 2037 } hitcount: 1
2402 { lat: 236, common_pid: 2041 } hitcount: 5
2403 { lat: 236, common_pid: 2039 } hitcount: 3
2404 { lat: 236, common_pid: 2043 } hitcount: 9
2405 { lat: 236, common_pid: 2040 } hitcount: 7
2406 { lat: 237, common_pid: 2037 } hitcount: 1
2407 { lat: 237, common_pid: 2040 } hitcount: 1
2408 { lat: 237, common_pid: 2036 } hitcount: 9
2409 { lat: 237, common_pid: 2039 } hitcount: 3
2410 { lat: 237, common_pid: 2043 } hitcount: 8
2411 { lat: 237, common_pid: 2042 } hitcount: 2
2412 { lat: 237, common_pid: 2041 } hitcount: 2
2413 { lat: 238, common_pid: 2043 } hitcount: 10
2414 { lat: 238, common_pid: 2040 } hitcount: 1
2415 { lat: 238, common_pid: 2037 } hitcount: 9
2416 { lat: 238, common_pid: 2038 } hitcount: 1
2417 { lat: 238, common_pid: 2039 } hitcount: 1
2418 { lat: 238, common_pid: 2042 } hitcount: 3
2419 { lat: 238, common_pid: 2036 } hitcount: 7
2420 { lat: 239, common_pid: 2041 } hitcount: 1
2421 { lat: 239, common_pid: 2043 } hitcount: 11
2422 { lat: 239, common_pid: 2037 } hitcount: 11
2423 { lat: 239, common_pid: 2038 } hitcount: 6
2424 { lat: 239, common_pid: 2036 } hitcount: 7
2425 { lat: 239, common_pid: 2040 } hitcount: 1
2426 { lat: 239, common_pid: 2042 } hitcount: 9
2427 { lat: 240, common_pid: 2037 } hitcount: 29
2428 { lat: 240, common_pid: 2043 } hitcount: 15
2429 { lat: 240, common_pid: 2040 } hitcount: 44
2430 { lat: 240, common_pid: 2039 } hitcount: 1
2431 { lat: 240, common_pid: 2041 } hitcount: 2
2432 { lat: 240, common_pid: 2038 } hitcount: 1
2433 { lat: 240, common_pid: 2036 } hitcount: 10
2434 { lat: 240, common_pid: 2042 } hitcount: 13
2435 { lat: 241, common_pid: 2036 } hitcount: 21
2436 { lat: 241, common_pid: 2041 } hitcount: 36
2437 { lat: 241, common_pid: 2037 } hitcount: 34
2438 { lat: 241, common_pid: 2042 } hitcount: 14
2439 { lat: 241, common_pid: 2040 } hitcount: 94
2440 { lat: 241, common_pid: 2039 } hitcount: 12
2441 { lat: 241, common_pid: 2038 } hitcount: 2
2442 { lat: 241, common_pid: 2043 } hitcount: 28
2443 { lat: 242, common_pid: 2040 } hitcount: 109
2444 { lat: 242, common_pid: 2041 } hitcount: 506
2445 { lat: 242, common_pid: 2039 } hitcount: 155
2446 { lat: 242, common_pid: 2042 } hitcount: 21
2447 { lat: 242, common_pid: 2037 } hitcount: 52
2448 { lat: 242, common_pid: 2043 } hitcount: 21
2449 { lat: 242, common_pid: 2036 } hitcount: 16
2450 { lat: 242, common_pid: 2038 } hitcount: 156
2451 { lat: 243, common_pid: 2037 } hitcount: 46
2452 { lat: 243, common_pid: 2039 } hitcount: 40
2453 { lat: 243, common_pid: 2042 } hitcount: 119
2454 { lat: 243, common_pid: 2041 } hitcount: 611
2455 { lat: 243, common_pid: 2036 } hitcount: 69
2456 { lat: 243, common_pid: 2038 } hitcount: 784
2457 { lat: 243, common_pid: 2040 } hitcount: 323
2458 { lat: 243, common_pid: 2043 } hitcount: 14
2459 { lat: 244, common_pid: 2043 } hitcount: 35
2460 { lat: 244, common_pid: 2042 } hitcount: 305
2461 { lat: 244, common_pid: 2039 } hitcount: 8
2462 { lat: 244, common_pid: 2040 } hitcount: 4515
2463 { lat: 244, common_pid: 2038 } hitcount: 371
2464 { lat: 244, common_pid: 2037 } hitcount: 31
2465 { lat: 244, common_pid: 2036 } hitcount: 114
2466 { lat: 244, common_pid: 2041 } hitcount: 3396
2467 { lat: 245, common_pid: 2036 } hitcount: 700
2468 { lat: 245, common_pid: 2041 } hitcount: 2772
2469 { lat: 245, common_pid: 2037 } hitcount: 268
2470 { lat: 245, common_pid: 2039 } hitcount: 472
2471 { lat: 245, common_pid: 2038 } hitcount: 2758
2472 { lat: 245, common_pid: 2042 } hitcount: 3833
2473 { lat: 245, common_pid: 2040 } hitcount: 3105
2474 { lat: 245, common_pid: 2043 } hitcount: 645
2475 { lat: 246, common_pid: 2038 } hitcount: 3451
2476 { lat: 246, common_pid: 2041 } hitcount: 142
2477 { lat: 246, common_pid: 2037 } hitcount: 5101
2478 { lat: 246, common_pid: 2040 } hitcount: 68
2479 { lat: 246, common_pid: 2043 } hitcount: 5099
2480 { lat: 246, common_pid: 2039 } hitcount: 5608
2481 { lat: 246, common_pid: 2042 } hitcount: 3723
2482 { lat: 246, common_pid: 2036 } hitcount: 4738
2483 { lat: 247, common_pid: 2042 } hitcount: 312
2484 { lat: 247, common_pid: 2043 } hitcount: 2385
2485 { lat: 247, common_pid: 2041 } hitcount: 452
2486 { lat: 247, common_pid: 2038 } hitcount: 792
2487 { lat: 247, common_pid: 2040 } hitcount: 78
2488 { lat: 247, common_pid: 2036 } hitcount: 2375
2489 { lat: 247, common_pid: 2039 } hitcount: 1834
2490 { lat: 247, common_pid: 2037 } hitcount: 2655
2491 { lat: 248, common_pid: 2037 } hitcount: 36
2492 { lat: 248, common_pid: 2042 } hitcount: 11
2493 { lat: 248, common_pid: 2038 } hitcount: 122
2494 { lat: 248, common_pid: 2036 } hitcount: 135
2495 { lat: 248, common_pid: 2039 } hitcount: 26
2496 { lat: 248, common_pid: 2041 } hitcount: 503
2497 { lat: 248, common_pid: 2043 } hitcount: 66
2498 { lat: 248, common_pid: 2040 } hitcount: 46
2499 { lat: 249, common_pid: 2037 } hitcount: 29
2500 { lat: 249, common_pid: 2038 } hitcount: 1
2501 { lat: 249, common_pid: 2043 } hitcount: 29
2502 { lat: 249, common_pid: 2039 } hitcount: 8
2503 { lat: 249, common_pid: 2042 } hitcount: 56
2504 { lat: 249, common_pid: 2040 } hitcount: 27
2505 { lat: 249, common_pid: 2041 } hitcount: 11
2506 { lat: 249, common_pid: 2036 } hitcount: 27
2507 { lat: 250, common_pid: 2038 } hitcount: 1
2508 { lat: 250, common_pid: 2036 } hitcount: 30
2509 { lat: 250, common_pid: 2040 } hitcount: 19
2510 { lat: 250, common_pid: 2043 } hitcount: 22
2511 { lat: 250, common_pid: 2042 } hitcount: 20
2512 { lat: 250, common_pid: 2041 } hitcount: 1
2513 { lat: 250, common_pid: 2039 } hitcount: 6
2514 { lat: 250, common_pid: 2037 } hitcount: 48
2515 { lat: 251, common_pid: 2037 } hitcount: 43
2516 { lat: 251, common_pid: 2039 } hitcount: 1
2517 { lat: 251, common_pid: 2036 } hitcount: 12
2518 { lat: 251, common_pid: 2042 } hitcount: 2
2519 { lat: 251, common_pid: 2041 } hitcount: 1
2520 { lat: 251, common_pid: 2043 } hitcount: 15
2521 { lat: 251, common_pid: 2040 } hitcount: 3
2522 { lat: 252, common_pid: 2040 } hitcount: 1
2523 { lat: 252, common_pid: 2036 } hitcount: 12
2524 { lat: 252, common_pid: 2037 } hitcount: 21
2525 { lat: 252, common_pid: 2043 } hitcount: 14
2526 { lat: 253, common_pid: 2037 } hitcount: 21
2527 { lat: 253, common_pid: 2039 } hitcount: 2
2528 { lat: 253, common_pid: 2036 } hitcount: 9
2529 { lat: 253, common_pid: 2043 } hitcount: 6
2530 { lat: 253, common_pid: 2040 } hitcount: 1
2531 { lat: 254, common_pid: 2036 } hitcount: 8
2532 { lat: 254, common_pid: 2043 } hitcount: 3
2533 { lat: 254, common_pid: 2041 } hitcount: 1
2534 { lat: 254, common_pid: 2042 } hitcount: 1
2535 { lat: 254, common_pid: 2039 } hitcount: 1
2536 { lat: 254, common_pid: 2037 } hitcount: 12
2537 { lat: 255, common_pid: 2043 } hitcount: 1
2538 { lat: 255, common_pid: 2037 } hitcount: 2
2539 { lat: 255, common_pid: 2036 } hitcount: 2
2540 { lat: 255, common_pid: 2039 } hitcount: 8
2541 { lat: 256, common_pid: 2043 } hitcount: 1
2542 { lat: 256, common_pid: 2036 } hitcount: 4
2543 { lat: 256, common_pid: 2039 } hitcount: 6
2544 { lat: 257, common_pid: 2039 } hitcount: 5
2545 { lat: 257, common_pid: 2036 } hitcount: 4
2546 { lat: 258, common_pid: 2039 } hitcount: 5
2547 { lat: 258, common_pid: 2036 } hitcount: 2
2548 { lat: 259, common_pid: 2036 } hitcount: 7
2549 { lat: 259, common_pid: 2039 } hitcount: 7
2550 { lat: 260, common_pid: 2036 } hitcount: 8
2551 { lat: 260, common_pid: 2039 } hitcount: 6
2552 { lat: 261, common_pid: 2036 } hitcount: 5
2553 { lat: 261, common_pid: 2039 } hitcount: 7
2554 { lat: 262, common_pid: 2039 } hitcount: 5
2555 { lat: 262, common_pid: 2036 } hitcount: 5
2556 { lat: 263, common_pid: 2039 } hitcount: 7
2557 { lat: 263, common_pid: 2036 } hitcount: 7
2558 { lat: 264, common_pid: 2039 } hitcount: 9
2559 { lat: 264, common_pid: 2036 } hitcount: 9
2560 { lat: 265, common_pid: 2036 } hitcount: 5
2561 { lat: 265, common_pid: 2039 } hitcount: 1
2562 { lat: 266, common_pid: 2036 } hitcount: 1
2563 { lat: 266, common_pid: 2039 } hitcount: 3
2564 { lat: 267, common_pid: 2036 } hitcount: 1
2565 { lat: 267, common_pid: 2039 } hitcount: 3
2566 { lat: 268, common_pid: 2036 } hitcount: 1
2567 { lat: 268, common_pid: 2039 } hitcount: 6
2568 { lat: 269, common_pid: 2036 } hitcount: 1
2569 { lat: 269, common_pid: 2043 } hitcount: 1
2570 { lat: 269, common_pid: 2039 } hitcount: 2
2571 { lat: 270, common_pid: 2040 } hitcount: 1
2572 { lat: 270, common_pid: 2039 } hitcount: 6
2573 { lat: 271, common_pid: 2041 } hitcount: 1
2574 { lat: 271, common_pid: 2039 } hitcount: 5
2575 { lat: 272, common_pid: 2039 } hitcount: 10
2576 { lat: 273, common_pid: 2039 } hitcount: 8
2577 { lat: 274, common_pid: 2039 } hitcount: 2
2578 { lat: 275, common_pid: 2039 } hitcount: 1
2579 { lat: 276, common_pid: 2039 } hitcount: 2
2580 { lat: 276, common_pid: 2037 } hitcount: 1
2581 { lat: 276, common_pid: 2038 } hitcount: 1
2582 { lat: 277, common_pid: 2039 } hitcount: 1
2583 { lat: 277, common_pid: 2042 } hitcount: 1
2584 { lat: 278, common_pid: 2039 } hitcount: 1
2585 { lat: 279, common_pid: 2039 } hitcount: 4
2586 { lat: 279, common_pid: 2043 } hitcount: 1
2587 { lat: 280, common_pid: 2039 } hitcount: 3
2588 { lat: 283, common_pid: 2036 } hitcount: 2
2589 { lat: 284, common_pid: 2039 } hitcount: 1
2590 { lat: 284, common_pid: 2043 } hitcount: 1
2591 { lat: 288, common_pid: 2039 } hitcount: 1
2592 { lat: 289, common_pid: 2039 } hitcount: 1
2593 { lat: 300, common_pid: 2039 } hitcount: 1
2594 { lat: 384, common_pid: 2039 } hitcount: 1
2596 Totals:
2597 Hits: 67625
2598 Entries: 278
2599 Dropped: 0
2601 Note, the writes are around the sleep, so ideally they will all be of 250
2602 microseconds. If you are wondering how there are several that are under
2603 250 microseconds, that is because the way cyclictest works, is if one
2604 iteration comes in late, the next one will set the timer to wake up less that
2605 250. That is, if an iteration came in 50 microseconds late, the next wake up
2606 will be at 200 microseconds.
2608 But this could easily be done in userspace. To make this even more
2609 interesting, we can mix the histogram between events that happened in the
2610 kernel with trace_marker::
2612 # cd /sys/kernel/tracing
2613 # echo 'latency u64 lat' > synthetic_events
2614 # echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
2615 # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat) if buf == "end"' > events/ftrace/print/trigger
2616 # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
2618 The difference this time is that instead of using the trace_marker to start
2619 the latency, the sched_waking event is used, matching the common_pid for the
2620 trace_marker write with the pid that is being woken by sched_waking.
2622 After running cyclictest again with the same parameters, we now have::
2624 # cat events/synthetic/latency/hist
2625 # event histogram
2626 #
2627 # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
2628 #
2630 { lat: 7, common_pid: 2302 } hitcount: 640
2631 { lat: 7, common_pid: 2299 } hitcount: 42
2632 { lat: 7, common_pid: 2303 } hitcount: 18
2633 { lat: 7, common_pid: 2305 } hitcount: 166
2634 { lat: 7, common_pid: 2306 } hitcount: 1
2635 { lat: 7, common_pid: 2301 } hitcount: 91
2636 { lat: 7, common_pid: 2300 } hitcount: 17
2637 { lat: 8, common_pid: 2303 } hitcount: 8296
2638 { lat: 8, common_pid: 2304 } hitcount: 6864
2639 { lat: 8, common_pid: 2305 } hitcount: 9464
2640 { lat: 8, common_pid: 2301 } hitcount: 9213
2641 { lat: 8, common_pid: 2306 } hitcount: 6246
2642 { lat: 8, common_pid: 2302 } hitcount: 8797
2643 { lat: 8, common_pid: 2299 } hitcount: 8771
2644 { lat: 8, common_pid: 2300 } hitcount: 8119
2645 { lat: 9, common_pid: 2305 } hitcount: 1519
2646 { lat: 9, common_pid: 2299 } hitcount: 2346
2647 { lat: 9, common_pid: 2303 } hitcount: 2841
2648 { lat: 9, common_pid: 2301 } hitcount: 1846
2649 { lat: 9, common_pid: 2304 } hitcount: 3861
2650 { lat: 9, common_pid: 2302 } hitcount: 1210
2651 { lat: 9, common_pid: 2300 } hitcount: 2762
2652 { lat: 9, common_pid: 2306 } hitcount: 4247
2653 { lat: 10, common_pid: 2299 } hitcount: 16
2654 { lat: 10, common_pid: 2306 } hitcount: 333
2655 { lat: 10, common_pid: 2303 } hitcount: 16
2656 { lat: 10, common_pid: 2304 } hitcount: 168
2657 { lat: 10, common_pid: 2302 } hitcount: 240
2658 { lat: 10, common_pid: 2301 } hitcount: 28
2659 { lat: 10, common_pid: 2300 } hitcount: 95
2660 { lat: 10, common_pid: 2305 } hitcount: 18
2661 { lat: 11, common_pid: 2303 } hitcount: 5
2662 { lat: 11, common_pid: 2305 } hitcount: 8
2663 { lat: 11, common_pid: 2306 } hitcount: 221
2664 { lat: 11, common_pid: 2302 } hitcount: 76
2665 { lat: 11, common_pid: 2304 } hitcount: 26
2666 { lat: 11, common_pid: 2300 } hitcount: 125
2667 { lat: 11, common_pid: 2299 } hitcount: 2
2668 { lat: 12, common_pid: 2305 } hitcount: 3
2669 { lat: 12, common_pid: 2300 } hitcount: 6
2670 { lat: 12, common_pid: 2306 } hitcount: 90
2671 { lat: 12, common_pid: 2302 } hitcount: 4
2672 { lat: 12, common_pid: 2303 } hitcount: 1
2673 { lat: 12, common_pid: 2304 } hitcount: 122
2674 { lat: 13, common_pid: 2300 } hitcount: 12
2675 { lat: 13, common_pid: 2301 } hitcount: 1
2676 { lat: 13, common_pid: 2306 } hitcount: 32
2677 { lat: 13, common_pid: 2302 } hitcount: 5
2678 { lat: 13, common_pid: 2305 } hitcount: 1
2679 { lat: 13, common_pid: 2303 } hitcount: 1
2680 { lat: 13, common_pid: 2304 } hitcount: 61
2681 { lat: 14, common_pid: 2303 } hitcount: 4
2682 { lat: 14, common_pid: 2306 } hitcount: 5
2683 { lat: 14, common_pid: 2305 } hitcount: 4
2684 { lat: 14, common_pid: 2304 } hitcount: 62
2685 { lat: 14, common_pid: 2302 } hitcount: 19
2686 { lat: 14, common_pid: 2300 } hitcount: 33
2687 { lat: 14, common_pid: 2299 } hitcount: 1
2688 { lat: 14, common_pid: 2301 } hitcount: 4
2689 { lat: 15, common_pid: 2305 } hitcount: 1
2690 { lat: 15, common_pid: 2302 } hitcount: 25
2691 { lat: 15, common_pid: 2300 } hitcount: 11
2692 { lat: 15, common_pid: 2299 } hitcount: 5
2693 { lat: 15, common_pid: 2301 } hitcount: 1
2694 { lat: 15, common_pid: 2304 } hitcount: 8
2695 { lat: 15, common_pid: 2303 } hitcount: 1
2696 { lat: 15, common_pid: 2306 } hitcount: 6
2697 { lat: 16, common_pid: 2302 } hitcount: 31
2698 { lat: 16, common_pid: 2306 } hitcount: 3
2699 { lat: 16, common_pid: 2300 } hitcount: 5
2700 { lat: 17, common_pid: 2302 } hitcount: 6
2701 { lat: 17, common_pid: 2303 } hitcount: 1
2702 { lat: 18, common_pid: 2304 } hitcount: 1
2703 { lat: 18, common_pid: 2302 } hitcount: 8
2704 { lat: 18, common_pid: 2299 } hitcount: 1
2705 { lat: 18, common_pid: 2301 } hitcount: 1
2706 { lat: 19, common_pid: 2303 } hitcount: 4
2707 { lat: 19, common_pid: 2304 } hitcount: 5
2708 { lat: 19, common_pid: 2302 } hitcount: 4
2709 { lat: 19, common_pid: 2299 } hitcount: 3
2710 { lat: 19, common_pid: 2306 } hitcount: 1
2711 { lat: 19, common_pid: 2300 } hitcount: 4
2712 { lat: 19, common_pid: 2305 } hitcount: 5
2713 { lat: 20, common_pid: 2299 } hitcount: 2
2714 { lat: 20, common_pid: 2302 } hitcount: 3
2715 { lat: 20, common_pid: 2305 } hitcount: 1
2716 { lat: 20, common_pid: 2300 } hitcount: 2
2717 { lat: 20, common_pid: 2301 } hitcount: 2
2718 { lat: 20, common_pid: 2303 } hitcount: 3
2719 { lat: 21, common_pid: 2305 } hitcount: 1
2720 { lat: 21, common_pid: 2299 } hitcount: 5
2721 { lat: 21, common_pid: 2303 } hitcount: 4
2722 { lat: 21, common_pid: 2302 } hitcount: 7
2723 { lat: 21, common_pid: 2300 } hitcount: 1
2724 { lat: 21, common_pid: 2301 } hitcount: 5
2725 { lat: 21, common_pid: 2304 } hitcount: 2
2726 { lat: 22, common_pid: 2302 } hitcount: 5
2727 { lat: 22, common_pid: 2303 } hitcount: 1
2728 { lat: 22, common_pid: 2306 } hitcount: 3
2729 { lat: 22, common_pid: 2301 } hitcount: 2
2730 { lat: 22, common_pid: 2300 } hitcount: 1
2731 { lat: 22, common_pid: 2299 } hitcount: 1
2732 { lat: 22, common_pid: 2305 } hitcount: 1
2733 { lat: 22, common_pid: 2304 } hitcount: 1
2734 { lat: 23, common_pid: 2299 } hitcount: 1
2735 { lat: 23, common_pid: 2306 } hitcount: 2
2736 { lat: 23, common_pid: 2302 } hitcount: 6
2737 { lat: 24, common_pid: 2302 } hitcount: 3
2738 { lat: 24, common_pid: 2300 } hitcount: 1
2739 { lat: 24, common_pid: 2306 } hitcount: 2
2740 { lat: 24, common_pid: 2305 } hitcount: 1
2741 { lat: 24, common_pid: 2299 } hitcount: 1
2742 { lat: 25, common_pid: 2300 } hitcount: 1
2743 { lat: 25, common_pid: 2302 } hitcount: 4
2744 { lat: 26, common_pid: 2302 } hitcount: 2
2745 { lat: 27, common_pid: 2305 } hitcount: 1
2746 { lat: 27, common_pid: 2300 } hitcount: 1
2747 { lat: 27, common_pid: 2302 } hitcount: 3
2748 { lat: 28, common_pid: 2306 } hitcount: 1
2749 { lat: 28, common_pid: 2302 } hitcount: 4
2750 { lat: 29, common_pid: 2302 } hitcount: 1
2751 { lat: 29, common_pid: 2300 } hitcount: 2
2752 { lat: 29, common_pid: 2306 } hitcount: 1
2753 { lat: 29, common_pid: 2304 } hitcount: 1
2754 { lat: 30, common_pid: 2302 } hitcount: 4
2755 { lat: 31, common_pid: 2302 } hitcount: 6
2756 { lat: 32, common_pid: 2302 } hitcount: 1
2757 { lat: 33, common_pid: 2299 } hitcount: 1
2758 { lat: 33, common_pid: 2302 } hitcount: 3
2759 { lat: 34, common_pid: 2302 } hitcount: 2
2760 { lat: 35, common_pid: 2302 } hitcount: 1
2761 { lat: 35, common_pid: 2304 } hitcount: 1
2762 { lat: 36, common_pid: 2302 } hitcount: 4
2763 { lat: 37, common_pid: 2302 } hitcount: 6
2764 { lat: 38, common_pid: 2302 } hitcount: 2
2765 { lat: 39, common_pid: 2302 } hitcount: 2
2766 { lat: 39, common_pid: 2304 } hitcount: 1
2767 { lat: 40, common_pid: 2304 } hitcount: 2
2768 { lat: 40, common_pid: 2302 } hitcount: 5
2769 { lat: 41, common_pid: 2304 } hitcount: 1
2770 { lat: 41, common_pid: 2302 } hitcount: 8
2771 { lat: 42, common_pid: 2302 } hitcount: 6
2772 { lat: 42, common_pid: 2304 } hitcount: 1
2773 { lat: 43, common_pid: 2302 } hitcount: 3
2774 { lat: 43, common_pid: 2304 } hitcount: 4
2775 { lat: 44, common_pid: 2302 } hitcount: 6
2776 { lat: 45, common_pid: 2302 } hitcount: 5
2777 { lat: 46, common_pid: 2302 } hitcount: 5
2778 { lat: 47, common_pid: 2302 } hitcount: 7
2779 { lat: 48, common_pid: 2301 } hitcount: 1
2780 { lat: 48, common_pid: 2302 } hitcount: 9
2781 { lat: 49, common_pid: 2302 } hitcount: 3
2782 { lat: 50, common_pid: 2302 } hitcount: 1
2783 { lat: 50, common_pid: 2301 } hitcount: 1
2784 { lat: 51, common_pid: 2302 } hitcount: 2
2785 { lat: 51, common_pid: 2301 } hitcount: 1
2786 { lat: 61, common_pid: 2302 } hitcount: 1
2787 { lat: 110, common_pid: 2302 } hitcount: 1
2789 Totals:
2790 Hits: 89565
2791 Entries: 158
2792 Dropped: 0
2794 This doesn't tell us any information about how late cyclictest may have
2795 woken up, but it does show us a nice histogram of how long it took from
2796 the time that cyclictest was woken to the time it made it into user space.