| blob | b71e09f745c3dae4511c36beb8ccf290f5f01c3e |
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 kernel_clone+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 kernel_clone+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 See synth_field_size() for available types.
1781 If field_name contains [n], the field is considered to be a static array.
1783 If field_names contains[] (no subscript), the field is considered to
1784 be a dynamic array, which will only take as much space in the event as
1785 is required to hold the array.
1787 A string field can be specified using either the static notation:
1789 char name[32];
1791 Or the dynamic:
1793 char name[];
1795 The size limit for either is 256.
1797 For instance, the following creates a new event named 'wakeup_latency'
1798 with 3 fields: lat, pid, and prio. Each of those fields is simply a
1799 variable reference to a variable on another event::
1801 # echo 'wakeup_latency \
1802 u64 lat; \
1803 pid_t pid; \
1804 int prio' >> \
1805 /sys/kernel/debug/tracing/synthetic_events
1807 Reading the tracing/synthetic_events file lists all the currently
1808 defined synthetic events, in this case the event defined above::
1810 # cat /sys/kernel/debug/tracing/synthetic_events
1811 wakeup_latency u64 lat; pid_t pid; int prio
1813 An existing synthetic event definition can be removed by prepending
1814 the command that defined it with a '!'::
1816 # echo '!wakeup_latency u64 lat pid_t pid int prio' >> \
1817 /sys/kernel/debug/tracing/synthetic_events
1819 At this point, there isn't yet an actual 'wakeup_latency' event
1820 instantiated in the event subsystem - for this to happen, a 'hist
1821 trigger action' needs to be instantiated and bound to actual fields
1822 and variables defined on other events (see Section 2.2.3 below on
1823 how that is done using hist trigger 'onmatch' action). Once that is
1824 done, the 'wakeup_latency' synthetic event instance is created.
1826 A histogram can now be defined for the new synthetic event::
1828 # echo 'hist:keys=pid,prio,lat.log2:sort=pid,lat' >> \
1829 /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
1831 The new event is created under the tracing/events/synthetic/ directory
1832 and looks and behaves just like any other event::
1834 # ls /sys/kernel/debug/tracing/events/synthetic/wakeup_latency
1835 enable filter format hist id trigger
1837 Like any other event, once a histogram is enabled for the event, the
1838 output can be displayed by reading the event's 'hist' file.
1840 2.2.3 Hist trigger 'handlers' and 'actions'
1841 -------------------------------------------
1843 A hist trigger 'action' is a function that's executed (in most cases
1844 conditionally) whenever a histogram entry is added or updated.
1846 When a histogram entry is added or updated, a hist trigger 'handler'
1847 is what decides whether the corresponding action is actually invoked
1848 or not.
1850 Hist trigger handlers and actions are paired together in the general
1851 form:
1853 <handler>.<action>
1855 To specify a handler.action pair for a given event, simply specify
1856 that handler.action pair between colons in the hist trigger
1857 specification.
1859 In theory, any handler can be combined with any action, but in
1860 practice, not every handler.action combination is currently supported;
1861 if a given handler.action combination isn't supported, the hist
1862 trigger will fail with -EINVAL;
1864 The default 'handler.action' if none is explicitly specified is as it
1865 always has been, to simply update the set of values associated with an
1866 entry. Some applications, however, may want to perform additional
1867 actions at that point, such as generate another event, or compare and
1868 save a maximum.
1870 The supported handlers and actions are listed below, and each is
1871 described in more detail in the following paragraphs, in the context
1872 of descriptions of some common and useful handler.action combinations.
1874 The available handlers are:
1876 - onmatch(matching.event) - invoke action on any addition or update
1877 - onmax(var) - invoke action if var exceeds current max
1878 - onchange(var) - invoke action if var changes
1880 The available actions are:
1882 - trace(<synthetic_event_name>,param list) - generate synthetic event
1883 - save(field,...) - save current event fields
1884 - snapshot() - snapshot the trace buffer
1886 The following commonly-used handler.action pairs are available:
1888 - onmatch(matching.event).trace(<synthetic_event_name>,param list)
1890 The 'onmatch(matching.event).trace(<synthetic_event_name>,param
1891 list)' hist trigger action is invoked whenever an event matches
1892 and the histogram entry would be added or updated. It causes the
1893 named synthetic event to be generated with the values given in the
1894 'param list'. The result is the generation of a synthetic event
1895 that consists of the values contained in those variables at the
1896 time the invoking event was hit. For example, if the synthetic
1897 event name is 'wakeup_latency', a wakeup_latency event is
1898 generated using onmatch(event).trace(wakeup_latency,arg1,arg2).
1900 There is also an equivalent alternative form available for
1901 generating synthetic events. In this form, the synthetic event
1902 name is used as if it were a function name. For example, using
1903 the 'wakeup_latency' synthetic event name again, the
1904 wakeup_latency event would be generated by invoking it as if it
1905 were a function call, with the event field values passed in as
1906 arguments: onmatch(event).wakeup_latency(arg1,arg2). The syntax
1907 for this form is:
1909 onmatch(matching.event).<synthetic_event_name>(param list)
1911 In either case, the 'param list' consists of one or more
1912 parameters which may be either variables or fields defined on
1913 either the 'matching.event' or the target event. The variables or
1914 fields specified in the param list may be either fully-qualified
1915 or unqualified. If a variable is specified as unqualified, it
1916 must be unique between the two events. A field name used as a
1917 param can be unqualified if it refers to the target event, but
1918 must be fully qualified if it refers to the matching event. A
1919 fully-qualified name is of the form 'system.event_name.$var_name'
1920 or 'system.event_name.field'.
1922 The 'matching.event' specification is simply the fully qualified
1923 event name of the event that matches the target event for the
1924 onmatch() functionality, in the form 'system.event_name'. Histogram
1925 keys of both events are compared to find if events match. In case
1926 multiple histogram keys are used, they all must match in the specified
1927 order.
1929 Finally, the number and type of variables/fields in the 'param
1930 list' must match the number and types of the fields in the
1931 synthetic event being generated.
1933 As an example the below defines a simple synthetic event and uses
1934 a variable defined on the sched_wakeup_new event as a parameter
1935 when invoking the synthetic event. Here we define the synthetic
1936 event::
1938 # echo 'wakeup_new_test pid_t pid' >> \
1939 /sys/kernel/debug/tracing/synthetic_events
1941 # cat /sys/kernel/debug/tracing/synthetic_events
1942 wakeup_new_test pid_t pid
1944 The following hist trigger both defines the missing testpid
1945 variable and specifies an onmatch() action that generates a
1946 wakeup_new_test synthetic event whenever a sched_wakeup_new event
1947 occurs, which because of the 'if comm == "cyclictest"' filter only
1948 happens when the executable is cyclictest::
1950 # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\
1951 wakeup_new_test($testpid) if comm=="cyclictest"' >> \
1952 /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger
1954 Or, equivalently, using the 'trace' keyword syntax:
1956 # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\
1957 trace(wakeup_new_test,$testpid) if comm=="cyclictest"' >> \
1958 /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger
1960 Creating and displaying a histogram based on those events is now
1961 just a matter of using the fields and new synthetic event in the
1962 tracing/events/synthetic directory, as usual::
1964 # echo 'hist:keys=pid:sort=pid' >> \
1965 /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/trigger
1967 Running 'cyclictest' should cause wakeup_new events to generate
1968 wakeup_new_test synthetic events which should result in histogram
1969 output in the wakeup_new_test event's hist file::
1971 # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/hist
1973 A more typical usage would be to use two events to calculate a
1974 latency. The following example uses a set of hist triggers to
1975 produce a 'wakeup_latency' histogram.
1977 First, we define a 'wakeup_latency' synthetic event::
1979 # echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> \
1980 /sys/kernel/debug/tracing/synthetic_events
1982 Next, we specify that whenever we see a sched_waking event for a
1983 cyclictest thread, save the timestamp in a 'ts0' variable::
1985 # echo 'hist:keys=$saved_pid:saved_pid=pid:ts0=common_timestamp.usecs \
1986 if comm=="cyclictest"' >> \
1987 /sys/kernel/debug/tracing/events/sched/sched_waking/trigger
1989 Then, when the corresponding thread is actually scheduled onto the
1990 CPU by a sched_switch event (saved_pid matches next_pid), calculate
1991 the latency and use that along with another variable and an event field
1992 to generate a wakeup_latency synthetic event::
1994 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\
1995 onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,\
1996 $saved_pid,next_prio) if next_comm=="cyclictest"' >> \
1997 /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
1999 We also need to create a histogram on the wakeup_latency synthetic
2000 event in order to aggregate the generated synthetic event data::
2002 # echo 'hist:keys=pid,prio,lat:sort=pid,lat' >> \
2003 /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger
2005 Finally, once we've run cyclictest to actually generate some
2006 events, we can see the output by looking at the wakeup_latency
2007 synthetic event's hist file::
2009 # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist
2011 - onmax(var).save(field,.. .)
2013 The 'onmax(var).save(field,...)' hist trigger action is invoked
2014 whenever the value of 'var' associated with a histogram entry
2015 exceeds the current maximum contained in that variable.
2017 The end result is that the trace event fields specified as the
2018 onmax.save() params will be saved if 'var' exceeds the current
2019 maximum for that hist trigger entry. This allows context from the
2020 event that exhibited the new maximum to be saved for later
2021 reference. When the histogram is displayed, additional fields
2022 displaying the saved values will be printed.
2024 As an example the below defines a couple of hist triggers, one for
2025 sched_waking and another for sched_switch, keyed on pid. Whenever
2026 a sched_waking occurs, the timestamp is saved in the entry
2027 corresponding to the current pid, and when the scheduler switches
2028 back to that pid, the timestamp difference is calculated. If the
2029 resulting latency, stored in wakeup_lat, exceeds the current
2030 maximum latency, the values specified in the save() fields are
2031 recorded::
2033 # echo 'hist:keys=pid:ts0=common_timestamp.usecs \
2034 if comm=="cyclictest"' >> \
2035 /sys/kernel/debug/tracing/events/sched/sched_waking/trigger
2037 # echo 'hist:keys=next_pid:\
2038 wakeup_lat=common_timestamp.usecs-$ts0:\
2039 onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) \
2040 if next_comm=="cyclictest"' >> \
2041 /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
2043 When the histogram is displayed, the max value and the saved
2044 values corresponding to the max are displayed following the rest
2045 of the fields::
2047 # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
2048 { next_pid: 2255 } hitcount: 239
2049 common_timestamp-ts0: 0
2050 max: 27
2051 next_comm: cyclictest
2052 prev_pid: 0 prev_prio: 120 prev_comm: swapper/1
2054 { next_pid: 2256 } hitcount: 2355
2055 common_timestamp-ts0: 0
2056 max: 49 next_comm: cyclictest
2057 prev_pid: 0 prev_prio: 120 prev_comm: swapper/0
2059 Totals:
2060 Hits: 12970
2061 Entries: 2
2062 Dropped: 0
2064 - onmax(var).snapshot()
2066 The 'onmax(var).snapshot()' hist trigger action is invoked
2067 whenever the value of 'var' associated with a histogram entry
2068 exceeds the current maximum contained in that variable.
2070 The end result is that a global snapshot of the trace buffer will
2071 be saved in the tracing/snapshot file if 'var' exceeds the current
2072 maximum for any hist trigger entry.
2074 Note that in this case the maximum is a global maximum for the
2075 current trace instance, which is the maximum across all buckets of
2076 the histogram. The key of the specific trace event that caused
2077 the global maximum and the global maximum itself are displayed,
2078 along with a message stating that a snapshot has been taken and
2079 where to find it. The user can use the key information displayed
2080 to locate the corresponding bucket in the histogram for even more
2081 detail.
2083 As an example the below defines a couple of hist triggers, one for
2084 sched_waking and another for sched_switch, keyed on pid. Whenever
2085 a sched_waking event occurs, the timestamp is saved in the entry
2086 corresponding to the current pid, and when the scheduler switches
2087 back to that pid, the timestamp difference is calculated. If the
2088 resulting latency, stored in wakeup_lat, exceeds the current
2089 maximum latency, a snapshot is taken. As part of the setup, all
2090 the scheduler events are also enabled, which are the events that
2091 will show up in the snapshot when it is taken at some point:
2093 # echo 1 > /sys/kernel/debug/tracing/events/sched/enable
2095 # echo 'hist:keys=pid:ts0=common_timestamp.usecs \
2096 if comm=="cyclictest"' >> \
2097 /sys/kernel/debug/tracing/events/sched/sched_waking/trigger
2099 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \
2100 onmax($wakeup_lat).save(next_prio,next_comm,prev_pid,prev_prio, \
2101 prev_comm):onmax($wakeup_lat).snapshot() \
2102 if next_comm=="cyclictest"' >> \
2103 /sys/kernel/debug/tracing/events/sched/sched_switch/trigger
2105 When the histogram is displayed, for each bucket the max value
2106 and the saved values corresponding to the max are displayed
2107 following the rest of the fields.
2109 If a snapshot was taken, there is also a message indicating that,
2110 along with the value and event that triggered the global maximum:
2112 # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist
2113 { next_pid: 2101 } hitcount: 200
2114 max: 52 next_prio: 120 next_comm: cyclictest \
2115 prev_pid: 0 prev_prio: 120 prev_comm: swapper/6
2117 { next_pid: 2103 } hitcount: 1326
2118 max: 572 next_prio: 19 next_comm: cyclictest \
2119 prev_pid: 0 prev_prio: 120 prev_comm: swapper/1
2121 { next_pid: 2102 } hitcount: 1982 \
2122 max: 74 next_prio: 19 next_comm: cyclictest \
2123 prev_pid: 0 prev_prio: 120 prev_comm: swapper/5
2125 Snapshot taken (see tracing/snapshot). Details:
2126 triggering value { onmax($wakeup_lat) }: 572 \
2127 triggered by event with key: { next_pid: 2103 }
2129 Totals:
2130 Hits: 3508
2131 Entries: 3
2132 Dropped: 0
2134 In the above case, the event that triggered the global maximum has
2135 the key with next_pid == 2103. If you look at the bucket that has
2136 2103 as the key, you'll find the additional values save()'d along
2137 with the local maximum for that bucket, which should be the same
2138 as the global maximum (since that was the same value that
2139 triggered the global snapshot).
2141 And finally, looking at the snapshot data should show at or near
2142 the end the event that triggered the snapshot (in this case you
2143 can verify the timestamps between the sched_waking and
2144 sched_switch events, which should match the time displayed in the
2145 global maximum)::
2147 # cat /sys/kernel/debug/tracing/snapshot
2149 <...>-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
2150 <idle>-0 [005] d.h3 309.873611: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005
2151 <idle>-0 [005] dNh4 309.873613: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005
2152 <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
2153 <...>-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
2154 <idle>-0 [005] d.h3 309.874624: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005
2155 <idle>-0 [005] dNh4 309.874626: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005
2156 <idle>-0 [005] dNh3 309.874628: sched_waking: comm=cyclictest pid=2103 prio=19 target_cpu=005
2157 <idle>-0 [005] dNh4 309.874630: sched_wakeup: comm=cyclictest pid=2103 prio=19 target_cpu=005
2158 <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
2159 <idle>-0 [004] d.h3 309.874757: sched_waking: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004
2160 <idle>-0 [004] dNh4 309.874762: sched_wakeup: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004
2161 <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
2162 gnome-terminal--1699 [004] d.h2 309.874941: sched_stat_runtime: comm=gnome-terminal- pid=1699 runtime=180706 [ns] vruntime=1126870572 [ns]
2163 <idle>-0 [003] d.s4 309.874956: sched_waking: comm=rcu_sched pid=9 prio=120 target_cpu=007
2164 <idle>-0 [003] d.s5 309.874960: sched_wake_idle_without_ipi: cpu=7
2165 <idle>-0 [003] d.s5 309.874961: sched_wakeup: comm=rcu_sched pid=9 prio=120 target_cpu=007
2166 <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
2167 rcu_sched-9 [007] d..3 309.874973: sched_stat_runtime: comm=rcu_sched pid=9 runtime=13646 [ns] vruntime=22531430286 [ns]
2168 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
2169 <...>-2102 [005] d..4 309.874994: sched_migrate_task: comm=cyclictest pid=2103 prio=19 orig_cpu=5 dest_cpu=1
2170 <...>-2102 [005] d..4 309.875185: sched_wake_idle_without_ipi: cpu=1
2171 <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
2173 - onchange(var).save(field,.. .)
2175 The 'onchange(var).save(field,...)' hist trigger action is invoked
2176 whenever the value of 'var' associated with a histogram entry
2177 changes.
2179 The end result is that the trace event fields specified as the
2180 onchange.save() params will be saved if 'var' changes for that
2181 hist trigger entry. This allows context from the event that
2182 changed the value to be saved for later reference. When the
2183 histogram is displayed, additional fields displaying the saved
2184 values will be printed.
2186 - onchange(var).snapshot()
2188 The 'onchange(var).snapshot()' hist trigger action is invoked
2189 whenever the value of 'var' associated with a histogram entry
2190 changes.
2192 The end result is that a global snapshot of the trace buffer will
2193 be saved in the tracing/snapshot file if 'var' changes for any
2194 hist trigger entry.
2196 Note that in this case the changed value is a global variable
2197 associated with current trace instance. The key of the specific
2198 trace event that caused the value to change and the global value
2199 itself are displayed, along with a message stating that a snapshot
2200 has been taken and where to find it. The user can use the key
2201 information displayed to locate the corresponding bucket in the
2202 histogram for even more detail.
2204 As an example the below defines a hist trigger on the tcp_probe
2205 event, keyed on dport. Whenever a tcp_probe event occurs, the
2206 cwnd field is checked against the current value stored in the
2207 $cwnd variable. If the value has changed, a snapshot is taken.
2208 As part of the setup, all the scheduler and tcp events are also
2209 enabled, which are the events that will show up in the snapshot
2210 when it is taken at some point:
2212 # echo 1 > /sys/kernel/debug/tracing/events/sched/enable
2213 # echo 1 > /sys/kernel/debug/tracing/events/tcp/enable
2215 # echo 'hist:keys=dport:cwnd=snd_cwnd: \
2216 onchange($cwnd).save(snd_wnd,srtt,rcv_wnd): \
2217 onchange($cwnd).snapshot()' >> \
2218 /sys/kernel/debug/tracing/events/tcp/tcp_probe/trigger
2220 When the histogram is displayed, for each bucket the tracked value
2221 and the saved values corresponding to that value are displayed
2222 following the rest of the fields.
2224 If a snapshot was taken, there is also a message indicating that,
2225 along with the value and event that triggered the snapshot::
2227 # cat /sys/kernel/debug/tracing/events/tcp/tcp_probe/hist
2229 { dport: 1521 } hitcount: 8
2230 changed: 10 snd_wnd: 35456 srtt: 154262 rcv_wnd: 42112
2232 { dport: 80 } hitcount: 23
2233 changed: 10 snd_wnd: 28960 srtt: 19604 rcv_wnd: 29312
2235 { dport: 9001 } hitcount: 172
2236 changed: 10 snd_wnd: 48384 srtt: 260444 rcv_wnd: 55168
2238 { dport: 443 } hitcount: 211
2239 changed: 10 snd_wnd: 26960 srtt: 17379 rcv_wnd: 28800
2241 Snapshot taken (see tracing/snapshot). Details::
2243 triggering value { onchange($cwnd) }: 10
2244 triggered by event with key: { dport: 80 }
2246 Totals:
2247 Hits: 414
2248 Entries: 4
2249 Dropped: 0
2251 In the above case, the event that triggered the snapshot has the
2252 key with dport == 80. If you look at the bucket that has 80 as
2253 the key, you'll find the additional values save()'d along with the
2254 changed value for that bucket, which should be the same as the
2255 global changed value (since that was the same value that triggered
2256 the global snapshot).
2258 And finally, looking at the snapshot data should show at or near
2259 the end the event that triggered the snapshot::
2261 # cat /sys/kernel/debug/tracing/snapshot
2263 gnome-shell-1261 [006] dN.3 49.823113: sched_stat_runtime: comm=gnome-shell pid=1261 runtime=49347 [ns] vruntime=1835730389 [ns]
2264 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
2265 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
2266 kworker/3:2-135 [003] d..3 49.823118: sched_stat_runtime: comm=kworker/3:2 pid=135 runtime=5339 [ns] vruntime=17815800388 [ns]
2267 kworker/6:2-387 [006] d..3 49.823120: sched_stat_runtime: comm=kworker/6:2 pid=387 runtime=9594 [ns] vruntime=14589605367 [ns]
2268 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
2269 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
2270 <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
2272 3. User space creating a trigger
2273 --------------------------------
2275 Writing into /sys/kernel/tracing/trace_marker writes into the ftrace
2276 ring buffer. This can also act like an event, by writing into the trigger
2277 file located in /sys/kernel/tracing/events/ftrace/print/
2279 Modifying cyclictest to write into the trace_marker file before it sleeps
2280 and after it wakes up, something like this::
2282 static void traceputs(char *str)
2283 {
2284 /* tracemark_fd is the trace_marker file descriptor */
2285 if (tracemark_fd < 0)
2286 return;
2287 /* write the tracemark message */
2288 write(tracemark_fd, str, strlen(str));
2289 }
2291 And later add something like::
2293 traceputs("start");
2294 clock_nanosleep(...);
2295 traceputs("end");
2297 We can make a histogram from this::
2299 # cd /sys/kernel/tracing
2300 # echo 'latency u64 lat' > synthetic_events
2301 # echo 'hist:keys=common_pid:ts0=common_timestamp.usecs if buf == "start"' > events/ftrace/print/trigger
2302 # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) if buf == "end"' >> events/ftrace/print/trigger
2303 # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
2305 The above created a synthetic event called "latency" and two histograms
2306 against the trace_marker, one gets triggered when "start" is written into the
2307 trace_marker file and the other when "end" is written. If the pids match, then
2308 it will call the "latency" synthetic event with the calculated latency as its
2309 parameter. Finally, a histogram is added to the latency synthetic event to
2310 record the calculated latency along with the pid.
2312 Now running cyclictest with::
2314 # ./cyclictest -p80 -d0 -i250 -n -a -t --tracemark -b 1000
2316 -p80 : run threads at priority 80
2317 -d0 : have all threads run at the same interval
2318 -i250 : start the interval at 250 microseconds (all threads will do this)
2319 -n : sleep with nanosleep
2320 -a : affine all threads to a separate CPU
2321 -t : one thread per available CPU
2322 --tracemark : enable trace mark writing
2323 -b 1000 : stop if any latency is greater than 1000 microseconds
2325 Note, the -b 1000 is used just to make --tracemark available.
2327 Then we can see the histogram created by this with::
2329 # cat events/synthetic/latency/hist
2330 # event histogram
2331 #
2332 # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
2333 #
2335 { lat: 107, common_pid: 2039 } hitcount: 1
2336 { lat: 122, common_pid: 2041 } hitcount: 1
2337 { lat: 166, common_pid: 2039 } hitcount: 1
2338 { lat: 174, common_pid: 2039 } hitcount: 1
2339 { lat: 194, common_pid: 2041 } hitcount: 1
2340 { lat: 196, common_pid: 2036 } hitcount: 1
2341 { lat: 197, common_pid: 2038 } hitcount: 1
2342 { lat: 198, common_pid: 2039 } hitcount: 1
2343 { lat: 199, common_pid: 2039 } hitcount: 1
2344 { lat: 200, common_pid: 2041 } hitcount: 1
2345 { lat: 201, common_pid: 2039 } hitcount: 2
2346 { lat: 202, common_pid: 2038 } hitcount: 1
2347 { lat: 202, common_pid: 2043 } hitcount: 1
2348 { lat: 203, common_pid: 2039 } hitcount: 1
2349 { lat: 203, common_pid: 2036 } hitcount: 1
2350 { lat: 203, common_pid: 2041 } hitcount: 1
2351 { lat: 206, common_pid: 2038 } hitcount: 2
2352 { lat: 207, common_pid: 2039 } hitcount: 1
2353 { lat: 207, common_pid: 2036 } hitcount: 1
2354 { lat: 208, common_pid: 2040 } hitcount: 1
2355 { lat: 209, common_pid: 2043 } hitcount: 1
2356 { lat: 210, common_pid: 2039 } hitcount: 1
2357 { lat: 211, common_pid: 2039 } hitcount: 4
2358 { lat: 212, common_pid: 2043 } hitcount: 1
2359 { lat: 212, common_pid: 2039 } hitcount: 2
2360 { lat: 213, common_pid: 2039 } hitcount: 1
2361 { lat: 214, common_pid: 2038 } hitcount: 1
2362 { lat: 214, common_pid: 2039 } hitcount: 2
2363 { lat: 214, common_pid: 2042 } hitcount: 1
2364 { lat: 215, common_pid: 2039 } hitcount: 1
2365 { lat: 217, common_pid: 2036 } hitcount: 1
2366 { lat: 217, common_pid: 2040 } hitcount: 1
2367 { lat: 217, common_pid: 2039 } hitcount: 1
2368 { lat: 218, common_pid: 2039 } hitcount: 6
2369 { lat: 219, common_pid: 2039 } hitcount: 9
2370 { lat: 220, common_pid: 2039 } hitcount: 11
2371 { lat: 221, common_pid: 2039 } hitcount: 5
2372 { lat: 221, common_pid: 2042 } hitcount: 1
2373 { lat: 222, common_pid: 2039 } hitcount: 7
2374 { lat: 223, common_pid: 2036 } hitcount: 1
2375 { lat: 223, common_pid: 2039 } hitcount: 3
2376 { lat: 224, common_pid: 2039 } hitcount: 4
2377 { lat: 224, common_pid: 2037 } hitcount: 1
2378 { lat: 224, common_pid: 2036 } hitcount: 2
2379 { lat: 225, common_pid: 2039 } hitcount: 5
2380 { lat: 225, common_pid: 2042 } hitcount: 1
2381 { lat: 226, common_pid: 2039 } hitcount: 7
2382 { lat: 226, common_pid: 2036 } hitcount: 4
2383 { lat: 227, common_pid: 2039 } hitcount: 6
2384 { lat: 227, common_pid: 2036 } hitcount: 12
2385 { lat: 227, common_pid: 2043 } hitcount: 1
2386 { lat: 228, common_pid: 2039 } hitcount: 7
2387 { lat: 228, common_pid: 2036 } hitcount: 14
2388 { lat: 229, common_pid: 2039 } hitcount: 9
2389 { lat: 229, common_pid: 2036 } hitcount: 8
2390 { lat: 229, common_pid: 2038 } hitcount: 1
2391 { lat: 230, common_pid: 2039 } hitcount: 11
2392 { lat: 230, common_pid: 2036 } hitcount: 6
2393 { lat: 230, common_pid: 2043 } hitcount: 1
2394 { lat: 230, common_pid: 2042 } hitcount: 2
2395 { lat: 231, common_pid: 2041 } hitcount: 1
2396 { lat: 231, common_pid: 2036 } hitcount: 6
2397 { lat: 231, common_pid: 2043 } hitcount: 1
2398 { lat: 231, common_pid: 2039 } hitcount: 8
2399 { lat: 232, common_pid: 2037 } hitcount: 1
2400 { lat: 232, common_pid: 2039 } hitcount: 6
2401 { lat: 232, common_pid: 2040 } hitcount: 2
2402 { lat: 232, common_pid: 2036 } hitcount: 5
2403 { lat: 232, common_pid: 2043 } hitcount: 1
2404 { lat: 233, common_pid: 2036 } hitcount: 5
2405 { lat: 233, common_pid: 2039 } hitcount: 11
2406 { lat: 234, common_pid: 2039 } hitcount: 4
2407 { lat: 234, common_pid: 2038 } hitcount: 2
2408 { lat: 234, common_pid: 2043 } hitcount: 2
2409 { lat: 234, common_pid: 2036 } hitcount: 11
2410 { lat: 234, common_pid: 2040 } hitcount: 1
2411 { lat: 235, common_pid: 2037 } hitcount: 2
2412 { lat: 235, common_pid: 2036 } hitcount: 8
2413 { lat: 235, common_pid: 2043 } hitcount: 2
2414 { lat: 235, common_pid: 2039 } hitcount: 5
2415 { lat: 235, common_pid: 2042 } hitcount: 2
2416 { lat: 235, common_pid: 2040 } hitcount: 4
2417 { lat: 235, common_pid: 2041 } hitcount: 1
2418 { lat: 236, common_pid: 2036 } hitcount: 7
2419 { lat: 236, common_pid: 2037 } hitcount: 1
2420 { lat: 236, common_pid: 2041 } hitcount: 5
2421 { lat: 236, common_pid: 2039 } hitcount: 3
2422 { lat: 236, common_pid: 2043 } hitcount: 9
2423 { lat: 236, common_pid: 2040 } hitcount: 7
2424 { lat: 237, common_pid: 2037 } hitcount: 1
2425 { lat: 237, common_pid: 2040 } hitcount: 1
2426 { lat: 237, common_pid: 2036 } hitcount: 9
2427 { lat: 237, common_pid: 2039 } hitcount: 3
2428 { lat: 237, common_pid: 2043 } hitcount: 8
2429 { lat: 237, common_pid: 2042 } hitcount: 2
2430 { lat: 237, common_pid: 2041 } hitcount: 2
2431 { lat: 238, common_pid: 2043 } hitcount: 10
2432 { lat: 238, common_pid: 2040 } hitcount: 1
2433 { lat: 238, common_pid: 2037 } hitcount: 9
2434 { lat: 238, common_pid: 2038 } hitcount: 1
2435 { lat: 238, common_pid: 2039 } hitcount: 1
2436 { lat: 238, common_pid: 2042 } hitcount: 3
2437 { lat: 238, common_pid: 2036 } hitcount: 7
2438 { lat: 239, common_pid: 2041 } hitcount: 1
2439 { lat: 239, common_pid: 2043 } hitcount: 11
2440 { lat: 239, common_pid: 2037 } hitcount: 11
2441 { lat: 239, common_pid: 2038 } hitcount: 6
2442 { lat: 239, common_pid: 2036 } hitcount: 7
2443 { lat: 239, common_pid: 2040 } hitcount: 1
2444 { lat: 239, common_pid: 2042 } hitcount: 9
2445 { lat: 240, common_pid: 2037 } hitcount: 29
2446 { lat: 240, common_pid: 2043 } hitcount: 15
2447 { lat: 240, common_pid: 2040 } hitcount: 44
2448 { lat: 240, common_pid: 2039 } hitcount: 1
2449 { lat: 240, common_pid: 2041 } hitcount: 2
2450 { lat: 240, common_pid: 2038 } hitcount: 1
2451 { lat: 240, common_pid: 2036 } hitcount: 10
2452 { lat: 240, common_pid: 2042 } hitcount: 13
2453 { lat: 241, common_pid: 2036 } hitcount: 21
2454 { lat: 241, common_pid: 2041 } hitcount: 36
2455 { lat: 241, common_pid: 2037 } hitcount: 34
2456 { lat: 241, common_pid: 2042 } hitcount: 14
2457 { lat: 241, common_pid: 2040 } hitcount: 94
2458 { lat: 241, common_pid: 2039 } hitcount: 12
2459 { lat: 241, common_pid: 2038 } hitcount: 2
2460 { lat: 241, common_pid: 2043 } hitcount: 28
2461 { lat: 242, common_pid: 2040 } hitcount: 109
2462 { lat: 242, common_pid: 2041 } hitcount: 506
2463 { lat: 242, common_pid: 2039 } hitcount: 155
2464 { lat: 242, common_pid: 2042 } hitcount: 21
2465 { lat: 242, common_pid: 2037 } hitcount: 52
2466 { lat: 242, common_pid: 2043 } hitcount: 21
2467 { lat: 242, common_pid: 2036 } hitcount: 16
2468 { lat: 242, common_pid: 2038 } hitcount: 156
2469 { lat: 243, common_pid: 2037 } hitcount: 46
2470 { lat: 243, common_pid: 2039 } hitcount: 40
2471 { lat: 243, common_pid: 2042 } hitcount: 119
2472 { lat: 243, common_pid: 2041 } hitcount: 611
2473 { lat: 243, common_pid: 2036 } hitcount: 69
2474 { lat: 243, common_pid: 2038 } hitcount: 784
2475 { lat: 243, common_pid: 2040 } hitcount: 323
2476 { lat: 243, common_pid: 2043 } hitcount: 14
2477 { lat: 244, common_pid: 2043 } hitcount: 35
2478 { lat: 244, common_pid: 2042 } hitcount: 305
2479 { lat: 244, common_pid: 2039 } hitcount: 8
2480 { lat: 244, common_pid: 2040 } hitcount: 4515
2481 { lat: 244, common_pid: 2038 } hitcount: 371
2482 { lat: 244, common_pid: 2037 } hitcount: 31
2483 { lat: 244, common_pid: 2036 } hitcount: 114
2484 { lat: 244, common_pid: 2041 } hitcount: 3396
2485 { lat: 245, common_pid: 2036 } hitcount: 700
2486 { lat: 245, common_pid: 2041 } hitcount: 2772
2487 { lat: 245, common_pid: 2037 } hitcount: 268
2488 { lat: 245, common_pid: 2039 } hitcount: 472
2489 { lat: 245, common_pid: 2038 } hitcount: 2758
2490 { lat: 245, common_pid: 2042 } hitcount: 3833
2491 { lat: 245, common_pid: 2040 } hitcount: 3105
2492 { lat: 245, common_pid: 2043 } hitcount: 645
2493 { lat: 246, common_pid: 2038 } hitcount: 3451
2494 { lat: 246, common_pid: 2041 } hitcount: 142
2495 { lat: 246, common_pid: 2037 } hitcount: 5101
2496 { lat: 246, common_pid: 2040 } hitcount: 68
2497 { lat: 246, common_pid: 2043 } hitcount: 5099
2498 { lat: 246, common_pid: 2039 } hitcount: 5608
2499 { lat: 246, common_pid: 2042 } hitcount: 3723
2500 { lat: 246, common_pid: 2036 } hitcount: 4738
2501 { lat: 247, common_pid: 2042 } hitcount: 312
2502 { lat: 247, common_pid: 2043 } hitcount: 2385
2503 { lat: 247, common_pid: 2041 } hitcount: 452
2504 { lat: 247, common_pid: 2038 } hitcount: 792
2505 { lat: 247, common_pid: 2040 } hitcount: 78
2506 { lat: 247, common_pid: 2036 } hitcount: 2375
2507 { lat: 247, common_pid: 2039 } hitcount: 1834
2508 { lat: 247, common_pid: 2037 } hitcount: 2655
2509 { lat: 248, common_pid: 2037 } hitcount: 36
2510 { lat: 248, common_pid: 2042 } hitcount: 11
2511 { lat: 248, common_pid: 2038 } hitcount: 122
2512 { lat: 248, common_pid: 2036 } hitcount: 135
2513 { lat: 248, common_pid: 2039 } hitcount: 26
2514 { lat: 248, common_pid: 2041 } hitcount: 503
2515 { lat: 248, common_pid: 2043 } hitcount: 66
2516 { lat: 248, common_pid: 2040 } hitcount: 46
2517 { lat: 249, common_pid: 2037 } hitcount: 29
2518 { lat: 249, common_pid: 2038 } hitcount: 1
2519 { lat: 249, common_pid: 2043 } hitcount: 29
2520 { lat: 249, common_pid: 2039 } hitcount: 8
2521 { lat: 249, common_pid: 2042 } hitcount: 56
2522 { lat: 249, common_pid: 2040 } hitcount: 27
2523 { lat: 249, common_pid: 2041 } hitcount: 11
2524 { lat: 249, common_pid: 2036 } hitcount: 27
2525 { lat: 250, common_pid: 2038 } hitcount: 1
2526 { lat: 250, common_pid: 2036 } hitcount: 30
2527 { lat: 250, common_pid: 2040 } hitcount: 19
2528 { lat: 250, common_pid: 2043 } hitcount: 22
2529 { lat: 250, common_pid: 2042 } hitcount: 20
2530 { lat: 250, common_pid: 2041 } hitcount: 1
2531 { lat: 250, common_pid: 2039 } hitcount: 6
2532 { lat: 250, common_pid: 2037 } hitcount: 48
2533 { lat: 251, common_pid: 2037 } hitcount: 43
2534 { lat: 251, common_pid: 2039 } hitcount: 1
2535 { lat: 251, common_pid: 2036 } hitcount: 12
2536 { lat: 251, common_pid: 2042 } hitcount: 2
2537 { lat: 251, common_pid: 2041 } hitcount: 1
2538 { lat: 251, common_pid: 2043 } hitcount: 15
2539 { lat: 251, common_pid: 2040 } hitcount: 3
2540 { lat: 252, common_pid: 2040 } hitcount: 1
2541 { lat: 252, common_pid: 2036 } hitcount: 12
2542 { lat: 252, common_pid: 2037 } hitcount: 21
2543 { lat: 252, common_pid: 2043 } hitcount: 14
2544 { lat: 253, common_pid: 2037 } hitcount: 21
2545 { lat: 253, common_pid: 2039 } hitcount: 2
2546 { lat: 253, common_pid: 2036 } hitcount: 9
2547 { lat: 253, common_pid: 2043 } hitcount: 6
2548 { lat: 253, common_pid: 2040 } hitcount: 1
2549 { lat: 254, common_pid: 2036 } hitcount: 8
2550 { lat: 254, common_pid: 2043 } hitcount: 3
2551 { lat: 254, common_pid: 2041 } hitcount: 1
2552 { lat: 254, common_pid: 2042 } hitcount: 1
2553 { lat: 254, common_pid: 2039 } hitcount: 1
2554 { lat: 254, common_pid: 2037 } hitcount: 12
2555 { lat: 255, common_pid: 2043 } hitcount: 1
2556 { lat: 255, common_pid: 2037 } hitcount: 2
2557 { lat: 255, common_pid: 2036 } hitcount: 2
2558 { lat: 255, common_pid: 2039 } hitcount: 8
2559 { lat: 256, common_pid: 2043 } hitcount: 1
2560 { lat: 256, common_pid: 2036 } hitcount: 4
2561 { lat: 256, common_pid: 2039 } hitcount: 6
2562 { lat: 257, common_pid: 2039 } hitcount: 5
2563 { lat: 257, common_pid: 2036 } hitcount: 4
2564 { lat: 258, common_pid: 2039 } hitcount: 5
2565 { lat: 258, common_pid: 2036 } hitcount: 2
2566 { lat: 259, common_pid: 2036 } hitcount: 7
2567 { lat: 259, common_pid: 2039 } hitcount: 7
2568 { lat: 260, common_pid: 2036 } hitcount: 8
2569 { lat: 260, common_pid: 2039 } hitcount: 6
2570 { lat: 261, common_pid: 2036 } hitcount: 5
2571 { lat: 261, common_pid: 2039 } hitcount: 7
2572 { lat: 262, common_pid: 2039 } hitcount: 5
2573 { lat: 262, common_pid: 2036 } hitcount: 5
2574 { lat: 263, common_pid: 2039 } hitcount: 7
2575 { lat: 263, common_pid: 2036 } hitcount: 7
2576 { lat: 264, common_pid: 2039 } hitcount: 9
2577 { lat: 264, common_pid: 2036 } hitcount: 9
2578 { lat: 265, common_pid: 2036 } hitcount: 5
2579 { lat: 265, common_pid: 2039 } hitcount: 1
2580 { lat: 266, common_pid: 2036 } hitcount: 1
2581 { lat: 266, common_pid: 2039 } hitcount: 3
2582 { lat: 267, common_pid: 2036 } hitcount: 1
2583 { lat: 267, common_pid: 2039 } hitcount: 3
2584 { lat: 268, common_pid: 2036 } hitcount: 1
2585 { lat: 268, common_pid: 2039 } hitcount: 6
2586 { lat: 269, common_pid: 2036 } hitcount: 1
2587 { lat: 269, common_pid: 2043 } hitcount: 1
2588 { lat: 269, common_pid: 2039 } hitcount: 2
2589 { lat: 270, common_pid: 2040 } hitcount: 1
2590 { lat: 270, common_pid: 2039 } hitcount: 6
2591 { lat: 271, common_pid: 2041 } hitcount: 1
2592 { lat: 271, common_pid: 2039 } hitcount: 5
2593 { lat: 272, common_pid: 2039 } hitcount: 10
2594 { lat: 273, common_pid: 2039 } hitcount: 8
2595 { lat: 274, common_pid: 2039 } hitcount: 2
2596 { lat: 275, common_pid: 2039 } hitcount: 1
2597 { lat: 276, common_pid: 2039 } hitcount: 2
2598 { lat: 276, common_pid: 2037 } hitcount: 1
2599 { lat: 276, common_pid: 2038 } hitcount: 1
2600 { lat: 277, common_pid: 2039 } hitcount: 1
2601 { lat: 277, common_pid: 2042 } hitcount: 1
2602 { lat: 278, common_pid: 2039 } hitcount: 1
2603 { lat: 279, common_pid: 2039 } hitcount: 4
2604 { lat: 279, common_pid: 2043 } hitcount: 1
2605 { lat: 280, common_pid: 2039 } hitcount: 3
2606 { lat: 283, common_pid: 2036 } hitcount: 2
2607 { lat: 284, common_pid: 2039 } hitcount: 1
2608 { lat: 284, common_pid: 2043 } hitcount: 1
2609 { lat: 288, common_pid: 2039 } hitcount: 1
2610 { lat: 289, common_pid: 2039 } hitcount: 1
2611 { lat: 300, common_pid: 2039 } hitcount: 1
2612 { lat: 384, common_pid: 2039 } hitcount: 1
2614 Totals:
2615 Hits: 67625
2616 Entries: 278
2617 Dropped: 0
2619 Note, the writes are around the sleep, so ideally they will all be of 250
2620 microseconds. If you are wondering how there are several that are under
2621 250 microseconds, that is because the way cyclictest works, is if one
2622 iteration comes in late, the next one will set the timer to wake up less that
2623 250. That is, if an iteration came in 50 microseconds late, the next wake up
2624 will be at 200 microseconds.
2626 But this could easily be done in userspace. To make this even more
2627 interesting, we can mix the histogram between events that happened in the
2628 kernel with trace_marker::
2630 # cd /sys/kernel/tracing
2631 # echo 'latency u64 lat' > synthetic_events
2632 # echo 'hist:keys=pid:ts0=common_timestamp.usecs' > events/sched/sched_waking/trigger
2633 # echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($lat) if buf == "end"' > events/ftrace/print/trigger
2634 # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
2636 The difference this time is that instead of using the trace_marker to start
2637 the latency, the sched_waking event is used, matching the common_pid for the
2638 trace_marker write with the pid that is being woken by sched_waking.
2640 After running cyclictest again with the same parameters, we now have::
2642 # cat events/synthetic/latency/hist
2643 # event histogram
2644 #
2645 # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
2646 #
2648 { lat: 7, common_pid: 2302 } hitcount: 640
2649 { lat: 7, common_pid: 2299 } hitcount: 42
2650 { lat: 7, common_pid: 2303 } hitcount: 18
2651 { lat: 7, common_pid: 2305 } hitcount: 166
2652 { lat: 7, common_pid: 2306 } hitcount: 1
2653 { lat: 7, common_pid: 2301 } hitcount: 91
2654 { lat: 7, common_pid: 2300 } hitcount: 17
2655 { lat: 8, common_pid: 2303 } hitcount: 8296
2656 { lat: 8, common_pid: 2304 } hitcount: 6864
2657 { lat: 8, common_pid: 2305 } hitcount: 9464
2658 { lat: 8, common_pid: 2301 } hitcount: 9213
2659 { lat: 8, common_pid: 2306 } hitcount: 6246
2660 { lat: 8, common_pid: 2302 } hitcount: 8797
2661 { lat: 8, common_pid: 2299 } hitcount: 8771
2662 { lat: 8, common_pid: 2300 } hitcount: 8119
2663 { lat: 9, common_pid: 2305 } hitcount: 1519
2664 { lat: 9, common_pid: 2299 } hitcount: 2346
2665 { lat: 9, common_pid: 2303 } hitcount: 2841
2666 { lat: 9, common_pid: 2301 } hitcount: 1846
2667 { lat: 9, common_pid: 2304 } hitcount: 3861
2668 { lat: 9, common_pid: 2302 } hitcount: 1210
2669 { lat: 9, common_pid: 2300 } hitcount: 2762
2670 { lat: 9, common_pid: 2306 } hitcount: 4247
2671 { lat: 10, common_pid: 2299 } hitcount: 16
2672 { lat: 10, common_pid: 2306 } hitcount: 333
2673 { lat: 10, common_pid: 2303 } hitcount: 16
2674 { lat: 10, common_pid: 2304 } hitcount: 168
2675 { lat: 10, common_pid: 2302 } hitcount: 240
2676 { lat: 10, common_pid: 2301 } hitcount: 28
2677 { lat: 10, common_pid: 2300 } hitcount: 95
2678 { lat: 10, common_pid: 2305 } hitcount: 18
2679 { lat: 11, common_pid: 2303 } hitcount: 5
2680 { lat: 11, common_pid: 2305 } hitcount: 8
2681 { lat: 11, common_pid: 2306 } hitcount: 221
2682 { lat: 11, common_pid: 2302 } hitcount: 76
2683 { lat: 11, common_pid: 2304 } hitcount: 26
2684 { lat: 11, common_pid: 2300 } hitcount: 125
2685 { lat: 11, common_pid: 2299 } hitcount: 2
2686 { lat: 12, common_pid: 2305 } hitcount: 3
2687 { lat: 12, common_pid: 2300 } hitcount: 6
2688 { lat: 12, common_pid: 2306 } hitcount: 90
2689 { lat: 12, common_pid: 2302 } hitcount: 4
2690 { lat: 12, common_pid: 2303 } hitcount: 1
2691 { lat: 12, common_pid: 2304 } hitcount: 122
2692 { lat: 13, common_pid: 2300 } hitcount: 12
2693 { lat: 13, common_pid: 2301 } hitcount: 1
2694 { lat: 13, common_pid: 2306 } hitcount: 32
2695 { lat: 13, common_pid: 2302 } hitcount: 5
2696 { lat: 13, common_pid: 2305 } hitcount: 1
2697 { lat: 13, common_pid: 2303 } hitcount: 1
2698 { lat: 13, common_pid: 2304 } hitcount: 61
2699 { lat: 14, common_pid: 2303 } hitcount: 4
2700 { lat: 14, common_pid: 2306 } hitcount: 5
2701 { lat: 14, common_pid: 2305 } hitcount: 4
2702 { lat: 14, common_pid: 2304 } hitcount: 62
2703 { lat: 14, common_pid: 2302 } hitcount: 19
2704 { lat: 14, common_pid: 2300 } hitcount: 33
2705 { lat: 14, common_pid: 2299 } hitcount: 1
2706 { lat: 14, common_pid: 2301 } hitcount: 4
2707 { lat: 15, common_pid: 2305 } hitcount: 1
2708 { lat: 15, common_pid: 2302 } hitcount: 25
2709 { lat: 15, common_pid: 2300 } hitcount: 11
2710 { lat: 15, common_pid: 2299 } hitcount: 5
2711 { lat: 15, common_pid: 2301 } hitcount: 1
2712 { lat: 15, common_pid: 2304 } hitcount: 8
2713 { lat: 15, common_pid: 2303 } hitcount: 1
2714 { lat: 15, common_pid: 2306 } hitcount: 6
2715 { lat: 16, common_pid: 2302 } hitcount: 31
2716 { lat: 16, common_pid: 2306 } hitcount: 3
2717 { lat: 16, common_pid: 2300 } hitcount: 5
2718 { lat: 17, common_pid: 2302 } hitcount: 6
2719 { lat: 17, common_pid: 2303 } hitcount: 1
2720 { lat: 18, common_pid: 2304 } hitcount: 1
2721 { lat: 18, common_pid: 2302 } hitcount: 8
2722 { lat: 18, common_pid: 2299 } hitcount: 1
2723 { lat: 18, common_pid: 2301 } hitcount: 1
2724 { lat: 19, common_pid: 2303 } hitcount: 4
2725 { lat: 19, common_pid: 2304 } hitcount: 5
2726 { lat: 19, common_pid: 2302 } hitcount: 4
2727 { lat: 19, common_pid: 2299 } hitcount: 3
2728 { lat: 19, common_pid: 2306 } hitcount: 1
2729 { lat: 19, common_pid: 2300 } hitcount: 4
2730 { lat: 19, common_pid: 2305 } hitcount: 5
2731 { lat: 20, common_pid: 2299 } hitcount: 2
2732 { lat: 20, common_pid: 2302 } hitcount: 3
2733 { lat: 20, common_pid: 2305 } hitcount: 1
2734 { lat: 20, common_pid: 2300 } hitcount: 2
2735 { lat: 20, common_pid: 2301 } hitcount: 2
2736 { lat: 20, common_pid: 2303 } hitcount: 3
2737 { lat: 21, common_pid: 2305 } hitcount: 1
2738 { lat: 21, common_pid: 2299 } hitcount: 5
2739 { lat: 21, common_pid: 2303 } hitcount: 4
2740 { lat: 21, common_pid: 2302 } hitcount: 7
2741 { lat: 21, common_pid: 2300 } hitcount: 1
2742 { lat: 21, common_pid: 2301 } hitcount: 5
2743 { lat: 21, common_pid: 2304 } hitcount: 2
2744 { lat: 22, common_pid: 2302 } hitcount: 5
2745 { lat: 22, common_pid: 2303 } hitcount: 1
2746 { lat: 22, common_pid: 2306 } hitcount: 3
2747 { lat: 22, common_pid: 2301 } hitcount: 2
2748 { lat: 22, common_pid: 2300 } hitcount: 1
2749 { lat: 22, common_pid: 2299 } hitcount: 1
2750 { lat: 22, common_pid: 2305 } hitcount: 1
2751 { lat: 22, common_pid: 2304 } hitcount: 1
2752 { lat: 23, common_pid: 2299 } hitcount: 1
2753 { lat: 23, common_pid: 2306 } hitcount: 2
2754 { lat: 23, common_pid: 2302 } hitcount: 6
2755 { lat: 24, common_pid: 2302 } hitcount: 3
2756 { lat: 24, common_pid: 2300 } hitcount: 1
2757 { lat: 24, common_pid: 2306 } hitcount: 2
2758 { lat: 24, common_pid: 2305 } hitcount: 1
2759 { lat: 24, common_pid: 2299 } hitcount: 1
2760 { lat: 25, common_pid: 2300 } hitcount: 1
2761 { lat: 25, common_pid: 2302 } hitcount: 4
2762 { lat: 26, common_pid: 2302 } hitcount: 2
2763 { lat: 27, common_pid: 2305 } hitcount: 1
2764 { lat: 27, common_pid: 2300 } hitcount: 1
2765 { lat: 27, common_pid: 2302 } hitcount: 3
2766 { lat: 28, common_pid: 2306 } hitcount: 1
2767 { lat: 28, common_pid: 2302 } hitcount: 4
2768 { lat: 29, common_pid: 2302 } hitcount: 1
2769 { lat: 29, common_pid: 2300 } hitcount: 2
2770 { lat: 29, common_pid: 2306 } hitcount: 1
2771 { lat: 29, common_pid: 2304 } hitcount: 1
2772 { lat: 30, common_pid: 2302 } hitcount: 4
2773 { lat: 31, common_pid: 2302 } hitcount: 6
2774 { lat: 32, common_pid: 2302 } hitcount: 1
2775 { lat: 33, common_pid: 2299 } hitcount: 1
2776 { lat: 33, common_pid: 2302 } hitcount: 3
2777 { lat: 34, common_pid: 2302 } hitcount: 2
2778 { lat: 35, common_pid: 2302 } hitcount: 1
2779 { lat: 35, common_pid: 2304 } hitcount: 1
2780 { lat: 36, common_pid: 2302 } hitcount: 4
2781 { lat: 37, common_pid: 2302 } hitcount: 6
2782 { lat: 38, common_pid: 2302 } hitcount: 2
2783 { lat: 39, common_pid: 2302 } hitcount: 2
2784 { lat: 39, common_pid: 2304 } hitcount: 1
2785 { lat: 40, common_pid: 2304 } hitcount: 2
2786 { lat: 40, common_pid: 2302 } hitcount: 5
2787 { lat: 41, common_pid: 2304 } hitcount: 1
2788 { lat: 41, common_pid: 2302 } hitcount: 8
2789 { lat: 42, common_pid: 2302 } hitcount: 6
2790 { lat: 42, common_pid: 2304 } hitcount: 1
2791 { lat: 43, common_pid: 2302 } hitcount: 3
2792 { lat: 43, common_pid: 2304 } hitcount: 4
2793 { lat: 44, common_pid: 2302 } hitcount: 6
2794 { lat: 45, common_pid: 2302 } hitcount: 5
2795 { lat: 46, common_pid: 2302 } hitcount: 5
2796 { lat: 47, common_pid: 2302 } hitcount: 7
2797 { lat: 48, common_pid: 2301 } hitcount: 1
2798 { lat: 48, common_pid: 2302 } hitcount: 9
2799 { lat: 49, common_pid: 2302 } hitcount: 3
2800 { lat: 50, common_pid: 2302 } hitcount: 1
2801 { lat: 50, common_pid: 2301 } hitcount: 1
2802 { lat: 51, common_pid: 2302 } hitcount: 2
2803 { lat: 51, common_pid: 2301 } hitcount: 1
2804 { lat: 61, common_pid: 2302 } hitcount: 1
2805 { lat: 110, common_pid: 2302 } hitcount: 1
2807 Totals:
2808 Hits: 89565
2809 Entries: 158
2810 Dropped: 0
2812 This doesn't tell us any information about how late cyclictest may have
2813 woken up, but it does show us a nice histogram of how long it took from
2814 the time that cyclictest was woken to the time it made it into user space.