platform/x86: thinkpad_acpi: Add 2nd Fan Support for Thinkpad P50
[sfrench/cifs-2.6.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