Commit | Line | Data |
---|---|---|
abd41443 TT |
1 | Event Tracing |
2 | ||
3 | Documentation written by Theodore Ts'o | |
95b69608 | 4 | Updated by Li Zefan and Tom Zanussi |
abd41443 | 5 | |
143c145e LZ |
6 | 1. Introduction |
7 | =============== | |
abd41443 TT |
8 | |
9 | Tracepoints (see Documentation/trace/tracepoints.txt) can be used | |
10 | without creating custom kernel modules to register probe functions | |
11 | using the event tracing infrastructure. | |
12 | ||
13 | Not all tracepoints can be traced using the event tracing system; | |
14 | the kernel developer must provide code snippets which define how the | |
15 | tracing information is saved into the tracing buffer, and how the | |
143c145e | 16 | tracing information should be printed. |
abd41443 | 17 | |
143c145e LZ |
18 | 2. Using Event Tracing |
19 | ====================== | |
20 | ||
21 | 2.1 Via the 'set_event' interface | |
22 | --------------------------------- | |
abd41443 TT |
23 | |
24 | The events which are available for tracing can be found in the file | |
52ad51e7 | 25 | /sys/kernel/debug/tracing/available_events. |
abd41443 TT |
26 | |
27 | To enable a particular event, such as 'sched_wakeup', simply echo it | |
52ad51e7 | 28 | to /sys/kernel/debug/tracing/set_event. For example: |
abd41443 | 29 | |
52ad51e7 | 30 | # echo sched_wakeup >> /sys/kernel/debug/tracing/set_event |
abd41443 | 31 | |
143c145e LZ |
32 | [ Note: '>>' is necessary, otherwise it will firstly disable |
33 | all the events. ] | |
abd41443 TT |
34 | |
35 | To disable an event, echo the event name to the set_event file prefixed | |
36 | with an exclamation point: | |
37 | ||
52ad51e7 | 38 | # echo '!sched_wakeup' >> /sys/kernel/debug/tracing/set_event |
143c145e LZ |
39 | |
40 | To disable all events, echo an empty line to the set_event file: | |
41 | ||
52ad51e7 | 42 | # echo > /sys/kernel/debug/tracing/set_event |
abd41443 | 43 | |
143c145e | 44 | To enable all events, echo '*:*' or '*:' to the set_event file: |
abd41443 | 45 | |
52ad51e7 | 46 | # echo *:* > /sys/kernel/debug/tracing/set_event |
abd41443 TT |
47 | |
48 | The events are organized into subsystems, such as ext4, irq, sched, | |
49 | etc., and a full event name looks like this: <subsystem>:<event>. The | |
50 | subsystem name is optional, but it is displayed in the available_events | |
51 | file. All of the events in a subsystem can be specified via the syntax | |
52 | "<subsystem>:*"; for example, to enable all irq events, you can use the | |
53 | command: | |
54 | ||
52ad51e7 | 55 | # echo 'irq:*' > /sys/kernel/debug/tracing/set_event |
143c145e LZ |
56 | |
57 | 2.2 Via the 'enable' toggle | |
58 | --------------------------- | |
59 | ||
52ad51e7 | 60 | The events available are also listed in /sys/kernel/debug/tracing/events/ hierarchy |
143c145e LZ |
61 | of directories. |
62 | ||
63 | To enable event 'sched_wakeup': | |
64 | ||
52ad51e7 | 65 | # echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable |
143c145e LZ |
66 | |
67 | To disable it: | |
68 | ||
52ad51e7 | 69 | # echo 0 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable |
143c145e LZ |
70 | |
71 | To enable all events in sched subsystem: | |
72 | ||
52ad51e7 | 73 | # echo 1 > /sys/kernel/debug/tracing/events/sched/enable |
143c145e | 74 | |
6afb1c65 | 75 | To enable all events: |
143c145e | 76 | |
52ad51e7 | 77 | # echo 1 > /sys/kernel/debug/tracing/events/enable |
143c145e LZ |
78 | |
79 | When reading one of these enable files, there are four results: | |
80 | ||
81 | 0 - all events this file affects are disabled | |
82 | 1 - all events this file affects are enabled | |
83 | X - there is a mixture of events enabled and disabled | |
84 | ? - this file does not affect any event | |
85 | ||
020e5f85 LZ |
86 | 2.3 Boot option |
87 | --------------- | |
88 | ||
89 | In order to facilitate early boot debugging, use boot option: | |
90 | ||
91 | trace_event=[event-list] | |
92 | ||
03d646e6 LZ |
93 | event-list is a comma separated list of events. See section 2.1 for event |
94 | format. | |
020e5f85 | 95 | |
143c145e LZ |
96 | 3. Defining an event-enabled tracepoint |
97 | ======================================= | |
98 | ||
99 | See The example provided in samples/trace_events | |
100 | ||
95b69608 TZ |
101 | 4. Event formats |
102 | ================ | |
103 | ||
104 | Each trace event has a 'format' file associated with it that contains | |
105 | a description of each field in a logged event. This information can | |
106 | be used to parse the binary trace stream, and is also the place to | |
107 | find the field names that can be used in event filters (see section 5). | |
108 | ||
109 | It also displays the format string that will be used to print the | |
110 | event in text mode, along with the event name and ID used for | |
111 | profiling. | |
112 | ||
113 | Every event has a set of 'common' fields associated with it; these are | |
114 | the fields prefixed with 'common_'. The other fields vary between | |
115 | events and correspond to the fields defined in the TRACE_EVENT | |
116 | definition for that event. | |
117 | ||
118 | Each field in the format has the form: | |
119 | ||
120 | field:field-type field-name; offset:N; size:N; | |
121 | ||
122 | where offset is the offset of the field in the trace record and size | |
123 | is the size of the data item, in bytes. | |
124 | ||
125 | For example, here's the information displayed for the 'sched_wakeup' | |
126 | event: | |
127 | ||
bfc672dc | 128 | # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/format |
95b69608 TZ |
129 | |
130 | name: sched_wakeup | |
131 | ID: 60 | |
132 | format: | |
133 | field:unsigned short common_type; offset:0; size:2; | |
134 | field:unsigned char common_flags; offset:2; size:1; | |
135 | field:unsigned char common_preempt_count; offset:3; size:1; | |
136 | field:int common_pid; offset:4; size:4; | |
137 | field:int common_tgid; offset:8; size:4; | |
138 | ||
139 | field:char comm[TASK_COMM_LEN]; offset:12; size:16; | |
140 | field:pid_t pid; offset:28; size:4; | |
141 | field:int prio; offset:32; size:4; | |
142 | field:int success; offset:36; size:4; | |
143 | field:int cpu; offset:40; size:4; | |
144 | ||
145 | print fmt: "task %s:%d [%d] success=%d [%03d]", REC->comm, REC->pid, | |
146 | REC->prio, REC->success, REC->cpu | |
147 | ||
148 | This event contains 10 fields, the first 5 common and the remaining 5 | |
149 | event-specific. All the fields for this event are numeric, except for | |
150 | 'comm' which is a string, a distinction important for event filtering. | |
151 | ||
152 | 5. Event filtering | |
153 | ================== | |
154 | ||
155 | Trace events can be filtered in the kernel by associating boolean | |
156 | 'filter expressions' with them. As soon as an event is logged into | |
157 | the trace buffer, its fields are checked against the filter expression | |
158 | associated with that event type. An event with field values that | |
159 | 'match' the filter will appear in the trace output, and an event whose | |
160 | values don't match will be discarded. An event with no filter | |
161 | associated with it matches everything, and is the default when no | |
162 | filter has been set for an event. | |
163 | ||
164 | 5.1 Expression syntax | |
165 | --------------------- | |
166 | ||
167 | A filter expression consists of one or more 'predicates' that can be | |
168 | combined using the logical operators '&&' and '||'. A predicate is | |
169 | simply a clause that compares the value of a field contained within a | |
170 | logged event with a constant value and returns either 0 or 1 depending | |
171 | on whether the field value matched (1) or didn't match (0): | |
172 | ||
173 | field-name relational-operator value | |
174 | ||
175 | Parentheses can be used to provide arbitrary logical groupings and | |
176 | double-quotes can be used to prevent the shell from interpreting | |
177 | operators as shell metacharacters. | |
178 | ||
179 | The field-names available for use in filters can be found in the | |
180 | 'format' files for trace events (see section 4). | |
181 | ||
182 | The relational-operators depend on the type of the field being tested: | |
183 | ||
184 | The operators available for numeric fields are: | |
185 | ||
1a891cf1 | 186 | ==, !=, <, <=, >, >=, & |
95b69608 TZ |
187 | |
188 | And for string fields they are: | |
189 | ||
c3e13c7c | 190 | ==, !=, ~ |
95b69608 | 191 | |
c3e13c7c SRRH |
192 | The glob (~) only accepts a wild card character (*) at the start and or |
193 | end of the string. For example: | |
194 | ||
195 | prev_comm ~ "*sh" | |
196 | prev_comm ~ "sh*" | |
197 | prev_comm ~ "*sh*" | |
198 | ||
199 | But does not allow for it to be within the string: | |
200 | ||
201 | prev_comm ~ "ba*sh" <-- is invalid | |
95b69608 | 202 | |
95b69608 TZ |
203 | 5.2 Setting filters |
204 | ------------------- | |
205 | ||
206 | A filter for an individual event is set by writing a filter expression | |
207 | to the 'filter' file for the given event. | |
208 | ||
209 | For example: | |
210 | ||
bfc672dc | 211 | # cd /sys/kernel/debug/tracing/events/sched/sched_wakeup |
95b69608 TZ |
212 | # echo "common_preempt_count > 4" > filter |
213 | ||
214 | A slightly more involved example: | |
215 | ||
bfc672dc | 216 | # cd /sys/kernel/debug/tracing/events/signal/signal_generate |
95b69608 TZ |
217 | # echo "((sig >= 10 && sig < 15) || sig == 17) && comm != bash" > filter |
218 | ||
219 | If there is an error in the expression, you'll get an 'Invalid | |
220 | argument' error when setting it, and the erroneous string along with | |
221 | an error message can be seen by looking at the filter e.g.: | |
222 | ||
bfc672dc | 223 | # cd /sys/kernel/debug/tracing/events/signal/signal_generate |
95b69608 TZ |
224 | # echo "((sig >= 10 && sig < 15) || dsig == 17) && comm != bash" > filter |
225 | -bash: echo: write error: Invalid argument | |
226 | # cat filter | |
227 | ((sig >= 10 && sig < 15) || dsig == 17) && comm != bash | |
228 | ^ | |
229 | parse_error: Field not found | |
230 | ||
231 | Currently the caret ('^') for an error always appears at the beginning of | |
232 | the filter string; the error message should still be useful though | |
233 | even without more accurate position info. | |
234 | ||
235 | 5.3 Clearing filters | |
236 | -------------------- | |
237 | ||
238 | To clear the filter for an event, write a '0' to the event's filter | |
239 | file. | |
240 | ||
241 | To clear the filters for all events in a subsystem, write a '0' to the | |
242 | subsystem's filter file. | |
243 | ||
244 | 5.3 Subsystem filters | |
245 | --------------------- | |
246 | ||
247 | For convenience, filters for every event in a subsystem can be set or | |
248 | cleared as a group by writing a filter expression into the filter file | |
88393161 | 249 | at the root of the subsystem. Note however, that if a filter for any |
95b69608 TZ |
250 | event within the subsystem lacks a field specified in the subsystem |
251 | filter, or if the filter can't be applied for any other reason, the | |
252 | filter for that event will retain its previous setting. This can | |
253 | result in an unintended mixture of filters which could lead to | |
254 | confusing (to the user who might think different filters are in | |
255 | effect) trace output. Only filters that reference just the common | |
256 | fields can be guaranteed to propagate successfully to all events. | |
257 | ||
258 | Here are a few subsystem filter examples that also illustrate the | |
259 | above points: | |
260 | ||
88393161 | 261 | Clear the filters on all events in the sched subsystem: |
95b69608 TZ |
262 | |
263 | # cd /sys/kernel/debug/tracing/events/sched | |
264 | # echo 0 > filter | |
265 | # cat sched_switch/filter | |
266 | none | |
267 | # cat sched_wakeup/filter | |
268 | none | |
269 | ||
270 | Set a filter using only common fields for all events in the sched | |
88393161 | 271 | subsystem (all events end up with the same filter): |
95b69608 TZ |
272 | |
273 | # cd /sys/kernel/debug/tracing/events/sched | |
274 | # echo common_pid == 0 > filter | |
275 | # cat sched_switch/filter | |
276 | common_pid == 0 | |
277 | # cat sched_wakeup/filter | |
278 | common_pid == 0 | |
279 | ||
280 | Attempt to set a filter using a non-common field for all events in the | |
88393161 | 281 | sched subsystem (all events but those that have a prev_pid field retain |
95b69608 TZ |
282 | their old filters): |
283 | ||
284 | # cd /sys/kernel/debug/tracing/events/sched | |
285 | # echo prev_pid == 0 > filter | |
286 | # cat sched_switch/filter | |
287 | prev_pid == 0 | |
288 | # cat sched_wakeup/filter | |
289 | common_pid == 0 | |
ac38fb85 | 290 | |
627645fd SRRH |
291 | 5.4 PID filtering |
292 | ----------------- | |
293 | ||
294 | The set_event_pid file in the same directory as the top events directory | |
295 | exists, will filter all events from tracing any task that does not have the | |
296 | PID listed in the set_event_pid file. | |
297 | ||
298 | # cd /sys/kernel/debug/tracing | |
299 | # echo $$ > set_event_pid | |
300 | # echo 1 > events/enabled | |
301 | ||
302 | Will only trace events for the current task. | |
303 | ||
304 | To add more PIDs without losing the PIDs already included, use '>>'. | |
305 | ||
306 | # echo 123 244 1 >> set_event_pid | |
307 | ||
308 | ||
ac38fb85 TZ |
309 | 6. Event triggers |
310 | ================= | |
311 | ||
312 | Trace events can be made to conditionally invoke trigger 'commands' | |
313 | which can take various forms and are described in detail below; | |
314 | examples would be enabling or disabling other trace events or invoking | |
315 | a stack trace whenever the trace event is hit. Whenever a trace event | |
316 | with attached triggers is invoked, the set of trigger commands | |
317 | associated with that event is invoked. Any given trigger can | |
318 | additionally have an event filter of the same form as described in | |
319 | section 5 (Event filtering) associated with it - the command will only | |
320 | be invoked if the event being invoked passes the associated filter. | |
321 | If no filter is associated with the trigger, it always passes. | |
322 | ||
323 | Triggers are added to and removed from a particular event by writing | |
324 | trigger expressions to the 'trigger' file for the given event. | |
325 | ||
326 | A given event can have any number of triggers associated with it, | |
327 | subject to any restrictions that individual commands may have in that | |
328 | regard. | |
329 | ||
330 | Event triggers are implemented on top of "soft" mode, which means that | |
331 | whenever a trace event has one or more triggers associated with it, | |
332 | the event is activated even if it isn't actually enabled, but is | |
333 | disabled in a "soft" mode. That is, the tracepoint will be called, | |
334 | but just will not be traced, unless of course it's actually enabled. | |
335 | This scheme allows triggers to be invoked even for events that aren't | |
336 | enabled, and also allows the current event filter implementation to be | |
337 | used for conditionally invoking triggers. | |
338 | ||
339 | The syntax for event triggers is roughly based on the syntax for | |
340 | set_ftrace_filter 'ftrace filter commands' (see the 'Filter commands' | |
341 | section of Documentation/trace/ftrace.txt), but there are major | |
342 | differences and the implementation isn't currently tied to it in any | |
343 | way, so beware about making generalizations between the two. | |
344 | ||
345 | 6.1 Expression syntax | |
346 | --------------------- | |
347 | ||
348 | Triggers are added by echoing the command to the 'trigger' file: | |
349 | ||
350 | # echo 'command[:count] [if filter]' > trigger | |
351 | ||
352 | Triggers are removed by echoing the same command but starting with '!' | |
353 | to the 'trigger' file: | |
354 | ||
355 | # echo '!command[:count] [if filter]' > trigger | |
356 | ||
357 | The [if filter] part isn't used in matching commands when removing, so | |
358 | leaving that off in a '!' command will accomplish the same thing as | |
359 | having it in. | |
360 | ||
361 | The filter syntax is the same as that described in the 'Event | |
362 | filtering' section above. | |
363 | ||
364 | For ease of use, writing to the trigger file using '>' currently just | |
365 | adds or removes a single trigger and there's no explicit '>>' support | |
366 | ('>' actually behaves like '>>') or truncation support to remove all | |
367 | triggers (you have to use '!' for each one added.) | |
368 | ||
369 | 6.2 Supported trigger commands | |
370 | ------------------------------ | |
371 | ||
372 | The 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 | |
c98be0c9 | 464 | capture those events when the trigger event occurred: |
ac38fb85 TZ |
465 | |
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. | |
0fc3813c TZ |
515 | |
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] | |
5463bfda | 527 | [:clear][:name=histname1] [if <filter>] |
0fc3813c TZ |
528 | |
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 | |
5463bfda TZ |
549 | key. If a hist trigger is given a name using the 'name' parameter, |
550 | its histogram data will be shared with other triggers of the same | |
551 | name, and trigger hits will update this common data. Only triggers | |
552 | with 'compatible' fields can be combined in this way; triggers are | |
553 | 'compatible' if the fields named in the trigger share the same | |
554 | number and type of fields and those fields also have the same names. | |
555 | Note that any two events always share the compatible 'hitcount' and | |
556 | 'stacktrace' fields and can therefore be combined using those | |
557 | fields, however pointless that may be. | |
0fc3813c TZ |
558 | |
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 | |
52a7f16d TZ |
561 | its entirety to stdout. If there are multiple hist triggers |
562 | attached to an event, there will be a table for each trigger in the | |
5463bfda TZ |
563 | output. The table displayed for a named trigger will be the same as |
564 | any other instance having the same name. Each printed hash table | |
565 | entry is a simple list of the keys and values comprising the entry; | |
566 | keys are printed first and are delineated by curly braces, and are | |
567 | followed by the set of value fields for the entry. By default, | |
568 | numeric fields are displayed as base-10 integers. This can be | |
569 | modified by appending any of the following modifiers to the field | |
570 | name: | |
0fc3813c TZ |
571 | |
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 | ||
675 | 6.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 | . | |
52a7f16d TZ |
1682 | |
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 | |
5463bfda TZ |
1822 | |
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 |