diff options
30 files changed, 8372 insertions, 3268 deletions
diff --git a/Documentation/trace/events.rst b/Documentation/trace/events.rst index bdf1963ba6ba..a5ea2cb0082b 100644 --- a/Documentation/trace/events.rst +++ b/Documentation/trace/events.rst @@ -520,1550 +520,4 @@ The following commands are supported: totals derived from one or more trace event format fields and/or event counts (hitcount). - The format of a hist trigger is as follows:: - - hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>] - [:sort=<field1[,field2,...]>][:size=#entries][:pause][:continue] - [:clear][:name=histname1] [if <filter>] - - When a matching event is hit, an entry is added to a hash table - using the key(s) and value(s) named. Keys and values correspond to - fields in the event's format description. Values must correspond to - numeric fields - on an event hit, the value(s) will be added to a - sum kept for that field. The special string 'hitcount' can be used - in place of an explicit value field - this is simply a count of - event hits. If 'values' isn't specified, an implicit 'hitcount' - value will be automatically created and used as the only value. - Keys can be any field, or the special string 'stacktrace', which - will use the event's kernel stacktrace as the key. The keywords - 'keys' or 'key' can be used to specify keys, and the keywords - 'values', 'vals', or 'val' can be used to specify values. Compound - keys consisting of up to two fields can be specified by the 'keys' - keyword. Hashing a compound key produces a unique entry in the - table for each unique combination of component keys, and can be - useful for providing more fine-grained summaries of event data. - Additionally, sort keys consisting of up to two fields can be - specified by the 'sort' keyword. If more than one field is - specified, the result will be a 'sort within a sort': the first key - is taken to be the primary sort key and the second the secondary - key. If a hist trigger is given a name using the 'name' parameter, - its histogram data will be shared with other triggers of the same - name, and trigger hits will update this common data. Only triggers - with 'compatible' fields can be combined in this way; triggers are - 'compatible' if the fields named in the trigger share the same - number and type of fields and those fields also have the same names. - Note that any two events always share the compatible 'hitcount' and - 'stacktrace' fields and can therefore be combined using those - fields, however pointless that may be. - - 'hist' triggers add a 'hist' file to each event's subdirectory. - Reading the 'hist' file for the event will dump the hash table in - its entirety to stdout. If there are multiple hist triggers - attached to an event, there will be a table for each trigger in the - output. The table displayed for a named trigger will be the same as - any other instance having the same name. Each printed hash table - entry is a simple list of the keys and values comprising the entry; - keys are printed first and are delineated by curly braces, and are - followed by the set of value fields for the entry. By default, - numeric fields are displayed as base-10 integers. This can be - modified by appending any of the following modifiers to the field - name: - - - .hex display a number as a hex value - - .sym display an address as a symbol - - .sym-offset display an address as a symbol and offset - - .syscall display a syscall id as a system call name - - .execname display a common_pid as a program name - - Note that in general the semantics of a given field aren't - interpreted when applying a modifier to it, but there are some - restrictions to be aware of in this regard: - - - only the 'hex' modifier can be used for values (because values - are essentially sums, and the other modifiers don't make sense - in that context). - - the 'execname' modifier can only be used on a 'common_pid'. The - reason for this is that the execname is simply the 'comm' value - saved for the 'current' process when an event was triggered, - which is the same as the common_pid value saved by the event - tracing code. Trying to apply that comm value to other pid - values wouldn't be correct, and typically events that care save - pid-specific comm fields in the event itself. - - A typical usage scenario would be the following to enable a hist - trigger, read its current contents, and then turn it off:: - - # echo 'hist:keys=skbaddr.hex:vals=len' > \ - /sys/kernel/debug/tracing/events/net/netif_rx/trigger - - # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist - - # echo '!hist:keys=skbaddr.hex:vals=len' > \ - /sys/kernel/debug/tracing/events/net/netif_rx/trigger - - The trigger file itself can be read to show the details of the - currently attached hist trigger. This information is also displayed - at the top of the 'hist' file when read. - - By default, the size of the hash table is 2048 entries. The 'size' - parameter can be used to specify more or fewer than that. The units - are in terms of hashtable entries - if a run uses more entries than - specified, the results will show the number of 'drops', the number - of hits that were ignored. The size should be a power of 2 between - 128 and 131072 (any non- power-of-2 number specified will be rounded - up). - - The 'sort' parameter can be used to specify a value field to sort - on. The default if unspecified is 'hitcount' and the default sort - order is 'ascending'. To sort in the opposite direction, append - .descending' to the sort key. - - The 'pause' parameter can be used to pause an existing hist trigger - or to start a hist trigger but not log any events until told to do - so. 'continue' or 'cont' can be used to start or restart a paused - hist trigger. - - The 'clear' parameter will clear the contents of a running hist - trigger and leave its current paused/active state. - - Note that the 'pause', 'cont', and 'clear' parameters should be - applied using 'append' shell operator ('>>') if applied to an - existing trigger, rather than via the '>' operator, which will cause - the trigger to be removed through truncation. - -- enable_hist/disable_hist - - The enable_hist and disable_hist triggers can be used to have one - event conditionally start and stop another event's already-attached - hist trigger. Any number of enable_hist and disable_hist triggers - can be attached to a given event, allowing that event to kick off - and stop aggregations on a host of other events. - - The format is very similar to the enable/disable_event triggers:: - - enable_hist:<system>:<event>[:count] - disable_hist:<system>:<event>[:count] - - Instead of enabling or disabling the tracing of the target event - into the trace buffer as the enable/disable_event triggers do, the - enable/disable_hist triggers enable or disable the aggregation of - the target event into a hash table. - - A typical usage scenario for the enable_hist/disable_hist triggers - would be to first set up a paused hist trigger on some event, - followed by an enable_hist/disable_hist pair that turns the hist - aggregation on and off when conditions of interest are hit:: - - # echo 'hist:keys=skbaddr.hex:vals=len:pause' > \ - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger - - # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ - /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger - - # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ - /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger - - The above sets up an initially paused hist trigger which is unpaused - and starts aggregating events when a given program is executed, and - which stops aggregating when the process exits and the hist trigger - is paused again. - - The examples below provide a more concrete illustration of the - concepts and typical usage patterns discussed above. - - -6.2 'hist' trigger examples ---------------------------- - - The first set of examples creates aggregations using the kmalloc - event. The fields that can be used for the hist trigger are listed - in the kmalloc event's format file:: - - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/format - name: kmalloc - ID: 374 - format: - field:unsigned short common_type; offset:0; size:2; signed:0; - field:unsigned char common_flags; offset:2; size:1; signed:0; - field:unsigned char common_preempt_count; offset:3; size:1; signed:0; - field:int common_pid; offset:4; size:4; signed:1; - - field:unsigned long call_site; offset:8; size:8; signed:0; - field:const void * ptr; offset:16; size:8; signed:0; - field:size_t bytes_req; offset:24; size:8; signed:0; - field:size_t bytes_alloc; offset:32; size:8; signed:0; - field:gfp_t gfp_flags; offset:40; size:4; signed:0; - - We'll start by creating a hist trigger that generates a simple table - that lists the total number of bytes requested for each function in - the kernel that made one or more calls to kmalloc:: - - # echo 'hist:key=call_site:val=bytes_req' > \ - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger - - This tells the tracing system to create a 'hist' trigger using the - call_site field of the kmalloc event as the key for the table, which - just means that each unique call_site address will have an entry - created for it in the table. The 'val=bytes_req' parameter tells - the hist trigger that for each unique entry (call_site) in the - table, it should keep a running total of the number of bytes - requested by that call_site. - - We'll let it run for awhile and then dump the contents of the 'hist' - file in the kmalloc event's subdirectory (for readability, a number - of entries have been omitted):: - - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist - # trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active] - - { call_site: 18446744072106379007 } hitcount: 1 bytes_req: 176 - { call_site: 18446744071579557049 } hitcount: 1 bytes_req: 1024 - { call_site: 18446744071580608289 } hitcount: 1 bytes_req: 16384 - { call_site: 18446744071581827654 } hitcount: 1 bytes_req: 24 - { call_site: 18446744071580700980 } hitcount: 1 bytes_req: 8 - { call_site: 18446744071579359876 } hitcount: 1 bytes_req: 152 - { call_site: 18446744071580795365 } hitcount: 3 bytes_req: 144 - { call_site: 18446744071581303129 } hitcount: 3 bytes_req: 144 - { call_site: 18446744071580713234 } hitcount: 4 bytes_req: 2560 - { call_site: 18446744071580933750 } hitcount: 4 bytes_req: 736 - . - . - . - { call_site: 18446744072106047046 } hitcount: 69 bytes_req: 5576 - { call_site: 18446744071582116407 } hitcount: 73 bytes_req: 2336 - { call_site: 18446744072106054684 } hitcount: 136 bytes_req: 140504 - { call_site: 18446744072106224230 } hitcount: 136 bytes_req: 19584 - { call_site: 18446744072106078074 } hitcount: 153 bytes_req: 2448 - { call_site: 18446744072106062406 } hitcount: 153 bytes_req: 36720 - { call_site: 18446744071582507929 } hitcount: 153 bytes_req: 37088 - { call_site: 18446744072102520590 } hitcount: 273 bytes_req: 10920 - { call_site: 18446744071582143559 } hitcount: 358 bytes_req: 716 - { call_site: 18446744072106465852 } hitcount: 417 bytes_req: 56712 - { call_site: 18446744072102523378 } hitcount: 485 bytes_req: 27160 - { call_site: 18446744072099568646 } hitcount: 1676 bytes_req: 33520 - - Totals: - Hits: 4610 - Entries: 45 - Dropped: 0 - - The output displays a line for each entry, beginning with the key - specified in the trigger, followed by the value(s) also specified in - the trigger. At the beginning of the output is a line that displays - the trigger info, which can also be displayed by reading the - 'trigger' file:: - - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger - hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active] - - At the end of the output are a few lines that display the overall - totals for the run. The 'Hits' field shows the total number of - times the event trigger was hit, the 'Entries' field shows the total - number of used entries in the hash table, and the 'Dropped' field - shows the number of hits that were dropped because the number of - used entries for the run exceeded the maximum number of entries - allowed for the table (normally 0, but if not a hint that you may - want to increase the size of the table using the 'size' parameter). - - Notice in the above output that there's an extra field, 'hitcount', - which wasn't specified in the trigger. Also notice that in the - trigger info output, there's a parameter, 'sort=hitcount', which - wasn't specified in the trigger either. The reason for that is that - every trigger implicitly keeps a count of the total number of hits - attributed to a given entry, called the 'hitcount'. That hitcount - information is explicitly displayed in the output, and in the - absence of a user-specified sort parameter, is used as the default - sort field. - - The value 'hitcount' can be used in place of an explicit value in - the 'values' parameter if you don't really need to have any - particular field summed and are mainly interested in hit - frequencies. - - To turn the hist trigger off, simply call up the trigger in the - command history and re-execute it with a '!' prepended:: - - # echo '!hist:key=call_site:val=bytes_req' > \ - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger - - Finally, notice that the call_site as displayed in the output above - isn't really very useful. It's an address, but normally addresses - are displayed in hex. To have a numeric field displayed as a hex - value, simply append '.hex' to the field name in the trigger:: - - # echo 'hist:key=call_site.hex:val=bytes_req' > \ - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger - - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist - # trigger info: hist:keys=call_site.hex:vals=bytes_req:sort=hitcount:size=2048 [active] - - { call_site: ffffffffa026b291 } hitcount: 1 bytes_req: 433 - { call_site: ffffffffa07186ff } hitcount: 1 bytes_req: 176 - { call_site: ffffffff811ae721 } hitcount: 1 bytes_req: 16384 - { call_site: ffffffff811c5134 } hitcount: 1 bytes_req: 8 - { call_site: ffffffffa04a9ebb } hitcount: 1 bytes_req: 511 - { call_site: ffffffff8122e0a6 } hitcount: 1 bytes_req: 12 - { call_site: ffffffff8107da84 } hitcount: 1 bytes_req: 152 - { call_site: ffffffff812d8246 } hitcount: 1 bytes_req: 24 - { call_site: ffffffff811dc1e5 } hitcount: 3 bytes_req: 144 - { call_site: ffffffffa02515e8 } hitcount: 3 bytes_req: 648 - { call_site: ffffffff81258159 } hitcount: 3 bytes_req: 144 - { call_site: ffffffff811c80f4 } hitcount: 4 bytes_req: 544 - . - . - . - { call_site: ffffffffa06c7646 } hitcount: 106 bytes_req: 8024 - { call_site: ffffffffa06cb246 } hitcount: 132 bytes_req: 31680 - { call_site: ffffffffa06cef7a } hitcount: 132 bytes_req: 2112 - { call_site: ffffffff8137e399 } hitcount: 132 bytes_req: 23232 - { call_site: ffffffffa06c941c } hitcount: 185 bytes_req: 171360 - { call_site: ffffffffa06f2a66 } hitcount: 185 bytes_req: 26640 - { call_site: ffffffffa036a70e } hitcount: 265 bytes_req: 10600 - { call_site: ffffffff81325447 } hitcount: 292 bytes_req: 584 - { call_site: ffffffffa072da3c } hitcount: 446 bytes_req: 60656 - { call_site: ffffffffa036b1f2 } hitcount: 526 bytes_req: 29456 - { call_site: ffffffffa0099c06 } hitcount: 1780 bytes_req: 35600 - - Totals: - Hits: 4775 - Entries: 46 - Dropped: 0 - - Even that's only marginally more useful - while hex values do look - more like addresses, what users are typically more interested in - when looking at text addresses are the corresponding symbols - instead. To have an address displayed as symbolic value instead, - simply append '.sym' or '.sym-offset' to the field name in the - trigger:: - - # echo 'hist:key=call_site.sym:val=bytes_req' > \ - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger - - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist - # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=hitcount:size=2048 [active] - - { call_site: [ffffffff810adcb9] syslog_print_all } hitcount: 1 bytes_req: 1024 - { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 - { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 - { call_site: [ffffffff8154acbe] usb_alloc_urb } hitcount: 1 bytes_req: 192 - { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 - { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40 - { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 - { call_site: [ffffffff811febd5] fsnotify_alloc_group } hitcount: 2 bytes_req: 528 - { call_site: [ffffffff81440f58] __tty_buffer_request_room } hitcount: 2 bytes_req: 2624 - { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 2 bytes_req: 96 - { call_site: [ffffffffa05e19af] ieee80211_start_tx_ba_session [mac80211] } hitcount: 2 bytes_req: 464 - { call_site: [ffffffff81672406] tcp_get_metrics } hitcount: 2 bytes_req: 304 - { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 - { call_site: [ffffffff81089b05] sched_create_group } hitcount: 2 bytes_req: 1424 - . - . - . - { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1185 bytes_req: 123240 - { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 1185 bytes_req: 104280 - { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 1402 bytes_req: 190672 - { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 1518 bytes_req: 146208 - { call_site: [ffffffffa029070e] drm_vma_node_allow [drm] } hitcount: 1746 bytes_req: 69840 - { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 2021 bytes_req: 792312 - { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 2592 bytes_req: 145152 - { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2629 bytes_req: 378576 - { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2629 bytes_req: 3783248 - { call_site: [ffffffff81325607] apparmor_file_alloc_security } hitcount: 5192 bytes_req: 10384 - { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 5529 bytes_req: 110584 - { call_site: [ffffffff8131ebf7] aa_alloc_task_context } hitcount: 21943 bytes_req: 702176 - { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 55759 bytes_req: 5074265 - - Totals: - Hits: 109928 - Entries: 71 - Dropped: 0 - - Because the default sort key above is 'hitcount', the above shows a - the list of call_sites by increasing hitcount, so that at the bottom - we see the functions that made the most kmalloc calls during the - run. If instead we we wanted to see the top kmalloc callers in - terms of the number of bytes requested rather than the number of - calls, and we wanted the top caller to appear at the top, we can use - the 'sort' parameter, along with the 'descending' modifier:: - - # echo 'hist:key=call_site.sym:val=bytes_req:sort=bytes_req.descending' > \ - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger - - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist - # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] - - { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 2186 bytes_req: 3397464 - { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1790 bytes_req: 712176 - { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 8132 bytes_req: 513135 - { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 106 bytes_req: 440128 - { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 2186 bytes_req: 314784 - { call_site: [ffffffff812891ca] ext4_find_extent } hitcount: 2174 bytes_req: 208992 - { call_site: [ffffffff811ae8e1] __kmalloc } hitcount: 8 bytes_req: 131072 - { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 859 bytes_req: 116824 - { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 1834 bytes_req: 102704 - { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 972 bytes_req: 101088 - { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl [drm] } hitcount: 972 bytes_req: 85536 - { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 3333 bytes_req: 66664 - { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 209 bytes_req: 61632 - . - . - . - { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 - { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 - { call_site: [ffffffff812d8406] copy_semundo } hitcount: 2 bytes_req: 48 - { call_site: [ffffffff81200ba6] inotify_new_group } hitcount: 1 bytes_req: 48 - { call_site: [ffffffffa027121a] drm_getmagic [drm] } hitcount: 1 bytes_req: 48 - { call_site: [ffffffff811e3a25] __seq_open_private } hitcount: 1 bytes_req: 40 - { call_site: [ffffffff811c52f4] bprm_change_interp } hitcount: 2 bytes_req: 16 - { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 - { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 - { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 - - Totals: - Hits: 32133 - Entries: 81 - Dropped: 0 - - To display the offset and size information in addition to the symbol - name, just use 'sym-offset' instead:: - - # echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \ - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger - - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist - # trigger info: hist:keys=call_site.sym-offset:vals=bytes_req:sort=bytes_req.descending:size=2048 [active] - - { call_site: [ffffffffa046041c] i915_gem_execbuffer2+0x6c/0x2c0 [i915] } hitcount: 4569 bytes_req: 3163720 - { call_site: [ffffffffa0489a66] intel_ring_begin+0xc6/0x1f0 [i915] } hitcount: 4569 bytes_req: 657936 - { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23+0x694/0x1020 [i915] } hitcount: 1519 bytes_req: 472936 - { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23+0x516/0x1020 [i915] } hitcount: 3050 bytes_req: 211832 - { call_site: [ffffffff811e2a1b] seq_buf_alloc+0x1b/0x50 } hitcount: 34 bytes_req: 148384 - { call_site: [ffffffffa04a580c] intel_crtc_page_flip+0xbc/0x870 [i915] } hitcount: 1385 bytes_req: 144040 - { call_site: [ffffffff811ae8e1] __kmalloc+0x191/0x1b0 } hitcount: 8 bytes_req: 131072 - { call_site: [ffffffffa0287592] drm_mode_page_flip_ioctl+0x282/0x360 [drm] } hitcount: 1385 bytes_req: 121880 - { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc+0x32/0x100 [drm] } hitcount: 1848 bytes_req: 103488 - { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state+0x2c/0xa0 [i915] } hitcount: 461 bytes_req: 62696 - { call_site: [ffffffffa029070e] drm_vma_node_allow+0x2e/0xd0 [drm] } hitcount: 1541 bytes_req: 61640 - { call_site: [ffffffff815f8d7b] sk_prot_alloc+0xcb/0x1b0 } hitcount: 57 bytes_req: 57456 - . - . - . - { call_site: [ffffffff8109524a] alloc_fair_sched_group+0x5a/0x1a0 } hitcount: 2 bytes_req: 128 - { call_site: [ffffffffa027b921] drm_vm_open_locked+0x31/0xa0 [drm] } hitcount: 3 bytes_req: 96 - { call_site: [ffffffff8122e266] proc_self_follow_link+0x76/0xb0 } hitcount: 8 bytes_req: 96 - { call_site: [ffffffff81213e80] load_elf_binary+0x240/0x1650 } hitcount: 3 bytes_req: 84 - { call_site: [ffffffff8154bc62] usb_control_msg+0x42/0x110 } hitcount: 1 bytes_req: 8 - { call_site: [ffffffffa00bf6fe] hidraw_send_report+0x7e/0x1a0 [hid] } hitcount: 1 bytes_req: 7 - { call_site: [ffffffffa00bf1ca] hidraw_report_event+0x8a/0x120 [hid] } hitcount: 1 bytes_req: 7 - - Totals: - Hits: 26098 - Entries: 64 - Dropped: 0 - - We can also add multiple fields to the 'values' parameter. For - example, we might want to see the total number of bytes allocated - alongside bytes requested, and display the result sorted by bytes - allocated in a descending order:: - - # echo 'hist:keys=call_site.sym:values=bytes_req,bytes_alloc:sort=bytes_alloc.descending' > \ - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger - - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist - # trigger info: hist:keys=call_site.sym:vals=bytes_req,bytes_alloc:sort=bytes_alloc.descending:size=2048 [active] - - { call_site: [ffffffffa046041c] i915_gem_execbuffer2 [i915] } hitcount: 7403 bytes_req: 4084360 bytes_alloc: 5958016 - { call_site: [ffffffff811e2a1b] seq_buf_alloc } hitcount: 541 bytes_req: 2213968 bytes_alloc: 2228224 - { call_site: [ffffffffa0489a66] intel_ring_begin [i915] } hitcount: 7404 bytes_req: 1066176 bytes_alloc: 1421568 - { call_site: [ffffffffa045e7c4] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 1565 bytes_req: 557368 bytes_alloc: 1037760 - { call_site: [ffffffff8125847d] ext4_htree_store_dirent } hitcount: 9557 bytes_req: 595778 bytes_alloc: 695744 - { call_site: [ffffffffa045e646] i915_gem_do_execbuffer.isra.23 [i915] } hitcount: 5839 bytes_req: 430680 bytes_alloc: 470400 - { call_site: [ffffffffa04c4a3c] intel_plane_duplicate_state [i915] } hitcount: 2388 bytes_req: 324768 bytes_alloc: 458496 - { call_site: [ffffffffa02911f2] drm_modeset_lock_crtc [drm] } hitcount: 3911 bytes_req: 219016 bytes_alloc: 250304 - { call_site: [ffffffff815f8d7b] sk_prot_alloc } hitcount: 235 bytes_req: 236880 bytes_alloc: 240640 - { call_site: [ffffffff8137e559] sg_kmalloc } hitcount: 557 bytes_req: 169024 bytes_alloc: 221760 - { call_site: [ffffffffa00b7c06] hid_report_raw_event [hid] } hitcount: 9378 bytes_req: 187548 bytes_alloc: 206312 - { call_site: [ffffffffa04a580c] intel_crtc_page_flip [i915] } hitcount: 1519 bytes_req: 157976 bytes_alloc: 194432 - . - . - . - { call_site: [ffffffff8109bd3b] sched_autogroup_create_attach } hitcount: 2 bytes_req: 144 bytes_alloc: 192 - { call_site: [ffffffff81097ee8] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 - { call_site: [ffffffff8109524a] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 - { call_site: [ffffffff81095225] alloc_fair_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 - { call_site: [ffffffff81097ec2] alloc_rt_sched_group } hitcount: 2 bytes_req: 128 bytes_alloc: 128 - { call_site: [ffffffff81213e80] load_elf_binary } hitcount: 3 bytes_req: 84 bytes_alloc: 96 - { call_site: [ffffffff81079a2e] kthread_create_on_node } hitcount: 1 bytes_req: 56 bytes_alloc: 64 - { call_site: [ffffffffa00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8 - { call_site: [ffffffff8154bc62] usb_control_msg } hitcount: 1 bytes_req: 8 bytes_alloc: 8 - { call_site: [ffffffffa00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: 7 bytes_alloc: 8 - - Totals: - Hits: 66598 - Entries: 65 - Dropped: 0 - - Finally, to finish off our kmalloc example, instead of simply having - the hist trigger display symbolic call_sites, we can have the hist - trigger additionally display the complete set of kernel stack traces - that led to each call_site. To do that, we simply use the special - value 'stacktrace' for the key parameter:: - - # echo 'hist:keys=stacktrace:values=bytes_req,bytes_alloc:sort=bytes_alloc' > \ - /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger - - The above trigger will use the kernel stack trace in effect when an - event is triggered as the key for the hash table. This allows the - enumeration of every kernel callpath that led up to a particular - event, along with a running total of any of the event fields for - that event. Here we tally bytes requested and bytes allocated for - every callpath in the system that led up to a kmalloc (in this case - every callpath to a kmalloc for a kernel compile):: - - # cat /sys/kernel/debug/tracing/events/kmem/kmalloc/hist - # trigger info: hist:keys=stacktrace:vals=bytes_req,bytes_alloc:sort=bytes_alloc:size=2048 [active] - - { stacktrace: - __kmalloc_track_caller+0x10b/0x1a0 - kmemdup+0x20/0x50 - hidraw_report_event+0x8a/0x120 [hid] - hid_report_raw_event+0x3ea/0x440 [hid] - hid_input_report+0x112/0x190 [hid] - hid_irq_in+0xc2/0x260 [usbhid] - __usb_hcd_giveback_urb+0x72/0x120 - usb_giveback_urb_bh+0x9e/0xe0 - tasklet_hi_action+0xf8/0x100 - __do_softirq+0x114/0x2c0 - irq_exit+0xa5/0xb0 - do_IRQ+0x5a/0xf0 - ret_from_intr+0x0/0x30 - cpuidle_enter+0x17/0x20 - cpu_startup_entry+0x315/0x3e0 - rest_init+0x7c/0x80 - } hitcount: 3 bytes_req: 21 bytes_alloc: 24 - { stacktrace: - __kmalloc_track_caller+0x10b/0x1a0 - kmemdup+0x20/0x50 - hidraw_report_event+0x8a/0x120 [hid] - hid_report_raw_event+0x3ea/0x440 [hid] - hid_input_report+0x112/0x190 [hid] - hid_irq_in+0xc2/0x260 [usbhid] - __usb_hcd_giveback_urb+0x72/0x120 - usb_giveback_urb_bh+0x9e/0xe0 - tasklet_hi_action+0xf8/0x100 - __do_softirq+0x114/0x2c0 - irq_exit+0xa5/0xb0 - do_IRQ+0x5a/0xf0 - ret_from_intr+0x0/0x30 - } hitcount: 3 bytes_req: 21 bytes_alloc: 24 - { stacktrace: - kmem_cache_alloc_trace+0xeb/0x150 - aa_alloc_task_context+0x27/0x40 - apparmor_cred_prepare+0x1f/0x50 - security_prepare_creds+0x16/0x20 - prepare_creds+0xdf/0x1a0 - SyS_capset+0xb5/0x200 - system_call_fastpath+0x12/0x6a - } hitcount: 1 bytes_req: 32 bytes_alloc: 32 - . - . - . - { stacktrace: - __kmalloc+0x11b/0x1b0 - i915_gem_execbuffer2+0x6c/0x2c0 [i915] - drm_ioctl+0x349/0x670 [drm] - do_vfs_ioctl+0x2f0/0x4f0 - SyS_ioctl+0x81/0xa0 - system_call_fastpath+0x12/0x6a - } hitcount: 17726 bytes_req: 13944120 bytes_alloc: 19593808 - { stacktrace: - __kmalloc+0x11b/0x1b0 - load_elf_phdrs+0x76/0xa0 - load_elf_binary+0x102/0x1650 - search_binary_handler+0x97/0x1d0 - |