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