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