blob: 08d74d75150ddb40564c8da0187034412277b964 [file] [log] [blame]
Theodore Ts'oabd41442009-04-11 15:51:18 -04001 Event Tracing
2
3 Documentation written by Theodore Ts'o
Tom Zanussi95b69602009-09-10 23:13:51 -05004 Updated by Li Zefan and Tom Zanussi
Theodore Ts'oabd41442009-04-11 15:51:18 -04005
Li Zefan143c1452009-05-19 14:43:15 +080061. Introduction
7===============
Theodore Ts'oabd41442009-04-11 15:51:18 -04008
9Tracepoints (see Documentation/trace/tracepoints.txt) can be used
10without creating custom kernel modules to register probe functions
11using the event tracing infrastructure.
12
13Not all tracepoints can be traced using the event tracing system;
14the kernel developer must provide code snippets which define how the
15tracing information is saved into the tracing buffer, and how the
Li Zefan143c1452009-05-19 14:43:15 +080016tracing information should be printed.
Theodore Ts'oabd41442009-04-11 15:51:18 -040017
Li Zefan143c1452009-05-19 14:43:15 +0800182. Using Event Tracing
19======================
20
212.1 Via the 'set_event' interface
22---------------------------------
Theodore Ts'oabd41442009-04-11 15:51:18 -040023
24The events which are available for tracing can be found in the file
GeunSik Lim52ad51e2009-09-07 21:37:17 +090025/sys/kernel/debug/tracing/available_events.
Theodore Ts'oabd41442009-04-11 15:51:18 -040026
27To enable a particular event, such as 'sched_wakeup', simply echo it
GeunSik Lim52ad51e2009-09-07 21:37:17 +090028to /sys/kernel/debug/tracing/set_event. For example:
Theodore Ts'oabd41442009-04-11 15:51:18 -040029
GeunSik Lim52ad51e2009-09-07 21:37:17 +090030 # echo sched_wakeup >> /sys/kernel/debug/tracing/set_event
Theodore Ts'oabd41442009-04-11 15:51:18 -040031
Li Zefan143c1452009-05-19 14:43:15 +080032[ Note: '>>' is necessary, otherwise it will firstly disable
33 all the events. ]
Theodore Ts'oabd41442009-04-11 15:51:18 -040034
35To disable an event, echo the event name to the set_event file prefixed
36with an exclamation point:
37
GeunSik Lim52ad51e2009-09-07 21:37:17 +090038 # echo '!sched_wakeup' >> /sys/kernel/debug/tracing/set_event
Theodore Ts'oabd41442009-04-11 15:51:18 -040039
Li Zefan143c1452009-05-19 14:43:15 +080040To disable all events, echo an empty line to the set_event file:
Theodore Ts'oabd41442009-04-11 15:51:18 -040041
GeunSik Lim52ad51e2009-09-07 21:37:17 +090042 # echo > /sys/kernel/debug/tracing/set_event
Li Zefan143c1452009-05-19 14:43:15 +080043
44To enable all events, echo '*:*' or '*:' to the set_event file:
45
GeunSik Lim52ad51e2009-09-07 21:37:17 +090046 # echo *:* > /sys/kernel/debug/tracing/set_event
Theodore Ts'oabd41442009-04-11 15:51:18 -040047
48The events are organized into subsystems, such as ext4, irq, sched,
49etc., and a full event name looks like this: <subsystem>:<event>. The
50subsystem name is optional, but it is displayed in the available_events
51file. 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
53command:
54
GeunSik Lim52ad51e2009-09-07 21:37:17 +090055 # echo 'irq:*' > /sys/kernel/debug/tracing/set_event
Theodore Ts'oabd41442009-04-11 15:51:18 -040056
Li Zefan143c1452009-05-19 14:43:15 +0800572.2 Via the 'enable' toggle
58---------------------------
Theodore Ts'oabd41442009-04-11 15:51:18 -040059
GeunSik Lim52ad51e2009-09-07 21:37:17 +090060The events available are also listed in /sys/kernel/debug/tracing/events/ hierarchy
Li Zefan143c1452009-05-19 14:43:15 +080061of directories.
Theodore Ts'oabd41442009-04-11 15:51:18 -040062
Li Zefan143c1452009-05-19 14:43:15 +080063To enable event 'sched_wakeup':
Theodore Ts'oabd41442009-04-11 15:51:18 -040064
GeunSik Lim52ad51e2009-09-07 21:37:17 +090065 # echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
Theodore Ts'oabd41442009-04-11 15:51:18 -040066
Li Zefan143c1452009-05-19 14:43:15 +080067To disable it:
Theodore Ts'oabd41442009-04-11 15:51:18 -040068
GeunSik Lim52ad51e2009-09-07 21:37:17 +090069 # echo 0 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
Theodore Ts'oabd41442009-04-11 15:51:18 -040070
Li Zefan143c1452009-05-19 14:43:15 +080071To enable all events in sched subsystem:
Theodore Ts'oabd41442009-04-11 15:51:18 -040072
GeunSik Lim52ad51e2009-09-07 21:37:17 +090073 # echo 1 > /sys/kernel/debug/tracing/events/sched/enable
Theodore Ts'oabd41442009-04-11 15:51:18 -040074
Michal Sojka6afb1c62009-09-10 08:02:21 +020075To enable all events:
Theodore Ts'oabd41442009-04-11 15:51:18 -040076
GeunSik Lim52ad51e2009-09-07 21:37:17 +090077 # echo 1 > /sys/kernel/debug/tracing/events/enable
Theodore Ts'oabd41442009-04-11 15:51:18 -040078
Li Zefan143c1452009-05-19 14:43:15 +080079When reading one of these enable files, there are four results:
Theodore Ts'oabd41442009-04-11 15:51:18 -040080
Li Zefan143c1452009-05-19 14:43:15 +080081 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
Theodore Ts'oabd41442009-04-11 15:51:18 -040085
Li Zefan020e5f82009-07-01 10:47:05 +0800862.3 Boot option
87---------------
88
89In order to facilitate early boot debugging, use boot option:
90
91 trace_event=[event-list]
92
Li Zefan03d646e2009-12-21 14:27:24 +080093event-list is a comma separated list of events. See section 2.1 for event
94format.
Li Zefan020e5f82009-07-01 10:47:05 +080095
Li Zefan143c1452009-05-19 14:43:15 +0800963. Defining an event-enabled tracepoint
97=======================================
Theodore Ts'oabd41442009-04-11 15:51:18 -040098
Li Zefan143c1452009-05-19 14:43:15 +080099See The example provided in samples/trace_events
Theodore Ts'oabd41442009-04-11 15:51:18 -0400100
Tom Zanussi95b69602009-09-10 23:13:51 -05001014. Event formats
102================
103
104Each trace event has a 'format' file associated with it that contains
105a description of each field in a logged event. This information can
106be used to parse the binary trace stream, and is also the place to
107find the field names that can be used in event filters (see section 5).
108
109It also displays the format string that will be used to print the
110event in text mode, along with the event name and ID used for
111profiling.
112
113Every event has a set of 'common' fields associated with it; these are
114the fields prefixed with 'common_'. The other fields vary between
115events and correspond to the fields defined in the TRACE_EVENT
116definition for that event.
117
118Each field in the format has the form:
119
120 field:field-type field-name; offset:N; size:N;
121
122where offset is the offset of the field in the trace record and size
123is the size of the data item, in bytes.
124
125For example, here's the information displayed for the 'sched_wakeup'
126event:
127
Tao Mabfc672d2011-01-05 14:07:54 +0800128# cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/format
Tom Zanussi95b69602009-09-10 23:13:51 -0500129
130name: sched_wakeup
131ID: 60
132format:
133 field:unsigned short common_type; offset:0; size:2;
134 field:unsigned char common_flags; offset:2; size:1;
135 field:unsigned char common_preempt_count; offset:3; size:1;
136 field:int common_pid; offset:4; size:4;
137 field:int common_tgid; offset:8; size:4;
138
139 field:char comm[TASK_COMM_LEN]; offset:12; size:16;
140 field:pid_t pid; offset:28; size:4;
141 field:int prio; offset:32; size:4;
142 field:int success; offset:36; size:4;
143 field:int cpu; offset:40; size:4;
144
145print fmt: "task %s:%d [%d] success=%d [%03d]", REC->comm, REC->pid,
146 REC->prio, REC->success, REC->cpu
147
148This event contains 10 fields, the first 5 common and the remaining 5
149event-specific. All the fields for this event are numeric, except for
150'comm' which is a string, a distinction important for event filtering.
151
1525. Event filtering
153==================
154
155Trace events can be filtered in the kernel by associating boolean
156'filter expressions' with them. As soon as an event is logged into
157the trace buffer, its fields are checked against the filter expression
158associated with that event type. An event with field values that
159'match' the filter will appear in the trace output, and an event whose
160values don't match will be discarded. An event with no filter
161associated with it matches everything, and is the default when no
162filter has been set for an event.
163
1645.1 Expression syntax
165---------------------
166
167A filter expression consists of one or more 'predicates' that can be
168combined using the logical operators '&&' and '||'. A predicate is
169simply a clause that compares the value of a field contained within a
170logged event with a constant value and returns either 0 or 1 depending
171on whether the field value matched (1) or didn't match (0):
172
173 field-name relational-operator value
174
175Parentheses can be used to provide arbitrary logical groupings and
176double-quotes can be used to prevent the shell from interpreting
177operators as shell metacharacters.
178
179The field-names available for use in filters can be found in the
180'format' files for trace events (see section 4).
181
182The relational-operators depend on the type of the field being tested:
183
184The operators available for numeric fields are:
185
Steven Rostedt1a891cf2013-06-12 13:16:25 -0400186==, !=, <, <=, >, >=, &
Tom Zanussi95b69602009-09-10 23:13:51 -0500187
188And for string fields they are:
189
Steven Rostedt (Red Hat)c3e13c72013-06-17 10:59:17 -0400190==, !=, ~
Tom Zanussi95b69602009-09-10 23:13:51 -0500191
Steven Rostedt (Red Hat)c3e13c72013-06-17 10:59:17 -0400192The glob (~) only accepts a wild card character (*) at the start and or
193end of the string. For example:
194
195 prev_comm ~ "*sh"
196 prev_comm ~ "sh*"
197 prev_comm ~ "*sh*"
198
199But does not allow for it to be within the string:
200
201 prev_comm ~ "ba*sh" <-- is invalid
Tom Zanussi95b69602009-09-10 23:13:51 -0500202
Tom Zanussi95b69602009-09-10 23:13:51 -05002035.2 Setting filters
204-------------------
205
206A filter for an individual event is set by writing a filter expression
207to the 'filter' file for the given event.
208
209For example:
210
Tao Mabfc672d2011-01-05 14:07:54 +0800211# cd /sys/kernel/debug/tracing/events/sched/sched_wakeup
Tom Zanussi95b69602009-09-10 23:13:51 -0500212# echo "common_preempt_count > 4" > filter
213
214A slightly more involved example:
215
Tao Mabfc672d2011-01-05 14:07:54 +0800216# cd /sys/kernel/debug/tracing/events/signal/signal_generate
Tom Zanussi95b69602009-09-10 23:13:51 -0500217# echo "((sig >= 10 && sig < 15) || sig == 17) && comm != bash" > filter
218
219If there is an error in the expression, you'll get an 'Invalid
220argument' error when setting it, and the erroneous string along with
221an error message can be seen by looking at the filter e.g.:
222
Tao Mabfc672d2011-01-05 14:07:54 +0800223# cd /sys/kernel/debug/tracing/events/signal/signal_generate
Tom Zanussi95b69602009-09-10 23:13:51 -0500224# 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
228^
229parse_error: Field not found
230
231Currently the caret ('^') for an error always appears at the beginning of
232the filter string; the error message should still be useful though
233even without more accurate position info.
234
2355.3 Clearing filters
236--------------------
237
238To clear the filter for an event, write a '0' to the event's filter
239file.
240
241To clear the filters for all events in a subsystem, write a '0' to the
242subsystem's filter file.
243
2445.3 Subsystem filters
245---------------------
246
247For convenience, filters for every event in a subsystem can be set or
248cleared as a group by writing a filter expression into the filter file
Thomas Weber88393162010-03-16 11:47:56 +0100249at the root of the subsystem. Note however, that if a filter for any
Tom Zanussi95b69602009-09-10 23:13:51 -0500250event within the subsystem lacks a field specified in the subsystem
251filter, or if the filter can't be applied for any other reason, the
252filter for that event will retain its previous setting. This can
253result in an unintended mixture of filters which could lead to
254confusing (to the user who might think different filters are in
255effect) trace output. Only filters that reference just the common
256fields can be guaranteed to propagate successfully to all events.
257
258Here are a few subsystem filter examples that also illustrate the
259above points:
260
Thomas Weber88393162010-03-16 11:47:56 +0100261Clear the filters on all events in the sched subsystem:
Tom Zanussi95b69602009-09-10 23:13:51 -0500262
263# cd /sys/kernel/debug/tracing/events/sched
264# echo 0 > filter
265# cat sched_switch/filter
266none
267# cat sched_wakeup/filter
268none
269
270Set a filter using only common fields for all events in the sched
Thomas Weber88393162010-03-16 11:47:56 +0100271subsystem (all events end up with the same filter):
Tom Zanussi95b69602009-09-10 23:13:51 -0500272
273# cd /sys/kernel/debug/tracing/events/sched
274# echo common_pid == 0 > filter
275# cat sched_switch/filter
276common_pid == 0
277# cat sched_wakeup/filter
278common_pid == 0
279
280Attempt to set a filter using a non-common field for all events in the
Thomas Weber88393162010-03-16 11:47:56 +0100281sched subsystem (all events but those that have a prev_pid field retain
Tom Zanussi95b69602009-09-10 23:13:51 -0500282their old filters):
283
284# cd /sys/kernel/debug/tracing/events/sched
285# echo prev_pid == 0 > filter
286# cat sched_switch/filter
287prev_pid == 0
288# cat sched_wakeup/filter
289common_pid == 0
Tom Zanussiac38fb82013-10-24 08:59:30 -0500290
Steven Rostedt (Red Hat)627645f2015-11-03 16:37:15 -05002915.4 PID filtering
292-----------------
293
294The set_event_pid file in the same directory as the top events directory
295exists, will filter all events from tracing any task that does not have the
296PID listed in the set_event_pid file.
297
298# cd /sys/kernel/debug/tracing
299# echo $$ > set_event_pid
300# echo 1 > events/enabled
301
302Will only trace events for the current task.
303
304To add more PIDs without losing the PIDs already included, use '>>'.
305
306# echo 123 244 1 >> set_event_pid
307
308
Tom Zanussiac38fb82013-10-24 08:59:30 -05003096. Event triggers
310=================
311
312Trace events can be made to conditionally invoke trigger 'commands'
313which can take various forms and are described in detail below;
314examples would be enabling or disabling other trace events or invoking
315a stack trace whenever the trace event is hit. Whenever a trace event
316with attached triggers is invoked, the set of trigger commands
317associated with that event is invoked. Any given trigger can
318additionally have an event filter of the same form as described in
319section 5 (Event filtering) associated with it - the command will only
320be invoked if the event being invoked passes the associated filter.
321If no filter is associated with the trigger, it always passes.
322
323Triggers are added to and removed from a particular event by writing
324trigger expressions to the 'trigger' file for the given event.
325
326A given event can have any number of triggers associated with it,
327subject to any restrictions that individual commands may have in that
328regard.
329
330Event triggers are implemented on top of "soft" mode, which means that
331whenever a trace event has one or more triggers associated with it,
332the event is activated even if it isn't actually enabled, but is
333disabled in a "soft" mode. That is, the tracepoint will be called,
334but just will not be traced, unless of course it's actually enabled.
335This scheme allows triggers to be invoked even for events that aren't
336enabled, and also allows the current event filter implementation to be
337used for conditionally invoking triggers.
338
339The syntax for event triggers is roughly based on the syntax for
340set_ftrace_filter 'ftrace filter commands' (see the 'Filter commands'
341section of Documentation/trace/ftrace.txt), but there are major
342differences and the implementation isn't currently tied to it in any
343way, so beware about making generalizations between the two.
344
3456.1 Expression syntax
346---------------------
347
348Triggers are added by echoing the command to the 'trigger' file:
349
350 # echo 'command[:count] [if filter]' > trigger
351
352Triggers are removed by echoing the same command but starting with '!'
353to the 'trigger' file:
354
355 # echo '!command[:count] [if filter]' > trigger
356
357The [if filter] part isn't used in matching commands when removing, so
358leaving that off in a '!' command will accomplish the same thing as
359having it in.
360
361The filter syntax is the same as that described in the 'Event
362filtering' section above.
363
364For ease of use, writing to the trigger file using '>' currently just
365adds or removes a single trigger and there's no explicit '>>' support
366('>' actually behaves like '>>') or truncation support to remove all
367triggers (you have to use '!' for each one added.)
368
3696.2 Supported trigger commands
370------------------------------
371
372The following commands are supported:
373
374- enable_event/disable_event
375
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.
382
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:
386
387 # echo 'enable_event:kmem:kmalloc:1' > \
388 /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
389
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:
393
394 # echo 'disable_event:kmem:kmalloc' > \
395 /sys/kernel/debug/tracing/events/syscalls/sys_exit_read/trigger
396
397 The format is:
398
399 enable_event:<system>:<event>[:count]
400 disable_event:<system>:<event>[:count]
401
402 To remove the above commands:
403
404 # echo '!enable_event:kmem:kmalloc:1' > \
405 /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
406
407 # echo '!disable_event:kmem:kmalloc' > \
408 /sys/kernel/debug/tracing/events/syscalls/sys_exit_read/trigger
409
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).
417
418- stacktrace
419
420 This command dumps a stacktrace in the trace buffer whenever the
421 triggering event occurs.
422
423 For example, the following trigger dumps a stacktrace every time the
424 kmalloc tracepoint is hit:
425
426 # echo 'stacktrace' > \
427 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
428
429 The following trigger dumps a stacktrace the first 5 times a kmalloc
430 request happens with a size >= 64K
431
432 # echo 'stacktrace:5 if bytes_req >= 65536' > \
433 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
434
435 The format is:
436
437 stacktrace[:count]
438
439 To remove the above commands:
440
441 # echo '!stacktrace' > \
442 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
443
444 # echo '!stacktrace:5 if bytes_req >= 65536' > \
445 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
446
447 The latter can also be removed more simply by the following (without
448 the filter):
449
450 # echo '!stacktrace:5' > \
451 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
452
453 Note that there can be only one stacktrace trigger per triggering
454 event.
455
456- snapshot
457
458 This command causes a snapshot to be triggered whenever the
459 triggering event occurs.
460
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
Carlos Garciac98be0c2014-04-04 22:31:00 -0400464 capture those events when the trigger event occurred:
Tom Zanussiac38fb82013-10-24 08:59:30 -0500465
466 # echo 'snapshot if nr_rq > 1' > \
467 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
468
469 To only snapshot once:
470
471 # echo 'snapshot:1 if nr_rq > 1' > \
472 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
473
474 To remove the above commands:
475
476 # echo '!snapshot if nr_rq > 1' > \
477 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
478
479 # echo '!snapshot:1 if nr_rq > 1' > \
480 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
481
482 Note that there can be only one snapshot trigger per triggering
483 event.
484
485- traceon/traceoff
486
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.
490
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:
496
497 # echo 'traceoff:1 if nr_rq > 1' > \
498 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
499
500 To always disable tracing when nr_rq > 1 :
501
502 # echo 'traceoff if nr_rq > 1' > \
503 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
504
505 To remove the above commands:
506
507 # echo '!traceoff:1 if nr_rq > 1' > \
508 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
509
510 # echo '!traceoff if nr_rq > 1' > \
511 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
512
513 Note that there can be only one traceon or traceoff trigger per
514 triggering event.
Tom Zanussi0fc38132016-03-03 12:54:56 -0600515
516- hist
517
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).
522
523 The format of a hist trigger is as follows:
524
525 hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>]
526 [:sort=<field1[,field2,...]>][:size=#entries][:pause][:continue]
Tom Zanussi5463bfd2016-03-03 12:54:59 -0600527 [:clear][:name=histname1] [if <filter>]
Tom Zanussi0fc38132016-03-03 12:54:56 -0600528
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
Tom Zanussi5463bfd2016-03-03 12:54:59 -0600549 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.
Tom Zanussi0fc38132016-03-03 12:54:56 -0600558
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
Tom Zanussi52a7f162016-03-03 12:54:57 -0600561 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
Tom Zanussi5463bfd2016-03-03 12:54:59 -0600563 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:
Tom Zanussi0fc38132016-03-03 12:54:56 -0600571
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
577
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:
581
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.
592
593 A typical usage scenario would be the following to enable a hist
594 trigger, read its current contents, and then turn it off:
595
596 # echo 'hist:keys=skbaddr.hex:vals=len' > \
597 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
598
599 # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
600
601 # echo '!hist:keys=skbaddr.hex:vals=len' > \
602 /sys/kernel/debug/tracing/events/net/netif_rx/trigger
603
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.
607
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).
615
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.
620
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.
625
626 The 'clear' parameter will clear the contents of a running hist
627 trigger and leave its current paused/active state.
628
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.
633
634- enable_hist/disable_hist
635
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.
641
642 The format is very similar to the enable/disable_event triggers:
643
644 enable_hist:<system>:<event>[:count]
645 disable_hist:<system>:<event>[:count]
646
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.
651
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:
656
657 # echo 'hist:keys=skbaddr.hex:vals=len:pause' > \
658 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
659
660 # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \
661 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
662
663 # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \
664 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
665
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.
670
671 The examples below provide a more concrete illustration of the
672 concepts and typical usage patterns discussed above.
673
674
6756.2 'hist' trigger examples
676---------------------------
677
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:
681
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;
690
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;
696
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:
700
701 # echo 'hist:key=call_site:val=bytes_req' > \
702 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
703
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.
711
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):
715
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]
718
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
744
745 Totals:
746 Hits: 4610
747 Entries: 45
748 Dropped: 0
749
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:
755
756 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
757 hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
758
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).
767
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.
777
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.
782
783 To turn the hist trigger off, simply call up the trigger in the
784 command history and re-execute it with a '!' prepended:
785
786 # echo '!hist:key=call_site:val=bytes_req' > \
787 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
788
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:
793
794 # echo 'hist:key=call_site.hex:val=bytes_req' > \
795 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
796
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]
799
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
826
827 Totals:
828 Hits: 4775
829 Entries: 46
830 Dropped: 0
831
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:
838
839 # echo 'hist:key=call_site.sym:val=bytes_req' > \
840 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
841
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]
844
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
875
876 Totals:
877 Hits: 109928
878 Entries: 71
879 Dropped: 0
880
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:
888
889 # echo 'hist:key=call_site.sym:val=bytes_req:sort=bytes_req.descending' > \
890 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
891
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]
894
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
921
922 Totals:
923 Hits: 32133
924 Entries: 81
925 Dropped: 0
926
927 To display the offset and size information in addition to the symbol
928 name, just use 'sym-offset' instead:
929
930 # echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \
931 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
932
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]
935
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
958
959 Totals:
960 Hits: 26098
961 Entries: 64
962 Dropped: 0
963
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:
968
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
971
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]
974
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
1000
1001 Totals:
1002 Hits: 66598
1003 Entries: 65
1004 Dropped: 0
1005
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:
1011
1012 # echo 'hist:keys=stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' > \
1013 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
1014
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):
1022
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]
1025
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
1109
1110 Totals:
1111 Hits: 6085872
1112 Entries: 253
1113 Dropped: 0
1114
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:
1120
1121 # echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \
1122 /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
1123
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]
1126
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
1150
1151 Totals:
1152 Hits: 2116
1153 Entries: 51
1154 Dropped: 0
1155
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:
1161
1162 # echo 'hist:key=id.syscall:val=hitcount' > \
1163 /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger
1164
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]
1167
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
1196
1197 Totals:
1198 Hits: 67612
1199 Entries: 72
1200 Dropped: 0
1201
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.
1205
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.
1209
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:
1215
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
1218
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]
1221
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
1254
1255 Totals:
1256 Hits: 31536
1257 Entries: 323
1258 Dropped: 0
1259
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:
1265
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
1268
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]
1271
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
1290
1291 Totals:
1292 Hits: 101162
1293 Entries: 103
1294 Dropped: 0
1295
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.)
1300
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:
1308
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
1311
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]
1314
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
1346
1347 Totals:
1348 Hits: 2016
1349 Entries: 224
1350 Dropped: 0
1351
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.
1355
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:
1361
1362 # echo 'hist:key=child_comm:val=hitcount:size=256' > \
1363 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
1364
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]
1367
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
1388
1389 Totals:
1390 Hits: 89
1391 Entries: 20
1392 Dropped: 0
1393
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]:
1397
1398 # echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \
1399 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
1400
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]
1403
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
1425
1426 Totals:
1427 Hits: 199
1428 Entries: 21
1429 Dropped: 0
1430
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:
1434
1435 # echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \
1436 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger
1437
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]
1440
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
1462
1463 Totals:
1464 Hits: 206
1465 Entries: 21
1466 Dropped: 0
1467
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.
1476
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.
1480
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.
1485
1486 First we set up an initially paused stacktrace trigger on the
1487 netif_receive_skb event:
1488
1489 # echo 'hist:key=stacktrace:vals=len:pause' > \
1490 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1491
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:
1499
1500 # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \
1501 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
1502
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':
1507
1508 # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \
1509 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
1510
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.
1514
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:
1519
1520 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1521
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]
1524
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
1590
1591 Totals:
1592 Hits: 1232
1593 Entries: 4
1594 Dropped: 0
1595
1596 The above shows all the netif_receive_skb callpaths and their total
1597 lengths for the duration of the wget command.
1598
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:
1604
1605 # echo 'hist:key=stacktrace:vals=len:clear' >> \
1606 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger
1607
1608 Just to verify that it is in fact cleared, here's what we now see in
1609 the hist file:
1610
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]
1613
1614 Totals:
1615 Hits: 0
1616 Entries: 0
1617 Dropped: 0
1618
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:
1624
1625 # echo 'enable_event:net:netif_receive_skb if filename==/usr/bin/wget' > \
1626 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger
1627
1628 # echo 'disable_event:net:netif_receive_skb if comm==wget' > \
1629 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger
1630
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:
1635
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
1639
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
1643
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:
1649
1650 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1651
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:
1655
1656 # cat /sys/kernel/debug/tracing/trace
1657
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 .
Tom Zanussi52a7f162016-03-03 12:54:57 -06001682
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.
1688
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
1699
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).
1706
1707 Displaying the contents of the 'hist' file for the event shows the
1708 contents of all five histograms:
1709
1710 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist
1711
1712 # event histogram
1713 #
1714 # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active]
1715 #
1716
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
1732
1733 Totals:
1734 Hits: 1428
1735 Entries: 147
1736 Dropped: 0
1737
1738
1739 # event histogram
1740 #
1741 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1742 #
1743
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
1769
1770 Totals:
1771 Hits: 1451
1772 Entries: 318
1773 Dropped: 0
1774
1775
1776 # event histogram
1777 #
1778 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [active]
1779 #
1780
1781
1782 Totals:
1783 Hits: 0
1784 Entries: 0
1785 Dropped: 0
1786
1787
1788 # event histogram
1789 #
1790 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [active]
1791 #
1792
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
1805
1806 Totals:
1807 Hits: 14
1808 Entries: 12
1809 Dropped: 0
1810
1811
1812 # event histogram
1813 #
1814 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active]
1815 #
1816
1817
1818 Totals:
1819 Hits: 0
1820 Entries: 0
1821 Dropped: 0
Tom Zanussi5463bfd2016-03-03 12:54:59 -06001822
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:
1829
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
1834
1835 You can see that they're updating common histogram data by reading
1836 each event's hist files at the same time:
1837
1838 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist;
1839 cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
1840
1841 # event histogram
1842 #
1843 # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1844 #
1845
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
1888
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 #
1897
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
1940
1941 Totals:
1942 Hits: 81
1943 Entries: 42
1944 Dropped: 0
1945
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:
1950
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
1955
1956 And displaying the output of either shows some interesting if
1957 somewhat confusing output:
1958
1959 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist
1960 # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist
1961
1962 # event histogram
1963 #
1964 # trigger info: hist:name=bar:keys=stacktrace:vals=hitcount:sort=hitcount:size=2048 [active]
1965 #
1966
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
2065
2066 Totals:
2067 Hits: 489
2068 Entries: 7
2069 Dropped: 0