3 Documentation written by Theodore Ts'o
4 Updated by Li Zefan and Tom Zanussi
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
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
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
63 To enable event 'sched_wakeup':
65 # echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
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
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
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
96 3. Defining an event-enabled tracepoint
97 =======================================
99 See The example provided in samples/trace_events
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
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'
128 # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/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.
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:
192 The glob (~) only accepts a wild card character (*) at the start and or
193 end of the string. For example:
199 But does not allow for it to be within the string:
201 prev_comm ~ "ba*sh" <-- is invalid
206 A filter for an individual event is set by writing a filter expression
207 to the 'filter' file for the given event.
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
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.
238 To clear the filter for an event, write a '0' to the event's filter
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
261 Clear the filters on all events in the sched subsystem:
263 # cd /sys/kernel/debug/tracing/events/sched
265 # cat sched_switch/filter
267 # cat sched_wakeup/filter
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
277 # cat sched_wakeup/filter
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
284 # cd /sys/kernel/debug/tracing/events/sched
285 # echo prev_pid == 0 > filter
286 # cat sched_switch/filter
288 # cat sched_wakeup/filter
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
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
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
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
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).
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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]
1027 __kmalloc_track_caller+0x10b/0x1a0
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
1039 ret_from_intr+0x0/0x30
1040 cpuidle_enter+0x17/0x20
1041 cpu_startup_entry+0x315/0x3e0
1043 } hitcount: 3 bytes_req: 21 bytes_alloc: 24
1045 __kmalloc_track_caller+0x10b/0x1a0
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
1057 ret_from_intr+0x0/0x30
1058 } hitcount: 3 bytes_req: 21 bytes_alloc: 24
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
1072 __kmalloc+0x11b/0x1b0
1073 i915_gem_execbuffer2+0x6c/0x2c0 [i915]
1074 drm_ioctl+0x349/0x670 [drm]
1075 do_vfs_ioctl+0x2f0/0x4f0
1077 system_call_fastpath+0x12/0x6a
1078 } hitcount: 17726 bytes_req: 13944120 bytes_alloc: 19593808
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
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
1097 system_call_fastpath+0x12/0x6a
1098 } hitcount: 4766422 bytes_req: 9532844 bytes_alloc: 38131376
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
1107 system_call_fastpath+0x12/0x6a
1108 } hitcount: 19133 bytes_req: 78368768 bytes_alloc: 78368768
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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
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]
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
1540 ret_from_fork+0x42/0x70
1541 } hitcount: 85 len: 28884
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
1559 } hitcount: 98 len: 664329
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
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
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
1588 ret_from_fork+0x42/0x70
1589 } hitcount: 934 len: 5512212
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
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]
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
1660 # entries-in-buffer/entries-written: 183/1426 #P:4
1663 # / _----=> need-resched
1664 # | / _---=> hardirq/softirq
1665 # || / _--=> preempt-depth
1667 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
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
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
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
1714 # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active]
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
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
1741 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
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
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
1778 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [active]
1790 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [active]
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
1814 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active]
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
1843 # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
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
1895 # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
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
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
1964 # trigger info: hist:name=bar:keys=stacktrace:vals=hitcount:sort=hitcount:size=2048 [active]
1968 _do_fork+0x18e/0x330
1969 kernel_thread+0x29/0x30
1970 kthreadd+0x154/0x1b0
1971 ret_from_fork+0x3f/0x70
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
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
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
2004 entry_SYSCALL_64_fastpath+0x12/0x6a
2007 netif_rx_internal+0xb2/0xd0
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
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
2025 netif_rx_internal+0xb2/0xd0
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
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
2043 netif_rx_internal+0xb2/0xd0
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
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
2061 _do_fork+0x18e/0x330
2063 entry_SYSCALL_64_fastpath+0x12/0x6a