blob: 25c94730d3fe9a408006ec72744425059020e00f [file] [log] [blame]
Tom Zanussib8df4a32018-01-15 20:51:35 -06001 Event Histograms
2
3 Documentation written by Tom Zanussi
4
51. Introduction
6===============
7
8 Histogram triggers are special event triggers that can be used to
9 aggregate trace event data into histograms. For information on
10 trace events and event triggers, see Documentation/trace/events.txt.
11
12
132. Histogram Trigger Command
14============================
15
16 A histogram trigger command is an event trigger command that
17 aggregates event hits into a hash table keyed on one or more trace
18 event format fields (or stacktrace) and a set of running totals
19 derived from one or more trace event format fields and/or event
20 counts (hitcount).
21
22 The format of a hist trigger is as follows:
23
24 hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>]
25 [:sort=<field1[,field2,...]>][:size=#entries][:pause][:continue]
26 [:clear][:name=histname1] [if <filter>]
27
28 When a matching event is hit, an entry is added to a hash table
29 using the key(s) and value(s) named. Keys and values correspond to
30 fields in the event's format description. Values must correspond to
31 numeric fields - on an event hit, the value(s) will be added to a
32 sum kept for that field. The special string 'hitcount' can be used
33 in place of an explicit value field - this is simply a count of
34 event hits. If 'values' isn't specified, an implicit 'hitcount'
35 value will be automatically created and used as the only value.
36 Keys can be any field, or the special string 'stacktrace', which
37 will use the event's kernel stacktrace as the key. The keywords
38 'keys' or 'key' can be used to specify keys, and the keywords
39 'values', 'vals', or 'val' can be used to specify values. Compound
40 keys consisting of up to two fields can be specified by the 'keys'
41 keyword. Hashing a compound key produces a unique entry in the
42 table for each unique combination of component keys, and can be
43 useful for providing more fine-grained summaries of event data.
44 Additionally, sort keys consisting of up to two fields can be
45 specified by the 'sort' keyword. If more than one field is
46 specified, the result will be a 'sort within a sort': the first key
47 is taken to be the primary sort key and the second the secondary
48 key. If a hist trigger is given a name using the 'name' parameter,
49 its histogram data will be shared with other triggers of the same
50 name, and trigger hits will update this common data. Only triggers
51 with 'compatible' fields can be combined in this way; triggers are
52 'compatible' if the fields named in the trigger share the same
53 number and type of fields and those fields also have the same names.
54 Note that any two events always share the compatible 'hitcount' and
55 'stacktrace' fields and can therefore be combined using those
56 fields, however pointless that may be.
57
58 'hist' triggers add a 'hist' file to each event's subdirectory.
59 Reading the 'hist' file for the event will dump the hash table in
60 its entirety to stdout. If there are multiple hist triggers
61 attached to an event, there will be a table for each trigger in the
62 output. The table displayed for a named trigger will be the same as
63 any other instance having the same name. Each printed hash table
64 entry is a simple list of the keys and values comprising the entry;
65 keys are printed first and are delineated by curly braces, and are
66 followed by the set of value fields for the entry. By default,
67 numeric fields are displayed as base-10 integers. This can be
68 modified by appending any of the following modifiers to the field
69 name:
70
71 .hex display a number as a hex value
72 .sym display an address as a symbol
73 .sym-offset display an address as a symbol and offset
74 .syscall display a syscall id as a system call name
75 .execname display a common_pid as a program name
Tom Zanussi442c9482018-01-15 20:51:36 -060076 .log2 display log2 value rather than raw number
Tom Zanussi860f9f62018-01-15 20:51:48 -060077 .usecs display a common_timestamp in microseconds
Tom Zanussib8df4a32018-01-15 20:51:35 -060078
79 Note that in general the semantics of a given field aren't
80 interpreted when applying a modifier to it, but there are some
81 restrictions to be aware of in this regard:
82
83 - only the 'hex' modifier can be used for values (because values
84 are essentially sums, and the other modifiers don't make sense
85 in that context).
86 - the 'execname' modifier can only be used on a 'common_pid'. The
87 reason for this is that the execname is simply the 'comm' value
88 saved for the 'current' process when an event was triggered,
89 which is the same as the common_pid value saved by the event
90 tracing code. Trying to apply that comm value to other pid
91 values wouldn't be correct, and typically events that care save
92 pid-specific comm fields in the event itself.
93
94 A typical usage scenario would be the following to enable a hist
95 trigger, read its current contents, and then turn it off:
96
97 # echo 'hist:keys=skbaddr.hex:vals=len' > \
98 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
99
100 # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
101
102 # echo '!hist:keys=skbaddr.hex:vals=len' > \
103 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
104
105 The trigger file itself can be read to show the details of the
106 currently attached hist trigger. This information is also displayed
107 at the top of the 'hist' file when read.
108
109 By default, the size of the hash table is 2048 entries. The 'size'
110 parameter can be used to specify more or fewer than that. The units
111 are in terms of hashtable entries - if a run uses more entries than
112 specified, the results will show the number of 'drops', the number
113 of hits that were ignored. The size should be a power of 2 between
114 128 and 131072 (any non- power-of-2 number specified will be rounded
115 up).
116
117 The 'sort' parameter can be used to specify a value field to sort
118 on. The default if unspecified is 'hitcount' and the default sort
119 order is 'ascending'. To sort in the opposite direction, append
120 .descending' to the sort key.
121
122 The 'pause' parameter can be used to pause an existing hist trigger
123 or to start a hist trigger but not log any events until told to do
124 so. 'continue' or 'cont' can be used to start or restart a paused
125 hist trigger.
126
127 The 'clear' parameter will clear the contents of a running hist
128 trigger and leave its current paused/active state.
129
130 Note that the 'pause', 'cont', and 'clear' parameters should be
131 applied using 'append' shell operator ('>>') if applied to an
132 existing trigger, rather than via the '>' operator, which will cause
133 the trigger to be removed through truncation.
134
135- enable_hist/disable_hist
136
137 The enable_hist and disable_hist triggers can be used to have one
138 event conditionally start and stop another event's already-attached
139 hist trigger. Any number of enable_hist and disable_hist triggers
140 can be attached to a given event, allowing that event to kick off
141 and stop aggregations on a host of other events.
142
143 The format is very similar to the enable/disable_event triggers:
144
145 enable_hist:<system>:<event>[:count]
146 disable_hist:<system>:<event>[:count]
147
148 Instead of enabling or disabling the tracing of the target event
149 into the trace buffer as the enable/disable_event triggers do, the
150 enable/disable_hist triggers enable or disable the aggregation of
151 the target event into a hash table.
152
153 A typical usage scenario for the enable_hist/disable_hist triggers
154 would be to first set up a paused hist trigger on some event,
155 followed by an enable_hist/disable_hist pair that turns the hist
156 aggregation on and off when conditions of interest are hit:
157
158 # echo 'hist:keys=skbaddr.hex:vals=len:pause' > \
159 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
160
161 # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \
162 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
163
164 # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \
165 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
166
167 The above sets up an initially paused hist trigger which is unpaused
168 and starts aggregating events when a given program is executed, and
169 which stops aggregating when the process exits and the hist trigger
170 is paused again.
171
172 The examples below provide a more concrete illustration of the
173 concepts and typical usage patterns discussed above.
174
175
1766.2 'hist' trigger examples
177---------------------------
178
179 The first set of examples creates aggregations using the kmalloc
180 event. The fields that can be used for the hist trigger are listed
181 in the kmalloc event's format file:
182
183 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format
184 name: kmalloc
185 ID: 374
186 format:
187 field:unsigned short common_type; offset:0; size:2; signed:0;
188 field:unsigned char common_flags; offset:2; size:1; signed:0;
189 field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
190 field:int common_pid; offset:4; size:4; signed:1;
191
192 field:unsigned long call_site; offset:8; size:8; signed:0;
193 field:const void * ptr; offset:16; size:8; signed:0;
194 field:size_t bytes_req; offset:24; size:8; signed:0;
195 field:size_t bytes_alloc; offset:32; size:8; signed:0;
196 field:gfp_t gfp_flags; offset:40; size:4; signed:0;
197
198 We'll start by creating a hist trigger that generates a simple table
199 that lists the total number of bytes requested for each function in
200 the kernel that made one or more calls to kmalloc:
201
202 # echo 'hist:key=call_site:val=bytes_req' > \
203 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
204
205 This tells the tracing system to create a 'hist' trigger using the
206 call_site field of the kmalloc event as the key for the table, which
207 just means that each unique call_site address will have an entry
208 created for it in the table. The 'val=bytes_req' parameter tells
209 the hist trigger that for each unique entry (call_site) in the
210 table, it should keep a running total of the number of bytes
211 requested by that call_site.
212
213 We'll let it run for awhile and then dump the contents of the 'hist'
214 file in the kmalloc event's subdirectory (for readability, a number
215 of entries have been omitted):
216
217 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
218 # trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
219
220 { call_site: 18446744072106379007 } hitcount: 1 bytes_req: 176
221 { call_site: 18446744071579557049 } hitcount: 1 bytes_req: 1024
222 { call_site: 18446744071580608289 } hitcount: 1 bytes_req: 16384
223 { call_site: 18446744071581827654 } hitcount: 1 bytes_req: 24
224 { call_site: 18446744071580700980 } hitcount: 1 bytes_req: 8
225 { call_site: 18446744071579359876 } hitcount: 1 bytes_req: 152
226 { call_site: 18446744071580795365 } hitcount: 3 bytes_req: 144
227 { call_site: 18446744071581303129 } hitcount: 3 bytes_req: 144
228 { call_site: 18446744071580713234 } hitcount: 4 bytes_req: 2560
229 { call_site: 18446744071580933750 } hitcount: 4 bytes_req: 736
230 .
231 .
232 .
233 { call_site: 18446744072106047046 } hitcount: 69 bytes_req: 5576
234 { call_site: 18446744071582116407 } hitcount: 73 bytes_req: 2336
235 { call_site: 18446744072106054684 } hitcount: 136 bytes_req: 140504
236 { call_site: 18446744072106224230 } hitcount: 136 bytes_req: 19584
237 { call_site: 18446744072106078074 } hitcount: 153 bytes_req: 2448
238 { call_site: 18446744072106062406 } hitcount: 153 bytes_req: 36720
239 { call_site: 18446744071582507929 } hitcount: 153 bytes_req: 37088
240 { call_site: 18446744072102520590 } hitcount: 273 bytes_req: 10920
241 { call_site: 18446744071582143559 } hitcount: 358 bytes_req: 716
242 { call_site: 18446744072106465852 } hitcount: 417 bytes_req: 56712
243 { call_site: 18446744072102523378 } hitcount: 485 bytes_req: 27160
244 { call_site: 18446744072099568646 } hitcount: 1676 bytes_req: 33520
245
246 Totals:
247 Hits: 4610
248 Entries: 45
249 Dropped: 0
250
251 The output displays a line for each entry, beginning with the key
252 specified in the trigger, followed by the value(s) also specified in
253 the trigger. At the beginning of the output is a line that displays
254 the trigger info, which can also be displayed by reading the
255 'trigger' file:
256
257 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
258 hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
259
260 At the end of the output are a few lines that display the overall
261 totals for the run. The 'Hits' field shows the total number of
262 times the event trigger was hit, the 'Entries' field shows the total
263 number of used entries in the hash table, and the 'Dropped' field
264 shows the number of hits that were dropped because the number of
265 used entries for the run exceeded the maximum number of entries
266 allowed for the table (normally 0, but if not a hint that you may
267 want to increase the size of the table using the 'size' parameter).
268
269 Notice in the above output that there's an extra field, 'hitcount',
270 which wasn't specified in the trigger. Also notice that in the
271 trigger info output, there's a parameter, 'sort=hitcount', which
272 wasn't specified in the trigger either. The reason for that is that
273 every trigger implicitly keeps a count of the total number of hits
274 attributed to a given entry, called the 'hitcount'. That hitcount
275 information is explicitly displayed in the output, and in the
276 absence of a user-specified sort parameter, is used as the default
277 sort field.
278
279 The value 'hitcount' can be used in place of an explicit value in
280 the 'values' parameter if you don't really need to have any
281 particular field summed and are mainly interested in hit
282 frequencies.
283
284 To turn the hist trigger off, simply call up the trigger in the
285 command history and re-execute it with a '!' prepended:
286
287 # echo '!hist:key=call_site:val=bytes_req' > \
288 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
289
290 Finally, notice that the call_site as displayed in the output above
291 isn't really very useful. It's an address, but normally addresses
292 are displayed in hex. To have a numeric field displayed as a hex
293 value, simply append '.hex' to the field name in the trigger:
294
295 # echo 'hist:key=call_site.hex:val=bytes_req' > \
296 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
297
298 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
299 # trigger info: hist:keys=call_site.hex:vals=bytes_req:sort=hitcount:size=2048 [active]
300
301 { call_site: ffffffffa026b291 } hitcount: 1 bytes_req: 433
302 { call_site: ffffffffa07186ff } hitcount: 1 bytes_req: 176
303 { call_site: ffffffff811ae721 } hitcount: 1 bytes_req: 16384
304 { call_site: ffffffff811c5134 } hitcount: 1 bytes_req: 8
305 { call_site: ffffffffa04a9ebb } hitcount: 1 bytes_req: 511
306 { call_site: ffffffff8122e0a6 } hitcount: 1 bytes_req: 12
307 { call_site: ffffffff8107da84 } hitcount: 1 bytes_req: 152
308 { call_site: ffffffff812d8246 } hitcount: 1 bytes_req: 24
309 { call_site: ffffffff811dc1e5 } hitcount: 3 bytes_req: 144
310 { call_site: ffffffffa02515e8 } hitcount: 3 bytes_req: 648
311 { call_site: ffffffff81258159 } hitcount: 3 bytes_req: 144
312 { call_site: ffffffff811c80f4 } hitcount: 4 bytes_req: 544
313 .
314 .
315 .
316 { call_site: ffffffffa06c7646 } hitcount: 106 bytes_req: 8024
317 { call_site: ffffffffa06cb246 } hitcount: 132 bytes_req: 31680
318 { call_site: ffffffffa06cef7a } hitcount: 132 bytes_req: 2112
319 { call_site: ffffffff8137e399 } hitcount: 132 bytes_req: 23232
320 { call_site: ffffffffa06c941c } hitcount: 185 bytes_req: 171360
321 { call_site: ffffffffa06f2a66 } hitcount: 185 bytes_req: 26640
322 { call_site: ffffffffa036a70e } hitcount: 265 bytes_req: 10600
323 { call_site: ffffffff81325447 } hitcount: 292 bytes_req: 584
324 { call_site: ffffffffa072da3c } hitcount: 446 bytes_req: 60656
325 { call_site: ffffffffa036b1f2 } hitcount: 526 bytes_req: 29456
326 { call_site: ffffffffa0099c06 } hitcount: 1780 bytes_req: 35600
327
328 Totals:
329 Hits: 4775
330 Entries: 46
331 Dropped: 0
332
333 Even that's only marginally more useful - while hex values do look
334 more like addresses, what users are typically more interested in
335 when looking at text addresses are the corresponding symbols
336 instead. To have an address displayed as symbolic value instead,
337 simply append '.sym' or '.sym-offset' to the field name in the
338 trigger:
339
340 # echo 'hist:key=call_site.sym:val=bytes_req' > \
341 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
342
343 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
344 # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=hitcount:size=2048 [active]
345
346 { call_site: [ffffffff810adcb9] syslog_print_all } hitcount: 1 bytes_req: 1024
347 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8
348 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7
349 { call_site: [ffffffff8154acbe] usb_alloc_urb } hitcount: 1 bytes_req: 192
350 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7
351 { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40
352 { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128
353 { call_site: [ffffffff811febd5] fsnotify_alloc_group } hitcount: 2 bytes_req: 528
354 { call_site: [ffffffff81440f58] __tty_buffer_request_room } hitcount: 2 bytes_req: 2624
355 { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 2 bytes_req: 96
356 { call_site: [ffffffffa05e19af] ieee80211_start_tx_ba_session [mac80211] } hitcount: 2 bytes_req: 464
357 { call_site: [ffffffff81672406] tcp_get_metrics } hitcount: 2 bytes_req: 304
358 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128
359 { call_site: [ffffffff81089b05] sched_create_group } hitcount: 2 bytes_req: 1424
360 .
361 .
362 .
363 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1185 bytes_req: 123240
364 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 1185 bytes_req: 104280
365 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 1402 bytes_req: 190672
366 { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 1518 bytes_req: 146208
367 { call_site: [ffffffffa029070e] drm_vma_node_allow [drm] } hitcount: 1746 bytes_req: 69840
368 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 2021 bytes_req: 792312
369 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 2592 bytes_req: 145152
370 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2629 bytes_req: 378576
371 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2629 bytes_req: 3783248
372 { call_site: [ffffffff81325607] apparmor_file_alloc_security } hitcount: 5192 bytes_req: 10384
373 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 5529 bytes_req: 110584
374 { call_site: [ffffffff8131ebf7] aa_alloc_task_context } hitcount: 21943 bytes_req: 702176
375 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 55759 bytes_req: 5074265
376
377 Totals:
378 Hits: 109928
379 Entries: 71
380 Dropped: 0
381
382 Because the default sort key above is 'hitcount', the above shows a
383 the list of call_sites by increasing hitcount, so that at the bottom
384 we see the functions that made the most kmalloc calls during the
385 run. If instead we we wanted to see the top kmalloc callers in
386 terms of the number of bytes requested rather than the number of
387 calls, and we wanted the top caller to appear at the top, we can use
388 the 'sort' parameter, along with the 'descending' modifier:
389
390 # echo 'hist:key=call_site.sym:val=bytes_req:sort=bytes_req.descending' > \
391 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
392
393 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
394 # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=bytes_req.descending:size=2048 [active]
395
396 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2186 bytes_req: 3397464
397 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1790 bytes_req: 712176
398 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 8132 bytes_req: 513135
399 { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 106 bytes_req: 440128
400 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2186 bytes_req: 314784
401 { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 2174 bytes_req: 208992
402 { call_site: [ffffffff811ae8e1] __kmalloc } hitcount: 8 bytes_req: 131072
403 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 859 bytes_req: 116824
404 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 1834 bytes_req: 102704
405 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 972 bytes_req: 101088
406 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 972 bytes_req: 85536
407 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 3333 bytes_req: 66664
408 { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 209 bytes_req: 61632
409 .
410 .
411 .
412 { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128
413 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128
414 { call_site: [ffffffff812d8406] copy_semundo } hitcount: 2 bytes_req: 48
415 { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 1 bytes_req: 48
416 { call_site: [ffffffffa027121a] drm_getmagic [drm] } hitcount: 1 bytes_req: 48
417 { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40
418 { call_site: [ffffffff811c52f4] bprm_change_interp } hitcount: 2 bytes_req: 16
419 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8
420 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7
421 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7
422
423 Totals:
424 Hits: 32133
425 Entries: 81
426 Dropped: 0
427
428 To display the offset and size information in addition to the symbol
429 name, just use 'sym-offset' instead:
430
431 # echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \
432 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
433
434 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
435 # trigger info: hist:keys=call_site.sym-offset:vals=bytes_req:sort=bytes_req.descending:size=2048 [active]
436
437 { call_site: [ffffffffa046041c] i915_gem_execbuffer2+0x6c/0x2c0 [i915] } hitcount: 4569 bytes_req: 3163720
438 { call_site: [ffffffffa0489a66] intel_ring_begin+0xc6/0x1f0 [i915] } hitcount: 4569 bytes_req: 657936
439 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23+0x694/0x1020 [i915] } hitcount: 1519 bytes_req: 472936
440 { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23+0x516/0x1020 [i915] } hitcount: 3050 bytes_req: 211832
441 { call_site: [ffffffff811e2a1b] seq_buf_alloc+0x1b/0x50 } hitcount: 34 bytes_req: 148384
442 { call_site: [ffffffffa04a580c] intel_crtc_page_flip+0xbc/0x870 [i915] } hitcount: 1385 bytes_req: 144040
443 { call_site: [ffffffff811ae8e1] __kmalloc+0x191/0x1b0 } hitcount: 8 bytes_req: 131072
444 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl+0x282/0x360 [drm] } hitcount: 1385 bytes_req: 121880
445 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc+0x32/0x100 [drm] } hitcount: 1848 bytes_req: 103488
446 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state+0x2c/0xa0 [i915] } hitcount: 461 bytes_req: 62696
447 { call_site: [ffffffffa029070e] drm_vma_node_allow+0x2e/0xd0 [drm] } hitcount: 1541 bytes_req: 61640
448 { call_site: [ffffffff815f8d7b] sk_prot_alloc+0xcb/0x1b0 } hitcount: 57 bytes_req: 57456
449 .
450 .
451 .
452 { call_site: [ffffffff8109524a] alloc_fair_sched_group+0x5a/0x1a0 } hitcount: 2 bytes_req: 128
453 { call_site: [ffffffffa027b921] drm_vm_open_locked+0x31/0xa0 [drm] } hitcount: 3 bytes_req: 96
454 { call_site: [ffffffff8122e266] proc_self_follow_link+0x76/0xb0 } hitcount: 8 bytes_req: 96
455 { call_site: [ffffffff81213e80] load_elf_binary+0x240/0x1650 } hitcount: 3 bytes_req: 84
456 { call_site: [ffffffff8154bc62] usb_control_msg+0x42/0x110 } hitcount: 1 bytes_req: 8
457 { call_site: [ffffffffa00bf6fe] hidraw_send_report+0x7e/0x1a0 [hid] } hitcount: 1 bytes_req: 7
458 { call_site: [ffffffffa00bf1ca] hidraw_report_event+0x8a/0x120 [hid] } hitcount: 1 bytes_req: 7
459
460 Totals:
461 Hits: 26098
462 Entries: 64
463 Dropped: 0
464
465 We can also add multiple fields to the 'values' parameter. For
466 example, we might want to see the total number of bytes allocated
467 alongside bytes requested, and display the result sorted by bytes
468 allocated in a descending order:
469
470 # echo 'hist:keys=call_site.sym:values=bytes_req,bytes_alloc:sort=bytes_alloc.descending' > \
471 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
472
473 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
474 # trigger info: hist:keys=call_site.sym:vals=bytes_req,bytes_alloc:sort=bytes_alloc.descending:size=2048 [active]
475
476 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 7403 bytes_req: 4084360 bytes_alloc: 5958016
477 { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 541 bytes_req: 2213968 bytes_alloc: 2228224
478 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 7404 bytes_req: 1066176 bytes_alloc: 1421568
479 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1565 bytes_req: 557368 bytes_alloc: 1037760
480 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 9557 bytes_req: 595778 bytes_alloc: 695744
481 { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 5839 bytes_req: 430680 bytes_alloc: 470400
482 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 2388 bytes_req: 324768 bytes_alloc: 458496
483 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 3911 bytes_req: 219016 bytes_alloc: 250304
484 { call_site: [ffffffff815f8d7b] sk_prot_alloc } hitcount: 235 bytes_req: 236880 bytes_alloc: 240640
485 { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 557 bytes_req: 169024 bytes_alloc: 221760
486 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 9378 bytes_req: 187548 bytes_alloc: 206312
487 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1519 bytes_req: 157976 bytes_alloc: 194432
488 .
489 .
490 .
491 { call_site: [ffffffff8109bd3b] sched_autogroup_create_attach } hitcount: 2 bytes_req: 144 bytes_alloc: 192
492 { call_site: [ffffffff81097ee8] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128
493 { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128
494 { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128
495 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128
496 { call_site: [ffffffff81213e80] load_elf_binary } hitcount: 3 bytes_req: 84 bytes_alloc: 96
497 { call_site: [ffffffff81079a2e] kthread_create_on_node } hitcount: 1 bytes_req: 56 bytes_alloc: 64
498 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8
499 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 bytes_alloc: 8
500 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8
501
502 Totals:
503 Hits: 66598
504 Entries: 65
505 Dropped: 0
506
507 Finally, to finish off our kmalloc example, instead of simply having
508 the hist trigger display symbolic call_sites, we can have the hist
509 trigger additionally display the complete set of kernel stack traces
510 that led to each call_site. To do that, we simply use the special
511 value 'stacktrace' for the key parameter:
512
513 # echo 'hist:keys=stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' > \
514 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
515
516 The above trigger will use the kernel stack trace in effect when an
517 event is triggered as the key for the hash table. This allows the
518 enumeration of every kernel callpath that led up to a particular
519 event, along with a running total of any of the event fields for
520 that event. Here we tally bytes requested and bytes allocated for
521 every callpath in the system that led up to a kmalloc (in this case
522 every callpath to a kmalloc for a kernel compile):
523
524 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
525 # trigger info: hist:keys=stacktrace:vals=bytes_req,bytes_alloc:sort=bytes_alloc:size=2048 [active]
526
527 { stacktrace:
528 __kmalloc_track_caller+0x10b/0x1a0
529 kmemdup+0x20/0x50
530 hidraw_report_event+0x8a/0x120 [hid]
531 hid_report_raw_event+0x3ea/0x440 [hid]
532 hid_input_report+0x112/0x190 [hid]
533 hid_irq_in+0xc2/0x260 [usbhid]
534 __usb_hcd_giveback_urb+0x72/0x120
535 usb_giveback_urb_bh+0x9e/0xe0
536 tasklet_hi_action+0xf8/0x100
537 __do_softirq+0x114/0x2c0
538 irq_exit+0xa5/0xb0
539 do_IRQ+0x5a/0xf0
540 ret_from_intr+0x0/0x30
541 cpuidle_enter+0x17/0x20
542 cpu_startup_entry+0x315/0x3e0
543 rest_init+0x7c/0x80
544 } hitcount: 3 bytes_req: 21 bytes_alloc: 24
545 { stacktrace:
546 __kmalloc_track_caller+0x10b/0x1a0
547 kmemdup+0x20/0x50
548 hidraw_report_event+0x8a/0x120 [hid]
549 hid_report_raw_event+0x3ea/0x440 [hid]
550 hid_input_report+0x112/0x190 [hid]
551 hid_irq_in+0xc2/0x260 [usbhid]
552 __usb_hcd_giveback_urb+0x72/0x120
553 usb_giveback_urb_bh+0x9e/0xe0
554 tasklet_hi_action+0xf8/0x100
555 __do_softirq+0x114/0x2c0
556 irq_exit+0xa5/0xb0
557 do_IRQ+0x5a/0xf0
558 ret_from_intr+0x0/0x30
559 } hitcount: 3 bytes_req: 21 bytes_alloc: 24
560 { stacktrace:
561 kmem_cache_alloc_trace+0xeb/0x150
562 aa_alloc_task_context+0x27/0x40
563 apparmor_cred_prepare+0x1f/0x50
564 security_prepare_creds+0x16/0x20
565 prepare_creds+0xdf/0x1a0
566 SyS_capset+0xb5/0x200
567 system_call_fastpath+0x12/0x6a
568 } hitcount: 1 bytes_req: 32 bytes_alloc: 32
569 .
570 .
571 .
572 { stacktrace:
573 __kmalloc+0x11b/0x1b0
574 i915_gem_execbuffer2+0x6c/0x2c0 [i915]
575 drm_ioctl+0x349/0x670 [drm]
576 do_vfs_ioctl+0x2f0/0x4f0
577 SyS_ioctl+0x81/0xa0
578 system_call_fastpath+0x12/0x6a
579 } hitcount: 17726 bytes_req: 13944120 bytes_alloc: 19593808
580 { stacktrace:
581 __kmalloc+0x11b/0x1b0
582 load_elf_phdrs+0x76/0xa0
583 load_elf_binary+0x102/0x1650
584 search_binary_handler+0x97/0x1d0
585 do_execveat_common.isra.34+0x551/0x6e0
586 SyS_execve+0x3a/0x50
587 return_from_execve+0x0/0x23
588 } hitcount: 33348 bytes_req: 17152128 bytes_alloc: 20226048
589 { stacktrace:
590 kmem_cache_alloc_trace+0xeb/0x150
591 apparmor_file_alloc_security+0x27/0x40
592 security_file_alloc+0x16/0x20
593 get_empty_filp+0x93/0x1c0
594 path_openat+0x31/0x5f0
595 do_filp_open+0x3a/0x90
596 do_sys_open+0x128/0x220
597 SyS_open+0x1e/0x20
598 system_call_fastpath+0x12/0x6a
599 } hitcount: 4766422 bytes_req: 9532844 bytes_alloc: 38131376
600 { stacktrace:
601 __kmalloc+0x11b/0x1b0
602 seq_buf_alloc+0x1b/0x50
603 seq_read+0x2cc/0x370
604 proc_reg_read+0x3d/0x80
605 __vfs_read+0x28/0xe0
606 vfs_read+0x86/0x140
607 SyS_read+0x46/0xb0
608 system_call_fastpath+0x12/0x6a
609 } hitcount: 19133 bytes_req: 78368768 bytes_alloc: 78368768
610
611 Totals:
612 Hits: 6085872
613 Entries: 253
614 Dropped: 0
615
616 If you key a hist trigger on common_pid, in order for example to
617 gather and display sorted totals for each process, you can use the
618 special .execname modifier to display the executable names for the
619 processes in the table rather than raw pids. The example below
620 keeps a per-process sum of total bytes read:
621
622 # echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \
623 /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
624
625 # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/hist
626 # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active]
627
628 { common_pid: gnome-terminal [ 3196] } hitcount: 280 count: 1093512
629 { common_pid: Xorg [ 1309] } hitcount: 525 count: 256640
630 { common_pid: compiz [ 2889] } hitcount: 59 count: 254400
631 { common_pid: bash [ 8710] } hitcount: 3 count: 66369
632 { common_pid: dbus-daemon-lau [ 8703] } hitcount: 49 count: 47739
633 { common_pid: irqbalance [ 1252] } hitcount: 27 count: 27648
634 { common_pid: 01ifupdown [ 8705] } hitcount: 3 count: 17216
635 { common_pid: dbus-daemon [ 772] } hitcount: 10 count: 12396
636 { common_pid: Socket Thread [ 8342] } hitcount: 11 count: 11264
637 { common_pid: nm-dhcp-client. [ 8701] } hitcount: 6 count: 7424
638 { common_pid: gmain [ 1315] } hitcount: 18 count: 6336
639 .
640 .
641 .
642 { common_pid: postgres [ 1892] } hitcount: 2 count: 32
643 { common_pid: postgres [ 1891] } hitcount: 2 count: 32
644 { common_pid: gmain [ 8704] } hitcount: 2 count: 32
645 { common_pid: upstart-dbus-br [ 2740] } hitcount: 21 count: 21
646 { common_pid: nm-dispatcher.a [ 8696] } hitcount: 1 count: 16
647 { common_pid: indicator-datet [ 2904] } hitcount: 1 count: 16
648 { common_pid: gdbus [ 2998] } hitcount: 1 count: 16
649 { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8
650 { common_pid: init [ 1] } hitcount: 2 count: 2
651
652 Totals:
653 Hits: 2116
654 Entries: 51
655 Dropped: 0
656
657 Similarly, if you key a hist trigger on syscall id, for example to
658 gather and display a list of systemwide syscall hits, you can use
659 the special .syscall modifier to display the syscall names rather
660 than raw ids. The example below keeps a running total of syscall
661 counts for the system during the run:
662
663 # echo 'hist:key=id.syscall:val=hitcount' > \
664 /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
665
666 # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist
667 # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active]
668
669 { id: sys_fsync [ 74] } hitcount: 1
670 { id: sys_newuname [ 63] } hitcount: 1
671 { id: sys_prctl [157] } hitcount: 1
672 { id: sys_statfs [137] } hitcount: 1
673 { id: sys_symlink [ 88] } hitcount: 1
674 { id: sys_sendmmsg [307] } hitcount: 1
675 { id: sys_semctl [ 66] } hitcount: 1
676 { id: sys_readlink [ 89] } hitcount: 3
677 { id: sys_bind [ 49] } hitcount: 3
678 { id: sys_getsockname [ 51] } hitcount: 3
679 { id: sys_unlink [ 87] } hitcount: 3
680 { id: sys_rename [ 82] } hitcount: 4
681 { id: unknown_syscall [ 58] } hitcount: 4
682 { id: sys_connect [ 42] } hitcount: 4
683 { id: sys_getpid [ 39] } hitcount: 4
684 .
685 .
686 .
687 { id: sys_rt_sigprocmask [ 14] } hitcount: 952
688 { id: sys_futex [202] } hitcount: 1534
689 { id: sys_write [ 1] } hitcount: 2689
690 { id: sys_setitimer [ 38] } hitcount: 2797
691 { id: sys_read [ 0] } hitcount: 3202
692 { id: sys_select [ 23] } hitcount: 3773
693 { id: sys_writev [ 20] } hitcount: 4531
694 { id: sys_poll [ 7] } hitcount: 8314
695 { id: sys_recvmsg [ 47] } hitcount: 13738
696 { id: sys_ioctl [ 16] } hitcount: 21843
697
698 Totals:
699 Hits: 67612
700 Entries: 72
701 Dropped: 0
702
703 The syscall counts above provide a rough overall picture of system
704 call activity on the system; we can see for example that the most
705 popular system call on this system was the 'sys_ioctl' system call.
706
707 We can use 'compound' keys to refine that number and provide some
708 further insight as to which processes exactly contribute to the
709 overall ioctl count.
710
711 The command below keeps a hitcount for every unique combination of
712 system call id and pid - the end result is essentially a table
713 that keeps a per-pid sum of system call hits. The results are
714 sorted using the system call id as the primary key, and the
715 hitcount sum as the secondary key:
716
717 # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' > \
718 /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
719
720 # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist
721 # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active]
722
723 { id: sys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: 1
724 { id: sys_read [ 0], common_pid: gdbus [ 2976] } hitcount: 1
725 { id: sys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: 1
726 { id: sys_read [ 0], common_pid: postgres [ 1865] } hitcount: 1
727 { id: sys_read [ 0], common_pid: deja-dup-monito [ 3543] } hitcount: 2
728 { id: sys_read [ 0], common_pid: NetworkManager [ 890] } hitcount: 2
729 { id: sys_read [ 0], common_pid: evolution-calen [ 3048] } hitcount: 2
730 { id: sys_read [ 0], common_pid: postgres [ 1864] } hitcount: 2
731 { id: sys_read [ 0], common_pid: nm-applet [ 3022] } hitcount: 2
732 { id: sys_read [ 0], common_pid: whoopsie [ 1212] } hitcount: 2
733 .
734 .
735 .
736 { id: sys_ioctl [ 16], common_pid: bash [ 8479] } hitcount: 1
737 { id: sys_ioctl [ 16], common_pid: bash [ 3472] } hitcount: 12
738 { id: sys_ioctl [ 16], common_pid: gnome-terminal [ 3199] } hitcount: 16
739 { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 1808
740 { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 5580
741 .
742 .
743 .
744 { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2690] } hitcount: 3
745 { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2688] } hitcount: 16
746 { id: sys_inotify_add_watch [254], common_pid: gmain [ 975] } hitcount: 2
747 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3204] } hitcount: 4
748 { id: sys_inotify_add_watch [254], common_pid: gmain [ 2888] } hitcount: 4
749 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3003] } hitcount: 4
750 { id: sys_inotify_add_watch [254], common_pid: gmain [ 2873] } hitcount: 4
751 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3196] } hitcount: 6
752 { id: sys_openat [257], common_pid: java [ 2623] } hitcount: 2
753 { id: sys_eventfd2 [290], common_pid: ibus-ui-gtk3 [ 2760] } hitcount: 4
754 { id: sys_eventfd2 [290], common_pid: compiz [ 2994] } hitcount: 6
755
756 Totals:
757 Hits: 31536
758 Entries: 323
759 Dropped: 0
760
761 The above list does give us a breakdown of the ioctl syscall by
762 pid, but it also gives us quite a bit more than that, which we
763 don't really care about at the moment. Since we know the syscall
764 id for sys_ioctl (16, displayed next to the sys_ioctl name), we
765 can use that to filter out all the other syscalls:
766
767 # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount if id == 16' > \
768 /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
769
770 # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist
771 # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 if id == 16 [active]
772
773 { id: sys_ioctl [ 16], common_pid: gmain [ 2769] } hitcount: 1
774 { id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: 1
775 { id: sys_ioctl [ 16], common_pid: gmain [ 3003] } hitcount: 1
776 { id: sys_ioctl [ 16], common_pid: gmain [ 2781] } hitcount: 1
777 { id: sys_ioctl [ 16], common_pid: gmain [ 2829] } hitcount: 1
778 { id: sys_ioctl [ 16], common_pid: bash [ 8726] } hitcount: 1
779 { id: sys_ioctl [ 16], common_pid: bash [ 8508] } hitcount: 1
780 { id: sys_ioctl [ 16], common_pid: gmain [ 2970] } hitcount: 1
781 { id: sys_ioctl [ 16], common_pid: gmain [ 2768] } hitcount: 1
782 .
783 .
784 .
785 { id: sys_ioctl [ 16], common_pid: pool [ 8559] } hitcount: 45
786 { id: sys_ioctl [ 16], common_pid: pool [ 8555] } hitcount: 48
787 { id: sys_ioctl [ 16], common_pid: pool [ 8551] } hitcount: 48
788 { id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: 66
789 { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 26674
790 { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 73443
791
792 Totals:
793 Hits: 101162
794 Entries: 103
795 Dropped: 0
796
797 The above output shows that 'compiz' and 'Xorg' are far and away
798 the heaviest ioctl callers (which might lead to questions about
799 whether they really need to be making all those calls and to
800 possible avenues for further investigation.)
801
802 The compound key examples used a key and a sum value (hitcount) to
803 sort the output, but we can just as easily use two keys instead.
804 Here's an example where we use a compound key composed of the the
805 common_pid and size event fields. Sorting with pid as the primary
806 key and 'size' as the secondary key allows us to display an
807 ordered summary of the recvfrom sizes, with counts, received by
808 each process:
809
810 # echo 'hist:key=common_pid.execname,size:val=hitcount:sort=common_pid,size' > \
811 /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/trigger
812
813 # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/hist
814 # trigger info: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:size=2048 [active]
815
816 { common_pid: smbd [ 784], size: 4 } hitcount: 1
817 { common_pid: dnsmasq [ 1412], size: 4096 } hitcount: 672
818 { common_pid: postgres [ 1796], size: 1000 } hitcount: 6
819 { common_pid: postgres [ 1867], size: 1000 } hitcount: 10
820 { common_pid: bamfdaemon [ 2787], size: 28 } hitcount: 2
821 { common_pid: bamfdaemon [ 2787], size: 14360 } hitcount: 1
822 { common_pid: compiz [ 2994], size: 8 } hitcount: 1
823 { common_pid: compiz [ 2994], size: 20 } hitcount: 11
824 { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2
825 { common_pid: firefox [ 8817], size: 4 } hitcount: 1
826 { common_pid: firefox [ 8817], size: 8 } hitcount: 5
827 { common_pid: firefox [ 8817], size: 588 } hitcount: 2
828 { common_pid: firefox [ 8817], size: 628 } hitcount: 1
829 { common_pid: firefox [ 8817], size: 6944 } hitcount: 1
830 { common_pid: firefox [ 8817], size: 408880 } hitcount: 2
831 { common_pid: firefox [ 8822], size: 8 } hitcount: 2
832 { common_pid: firefox [ 8822], size: 160 } hitcount: 2
833 { common_pid: firefox [ 8822], size: 320 } hitcount: 2
834 { common_pid: firefox [ 8822], size: 352 } hitcount: 1
835 .
836 .
837 .
838 { common_pid: pool [ 8923], size: 1960 } hitcount: 10
839 { common_pid: pool [ 8923], size: 2048 } hitcount: 10
840 { common_pid: pool [ 8924], size: 1960 } hitcount: 10
841 { common_pid: pool [ 8924], size: 2048 } hitcount: 10
842 { common_pid: pool [ 8928], size: 1964 } hitcount: 4
843 { common_pid: pool [ 8928], size: 1965 } hitcount: 2
844 { common_pid: pool [ 8928], size: 2048 } hitcount: 6
845 { common_pid: pool [ 8929], size: 1982 } hitcount: 1
846 { common_pid: pool [ 8929], size: 2048 } hitcount: 1
847
848 Totals:
849 Hits: 2016
850 Entries: 224
851 Dropped: 0
852
853 The above example also illustrates the fact that although a compound
854 key is treated as a single entity for hashing purposes, the sub-keys
855 it's composed of can be accessed independently.
856
857 The next example uses a string field as the hash key and
858 demonstrates how you can manually pause and continue a hist trigger.
859 In this example, we'll aggregate fork counts and don't expect a
860 large number of entries in the hash table, so we'll drop it to a
861 much smaller number, say 256:
862
863 # echo 'hist:key=child_comm:val=hitcount:size=256' > \
864 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
865
866 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
867 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active]
868
869 { child_comm: dconf worker } hitcount: 1
870 { child_comm: ibus-daemon } hitcount: 1
871 { child_comm: whoopsie } hitcount: 1
872 { child_comm: smbd } hitcount: 1
873 { child_comm: gdbus } hitcount: 1
874 { child_comm: kthreadd } hitcount: 1
875 { child_comm: dconf worker } hitcount: 1
876 { child_comm: evolution-alarm } hitcount: 2
877 { child_comm: Socket Thread } hitcount: 2
878 { child_comm: postgres } hitcount: 2
879 { child_comm: bash } hitcount: 3
880 { child_comm: compiz } hitcount: 3
881 { child_comm: evolution-sourc } hitcount: 4
882 { child_comm: dhclient } hitcount: 4
883 { child_comm: pool } hitcount: 5
884 { child_comm: nm-dispatcher.a } hitcount: 8
885 { child_comm: firefox } hitcount: 8
886 { child_comm: dbus-daemon } hitcount: 8
887 { child_comm: glib-pacrunner } hitcount: 10
888 { child_comm: evolution } hitcount: 23
889
890 Totals:
891 Hits: 89
892 Entries: 20
893 Dropped: 0
894
895 If we want to pause the hist trigger, we can simply append :pause to
896 the command that started the trigger. Notice that the trigger info
897 displays as [paused]:
898
899 # echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \
900 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
901
902 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
903 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [paused]
904
905 { child_comm: dconf worker } hitcount: 1
906 { child_comm: kthreadd } hitcount: 1
907 { child_comm: dconf worker } hitcount: 1
908 { child_comm: gdbus } hitcount: 1
909 { child_comm: ibus-daemon } hitcount: 1
910 { child_comm: Socket Thread } hitcount: 2
911 { child_comm: evolution-alarm } hitcount: 2
912 { child_comm: smbd } hitcount: 2
913 { child_comm: bash } hitcount: 3
914 { child_comm: whoopsie } hitcount: 3
915 { child_comm: compiz } hitcount: 3
916 { child_comm: evolution-sourc } hitcount: 4
917 { child_comm: pool } hitcount: 5
918 { child_comm: postgres } hitcount: 6
919 { child_comm: firefox } hitcount: 8
920 { child_comm: dhclient } hitcount: 10
921 { child_comm: emacs } hitcount: 12
922 { child_comm: dbus-daemon } hitcount: 20
923 { child_comm: nm-dispatcher.a } hitcount: 20
924 { child_comm: evolution } hitcount: 35
925 { child_comm: glib-pacrunner } hitcount: 59
926
927 Totals:
928 Hits: 199
929 Entries: 21
930 Dropped: 0
931
932 To manually continue having the trigger aggregate events, append
933 :cont instead. Notice that the trigger info displays as [active]
934 again, and the data has changed:
935
936 # echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \
937 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
938
939 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
940 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active]
941
942 { child_comm: dconf worker } hitcount: 1
943 { child_comm: dconf worker } hitcount: 1
944 { child_comm: kthreadd } hitcount: 1
945 { child_comm: gdbus } hitcount: 1
946 { child_comm: ibus-daemon } hitcount: 1
947 { child_comm: Socket Thread } hitcount: 2
948 { child_comm: evolution-alarm } hitcount: 2
949 { child_comm: smbd } hitcount: 2
950 { child_comm: whoopsie } hitcount: 3
951 { child_comm: compiz } hitcount: 3
952 { child_comm: evolution-sourc } hitcount: 4
953 { child_comm: bash } hitcount: 5
954 { child_comm: pool } hitcount: 5
955 { child_comm: postgres } hitcount: 6
956 { child_comm: firefox } hitcount: 8
957 { child_comm: dhclient } hitcount: 11
958 { child_comm: emacs } hitcount: 12
959 { child_comm: dbus-daemon } hitcount: 22
960 { child_comm: nm-dispatcher.a } hitcount: 22
961 { child_comm: evolution } hitcount: 35
962 { child_comm: glib-pacrunner } hitcount: 59
963
964 Totals:
965 Hits: 206
966 Entries: 21
967 Dropped: 0
968
969 The previous example showed how to start and stop a hist trigger by
970 appending 'pause' and 'continue' to the hist trigger command. A
971 hist trigger can also be started in a paused state by initially
972 starting the trigger with ':pause' appended. This allows you to
973 start the trigger only when you're ready to start collecting data
974 and not before. For example, you could start the trigger in a
975 paused state, then unpause it and do something you want to measure,
976 then pause the trigger again when done.
977
978 Of course, doing this manually can be difficult and error-prone, but
979 it is possible to automatically start and stop a hist trigger based
980 on some condition, via the enable_hist and disable_hist triggers.
981
982 For example, suppose we wanted to take a look at the relative
983 weights in terms of skb length for each callpath that leads to a
984 netif_receieve_skb event when downloading a decent-sized file using
985 wget.
986
987 First we set up an initially paused stacktrace trigger on the
988 netif_receive_skb event:
989
990 # echo 'hist:key=stacktrace:vals=len:pause' > \
991 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
992
993 Next, we set up an 'enable_hist' trigger on the sched_process_exec
994 event, with an 'if filename==/usr/bin/wget' filter. The effect of
995 this new trigger is that it will 'unpause' the hist trigger we just
996 set up on netif_receive_skb if and only if it sees a
997 sched_process_exec event with a filename of '/usr/bin/wget'. When
998 that happens, all netif_receive_skb events are aggregated into a
999 hash table keyed on stacktrace:
1000
1001 # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \
1002 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
1003
1004 The aggregation continues until the netif_receive_skb is paused
1005 again, which is what the following disable_hist event does by
1006 creating a similar setup on the sched_process_exit event, using the
1007 filter 'comm==wget':
1008
1009 # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \
1010 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
1011
1012 Whenever a process exits and the comm field of the disable_hist
1013 trigger filter matches 'comm==wget', the netif_receive_skb hist
1014 trigger is disabled.
1015
1016 The overall effect is that netif_receive_skb events are aggregated
1017 into the hash table for only the duration of the wget. Executing a
1018 wget command and then listing the 'hist' file will display the
1019 output generated by the wget command:
1020
1021 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1022
1023 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
1024 # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused]
1025
1026 { stacktrace:
1027 __netif_receive_skb_core+0x46d/0x990
1028 __netif_receive_skb+0x18/0x60
1029 netif_receive_skb_internal+0x23/0x90
1030 napi_gro_receive+0xc8/0x100
1031 ieee80211_deliver_skb+0xd6/0x270 [mac80211]
1032 ieee80211_rx_handlers+0xccf/0x22f0 [mac80211]
1033 ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211]
1034 ieee80211_rx+0x31d/0x900 [mac80211]
1035 iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm]
1036 iwl_rx_dispatch+0x8e/0xf0 [iwldvm]
1037 iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi]
1038 irq_thread_fn+0x20/0x50
1039 irq_thread+0x11f/0x150
1040 kthread+0xd2/0xf0
1041 ret_from_fork+0x42/0x70
1042 } hitcount: 85 len: 28884
1043 { stacktrace:
1044 __netif_receive_skb_core+0x46d/0x990
1045 __netif_receive_skb+0x18/0x60
1046 netif_receive_skb_internal+0x23/0x90
1047 napi_gro_complete+0xa4/0xe0
1048 dev_gro_receive+0x23a/0x360
1049 napi_gro_receive+0x30/0x100
1050 ieee80211_deliver_skb+0xd6/0x270 [mac80211]
1051 ieee80211_rx_handlers+0xccf/0x22f0 [mac80211]
1052 ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211]
1053 ieee80211_rx+0x31d/0x900 [mac80211]
1054 iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm]
1055 iwl_rx_dispatch+0x8e/0xf0 [iwldvm]
1056 iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi]
1057 irq_thread_fn+0x20/0x50
1058 irq_thread+0x11f/0x150
1059 kthread+0xd2/0xf0
1060 } hitcount: 98 len: 664329
1061 { stacktrace:
1062 __netif_receive_skb_core+0x46d/0x990
1063 __netif_receive_skb+0x18/0x60
1064 process_backlog+0xa8/0x150
1065 net_rx_action+0x15d/0x340
1066 __do_softirq+0x114/0x2c0
1067 do_softirq_own_stack+0x1c/0x30
1068 do_softirq+0x65/0x70
1069 __local_bh_enable_ip+0xb5/0xc0
1070 ip_finish_output+0x1f4/0x840
1071 ip_output+0x6b/0xc0
1072 ip_local_out_sk+0x31/0x40
1073 ip_send_skb+0x1a/0x50
1074 udp_send_skb+0x173/0x2a0
1075 udp_sendmsg+0x2bf/0x9f0
1076 inet_sendmsg+0x64/0xa0
1077 sock_sendmsg+0x3d/0x50
1078 } hitcount: 115 len: 13030
1079 { stacktrace:
1080 __netif_receive_skb_core+0x46d/0x990
1081 __netif_receive_skb+0x18/0x60
1082 netif_receive_skb_internal+0x23/0x90
1083 napi_gro_complete+0xa4/0xe0
1084 napi_gro_flush+0x6d/0x90
1085 iwl_pcie_irq_handler+0x92a/0x12f0 [iwlwifi]
1086 irq_thread_fn+0x20/0x50
1087 irq_thread+0x11f/0x150
1088 kthread+0xd2/0xf0
1089 ret_from_fork+0x42/0x70
1090 } hitcount: 934 len: 5512212
1091
1092 Totals:
1093 Hits: 1232
1094 Entries: 4
1095 Dropped: 0
1096
1097 The above shows all the netif_receive_skb callpaths and their total
1098 lengths for the duration of the wget command.
1099
1100 The 'clear' hist trigger param can be used to clear the hash table.
1101 Suppose we wanted to try another run of the previous example but
1102 this time also wanted to see the complete list of events that went
1103 into the histogram. In order to avoid having to set everything up
1104 again, we can just clear the histogram first:
1105
1106 # echo 'hist:key=stacktrace:vals=len:clear' >> \
1107 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1108
1109 Just to verify that it is in fact cleared, here's what we now see in
1110 the hist file:
1111
1112 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
1113 # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused]
1114
1115 Totals:
1116 Hits: 0
1117 Entries: 0
1118 Dropped: 0
1119
1120 Since we want to see the detailed list of every netif_receive_skb
1121 event occurring during the new run, which are in fact the same
1122 events being aggregated into the hash table, we add some additional
1123 'enable_event' events to the triggering sched_process_exec and
1124 sched_process_exit events as such:
1125
1126 # echo 'enable_event:net:netif_receive_skb if filename==/usr/bin/wget' > \
1127 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
1128
1129 # echo 'disable_event:net:netif_receive_skb if comm==wget' > \
1130 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
1131
1132 If you read the trigger files for the sched_process_exec and
1133 sched_process_exit triggers, you should see two triggers for each:
1134 one enabling/disabling the hist aggregation and the other
1135 enabling/disabling the logging of events:
1136
1137 # cat /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
1138 enable_event:net:netif_receive_skb:unlimited if filename==/usr/bin/wget
1139 enable_hist:net:netif_receive_skb:unlimited if filename==/usr/bin/wget
1140
1141 # cat /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
1142 enable_event:net:netif_receive_skb:unlimited if comm==wget
1143 disable_hist:net:netif_receive_skb:unlimited if comm==wget
1144
1145 In other words, whenever either of the sched_process_exec or
1146 sched_process_exit events is hit and matches 'wget', it enables or
1147 disables both the histogram and the event log, and what you end up
1148 with is a hash table and set of events just covering the specified
1149 duration. Run the wget command again:
1150
1151 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1152
1153 Displaying the 'hist' file should show something similar to what you
1154 saw in the last run, but this time you should also see the
1155 individual events in the trace file:
1156
1157 # cat /sys/kernel/debug/tracing/trace
1158
1159 # tracer: nop
1160 #
1161 # entries-in-buffer/entries-written: 183/1426 #P:4
1162 #
1163 # _-----=> irqs-off
1164 # / _----=> need-resched
1165 # | / _---=> hardirq/softirq
1166 # || / _--=> preempt-depth
1167 # ||| / delay
1168 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
1169 # | | | |||| | |
1170 wget-15108 [000] ..s1 31769.606929: netif_receive_skb: dev=lo skbaddr=ffff88009c353100 len=60
1171 wget-15108 [000] ..s1 31769.606999: netif_receive_skb: dev=lo skbaddr=ffff88009c353200 len=60
1172 dnsmasq-1382 [000] ..s1 31769.677652: netif_receive_skb: dev=lo skbaddr=ffff88009c352b00 len=130
1173 dnsmasq-1382 [000] ..s1 31769.685917: netif_receive_skb: dev=lo skbaddr=ffff88009c352200 len=138
1174 ##### CPU 2 buffer started ####
1175 irq/29-iwlwifi-559 [002] ..s. 31772.031529: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433d00 len=2948
1176 irq/29-iwlwifi-559 [002] ..s. 31772.031572: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432200 len=1500
1177 irq/29-iwlwifi-559 [002] ..s. 31772.032196: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433100 len=2948
1178 irq/29-iwlwifi-559 [002] ..s. 31772.032761: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433000 len=2948
1179 irq/29-iwlwifi-559 [002] ..s. 31772.033220: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432e00 len=1500
1180 .
1181 .
1182 .
1183
1184 The following example demonstrates how multiple hist triggers can be
1185 attached to a given event. This capability can be useful for
1186 creating a set of different summaries derived from the same set of
1187 events, or for comparing the effects of different filters, among
1188 other things.
1189
1190 # echo 'hist:keys=skbaddr.hex:vals=len if len < 0' >> \
1191 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1192 # echo 'hist:keys=skbaddr.hex:vals=len if len > 4096' >> \
1193 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1194 # echo 'hist:keys=skbaddr.hex:vals=len if len == 256' >> \
1195 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1196 # echo 'hist:keys=skbaddr.hex:vals=len' >> \
1197 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1198 # echo 'hist:keys=len:vals=common_preempt_count' >> \
1199 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1200
1201 The above set of commands create four triggers differing only in
1202 their filters, along with a completely different though fairly
1203 nonsensical trigger. Note that in order to append multiple hist
1204 triggers to the same file, you should use the '>>' operator to
1205 append them ('>' will also add the new hist trigger, but will remove
1206 any existing hist triggers beforehand).
1207
1208 Displaying the contents of the 'hist' file for the event shows the
1209 contents of all five histograms:
1210
1211 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
1212
1213 # event histogram
1214 #
1215 # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active]
1216 #
1217
1218 { len: 176 } hitcount: 1 common_preempt_count: 0
1219 { len: 223 } hitcount: 1 common_preempt_count: 0
1220 { len: 4854 } hitcount: 1 common_preempt_count: 0
1221 { len: 395 } hitcount: 1 common_preempt_count: 0
1222 { len: 177 } hitcount: 1 common_preempt_count: 0
1223 { len: 446 } hitcount: 1 common_preempt_count: 0
1224 { len: 1601 } hitcount: 1 common_preempt_count: 0
1225 .
1226 .
1227 .
1228 { len: 1280 } hitcount: 66 common_preempt_count: 0
1229 { len: 116 } hitcount: 81 common_preempt_count: 40
1230 { len: 708 } hitcount: 112 common_preempt_count: 0
1231 { len: 46 } hitcount: 221 common_preempt_count: 0
1232 { len: 1264 } hitcount: 458 common_preempt_count: 0
1233
1234 Totals:
1235 Hits: 1428
1236 Entries: 147
1237 Dropped: 0
1238
1239
1240 # event histogram
1241 #
1242 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1243 #
1244
1245 { skbaddr: ffff8800baee5e00 } hitcount: 1 len: 130
1246 { skbaddr: ffff88005f3d5600 } hitcount: 1 len: 1280
1247 { skbaddr: ffff88005f3d4900 } hitcount: 1 len: 1280
1248 { skbaddr: ffff88009fed6300 } hitcount: 1 len: 115
1249 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 115
1250 { skbaddr: ffff88008cdb1900 } hitcount: 1 len: 46
1251 { skbaddr: ffff880064b5ef00 } hitcount: 1 len: 118
1252 { skbaddr: ffff880044e3c700 } hitcount: 1 len: 60
1253 { skbaddr: ffff880100065900 } hitcount: 1 len: 46
1254 { skbaddr: ffff8800d46bd500 } hitcount: 1 len: 116
1255 { skbaddr: ffff88005f3d5f00 } hitcount: 1 len: 1280
1256 { skbaddr: ffff880100064700 } hitcount: 1 len: 365
1257 { skbaddr: ffff8800badb6f00 } hitcount: 1 len: 60
1258 .
1259 .
1260 .
1261 { skbaddr: ffff88009fe0be00 } hitcount: 27 len: 24677
1262 { skbaddr: ffff88009fe0a400 } hitcount: 27 len: 23052
1263 { skbaddr: ffff88009fe0b700 } hitcount: 31 len: 25589
1264 { skbaddr: ffff88009fe0b600 } hitcount: 32 len: 27326
1265 { skbaddr: ffff88006a462800 } hitcount: 68 len: 71678
1266 { skbaddr: ffff88006a463700 } hitcount: 70 len: 72678
1267 { skbaddr: ffff88006a462b00 } hitcount: 71 len: 77589
1268 { skbaddr: ffff88006a463600 } hitcount: 73 len: 71307
1269 { skbaddr: ffff88006a462200 } hitcount: 81 len: 81032
1270
1271 Totals:
1272 Hits: 1451
1273 Entries: 318
1274 Dropped: 0
1275
1276
1277 # event histogram
1278 #
1279 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [active]
1280 #
1281
1282
1283 Totals:
1284 Hits: 0
1285 Entries: 0
1286 Dropped: 0
1287
1288
1289 # event histogram
1290 #
1291 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [active]
1292 #
1293
1294 { skbaddr: ffff88009fd2c300 } hitcount: 1 len: 7212
1295 { skbaddr: ffff8800d2bcce00 } hitcount: 1 len: 7212
1296 { skbaddr: ffff8800d2bcd700 } hitcount: 1 len: 7212
1297 { skbaddr: ffff8800d2bcda00 } hitcount: 1 len: 21492
1298 { skbaddr: ffff8800ae2e2d00 } hitcount: 1 len: 7212
1299 { skbaddr: ffff8800d2bcdb00 } hitcount: 1 len: 7212
1300 { skbaddr: ffff88006a4df500 } hitcount: 1 len: 4854
1301 { skbaddr: ffff88008ce47b00 } hitcount: 1 len: 18636
1302 { skbaddr: ffff8800ae2e2200 } hitcount: 1 len: 12924
1303 { skbaddr: ffff88005f3e1000 } hitcount: 1 len: 4356
1304 { skbaddr: ffff8800d2bcdc00 } hitcount: 2 len: 24420
1305 { skbaddr: ffff8800d2bcc200 } hitcount: 2 len: 12996
1306
1307 Totals:
1308 Hits: 14
1309 Entries: 12
1310 Dropped: 0
1311
1312
1313 # event histogram
1314 #
1315 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active]
1316 #
1317
1318
1319 Totals:
1320 Hits: 0
1321 Entries: 0
1322 Dropped: 0
1323
1324 Named triggers can be used to have triggers share a common set of
1325 histogram data. This capability is mostly useful for combining the
1326 output of events generated by tracepoints contained inside inline
1327 functions, but names can be used in a hist trigger on any event.
1328 For example, these two triggers when hit will update the same 'len'
1329 field in the shared 'foo' histogram data:
1330
1331 # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \
1332 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1333 # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \
1334 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
1335
1336 You can see that they're updating common histogram data by reading
1337 each event's hist files at the same time:
1338
1339 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist;
1340 cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
1341
1342 # event histogram
1343 #
1344 # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1345 #
1346
1347 { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46
1348 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76
1349 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46
1350 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468
1351 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46
1352 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52
1353 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168
1354 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46
1355 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260
1356 { skbaddr: ffff880064505000 } hitcount: 1 len: 46
1357 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32
1358 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46
1359 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44
1360 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168
1361 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40
1362 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40
1363 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174
1364 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160
1365 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76
1366 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46
1367 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32
1368 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46
1369 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988
1370 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46
1371 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44
1372 { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676
1373 { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107
1374 { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92
1375 { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142
1376 { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220
1377 { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92
1378 { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92
1379 { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675
1380 { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138
1381 { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138
1382 { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184
1383 { skbaddr: ffff880064504400 } hitcount: 4 len: 184
1384 { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184
1385 { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230
1386 { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196
1387 { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276
1388 { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276
1389
1390 Totals:
1391 Hits: 81
1392 Entries: 42
1393 Dropped: 0
1394 # event histogram
1395 #
1396 # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1397 #
1398
1399 { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46
1400 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76
1401 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46
1402 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468
1403 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46
1404 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52
1405 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168
1406 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46
1407 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260
1408 { skbaddr: ffff880064505000 } hitcount: 1 len: 46
1409 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32
1410 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46
1411 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44
1412 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168
1413 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40
1414 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40
1415 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174
1416 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160
1417 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76
1418 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46
1419 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32
1420 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46
1421 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988
1422 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46
1423 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44
1424 { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676
1425 { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107
1426 { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92
1427 { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142
1428 { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220
1429 { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92
1430 { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92
1431 { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675
1432 { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138
1433 { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138
1434 { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184
1435 { skbaddr: ffff880064504400 } hitcount: 4 len: 184
1436 { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184
1437 { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230
1438 { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196
1439 { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276
1440 { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276
1441
1442 Totals:
1443 Hits: 81
1444 Entries: 42
1445 Dropped: 0
1446
1447 And here's an example that shows how to combine histogram data from
1448 any two events even if they don't share any 'compatible' fields
1449 other than 'hitcount' and 'stacktrace'. These commands create a
1450 couple of triggers named 'bar' using those fields:
1451
1452 # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \
1453 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
1454 # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \
1455 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
1456
1457 And displaying the output of either shows some interesting if
1458 somewhat confusing output:
1459
1460 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
1461 # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
1462
1463 # event histogram
1464 #
1465 # trigger info: hist:name=bar:keys=stacktrace:vals=hitcount:sort=hitcount:size=2048 [active]
1466 #
1467
1468 { stacktrace:
1469 _do_fork+0x18e/0x330
1470 kernel_thread+0x29/0x30
1471 kthreadd+0x154/0x1b0
1472 ret_from_fork+0x3f/0x70
1473 } hitcount: 1
1474 { stacktrace:
1475 netif_rx_internal+0xb2/0xd0
1476 netif_rx_ni+0x20/0x70
1477 dev_loopback_xmit+0xaa/0xd0
1478 ip_mc_output+0x126/0x240
1479 ip_local_out_sk+0x31/0x40
1480 igmp_send_report+0x1e9/0x230
1481 igmp_timer_expire+0xe9/0x120
1482 call_timer_fn+0x39/0xf0
1483 run_timer_softirq+0x1e1/0x290
1484 __do_softirq+0xfd/0x290
1485 irq_exit+0x98/0xb0
1486 smp_apic_timer_interrupt+0x4a/0x60
1487 apic_timer_interrupt+0x6d/0x80
1488 cpuidle_enter+0x17/0x20
1489 call_cpuidle+0x3b/0x60
1490 cpu_startup_entry+0x22d/0x310
1491 } hitcount: 1
1492 { stacktrace:
1493 netif_rx_internal+0xb2/0xd0
1494 netif_rx_ni+0x20/0x70
1495 dev_loopback_xmit+0xaa/0xd0
1496 ip_mc_output+0x17f/0x240
1497 ip_local_out_sk+0x31/0x40
1498 ip_send_skb+0x1a/0x50
1499 udp_send_skb+0x13e/0x270
1500 udp_sendmsg+0x2bf/0x980
1501 inet_sendmsg+0x67/0xa0
1502 sock_sendmsg+0x38/0x50
1503 SYSC_sendto+0xef/0x170
1504 SyS_sendto+0xe/0x10
1505 entry_SYSCALL_64_fastpath+0x12/0x6a
1506 } hitcount: 2
1507 { stacktrace:
1508 netif_rx_internal+0xb2/0xd0
1509 netif_rx+0x1c/0x60
1510 loopback_xmit+0x6c/0xb0
1511 dev_hard_start_xmit+0x219/0x3a0
1512 __dev_queue_xmit+0x415/0x4f0
1513 dev_queue_xmit_sk+0x13/0x20
1514 ip_finish_output2+0x237/0x340
1515 ip_finish_output+0x113/0x1d0
1516 ip_output+0x66/0xc0
1517 ip_local_out_sk+0x31/0x40
1518 ip_send_skb+0x1a/0x50
1519 udp_send_skb+0x16d/0x270
1520 udp_sendmsg+0x2bf/0x980
1521 inet_sendmsg+0x67/0xa0
1522 sock_sendmsg+0x38/0x50
1523 ___sys_sendmsg+0x14e/0x270
1524 } hitcount: 76
1525 { stacktrace:
1526 netif_rx_internal+0xb2/0xd0
1527 netif_rx+0x1c/0x60
1528 loopback_xmit+0x6c/0xb0
1529 dev_hard_start_xmit+0x219/0x3a0
1530 __dev_queue_xmit+0x415/0x4f0
1531 dev_queue_xmit_sk+0x13/0x20
1532 ip_finish_output2+0x237/0x340
1533 ip_finish_output+0x113/0x1d0
1534 ip_output+0x66/0xc0
1535 ip_local_out_sk+0x31/0x40
1536 ip_send_skb+0x1a/0x50
1537 udp_send_skb+0x16d/0x270
1538 udp_sendmsg+0x2bf/0x980
1539 inet_sendmsg+0x67/0xa0
1540 sock_sendmsg+0x38/0x50
1541 ___sys_sendmsg+0x269/0x270
1542 } hitcount: 77
1543 { stacktrace:
1544 netif_rx_internal+0xb2/0xd0
1545 netif_rx+0x1c/0x60
1546 loopback_xmit+0x6c/0xb0
1547 dev_hard_start_xmit+0x219/0x3a0
1548 __dev_queue_xmit+0x415/0x4f0
1549 dev_queue_xmit_sk+0x13/0x20
1550 ip_finish_output2+0x237/0x340
1551 ip_finish_output+0x113/0x1d0
1552 ip_output+0x66/0xc0
1553 ip_local_out_sk+0x31/0x40
1554 ip_send_skb+0x1a/0x50
1555 udp_send_skb+0x16d/0x270
1556 udp_sendmsg+0x2bf/0x980
1557 inet_sendmsg+0x67/0xa0
1558 sock_sendmsg+0x38/0x50
1559 SYSC_sendto+0xef/0x170
1560 } hitcount: 88
1561 { stacktrace:
1562 _do_fork+0x18e/0x330
1563 SyS_clone+0x19/0x20
1564 entry_SYSCALL_64_fastpath+0x12/0x6a
1565 } hitcount: 244
1566
1567 Totals:
1568 Hits: 489
1569 Entries: 7
1570 Dropped: 0