1============= 2Event Tracing 3============= 4 5:Author: Theodore Ts'o 6:Updated: Li Zefan and Tom Zanussi 7 81. Introduction 9=============== 10 11Tracepoints (see Documentation/trace/tracepoints.txt) can be used 12without creating custom kernel modules to register probe functions 13using the event tracing infrastructure. 14 15Not all tracepoints can be traced using the event tracing system; 16the kernel developer must provide code snippets which define how the 17tracing information is saved into the tracing buffer, and how the 18tracing information should be printed. 19 202. Using Event Tracing 21====================== 22 232.1 Via the 'set_event' interface 24--------------------------------- 25 26The events which are available for tracing can be found in the file 27/sys/kernel/debug/tracing/available_events. 28 29To enable a particular event, such as 'sched_wakeup', simply echo it 30to /sys/kernel/debug/tracing/set_event. For example:: 31 32 # echo sched_wakeup >> /sys/kernel/debug/tracing/set_event 33 34.. Note:: '>>' is necessary, otherwise it will firstly disable all the events. 35 36To disable an event, echo the event name to the set_event file prefixed 37with an exclamation point:: 38 39 # echo '!sched_wakeup' >> /sys/kernel/debug/tracing/set_event 40 41To disable all events, echo an empty line to the set_event file:: 42 43 # echo > /sys/kernel/debug/tracing/set_event 44 45To enable all events, echo ``*:*`` or ``*:`` to the set_event file:: 46 47 # echo *:* > /sys/kernel/debug/tracing/set_event 48 49The events are organized into subsystems, such as ext4, irq, sched, 50etc., and a full event name looks like this: <subsystem>:<event>. The 51subsystem name is optional, but it is displayed in the available_events 52file. All of the events in a subsystem can be specified via the syntax 53``<subsystem>:*``; for example, to enable all irq events, you can use the 54command:: 55 56 # echo 'irq:*' > /sys/kernel/debug/tracing/set_event 57 582.2 Via the 'enable' toggle 59--------------------------- 60 61The events available are also listed in /sys/kernel/debug/tracing/events/ hierarchy 62of directories. 63 64To enable event 'sched_wakeup':: 65 66 # echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable 67 68To disable it:: 69 70 # echo 0 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable 71 72To enable all events in sched subsystem:: 73 74 # echo 1 > /sys/kernel/debug/tracing/events/sched/enable 75 76To enable all events:: 77 78 # echo 1 > /sys/kernel/debug/tracing/events/enable 79 80When reading one of these enable files, there are four results: 81 82 - 0 - all events this file affects are disabled 83 - 1 - all events this file affects are enabled 84 - X - there is a mixture of events enabled and disabled 85 - ? - this file does not affect any event 86 872.3 Boot option 88--------------- 89 90In order to facilitate early boot debugging, use boot option:: 91 92 trace_event=[event-list] 93 94event-list is a comma separated list of events. See section 2.1 for event 95format. 96 973. Defining an event-enabled tracepoint 98======================================= 99 100See The example provided in samples/trace_events 101 1024. Event formats 103================ 104 105Each trace event has a 'format' file associated with it that contains 106a description of each field in a logged event. This information can 107be used to parse the binary trace stream, and is also the place to 108find the field names that can be used in event filters (see section 5). 109 110It also displays the format string that will be used to print the 111event in text mode, along with the event name and ID used for 112profiling. 113 114Every event has a set of ``common`` fields associated with it; these are 115the fields prefixed with ``common_``. The other fields vary between 116events and correspond to the fields defined in the TRACE_EVENT 117definition for that event. 118 119Each field in the format has the form:: 120 121 field:field-type field-name; offset:N; size:N; 122 123where offset is the offset of the field in the trace record and size 124is the size of the data item, in bytes. 125 126For example, here's the information displayed for the 'sched_wakeup' 127event:: 128 129 # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/format 130 131 name: sched_wakeup 132 ID: 60 133 format: 134 field:unsigned short common_type; offset:0; size:2; 135 field:unsigned char common_flags; offset:2; size:1; 136 field:unsigned char common_preempt_count; offset:3; size:1; 137 field:int common_pid; offset:4; size:4; 138 field:int common_tgid; offset:8; size:4; 139 140 field:char comm[TASK_COMM_LEN]; offset:12; size:16; 141 field:pid_t pid; offset:28; size:4; 142 field:int prio; offset:32; size:4; 143 field:int success; offset:36; size:4; 144 field:int cpu; offset:40; size:4; 145 146 print fmt: "task %s:%d [%d] success=%d [%03d]", REC->comm, REC->pid, 147 REC->prio, REC->success, REC->cpu 148 149This event contains 10 fields, the first 5 common and the remaining 5 150event-specific. All the fields for this event are numeric, except for 151'comm' which is a string, a distinction important for event filtering. 152 1535. Event filtering 154================== 155 156Trace events can be filtered in the kernel by associating boolean 157'filter expressions' with them. As soon as an event is logged into 158the trace buffer, its fields are checked against the filter expression 159associated with that event type. An event with field values that 160'match' the filter will appear in the trace output, and an event whose 161values don't match will be discarded. An event with no filter 162associated with it matches everything, and is the default when no 163filter has been set for an event. 164 1655.1 Expression syntax 166--------------------- 167 168A filter expression consists of one or more 'predicates' that can be 169combined using the logical operators '&&' and '||'. A predicate is 170simply a clause that compares the value of a field contained within a 171logged event with a constant value and returns either 0 or 1 depending 172on whether the field value matched (1) or didn't match (0):: 173 174 field-name relational-operator value 175 176Parentheses can be used to provide arbitrary logical groupings and 177double-quotes can be used to prevent the shell from interpreting 178operators as shell metacharacters. 179 180The field-names available for use in filters can be found in the 181'format' files for trace events (see section 4). 182 183The relational-operators depend on the type of the field being tested: 184 185The operators available for numeric fields are: 186 187==, !=, <, <=, >, >=, & 188 189And for string fields they are: 190 191==, !=, ~ 192 193The glob (~) accepts a wild card character (\*,?) and character classes 194([). For example:: 195 196 prev_comm ~ "*sh" 197 prev_comm ~ "sh*" 198 prev_comm ~ "*sh*" 199 prev_comm ~ "ba*sh" 200 2015.2 Setting filters 202------------------- 203 204A filter for an individual event is set by writing a filter expression 205to the 'filter' file for the given event. 206 207For example:: 208 209 # cd /sys/kernel/debug/tracing/events/sched/sched_wakeup 210 # echo "common_preempt_count > 4" > filter 211 212A slightly more involved example:: 213 214 # cd /sys/kernel/debug/tracing/events/signal/signal_generate 215 # echo "((sig >= 10 && sig < 15) || sig == 17) && comm != bash" > filter 216 217If there is an error in the expression, you'll get an 'Invalid 218argument' error when setting it, and the erroneous string along with 219an error message can be seen by looking at the filter e.g.:: 220 221 # cd /sys/kernel/debug/tracing/events/signal/signal_generate 222 # echo "((sig >= 10 && sig < 15) || dsig == 17) && comm != bash" > filter 223 -bash: echo: write error: Invalid argument 224 # cat filter 225 ((sig >= 10 && sig < 15) || dsig == 17) && comm != bash 226 ^ 227 parse_error: Field not found 228 229Currently the caret ('^') for an error always appears at the beginning of 230the filter string; the error message should still be useful though 231even without more accurate position info. 232 2335.3 Clearing filters 234-------------------- 235 236To clear the filter for an event, write a '0' to the event's filter 237file. 238 239To clear the filters for all events in a subsystem, write a '0' to the 240subsystem's filter file. 241 2425.3 Subsystem filters 243--------------------- 244 245For convenience, filters for every event in a subsystem can be set or 246cleared as a group by writing a filter expression into the filter file 247at the root of the subsystem. Note however, that if a filter for any 248event within the subsystem lacks a field specified in the subsystem 249filter, or if the filter can't be applied for any other reason, the 250filter for that event will retain its previous setting. This can 251result in an unintended mixture of filters which could lead to 252confusing (to the user who might think different filters are in 253effect) trace output. Only filters that reference just the common 254fields can be guaranteed to propagate successfully to all events. 255 256Here are a few subsystem filter examples that also illustrate the 257above points: 258 259Clear the filters on all events in the sched subsystem:: 260 261 # cd /sys/kernel/debug/tracing/events/sched 262 # echo 0 > filter 263 # cat sched_switch/filter 264 none 265 # cat sched_wakeup/filter 266 none 267 268Set a filter using only common fields for all events in the sched 269subsystem (all events end up with the same filter):: 270 271 # cd /sys/kernel/debug/tracing/events/sched 272 # echo common_pid == 0 > filter 273 # cat sched_switch/filter 274 common_pid == 0 275 # cat sched_wakeup/filter 276 common_pid == 0 277 278Attempt to set a filter using a non-common field for all events in the 279sched subsystem (all events but those that have a prev_pid field retain 280their old filters):: 281 282 # cd /sys/kernel/debug/tracing/events/sched 283 # echo prev_pid == 0 > filter 284 # cat sched_switch/filter 285 prev_pid == 0 286 # cat sched_wakeup/filter 287 common_pid == 0 288 2895.4 PID filtering 290----------------- 291 292The set_event_pid file in the same directory as the top events directory 293exists, will filter all events from tracing any task that does not have the 294PID listed in the set_event_pid file. 295:: 296 297 # cd /sys/kernel/debug/tracing 298 # echo $$ > set_event_pid 299 # echo 1 > events/enable 300 301Will only trace events for the current task. 302 303To add more PIDs without losing the PIDs already included, use '>>'. 304:: 305 306 # echo 123 244 1 >> set_event_pid 307 308 3096. Event triggers 310================= 311 312Trace events can be made to conditionally invoke trigger 'commands' 313which can take various forms and are described in detail below; 314examples would be enabling or disabling other trace events or invoking 315a stack trace whenever the trace event is hit. Whenever a trace event 316with attached triggers is invoked, the set of trigger commands 317associated with that event is invoked. Any given trigger can 318additionally have an event filter of the same form as described in 319section 5 (Event filtering) associated with it - the command will only 320be invoked if the event being invoked passes the associated filter. 321If no filter is associated with the trigger, it always passes. 322 323Triggers are added to and removed from a particular event by writing 324trigger expressions to the 'trigger' file for the given event. 325 326A given event can have any number of triggers associated with it, 327subject to any restrictions that individual commands may have in that 328regard. 329 330Event triggers are implemented on top of "soft" mode, which means that 331whenever a trace event has one or more triggers associated with it, 332the event is activated even if it isn't actually enabled, but is 333disabled in a "soft" mode. That is, the tracepoint will be called, 334but just will not be traced, unless of course it's actually enabled. 335This scheme allows triggers to be invoked even for events that aren't 336enabled, and also allows the current event filter implementation to be 337used for conditionally invoking triggers. 338 339The syntax for event triggers is roughly based on the syntax for 340set_ftrace_filter 'ftrace filter commands' (see the 'Filter commands' 341section of Documentation/trace/ftrace.txt), but there are major 342differences and the implementation isn't currently tied to it in any 343way, so beware about making generalizations between the two. 344 3456.1 Expression syntax 346--------------------- 347 348Triggers are added by echoing the command to the 'trigger' file:: 349 350 # echo 'command[:count] [if filter]' > trigger 351 352Triggers are removed by echoing the same command but starting with '!' 353to the 'trigger' file:: 354 355 # echo '!command[:count] [if filter]' > trigger 356 357The [if filter] part isn't used in matching commands when removing, so 358leaving that off in a '!' command will accomplish the same thing as 359having it in. 360 361The filter syntax is the same as that described in the 'Event 362filtering' section above. 363 364For ease of use, writing to the trigger file using '>' currently just 365adds or removes a single trigger and there's no explicit '>>' support 366('>' actually behaves like '>>') or truncation support to remove all 367triggers (you have to use '!' for each one added.) 368 3696.2 Supported trigger commands 370------------------------------ 371 372The following commands are supported: 373 374- enable_event/disable_event 375 376 These commands can enable or disable another trace event whenever 377 the triggering event is hit. When these commands are registered, 378 the other trace event is activated, but disabled in a "soft" mode. 379 That is, the tracepoint will be called, but just will not be traced. 380 The event tracepoint stays in this mode as long as there's a trigger 381 in effect that can trigger it. 382 383 For example, the following trigger causes kmalloc events to be 384 traced when a read system call is entered, and the :1 at the end 385 specifies that this enablement happens only once:: 386 387 # echo 'enable_event:kmem:kmalloc:1' > \ 388 /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger 389 390 The following trigger causes kmalloc events to stop being traced 391 when a read system call exits. This disablement happens on every 392 read system call exit:: 393 394 # echo 'disable_event:kmem:kmalloc' > \ 395 /sys/kernel/debug/tracing/events/syscalls/sys_exit_read/trigger 396 397 The format is:: 398 399 enable_event:<system>:<event>[:count] 400 disable_event:<system>:<event>[:count] 401 402 To remove the above commands:: 403 404 # echo '!enable_event:kmem:kmalloc:1' > \ 405 /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger 406 407 # echo '!disable_event:kmem:kmalloc' > \ 408 /sys/kernel/debug/tracing/events/syscalls/sys_exit_read/trigger 409 410 Note that there can be any number of enable/disable_event triggers 411 per triggering event, but there can only be one trigger per 412 triggered event. e.g. sys_enter_read can have triggers enabling both 413 kmem:kmalloc and sched:sched_switch, but can't have two kmem:kmalloc 414 versions such as kmem:kmalloc and kmem:kmalloc:1 or 'kmem:kmalloc if 415 bytes_req == 256' and 'kmem:kmalloc if bytes_alloc == 256' (they 416 could be combined into a single filter on kmem:kmalloc though). 417 418- stacktrace 419 420 This command dumps a stacktrace in the trace buffer whenever the 421 triggering event occurs. 422 423 For example, the following trigger dumps a stacktrace every time the 424 kmalloc tracepoint is hit:: 425 426 # echo 'stacktrace' > \ 427 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 428 429 The following trigger dumps a stacktrace the first 5 times a kmalloc 430 request happens with a size >= 64K:: 431 432 # echo 'stacktrace:5 if bytes_req >= 65536' > \ 433 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 434 435 The format is:: 436 437 stacktrace[:count] 438 439 To remove the above commands:: 440 441 # echo '!stacktrace' > \ 442 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 443 444 # echo '!stacktrace:5 if bytes_req >= 65536' > \ 445 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 446 447 The latter can also be removed more simply by the following (without 448 the filter):: 449 450 # echo '!stacktrace:5' > \ 451 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 452 453 Note that there can be only one stacktrace trigger per triggering 454 event. 455 456- snapshot 457 458 This command causes a snapshot to be triggered whenever the 459 triggering event occurs. 460 461 The following command creates a snapshot every time a block request 462 queue is unplugged with a depth > 1. If you were tracing a set of 463 events or functions at the time, the snapshot trace buffer would 464 capture those events when the trigger event occurred:: 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. 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] 527 [:clear][:name=histname1] [if <filter>] 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 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. 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 561 its entirety to stdout. If there are multiple hist triggers 562 attached to an event, there will be a table for each trigger in the 563 output. The table displayed for a named trigger will be the same as 564 any other instance having the same name. Each printed hash table 565 entry is a simple list of the keys and values comprising the entry; 566 keys are printed first and are delineated by curly braces, and are 567 followed by the set of value fields for the entry. By default, 568 numeric fields are displayed as base-10 integers. This can be 569 modified by appending any of the following modifiers to the field 570 name: 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 6756.2 'hist' trigger examples 676--------------------------- 677 678 The first set of examples creates aggregations using the kmalloc 679 event. The fields that can be used for the hist trigger are listed 680 in the kmalloc event's format file:: 681 682 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format 683 name: kmalloc 684 ID: 374 685 format: 686 field:unsigned short common_type; offset:0; size:2; signed:0; 687 field:unsigned char common_flags; offset:2; size:1; signed:0; 688 field:unsigned char common_preempt_count; offset:3; size:1; signed:0; 689 field:int common_pid; offset:4; size:4; signed:1; 690 691 field:unsigned long call_site; offset:8; size:8; signed:0; 692 field:const void * ptr; offset:16; size:8; signed:0; 693 field:size_t bytes_req; offset:24; size:8; signed:0; 694 field:size_t bytes_alloc; offset:32; size:8; signed:0; 695 field:gfp_t gfp_flags; offset:40; size:4; signed:0; 696 697 We'll start by creating a hist trigger that generates a simple table 698 that lists the total number of bytes requested for each function in 699 the kernel that made one or more calls to kmalloc:: 700 701 # echo 'hist:key=call_site:val=bytes_req' > \ 702 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 703 704 This tells the tracing system to create a 'hist' trigger using the 705 call_site field of the kmalloc event as the key for the table, which 706 just means that each unique call_site address will have an entry 707 created for it in the table. The 'val=bytes_req' parameter tells 708 the hist trigger that for each unique entry (call_site) in the 709 table, it should keep a running total of the number of bytes 710 requested by that call_site. 711 712 We'll let it run for awhile and then dump the contents of the 'hist' 713 file in the kmalloc event's subdirectory (for readability, a number 714 of entries have been omitted):: 715 716 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 717 # trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active] 718 719 { call_site: 18446744072106379007 } hitcount: 1 bytes_req: 176 720 { call_site: 18446744071579557049 } hitcount: 1 bytes_req: 1024 721 { call_site: 18446744071580608289 } hitcount: 1 bytes_req: 16384 722 { call_site: 18446744071581827654 } hitcount: 1 bytes_req: 24 723 { call_site: 18446744071580700980 } hitcount: 1 bytes_req: 8 724 { call_site: 18446744071579359876 } hitcount: 1 bytes_req: 152 725 { call_site: 18446744071580795365 } hitcount: 3 bytes_req: 144 726 { call_site: 18446744071581303129 } hitcount: 3 bytes_req: 144 727 { call_site: 18446744071580713234 } hitcount: 4 bytes_req: 2560 728 { call_site: 18446744071580933750 } hitcount: 4 bytes_req: 736 729 . 730 . 731 . 732 { call_site: 18446744072106047046 } hitcount: 69 bytes_req: 5576 733 { call_site: 18446744071582116407 } hitcount: 73 bytes_req: 2336 734 { call_site: 18446744072106054684 } hitcount: 136 bytes_req: 140504 735 { call_site: 18446744072106224230 } hitcount: 136 bytes_req: 19584 736 { call_site: 18446744072106078074 } hitcount: 153 bytes_req: 2448 737 { call_site: 18446744072106062406 } hitcount: 153 bytes_req: 36720 738 { call_site: 18446744071582507929 } hitcount: 153 bytes_req: 37088 739 { call_site: 18446744072102520590 } hitcount: 273 bytes_req: 10920 740 { call_site: 18446744071582143559 } hitcount: 358 bytes_req: 716 741 { call_site: 18446744072106465852 } hitcount: 417 bytes_req: 56712 742 { call_site: 18446744072102523378 } hitcount: 485 bytes_req: 27160 743 { call_site: 18446744072099568646 } hitcount: 1676 bytes_req: 33520 744 745 Totals: 746 Hits: 4610 747 Entries: 45 748 Dropped: 0 749 750 The output displays a line for each entry, beginning with the key 751 specified in the trigger, followed by the value(s) also specified in 752 the trigger. At the beginning of the output is a line that displays 753 the trigger info, which can also be displayed by reading the 754 'trigger' file:: 755 756 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 757 hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active] 758 759 At the end of the output are a few lines that display the overall 760 totals for the run. The 'Hits' field shows the total number of 761 times the event trigger was hit, the 'Entries' field shows the total 762 number of used entries in the hash table, and the 'Dropped' field 763 shows the number of hits that were dropped because the number of 764 used entries for the run exceeded the maximum number of entries 765 allowed for the table (normally 0, but if not a hint that you may 766 want to increase the size of the table using the 'size' parameter). 767 768 Notice in the above output that there's an extra field, 'hitcount', 769 which wasn't specified in the trigger. Also notice that in the 770 trigger info output, there's a parameter, 'sort=hitcount', which 771 wasn't specified in the trigger either. The reason for that is that 772 every trigger implicitly keeps a count of the total number of hits 773 attributed to a given entry, called the 'hitcount'. That hitcount 774 information is explicitly displayed in the output, and in the 775 absence of a user-specified sort parameter, is used as the default 776 sort field. 777 778 The value 'hitcount' can be used in place of an explicit value in 779 the 'values' parameter if you don't really need to have any 780 particular field summed and are mainly interested in hit 781 frequencies. 782 783 To turn the hist trigger off, simply call up the trigger in the 784 command history and re-execute it with a '!' prepended:: 785 786 # echo '!hist:key=call_site:val=bytes_req' > \ 787 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 788 789 Finally, notice that the call_site as displayed in the output above 790 isn't really very useful. It's an address, but normally addresses 791 are displayed in hex. To have a numeric field displayed as a hex 792 value, simply append '.hex' to the field name in the trigger:: 793 794 # echo 'hist:key=call_site.hex:val=bytes_req' > \ 795 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 796 797 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 798 # trigger info: hist:keys=call_site.hex:vals=bytes_req:sort=hitcount:size=2048 [active] 799 800 { call_site: ffffffffa026b291 } hitcount: 1 bytes_req: 433 801 { call_site: ffffffffa07186ff } hitcount: 1 bytes_req: 176 802 { call_site: ffffffff811ae721 } hitcount: 1 bytes_req: 16384 803 { call_site: ffffffff811c5134 } hitcount: 1 bytes_req: 8 804 { call_site: ffffffffa04a9ebb } hitcount: 1 bytes_req: 511 805 { call_site: ffffffff8122e0a6 } hitcount: 1 bytes_req: 12 806 { call_site: ffffffff8107da84 } hitcount: 1 bytes_req: 152 807 { call_site: ffffffff812d8246 } hitcount: 1 bytes_req: 24 808 { call_site: ffffffff811dc1e5 } hitcount: 3 bytes_req: 144 809 { call_site: ffffffffa02515e8 } hitcount: 3 bytes_req: 648 810 { call_site: ffffffff81258159 } hitcount: 3 bytes_req: 144 811 { call_site: ffffffff811c80f4 } hitcount: 4 bytes_req: 544 812 . 813 . 814 . 815 { call_site: ffffffffa06c7646 } hitcount: 106 bytes_req: 8024 816 { call_site: ffffffffa06cb246 } hitcount: 132 bytes_req: 31680 817 { call_site: ffffffffa06cef7a } hitcount: 132 bytes_req: 2112 818 { call_site: ffffffff8137e399 } hitcount: 132 bytes_req: 23232 819 { call_site: ffffffffa06c941c } hitcount: 185 bytes_req: 171360 820 { call_site: ffffffffa06f2a66 } hitcount: 185 bytes_req: 26640 821 { call_site: ffffffffa036a70e } hitcount: 265 bytes_req: 10600 822 { call_site: ffffffff81325447 } hitcount: 292 bytes_req: 584 823 { call_site: ffffffffa072da3c } hitcount: 446 bytes_req: 60656 824 { call_site: ffffffffa036b1f2 } hitcount: 526 bytes_req: 29456 825 { call_site: ffffffffa0099c06 } hitcount: 1780 bytes_req: 35600 826 827 Totals: 828 Hits: 4775 829 Entries: 46 830 Dropped: 0 831 832 Even that's only marginally more useful - while hex values do look 833 more like addresses, what users are typically more interested in 834 when looking at text addresses are the corresponding symbols 835 instead. To have an address displayed as symbolic value instead, 836 simply append '.sym' or '.sym-offset' to the field name in the 837 trigger:: 838 839 # echo 'hist:key=call_site.sym:val=bytes_req' > \ 840 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 841 842 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 843 # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=hitcount:size=2048 [active] 844 845 { call_site: [ffffffff810adcb9] syslog_print_all } hitcount: 1 bytes_req: 1024 846 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 847 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 848 { call_site: [ffffffff8154acbe] usb_alloc_urb } hitcount: 1 bytes_req: 192 849 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 850 { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40 851 { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 852 { call_site: [ffffffff811febd5] fsnotify_alloc_group } hitcount: 2 bytes_req: 528 853 { call_site: [ffffffff81440f58] __tty_buffer_request_room } hitcount: 2 bytes_req: 2624 854 { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 2 bytes_req: 96 855 { call_site: [ffffffffa05e19af] ieee80211_start_tx_ba_session [mac80211] } hitcount: 2 bytes_req: 464 856 { call_site: [ffffffff81672406] tcp_get_metrics } hitcount: 2 bytes_req: 304 857 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 858 { call_site: [ffffffff81089b05] sched_create_group } hitcount: 2 bytes_req: 1424 859 . 860 . 861 . 862 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1185 bytes_req: 123240 863 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 1185 bytes_req: 104280 864 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 1402 bytes_req: 190672 865 { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 1518 bytes_req: 146208 866 { call_site: [ffffffffa029070e] drm_vma_node_allow [drm] } hitcount: 1746 bytes_req: 69840 867 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 2021 bytes_req: 792312 868 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 2592 bytes_req: 145152 869 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2629 bytes_req: 378576 870 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2629 bytes_req: 3783248 871 { call_site: [ffffffff81325607] apparmor_file_alloc_security } hitcount: 5192 bytes_req: 10384 872 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 5529 bytes_req: 110584 873 { call_site: [ffffffff8131ebf7] aa_alloc_task_context } hitcount: 21943 bytes_req: 702176 874 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 55759 bytes_req: 5074265 875 876 Totals: 877 Hits: 109928 878 Entries: 71 879 Dropped: 0 880 881 Because the default sort key above is 'hitcount', the above shows a 882 the list of call_sites by increasing hitcount, so that at the bottom 883 we see the functions that made the most kmalloc calls during the 884 run. If instead we we wanted to see the top kmalloc callers in 885 terms of the number of bytes requested rather than the number of 886 calls, and we wanted the top caller to appear at the top, we can use 887 the 'sort' parameter, along with the 'descending' modifier:: 888 889 # echo 'hist:key=call_site.sym:val=bytes_req:sort=bytes_req.descending' > \ 890 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 891 892 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 893 # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] 894 895 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2186 bytes_req: 3397464 896 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1790 bytes_req: 712176 897 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 8132 bytes_req: 513135 898 { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 106 bytes_req: 440128 899 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2186 bytes_req: 314784 900 { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 2174 bytes_req: 208992 901 { call_site: [ffffffff811ae8e1] __kmalloc } hitcount: 8 bytes_req: 131072 902 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 859 bytes_req: 116824 903 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 1834 bytes_req: 102704 904 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 972 bytes_req: 101088 905 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 972 bytes_req: 85536 906 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 3333 bytes_req: 66664 907 { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 209 bytes_req: 61632 908 . 909 . 910 . 911 { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 912 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 913 { call_site: [ffffffff812d8406] copy_semundo } hitcount: 2 bytes_req: 48 914 { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 1 bytes_req: 48 915 { call_site: [ffffffffa027121a] drm_getmagic [drm] } hitcount: 1 bytes_req: 48 916 { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40 917 { call_site: [ffffffff811c52f4] bprm_change_interp } hitcount: 2 bytes_req: 16 918 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 919 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 920 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 921 922 Totals: 923 Hits: 32133 924 Entries: 81 925 Dropped: 0 926 927 To display the offset and size information in addition to the symbol 928 name, just use 'sym-offset' instead:: 929 930 # echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \ 931 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 932 933 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 934 # trigger info: hist:keys=call_site.sym-offset:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] 935 936 { call_site: [ffffffffa046041c] i915_gem_execbuffer2+0x6c/0x2c0 [i915] } hitcount: 4569 bytes_req: 3163720 937 { call_site: [ffffffffa0489a66] intel_ring_begin+0xc6/0x1f0 [i915] } hitcount: 4569 bytes_req: 657936 938 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23+0x694/0x1020 [i915] } hitcount: 1519 bytes_req: 472936 939 { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23+0x516/0x1020 [i915] } hitcount: 3050 bytes_req: 211832 940 { call_site: [ffffffff811e2a1b] seq_buf_alloc+0x1b/0x50 } hitcount: 34 bytes_req: 148384 941 { call_site: [ffffffffa04a580c] intel_crtc_page_flip+0xbc/0x870 [i915] } hitcount: 1385 bytes_req: 144040 942 { call_site: [ffffffff811ae8e1] __kmalloc+0x191/0x1b0 } hitcount: 8 bytes_req: 131072 943 { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl+0x282/0x360 [drm] } hitcount: 1385 bytes_req: 121880 944 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc+0x32/0x100 [drm] } hitcount: 1848 bytes_req: 103488 945 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state+0x2c/0xa0 [i915] } hitcount: 461 bytes_req: 62696 946 { call_site: [ffffffffa029070e] drm_vma_node_allow+0x2e/0xd0 [drm] } hitcount: 1541 bytes_req: 61640 947 { call_site: [ffffffff815f8d7b] sk_prot_alloc+0xcb/0x1b0 } hitcount: 57 bytes_req: 57456 948 . 949 . 950 . 951 { call_site: [ffffffff8109524a] alloc_fair_sched_group+0x5a/0x1a0 } hitcount: 2 bytes_req: 128 952 { call_site: [ffffffffa027b921] drm_vm_open_locked+0x31/0xa0 [drm] } hitcount: 3 bytes_req: 96 953 { call_site: [ffffffff8122e266] proc_self_follow_link+0x76/0xb0 } hitcount: 8 bytes_req: 96 954 { call_site: [ffffffff81213e80] load_elf_binary+0x240/0x1650 } hitcount: 3 bytes_req: 84 955 { call_site: [ffffffff8154bc62] usb_control_msg+0x42/0x110 } hitcount: 1 bytes_req: 8 956 { call_site: [ffffffffa00bf6fe] hidraw_send_report+0x7e/0x1a0 [hid] } hitcount: 1 bytes_req: 7 957 { call_site: [ffffffffa00bf1ca] hidraw_report_event+0x8a/0x120 [hid] } hitcount: 1 bytes_req: 7 958 959 Totals: 960 Hits: 26098 961 Entries: 64 962 Dropped: 0 963 964 We can also add multiple fields to the 'values' parameter. For 965 example, we might want to see the total number of bytes allocated 966 alongside bytes requested, and display the result sorted by bytes 967 allocated in a descending order:: 968 969 # echo 'hist:keys=call_site.sym:values=bytes_req,bytes_alloc:sort=bytes_alloc.descending' > \ 970 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 971 972 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 973 # trigger info: hist:keys=call_site.sym:vals=bytes_req,bytes_alloc:sort=bytes_alloc.descending:size=2048 [active] 974 975 { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 7403 bytes_req: 4084360 bytes_alloc: 5958016 976 { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 541 bytes_req: 2213968 bytes_alloc: 2228224 977 { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 7404 bytes_req: 1066176 bytes_alloc: 1421568 978 { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1565 bytes_req: 557368 bytes_alloc: 1037760 979 { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 9557 bytes_req: 595778 bytes_alloc: 695744 980 { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 5839 bytes_req: 430680 bytes_alloc: 470400 981 { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 2388 bytes_req: 324768 bytes_alloc: 458496 982 { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 3911 bytes_req: 219016 bytes_alloc: 250304 983 { call_site: [ffffffff815f8d7b] sk_prot_alloc } hitcount: 235 bytes_req: 236880 bytes_alloc: 240640 984 { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 557 bytes_req: 169024 bytes_alloc: 221760 985 { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 9378 bytes_req: 187548 bytes_alloc: 206312 986 { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1519 bytes_req: 157976 bytes_alloc: 194432 987 . 988 . 989 . 990 { call_site: [ffffffff8109bd3b] sched_autogroup_create_attach } hitcount: 2 bytes_req: 144 bytes_alloc: 192 991 { call_site: [ffffffff81097ee8] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 992 { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 993 { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 994 { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 995 { call_site: [ffffffff81213e80] load_elf_binary } hitcount: 3 bytes_req: 84 bytes_alloc: 96 996 { call_site: [ffffffff81079a2e] kthread_create_on_node } hitcount: 1 bytes_req: 56 bytes_alloc: 64 997 { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8 998 { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 bytes_alloc: 8 999 { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8 1000 1001 Totals: 1002 Hits: 66598 1003 Entries: 65 1004 Dropped: 0 1005 1006 Finally, to finish off our kmalloc example, instead of simply having 1007 the hist trigger display symbolic call_sites, we can have the hist 1008 trigger additionally display the complete set of kernel stack traces 1009 that led to each call_site. To do that, we simply use the special 1010 value 'stacktrace' for the key parameter:: 1011 1012 # echo 'hist:keys=stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' > \ 1013 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger 1014 1015 The above trigger will use the kernel stack trace in effect when an 1016 event is triggered as the key for the hash table. This allows the 1017 enumeration of every kernel callpath that led up to a particular 1018 event, along with a running total of any of the event fields for 1019 that event. Here we tally bytes requested and bytes allocated for 1020 every callpath in the system that led up to a kmalloc (in this case 1021 every callpath to a kmalloc for a kernel compile):: 1022 1023 # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist 1024 # trigger info: hist:keys=stacktrace:vals=bytes_req,bytes_alloc:sort=bytes_alloc:size=2048 [active] 1025 1026 { stacktrace: 1027 __kmalloc_track_caller+0x10b/0x1a0 1028 kmemdup+0x20/0x50 1029 hidraw_report_event+0x8a/0x120 [hid] 1030 hid_report_raw_event+0x3ea/0x440 [hid] 1031 hid_input_report+0x112/0x190 [hid] 1032 hid_irq_in+0xc2/0x260 [usbhid] 1033 __usb_hcd_giveback_urb+0x72/0x120 1034 usb_giveback_urb_bh+0x9e/0xe0 1035 tasklet_hi_action+0xf8/0x100 1036 __do_softirq+0x114/0x2c0 1037 irq_exit+0xa5/0xb0 1038 do_IRQ+0x5a/0xf0 1039 ret_from_intr+0x0/0x30 1040 cpuidle_enter+0x17/0x20 1041 cpu_startup_entry+0x315/0x3e0 1042 rest_init+0x7c/0x80 1043 } hitcount: 3 bytes_req: 21 bytes_alloc: 24 1044 { stacktrace: 1045 __kmalloc_track_caller+0x10b/0x1a0 1046 kmemdup+0x20/0x50 1047 hidraw_report_event+0x8a/0x120 [hid] 1048 hid_report_raw_event+0x3ea/0x440 [hid] 1049 hid_input_report+0x112/0x190 [hid] 1050 hid_irq_in+0xc2/0x260 [usbhid] 1051 __usb_hcd_giveback_urb+0x72/0x120 1052 usb_giveback_urb_bh+0x9e/0xe0 1053 tasklet_hi_action+0xf8/0x100 1054 __do_softirq+0x114/0x2c0 1055 irq_exit+0xa5/0xb0 1056 do_IRQ+0x5a/0xf0 1057 ret_from_intr+0x0/0x30 1058 } hitcount: 3 bytes_req: 21 bytes_alloc: 24 1059 { stacktrace: 1060 kmem_cache_alloc_trace+0xeb/0x150 1061 aa_alloc_task_context+0x27/0x40 1062 apparmor_cred_prepare+0x1f/0x50 1063 security_prepare_creds+0x16/0x20 1064 prepare_creds+0xdf/0x1a0 1065 SyS_capset+0xb5/0x200 1066 system_call_fastpath+0x12/0x6a 1067 } hitcount: 1 bytes_req: 32 bytes_alloc: 32 1068 . 1069 . 1070 . 1071 { stacktrace: 1072 __kmalloc+0x11b/0x1b0 1073 i915_gem_execbuffer2+0x6c/0x2c0 [i915] 1074 drm_ioctl+0x349/0x670 [drm] 1075 do_vfs_ioctl+0x2f0/0x4f0 1076 SyS_ioctl+0x81/0xa0 1077 system_call_fastpath+0x12/0x6a 1078 } hitcount: 17726 bytes_req: 13944120 bytes_alloc: 19593808 1079 { stacktrace: 1080 __kmalloc+0x11b/0x1b0 1081 load_elf_phdrs+0x76/0xa0 1082 load_elf_binary+0x102/0x1650 1083 search_binary_handler+0x97/0x1d0 1084 do_execveat_common.isra.34+0x551/0x6e0 1085 SyS_execve+0x3a/0x50 1086 return_from_execve+0x0/0x23 1087 } hitcount: 33348 bytes_req: 17152128 bytes_alloc: 20226048 1088 { stacktrace: 1089 kmem_cache_alloc_trace+0xeb/0x150 1090 apparmor_file_alloc_security+0x27/0x40 1091 security_file_alloc+0x16/0x20 1092 get_empty_filp+0x93/0x1c0 1093 path_openat+0x31/0x5f0 1094 do_filp_open+0x3a/0x90 1095 do_sys_open+0x128/0x220 1096 SyS_open+0x1e/0x20 1097 system_call_fastpath+0x12/0x6a 1098 } hitcount: 4766422 bytes_req: 9532844 bytes_alloc: 38131376 1099 { stacktrace: 1100 __kmalloc+0x11b/0x1b0 1101 seq_buf_alloc+0x1b/0x50 1102 seq_read+0x2cc/0x370 1103 proc_reg_read+0x3d/0x80 1104 __vfs_read+0x28/0xe0 1105 vfs_read+0x86/0x140 1106 SyS_read+0x46/0xb0 1107 system_call_fastpath+0x12/0x6a 1108 } hitcount: 19133 bytes_req: 78368768 bytes_alloc: 78368768 1109 1110 Totals: 1111 Hits: 6085872 1112 Entries: 253 1113 Dropped: 0 1114 1115 If you key a hist trigger on common_pid, in order for example to 1116 gather and display sorted totals for each process, you can use the 1117 special .execname modifier to display the executable names for the 1118 processes in the table rather than raw pids. The example below 1119 keeps a per-process sum of total bytes read:: 1120 1121 # echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \ 1122 /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger 1123 1124 # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/hist 1125 # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active] 1126 1127 { common_pid: gnome-terminal [ 3196] } hitcount: 280 count: 1093512 1128 { common_pid: Xorg [ 1309] } hitcount: 525 count: 256640 1129 { common_pid: compiz [ 2889] } hitcount: 59 count: 254400 1130 { common_pid: bash [ 8710] } hitcount: 3 count: 66369 1131 { common_pid: dbus-daemon-lau [ 8703] } hitcount: 49 count: 47739 1132 { common_pid: irqbalance [ 1252] } hitcount: 27 count: 27648 1133 { common_pid: 01ifupdown [ 8705] } hitcount: 3 count: 17216 1134 { common_pid: dbus-daemon [ 772] } hitcount: 10 count: 12396 1135 { common_pid: Socket Thread [ 8342] } hitcount: 11 count: 11264 1136 { common_pid: nm-dhcp-client. [ 8701] } hitcount: 6 count: 7424 1137 { common_pid: gmain [ 1315] } hitcount: 18 count: 6336 1138 . 1139 . 1140 . 1141 { common_pid: postgres [ 1892] } hitcount: 2 count: 32 1142 { common_pid: postgres [ 1891] } hitcount: 2 count: 32 1143 { common_pid: gmain [ 8704] } hitcount: 2 count: 32 1144 { common_pid: upstart-dbus-br [ 2740] } hitcount: 21 count: 21 1145 { common_pid: nm-dispatcher.a [ 8696] } hitcount: 1 count: 16 1146 { common_pid: indicator-datet [ 2904] } hitcount: 1 count: 16 1147 { common_pid: gdbus [ 2998] } hitcount: 1 count: 16 1148 { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8 1149 { common_pid: init [ 1] } hitcount: 2 count: 2 1150 1151 Totals: 1152 Hits: 2116 1153 Entries: 51 1154 Dropped: 0 1155 1156 Similarly, if you key a hist trigger on syscall id, for example to 1157 gather and display a list of systemwide syscall hits, you can use 1158 the special .syscall modifier to display the syscall names rather 1159 than raw ids. The example below keeps a running total of syscall 1160 counts for the system during the run:: 1161 1162 # echo 'hist:key=id.syscall:val=hitcount' > \ 1163 /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger 1164 1165 # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist 1166 # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active] 1167 1168 { id: sys_fsync [ 74] } hitcount: 1 1169 { id: sys_newuname [ 63] } hitcount: 1 1170 { id: sys_prctl [157] } hitcount: 1 1171 { id: sys_statfs [137] } hitcount: 1 1172 { id: sys_symlink [ 88] } hitcount: 1 1173 { id: sys_sendmmsg [307] } hitcount: 1 1174 { id: sys_semctl [ 66] } hitcount: 1 1175 { id: sys_readlink [ 89] } hitcount: 3 1176 { id: sys_bind [ 49] } hitcount: 3 1177 { id: sys_getsockname [ 51] } hitcount: 3 1178 { id: sys_unlink [ 87] } hitcount: 3 1179 { id: sys_rename [ 82] } hitcount: 4 1180 { id: unknown_syscall [ 58] } hitcount: 4 1181 { id: sys_connect [ 42] } hitcount: 4 1182 { id: sys_getpid [ 39] } hitcount: 4 1183 . 1184 . 1185 . 1186 { id: sys_rt_sigprocmask [ 14] } hitcount: 952 1187 { id: sys_futex [202] } hitcount: 1534 1188 { id: sys_write [ 1] } hitcount: 2689 1189 { id: sys_setitimer [ 38] } hitcount: 2797 1190 { id: sys_read [ 0] } hitcount: 3202 1191 { id: sys_select [ 23] } hitcount: 3773 1192 { id: sys_writev [ 20] } hitcount: 4531 1193 { id: sys_poll [ 7] } hitcount: 8314 1194 { id: sys_recvmsg [ 47] } hitcount: 13738 1195 { id: sys_ioctl [ 16] } hitcount: 21843 1196 1197 Totals: 1198 Hits: 67612 1199 Entries: 72 1200 Dropped: 0 1201 1202 The syscall counts above provide a rough overall picture of system 1203 call activity on the system; we can see for example that the most 1204 popular system call on this system was the 'sys_ioctl' system call. 1205 1206 We can use 'compound' keys to refine that number and provide some 1207 further insight as to which processes exactly contribute to the 1208 overall ioctl count. 1209 1210 The command below keeps a hitcount for every unique combination of 1211 system call id and pid - the end result is essentially a table 1212 that keeps a per-pid sum of system call hits. The results are 1213 sorted using the system call id as the primary key, and the 1214 hitcount sum as the secondary key:: 1215 1216 # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' > \ 1217 /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger 1218 1219 # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist 1220 # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active] 1221 1222 { id: sys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: 1 1223 { id: sys_read [ 0], common_pid: gdbus [ 2976] } hitcount: 1 1224 { id: sys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: 1 1225 { id: sys_read [ 0], common_pid: postgres [ 1865] } hitcount: 1 1226 { id: sys_read [ 0], common_pid: deja-dup-monito [ 3543] } hitcount: 2 1227 { id: sys_read [ 0], common_pid: NetworkManager [ 890] } hitcount: 2 1228 { id: sys_read [ 0], common_pid: evolution-calen [ 3048] } hitcount: 2 1229 { id: sys_read [ 0], common_pid: postgres [ 1864] } hitcount: 2 1230 { id: sys_read [ 0], common_pid: nm-applet [ 3022] } hitcount: 2 1231 { id: sys_read [ 0], common_pid: whoopsie [ 1212] } hitcount: 2 1232 . 1233 . 1234 . 1235 { id: sys_ioctl [ 16], common_pid: bash [ 8479] } hitcount: 1 1236 { id: sys_ioctl [ 16], common_pid: bash [ 3472] } hitcount: 12 1237 { id: sys_ioctl [ 16], common_pid: gnome-terminal [ 3199] } hitcount: 16 1238 { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 1808 1239 { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 5580 1240 . 1241 . 1242 . 1243 { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2690] } hitcount: 3 1244 { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2688] } hitcount: 16 1245 { id: sys_inotify_add_watch [254], common_pid: gmain [ 975] } hitcount: 2 1246 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3204] } hitcount: 4 1247 { id: sys_inotify_add_watch [254], common_pid: gmain [ 2888] } hitcount: 4 1248 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3003] } hitcount: 4 1249 { id: sys_inotify_add_watch [254], common_pid: gmain [ 2873] } hitcount: 4 1250 { id: sys_inotify_add_watch [254], common_pid: gmain [ 3196] } hitcount: 6 1251 { id: sys_openat [257], common_pid: java [ 2623] } hitcount: 2 1252 { id: sys_eventfd2 [290], common_pid: ibus-ui-gtk3 [ 2760] } hitcount: 4 1253 { id: sys_eventfd2 [290], common_pid: compiz [ 2994] } hitcount: 6 1254 1255 Totals: 1256 Hits: 31536 1257 Entries: 323 1258 Dropped: 0 1259 1260 The above list does give us a breakdown of the ioctl syscall by 1261 pid, but it also gives us quite a bit more than that, which we 1262 don't really care about at the moment. Since we know the syscall 1263 id for sys_ioctl (16, displayed next to the sys_ioctl name), we 1264 can use that to filter out all the other syscalls:: 1265 1266 # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount if id == 16' > \ 1267 /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger 1268 1269 # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist 1270 # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 if id == 16 [active] 1271 1272 { id: sys_ioctl [ 16], common_pid: gmain [ 2769] } hitcount: 1 1273 { id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: 1 1274 { id: sys_ioctl [ 16], common_pid: gmain [ 3003] } hitcount: 1 1275 { id: sys_ioctl [ 16], common_pid: gmain [ 2781] } hitcount: 1 1276 { id: sys_ioctl [ 16], common_pid: gmain [ 2829] } hitcount: 1 1277 { id: sys_ioctl [ 16], common_pid: bash [ 8726] } hitcount: 1 1278 { id: sys_ioctl [ 16], common_pid: bash [ 8508] } hitcount: 1 1279 { id: sys_ioctl [ 16], common_pid: gmain [ 2970] } hitcount: 1 1280 { id: sys_ioctl [ 16], common_pid: gmain [ 2768] } hitcount: 1 1281 . 1282 . 1283 . 1284 { id: sys_ioctl [ 16], common_pid: pool [ 8559] } hitcount: 45 1285 { id: sys_ioctl [ 16], common_pid: pool [ 8555] } hitcount: 48 1286 { id: sys_ioctl [ 16], common_pid: pool [ 8551] } hitcount: 48 1287 { id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: 66 1288 { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 26674 1289 { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 73443 1290 1291 Totals: 1292 Hits: 101162 1293 Entries: 103 1294 Dropped: 0 1295 1296 The above output shows that 'compiz' and 'Xorg' are far and away 1297 the heaviest ioctl callers (which might lead to questions about 1298 whether they really need to be making all those calls and to 1299 possible avenues for further investigation.) 1300 1301 The compound key examples used a key and a sum value (hitcount) to 1302 sort the output, but we can just as easily use two keys instead. 1303 Here's an example where we use a compound key composed of the the 1304 common_pid and size event fields. Sorting with pid as the primary 1305 key and 'size' as the secondary key allows us to display an 1306 ordered summary of the recvfrom sizes, with counts, received by 1307 each process:: 1308 1309 # echo 'hist:key=common_pid.execname,size:val=hitcount:sort=common_pid,size' > \ 1310 /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/trigger 1311 1312 # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/hist 1313 # trigger info: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:size=2048 [active] 1314 1315 { common_pid: smbd [ 784], size: 4 } hitcount: 1 1316 { common_pid: dnsmasq [ 1412], size: 4096 } hitcount: 672 1317 { common_pid: postgres [ 1796], size: 1000 } hitcount: 6 1318 { common_pid: postgres [ 1867], size: 1000 } hitcount: 10 1319 { common_pid: bamfdaemon [ 2787], size: 28 } hitcount: 2 1320 { common_pid: bamfdaemon [ 2787], size: 14360 } hitcount: 1 1321 { common_pid: compiz [ 2994], size: 8 } hitcount: 1 1322 { common_pid: compiz [ 2994], size: 20 } hitcount: 11 1323 { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2 1324 { common_pid: firefox [ 8817], size: 4 } hitcount: 1 1325 { common_pid: firefox [ 8817], size: 8 } hitcount: 5 1326 { common_pid: firefox [ 8817], size: 588 } hitcount: 2 1327 { common_pid: firefox [ 8817], size: 628 } hitcount: 1 1328 { common_pid: firefox [ 8817], size: 6944 } hitcount: 1 1329 { common_pid: firefox [ 8817], size: 408880 } hitcount: 2 1330 { common_pid: firefox [ 8822], size: 8 } hitcount: 2 1331 { common_pid: firefox [ 8822], size: 160 } hitcount: 2 1332 { common_pid: firefox [ 8822], size: 320 } hitcount: 2 1333 { common_pid: firefox [ 8822], size: 352 } hitcount: 1 1334 . 1335 . 1336 . 1337 { common_pid: pool [ 8923], size: 1960 } hitcount: 10 1338 { common_pid: pool [ 8923], size: 2048 } hitcount: 10 1339 { common_pid: pool [ 8924], size: 1960 } hitcount: 10 1340 { common_pid: pool [ 8924], size: 2048 } hitcount: 10 1341 { common_pid: pool [ 8928], size: 1964 } hitcount: 4 1342 { common_pid: pool [ 8928], size: 1965 } hitcount: 2 1343 { common_pid: pool [ 8928], size: 2048 } hitcount: 6 1344 { common_pid: pool [ 8929], size: 1982 } hitcount: 1 1345 { common_pid: pool [ 8929], size: 2048 } hitcount: 1 1346 1347 Totals: 1348 Hits: 2016 1349 Entries: 224 1350 Dropped: 0 1351 1352 The above example also illustrates the fact that although a compound 1353 key is treated as a single entity for hashing purposes, the sub-keys 1354 it's composed of can be accessed independently. 1355 1356 The next example uses a string field as the hash key and 1357 demonstrates how you can manually pause and continue a hist trigger. 1358 In this example, we'll aggregate fork counts and don't expect a 1359 large number of entries in the hash table, so we'll drop it to a 1360 much smaller number, say 256:: 1361 1362 # echo 'hist:key=child_comm:val=hitcount:size=256' > \ 1363 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger 1364 1365 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist 1366 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] 1367 1368 { child_comm: dconf worker } hitcount: 1 1369 { child_comm: ibus-daemon } hitcount: 1 1370 { child_comm: whoopsie } hitcount: 1 1371 { child_comm: smbd } hitcount: 1 1372 { child_comm: gdbus } hitcount: 1 1373 { child_comm: kthreadd } hitcount: 1 1374 { child_comm: dconf worker } hitcount: 1 1375 { child_comm: evolution-alarm } hitcount: 2 1376 { child_comm: Socket Thread } hitcount: 2 1377 { child_comm: postgres } hitcount: 2 1378 { child_comm: bash } hitcount: 3 1379 { child_comm: compiz } hitcount: 3 1380 { child_comm: evolution-sourc } hitcount: 4 1381 { child_comm: dhclient } hitcount: 4 1382 { child_comm: pool } hitcount: 5 1383 { child_comm: nm-dispatcher.a } hitcount: 8 1384 { child_comm: firefox } hitcount: 8 1385 { child_comm: dbus-daemon } hitcount: 8 1386 { child_comm: glib-pacrunner } hitcount: 10 1387 { child_comm: evolution } hitcount: 23 1388 1389 Totals: 1390 Hits: 89 1391 Entries: 20 1392 Dropped: 0 1393 1394 If we want to pause the hist trigger, we can simply append :pause to 1395 the command that started the trigger. Notice that the trigger info 1396 displays as [paused]:: 1397 1398 # echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \ 1399 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger 1400 1401 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist 1402 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [paused] 1403 1404 { child_comm: dconf worker } hitcount: 1 1405 { child_comm: kthreadd } hitcount: 1 1406 { child_comm: dconf worker } hitcount: 1 1407 { child_comm: gdbus } hitcount: 1 1408 { child_comm: ibus-daemon } hitcount: 1 1409 { child_comm: Socket Thread } hitcount: 2 1410 { child_comm: evolution-alarm } hitcount: 2 1411 { child_comm: smbd } hitcount: 2 1412 { child_comm: bash } hitcount: 3 1413 { child_comm: whoopsie } hitcount: 3 1414 { child_comm: compiz } hitcount: 3 1415 { child_comm: evolution-sourc } hitcount: 4 1416 { child_comm: pool } hitcount: 5 1417 { child_comm: postgres } hitcount: 6 1418 { child_comm: firefox } hitcount: 8 1419 { child_comm: dhclient } hitcount: 10 1420 { child_comm: emacs } hitcount: 12 1421 { child_comm: dbus-daemon } hitcount: 20 1422 { child_comm: nm-dispatcher.a } hitcount: 20 1423 { child_comm: evolution } hitcount: 35 1424 { child_comm: glib-pacrunner } hitcount: 59 1425 1426 Totals: 1427 Hits: 199 1428 Entries: 21 1429 Dropped: 0 1430 1431 To manually continue having the trigger aggregate events, append 1432 :cont instead. Notice that the trigger info displays as [active] 1433 again, and the data has changed:: 1434 1435 # echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \ 1436 /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger 1437 1438 # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist 1439 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] 1440 1441 { child_comm: dconf worker } hitcount: 1 1442 { child_comm: dconf worker } hitcount: 1 1443 { child_comm: kthreadd } hitcount: 1 1444 { child_comm: gdbus } hitcount: 1 1445 { child_comm: ibus-daemon } hitcount: 1 1446 { child_comm: Socket Thread } hitcount: 2 1447 { child_comm: evolution-alarm } hitcount: 2 1448 { child_comm: smbd } hitcount: 2 1449 { child_comm: whoopsie } hitcount: 3 1450 { child_comm: compiz } hitcount: 3 1451 { child_comm: evolution-sourc } hitcount: 4 1452 { child_comm: bash } hitcount: 5 1453 { child_comm: pool } hitcount: 5 1454 { child_comm: postgres } hitcount: 6 1455 { child_comm: firefox } hitcount: 8 1456 { child_comm: dhclient } hitcount: 11 1457 { child_comm: emacs } hitcount: 12 1458 { child_comm: dbus-daemon } hitcount: 22 1459 { child_comm: nm-dispatcher.a } hitcount: 22 1460 { child_comm: evolution } hitcount: 35 1461 { child_comm: glib-pacrunner } hitcount: 59 1462 1463 Totals: 1464 Hits: 206 1465 Entries: 21 1466 Dropped: 0 1467 1468 The previous example showed how to start and stop a hist trigger by 1469 appending 'pause' and 'continue' to the hist trigger command. A 1470 hist trigger can also be started in a paused state by initially 1471 starting the trigger with ':pause' appended. This allows you to 1472 start the trigger only when you're ready to start collecting data 1473 and not before. For example, you could start the trigger in a 1474 paused state, then unpause it and do something you want to measure, 1475 then pause the trigger again when done. 1476 1477 Of course, doing this manually can be difficult and error-prone, but 1478 it is possible to automatically start and stop a hist trigger based 1479 on some condition, via the enable_hist and disable_hist triggers. 1480 1481 For example, suppose we wanted to take a look at the relative 1482 weights in terms of skb length for each callpath that leads to a 1483 netif_receieve_skb event when downloading a decent-sized file using 1484 wget. 1485 1486 First we set up an initially paused stacktrace trigger on the 1487 netif_receive_skb event:: 1488 1489 # echo 'hist:key=stacktrace:vals=len:pause' > \ 1490 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger 1491 1492 Next, we set up an 'enable_hist' trigger on the sched_process_exec 1493 event, with an 'if filename==/usr/bin/wget' filter. The effect of 1494 this new trigger is that it will 'unpause' the hist trigger we just 1495 set up on netif_receive_skb if and only if it sees a 1496 sched_process_exec event with a filename of '/usr/bin/wget'. When 1497 that happens, all netif_receive_skb events are aggregated into a 1498 hash table keyed on stacktrace:: 1499 1500 # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ 1501 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger 1502 1503 The aggregation continues until the netif_receive_skb is paused 1504 again, which is what the following disable_hist event does by 1505 creating a similar setup on the sched_process_exit event, using the 1506 filter 'comm==wget':: 1507 1508 # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ 1509 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger 1510 1511 Whenever a process exits and the comm field of the disable_hist 1512 trigger filter matches 'comm==wget', the netif_receive_skb hist 1513 trigger is disabled. 1514 1515 The overall effect is that netif_receive_skb events are aggregated 1516 into the hash table for only the duration of the wget. Executing a 1517 wget command and then listing the 'hist' file will display the 1518 output generated by the wget command:: 1519 1520 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz 1521 1522 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist 1523 # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused] 1524 1525 { stacktrace: 1526 __netif_receive_skb_core+0x46d/0x990 1527 __netif_receive_skb+0x18/0x60 1528 netif_receive_skb_internal+0x23/0x90 1529 napi_gro_receive+0xc8/0x100 1530 ieee80211_deliver_skb+0xd6/0x270 [mac80211] 1531 ieee80211_rx_handlers+0xccf/0x22f0 [mac80211] 1532 ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211] 1533 ieee80211_rx+0x31d/0x900 [mac80211] 1534 iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm] 1535 iwl_rx_dispatch+0x8e/0xf0 [iwldvm] 1536 iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi] 1537 irq_thread_fn+0x20/0x50 1538 irq_thread+0x11f/0x150 1539 kthread+0xd2/0xf0 1540 ret_from_fork+0x42/0x70 1541 } hitcount: 85 len: 28884 1542 { stacktrace: 1543 __netif_receive_skb_core+0x46d/0x990 1544 __netif_receive_skb+0x18/0x60 1545 netif_receive_skb_internal+0x23/0x90 1546 napi_gro_complete+0xa4/0xe0 1547 dev_gro_receive+0x23a/0x360 1548 napi_gro_receive+0x30/0x100 1549 ieee80211_deliver_skb+0xd6/0x270 [mac80211] 1550 ieee80211_rx_handlers+0xccf/0x22f0 [mac80211] 1551 ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211] 1552 ieee80211_rx+0x31d/0x900 [mac80211] 1553 iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm] 1554 iwl_rx_dispatch+0x8e/0xf0 [iwldvm] 1555 iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi] 1556 irq_thread_fn+0x20/0x50 1557 irq_thread+0x11f/0x150 1558 kthread+0xd2/0xf0 1559 } hitcount: 98 len: 664329 1560 { stacktrace: 1561 __netif_receive_skb_core+0x46d/0x990 1562 __netif_receive_skb+0x18/0x60 1563 process_backlog+0xa8/0x150 1564 net_rx_action+0x15d/0x340 1565 __do_softirq+0x114/0x2c0 1566 do_softirq_own_stack+0x1c/0x30 1567 do_softirq+0x65/0x70 1568 __local_bh_enable_ip+0xb5/0xc0 1569 ip_finish_output+0x1f4/0x840 1570 ip_output+0x6b/0xc0 1571 ip_local_out_sk+0x31/0x40 1572 ip_send_skb+0x1a/0x50 1573 udp_send_skb+0x173/0x2a0 1574 udp_sendmsg+0x2bf/0x9f0 1575 inet_sendmsg+0x64/0xa0 1576 sock_sendmsg+0x3d/0x50 1577 } hitcount: 115 len: 13030 1578 { stacktrace: 1579 __netif_receive_skb_core+0x46d/0x990 1580 __netif_receive_skb+0x18/0x60 1581 netif_receive_skb_internal+0x23/0x90 1582 napi_gro_complete+0xa4/0xe0 1583 napi_gro_flush+0x6d/0x90 1584 iwl_pcie_irq_handler+0x92a/0x12f0 [iwlwifi] 1585 irq_thread_fn+0x20/0x50 1586 irq_thread+0x11f/0x150 1587 kthread+0xd2/0xf0 1588 ret_from_fork+0x42/0x70 1589 } hitcount: 934 len: 5512212 1590 1591 Totals: 1592 Hits: 1232 1593 Entries: 4 1594 Dropped: 0 1595 1596 The above shows all the netif_receive_skb callpaths and their total 1597 lengths for the duration of the wget command. 1598 1599 The 'clear' hist trigger param can be used to clear the hash table. 1600 Suppose we wanted to try another run of the previous example but 1601 this time also wanted to see the complete list of events that went 1602 into the histogram. In order to avoid having to set everything up 1603 again, we can just clear the histogram first:: 1604 1605 # echo 'hist:key=stacktrace:vals=len:clear' >> \ 1606 /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger 1607 1608 Just to verify that it is in fact cleared, here's what we now see in 1609 the hist file:: 1610 1611 # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist 1612 # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused] 1613 1614 Totals: 1615 Hits: 0 1616 Entries: 0 1617 Dropped: 0 1618 1619 Since we want to see the detailed list of every netif_receive_skb 1620 event occurring during the new run, which are in fact the same 1621 events being aggregated into the hash table, we add some additional 1622 'enable_event' events to the triggering sched_process_exec and 1623 sched_process_exit events as such:: 1624 1625 # echo 'enable_event:net:netif_receive_skb if filename==/usr/bin/wget' > \ 1626 /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger 1627 1628 # echo 'disable_event:net:netif_receive_skb if comm==wget' > \ 1629 /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger 1630 1631 If you read the trigger files for the sched_process_exec and 1632 sched_process_exit triggers, you should see two triggers for each: 1633 one enabling/disabling the hist aggregation and the other 1634 enabling/disabling the logging of events:: 1635 1636 # cat /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger 1637 enable_event:net:netif_receive_skb:unlimited if filename==/usr/bin/wget 1638 enable_hist:net:netif_receive_skb:unlimited if filename==/usr/bin/wget 1639 1640 # cat /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger 1641 enable_event:net:netif_receive_skb:unlimited if comm==wget 1642 disable_hist:net:netif_receive_skb:unlimited if comm==wget 1643 1644 In other words, whenever either of the sched_process_exec or 1645 sched_process_exit events is hit and matches 'wget', it enables or 1646 disables both the histogram and the event log, and what you end up 1647 with is a hash table and set of events just covering the specified 1648 duration. Run the wget command again:: 1649 1650 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz 1651 1652 Displaying the 'hist' file should show something similar to what you 1653 saw in the last run, but this time you should also see the 1654 individual events in the trace file:: 1655 1656 # cat /sys/kernel/debug/tracing/trace 1657 1658 # tracer: nop 1659 # 1660 # entries-in-buffer/entries-written: 183/1426 #P:4 1661 # 1662 # _-----=> irqs-off 1663 # / _----=> need-resched 1664 # | / _---=> hardirq/softirq 1665 # || / _--=> preempt-depth 1666 # ||| / delay 1667 # TASK-PID CPU# |||| TIMESTAMP FUNCTION 1668 # | | | |||| | | 1669 wget-15108 [000] ..s1 31769.606929: netif_receive_skb: dev=lo skbaddr=ffff88009c353100 len=60 1670 wget-15108 [000] ..s1 31769.606999: netif_receive_skb: dev=lo skbaddr=ffff88009c353200 len=60 1671 dnsmasq-1382 [000] ..s1 31769.677652: netif_receive_skb: dev=lo skbaddr=ffff88009c352b00 len=130 1672 dnsmasq-1382 [000] ..s1 31769.685917: netif_receive_skb: dev=lo skbaddr=ffff88009c352200 len=138 1673 ##### CPU 2 buffer started #### 1674 irq/29-iwlwifi-559 [002] ..s. 31772.031529: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433d00 len=2948 1675 irq/29-iwlwifi-559 [002] ..s. 31772.031572: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432200 len=1500 1676 irq/29-iwlwifi-559 [002] ..s. 31772.032196: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433100 len=2948 1677 irq/29-iwlwifi-559 [002] ..s. 31772.032761: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433000 len=2948 1678 irq/29-iwlwifi-559 [002] ..s. 31772.033220: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432e00 len=1500 1679 .... 1680 1681 1682 The following example demonstrates how multiple hist triggers can be 1683 attached to a given event. This capability can be useful for 1684 creating a set of different summaries derived from the same set of 1685 events, or for comparing the effects of different filters, among 1686 other things. 1687 :: 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 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 2070