]> git.proxmox.com Git - mirror_ubuntu-bionic-kernel.git/blob - Documentation/trace/events.txt
Merge branch 'soc-fixes' into omap-for-v4.15/fixes
[mirror_ubuntu-bionic-kernel.git] / Documentation / trace / events.txt
1 Event Tracing
2
3 Documentation written by Theodore Ts'o
4 Updated by Li Zefan and Tom Zanussi
5
6 1. Introduction
7 ===============
8
9 Tracepoints (see Documentation/trace/tracepoints.txt) can be used
10 without creating custom kernel modules to register probe functions
11 using the event tracing infrastructure.
12
13 Not all tracepoints can be traced using the event tracing system;
14 the kernel developer must provide code snippets which define how the
15 tracing information is saved into the tracing buffer, and how the
16 tracing information should be printed.
17
18 2. Using Event Tracing
19 ======================
20
21 2.1 Via the 'set_event' interface
22 ---------------------------------
23
24 The events which are available for tracing can be found in the file
25 /sys/kernel/debug/tracing/available_events.
26
27 To enable a particular event, such as 'sched_wakeup', simply echo it
28 to /sys/kernel/debug/tracing/set_event. For example:
29
30 # echo sched_wakeup >> /sys/kernel/debug/tracing/set_event
31
32 [ Note: '>>' is necessary, otherwise it will firstly disable
33 all the events. ]
34
35 To disable an event, echo the event name to the set_event file prefixed
36 with an exclamation point:
37
38 # echo '!sched_wakeup' >> /sys/kernel/debug/tracing/set_event
39
40 To disable all events, echo an empty line to the set_event file:
41
42 # echo > /sys/kernel/debug/tracing/set_event
43
44 To enable all events, echo '*:*' or '*:' to the set_event file:
45
46 # echo *:* > /sys/kernel/debug/tracing/set_event
47
48 The events are organized into subsystems, such as ext4, irq, sched,
49 etc., and a full event name looks like this: <subsystem>:<event>. The
50 subsystem name is optional, but it is displayed in the available_events
51 file. All of the events in a subsystem can be specified via the syntax
52 "<subsystem>:*"; for example, to enable all irq events, you can use the
53 command:
54
55 # echo 'irq:*' > /sys/kernel/debug/tracing/set_event
56
57 2.2 Via the 'enable' toggle
58 ---------------------------
59
60 The events available are also listed in /sys/kernel/debug/tracing/events/ hierarchy
61 of directories.
62
63 To enable event 'sched_wakeup':
64
65 # echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
66
67 To disable it:
68
69 # echo 0 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
70
71 To enable all events in sched subsystem:
72
73 # echo 1 > /sys/kernel/debug/tracing/events/sched/enable
74
75 To enable all events:
76
77 # echo 1 > /sys/kernel/debug/tracing/events/enable
78
79 When reading one of these enable files, there are four results:
80
81 0 - all events this file affects are disabled
82 1 - all events this file affects are enabled
83 X - there is a mixture of events enabled and disabled
84 ? - this file does not affect any event
85
86 2.3 Boot option
87 ---------------
88
89 In order to facilitate early boot debugging, use boot option:
90
91 trace_event=[event-list]
92
93 event-list is a comma separated list of events. See section 2.1 for event
94 format.
95
96 3. Defining an event-enabled tracepoint
97 =======================================
98
99 See The example provided in samples/trace_events
100
101 4. Event formats
102 ================
103
104 Each trace event has a 'format' file associated with it that contains
105 a description of each field in a logged event. This information can
106 be used to parse the binary trace stream, and is also the place to
107 find the field names that can be used in event filters (see section 5).
108
109 It also displays the format string that will be used to print the
110 event in text mode, along with the event name and ID used for
111 profiling.
112
113 Every event has a set of 'common' fields associated with it; these are
114 the fields prefixed with 'common_'. The other fields vary between
115 events and correspond to the fields defined in the TRACE_EVENT
116 definition for that event.
117
118 Each field in the format has the form:
119
120 field:field-type field-name; offset:N; size:N;
121
122 where offset is the offset of the field in the trace record and size
123 is the size of the data item, in bytes.
124
125 For example, here's the information displayed for the 'sched_wakeup'
126 event:
127
128 # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/format
129
130 name: sched_wakeup
131 ID: 60
132 format:
133 field:unsigned short common_type; offset:0; size:2;
134 field:unsigned char common_flags; offset:2; size:1;
135 field:unsigned char common_preempt_count; offset:3; size:1;
136 field:int common_pid; offset:4; size:4;
137 field:int common_tgid; offset:8; size:4;
138
139 field:char comm[TASK_COMM_LEN]; offset:12; size:16;
140 field:pid_t pid; offset:28; size:4;
141 field:int prio; offset:32; size:4;
142 field:int success; offset:36; size:4;
143 field:int cpu; offset:40; size:4;
144
145 print fmt: "task %s:%d [%d] success=%d [%03d]", REC->comm, REC->pid,
146 REC->prio, REC->success, REC->cpu
147
148 This event contains 10 fields, the first 5 common and the remaining 5
149 event-specific. All the fields for this event are numeric, except for
150 'comm' which is a string, a distinction important for event filtering.
151
152 5. Event filtering
153 ==================
154
155 Trace events can be filtered in the kernel by associating boolean
156 'filter expressions' with them. As soon as an event is logged into
157 the trace buffer, its fields are checked against the filter expression
158 associated with that event type. An event with field values that
159 'match' the filter will appear in the trace output, and an event whose
160 values don't match will be discarded. An event with no filter
161 associated with it matches everything, and is the default when no
162 filter has been set for an event.
163
164 5.1 Expression syntax
165 ---------------------
166
167 A filter expression consists of one or more 'predicates' that can be
168 combined using the logical operators '&&' and '||'. A predicate is
169 simply a clause that compares the value of a field contained within a
170 logged event with a constant value and returns either 0 or 1 depending
171 on whether the field value matched (1) or didn't match (0):
172
173 field-name relational-operator value
174
175 Parentheses can be used to provide arbitrary logical groupings and
176 double-quotes can be used to prevent the shell from interpreting
177 operators as shell metacharacters.
178
179 The field-names available for use in filters can be found in the
180 'format' files for trace events (see section 4).
181
182 The relational-operators depend on the type of the field being tested:
183
184 The operators available for numeric fields are:
185
186 ==, !=, <, <=, >, >=, &
187
188 And for string fields they are:
189
190 ==, !=, ~
191
192 The glob (~) accepts a wild card character (*,?) and character classes
193 ([). For example:
194
195 prev_comm ~ "*sh"
196 prev_comm ~ "sh*"
197 prev_comm ~ "*sh*"
198 prev_comm ~ "ba*sh"
199
200 5.2 Setting filters
201 -------------------
202
203 A filter for an individual event is set by writing a filter expression
204 to the 'filter' file for the given event.
205
206 For example:
207
208 # cd /sys/kernel/debug/tracing/events/sched/sched_wakeup
209 # echo "common_preempt_count > 4" > filter
210
211 A slightly more involved example:
212
213 # cd /sys/kernel/debug/tracing/events/signal/signal_generate
214 # echo "((sig >= 10 && sig < 15) || sig == 17) && comm != bash" > filter
215
216 If there is an error in the expression, you'll get an 'Invalid
217 argument' error when setting it, and the erroneous string along with
218 an error message can be seen by looking at the filter e.g.:
219
220 # cd /sys/kernel/debug/tracing/events/signal/signal_generate
221 # echo "((sig >= 10 && sig < 15) || dsig == 17) && comm != bash" > filter
222 -bash: echo: write error: Invalid argument
223 # cat filter
224 ((sig >= 10 && sig < 15) || dsig == 17) && comm != bash
225 ^
226 parse_error: Field not found
227
228 Currently the caret ('^') for an error always appears at the beginning of
229 the filter string; the error message should still be useful though
230 even without more accurate position info.
231
232 5.3 Clearing filters
233 --------------------
234
235 To clear the filter for an event, write a '0' to the event's filter
236 file.
237
238 To clear the filters for all events in a subsystem, write a '0' to the
239 subsystem's filter file.
240
241 5.3 Subsystem filters
242 ---------------------
243
244 For convenience, filters for every event in a subsystem can be set or
245 cleared as a group by writing a filter expression into the filter file
246 at the root of the subsystem. Note however, that if a filter for any
247 event within the subsystem lacks a field specified in the subsystem
248 filter, or if the filter can't be applied for any other reason, the
249 filter for that event will retain its previous setting. This can
250 result in an unintended mixture of filters which could lead to
251 confusing (to the user who might think different filters are in
252 effect) trace output. Only filters that reference just the common
253 fields can be guaranteed to propagate successfully to all events.
254
255 Here are a few subsystem filter examples that also illustrate the
256 above points:
257
258 Clear the filters on all events in the sched subsystem:
259
260 # cd /sys/kernel/debug/tracing/events/sched
261 # echo 0 > filter
262 # cat sched_switch/filter
263 none
264 # cat sched_wakeup/filter
265 none
266
267 Set a filter using only common fields for all events in the sched
268 subsystem (all events end up with the same filter):
269
270 # cd /sys/kernel/debug/tracing/events/sched
271 # echo common_pid == 0 > filter
272 # cat sched_switch/filter
273 common_pid == 0
274 # cat sched_wakeup/filter
275 common_pid == 0
276
277 Attempt to set a filter using a non-common field for all events in the
278 sched subsystem (all events but those that have a prev_pid field retain
279 their old filters):
280
281 # cd /sys/kernel/debug/tracing/events/sched
282 # echo prev_pid == 0 > filter
283 # cat sched_switch/filter
284 prev_pid == 0
285 # cat sched_wakeup/filter
286 common_pid == 0
287
288 5.4 PID filtering
289 -----------------
290
291 The set_event_pid file in the same directory as the top events directory
292 exists, will filter all events from tracing any task that does not have the
293 PID listed in the set_event_pid file.
294
295 # cd /sys/kernel/debug/tracing
296 # echo $$ > set_event_pid
297 # echo 1 > events/enabled
298
299 Will only trace events for the current task.
300
301 To add more PIDs without losing the PIDs already included, use '>>'.
302
303 # echo 123 244 1 >> set_event_pid
304
305
306 6. Event triggers
307 =================
308
309 Trace events can be made to conditionally invoke trigger 'commands'
310 which can take various forms and are described in detail below;
311 examples would be enabling or disabling other trace events or invoking
312 a stack trace whenever the trace event is hit. Whenever a trace event
313 with attached triggers is invoked, the set of trigger commands
314 associated with that event is invoked. Any given trigger can
315 additionally have an event filter of the same form as described in
316 section 5 (Event filtering) associated with it - the command will only
317 be invoked if the event being invoked passes the associated filter.
318 If no filter is associated with the trigger, it always passes.
319
320 Triggers are added to and removed from a particular event by writing
321 trigger expressions to the 'trigger' file for the given event.
322
323 A given event can have any number of triggers associated with it,
324 subject to any restrictions that individual commands may have in that
325 regard.
326
327 Event triggers are implemented on top of "soft" mode, which means that
328 whenever a trace event has one or more triggers associated with it,
329 the event is activated even if it isn't actually enabled, but is
330 disabled in a "soft" mode. That is, the tracepoint will be called,
331 but just will not be traced, unless of course it's actually enabled.
332 This scheme allows triggers to be invoked even for events that aren't
333 enabled, and also allows the current event filter implementation to be
334 used for conditionally invoking triggers.
335
336 The syntax for event triggers is roughly based on the syntax for
337 set_ftrace_filter 'ftrace filter commands' (see the 'Filter commands'
338 section of Documentation/trace/ftrace.txt), but there are major
339 differences and the implementation isn't currently tied to it in any
340 way, so beware about making generalizations between the two.
341
342 6.1 Expression syntax
343 ---------------------
344
345 Triggers are added by echoing the command to the 'trigger' file:
346
347 # echo 'command[:count] [if filter]' > trigger
348
349 Triggers are removed by echoing the same command but starting with '!'
350 to the 'trigger' file:
351
352 # echo '!command[:count] [if filter]' > trigger
353
354 The [if filter] part isn't used in matching commands when removing, so
355 leaving that off in a '!' command will accomplish the same thing as
356 having it in.
357
358 The filter syntax is the same as that described in the 'Event
359 filtering' section above.
360
361 For ease of use, writing to the trigger file using '>' currently just
362 adds or removes a single trigger and there's no explicit '>>' support
363 ('>' actually behaves like '>>') or truncation support to remove all
364 triggers (you have to use '!' for each one added.)
365
366 6.2 Supported trigger commands
367 ------------------------------
368
369 The following commands are supported:
370
371 - enable_event/disable_event
372
373 These commands can enable or disable another trace event whenever
374 the triggering event is hit. When these commands are registered,
375 the other trace event is activated, but disabled in a "soft" mode.
376 That is, the tracepoint will be called, but just will not be traced.
377 The event tracepoint stays in this mode as long as there's a trigger
378 in effect that can trigger it.
379
380 For example, the following trigger causes kmalloc events to be
381 traced when a read system call is entered, and the :1 at the end
382 specifies that this enablement happens only once:
383
384 # echo 'enable_event:kmem:kmalloc:1' > \
385 /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
386
387 The following trigger causes kmalloc events to stop being traced
388 when a read system call exits. This disablement happens on every
389 read system call exit:
390
391 # echo 'disable_event:kmem:kmalloc' > \
392 /sys/kernel/debug/tracing/events/syscalls/sys_exit_read/trigger
393
394 The format is:
395
396 enable_event:<system>:<event>[:count]
397 disable_event:<system>:<event>[:count]
398
399 To remove the above commands:
400
401 # echo '!enable_event:kmem:kmalloc:1' > \
402 /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
403
404 # echo '!disable_event:kmem:kmalloc' > \
405 /sys/kernel/debug/tracing/events/syscalls/sys_exit_read/trigger
406
407 Note that there can be any number of enable/disable_event triggers
408 per triggering event, but there can only be one trigger per
409 triggered event. e.g. sys_enter_read can have triggers enabling both
410 kmem:kmalloc and sched:sched_switch, but can't have two kmem:kmalloc
411 versions such as kmem:kmalloc and kmem:kmalloc:1 or 'kmem:kmalloc if
412 bytes_req == 256' and 'kmem:kmalloc if bytes_alloc == 256' (they
413 could be combined into a single filter on kmem:kmalloc though).
414
415 - stacktrace
416
417 This command dumps a stacktrace in the trace buffer whenever the
418 triggering event occurs.
419
420 For example, the following trigger dumps a stacktrace every time the
421 kmalloc tracepoint is hit:
422
423 # echo 'stacktrace' > \
424 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
425
426 The following trigger dumps a stacktrace the first 5 times a kmalloc
427 request happens with a size >= 64K
428
429 # echo 'stacktrace:5 if bytes_req >= 65536' > \
430 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
431
432 The format is:
433
434 stacktrace[:count]
435
436 To remove the above commands:
437
438 # echo '!stacktrace' > \
439 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
440
441 # echo '!stacktrace:5 if bytes_req >= 65536' > \
442 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
443
444 The latter can also be removed more simply by the following (without
445 the filter):
446
447 # echo '!stacktrace:5' > \
448 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
449
450 Note that there can be only one stacktrace trigger per triggering
451 event.
452
453 - snapshot
454
455 This command causes a snapshot to be triggered whenever the
456 triggering event occurs.
457
458 The following command creates a snapshot every time a block request
459 queue is unplugged with a depth > 1. If you were tracing a set of
460 events or functions at the time, the snapshot trace buffer would
461 capture those events when the trigger event occurred:
462
463 # echo 'snapshot if nr_rq > 1' > \
464 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
465
466 To only snapshot once:
467
468 # echo 'snapshot:1 if nr_rq > 1' > \
469 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
470
471 To remove the above commands:
472
473 # echo '!snapshot if nr_rq > 1' > \
474 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
475
476 # echo '!snapshot:1 if nr_rq > 1' > \
477 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
478
479 Note that there can be only one snapshot trigger per triggering
480 event.
481
482 - traceon/traceoff
483
484 These commands turn tracing on and off when the specified events are
485 hit. The parameter determines how many times the tracing system is
486 turned on and off. If unspecified, there is no limit.
487
488 The following command turns tracing off the first time a block
489 request queue is unplugged with a depth > 1. If you were tracing a
490 set of events or functions at the time, you could then examine the
491 trace buffer to see the sequence of events that led up to the
492 trigger event:
493
494 # echo 'traceoff:1 if nr_rq > 1' > \
495 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
496
497 To always disable tracing when nr_rq > 1 :
498
499 # echo 'traceoff if nr_rq > 1' > \
500 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
501
502 To remove the above commands:
503
504 # echo '!traceoff:1 if nr_rq > 1' > \
505 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
506
507 # echo '!traceoff if nr_rq > 1' > \
508 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
509
510 Note that there can be only one traceon or traceoff trigger per
511 triggering event.
512
513 - hist
514
515 This command aggregates event hits into a hash table keyed on one or
516 more trace event format fields (or stacktrace) and a set of running
517 totals derived from one or more trace event format fields and/or
518 event counts (hitcount).
519
520 The format of a hist trigger is as follows:
521
522 hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>]
523 [:sort=<field1[,field2,...]>][:size=#entries][:pause][:continue]
524 [:clear][:name=histname1] [if <filter>]
525
526 When a matching event is hit, an entry is added to a hash table
527 using the key(s) and value(s) named. Keys and values correspond to
528 fields in the event's format description. Values must correspond to
529 numeric fields - on an event hit, the value(s) will be added to a
530 sum kept for that field. The special string 'hitcount' can be used
531 in place of an explicit value field - this is simply a count of
532 event hits. If 'values' isn't specified, an implicit 'hitcount'
533 value will be automatically created and used as the only value.
534 Keys can be any field, or the special string 'stacktrace', which
535 will use the event's kernel stacktrace as the key. The keywords
536 'keys' or 'key' can be used to specify keys, and the keywords
537 'values', 'vals', or 'val' can be used to specify values. Compound
538 keys consisting of up to two fields can be specified by the 'keys'
539 keyword. Hashing a compound key produces a unique entry in the
540 table for each unique combination of component keys, and can be
541 useful for providing more fine-grained summaries of event data.
542 Additionally, sort keys consisting of up to two fields can be
543 specified by the 'sort' keyword. If more than one field is
544 specified, the result will be a 'sort within a sort': the first key
545 is taken to be the primary sort key and the second the secondary
546 key. If a hist trigger is given a name using the 'name' parameter,
547 its histogram data will be shared with other triggers of the same
548 name, and trigger hits will update this common data. Only triggers
549 with 'compatible' fields can be combined in this way; triggers are
550 'compatible' if the fields named in the trigger share the same
551 number and type of fields and those fields also have the same names.
552 Note that any two events always share the compatible 'hitcount' and
553 'stacktrace' fields and can therefore be combined using those
554 fields, however pointless that may be.
555
556 'hist' triggers add a 'hist' file to each event's subdirectory.
557 Reading the 'hist' file for the event will dump the hash table in
558 its entirety to stdout. If there are multiple hist triggers
559 attached to an event, there will be a table for each trigger in the
560 output. The table displayed for a named trigger will be the same as
561 any other instance having the same name. Each printed hash table
562 entry is a simple list of the keys and values comprising the entry;
563 keys are printed first and are delineated by curly braces, and are
564 followed by the set of value fields for the entry. By default,
565 numeric fields are displayed as base-10 integers. This can be
566 modified by appending any of the following modifiers to the field
567 name:
568
569 .hex display a number as a hex value
570 .sym display an address as a symbol
571 .sym-offset display an address as a symbol and offset
572 .syscall display a syscall id as a system call name
573 .execname display a common_pid as a program name
574
575 Note that in general the semantics of a given field aren't
576 interpreted when applying a modifier to it, but there are some
577 restrictions to be aware of in this regard:
578
579 - only the 'hex' modifier can be used for values (because values
580 are essentially sums, and the other modifiers don't make sense
581 in that context).
582 - the 'execname' modifier can only be used on a 'common_pid'. The
583 reason for this is that the execname is simply the 'comm' value
584 saved for the 'current' process when an event was triggered,
585 which is the same as the common_pid value saved by the event
586 tracing code. Trying to apply that comm value to other pid
587 values wouldn't be correct, and typically events that care save
588 pid-specific comm fields in the event itself.
589
590 A typical usage scenario would be the following to enable a hist
591 trigger, read its current contents, and then turn it off:
592
593 # echo 'hist:keys=skbaddr.hex:vals=len' > \
594 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
595
596 # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
597
598 # echo '!hist:keys=skbaddr.hex:vals=len' > \
599 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
600
601 The trigger file itself can be read to show the details of the
602 currently attached hist trigger. This information is also displayed
603 at the top of the 'hist' file when read.
604
605 By default, the size of the hash table is 2048 entries. The 'size'
606 parameter can be used to specify more or fewer than that. The units
607 are in terms of hashtable entries - if a run uses more entries than
608 specified, the results will show the number of 'drops', the number
609 of hits that were ignored. The size should be a power of 2 between
610 128 and 131072 (any non- power-of-2 number specified will be rounded
611 up).
612
613 The 'sort' parameter can be used to specify a value field to sort
614 on. The default if unspecified is 'hitcount' and the default sort
615 order is 'ascending'. To sort in the opposite direction, append
616 .descending' to the sort key.
617
618 The 'pause' parameter can be used to pause an existing hist trigger
619 or to start a hist trigger but not log any events until told to do
620 so. 'continue' or 'cont' can be used to start or restart a paused
621 hist trigger.
622
623 The 'clear' parameter will clear the contents of a running hist
624 trigger and leave its current paused/active state.
625
626 Note that the 'pause', 'cont', and 'clear' parameters should be
627 applied using 'append' shell operator ('>>') if applied to an
628 existing trigger, rather than via the '>' operator, which will cause
629 the trigger to be removed through truncation.
630
631 - enable_hist/disable_hist
632
633 The enable_hist and disable_hist triggers can be used to have one
634 event conditionally start and stop another event's already-attached
635 hist trigger. Any number of enable_hist and disable_hist triggers
636 can be attached to a given event, allowing that event to kick off
637 and stop aggregations on a host of other events.
638
639 The format is very similar to the enable/disable_event triggers:
640
641 enable_hist:<system>:<event>[:count]
642 disable_hist:<system>:<event>[:count]
643
644 Instead of enabling or disabling the tracing of the target event
645 into the trace buffer as the enable/disable_event triggers do, the
646 enable/disable_hist triggers enable or disable the aggregation of
647 the target event into a hash table.
648
649 A typical usage scenario for the enable_hist/disable_hist triggers
650 would be to first set up a paused hist trigger on some event,
651 followed by an enable_hist/disable_hist pair that turns the hist
652 aggregation on and off when conditions of interest are hit:
653
654 # echo 'hist:keys=skbaddr.hex:vals=len:pause' > \
655 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
656
657 # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \
658 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
659
660 # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \
661 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
662
663 The above sets up an initially paused hist trigger which is unpaused
664 and starts aggregating events when a given program is executed, and
665 which stops aggregating when the process exits and the hist trigger
666 is paused again.
667
668 The examples below provide a more concrete illustration of the
669 concepts and typical usage patterns discussed above.
670
671
672 6.2 'hist' trigger examples
673 ---------------------------
674
675 The first set of examples creates aggregations using the kmalloc
676 event. The fields that can be used for the hist trigger are listed
677 in the kmalloc event's format file:
678
679 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format
680 name: kmalloc
681 ID: 374
682 format:
683 field:unsigned short common_type; offset:0; size:2; signed:0;
684 field:unsigned char common_flags; offset:2; size:1; signed:0;
685 field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
686 field:int common_pid; offset:4; size:4; signed:1;
687
688 field:unsigned long call_site; offset:8; size:8; signed:0;
689 field:const void * ptr; offset:16; size:8; signed:0;
690 field:size_t bytes_req; offset:24; size:8; signed:0;
691 field:size_t bytes_alloc; offset:32; size:8; signed:0;
692 field:gfp_t gfp_flags; offset:40; size:4; signed:0;
693
694 We'll start by creating a hist trigger that generates a simple table
695 that lists the total number of bytes requested for each function in
696 the kernel that made one or more calls to kmalloc:
697
698 # echo 'hist:key=call_site:val=bytes_req' > \
699 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
700
701 This tells the tracing system to create a 'hist' trigger using the
702 call_site field of the kmalloc event as the key for the table, which
703 just means that each unique call_site address will have an entry
704 created for it in the table. The 'val=bytes_req' parameter tells
705 the hist trigger that for each unique entry (call_site) in the
706 table, it should keep a running total of the number of bytes
707 requested by that call_site.
708
709 We'll let it run for awhile and then dump the contents of the 'hist'
710 file in the kmalloc event's subdirectory (for readability, a number
711 of entries have been omitted):
712
713 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
714 # trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
715
716 { call_site: 18446744072106379007 } hitcount: 1 bytes_req: 176
717 { call_site: 18446744071579557049 } hitcount: 1 bytes_req: 1024
718 { call_site: 18446744071580608289 } hitcount: 1 bytes_req: 16384
719 { call_site: 18446744071581827654 } hitcount: 1 bytes_req: 24
720 { call_site: 18446744071580700980 } hitcount: 1 bytes_req: 8
721 { call_site: 18446744071579359876 } hitcount: 1 bytes_req: 152
722 { call_site: 18446744071580795365 } hitcount: 3 bytes_req: 144
723 { call_site: 18446744071581303129 } hitcount: 3 bytes_req: 144
724 { call_site: 18446744071580713234 } hitcount: 4 bytes_req: 2560
725 { call_site: 18446744071580933750 } hitcount: 4 bytes_req: 736
726 .
727 .
728 .
729 { call_site: 18446744072106047046 } hitcount: 69 bytes_req: 5576
730 { call_site: 18446744071582116407 } hitcount: 73 bytes_req: 2336
731 { call_site: 18446744072106054684 } hitcount: 136 bytes_req: 140504
732 { call_site: 18446744072106224230 } hitcount: 136 bytes_req: 19584
733 { call_site: 18446744072106078074 } hitcount: 153 bytes_req: 2448
734 { call_site: 18446744072106062406 } hitcount: 153 bytes_req: 36720
735 { call_site: 18446744071582507929 } hitcount: 153 bytes_req: 37088
736 { call_site: 18446744072102520590 } hitcount: 273 bytes_req: 10920
737 { call_site: 18446744071582143559 } hitcount: 358 bytes_req: 716
738 { call_site: 18446744072106465852 } hitcount: 417 bytes_req: 56712
739 { call_site: 18446744072102523378 } hitcount: 485 bytes_req: 27160
740 { call_site: 18446744072099568646 } hitcount: 1676 bytes_req: 33520
741
742 Totals:
743 Hits: 4610
744 Entries: 45
745 Dropped: 0
746
747 The output displays a line for each entry, beginning with the key
748 specified in the trigger, followed by the value(s) also specified in
749 the trigger. At the beginning of the output is a line that displays
750 the trigger info, which can also be displayed by reading the
751 'trigger' file:
752
753 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
754 hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
755
756 At the end of the output are a few lines that display the overall
757 totals for the run. The 'Hits' field shows the total number of
758 times the event trigger was hit, the 'Entries' field shows the total
759 number of used entries in the hash table, and the 'Dropped' field
760 shows the number of hits that were dropped because the number of
761 used entries for the run exceeded the maximum number of entries
762 allowed for the table (normally 0, but if not a hint that you may
763 want to increase the size of the table using the 'size' parameter).
764
765 Notice in the above output that there's an extra field, 'hitcount',
766 which wasn't specified in the trigger. Also notice that in the
767 trigger info output, there's a parameter, 'sort=hitcount', which
768 wasn't specified in the trigger either. The reason for that is that
769 every trigger implicitly keeps a count of the total number of hits
770 attributed to a given entry, called the 'hitcount'. That hitcount
771 information is explicitly displayed in the output, and in the
772 absence of a user-specified sort parameter, is used as the default
773 sort field.
774
775 The value 'hitcount' can be used in place of an explicit value in
776 the 'values' parameter if you don't really need to have any
777 particular field summed and are mainly interested in hit
778 frequencies.
779
780 To turn the hist trigger off, simply call up the trigger in the
781 command history and re-execute it with a '!' prepended:
782
783 # echo '!hist:key=call_site:val=bytes_req' > \
784 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
785
786 Finally, notice that the call_site as displayed in the output above
787 isn't really very useful. It's an address, but normally addresses
788 are displayed in hex. To have a numeric field displayed as a hex
789 value, simply append '.hex' to the field name in the trigger:
790
791 # echo 'hist:key=call_site.hex:val=bytes_req' > \
792 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
793
794 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
795 # trigger info: hist:keys=call_site.hex:vals=bytes_req:sort=hitcount:size=2048 [active]
796
797 { call_site: ffffffffa026b291 } hitcount: 1 bytes_req: 433
798 { call_site: ffffffffa07186ff } hitcount: 1 bytes_req: 176
799 { call_site: ffffffff811ae721 } hitcount: 1 bytes_req: 16384
800 { call_site: ffffffff811c5134 } hitcount: 1 bytes_req: 8
801 { call_site: ffffffffa04a9ebb } hitcount: 1 bytes_req: 511
802 { call_site: ffffffff8122e0a6 } hitcount: 1 bytes_req: 12
803 { call_site: ffffffff8107da84 } hitcount: 1 bytes_req: 152
804 { call_site: ffffffff812d8246 } hitcount: 1 bytes_req: 24
805 { call_site: ffffffff811dc1e5 } hitcount: 3 bytes_req: 144
806 { call_site: ffffffffa02515e8 } hitcount: 3 bytes_req: 648
807 { call_site: ffffffff81258159 } hitcount: 3 bytes_req: 144
808 { call_site: ffffffff811c80f4 } hitcount: 4 bytes_req: 544
809 .
810 .
811 .
812 { call_site: ffffffffa06c7646 } hitcount: 106 bytes_req: 8024
813 { call_site: ffffffffa06cb246 } hitcount: 132 bytes_req: 31680
814 { call_site: ffffffffa06cef7a } hitcount: 132 bytes_req: 2112
815 { call_site: ffffffff8137e399 } hitcount: 132 bytes_req: 23232
816 { call_site: ffffffffa06c941c } hitcount: 185 bytes_req: 171360
817 { call_site: ffffffffa06f2a66 } hitcount: 185 bytes_req: 26640
818 { call_site: ffffffffa036a70e } hitcount: 265 bytes_req: 10600
819 { call_site: ffffffff81325447 } hitcount: 292 bytes_req: 584
820 { call_site: ffffffffa072da3c } hitcount: 446 bytes_req: 60656
821 { call_site: ffffffffa036b1f2 } hitcount: 526 bytes_req: 29456
822 { call_site: ffffffffa0099c06 } hitcount: 1780 bytes_req: 35600
823
824 Totals:
825 Hits: 4775
826 Entries: 46
827 Dropped: 0
828
829 Even that's only marginally more useful - while hex values do look
830 more like addresses, what users are typically more interested in
831 when looking at text addresses are the corresponding symbols
832 instead. To have an address displayed as symbolic value instead,
833 simply append '.sym' or '.sym-offset' to the field name in the
834 trigger:
835
836 # echo 'hist:key=call_site.sym:val=bytes_req' > \
837 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
838
839 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
840 # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=hitcount:size=2048 [active]
841
842 { call_site: [ffffffff810adcb9] syslog_print_all } hitcount: 1 bytes_req: 1024
843 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8
844 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7
845 { call_site: [ffffffff8154acbe] usb_alloc_urb } hitcount: 1 bytes_req: 192
846 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7
847 { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40
848 { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128
849 { call_site: [ffffffff811febd5] fsnotify_alloc_group } hitcount: 2 bytes_req: 528
850 { call_site: [ffffffff81440f58] __tty_buffer_request_room } hitcount: 2 bytes_req: 2624
851 { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 2 bytes_req: 96
852 { call_site: [ffffffffa05e19af] ieee80211_start_tx_ba_session [mac80211] } hitcount: 2 bytes_req: 464
853 { call_site: [ffffffff81672406] tcp_get_metrics } hitcount: 2 bytes_req: 304
854 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128
855 { call_site: [ffffffff81089b05] sched_create_group } hitcount: 2 bytes_req: 1424
856 .
857 .
858 .
859 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1185 bytes_req: 123240
860 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 1185 bytes_req: 104280
861 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 1402 bytes_req: 190672
862 { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 1518 bytes_req: 146208
863 { call_site: [ffffffffa029070e] drm_vma_node_allow [drm] } hitcount: 1746 bytes_req: 69840
864 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 2021 bytes_req: 792312
865 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 2592 bytes_req: 145152
866 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2629 bytes_req: 378576
867 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2629 bytes_req: 3783248
868 { call_site: [ffffffff81325607] apparmor_file_alloc_security } hitcount: 5192 bytes_req: 10384
869 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 5529 bytes_req: 110584
870 { call_site: [ffffffff8131ebf7] aa_alloc_task_context } hitcount: 21943 bytes_req: 702176
871 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 55759 bytes_req: 5074265
872
873 Totals:
874 Hits: 109928
875 Entries: 71
876 Dropped: 0
877
878 Because the default sort key above is 'hitcount', the above shows a
879 the list of call_sites by increasing hitcount, so that at the bottom
880 we see the functions that made the most kmalloc calls during the
881 run. If instead we we wanted to see the top kmalloc callers in
882 terms of the number of bytes requested rather than the number of
883 calls, and we wanted the top caller to appear at the top, we can use
884 the 'sort' parameter, along with the 'descending' modifier:
885
886 # echo 'hist:key=call_site.sym:val=bytes_req:sort=bytes_req.descending' > \
887 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
888
889 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
890 # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=bytes_req.descending:size=2048 [active]
891
892 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2186 bytes_req: 3397464
893 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1790 bytes_req: 712176
894 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 8132 bytes_req: 513135
895 { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 106 bytes_req: 440128
896 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2186 bytes_req: 314784
897 { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 2174 bytes_req: 208992
898 { call_site: [ffffffff811ae8e1] __kmalloc } hitcount: 8 bytes_req: 131072
899 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 859 bytes_req: 116824
900 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 1834 bytes_req: 102704
901 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 972 bytes_req: 101088
902 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 972 bytes_req: 85536
903 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 3333 bytes_req: 66664
904 { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 209 bytes_req: 61632
905 .
906 .
907 .
908 { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128
909 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128
910 { call_site: [ffffffff812d8406] copy_semundo } hitcount: 2 bytes_req: 48
911 { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 1 bytes_req: 48
912 { call_site: [ffffffffa027121a] drm_getmagic [drm] } hitcount: 1 bytes_req: 48
913 { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40
914 { call_site: [ffffffff811c52f4] bprm_change_interp } hitcount: 2 bytes_req: 16
915 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8
916 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7
917 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7
918
919 Totals:
920 Hits: 32133
921 Entries: 81
922 Dropped: 0
923
924 To display the offset and size information in addition to the symbol
925 name, just use 'sym-offset' instead:
926
927 # echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \
928 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
929
930 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
931 # trigger info: hist:keys=call_site.sym-offset:vals=bytes_req:sort=bytes_req.descending:size=2048 [active]
932
933 { call_site: [ffffffffa046041c] i915_gem_execbuffer2+0x6c/0x2c0 [i915] } hitcount: 4569 bytes_req: 3163720
934 { call_site: [ffffffffa0489a66] intel_ring_begin+0xc6/0x1f0 [i915] } hitcount: 4569 bytes_req: 657936
935 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23+0x694/0x1020 [i915] } hitcount: 1519 bytes_req: 472936
936 { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23+0x516/0x1020 [i915] } hitcount: 3050 bytes_req: 211832
937 { call_site: [ffffffff811e2a1b] seq_buf_alloc+0x1b/0x50 } hitcount: 34 bytes_req: 148384
938 { call_site: [ffffffffa04a580c] intel_crtc_page_flip+0xbc/0x870 [i915] } hitcount: 1385 bytes_req: 144040
939 { call_site: [ffffffff811ae8e1] __kmalloc+0x191/0x1b0 } hitcount: 8 bytes_req: 131072
940 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl+0x282/0x360 [drm] } hitcount: 1385 bytes_req: 121880
941 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc+0x32/0x100 [drm] } hitcount: 1848 bytes_req: 103488
942 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state+0x2c/0xa0 [i915] } hitcount: 461 bytes_req: 62696
943 { call_site: [ffffffffa029070e] drm_vma_node_allow+0x2e/0xd0 [drm] } hitcount: 1541 bytes_req: 61640
944 { call_site: [ffffffff815f8d7b] sk_prot_alloc+0xcb/0x1b0 } hitcount: 57 bytes_req: 57456
945 .
946 .
947 .
948 { call_site: [ffffffff8109524a] alloc_fair_sched_group+0x5a/0x1a0 } hitcount: 2 bytes_req: 128
949 { call_site: [ffffffffa027b921] drm_vm_open_locked+0x31/0xa0 [drm] } hitcount: 3 bytes_req: 96
950 { call_site: [ffffffff8122e266] proc_self_follow_link+0x76/0xb0 } hitcount: 8 bytes_req: 96
951 { call_site: [ffffffff81213e80] load_elf_binary+0x240/0x1650 } hitcount: 3 bytes_req: 84
952 { call_site: [ffffffff8154bc62] usb_control_msg+0x42/0x110 } hitcount: 1 bytes_req: 8
953 { call_site: [ffffffffa00bf6fe] hidraw_send_report+0x7e/0x1a0 [hid] } hitcount: 1 bytes_req: 7
954 { call_site: [ffffffffa00bf1ca] hidraw_report_event+0x8a/0x120 [hid] } hitcount: 1 bytes_req: 7
955
956 Totals:
957 Hits: 26098
958 Entries: 64
959 Dropped: 0
960
961 We can also add multiple fields to the 'values' parameter. For
962 example, we might want to see the total number of bytes allocated
963 alongside bytes requested, and display the result sorted by bytes
964 allocated in a descending order:
965
966 # echo 'hist:keys=call_site.sym:values=bytes_req,bytes_alloc:sort=bytes_alloc.descending' > \
967 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
968
969 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
970 # trigger info: hist:keys=call_site.sym:vals=bytes_req,bytes_alloc:sort=bytes_alloc.descending:size=2048 [active]
971
972 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 7403 bytes_req: 4084360 bytes_alloc: 5958016
973 { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 541 bytes_req: 2213968 bytes_alloc: 2228224
974 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 7404 bytes_req: 1066176 bytes_alloc: 1421568
975 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1565 bytes_req: 557368 bytes_alloc: 1037760
976 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 9557 bytes_req: 595778 bytes_alloc: 695744
977 { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 5839 bytes_req: 430680 bytes_alloc: 470400
978 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 2388 bytes_req: 324768 bytes_alloc: 458496
979 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 3911 bytes_req: 219016 bytes_alloc: 250304
980 { call_site: [ffffffff815f8d7b] sk_prot_alloc } hitcount: 235 bytes_req: 236880 bytes_alloc: 240640
981 { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 557 bytes_req: 169024 bytes_alloc: 221760
982 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 9378 bytes_req: 187548 bytes_alloc: 206312
983 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1519 bytes_req: 157976 bytes_alloc: 194432
984 .
985 .
986 .
987 { call_site: [ffffffff8109bd3b] sched_autogroup_create_attach } hitcount: 2 bytes_req: 144 bytes_alloc: 192
988 { call_site: [ffffffff81097ee8] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128
989 { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128
990 { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128
991 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128
992 { call_site: [ffffffff81213e80] load_elf_binary } hitcount: 3 bytes_req: 84 bytes_alloc: 96
993 { call_site: [ffffffff81079a2e] kthread_create_on_node } hitcount: 1 bytes_req: 56 bytes_alloc: 64
994 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8
995 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 bytes_alloc: 8
996 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8
997
998 Totals:
999 Hits: 66598
1000 Entries: 65
1001 Dropped: 0
1002
1003 Finally, to finish off our kmalloc example, instead of simply having
1004 the hist trigger display symbolic call_sites, we can have the hist
1005 trigger additionally display the complete set of kernel stack traces
1006 that led to each call_site. To do that, we simply use the special
1007 value 'stacktrace' for the key parameter:
1008
1009 # echo 'hist:keys=stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' > \
1010 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
1011
1012 The above trigger will use the kernel stack trace in effect when an
1013 event is triggered as the key for the hash table. This allows the
1014 enumeration of every kernel callpath that led up to a particular
1015 event, along with a running total of any of the event fields for
1016 that event. Here we tally bytes requested and bytes allocated for
1017 every callpath in the system that led up to a kmalloc (in this case
1018 every callpath to a kmalloc for a kernel compile):
1019
1020 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist
1021 # trigger info: hist:keys=stacktrace:vals=bytes_req,bytes_alloc:sort=bytes_alloc:size=2048 [active]
1022
1023 { stacktrace:
1024 __kmalloc_track_caller+0x10b/0x1a0
1025 kmemdup+0x20/0x50
1026 hidraw_report_event+0x8a/0x120 [hid]
1027 hid_report_raw_event+0x3ea/0x440 [hid]
1028 hid_input_report+0x112/0x190 [hid]
1029 hid_irq_in+0xc2/0x260 [usbhid]
1030 __usb_hcd_giveback_urb+0x72/0x120
1031 usb_giveback_urb_bh+0x9e/0xe0
1032 tasklet_hi_action+0xf8/0x100
1033 __do_softirq+0x114/0x2c0
1034 irq_exit+0xa5/0xb0
1035 do_IRQ+0x5a/0xf0
1036 ret_from_intr+0x0/0x30
1037 cpuidle_enter+0x17/0x20
1038 cpu_startup_entry+0x315/0x3e0
1039 rest_init+0x7c/0x80
1040 } hitcount: 3 bytes_req: 21 bytes_alloc: 24
1041 { stacktrace:
1042 __kmalloc_track_caller+0x10b/0x1a0
1043 kmemdup+0x20/0x50
1044 hidraw_report_event+0x8a/0x120 [hid]
1045 hid_report_raw_event+0x3ea/0x440 [hid]
1046 hid_input_report+0x112/0x190 [hid]
1047 hid_irq_in+0xc2/0x260 [usbhid]
1048 __usb_hcd_giveback_urb+0x72/0x120
1049 usb_giveback_urb_bh+0x9e/0xe0
1050 tasklet_hi_action+0xf8/0x100
1051 __do_softirq+0x114/0x2c0
1052 irq_exit+0xa5/0xb0
1053 do_IRQ+0x5a/0xf0
1054 ret_from_intr+0x0/0x30
1055 } hitcount: 3 bytes_req: 21 bytes_alloc: 24
1056 { stacktrace:
1057 kmem_cache_alloc_trace+0xeb/0x150
1058 aa_alloc_task_context+0x27/0x40
1059 apparmor_cred_prepare+0x1f/0x50
1060 security_prepare_creds+0x16/0x20
1061 prepare_creds+0xdf/0x1a0
1062 SyS_capset+0xb5/0x200
1063 system_call_fastpath+0x12/0x6a
1064 } hitcount: 1 bytes_req: 32 bytes_alloc: 32
1065 .
1066 .
1067 .
1068 { stacktrace:
1069 __kmalloc+0x11b/0x1b0
1070 i915_gem_execbuffer2+0x6c/0x2c0 [i915]
1071 drm_ioctl+0x349/0x670 [drm]
1072 do_vfs_ioctl+0x2f0/0x4f0
1073 SyS_ioctl+0x81/0xa0
1074 system_call_fastpath+0x12/0x6a
1075 } hitcount: 17726 bytes_req: 13944120 bytes_alloc: 19593808
1076 { stacktrace:
1077 __kmalloc+0x11b/0x1b0
1078 load_elf_phdrs+0x76/0xa0
1079 load_elf_binary+0x102/0x1650
1080 search_binary_handler+0x97/0x1d0
1081 do_execveat_common.isra.34+0x551/0x6e0
1082 SyS_execve+0x3a/0x50
1083 return_from_execve+0x0/0x23
1084 } hitcount: 33348 bytes_req: 17152128 bytes_alloc: 20226048
1085 { stacktrace:
1086 kmem_cache_alloc_trace+0xeb/0x150
1087 apparmor_file_alloc_security+0x27/0x40
1088 security_file_alloc+0x16/0x20
1089 get_empty_filp+0x93/0x1c0
1090 path_openat+0x31/0x5f0
1091 do_filp_open+0x3a/0x90
1092 do_sys_open+0x128/0x220
1093 SyS_open+0x1e/0x20
1094 system_call_fastpath+0x12/0x6a
1095 } hitcount: 4766422 bytes_req: 9532844 bytes_alloc: 38131376
1096 { stacktrace:
1097 __kmalloc+0x11b/0x1b0
1098 seq_buf_alloc+0x1b/0x50
1099 seq_read+0x2cc/0x370
1100 proc_reg_read+0x3d/0x80
1101 __vfs_read+0x28/0xe0
1102 vfs_read+0x86/0x140
1103 SyS_read+0x46/0xb0
1104 system_call_fastpath+0x12/0x6a
1105 } hitcount: 19133 bytes_req: 78368768 bytes_alloc: 78368768
1106
1107 Totals:
1108 Hits: 6085872
1109 Entries: 253
1110 Dropped: 0
1111
1112 If you key a hist trigger on common_pid, in order for example to
1113 gather and display sorted totals for each process, you can use the
1114 special .execname modifier to display the executable names for the
1115 processes in the table rather than raw pids. The example below
1116 keeps a per-process sum of total bytes read:
1117
1118 # echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \
1119 /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
1120
1121 # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/hist
1122 # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active]
1123
1124 { common_pid: gnome-terminal [ 3196] } hitcount: 280 count: 1093512
1125 { common_pid: Xorg [ 1309] } hitcount: 525 count: 256640
1126 { common_pid: compiz [ 2889] } hitcount: 59 count: 254400
1127 { common_pid: bash [ 8710] } hitcount: 3 count: 66369
1128 { common_pid: dbus-daemon-lau [ 8703] } hitcount: 49 count: 47739
1129 { common_pid: irqbalance [ 1252] } hitcount: 27 count: 27648
1130 { common_pid: 01ifupdown [ 8705] } hitcount: 3 count: 17216
1131 { common_pid: dbus-daemon [ 772] } hitcount: 10 count: 12396
1132 { common_pid: Socket Thread [ 8342] } hitcount: 11 count: 11264
1133 { common_pid: nm-dhcp-client. [ 8701] } hitcount: 6 count: 7424
1134 { common_pid: gmain [ 1315] } hitcount: 18 count: 6336
1135 .
1136 .
1137 .
1138 { common_pid: postgres [ 1892] } hitcount: 2 count: 32
1139 { common_pid: postgres [ 1891] } hitcount: 2 count: 32
1140 { common_pid: gmain [ 8704] } hitcount: 2 count: 32
1141 { common_pid: upstart-dbus-br [ 2740] } hitcount: 21 count: 21
1142 { common_pid: nm-dispatcher.a [ 8696] } hitcount: 1 count: 16
1143 { common_pid: indicator-datet [ 2904] } hitcount: 1 count: 16
1144 { common_pid: gdbus [ 2998] } hitcount: 1 count: 16
1145 { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8
1146 { common_pid: init [ 1] } hitcount: 2 count: 2
1147
1148 Totals:
1149 Hits: 2116
1150 Entries: 51
1151 Dropped: 0
1152
1153 Similarly, if you key a hist trigger on syscall id, for example to
1154 gather and display a list of systemwide syscall hits, you can use
1155 the special .syscall modifier to display the syscall names rather
1156 than raw ids. The example below keeps a running total of syscall
1157 counts for the system during the run:
1158
1159 # echo 'hist:key=id.syscall:val=hitcount' > \
1160 /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
1161
1162 # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist
1163 # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active]
1164
1165 { id: sys_fsync [ 74] } hitcount: 1
1166 { id: sys_newuname [ 63] } hitcount: 1
1167 { id: sys_prctl [157] } hitcount: 1
1168 { id: sys_statfs [137] } hitcount: 1
1169 { id: sys_symlink [ 88] } hitcount: 1
1170 { id: sys_sendmmsg [307] } hitcount: 1
1171 { id: sys_semctl [ 66] } hitcount: 1
1172 { id: sys_readlink [ 89] } hitcount: 3
1173 { id: sys_bind [ 49] } hitcount: 3
1174 { id: sys_getsockname [ 51] } hitcount: 3
1175 { id: sys_unlink [ 87] } hitcount: 3
1176 { id: sys_rename [ 82] } hitcount: 4
1177 { id: unknown_syscall [ 58] } hitcount: 4
1178 { id: sys_connect [ 42] } hitcount: 4
1179 { id: sys_getpid [ 39] } hitcount: 4
1180 .
1181 .
1182 .
1183 { id: sys_rt_sigprocmask [ 14] } hitcount: 952
1184 { id: sys_futex [202] } hitcount: 1534
1185 { id: sys_write [ 1] } hitcount: 2689
1186 { id: sys_setitimer [ 38] } hitcount: 2797
1187 { id: sys_read [ 0] } hitcount: 3202
1188 { id: sys_select [ 23] } hitcount: 3773
1189 { id: sys_writev [ 20] } hitcount: 4531
1190 { id: sys_poll [ 7] } hitcount: 8314
1191 { id: sys_recvmsg [ 47] } hitcount: 13738
1192 { id: sys_ioctl [ 16] } hitcount: 21843
1193
1194 Totals:
1195 Hits: 67612
1196 Entries: 72
1197 Dropped: 0
1198
1199 The syscall counts above provide a rough overall picture of system
1200 call activity on the system; we can see for example that the most
1201 popular system call on this system was the 'sys_ioctl' system call.
1202
1203 We can use 'compound' keys to refine that number and provide some
1204 further insight as to which processes exactly contribute to the
1205 overall ioctl count.
1206
1207 The command below keeps a hitcount for every unique combination of
1208 system call id and pid - the end result is essentially a table
1209 that keeps a per-pid sum of system call hits. The results are
1210 sorted using the system call id as the primary key, and the
1211 hitcount sum as the secondary key:
1212
1213 # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' > \
1214 /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
1215
1216 # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist
1217 # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active]
1218
1219 { id: sys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: 1
1220 { id: sys_read [ 0], common_pid: gdbus [ 2976] } hitcount: 1
1221 { id: sys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: 1
1222 { id: sys_read [ 0], common_pid: postgres [ 1865] } hitcount: 1
1223 { id: sys_read [ 0], common_pid: deja-dup-monito [ 3543] } hitcount: 2
1224 { id: sys_read [ 0], common_pid: NetworkManager [ 890] } hitcount: 2
1225 { id: sys_read [ 0], common_pid: evolution-calen [ 3048] } hitcount: 2
1226 { id: sys_read [ 0], common_pid: postgres [ 1864] } hitcount: 2
1227 { id: sys_read [ 0], common_pid: nm-applet [ 3022] } hitcount: 2
1228 { id: sys_read [ 0], common_pid: whoopsie [ 1212] } hitcount: 2
1229 .
1230 .
1231 .
1232 { id: sys_ioctl [ 16], common_pid: bash [ 8479] } hitcount: 1
1233 { id: sys_ioctl [ 16], common_pid: bash [ 3472] } hitcount: 12
1234 { id: sys_ioctl [ 16], common_pid: gnome-terminal [ 3199] } hitcount: 16
1235 { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 1808
1236 { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 5580
1237 .
1238 .
1239 .
1240 { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2690] } hitcount: 3
1241 { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2688] } hitcount: 16
1242 { id: sys_inotify_add_watch [254], common_pid: gmain [ 975] } hitcount: 2
1243 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3204] } hitcount: 4
1244 { id: sys_inotify_add_watch [254], common_pid: gmain [ 2888] } hitcount: 4
1245 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3003] } hitcount: 4
1246 { id: sys_inotify_add_watch [254], common_pid: gmain [ 2873] } hitcount: 4
1247 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3196] } hitcount: 6
1248 { id: sys_openat [257], common_pid: java [ 2623] } hitcount: 2
1249 { id: sys_eventfd2 [290], common_pid: ibus-ui-gtk3 [ 2760] } hitcount: 4
1250 { id: sys_eventfd2 [290], common_pid: compiz [ 2994] } hitcount: 6
1251
1252 Totals:
1253 Hits: 31536
1254 Entries: 323
1255 Dropped: 0
1256
1257 The above list does give us a breakdown of the ioctl syscall by
1258 pid, but it also gives us quite a bit more than that, which we
1259 don't really care about at the moment. Since we know the syscall
1260 id for sys_ioctl (16, displayed next to the sys_ioctl name), we
1261 can use that to filter out all the other syscalls:
1262
1263 # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount if id == 16' > \
1264 /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
1265
1266 # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist
1267 # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 if id == 16 [active]
1268
1269 { id: sys_ioctl [ 16], common_pid: gmain [ 2769] } hitcount: 1
1270 { id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: 1
1271 { id: sys_ioctl [ 16], common_pid: gmain [ 3003] } hitcount: 1
1272 { id: sys_ioctl [ 16], common_pid: gmain [ 2781] } hitcount: 1
1273 { id: sys_ioctl [ 16], common_pid: gmain [ 2829] } hitcount: 1
1274 { id: sys_ioctl [ 16], common_pid: bash [ 8726] } hitcount: 1
1275 { id: sys_ioctl [ 16], common_pid: bash [ 8508] } hitcount: 1
1276 { id: sys_ioctl [ 16], common_pid: gmain [ 2970] } hitcount: 1
1277 { id: sys_ioctl [ 16], common_pid: gmain [ 2768] } hitcount: 1
1278 .
1279 .
1280 .
1281 { id: sys_ioctl [ 16], common_pid: pool [ 8559] } hitcount: 45
1282 { id: sys_ioctl [ 16], common_pid: pool [ 8555] } hitcount: 48
1283 { id: sys_ioctl [ 16], common_pid: pool [ 8551] } hitcount: 48
1284 { id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: 66
1285 { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 26674
1286 { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 73443
1287
1288 Totals:
1289 Hits: 101162
1290 Entries: 103
1291 Dropped: 0
1292
1293 The above output shows that 'compiz' and 'Xorg' are far and away
1294 the heaviest ioctl callers (which might lead to questions about
1295 whether they really need to be making all those calls and to
1296 possible avenues for further investigation.)
1297
1298 The compound key examples used a key and a sum value (hitcount) to
1299 sort the output, but we can just as easily use two keys instead.
1300 Here's an example where we use a compound key composed of the the
1301 common_pid and size event fields. Sorting with pid as the primary
1302 key and 'size' as the secondary key allows us to display an
1303 ordered summary of the recvfrom sizes, with counts, received by
1304 each process:
1305
1306 # echo 'hist:key=common_pid.execname,size:val=hitcount:sort=common_pid,size' > \
1307 /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/trigger
1308
1309 # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/hist
1310 # trigger info: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:size=2048 [active]
1311
1312 { common_pid: smbd [ 784], size: 4 } hitcount: 1
1313 { common_pid: dnsmasq [ 1412], size: 4096 } hitcount: 672
1314 { common_pid: postgres [ 1796], size: 1000 } hitcount: 6
1315 { common_pid: postgres [ 1867], size: 1000 } hitcount: 10
1316 { common_pid: bamfdaemon [ 2787], size: 28 } hitcount: 2
1317 { common_pid: bamfdaemon [ 2787], size: 14360 } hitcount: 1
1318 { common_pid: compiz [ 2994], size: 8 } hitcount: 1
1319 { common_pid: compiz [ 2994], size: 20 } hitcount: 11
1320 { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2
1321 { common_pid: firefox [ 8817], size: 4 } hitcount: 1
1322 { common_pid: firefox [ 8817], size: 8 } hitcount: 5
1323 { common_pid: firefox [ 8817], size: 588 } hitcount: 2
1324 { common_pid: firefox [ 8817], size: 628 } hitcount: 1
1325 { common_pid: firefox [ 8817], size: 6944 } hitcount: 1
1326 { common_pid: firefox [ 8817], size: 408880 } hitcount: 2
1327 { common_pid: firefox [ 8822], size: 8 } hitcount: 2
1328 { common_pid: firefox [ 8822], size: 160 } hitcount: 2
1329 { common_pid: firefox [ 8822], size: 320 } hitcount: 2
1330 { common_pid: firefox [ 8822], size: 352 } hitcount: 1
1331 .
1332 .
1333 .
1334 { common_pid: pool [ 8923], size: 1960 } hitcount: 10
1335 { common_pid: pool [ 8923], size: 2048 } hitcount: 10
1336 { common_pid: pool [ 8924], size: 1960 } hitcount: 10
1337 { common_pid: pool [ 8924], size: 2048 } hitcount: 10
1338 { common_pid: pool [ 8928], size: 1964 } hitcount: 4
1339 { common_pid: pool [ 8928], size: 1965 } hitcount: 2
1340 { common_pid: pool [ 8928], size: 2048 } hitcount: 6
1341 { common_pid: pool [ 8929], size: 1982 } hitcount: 1
1342 { common_pid: pool [ 8929], size: 2048 } hitcount: 1
1343
1344 Totals:
1345 Hits: 2016
1346 Entries: 224
1347 Dropped: 0
1348
1349 The above example also illustrates the fact that although a compound
1350 key is treated as a single entity for hashing purposes, the sub-keys
1351 it's composed of can be accessed independently.
1352
1353 The next example uses a string field as the hash key and
1354 demonstrates how you can manually pause and continue a hist trigger.
1355 In this example, we'll aggregate fork counts and don't expect a
1356 large number of entries in the hash table, so we'll drop it to a
1357 much smaller number, say 256:
1358
1359 # echo 'hist:key=child_comm:val=hitcount:size=256' > \
1360 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
1361
1362 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
1363 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active]
1364
1365 { child_comm: dconf worker } hitcount: 1
1366 { child_comm: ibus-daemon } hitcount: 1
1367 { child_comm: whoopsie } hitcount: 1
1368 { child_comm: smbd } hitcount: 1
1369 { child_comm: gdbus } hitcount: 1
1370 { child_comm: kthreadd } hitcount: 1
1371 { child_comm: dconf worker } hitcount: 1
1372 { child_comm: evolution-alarm } hitcount: 2
1373 { child_comm: Socket Thread } hitcount: 2
1374 { child_comm: postgres } hitcount: 2
1375 { child_comm: bash } hitcount: 3
1376 { child_comm: compiz } hitcount: 3
1377 { child_comm: evolution-sourc } hitcount: 4
1378 { child_comm: dhclient } hitcount: 4
1379 { child_comm: pool } hitcount: 5
1380 { child_comm: nm-dispatcher.a } hitcount: 8
1381 { child_comm: firefox } hitcount: 8
1382 { child_comm: dbus-daemon } hitcount: 8
1383 { child_comm: glib-pacrunner } hitcount: 10
1384 { child_comm: evolution } hitcount: 23
1385
1386 Totals:
1387 Hits: 89
1388 Entries: 20
1389 Dropped: 0
1390
1391 If we want to pause the hist trigger, we can simply append :pause to
1392 the command that started the trigger. Notice that the trigger info
1393 displays as [paused]:
1394
1395 # echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \
1396 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
1397
1398 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
1399 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [paused]
1400
1401 { child_comm: dconf worker } hitcount: 1
1402 { child_comm: kthreadd } hitcount: 1
1403 { child_comm: dconf worker } hitcount: 1
1404 { child_comm: gdbus } hitcount: 1
1405 { child_comm: ibus-daemon } hitcount: 1
1406 { child_comm: Socket Thread } hitcount: 2
1407 { child_comm: evolution-alarm } hitcount: 2
1408 { child_comm: smbd } hitcount: 2
1409 { child_comm: bash } hitcount: 3
1410 { child_comm: whoopsie } hitcount: 3
1411 { child_comm: compiz } hitcount: 3
1412 { child_comm: evolution-sourc } hitcount: 4
1413 { child_comm: pool } hitcount: 5
1414 { child_comm: postgres } hitcount: 6
1415 { child_comm: firefox } hitcount: 8
1416 { child_comm: dhclient } hitcount: 10
1417 { child_comm: emacs } hitcount: 12
1418 { child_comm: dbus-daemon } hitcount: 20
1419 { child_comm: nm-dispatcher.a } hitcount: 20
1420 { child_comm: evolution } hitcount: 35
1421 { child_comm: glib-pacrunner } hitcount: 59
1422
1423 Totals:
1424 Hits: 199
1425 Entries: 21
1426 Dropped: 0
1427
1428 To manually continue having the trigger aggregate events, append
1429 :cont instead. Notice that the trigger info displays as [active]
1430 again, and the data has changed:
1431
1432 # echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \
1433 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
1434
1435 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
1436 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active]
1437
1438 { child_comm: dconf worker } hitcount: 1
1439 { child_comm: dconf worker } hitcount: 1
1440 { child_comm: kthreadd } hitcount: 1
1441 { child_comm: gdbus } hitcount: 1
1442 { child_comm: ibus-daemon } hitcount: 1
1443 { child_comm: Socket Thread } hitcount: 2
1444 { child_comm: evolution-alarm } hitcount: 2
1445 { child_comm: smbd } hitcount: 2
1446 { child_comm: whoopsie } hitcount: 3
1447 { child_comm: compiz } hitcount: 3
1448 { child_comm: evolution-sourc } hitcount: 4
1449 { child_comm: bash } hitcount: 5
1450 { child_comm: pool } hitcount: 5
1451 { child_comm: postgres } hitcount: 6
1452 { child_comm: firefox } hitcount: 8
1453 { child_comm: dhclient } hitcount: 11
1454 { child_comm: emacs } hitcount: 12
1455 { child_comm: dbus-daemon } hitcount: 22
1456 { child_comm: nm-dispatcher.a } hitcount: 22
1457 { child_comm: evolution } hitcount: 35
1458 { child_comm: glib-pacrunner } hitcount: 59
1459
1460 Totals:
1461 Hits: 206
1462 Entries: 21
1463 Dropped: 0
1464
1465 The previous example showed how to start and stop a hist trigger by
1466 appending 'pause' and 'continue' to the hist trigger command. A
1467 hist trigger can also be started in a paused state by initially
1468 starting the trigger with ':pause' appended. This allows you to
1469 start the trigger only when you're ready to start collecting data
1470 and not before. For example, you could start the trigger in a
1471 paused state, then unpause it and do something you want to measure,
1472 then pause the trigger again when done.
1473
1474 Of course, doing this manually can be difficult and error-prone, but
1475 it is possible to automatically start and stop a hist trigger based
1476 on some condition, via the enable_hist and disable_hist triggers.
1477
1478 For example, suppose we wanted to take a look at the relative
1479 weights in terms of skb length for each callpath that leads to a
1480 netif_receieve_skb event when downloading a decent-sized file using
1481 wget.
1482
1483 First we set up an initially paused stacktrace trigger on the
1484 netif_receive_skb event:
1485
1486 # echo 'hist:key=stacktrace:vals=len:pause' > \
1487 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1488
1489 Next, we set up an 'enable_hist' trigger on the sched_process_exec
1490 event, with an 'if filename==/usr/bin/wget' filter. The effect of
1491 this new trigger is that it will 'unpause' the hist trigger we just
1492 set up on netif_receive_skb if and only if it sees a
1493 sched_process_exec event with a filename of '/usr/bin/wget'. When
1494 that happens, all netif_receive_skb events are aggregated into a
1495 hash table keyed on stacktrace:
1496
1497 # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \
1498 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
1499
1500 The aggregation continues until the netif_receive_skb is paused
1501 again, which is what the following disable_hist event does by
1502 creating a similar setup on the sched_process_exit event, using the
1503 filter 'comm==wget':
1504
1505 # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \
1506 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
1507
1508 Whenever a process exits and the comm field of the disable_hist
1509 trigger filter matches 'comm==wget', the netif_receive_skb hist
1510 trigger is disabled.
1511
1512 The overall effect is that netif_receive_skb events are aggregated
1513 into the hash table for only the duration of the wget. Executing a
1514 wget command and then listing the 'hist' file will display the
1515 output generated by the wget command:
1516
1517 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1518
1519 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
1520 # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused]
1521
1522 { stacktrace:
1523 __netif_receive_skb_core+0x46d/0x990
1524 __netif_receive_skb+0x18/0x60
1525 netif_receive_skb_internal+0x23/0x90
1526 napi_gro_receive+0xc8/0x100
1527 ieee80211_deliver_skb+0xd6/0x270 [mac80211]
1528 ieee80211_rx_handlers+0xccf/0x22f0 [mac80211]
1529 ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211]
1530 ieee80211_rx+0x31d/0x900 [mac80211]
1531 iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm]
1532 iwl_rx_dispatch+0x8e/0xf0 [iwldvm]
1533 iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi]
1534 irq_thread_fn+0x20/0x50
1535 irq_thread+0x11f/0x150
1536 kthread+0xd2/0xf0
1537 ret_from_fork+0x42/0x70
1538 } hitcount: 85 len: 28884
1539 { stacktrace:
1540 __netif_receive_skb_core+0x46d/0x990
1541 __netif_receive_skb+0x18/0x60
1542 netif_receive_skb_internal+0x23/0x90
1543 napi_gro_complete+0xa4/0xe0
1544 dev_gro_receive+0x23a/0x360
1545 napi_gro_receive+0x30/0x100
1546 ieee80211_deliver_skb+0xd6/0x270 [mac80211]
1547 ieee80211_rx_handlers+0xccf/0x22f0 [mac80211]
1548 ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211]
1549 ieee80211_rx+0x31d/0x900 [mac80211]
1550 iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm]
1551 iwl_rx_dispatch+0x8e/0xf0 [iwldvm]
1552 iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi]
1553 irq_thread_fn+0x20/0x50
1554 irq_thread+0x11f/0x150
1555 kthread+0xd2/0xf0
1556 } hitcount: 98 len: 664329
1557 { stacktrace:
1558 __netif_receive_skb_core+0x46d/0x990
1559 __netif_receive_skb+0x18/0x60
1560 process_backlog+0xa8/0x150
1561 net_rx_action+0x15d/0x340
1562 __do_softirq+0x114/0x2c0
1563 do_softirq_own_stack+0x1c/0x30
1564 do_softirq+0x65/0x70
1565 __local_bh_enable_ip+0xb5/0xc0
1566 ip_finish_output+0x1f4/0x840
1567 ip_output+0x6b/0xc0
1568 ip_local_out_sk+0x31/0x40
1569 ip_send_skb+0x1a/0x50
1570 udp_send_skb+0x173/0x2a0
1571 udp_sendmsg+0x2bf/0x9f0
1572 inet_sendmsg+0x64/0xa0
1573 sock_sendmsg+0x3d/0x50
1574 } hitcount: 115 len: 13030
1575 { stacktrace:
1576 __netif_receive_skb_core+0x46d/0x990
1577 __netif_receive_skb+0x18/0x60
1578 netif_receive_skb_internal+0x23/0x90
1579 napi_gro_complete+0xa4/0xe0
1580 napi_gro_flush+0x6d/0x90
1581 iwl_pcie_irq_handler+0x92a/0x12f0 [iwlwifi]
1582 irq_thread_fn+0x20/0x50
1583 irq_thread+0x11f/0x150
1584 kthread+0xd2/0xf0
1585 ret_from_fork+0x42/0x70
1586 } hitcount: 934 len: 5512212
1587
1588 Totals:
1589 Hits: 1232
1590 Entries: 4
1591 Dropped: 0
1592
1593 The above shows all the netif_receive_skb callpaths and their total
1594 lengths for the duration of the wget command.
1595
1596 The 'clear' hist trigger param can be used to clear the hash table.
1597 Suppose we wanted to try another run of the previous example but
1598 this time also wanted to see the complete list of events that went
1599 into the histogram. In order to avoid having to set everything up
1600 again, we can just clear the histogram first:
1601
1602 # echo 'hist:key=stacktrace:vals=len:clear' >> \
1603 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1604
1605 Just to verify that it is in fact cleared, here's what we now see in
1606 the hist file:
1607
1608 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
1609 # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused]
1610
1611 Totals:
1612 Hits: 0
1613 Entries: 0
1614 Dropped: 0
1615
1616 Since we want to see the detailed list of every netif_receive_skb
1617 event occurring during the new run, which are in fact the same
1618 events being aggregated into the hash table, we add some additional
1619 'enable_event' events to the triggering sched_process_exec and
1620 sched_process_exit events as such:
1621
1622 # echo 'enable_event:net:netif_receive_skb if filename==/usr/bin/wget' > \
1623 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
1624
1625 # echo 'disable_event:net:netif_receive_skb if comm==wget' > \
1626 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
1627
1628 If you read the trigger files for the sched_process_exec and
1629 sched_process_exit triggers, you should see two triggers for each:
1630 one enabling/disabling the hist aggregation and the other
1631 enabling/disabling the logging of events:
1632
1633 # cat /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
1634 enable_event:net:netif_receive_skb:unlimited if filename==/usr/bin/wget
1635 enable_hist:net:netif_receive_skb:unlimited if filename==/usr/bin/wget
1636
1637 # cat /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
1638 enable_event:net:netif_receive_skb:unlimited if comm==wget
1639 disable_hist:net:netif_receive_skb:unlimited if comm==wget
1640
1641 In other words, whenever either of the sched_process_exec or
1642 sched_process_exit events is hit and matches 'wget', it enables or
1643 disables both the histogram and the event log, and what you end up
1644 with is a hash table and set of events just covering the specified
1645 duration. Run the wget command again:
1646
1647 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1648
1649 Displaying the 'hist' file should show something similar to what you
1650 saw in the last run, but this time you should also see the
1651 individual events in the trace file:
1652
1653 # cat /sys/kernel/debug/tracing/trace
1654
1655 # tracer: nop
1656 #
1657 # entries-in-buffer/entries-written: 183/1426 #P:4
1658 #
1659 # _-----=> irqs-off
1660 # / _----=> need-resched
1661 # | / _---=> hardirq/softirq
1662 # || / _--=> preempt-depth
1663 # ||| / delay
1664 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
1665 # | | | |||| | |
1666 wget-15108 [000] ..s1 31769.606929: netif_receive_skb: dev=lo skbaddr=ffff88009c353100 len=60
1667 wget-15108 [000] ..s1 31769.606999: netif_receive_skb: dev=lo skbaddr=ffff88009c353200 len=60
1668 dnsmasq-1382 [000] ..s1 31769.677652: netif_receive_skb: dev=lo skbaddr=ffff88009c352b00 len=130
1669 dnsmasq-1382 [000] ..s1 31769.685917: netif_receive_skb: dev=lo skbaddr=ffff88009c352200 len=138
1670 ##### CPU 2 buffer started ####
1671 irq/29-iwlwifi-559 [002] ..s. 31772.031529: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433d00 len=2948
1672 irq/29-iwlwifi-559 [002] ..s. 31772.031572: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432200 len=1500
1673 irq/29-iwlwifi-559 [002] ..s. 31772.032196: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433100 len=2948
1674 irq/29-iwlwifi-559 [002] ..s. 31772.032761: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433000 len=2948
1675 irq/29-iwlwifi-559 [002] ..s. 31772.033220: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432e00 len=1500
1676 .
1677 .
1678 .
1679
1680 The following example demonstrates how multiple hist triggers can be
1681 attached to a given event. This capability can be useful for
1682 creating a set of different summaries derived from the same set of
1683 events, or for comparing the effects of different filters, among
1684 other things.
1685
1686 # echo 'hist:keys=skbaddr.hex:vals=len if len < 0' >> \
1687 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1688 # echo 'hist:keys=skbaddr.hex:vals=len if len > 4096' >> \
1689 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1690 # echo 'hist:keys=skbaddr.hex:vals=len if len == 256' >> \
1691 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1692 # echo 'hist:keys=skbaddr.hex:vals=len' >> \
1693 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1694 # echo 'hist:keys=len:vals=common_preempt_count' >> \
1695 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1696
1697 The above set of commands create four triggers differing only in
1698 their filters, along with a completely different though fairly
1699 nonsensical trigger. Note that in order to append multiple hist
1700 triggers to the same file, you should use the '>>' operator to
1701 append them ('>' will also add the new hist trigger, but will remove
1702 any existing hist triggers beforehand).
1703
1704 Displaying the contents of the 'hist' file for the event shows the
1705 contents of all five histograms:
1706
1707 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
1708
1709 # event histogram
1710 #
1711 # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active]
1712 #
1713
1714 { len: 176 } hitcount: 1 common_preempt_count: 0
1715 { len: 223 } hitcount: 1 common_preempt_count: 0
1716 { len: 4854 } hitcount: 1 common_preempt_count: 0
1717 { len: 395 } hitcount: 1 common_preempt_count: 0
1718 { len: 177 } hitcount: 1 common_preempt_count: 0
1719 { len: 446 } hitcount: 1 common_preempt_count: 0
1720 { len: 1601 } hitcount: 1 common_preempt_count: 0
1721 .
1722 .
1723 .
1724 { len: 1280 } hitcount: 66 common_preempt_count: 0
1725 { len: 116 } hitcount: 81 common_preempt_count: 40
1726 { len: 708 } hitcount: 112 common_preempt_count: 0
1727 { len: 46 } hitcount: 221 common_preempt_count: 0
1728 { len: 1264 } hitcount: 458 common_preempt_count: 0
1729
1730 Totals:
1731 Hits: 1428
1732 Entries: 147
1733 Dropped: 0
1734
1735
1736 # event histogram
1737 #
1738 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1739 #
1740
1741 { skbaddr: ffff8800baee5e00 } hitcount: 1 len: 130
1742 { skbaddr: ffff88005f3d5600 } hitcount: 1 len: 1280
1743 { skbaddr: ffff88005f3d4900 } hitcount: 1 len: 1280
1744 { skbaddr: ffff88009fed6300 } hitcount: 1 len: 115
1745 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 115
1746 { skbaddr: ffff88008cdb1900 } hitcount: 1 len: 46
1747 { skbaddr: ffff880064b5ef00 } hitcount: 1 len: 118
1748 { skbaddr: ffff880044e3c700 } hitcount: 1 len: 60
1749 { skbaddr: ffff880100065900 } hitcount: 1 len: 46
1750 { skbaddr: ffff8800d46bd500 } hitcount: 1 len: 116
1751 { skbaddr: ffff88005f3d5f00 } hitcount: 1 len: 1280
1752 { skbaddr: ffff880100064700 } hitcount: 1 len: 365
1753 { skbaddr: ffff8800badb6f00 } hitcount: 1 len: 60
1754 .
1755 .
1756 .
1757 { skbaddr: ffff88009fe0be00 } hitcount: 27 len: 24677
1758 { skbaddr: ffff88009fe0a400 } hitcount: 27 len: 23052
1759 { skbaddr: ffff88009fe0b700 } hitcount: 31 len: 25589
1760 { skbaddr: ffff88009fe0b600 } hitcount: 32 len: 27326
1761 { skbaddr: ffff88006a462800 } hitcount: 68 len: 71678
1762 { skbaddr: ffff88006a463700 } hitcount: 70 len: 72678
1763 { skbaddr: ffff88006a462b00 } hitcount: 71 len: 77589
1764 { skbaddr: ffff88006a463600 } hitcount: 73 len: 71307
1765 { skbaddr: ffff88006a462200 } hitcount: 81 len: 81032
1766
1767 Totals:
1768 Hits: 1451
1769 Entries: 318
1770 Dropped: 0
1771
1772
1773 # event histogram
1774 #
1775 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [active]
1776 #
1777
1778
1779 Totals:
1780 Hits: 0
1781 Entries: 0
1782 Dropped: 0
1783
1784
1785 # event histogram
1786 #
1787 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [active]
1788 #
1789
1790 { skbaddr: ffff88009fd2c300 } hitcount: 1 len: 7212
1791 { skbaddr: ffff8800d2bcce00 } hitcount: 1 len: 7212
1792 { skbaddr: ffff8800d2bcd700 } hitcount: 1 len: 7212
1793 { skbaddr: ffff8800d2bcda00 } hitcount: 1 len: 21492
1794 { skbaddr: ffff8800ae2e2d00 } hitcount: 1 len: 7212
1795 { skbaddr: ffff8800d2bcdb00 } hitcount: 1 len: 7212
1796 { skbaddr: ffff88006a4df500 } hitcount: 1 len: 4854
1797 { skbaddr: ffff88008ce47b00 } hitcount: 1 len: 18636
1798 { skbaddr: ffff8800ae2e2200 } hitcount: 1 len: 12924
1799 { skbaddr: ffff88005f3e1000 } hitcount: 1 len: 4356
1800 { skbaddr: ffff8800d2bcdc00 } hitcount: 2 len: 24420
1801 { skbaddr: ffff8800d2bcc200 } hitcount: 2 len: 12996
1802
1803 Totals:
1804 Hits: 14
1805 Entries: 12
1806 Dropped: 0
1807
1808
1809 # event histogram
1810 #
1811 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active]
1812 #
1813
1814
1815 Totals:
1816 Hits: 0
1817 Entries: 0
1818 Dropped: 0
1819
1820 Named triggers can be used to have triggers share a common set of
1821 histogram data. This capability is mostly useful for combining the
1822 output of events generated by tracepoints contained inside inline
1823 functions, but names can be used in a hist trigger on any event.
1824 For example, these two triggers when hit will update the same 'len'
1825 field in the shared 'foo' histogram data:
1826
1827 # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \
1828 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1829 # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \
1830 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
1831
1832 You can see that they're updating common histogram data by reading
1833 each event's hist files at the same time:
1834
1835 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist;
1836 cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
1837
1838 # event histogram
1839 #
1840 # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1841 #
1842
1843 { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46
1844 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76
1845 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46
1846 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468
1847 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46
1848 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52
1849 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168
1850 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46
1851 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260
1852 { skbaddr: ffff880064505000 } hitcount: 1 len: 46
1853 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32
1854 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46
1855 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44
1856 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168
1857 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40
1858 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40
1859 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174
1860 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160
1861 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76
1862 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46
1863 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32
1864 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46
1865 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988
1866 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46
1867 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44
1868 { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676
1869 { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107
1870 { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92
1871 { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142
1872 { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220
1873 { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92
1874 { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92
1875 { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675
1876 { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138
1877 { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138
1878 { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184
1879 { skbaddr: ffff880064504400 } hitcount: 4 len: 184
1880 { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184
1881 { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230
1882 { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196
1883 { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276
1884 { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276
1885
1886 Totals:
1887 Hits: 81
1888 Entries: 42
1889 Dropped: 0
1890 # event histogram
1891 #
1892 # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1893 #
1894
1895 { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46
1896 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76
1897 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46
1898 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468
1899 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46
1900 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52
1901 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168
1902 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46
1903 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260
1904 { skbaddr: ffff880064505000 } hitcount: 1 len: 46
1905 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32
1906 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46
1907 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44
1908 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168
1909 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40
1910 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40
1911 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174
1912 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160
1913 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76
1914 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46
1915 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32
1916 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46
1917 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988
1918 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46
1919 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44
1920 { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676
1921 { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107
1922 { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92
1923 { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142
1924 { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220
1925 { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92
1926 { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92
1927 { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675
1928 { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138
1929 { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138
1930 { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184
1931 { skbaddr: ffff880064504400 } hitcount: 4 len: 184
1932 { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184
1933 { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230
1934 { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196
1935 { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276
1936 { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276
1937
1938 Totals:
1939 Hits: 81
1940 Entries: 42
1941 Dropped: 0
1942
1943 And here's an example that shows how to combine histogram data from
1944 any two events even if they don't share any 'compatible' fields
1945 other than 'hitcount' and 'stacktrace'. These commands create a
1946 couple of triggers named 'bar' using those fields:
1947
1948 # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \
1949 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
1950 # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \
1951 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
1952
1953 And displaying the output of either shows some interesting if
1954 somewhat confusing output:
1955
1956 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
1957 # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
1958
1959 # event histogram
1960 #
1961 # trigger info: hist:name=bar:keys=stacktrace:vals=hitcount:sort=hitcount:size=2048 [active]
1962 #
1963
1964 { stacktrace:
1965 _do_fork+0x18e/0x330
1966 kernel_thread+0x29/0x30
1967 kthreadd+0x154/0x1b0
1968 ret_from_fork+0x3f/0x70
1969 } hitcount: 1
1970 { stacktrace:
1971 netif_rx_internal+0xb2/0xd0
1972 netif_rx_ni+0x20/0x70
1973 dev_loopback_xmit+0xaa/0xd0
1974 ip_mc_output+0x126/0x240
1975 ip_local_out_sk+0x31/0x40
1976 igmp_send_report+0x1e9/0x230
1977 igmp_timer_expire+0xe9/0x120
1978 call_timer_fn+0x39/0xf0
1979 run_timer_softirq+0x1e1/0x290
1980 __do_softirq+0xfd/0x290
1981 irq_exit+0x98/0xb0
1982 smp_apic_timer_interrupt+0x4a/0x60
1983 apic_timer_interrupt+0x6d/0x80
1984 cpuidle_enter+0x17/0x20
1985 call_cpuidle+0x3b/0x60
1986 cpu_startup_entry+0x22d/0x310
1987 } hitcount: 1
1988 { stacktrace:
1989 netif_rx_internal+0xb2/0xd0
1990 netif_rx_ni+0x20/0x70
1991 dev_loopback_xmit+0xaa/0xd0
1992 ip_mc_output+0x17f/0x240
1993 ip_local_out_sk+0x31/0x40
1994 ip_send_skb+0x1a/0x50
1995 udp_send_skb+0x13e/0x270
1996 udp_sendmsg+0x2bf/0x980
1997 inet_sendmsg+0x67/0xa0
1998 sock_sendmsg+0x38/0x50
1999 SYSC_sendto+0xef/0x170
2000 SyS_sendto+0xe/0x10
2001 entry_SYSCALL_64_fastpath+0x12/0x6a
2002 } hitcount: 2
2003 { stacktrace:
2004 netif_rx_internal+0xb2/0xd0
2005 netif_rx+0x1c/0x60
2006 loopback_xmit+0x6c/0xb0
2007 dev_hard_start_xmit+0x219/0x3a0
2008 __dev_queue_xmit+0x415/0x4f0
2009 dev_queue_xmit_sk+0x13/0x20
2010 ip_finish_output2+0x237/0x340
2011 ip_finish_output+0x113/0x1d0
2012 ip_output+0x66/0xc0
2013 ip_local_out_sk+0x31/0x40
2014 ip_send_skb+0x1a/0x50
2015 udp_send_skb+0x16d/0x270
2016 udp_sendmsg+0x2bf/0x980
2017 inet_sendmsg+0x67/0xa0
2018 sock_sendmsg+0x38/0x50
2019 ___sys_sendmsg+0x14e/0x270
2020 } hitcount: 76
2021 { stacktrace:
2022 netif_rx_internal+0xb2/0xd0
2023 netif_rx+0x1c/0x60
2024 loopback_xmit+0x6c/0xb0
2025 dev_hard_start_xmit+0x219/0x3a0
2026 __dev_queue_xmit+0x415/0x4f0
2027 dev_queue_xmit_sk+0x13/0x20
2028 ip_finish_output2+0x237/0x340
2029 ip_finish_output+0x113/0x1d0
2030 ip_output+0x66/0xc0
2031 ip_local_out_sk+0x31/0x40
2032 ip_send_skb+0x1a/0x50
2033 udp_send_skb+0x16d/0x270
2034 udp_sendmsg+0x2bf/0x980
2035 inet_sendmsg+0x67/0xa0
2036 sock_sendmsg+0x38/0x50
2037 ___sys_sendmsg+0x269/0x270
2038 } hitcount: 77
2039 { stacktrace:
2040 netif_rx_internal+0xb2/0xd0
2041 netif_rx+0x1c/0x60
2042 loopback_xmit+0x6c/0xb0
2043 dev_hard_start_xmit+0x219/0x3a0
2044 __dev_queue_xmit+0x415/0x4f0
2045 dev_queue_xmit_sk+0x13/0x20
2046 ip_finish_output2+0x237/0x340
2047 ip_finish_output+0x113/0x1d0
2048 ip_output+0x66/0xc0
2049 ip_local_out_sk+0x31/0x40
2050 ip_send_skb+0x1a/0x50
2051 udp_send_skb+0x16d/0x270
2052 udp_sendmsg+0x2bf/0x980
2053 inet_sendmsg+0x67/0xa0
2054 sock_sendmsg+0x38/0x50
2055 SYSC_sendto+0xef/0x170
2056 } hitcount: 88
2057 { stacktrace:
2058 _do_fork+0x18e/0x330
2059 SyS_clone+0x19/0x20
2060 entry_SYSCALL_64_fastpath+0x12/0x6a
2061 } hitcount: 244
2062
2063 Totals:
2064 Hits: 489
2065 Entries: 7
2066 Dropped: 0