diff --git a/Documentation/trace/events.txt b/Documentation/trace/events.txt index 820bbf3b892a..e28f7f29f2b3 100644 --- a/Documentation/trace/events.txt +++ b/Documentation/trace/events.txt @@ -517,1981 +517,4 @@ triggers (you have to use '!' for each one added.) 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=[:values=] - [:sort=][:size=#entries][:pause][:continue] - [:clear][:name=histname1] [if ] - - 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 - .usecs display a $common_timestamp in microseconds - - 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::[:count] - disable_hist::[: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. - - 'special' event fields - ------------------------ - - There are a number of 'special event fields' available for use as - keys or values in a hist trigger. These look like and behave as if - they were actual event fields, but aren't really part of the event's - field definition or format file. They are however available for any - event, and can be used anywhere an actual event field could be. - 'Special' field names are always prefixed with a '$' character to - indicate that they're not normal fields (with the exception of - 'cpu', for compatibility with existing filter usage): - - $common_timestamp u64 - timestamp (from ring buffer) associated - with the event, in nanoseconds. May be - modified by .usecs to have timestamps - interpreted as microseconds. - cpu int - the cpu on which the event occurred. - - Extended error information - -------------------------- - - For some error conditions encountered when invoking a hist trigger - command, extended error information is available via the - corresponding event's 'hist' file. Reading the hist file after an - error will display more detailed information about what went wrong, - if information is available. This extended error information will - be available until the next hist trigger command for that event. - - If available for a given error condition, the extended error - information and usage takes the following form: - - # echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger - echo: write error: Invalid argument - - # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist - ERROR: Couldn't yyy: zzz - Last command: xxx - -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 - do_execveat_common.isra.34+0x551/0x6e0 - SyS_execve+0x3a/0x50 - return_from_execve+0x0/0x23 - } hitcount: 33348 bytes_req: 17152128 bytes_alloc: 20226048 - { stacktrace: - kmem_cache_alloc_trace+0xeb/0x150 - apparmor_file_alloc_security+0x27/0x40 - security_file_alloc+0x16/0x20 - get_empty_filp+0x93/0x1c0 - path_openat+0x31/0x5f0 - do_filp_open+0x3a/0x90 - do_sys_open+0x128/0x220 - SyS_open+0x1e/0x20 - system_call_fastpath+0x12/0x6a - } hitcount: 4766422 bytes_req: 9532844 bytes_alloc: 38131376 - { stacktrace: - __kmalloc+0x11b/0x1b0 - seq_buf_alloc+0x1b/0x50 - seq_read+0x2cc/0x370 - proc_reg_read+0x3d/0x80 - __vfs_read+0x28/0xe0 - vfs_read+0x86/0x140 - SyS_read+0x46/0xb0 - system_call_fastpath+0x12/0x6a - } hitcount: 19133 bytes_req: 78368768 bytes_alloc: 78368768 - - Totals: - Hits: 6085872 - Entries: 253 - Dropped: 0 - - If you key a hist trigger on common_pid, in order for example to - gather and display sorted totals for each process, you can use the - special .execname modifier to display the executable names for the - processes in the table rather than raw pids. The example below - keeps a per-process sum of total bytes read: - - # echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \ - /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger - - # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/hist - # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active] - - { common_pid: gnome-terminal [ 3196] } hitcount: 280 count: 1093512 - { common_pid: Xorg [ 1309] } hitcount: 525 count: 256640 - { common_pid: compiz [ 2889] } hitcount: 59 count: 254400 - { common_pid: bash [ 8710] } hitcount: 3 count: 66369 - { common_pid: dbus-daemon-lau [ 8703] } hitcount: 49 count: 47739 - { common_pid: irqbalance [ 1252] } hitcount: 27 count: 27648 - { common_pid: 01ifupdown [ 8705] } hitcount: 3 count: 17216 - { common_pid: dbus-daemon [ 772] } hitcount: 10 count: 12396 - { common_pid: Socket Thread [ 8342] } hitcount: 11 count: 11264 - { common_pid: nm-dhcp-client. [ 8701] } hitcount: 6 count: 7424 - { common_pid: gmain [ 1315] } hitcount: 18 count: 6336 - . - . - . - { common_pid: postgres [ 1892] } hitcount: 2 count: 32 - { common_pid: postgres [ 1891] } hitcount: 2 count: 32 - { common_pid: gmain [ 8704] } hitcount: 2 count: 32 - { common_pid: upstart-dbus-br [ 2740] } hitcount: 21 count: 21 - { common_pid: nm-dispatcher.a [ 8696] } hitcount: 1 count: 16 - { common_pid: indicator-datet [ 2904] } hitcount: 1 count: 16 - { common_pid: gdbus [ 2998] } hitcount: 1 count: 16 - { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8 - { common_pid: init [ 1] } hitcount: 2 count: 2 - - Totals: - Hits: 2116 - Entries: 51 - Dropped: 0 - - Similarly, if you key a hist trigger on syscall id, for example to - gather and display a list of systemwide syscall hits, you can use - the special .syscall modifier to display the syscall names rather - than raw ids. The example below keeps a running total of syscall - counts for the system during the run: - - # echo 'hist:key=id.syscall:val=hitcount' > \ - /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger - - # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist - # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active] - - { id: sys_fsync [ 74] } hitcount: 1 - { id: sys_newuname [ 63] } hitcount: 1 - { id: sys_prctl [157] } hitcount: 1 - { id: sys_statfs [137] } hitcount: 1 - { id: sys_symlink [ 88] } hitcount: 1 - { id: sys_sendmmsg [307] } hitcount: 1 - { id: sys_semctl [ 66] } hitcount: 1 - { id: sys_readlink [ 89] } hitcount: 3 - { id: sys_bind [ 49] } hitcount: 3 - { id: sys_getsockname [ 51] } hitcount: 3 - { id: sys_unlink [ 87] } hitcount: 3 - { id: sys_rename [ 82] } hitcount: 4 - { id: unknown_syscall [ 58] } hitcount: 4 - { id: sys_connect [ 42] } hitcount: 4 - { id: sys_getpid [ 39] } hitcount: 4 - . - . - . - { id: sys_rt_sigprocmask [ 14] } hitcount: 952 - { id: sys_futex [202] } hitcount: 1534 - { id: sys_write [ 1] } hitcount: 2689 - { id: sys_setitimer [ 38] } hitcount: 2797 - { id: sys_read [ 0] } hitcount: 3202 - { id: sys_select [ 23] } hitcount: 3773 - { id: sys_writev [ 20] } hitcount: 4531 - { id: sys_poll [ 7] } hitcount: 8314 - { id: sys_recvmsg [ 47] } hitcount: 13738 - { id: sys_ioctl [ 16] } hitcount: 21843 - - Totals: - Hits: 67612 - Entries: 72 - Dropped: 0 - - The syscall counts above provide a rough overall picture of system - call activity on the system; we can see for example that the most - popular system call on this system was the 'sys_ioctl' system call. - - We can use 'compound' keys to refine that number and provide some - further insight as to which processes exactly contribute to the - overall ioctl count. - - The command below keeps a hitcount for every unique combination of - system call id and pid - the end result is essentially a table - that keeps a per-pid sum of system call hits. The results are - sorted using the system call id as the primary key, and the - hitcount sum as the secondary key: - - # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' > \ - /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger - - # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist - # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active] - - { id: sys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: 1 - { id: sys_read [ 0], common_pid: gdbus [ 2976] } hitcount: 1 - { id: sys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: 1 - { id: sys_read [ 0], common_pid: postgres [ 1865] } hitcount: 1 - { id: sys_read [ 0], common_pid: deja-dup-monito [ 3543] } hitcount: 2 - { id: sys_read [ 0], common_pid: NetworkManager [ 890] } hitcount: 2 - { id: sys_read [ 0], common_pid: evolution-calen [ 3048] } hitcount: 2 - { id: sys_read [ 0], common_pid: postgres [ 1864] } hitcount: 2 - { id: sys_read [ 0], common_pid: nm-applet [ 3022] } hitcount: 2 - { id: sys_read [ 0], common_pid: whoopsie [ 1212] } hitcount: 2 - . - . - . - { id: sys_ioctl [ 16], common_pid: bash [ 8479] } hitcount: 1 - { id: sys_ioctl [ 16], common_pid: bash [ 3472] } hitcount: 12 - { id: sys_ioctl [ 16], common_pid: gnome-terminal [ 3199] } hitcount: 16 - { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 1808 - { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 5580 - . - . - . - { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2690] } hitcount: 3 - { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2688] } hitcount: 16 - { id: sys_inotify_add_watch [254], common_pid: gmain [ 975] } hitcount: 2 - { id: sys_inotify_add_watch [254], common_pid: gmain [ 3204] } hitcount: 4 - { id: sys_inotify_add_watch [254], common_pid: gmain [ 2888] } hitcount: 4 - { id: sys_inotify_add_watch [254], common_pid: gmain [ 3003] } hitcount: 4 - { id: sys_inotify_add_watch [254], common_pid: gmain [ 2873] } hitcount: 4 - { id: sys_inotify_add_watch [254], common_pid: gmain [ 3196] } hitcount: 6 - { id: sys_openat [257], common_pid: java [ 2623] } hitcount: 2 - { id: sys_eventfd2 [290], common_pid: ibus-ui-gtk3 [ 2760] } hitcount: 4 - { id: sys_eventfd2 [290], common_pid: compiz [ 2994] } hitcount: 6 - - Totals: - Hits: 31536 - Entries: 323 - Dropped: 0 - - The above list does give us a breakdown of the ioctl syscall by - pid, but it also gives us quite a bit more than that, which we - don't really care about at the moment. Since we know the syscall - id for sys_ioctl (16, displayed next to the sys_ioctl name), we - can use that to filter out all the other syscalls: - - # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount if id == 16' > \ - /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger - - # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist - # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 if id == 16 [active] - - { id: sys_ioctl [ 16], common_pid: gmain [ 2769] } hitcount: 1 - { id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: 1 - { id: sys_ioctl [ 16], common_pid: gmain [ 3003] } hitcount: 1 - { id: sys_ioctl [ 16], common_pid: gmain [ 2781] } hitcount: 1 - { id: sys_ioctl [ 16], common_pid: gmain [ 2829] } hitcount: 1 - { id: sys_ioctl [ 16], common_pid: bash [ 8726] } hitcount: 1 - { id: sys_ioctl [ 16], common_pid: bash [ 8508] } hitcount: 1 - { id: sys_ioctl [ 16], common_pid: gmain [ 2970] } hitcount: 1 - { id: sys_ioctl [ 16], common_pid: gmain [ 2768] } hitcount: 1 - . - . - . - { id: sys_ioctl [ 16], common_pid: pool [ 8559] } hitcount: 45 - { id: sys_ioctl [ 16], common_pid: pool [ 8555] } hitcount: 48 - { id: sys_ioctl [ 16], common_pid: pool [ 8551] } hitcount: 48 - { id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: 66 - { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 26674 - { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 73443 - - Totals: - Hits: 101162 - Entries: 103 - Dropped: 0 - - The above output shows that 'compiz' and 'Xorg' are far and away - the heaviest ioctl callers (which might lead to questions about - whether they really need to be making all those calls and to - possible avenues for further investigation.) - - The compound key examples used a key and a sum value (hitcount) to - sort the output, but we can just as easily use two keys instead. - Here's an example where we use a compound key composed of the the - common_pid and size event fields. Sorting with pid as the primary - key and 'size' as the secondary key allows us to display an - ordered summary of the recvfrom sizes, with counts, received by - each process: - - # echo 'hist:key=common_pid.execname,size:val=hitcount:sort=common_pid,size' > \ - /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/trigger - - # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/hist - # trigger info: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:size=2048 [active] - - { common_pid: smbd [ 784], size: 4 } hitcount: 1 - { common_pid: dnsmasq [ 1412], size: 4096 } hitcount: 672 - { common_pid: postgres [ 1796], size: 1000 } hitcount: 6 - { common_pid: postgres [ 1867], size: 1000 } hitcount: 10 - { common_pid: bamfdaemon [ 2787], size: 28 } hitcount: 2 - { common_pid: bamfdaemon [ 2787], size: 14360 } hitcount: 1 - { common_pid: compiz [ 2994], size: 8 } hitcount: 1 - { common_pid: compiz [ 2994], size: 20 } hitcount: 11 - { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2 - { common_pid: firefox [ 8817], size: 4 } hitcount: 1 - { common_pid: firefox [ 8817], size: 8 } hitcount: 5 - { common_pid: firefox [ 8817], size: 588 } hitcount: 2 - { common_pid: firefox [ 8817], size: 628 } hitcount: 1 - { common_pid: firefox [ 8817], size: 6944 } hitcount: 1 - { common_pid: firefox [ 8817], size: 408880 } hitcount: 2 - { common_pid: firefox [ 8822], size: 8 } hitcount: 2 - { common_pid: firefox [ 8822], size: 160 } hitcount: 2 - { common_pid: firefox [ 8822], size: 320 } hitcount: 2 - { common_pid: firefox [ 8822], size: 352 } hitcount: 1 - . - . - . - { common_pid: pool [ 8923], size: 1960 } hitcount: 10 - { common_pid: pool [ 8923], size: 2048 } hitcount: 10 - { common_pid: pool [ 8924], size: 1960 } hitcount: 10 - { common_pid: pool [ 8924], size: 2048 } hitcount: 10 - { common_pid: pool [ 8928], size: 1964 } hitcount: 4 - { common_pid: pool [ 8928], size: 1965 } hitcount: 2 - { common_pid: pool [ 8928], size: 2048 } hitcount: 6 - { common_pid: pool [ 8929], size: 1982 } hitcount: 1 - { common_pid: pool [ 8929], size: 2048 } hitcount: 1 - - Totals: - Hits: 2016 - Entries: 224 - Dropped: 0 - - The above example also illustrates the fact that although a compound - key is treated as a single entity for hashing purposes, the sub-keys - it's composed of can be accessed independently. - - The next example uses a string field as the hash key and - demonstrates how you can manually pause and continue a hist trigger. - In this example, we'll aggregate fork counts and don't expect a - large number of entries in the hash table, so we'll drop it to a - much smaller number, say 256: - - # echo 'hist:key=child_comm:val=hitcount:size=256' > \ - /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger - - # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist - # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] - - { child_comm: dconf worker } hitcount: 1 - { child_comm: ibus-daemon } hitcount: 1 - { child_comm: whoopsie } hitcount: 1 - { child_comm: smbd } hitcount: 1 - { child_comm: gdbus } hitcount: 1 - { child_comm: kthreadd } hitcount: 1 - { child_comm: dconf worker } hitcount: 1 - { child_comm: evolution-alarm } hitcount: 2 - { child_comm: Socket Thread } hitcount: 2 - { child_comm: postgres } hitcount: 2 - { child_comm: bash } hitcount: 3 - { child_comm: compiz } hitcount: 3 - { child_comm: evolution-sourc } hitcount: 4 - { child_comm: dhclient } hitcount: 4 - { child_comm: pool } hitcount: 5 - { child_comm: nm-dispatcher.a } hitcount: 8 - { child_comm: firefox } hitcount: 8 - { child_comm: dbus-daemon } hitcount: 8 - { child_comm: glib-pacrunner } hitcount: 10 - { child_comm: evolution } hitcount: 23 - - Totals: - Hits: 89 - Entries: 20 - Dropped: 0 - - If we want to pause the hist trigger, we can simply append :pause to - the command that started the trigger. Notice that the trigger info - displays as [paused]: - - # echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \ - /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger - - # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist - # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [paused] - - { child_comm: dconf worker } hitcount: 1 - { child_comm: kthreadd } hitcount: 1 - { child_comm: dconf worker } hitcount: 1 - { child_comm: gdbus } hitcount: 1 - { child_comm: ibus-daemon } hitcount: 1 - { child_comm: Socket Thread } hitcount: 2 - { child_comm: evolution-alarm } hitcount: 2 - { child_comm: smbd } hitcount: 2 - { child_comm: bash } hitcount: 3 - { child_comm: whoopsie } hitcount: 3 - { child_comm: compiz } hitcount: 3 - { child_comm: evolution-sourc } hitcount: 4 - { child_comm: pool } hitcount: 5 - { child_comm: postgres } hitcount: 6 - { child_comm: firefox } hitcount: 8 - { child_comm: dhclient } hitcount: 10 - { child_comm: emacs } hitcount: 12 - { child_comm: dbus-daemon } hitcount: 20 - { child_comm: nm-dispatcher.a } hitcount: 20 - { child_comm: evolution } hitcount: 35 - { child_comm: glib-pacrunner } hitcount: 59 - - Totals: - Hits: 199 - Entries: 21 - Dropped: 0 - - To manually continue having the trigger aggregate events, append - :cont instead. Notice that the trigger info displays as [active] - again, and the data has changed: - - # echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \ - /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger - - # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist - # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] - - { child_comm: dconf worker } hitcount: 1 - { child_comm: dconf worker } hitcount: 1 - { child_comm: kthreadd } hitcount: 1 - { child_comm: gdbus } hitcount: 1 - { child_comm: ibus-daemon } hitcount: 1 - { child_comm: Socket Thread } hitcount: 2 - { child_comm: evolution-alarm } hitcount: 2 - { child_comm: smbd } hitcount: 2 - { child_comm: whoopsie } hitcount: 3 - { child_comm: compiz } hitcount: 3 - { child_comm: evolution-sourc } hitcount: 4 - { child_comm: bash } hitcount: 5 - { child_comm: pool } hitcount: 5 - { child_comm: postgres } hitcount: 6 - { child_comm: firefox } hitcount: 8 - { child_comm: dhclient } hitcount: 11 - { child_comm: emacs } hitcount: 12 - { child_comm: dbus-daemon } hitcount: 22 - { child_comm: nm-dispatcher.a } hitcount: 22 - { child_comm: evolution } hitcount: 35 - { child_comm: glib-pacrunner } hitcount: 59 - - Totals: - Hits: 206 - Entries: 21 - Dropped: 0 - - The previous example showed how to start and stop a hist trigger by - appending 'pause' and 'continue' to the hist trigger command. A - hist trigger can also be started in a paused state by initially - starting the trigger with ':pause' appended. This allows you to - start the trigger only when you're ready to start collecting data - and not before. For example, you could start the trigger in a - paused state, then unpause it and do something you want to measure, - then pause the trigger again when done. - - Of course, doing this manually can be difficult and error-prone, but - it is possible to automatically start and stop a hist trigger based - on some condition, via the enable_hist and disable_hist triggers. - - For example, suppose we wanted to take a look at the relative - weights in terms of skb length for each callpath that leads to a - netif_receieve_skb event when downloading a decent-sized file using - wget. - - First we set up an initially paused stacktrace trigger on the - netif_receive_skb event: - - # echo 'hist:key=stacktrace:vals=len:pause' > \ - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger - - Next, we set up an 'enable_hist' trigger on the sched_process_exec - event, with an 'if filename==/usr/bin/wget' filter. The effect of - this new trigger is that it will 'unpause' the hist trigger we just - set up on netif_receive_skb if and only if it sees a - sched_process_exec event with a filename of '/usr/bin/wget'. When - that happens, all netif_receive_skb events are aggregated into a - hash table keyed on stacktrace: - - # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ - /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger - - The aggregation continues until the netif_receive_skb is paused - again, which is what the following disable_hist event does by - creating a similar setup on the sched_process_exit event, using the - filter 'comm==wget': - - # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ - /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger - - Whenever a process exits and the comm field of the disable_hist - trigger filter matches 'comm==wget', the netif_receive_skb hist - trigger is disabled. - - The overall effect is that netif_receive_skb events are aggregated - into the hash table for only the duration of the wget. Executing a - wget command and then listing the 'hist' file will display the - output generated by the wget command: - - $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz - - # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist - # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused] - - { stacktrace: - __netif_receive_skb_core+0x46d/0x990 - __netif_receive_skb+0x18/0x60 - netif_receive_skb_internal+0x23/0x90 - napi_gro_receive+0xc8/0x100 - ieee80211_deliver_skb+0xd6/0x270 [mac80211] - ieee80211_rx_handlers+0xccf/0x22f0 [mac80211] - ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211] - ieee80211_rx+0x31d/0x900 [mac80211] - iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm] - iwl_rx_dispatch+0x8e/0xf0 [iwldvm] - iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi] - irq_thread_fn+0x20/0x50 - irq_thread+0x11f/0x150 - kthread+0xd2/0xf0 - ret_from_fork+0x42/0x70 - } hitcount: 85 len: 28884 - { stacktrace: - __netif_receive_skb_core+0x46d/0x990 - __netif_receive_skb+0x18/0x60 - netif_receive_skb_internal+0x23/0x90 - napi_gro_complete+0xa4/0xe0 - dev_gro_receive+0x23a/0x360 - napi_gro_receive+0x30/0x100 - ieee80211_deliver_skb+0xd6/0x270 [mac80211] - ieee80211_rx_handlers+0xccf/0x22f0 [mac80211] - ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211] - ieee80211_rx+0x31d/0x900 [mac80211] - iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm] - iwl_rx_dispatch+0x8e/0xf0 [iwldvm] - iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi] - irq_thread_fn+0x20/0x50 - irq_thread+0x11f/0x150 - kthread+0xd2/0xf0 - } hitcount: 98 len: 664329 - { stacktrace: - __netif_receive_skb_core+0x46d/0x990 - __netif_receive_skb+0x18/0x60 - process_backlog+0xa8/0x150 - net_rx_action+0x15d/0x340 - __do_softirq+0x114/0x2c0 - do_softirq_own_stack+0x1c/0x30 - do_softirq+0x65/0x70 - __local_bh_enable_ip+0xb5/0xc0 - ip_finish_output+0x1f4/0x840 - ip_output+0x6b/0xc0 - ip_local_out_sk+0x31/0x40 - ip_send_skb+0x1a/0x50 - udp_send_skb+0x173/0x2a0 - udp_sendmsg+0x2bf/0x9f0 - inet_sendmsg+0x64/0xa0 - sock_sendmsg+0x3d/0x50 - } hitcount: 115 len: 13030 - { stacktrace: - __netif_receive_skb_core+0x46d/0x990 - __netif_receive_skb+0x18/0x60 - netif_receive_skb_internal+0x23/0x90 - napi_gro_complete+0xa4/0xe0 - napi_gro_flush+0x6d/0x90 - iwl_pcie_irq_handler+0x92a/0x12f0 [iwlwifi] - irq_thread_fn+0x20/0x50 - irq_thread+0x11f/0x150 - kthread+0xd2/0xf0 - ret_from_fork+0x42/0x70 - } hitcount: 934 len: 5512212 - - Totals: - Hits: 1232 - Entries: 4 - Dropped: 0 - - The above shows all the netif_receive_skb callpaths and their total - lengths for the duration of the wget command. - - The 'clear' hist trigger param can be used to clear the hash table. - Suppose we wanted to try another run of the previous example but - this time also wanted to see the complete list of events that went - into the histogram. In order to avoid having to set everything up - again, we can just clear the histogram first: - - # echo 'hist:key=stacktrace:vals=len:clear' >> \ - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger - - Just to verify that it is in fact cleared, here's what we now see in - the hist file: - - # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist - # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused] - - Totals: - Hits: 0 - Entries: 0 - Dropped: 0 - - Since we want to see the detailed list of every netif_receive_skb - event occurring during the new run, which are in fact the same - events being aggregated into the hash table, we add some additional - 'enable_event' events to the triggering sched_process_exec and - sched_process_exit events as such: - - # echo 'enable_event:net:netif_receive_skb if filename==/usr/bin/wget' > \ - /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger - - # echo 'disable_event:net:netif_receive_skb if comm==wget' > \ - /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger - - If you read the trigger files for the sched_process_exec and - sched_process_exit triggers, you should see two triggers for each: - one enabling/disabling the hist aggregation and the other - enabling/disabling the logging of events: - - # cat /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger - enable_event:net:netif_receive_skb:unlimited if filename==/usr/bin/wget - enable_hist:net:netif_receive_skb:unlimited if filename==/usr/bin/wget - - # cat /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger - enable_event:net:netif_receive_skb:unlimited if comm==wget - disable_hist:net:netif_receive_skb:unlimited if comm==wget - - In other words, whenever either of the sched_process_exec or - sched_process_exit events is hit and matches 'wget', it enables or - disables both the histogram and the event log, and what you end up - with is a hash table and set of events just covering the specified - duration. Run the wget command again: - - $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz - - Displaying the 'hist' file should show something similar to what you - saw in the last run, but this time you should also see the - individual events in the trace file: - - # cat /sys/kernel/debug/tracing/trace - - # tracer: nop - # - # entries-in-buffer/entries-written: 183/1426 #P:4 - # - # _-----=> irqs-off - # / _----=> need-resched - # | / _---=> hardirq/softirq - # || / _--=> preempt-depth - # ||| / delay - # TASK-PID CPU# |||| TIMESTAMP FUNCTION - # | | | |||| | | - wget-15108 [000] ..s1 31769.606929: netif_receive_skb: dev=lo skbaddr=ffff88009c353100 len=60 - wget-15108 [000] ..s1 31769.606999: netif_receive_skb: dev=lo skbaddr=ffff88009c353200 len=60 - dnsmasq-1382 [000] ..s1 31769.677652: netif_receive_skb: dev=lo skbaddr=ffff88009c352b00 len=130 - dnsmasq-1382 [000] ..s1 31769.685917: netif_receive_skb: dev=lo skbaddr=ffff88009c352200 len=138 - ##### CPU 2 buffer started #### - irq/29-iwlwifi-559 [002] ..s. 31772.031529: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433d00 len=2948 - irq/29-iwlwifi-559 [002] ..s. 31772.031572: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432200 len=1500 - irq/29-iwlwifi-559 [002] ..s. 31772.032196: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433100 len=2948 - irq/29-iwlwifi-559 [002] ..s. 31772.032761: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433000 len=2948 - irq/29-iwlwifi-559 [002] ..s. 31772.033220: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432e00 len=1500 - . - . - . - - The following example demonstrates how multiple hist triggers can be - attached to a given event. This capability can be useful for - creating a set of different summaries derived from the same set of - events, or for comparing the effects of different filters, among - other things. - - # echo 'hist:keys=skbaddr.hex:vals=len if len < 0' >> \ - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger - # echo 'hist:keys=skbaddr.hex:vals=len if len > 4096' >> \ - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger - # echo 'hist:keys=skbaddr.hex:vals=len if len == 256' >> \ - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger - # echo 'hist:keys=skbaddr.hex:vals=len' >> \ - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger - # echo 'hist:keys=len:vals=common_preempt_count' >> \ - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger - - The above set of commands create four triggers differing only in - their filters, along with a completely different though fairly - nonsensical trigger. Note that in order to append multiple hist - triggers to the same file, you should use the '>>' operator to - append them ('>' will also add the new hist trigger, but will remove - any existing hist triggers beforehand). - - Displaying the contents of the 'hist' file for the event shows the - contents of all five histograms: - - # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist - - # event histogram - # - # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active] - # - - { len: 176 } hitcount: 1 common_preempt_count: 0 - { len: 223 } hitcount: 1 common_preempt_count: 0 - { len: 4854 } hitcount: 1 common_preempt_count: 0 - { len: 395 } hitcount: 1 common_preempt_count: 0 - { len: 177 } hitcount: 1 common_preempt_count: 0 - { len: 446 } hitcount: 1 common_preempt_count: 0 - { len: 1601 } hitcount: 1 common_preempt_count: 0 - . - . - . - { len: 1280 } hitcount: 66 common_preempt_count: 0 - { len: 116 } hitcount: 81 common_preempt_count: 40 - { len: 708 } hitcount: 112 common_preempt_count: 0 - { len: 46 } hitcount: 221 common_preempt_count: 0 - { len: 1264 } hitcount: 458 common_preempt_count: 0 - - Totals: - Hits: 1428 - Entries: 147 - Dropped: 0 - - - # event histogram - # - # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] - # - - { skbaddr: ffff8800baee5e00 } hitcount: 1 len: 130 - { skbaddr: ffff88005f3d5600 } hitcount: 1 len: 1280 - { skbaddr: ffff88005f3d4900 } hitcount: 1 len: 1280 - { skbaddr: ffff88009fed6300 } hitcount: 1 len: 115 - { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 115 - { skbaddr: ffff88008cdb1900 } hitcount: 1 len: 46 - { skbaddr: ffff880064b5ef00 } hitcount: 1 len: 118 - { skbaddr: ffff880044e3c700 } hitcount: 1 len: 60 - { skbaddr: ffff880100065900 } hitcount: 1 len: 46 - { skbaddr: ffff8800d46bd500 } hitcount: 1 len: 116 - { skbaddr: ffff88005f3d5f00 } hitcount: 1 len: 1280 - { skbaddr: ffff880100064700 } hitcount: 1 len: 365 - { skbaddr: ffff8800badb6f00 } hitcount: 1 len: 60 - . - . - . - { skbaddr: ffff88009fe0be00 } hitcount: 27 len: 24677 - { skbaddr: ffff88009fe0a400 } hitcount: 27 len: 23052 - { skbaddr: ffff88009fe0b700 } hitcount: 31 len: 25589 - { skbaddr: ffff88009fe0b600 } hitcount: 32 len: 27326 - { skbaddr: ffff88006a462800 } hitcount: 68 len: 71678 - { skbaddr: ffff88006a463700 } hitcount: 70 len: 72678 - { skbaddr: ffff88006a462b00 } hitcount: 71 len: 77589 - { skbaddr: ffff88006a463600 } hitcount: 73 len: 71307 - { skbaddr: ffff88006a462200 } hitcount: 81 len: 81032 - - Totals: - Hits: 1451 - Entries: 318 - Dropped: 0 - - - # event histogram - # - # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [active] - # - - - Totals: - Hits: 0 - Entries: 0 - Dropped: 0 - - - # event histogram - # - # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [active] - # - - { skbaddr: ffff88009fd2c300 } hitcount: 1 len: 7212 - { skbaddr: ffff8800d2bcce00 } hitcount: 1 len: 7212 - { skbaddr: ffff8800d2bcd700 } hitcount: 1 len: 7212 - { skbaddr: ffff8800d2bcda00 } hitcount: 1 len: 21492 - { skbaddr: ffff8800ae2e2d00 } hitcount: 1 len: 7212 - { skbaddr: ffff8800d2bcdb00 } hitcount: 1 len: 7212 - { skbaddr: ffff88006a4df500 } hitcount: 1 len: 4854 - { skbaddr: ffff88008ce47b00 } hitcount: 1 len: 18636 - { skbaddr: ffff8800ae2e2200 } hitcount: 1 len: 12924 - { skbaddr: ffff88005f3e1000 } hitcount: 1 len: 4356 - { skbaddr: ffff8800d2bcdc00 } hitcount: 2 len: 24420 - { skbaddr: ffff8800d2bcc200 } hitcount: 2 len: 12996 - - Totals: - Hits: 14 - Entries: 12 - Dropped: 0 - - - # event histogram - # - # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active] - # - - - Totals: - Hits: 0 - Entries: 0 - Dropped: 0 - - Named triggers can be used to have triggers share a common set of - histogram data. This capability is mostly useful for combining the - output of events generated by tracepoints contained inside inline - functions, but names can be used in a hist trigger on any event. - For example, these two triggers when hit will update the same 'len' - field in the shared 'foo' histogram data: - - # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ - /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger - # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ - /sys/kernel/debug/tracing/events/net/netif_rx/trigger - - You can see that they're updating common histogram data by reading - each event's hist files at the same time: - - # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist; - cat /sys/kernel/debug/tracing/events/net/netif_rx/hist - - # event histogram - # - # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] - # - - { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46 - { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76 - { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46 - { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468 - { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46 - { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52 - { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168 - { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46 - { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260 - { skbaddr: ffff880064505000 } hitcount: 1 len: 46 - { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32 - { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46 - { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44 - { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168 - { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40 - { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40 - { skbaddr: ffff880064505f00 } hitcount: 1 len: 174 - { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160 - { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76 - { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46 - { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32 - { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46 - { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988 - { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46 - { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44 - { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676 - { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107 - { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92 - { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142 - { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220 - { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92 - { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92 - { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675 - { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138 - { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138 - { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184 - { skbaddr: ffff880064504400 } hitcount: 4 len: 184 - { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184 - { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230 - { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196 - { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276 - { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276 - - Totals: - Hits: 81 - Entries: 42 - Dropped: 0 - # event histogram - # - # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] - # - - { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46 - { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76 - { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46 - { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468 - { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46 - { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52 - { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168 - { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46 - { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260 - { skbaddr: ffff880064505000 } hitcount: 1 len: 46 - { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32 - { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46 - { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44 - { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168 - { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40 - { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40 - { skbaddr: ffff880064505f00 } hitcount: 1 len: 174 - { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160 - { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76 - { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46 - { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32 - { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46 - { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988 - { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46 - { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44 - { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676 - { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107 - { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92 - { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142 - { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220 - { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92 - { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92 - { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675 - { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138 - { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138 - { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184 - { skbaddr: ffff880064504400 } hitcount: 4 len: 184 - { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184 - { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230 - { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196 - { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276 - { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276 - - Totals: - Hits: 81 - Entries: 42 - Dropped: 0 - - And here's an example that shows how to combine histogram data from - any two events even if they don't share any 'compatible' fields - other than 'hitcount' and 'stacktrace'. These commands create a - couple of triggers named 'bar' using those fields: - - # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \ - /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger - # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \ - /sys/kernel/debug/tracing/events/net/netif_rx/trigger - - And displaying the output of either shows some interesting if - somewhat confusing output: - - # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist - # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist - - # event histogram - # - # trigger info: hist:name=bar:keys=stacktrace:vals=hitcount:sort=hitcount:size=2048 [active] - # - - { stacktrace: - _do_fork+0x18e/0x330 - kernel_thread+0x29/0x30 - kthreadd+0x154/0x1b0 - ret_from_fork+0x3f/0x70 - } hitcount: 1 - { stacktrace: - netif_rx_internal+0xb2/0xd0 - netif_rx_ni+0x20/0x70 - dev_loopback_xmit+0xaa/0xd0 - ip_mc_output+0x126/0x240 - ip_local_out_sk+0x31/0x40 - igmp_send_report+0x1e9/0x230 - igmp_timer_expire+0xe9/0x120 - call_timer_fn+0x39/0xf0 - run_timer_softirq+0x1e1/0x290 - __do_softirq+0xfd/0x290 - irq_exit+0x98/0xb0 - smp_apic_timer_interrupt+0x4a/0x60 - apic_timer_interrupt+0x6d/0x80 - cpuidle_enter+0x17/0x20 - call_cpuidle+0x3b/0x60 - cpu_startup_entry+0x22d/0x310 - } hitcount: 1 - { stacktrace: - netif_rx_internal+0xb2/0xd0 - netif_rx_ni+0x20/0x70 - dev_loopback_xmit+0xaa/0xd0 - ip_mc_output+0x17f/0x240 - ip_local_out_sk+0x31/0x40 - ip_send_skb+0x1a/0x50 - udp_send_skb+0x13e/0x270 - udp_sendmsg+0x2bf/0x980 - inet_sendmsg+0x67/0xa0 - sock_sendmsg+0x38/0x50 - SYSC_sendto+0xef/0x170 - SyS_sendto+0xe/0x10 - entry_SYSCALL_64_fastpath+0x12/0x6a - } hitcount: 2 - { stacktrace: - netif_rx_internal+0xb2/0xd0 - netif_rx+0x1c/0x60 - loopback_xmit+0x6c/0xb0 - dev_hard_start_xmit+0x219/0x3a0 - __dev_queue_xmit+0x415/0x4f0 - dev_queue_xmit_sk+0x13/0x20 - ip_finish_output2+0x237/0x340 - ip_finish_output+0x113/0x1d0 - ip_output+0x66/0xc0 - ip_local_out_sk+0x31/0x40 - ip_send_skb+0x1a/0x50 - udp_send_skb+0x16d/0x270 - udp_sendmsg+0x2bf/0x980 - inet_sendmsg+0x67/0xa0 - sock_sendmsg+0x38/0x50 - ___sys_sendmsg+0x14e/0x270 - } hitcount: 76 - { stacktrace: - netif_rx_internal+0xb2/0xd0 - netif_rx+0x1c/0x60 - loopback_xmit+0x6c/0xb0 - dev_hard_start_xmit+0x219/0x3a0 - __dev_queue_xmit+0x415/0x4f0 - dev_queue_xmit_sk+0x13/0x20 - ip_finish_output2+0x237/0x340 - ip_finish_output+0x113/0x1d0 - ip_output+0x66/0xc0 - ip_local_out_sk+0x31/0x40 - ip_send_skb+0x1a/0x50 - udp_send_skb+0x16d/0x270 - udp_sendmsg+0x2bf/0x980 - inet_sendmsg+0x67/0xa0 - sock_sendmsg+0x38/0x50 - ___sys_sendmsg+0x269/0x270 - } hitcount: 77 - { stacktrace: - netif_rx_internal+0xb2/0xd0 - netif_rx+0x1c/0x60 - loopback_xmit+0x6c/0xb0 - dev_hard_start_xmit+0x219/0x3a0 - __dev_queue_xmit+0x415/0x4f0 - dev_queue_xmit_sk+0x13/0x20 - ip_finish_output2+0x237/0x340 - ip_finish_output+0x113/0x1d0 - ip_output+0x66/0xc0 - ip_local_out_sk+0x31/0x40 - ip_send_skb+0x1a/0x50 - udp_send_skb+0x16d/0x270 - udp_sendmsg+0x2bf/0x980 - inet_sendmsg+0x67/0xa0 - sock_sendmsg+0x38/0x50 - SYSC_sendto+0xef/0x170 - } hitcount: 88 - { stacktrace: - _do_fork+0x18e/0x330 - SyS_clone+0x19/0x20 - entry_SYSCALL_64_fastpath+0x12/0x6a - } hitcount: 244 - - Totals: - Hits: 489 - Entries: 7 - Dropped: 0 - -6.3 Inter-event hist triggers ------------------------------ - -Inter-event hist triggers are hist triggers that combine values from -one or more other events and create a histogram using that data. Data -from an inter-event histogram can in turn become the source for -further combined histograms, thus providing a chain of related -histograms, which is important for some applications. - -The most important example of an inter-event quantity that can be used -in this manner is latency, which is simply a difference in timestamps -between two events (although trace events don't have an externally -visible timestamp field, the inter-event hist trigger support adds a -pseudo-field to all events named '$common_timestamp' which can be used -as if it were an actual event field). Although latency is the most -important inter-event quantity, note that because the support is -completely general across the trace event subsystem, any event field -can be used in an inter-event quantity. - -An example of a histogram that combines data from other histograms -into a useful chain would be a 'wakeupswitch latency' histogram that -combines a 'wakeup latency' histogram and a 'switch latency' -histogram. - -Normally, a hist trigger specification consists of a (possibly -compound) key along with one or more numeric values, which are -continually updated sums associated with that key. A histogram -specification in this case consists of individual key and value -specifications that refer to trace event fields associated with a -single event type. - -The inter-event hist trigger extension allows fields from multiple -events to be referenced and combined into a multi-event histogram -specification. In support of this overall goal, a few enabling -features have been added to the hist trigger support: - - - In order to compute an inter-event quantity, a value from one - event needs to saved and then referenced from another event. This - requires the introduction of support for histogram 'variables'. - - - The computation of inter-event quantities and their combination - require some minimal amount of support for applying simple - expressions to variables (+ and -). - - - A histogram consisting of inter-event quantities isn't logically a - histogram on either event (so having the 'hist' file for either - event host the histogram output doesn't really make sense). To - address the idea that the histogram is associated with a - combination of events, support is added allowing the creation of - 'synthetic' events that are events derived from other events. - These synthetic events are full-fledged events just like any other - and can be used as such, as for instance to create the - 'combination' histograms mentioned previously. - - - A set of 'actions' can be associated with histogram entries - - these can be used to generate the previously mentioned synthetic - events, but can also be used for other purposes, such as for - example saving context when a 'max' latency has been hit. - - - Trace events don't have a 'timestamp' associated with them, but - there is an implicit timestamp saved along with an event in the - underlying ftrace ring buffer. This timestamp is now exposed as a - a synthetic field named '$common_timestamp' which can be used in - histograms as if it were any other event field. Note that it has - a '$' prefixed to it - this is meant to indicate that it isn't an - actual field in the trace format but rather is a synthesized value - that nonetheless can be used as if it were an actual field. By - default it is in units of nanoseconds; appending '.usecs' to a - common_timestamp field changes the units to microseconds. - -A note on inter-event timestamps: If $common_timestamp is used in a -histogram, the trace buffer is automatically switched over to using -absolute timestamps and the "global" trace clock, in order to avoid -bogus timestamp differences with other clocks that aren't coherent -across CPUs. This can be overridden by specifying one of the other -trace clocks instead, using the "clock=XXX" hist trigger attribute, -where XXX is any of the clocks listed in the tracing/trace_clock -pseudo-file. - -These features are decribed in more detail in the following sections. - -6.3.1 Histogram Variables -------------------------- - -Variables are simply named locations used for saving and retrieving -values between matching events. A 'matching' event is defined as an -event that has a matching key - if a variable is saved for a histogram -entry corresponding to that key, any subsequent event with a matching -key can access that variable. - -A variable's value is normally available to any subsequent event until -it is set to something else by a subsequent event. The one exception -to that rule is that any variable used in an expression is essentially -'read-once' - once it's used by an expression in a subsequent event, -it's reset to its 'unset' state, which means it can't be used again -unless it's set again. This ensures not only that an event doesn't -use an uninitialized variable in a calculation, but that that variable -is used only once and not for any unrelated subsequent match. - -The basic syntax for saving a variable is to simply prefix a unique -variable name not corresponding to any keyword along with an '=' sign -to any event field. - -Either keys or values can be saved and retrieved in this way. This -creates a variable named 'ts0' for a histogram entry with the key -'next_pid': - - # echo 'hist:keys=next_pid:vals=$ts0:ts0=$common_timestamp ... >> \ - event/trigger - -The ts0 variable can be accessed by any subsequent event having the -same pid as 'next_pid'. - -Variable references are formed by prepending the variable name with -the '$' sign. Thus for example, the ts0 variable above would be -referenced as '$ts0' in expressions. - -Because 'vals=' is used, the $common_timestamp variable value above -will also be summed as a normal histogram value would (though for a -timestamp it makes little sense). - -The below shows that a key value can also be saved in the same way: - - # echo 'hist:timer_pid=common_pid:key=timer_pid ...' >> event/trigger - -If a variable isn't a key variable or prefixed with 'vals=', the -associated event field will be saved in a variable but won't be summed -as a value: - - # echo 'hist:keys=next_pid:ts1=$common_timestamp ... >> event/trigger - -Multiple variables can be assigned at the same time. The below would -result in both ts0 and b being created as variables, with both -common_timestamp and field1 additionally being summed as values: - - # echo 'hist:keys=pid:vals=$ts0,$b:ts0=$common_timestamp,b=field1 ... >> \ - event/trigger - -Note that variable assignments can appear either preceding or -following their use. The command below behaves identically to the -command above: - - # echo 'hist:keys=pid:ts0=$common_timestamp,b=field1:vals=$ts0,$b ... >> \ - event/trigger - -Any number of variables not bound to a 'vals=' prefix can also be -assigned by simply separating them with colons. Below is the same -thing but without the values being summed in the histogram: - - # echo 'hist:keys=pid:ts0=$common_timestamp:b=field1 ... >> event/trigger - -Variables set as above can be referenced and used in expressions on -another event. - -For example, here's how a latency can be calculated: - - # echo 'hist:keys=pid,prio:ts0=$common_timestamp ... >> event1/trigger - # echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp-$ts0 ... >> event2/trigger - -In the first line above, the event's timetamp is saved into the -variable ts0. In the next line, ts0 is subtracted from the second -event's timestamp to produce the latency, which is then assigned into -yet another variable, 'wakeup_lat'. The hist trigger below in turn -makes use of the wakeup_lat variable to compute a combined latency -using the same key and variable from yet another event: - - # echo 'hist:key=pid:wakeupswitch_lat=$wakeup_lat+$switchtime_lat ... >> event3/trigger - -6.3.2 Synthetic Events ----------------------- - -Synthetic events are user-defined events generated from hist trigger -variables or fields associated with one or more other events. Their -purpose is to provide a mechanism for displaying data spanning -multiple events consistent with the existing and already familiar -usage for normal events. - -To define a synthetic event, the user writes a simple specification -consisting of the name of the new event along with one or more -variables and their types, which can be any valid field type, -separated by semicolons, to the tracing/synthetic_events file. - -For instance, the following creates a new event named 'wakeup_latency' -with 3 fields: lat, pid, and prio. Each of those fields is simply a -variable reference to a variable on another event: - - # echo 'wakeup_latency \ - u64 lat; \ - pid_t pid; \ - int prio' >> \ - /sys/kernel/debug/tracing/synthetic_events - -Reading the tracing/synthetic_events file lists all the currently -defined synthetic events, in this case the event defined above: - - # cat /sys/kernel/debug/tracing/synthetic_events - wakeup_latency u64 lat; pid_t pid; int prio - -An existing synthetic event definition can be removed by prepending -the command that defined it with a '!': - - # echo '!wakeup_latency u64 lat pid_t pid int prio' >> \ - /sys/kernel/debug/tracing/synthetic_events - -At this point, there isn't yet an actual 'wakeup_latency' event -instantiated in the event subsytem - for this to happen, a 'hist -trigger action' needs to be instantiated and bound to actual fields -and variables defined on other events (see Section 6.3.3 below). - -Once that is done, an event instance is created, and a histogram can -be defined using it: - - # echo 'hist:keys=pid,prio,lat.log2:sort=pid,lat' >> \ - /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger - -The new event is created under the tracing/events/synthetic/ directory -and looks and behaves just like any other event: - - # ls /sys/kernel/debug/tracing/events/synthetic/wakeup_latency - enable filter format hist id trigger - -Like any other event, once a histogram is enabled for the event, the -output can be displayed by reading the event's 'hist' file. - -6.3.3 Hist trigger 'actions' ----------------------------- - -A hist trigger 'action' is a function that's executed whenever a -histogram entry is added or updated. - -The default 'action' if no special function is explicity specified is -as it always has been, to simply update the set of values associated -with an entry. Some applications, however, may want to perform -additional actions at that point, such as generate another event, or -compare and save a maximum. - -The following additional actions are available. To specify an action -for a given event, simply specify the action between colons in the -hist trigger specification. - - - onmatch(matching.event).(param list) - - The 'onmatch(matching.event).(params)' hist - trigger action is invoked whenever an event matches and the - histogram entry would be added or updated. It causes the named - synthetic event to be generated with the values given in the - 'param list'. The result is the generation of a synthetic event - that consists of the values contained in those variables at the - time the invoking event was hit. - - The 'param list' consists of one or more parameters which may be - either variables or fields defined on either the 'matching.event' - or the target event. The variables or fields specified in the - param list may be either fully-qualified or unqualified. If a - variable is specified as unqualified, it must be unique between - the two events. A field name used as a param can be unqualified - if it refers to the target event, but must be fully qualified if - it refers to the matching event. A fully-qualified name is of the - form 'system.event_name.$var_name' or 'system.event_name.field'. - - The 'matching.event' specification is simply the fully qualified - event name of the event that matches the target event for the - onmatch() functionality, in the form 'system.event_name'. - - Finally, the number and type of variables/fields in the 'param - list' must match the number and types of the fields in the - synthetic event being generated. - - As an example the below defines a simple synthetic event and uses - a variable defined on the sched_wakeup_new event as a parameter - when invoking the synthetic event. Here we define the synthetic - event: - - # echo 'wakeup_new_test pid_t pid' >> \ - /sys/kernel/debug/tracing/synthetic_events - - # cat /sys/kernel/debug/tracing/synthetic_events - wakeup_new_test pid_t pid - - The following hist trigger both defines the missing testpid - variable and specifies an onmatch() action that generates a - wakeup_new_test synthetic event whenever a sched_wakeup_new event - occurs, which because of the 'if comm == "cyclictest"' filter only - happens when the executable is cyclictest: - - # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\ - wakeup_new_test($testpid) if comm=="cyclictest"' >> \ - /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger - - Creating and displaying a histogram based on those events is now - just a matter of using the fields and new synthetic event in the - tracing/events/synthetic directory, as usual: - - # echo 'hist:keys=pid:sort=pid' >> \ - /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/trigger - - Running 'cyclictest' should cause wakeup_new events to generate - wakeup_new_test synthetic events which should result in histogram - output in the wakeup_new_test event's hist file: - - # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/hist - - A more typical usage would be to use two events to calculate a - latency. The following example uses a set of hist triggers to - produce a 'wakeup_latency' histogram: - - First, we define a 'wakeup_latency' synthetic event: - - # echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> \ - /sys/kernel/debug/tracing/synthetic_events - - Next, we specify that whenever we see a sched_waking event for a - cyclictest thread, save the timestamp in a 'ts0' variable: - - # echo 'hist:keys=$saved_pid:saved_pid=pid:ts0=$common_timestamp.usecs \ - if comm=="cyclictest"' >> \ - /sys/kernel/debug/tracing/events/sched/sched_waking/trigger - - Then, when the corresponding thread is actually scheduled onto the - CPU by a sched_switch event, calculate the latency and use that - along with another variable and an event field to generate a - wakeup_latency synthetic event: - - # echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts0:\ - onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,\ - $saved_pid,next_prio) if next_comm=="cyclictest"' >> \ - /sys/kernel/debug/tracing/events/sched/sched_switch/trigger - - We also need to create a histogram on the wakeup_latency synthetic - event in order to aggregate the generated synthetic event data: - - # echo 'hist:keys=pid,prio,lat:sort=pid,lat' >> \ - /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger - - Finally, once we've run cyclictest to actually generate some - events, we can see the output by looking at the wakeup_latency - synthetic event's hist file: - - # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist - - - onmax(var).save(field,.. .) - - The 'onmax(var).save(field,...)' hist trigger action is invoked - whenever the value of 'var' associated with a histogram entry - exceeds the current maximum contained in that variable. - - The end result is that the trace event fields specified as the - onmax.save() params will be saved if 'var' exceeds the current - maximum for that hist trigger entry. This allows context from the - event that exhibited the new maximum to be saved for later - reference. When the histogram is displayed, additional fields - displaying the saved values will be printed. - - As an example the below defines a couple of hist triggers, one for - sched_waking and another for sched_switch, keyed on pid. Whenever - a sched_waking occurs, the timestamp is saved in the entry - corresponding to the current pid, and when the scheduler switches - back to that pid, the timestamp difference is calculated. If the - resulting latency, stored in wakeup_lat, exceeds the current - maximum latency, the values specified in the save() fields are - recoreded: - - # echo 'hist:keys=pid:ts0=$common_timestamp.usecs \ - if comm=="cyclictest"' >> \ - /sys/kernel/debug/tracing/events/sched/sched_waking/trigger - - # echo 'hist:keys=next_pid:\ - wakeup_lat=$common_timestamp.usecs-$ts0:\ - onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) \ - if next_comm=="cyclictest"' >> \ - /sys/kernel/debug/tracing/events/sched/sched_switch/trigger - - When the histogram is displayed, the max value and the saved - values corresponding to the max are displayed following the rest - of the fields: - - # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist - { next_pid: 2255 } hitcount: 239 - common_timestamp-ts0: 0 - max: 27 - next_comm: cyclictest - prev_pid: 0 prev_prio: 120 prev_comm: swapper/1 - - { next_pid: 2256 } hitcount: 2355 - common_timestamp-ts0: 0 - max: 49 next_comm: cyclictest - prev_pid: 0 prev_prio: 120 prev_comm: swapper/0 - - Totals: - Hits: 12970 - Entries: 2 - Dropped: 0 + See Documentation/trace/histogram.txt for details and examples. diff --git a/Documentation/trace/ftrace.txt b/Documentation/trace/ftrace.txt index d4601df6e72e..54213e5c23f6 100644 --- a/Documentation/trace/ftrace.txt +++ b/Documentation/trace/ftrace.txt @@ -539,6 +539,30 @@ After mounting tracefs you will have access to the control and output files See events.txt for more information. + timestamp_mode: + + Certain tracers may change the timestamp mode used when + logging trace events into the event buffer. Events with + different modes can coexist within a buffer but the mode in + effect when an event is logged determines which timestamp mode + is used for that event. The default timestamp mode is + 'delta'. + + Usual timestamp modes for tracing: + + # cat timestamp_mode + [delta] absolute + + The timestamp mode with the square brackets around it is the + one in effect. + + delta: Default timestamp mode - timestamp is a delta against + a per-buffer timestamp. + + absolute: The timestamp is a full timestamp, not a delta + against some other value. As such it takes up more + space and is less efficient. + hwlat_detector: Directory for the Hardware Latency Detector. diff --git a/Documentation/trace/histogram.txt b/Documentation/trace/histogram.txt new file mode 100644 index 000000000000..aa450bbebf1f --- /dev/null +++ b/Documentation/trace/histogram.txt @@ -0,0 +1,1998 @@ + Event Histograms + + Documentation written by Tom Zanussi + +1. Introduction +=============== + + Histogram triggers are special event triggers that can be used to + aggregate trace event data into histograms. For information on + trace events and event triggers, see Documentation/trace/events.txt. + + +2. Histogram Trigger Command +============================ + + A histogram trigger command is an event trigger command that + aggregates event hits into a hash table keyed on one or more trace + event format fields (or stacktrace) and a set of running 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=[:values=] + [:sort=][:size=#entries][:pause][:continue] + [:clear][:name=histname1] [if ] + + 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 + .log2 display log2 value rather than raw number + .usecs display a $common_timestamp in microseconds + + 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::[:count] + disable_hist::[: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. + + 'special' event fields + ------------------------ + + There are a number of 'special event fields' available for use as + keys or values in a hist trigger. These look like and behave as if + they were actual event fields, but aren't really part of the event's + field definition or format file. They are however available for any + event, and can be used anywhere an actual event field could be. + 'Special' field names are always prefixed with a '$' character to + indicate that they're not normal fields (with the exception of + 'cpu', for compatibility with existing filter usage): + + $common_timestamp u64 - timestamp (from ring buffer) associated + with the event, in nanoseconds. May be + modified by .usecs to have timestamps + interpreted as microseconds. + cpu int - the cpu on which the event occurred. + + Extended error information + -------------------------- + + For some error conditions encountered when invoking a hist trigger + command, extended error information is available via the + corresponding event's 'hist' file. Reading the hist file after an + error will display more detailed information about what went wrong, + if information is available. This extended error information will + be available until the next hist trigger command for that event. + + If available for a given error condition, the extended error + information and usage takes the following form: + + # echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger + echo: write error: Invalid argument + + # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist + ERROR: Couldn't yyy: zzz + Last command: xxx + +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 + do_execveat_common.isra.34+0x551/0x6e0 + SyS_execve+0x3a/0x50 + return_from_execve+0x0/0x23 + } hitcount: 33348 bytes_req: 17152128 bytes_alloc: 20226048 + { stacktrace: + kmem_cache_alloc_trace+0xeb/0x150 + apparmor_file_alloc_security+0x27/0x40 + security_file_alloc+0x16/0x20 + get_empty_filp+0x93/0x1c0 + path_openat+0x31/0x5f0 + do_filp_open+0x3a/0x90 + do_sys_open+0x128/0x220 + SyS_open+0x1e/0x20 + system_call_fastpath+0x12/0x6a + } hitcount: 4766422 bytes_req: 9532844 bytes_alloc: 38131376 + { stacktrace: + __kmalloc+0x11b/0x1b0 + seq_buf_alloc+0x1b/0x50 + seq_read+0x2cc/0x370 + proc_reg_read+0x3d/0x80 + __vfs_read+0x28/0xe0 + vfs_read+0x86/0x140 + SyS_read+0x46/0xb0 + system_call_fastpath+0x12/0x6a + } hitcount: 19133 bytes_req: 78368768 bytes_alloc: 78368768 + + Totals: + Hits: 6085872 + Entries: 253 + Dropped: 0 + + If you key a hist trigger on common_pid, in order for example to + gather and display sorted totals for each process, you can use the + special .execname modifier to display the executable names for the + processes in the table rather than raw pids. The example below + keeps a per-process sum of total bytes read: + + # echo 'hist:key=common_pid.execname:val=count:sort=count.descending' > \ + /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger + + # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/hist + # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active] + + { common_pid: gnome-terminal [ 3196] } hitcount: 280 count: 1093512 + { common_pid: Xorg [ 1309] } hitcount: 525 count: 256640 + { common_pid: compiz [ 2889] } hitcount: 59 count: 254400 + { common_pid: bash [ 8710] } hitcount: 3 count: 66369 + { common_pid: dbus-daemon-lau [ 8703] } hitcount: 49 count: 47739 + { common_pid: irqbalance [ 1252] } hitcount: 27 count: 27648 + { common_pid: 01ifupdown [ 8705] } hitcount: 3 count: 17216 + { common_pid: dbus-daemon [ 772] } hitcount: 10 count: 12396 + { common_pid: Socket Thread [ 8342] } hitcount: 11 count: 11264 + { common_pid: nm-dhcp-client. [ 8701] } hitcount: 6 count: 7424 + { common_pid: gmain [ 1315] } hitcount: 18 count: 6336 + . + . + . + { common_pid: postgres [ 1892] } hitcount: 2 count: 32 + { common_pid: postgres [ 1891] } hitcount: 2 count: 32 + { common_pid: gmain [ 8704] } hitcount: 2 count: 32 + { common_pid: upstart-dbus-br [ 2740] } hitcount: 21 count: 21 + { common_pid: nm-dispatcher.a [ 8696] } hitcount: 1 count: 16 + { common_pid: indicator-datet [ 2904] } hitcount: 1 count: 16 + { common_pid: gdbus [ 2998] } hitcount: 1 count: 16 + { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8 + { common_pid: init [ 1] } hitcount: 2 count: 2 + + Totals: + Hits: 2116 + Entries: 51 + Dropped: 0 + + Similarly, if you key a hist trigger on syscall id, for example to + gather and display a list of systemwide syscall hits, you can use + the special .syscall modifier to display the syscall names rather + than raw ids. The example below keeps a running total of syscall + counts for the system during the run: + + # echo 'hist:key=id.syscall:val=hitcount' > \ + /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger + + # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist + # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active] + + { id: sys_fsync [ 74] } hitcount: 1 + { id: sys_newuname [ 63] } hitcount: 1 + { id: sys_prctl [157] } hitcount: 1 + { id: sys_statfs [137] } hitcount: 1 + { id: sys_symlink [ 88] } hitcount: 1 + { id: sys_sendmmsg [307] } hitcount: 1 + { id: sys_semctl [ 66] } hitcount: 1 + { id: sys_readlink [ 89] } hitcount: 3 + { id: sys_bind [ 49] } hitcount: 3 + { id: sys_getsockname [ 51] } hitcount: 3 + { id: sys_unlink [ 87] } hitcount: 3 + { id: sys_rename [ 82] } hitcount: 4 + { id: unknown_syscall [ 58] } hitcount: 4 + { id: sys_connect [ 42] } hitcount: 4 + { id: sys_getpid [ 39] } hitcount: 4 + . + . + . + { id: sys_rt_sigprocmask [ 14] } hitcount: 952 + { id: sys_futex [202] } hitcount: 1534 + { id: sys_write [ 1] } hitcount: 2689 + { id: sys_setitimer [ 38] } hitcount: 2797 + { id: sys_read [ 0] } hitcount: 3202 + { id: sys_select [ 23] } hitcount: 3773 + { id: sys_writev [ 20] } hitcount: 4531 + { id: sys_poll [ 7] } hitcount: 8314 + { id: sys_recvmsg [ 47] } hitcount: 13738 + { id: sys_ioctl [ 16] } hitcount: 21843 + + Totals: + Hits: 67612 + Entries: 72 + Dropped: 0 + + The syscall counts above provide a rough overall picture of system + call activity on the system; we can see for example that the most + popular system call on this system was the 'sys_ioctl' system call. + + We can use 'compound' keys to refine that number and provide some + further insight as to which processes exactly contribute to the + overall ioctl count. + + The command below keeps a hitcount for every unique combination of + system call id and pid - the end result is essentially a table + that keeps a per-pid sum of system call hits. The results are + sorted using the system call id as the primary key, and the + hitcount sum as the secondary key: + + # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount' > \ + /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger + + # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist + # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active] + + { id: sys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: 1 + { id: sys_read [ 0], common_pid: gdbus [ 2976] } hitcount: 1 + { id: sys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: 1 + { id: sys_read [ 0], common_pid: postgres [ 1865] } hitcount: 1 + { id: sys_read [ 0], common_pid: deja-dup-monito [ 3543] } hitcount: 2 + { id: sys_read [ 0], common_pid: NetworkManager [ 890] } hitcount: 2 + { id: sys_read [ 0], common_pid: evolution-calen [ 3048] } hitcount: 2 + { id: sys_read [ 0], common_pid: postgres [ 1864] } hitcount: 2 + { id: sys_read [ 0], common_pid: nm-applet [ 3022] } hitcount: 2 + { id: sys_read [ 0], common_pid: whoopsie [ 1212] } hitcount: 2 + . + . + . + { id: sys_ioctl [ 16], common_pid: bash [ 8479] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: bash [ 3472] } hitcount: 12 + { id: sys_ioctl [ 16], common_pid: gnome-terminal [ 3199] } hitcount: 16 + { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 1808 + { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 5580 + . + . + . + { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2690] } hitcount: 3 + { id: sys_waitid [247], common_pid: upstart-dbus-br [ 2688] } hitcount: 16 + { id: sys_inotify_add_watch [254], common_pid: gmain [ 975] } hitcount: 2 + { id: sys_inotify_add_watch [254], common_pid: gmain [ 3204] } hitcount: 4 + { id: sys_inotify_add_watch [254], common_pid: gmain [ 2888] } hitcount: 4 + { id: sys_inotify_add_watch [254], common_pid: gmain [ 3003] } hitcount: 4 + { id: sys_inotify_add_watch [254], common_pid: gmain [ 2873] } hitcount: 4 + { id: sys_inotify_add_watch [254], common_pid: gmain [ 3196] } hitcount: 6 + { id: sys_openat [257], common_pid: java [ 2623] } hitcount: 2 + { id: sys_eventfd2 [290], common_pid: ibus-ui-gtk3 [ 2760] } hitcount: 4 + { id: sys_eventfd2 [290], common_pid: compiz [ 2994] } hitcount: 6 + + Totals: + Hits: 31536 + Entries: 323 + Dropped: 0 + + The above list does give us a breakdown of the ioctl syscall by + pid, but it also gives us quite a bit more than that, which we + don't really care about at the moment. Since we know the syscall + id for sys_ioctl (16, displayed next to the sys_ioctl name), we + can use that to filter out all the other syscalls: + + # echo 'hist:key=id.syscall,common_pid.execname:val=hitcount:sort=id,hitcount if id == 16' > \ + /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/trigger + + # cat /sys/kernel/debug/tracing/events/raw_syscalls/sys_enter/hist + # trigger info: hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 if id == 16 [active] + + { id: sys_ioctl [ 16], common_pid: gmain [ 2769] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: gmain [ 3003] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: gmain [ 2781] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: gmain [ 2829] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: bash [ 8726] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: bash [ 8508] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: gmain [ 2970] } hitcount: 1 + { id: sys_ioctl [ 16], common_pid: gmain [ 2768] } hitcount: 1 + . + . + . + { id: sys_ioctl [ 16], common_pid: pool [ 8559] } hitcount: 45 + { id: sys_ioctl [ 16], common_pid: pool [ 8555] } hitcount: 48 + { id: sys_ioctl [ 16], common_pid: pool [ 8551] } hitcount: 48 + { id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: 66 + { id: sys_ioctl [ 16], common_pid: Xorg [ 1267] } hitcount: 26674 + { id: sys_ioctl [ 16], common_pid: compiz [ 2994] } hitcount: 73443 + + Totals: + Hits: 101162 + Entries: 103 + Dropped: 0 + + The above output shows that 'compiz' and 'Xorg' are far and away + the heaviest ioctl callers (which might lead to questions about + whether they really need to be making all those calls and to + possible avenues for further investigation.) + + The compound key examples used a key and a sum value (hitcount) to + sort the output, but we can just as easily use two keys instead. + Here's an example where we use a compound key composed of the the + common_pid and size event fields. Sorting with pid as the primary + key and 'size' as the secondary key allows us to display an + ordered summary of the recvfrom sizes, with counts, received by + each process: + + # echo 'hist:key=common_pid.execname,size:val=hitcount:sort=common_pid,size' > \ + /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/trigger + + # cat /sys/kernel/debug/tracing/events/syscalls/sys_enter_recvfrom/hist + # trigger info: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:size=2048 [active] + + { common_pid: smbd [ 784], size: 4 } hitcount: 1 + { common_pid: dnsmasq [ 1412], size: 4096 } hitcount: 672 + { common_pid: postgres [ 1796], size: 1000 } hitcount: 6 + { common_pid: postgres [ 1867], size: 1000 } hitcount: 10 + { common_pid: bamfdaemon [ 2787], size: 28 } hitcount: 2 + { common_pid: bamfdaemon [ 2787], size: 14360 } hitcount: 1 + { common_pid: compiz [ 2994], size: 8 } hitcount: 1 + { common_pid: compiz [ 2994], size: 20 } hitcount: 11 + { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2 + { common_pid: firefox [ 8817], size: 4 } hitcount: 1 + { common_pid: firefox [ 8817], size: 8 } hitcount: 5 + { common_pid: firefox [ 8817], size: 588 } hitcount: 2 + { common_pid: firefox [ 8817], size: 628 } hitcount: 1 + { common_pid: firefox [ 8817], size: 6944 } hitcount: 1 + { common_pid: firefox [ 8817], size: 408880 } hitcount: 2 + { common_pid: firefox [ 8822], size: 8 } hitcount: 2 + { common_pid: firefox [ 8822], size: 160 } hitcount: 2 + { common_pid: firefox [ 8822], size: 320 } hitcount: 2 + { common_pid: firefox [ 8822], size: 352 } hitcount: 1 + . + . + . + { common_pid: pool [ 8923], size: 1960 } hitcount: 10 + { common_pid: pool [ 8923], size: 2048 } hitcount: 10 + { common_pid: pool [ 8924], size: 1960 } hitcount: 10 + { common_pid: pool [ 8924], size: 2048 } hitcount: 10 + { common_pid: pool [ 8928], size: 1964 } hitcount: 4 + { common_pid: pool [ 8928], size: 1965 } hitcount: 2 + { common_pid: pool [ 8928], size: 2048 } hitcount: 6 + { common_pid: pool [ 8929], size: 1982 } hitcount: 1 + { common_pid: pool [ 8929], size: 2048 } hitcount: 1 + + Totals: + Hits: 2016 + Entries: 224 + Dropped: 0 + + The above example also illustrates the fact that although a compound + key is treated as a single entity for hashing purposes, the sub-keys + it's composed of can be accessed independently. + + The next example uses a string field as the hash key and + demonstrates how you can manually pause and continue a hist trigger. + In this example, we'll aggregate fork counts and don't expect a + large number of entries in the hash table, so we'll drop it to a + much smaller number, say 256: + + # echo 'hist:key=child_comm:val=hitcount:size=256' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger + + # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist + # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] + + { child_comm: dconf worker } hitcount: 1 + { child_comm: ibus-daemon } hitcount: 1 + { child_comm: whoopsie } hitcount: 1 + { child_comm: smbd } hitcount: 1 + { child_comm: gdbus } hitcount: 1 + { child_comm: kthreadd } hitcount: 1 + { child_comm: dconf worker } hitcount: 1 + { child_comm: evolution-alarm } hitcount: 2 + { child_comm: Socket Thread } hitcount: 2 + { child_comm: postgres } hitcount: 2 + { child_comm: bash } hitcount: 3 + { child_comm: compiz } hitcount: 3 + { child_comm: evolution-sourc } hitcount: 4 + { child_comm: dhclient } hitcount: 4 + { child_comm: pool } hitcount: 5 + { child_comm: nm-dispatcher.a } hitcount: 8 + { child_comm: firefox } hitcount: 8 + { child_comm: dbus-daemon } hitcount: 8 + { child_comm: glib-pacrunner } hitcount: 10 + { child_comm: evolution } hitcount: 23 + + Totals: + Hits: 89 + Entries: 20 + Dropped: 0 + + If we want to pause the hist trigger, we can simply append :pause to + the command that started the trigger. Notice that the trigger info + displays as [paused]: + + # echo 'hist:key=child_comm:val=hitcount:size=256:pause' >> \ + /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger + + # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist + # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [paused] + + { child_comm: dconf worker } hitcount: 1 + { child_comm: kthreadd } hitcount: 1 + { child_comm: dconf worker } hitcount: 1 + { child_comm: gdbus } hitcount: 1 + { child_comm: ibus-daemon } hitcount: 1 + { child_comm: Socket Thread } hitcount: 2 + { child_comm: evolution-alarm } hitcount: 2 + { child_comm: smbd } hitcount: 2 + { child_comm: bash } hitcount: 3 + { child_comm: whoopsie } hitcount: 3 + { child_comm: compiz } hitcount: 3 + { child_comm: evolution-sourc } hitcount: 4 + { child_comm: pool } hitcount: 5 + { child_comm: postgres } hitcount: 6 + { child_comm: firefox } hitcount: 8 + { child_comm: dhclient } hitcount: 10 + { child_comm: emacs } hitcount: 12 + { child_comm: dbus-daemon } hitcount: 20 + { child_comm: nm-dispatcher.a } hitcount: 20 + { child_comm: evolution } hitcount: 35 + { child_comm: glib-pacrunner } hitcount: 59 + + Totals: + Hits: 199 + Entries: 21 + Dropped: 0 + + To manually continue having the trigger aggregate events, append + :cont instead. Notice that the trigger info displays as [active] + again, and the data has changed: + + # echo 'hist:key=child_comm:val=hitcount:size=256:cont' >> \ + /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger + + # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist + # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active] + + { child_comm: dconf worker } hitcount: 1 + { child_comm: dconf worker } hitcount: 1 + { child_comm: kthreadd } hitcount: 1 + { child_comm: gdbus } hitcount: 1 + { child_comm: ibus-daemon } hitcount: 1 + { child_comm: Socket Thread } hitcount: 2 + { child_comm: evolution-alarm } hitcount: 2 + { child_comm: smbd } hitcount: 2 + { child_comm: whoopsie } hitcount: 3 + { child_comm: compiz } hitcount: 3 + { child_comm: evolution-sourc } hitcount: 4 + { child_comm: bash } hitcount: 5 + { child_comm: pool } hitcount: 5 + { child_comm: postgres } hitcount: 6 + { child_comm: firefox } hitcount: 8 + { child_comm: dhclient } hitcount: 11 + { child_comm: emacs } hitcount: 12 + { child_comm: dbus-daemon } hitcount: 22 + { child_comm: nm-dispatcher.a } hitcount: 22 + { child_comm: evolution } hitcount: 35 + { child_comm: glib-pacrunner } hitcount: 59 + + Totals: + Hits: 206 + Entries: 21 + Dropped: 0 + + The previous example showed how to start and stop a hist trigger by + appending 'pause' and 'continue' to the hist trigger command. A + hist trigger can also be started in a paused state by initially + starting the trigger with ':pause' appended. This allows you to + start the trigger only when you're ready to start collecting data + and not before. For example, you could start the trigger in a + paused state, then unpause it and do something you want to measure, + then pause the trigger again when done. + + Of course, doing this manually can be difficult and error-prone, but + it is possible to automatically start and stop a hist trigger based + on some condition, via the enable_hist and disable_hist triggers. + + For example, suppose we wanted to take a look at the relative + weights in terms of skb length for each callpath that leads to a + netif_receieve_skb event when downloading a decent-sized file using + wget. + + First we set up an initially paused stacktrace trigger on the + netif_receive_skb event: + + # echo 'hist:key=stacktrace:vals=len:pause' > \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + + Next, we set up an 'enable_hist' trigger on the sched_process_exec + event, with an 'if filename==/usr/bin/wget' filter. The effect of + this new trigger is that it will 'unpause' the hist trigger we just + set up on netif_receive_skb if and only if it sees a + sched_process_exec event with a filename of '/usr/bin/wget'. When + that happens, all netif_receive_skb events are aggregated into a + hash table keyed on stacktrace: + + # echo 'enable_hist:net:netif_receive_skb if filename==/usr/bin/wget' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger + + The aggregation continues until the netif_receive_skb is paused + again, which is what the following disable_hist event does by + creating a similar setup on the sched_process_exit event, using the + filter 'comm==wget': + + # echo 'disable_hist:net:netif_receive_skb if comm==wget' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger + + Whenever a process exits and the comm field of the disable_hist + trigger filter matches 'comm==wget', the netif_receive_skb hist + trigger is disabled. + + The overall effect is that netif_receive_skb events are aggregated + into the hash table for only the duration of the wget. Executing a + wget command and then listing the 'hist' file will display the + output generated by the wget command: + + $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz + + # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist + # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused] + + { stacktrace: + __netif_receive_skb_core+0x46d/0x990 + __netif_receive_skb+0x18/0x60 + netif_receive_skb_internal+0x23/0x90 + napi_gro_receive+0xc8/0x100 + ieee80211_deliver_skb+0xd6/0x270 [mac80211] + ieee80211_rx_handlers+0xccf/0x22f0 [mac80211] + ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211] + ieee80211_rx+0x31d/0x900 [mac80211] + iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm] + iwl_rx_dispatch+0x8e/0xf0 [iwldvm] + iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi] + irq_thread_fn+0x20/0x50 + irq_thread+0x11f/0x150 + kthread+0xd2/0xf0 + ret_from_fork+0x42/0x70 + } hitcount: 85 len: 28884 + { stacktrace: + __netif_receive_skb_core+0x46d/0x990 + __netif_receive_skb+0x18/0x60 + netif_receive_skb_internal+0x23/0x90 + napi_gro_complete+0xa4/0xe0 + dev_gro_receive+0x23a/0x360 + napi_gro_receive+0x30/0x100 + ieee80211_deliver_skb+0xd6/0x270 [mac80211] + ieee80211_rx_handlers+0xccf/0x22f0 [mac80211] + ieee80211_prepare_and_rx_handle+0x4e7/0xc40 [mac80211] + ieee80211_rx+0x31d/0x900 [mac80211] + iwlagn_rx_reply_rx+0x3db/0x6f0 [iwldvm] + iwl_rx_dispatch+0x8e/0xf0 [iwldvm] + iwl_pcie_irq_handler+0xe3c/0x12f0 [iwlwifi] + irq_thread_fn+0x20/0x50 + irq_thread+0x11f/0x150 + kthread+0xd2/0xf0 + } hitcount: 98 len: 664329 + { stacktrace: + __netif_receive_skb_core+0x46d/0x990 + __netif_receive_skb+0x18/0x60 + process_backlog+0xa8/0x150 + net_rx_action+0x15d/0x340 + __do_softirq+0x114/0x2c0 + do_softirq_own_stack+0x1c/0x30 + do_softirq+0x65/0x70 + __local_bh_enable_ip+0xb5/0xc0 + ip_finish_output+0x1f4/0x840 + ip_output+0x6b/0xc0 + ip_local_out_sk+0x31/0x40 + ip_send_skb+0x1a/0x50 + udp_send_skb+0x173/0x2a0 + udp_sendmsg+0x2bf/0x9f0 + inet_sendmsg+0x64/0xa0 + sock_sendmsg+0x3d/0x50 + } hitcount: 115 len: 13030 + { stacktrace: + __netif_receive_skb_core+0x46d/0x990 + __netif_receive_skb+0x18/0x60 + netif_receive_skb_internal+0x23/0x90 + napi_gro_complete+0xa4/0xe0 + napi_gro_flush+0x6d/0x90 + iwl_pcie_irq_handler+0x92a/0x12f0 [iwlwifi] + irq_thread_fn+0x20/0x50 + irq_thread+0x11f/0x150 + kthread+0xd2/0xf0 + ret_from_fork+0x42/0x70 + } hitcount: 934 len: 5512212 + + Totals: + Hits: 1232 + Entries: 4 + Dropped: 0 + + The above shows all the netif_receive_skb callpaths and their total + lengths for the duration of the wget command. + + The 'clear' hist trigger param can be used to clear the hash table. + Suppose we wanted to try another run of the previous example but + this time also wanted to see the complete list of events that went + into the histogram. In order to avoid having to set everything up + again, we can just clear the histogram first: + + # echo 'hist:key=stacktrace:vals=len:clear' >> \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + + Just to verify that it is in fact cleared, here's what we now see in + the hist file: + + # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist + # trigger info: hist:keys=stacktrace:vals=len:sort=hitcount:size=2048 [paused] + + Totals: + Hits: 0 + Entries: 0 + Dropped: 0 + + Since we want to see the detailed list of every netif_receive_skb + event occurring during the new run, which are in fact the same + events being aggregated into the hash table, we add some additional + 'enable_event' events to the triggering sched_process_exec and + sched_process_exit events as such: + + # echo 'enable_event:net:netif_receive_skb if filename==/usr/bin/wget' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger + + # echo 'disable_event:net:netif_receive_skb if comm==wget' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger + + If you read the trigger files for the sched_process_exec and + sched_process_exit triggers, you should see two triggers for each: + one enabling/disabling the hist aggregation and the other + enabling/disabling the logging of events: + + # cat /sys/kernel/debug/tracing/events/sched/sched_process_exec/trigger + enable_event:net:netif_receive_skb:unlimited if filename==/usr/bin/wget + enable_hist:net:netif_receive_skb:unlimited if filename==/usr/bin/wget + + # cat /sys/kernel/debug/tracing/events/sched/sched_process_exit/trigger + enable_event:net:netif_receive_skb:unlimited if comm==wget + disable_hist:net:netif_receive_skb:unlimited if comm==wget + + In other words, whenever either of the sched_process_exec or + sched_process_exit events is hit and matches 'wget', it enables or + disables both the histogram and the event log, and what you end up + with is a hash table and set of events just covering the specified + duration. Run the wget command again: + + $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz + + Displaying the 'hist' file should show something similar to what you + saw in the last run, but this time you should also see the + individual events in the trace file: + + # cat /sys/kernel/debug/tracing/trace + + # tracer: nop + # + # entries-in-buffer/entries-written: 183/1426 #P:4 + # + # _-----=> irqs-off + # / _----=> need-resched + # | / _---=> hardirq/softirq + # || / _--=> preempt-depth + # ||| / delay + # TASK-PID CPU# |||| TIMESTAMP FUNCTION + # | | | |||| | | + wget-15108 [000] ..s1 31769.606929: netif_receive_skb: dev=lo skbaddr=ffff88009c353100 len=60 + wget-15108 [000] ..s1 31769.606999: netif_receive_skb: dev=lo skbaddr=ffff88009c353200 len=60 + dnsmasq-1382 [000] ..s1 31769.677652: netif_receive_skb: dev=lo skbaddr=ffff88009c352b00 len=130 + dnsmasq-1382 [000] ..s1 31769.685917: netif_receive_skb: dev=lo skbaddr=ffff88009c352200 len=138 + ##### CPU 2 buffer started #### + irq/29-iwlwifi-559 [002] ..s. 31772.031529: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433d00 len=2948 + irq/29-iwlwifi-559 [002] ..s. 31772.031572: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432200 len=1500 + irq/29-iwlwifi-559 [002] ..s. 31772.032196: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433100 len=2948 + irq/29-iwlwifi-559 [002] ..s. 31772.032761: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433000 len=2948 + irq/29-iwlwifi-559 [002] ..s. 31772.033220: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432e00 len=1500 + . + . + . + + The following example demonstrates how multiple hist triggers can be + attached to a given event. This capability can be useful for + creating a set of different summaries derived from the same set of + events, or for comparing the effects of different filters, among + other things. + + # echo 'hist:keys=skbaddr.hex:vals=len if len < 0' >> \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + # echo 'hist:keys=skbaddr.hex:vals=len if len > 4096' >> \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + # echo 'hist:keys=skbaddr.hex:vals=len if len == 256' >> \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + # echo 'hist:keys=skbaddr.hex:vals=len' >> \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + # echo 'hist:keys=len:vals=common_preempt_count' >> \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + + The above set of commands create four triggers differing only in + their filters, along with a completely different though fairly + nonsensical trigger. Note that in order to append multiple hist + triggers to the same file, you should use the '>>' operator to + append them ('>' will also add the new hist trigger, but will remove + any existing hist triggers beforehand). + + Displaying the contents of the 'hist' file for the event shows the + contents of all five histograms: + + # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist + + # event histogram + # + # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active] + # + + { len: 176 } hitcount: 1 common_preempt_count: 0 + { len: 223 } hitcount: 1 common_preempt_count: 0 + { len: 4854 } hitcount: 1 common_preempt_count: 0 + { len: 395 } hitcount: 1 common_preempt_count: 0 + { len: 177 } hitcount: 1 common_preempt_count: 0 + { len: 446 } hitcount: 1 common_preempt_count: 0 + { len: 1601 } hitcount: 1 common_preempt_count: 0 + . + . + . + { len: 1280 } hitcount: 66 common_preempt_count: 0 + { len: 116 } hitcount: 81 common_preempt_count: 40 + { len: 708 } hitcount: 112 common_preempt_count: 0 + { len: 46 } hitcount: 221 common_preempt_count: 0 + { len: 1264 } hitcount: 458 common_preempt_count: 0 + + Totals: + Hits: 1428 + Entries: 147 + Dropped: 0 + + + # event histogram + # + # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] + # + + { skbaddr: ffff8800baee5e00 } hitcount: 1 len: 130 + { skbaddr: ffff88005f3d5600 } hitcount: 1 len: 1280 + { skbaddr: ffff88005f3d4900 } hitcount: 1 len: 1280 + { skbaddr: ffff88009fed6300 } hitcount: 1 len: 115 + { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 115 + { skbaddr: ffff88008cdb1900 } hitcount: 1 len: 46 + { skbaddr: ffff880064b5ef00 } hitcount: 1 len: 118 + { skbaddr: ffff880044e3c700 } hitcount: 1 len: 60 + { skbaddr: ffff880100065900 } hitcount: 1 len: 46 + { skbaddr: ffff8800d46bd500 } hitcount: 1 len: 116 + { skbaddr: ffff88005f3d5f00 } hitcount: 1 len: 1280 + { skbaddr: ffff880100064700 } hitcount: 1 len: 365 + { skbaddr: ffff8800badb6f00 } hitcount: 1 len: 60 + . + . + . + { skbaddr: ffff88009fe0be00 } hitcount: 27 len: 24677 + { skbaddr: ffff88009fe0a400 } hitcount: 27 len: 23052 + { skbaddr: ffff88009fe0b700 } hitcount: 31 len: 25589 + { skbaddr: ffff88009fe0b600 } hitcount: 32 len: 27326 + { skbaddr: ffff88006a462800 } hitcount: 68 len: 71678 + { skbaddr: ffff88006a463700 } hitcount: 70 len: 72678 + { skbaddr: ffff88006a462b00 } hitcount: 71 len: 77589 + { skbaddr: ffff88006a463600 } hitcount: 73 len: 71307 + { skbaddr: ffff88006a462200 } hitcount: 81 len: 81032 + + Totals: + Hits: 1451 + Entries: 318 + Dropped: 0 + + + # event histogram + # + # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [active] + # + + + Totals: + Hits: 0 + Entries: 0 + Dropped: 0 + + + # event histogram + # + # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [active] + # + + { skbaddr: ffff88009fd2c300 } hitcount: 1 len: 7212 + { skbaddr: ffff8800d2bcce00 } hitcount: 1 len: 7212 + { skbaddr: ffff8800d2bcd700 } hitcount: 1 len: 7212 + { skbaddr: ffff8800d2bcda00 } hitcount: 1 len: 21492 + { skbaddr: ffff8800ae2e2d00 } hitcount: 1 len: 7212 + { skbaddr: ffff8800d2bcdb00 } hitcount: 1 len: 7212 + { skbaddr: ffff88006a4df500 } hitcount: 1 len: 4854 + { skbaddr: ffff88008ce47b00 } hitcount: 1 len: 18636 + { skbaddr: ffff8800ae2e2200 } hitcount: 1 len: 12924 + { skbaddr: ffff88005f3e1000 } hitcount: 1 len: 4356 + { skbaddr: ffff8800d2bcdc00 } hitcount: 2 len: 24420 + { skbaddr: ffff8800d2bcc200 } hitcount: 2 len: 12996 + + Totals: + Hits: 14 + Entries: 12 + Dropped: 0 + + + # event histogram + # + # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active] + # + + + Totals: + Hits: 0 + Entries: 0 + Dropped: 0 + + Named triggers can be used to have triggers share a common set of + histogram data. This capability is mostly useful for combining the + output of events generated by tracepoints contained inside inline + functions, but names can be used in a hist trigger on any event. + For example, these two triggers when hit will update the same 'len' + field in the shared 'foo' histogram data: + + # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ + /sys/kernel/debug/tracing/events/net/netif_receive_skb/trigger + # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \ + /sys/kernel/debug/tracing/events/net/netif_rx/trigger + + You can see that they're updating common histogram data by reading + each event's hist files at the same time: + + # cat /sys/kernel/debug/tracing/events/net/netif_receive_skb/hist; + cat /sys/kernel/debug/tracing/events/net/netif_rx/hist + + # event histogram + # + # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] + # + + { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46 + { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76 + { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468 + { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46 + { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52 + { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168 + { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260 + { skbaddr: ffff880064505000 } hitcount: 1 len: 46 + { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32 + { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46 + { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44 + { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168 + { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40 + { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40 + { skbaddr: ffff880064505f00 } hitcount: 1 len: 174 + { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160 + { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76 + { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32 + { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988 + { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46 + { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44 + { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676 + { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107 + { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92 + { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142 + { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220 + { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92 + { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92 + { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675 + { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138 + { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138 + { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184 + { skbaddr: ffff880064504400 } hitcount: 4 len: 184 + { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184 + { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230 + { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196 + { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276 + { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276 + + Totals: + Hits: 81 + Entries: 42 + Dropped: 0 + # event histogram + # + # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active] + # + + { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46 + { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76 + { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468 + { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46 + { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52 + { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168 + { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260 + { skbaddr: ffff880064505000 } hitcount: 1 len: 46 + { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32 + { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46 + { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44 + { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168 + { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40 + { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40 + { skbaddr: ffff880064505f00 } hitcount: 1 len: 174 + { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160 + { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76 + { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32 + { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46 + { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988 + { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46 + { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44 + { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676 + { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107 + { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92 + { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142 + { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220 + { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92 + { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92 + { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675 + { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138 + { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138 + { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184 + { skbaddr: ffff880064504400 } hitcount: 4 len: 184 + { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184 + { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230 + { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196 + { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276 + { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276 + + Totals: + Hits: 81 + Entries: 42 + Dropped: 0 + + And here's an example that shows how to combine histogram data from + any two events even if they don't share any 'compatible' fields + other than 'hitcount' and 'stacktrace'. These commands create a + couple of triggers named 'bar' using those fields: + + # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \ + /sys/kernel/debug/tracing/events/sched/sched_process_fork/trigger + # echo 'hist:name=bar:key=stacktrace:val=hitcount' > \ + /sys/kernel/debug/tracing/events/net/netif_rx/trigger + + And displaying the output of either shows some interesting if + somewhat confusing output: + + # cat /sys/kernel/debug/tracing/events/sched/sched_process_fork/hist + # cat /sys/kernel/debug/tracing/events/net/netif_rx/hist + + # event histogram + # + # trigger info: hist:name=bar:keys=stacktrace:vals=hitcount:sort=hitcount:size=2048 [active] + # + + { stacktrace: + _do_fork+0x18e/0x330 + kernel_thread+0x29/0x30 + kthreadd+0x154/0x1b0 + ret_from_fork+0x3f/0x70 + } hitcount: 1 + { stacktrace: + netif_rx_internal+0xb2/0xd0 + netif_rx_ni+0x20/0x70 + dev_loopback_xmit+0xaa/0xd0 + ip_mc_output+0x126/0x240 + ip_local_out_sk+0x31/0x40 + igmp_send_report+0x1e9/0x230 + igmp_timer_expire+0xe9/0x120 + call_timer_fn+0x39/0xf0 + run_timer_softirq+0x1e1/0x290 + __do_softirq+0xfd/0x290 + irq_exit+0x98/0xb0 + smp_apic_timer_interrupt+0x4a/0x60 + apic_timer_interrupt+0x6d/0x80 + cpuidle_enter+0x17/0x20 + call_cpuidle+0x3b/0x60 + cpu_startup_entry+0x22d/0x310 + } hitcount: 1 + { stacktrace: + netif_rx_internal+0xb2/0xd0 + netif_rx_ni+0x20/0x70 + dev_loopback_xmit+0xaa/0xd0 + ip_mc_output+0x17f/0x240 + ip_local_out_sk+0x31/0x40 + ip_send_skb+0x1a/0x50 + udp_send_skb+0x13e/0x270 + udp_sendmsg+0x2bf/0x980 + inet_sendmsg+0x67/0xa0 + sock_sendmsg+0x38/0x50 + SYSC_sendto+0xef/0x170 + SyS_sendto+0xe/0x10 + entry_SYSCALL_64_fastpath+0x12/0x6a + } hitcount: 2 + { stacktrace: + netif_rx_internal+0xb2/0xd0 + netif_rx+0x1c/0x60 + loopback_xmit+0x6c/0xb0 + dev_hard_start_xmit+0x219/0x3a0 + __dev_queue_xmit+0x415/0x4f0 + dev_queue_xmit_sk+0x13/0x20 + ip_finish_output2+0x237/0x340 + ip_finish_output+0x113/0x1d0 + ip_output+0x66/0xc0 + ip_local_out_sk+0x31/0x40 + ip_send_skb+0x1a/0x50 + udp_send_skb+0x16d/0x270 + udp_sendmsg+0x2bf/0x980 + inet_sendmsg+0x67/0xa0 + sock_sendmsg+0x38/0x50 + ___sys_sendmsg+0x14e/0x270 + } hitcount: 76 + { stacktrace: + netif_rx_internal+0xb2/0xd0 + netif_rx+0x1c/0x60 + loopback_xmit+0x6c/0xb0 + dev_hard_start_xmit+0x219/0x3a0 + __dev_queue_xmit+0x415/0x4f0 + dev_queue_xmit_sk+0x13/0x20 + ip_finish_output2+0x237/0x340 + ip_finish_output+0x113/0x1d0 + ip_output+0x66/0xc0 + ip_local_out_sk+0x31/0x40 + ip_send_skb+0x1a/0x50 + udp_send_skb+0x16d/0x270 + udp_sendmsg+0x2bf/0x980 + inet_sendmsg+0x67/0xa0 + sock_sendmsg+0x38/0x50 + ___sys_sendmsg+0x269/0x270 + } hitcount: 77 + { stacktrace: + netif_rx_internal+0xb2/0xd0 + netif_rx+0x1c/0x60 + loopback_xmit+0x6c/0xb0 + dev_hard_start_xmit+0x219/0x3a0 + __dev_queue_xmit+0x415/0x4f0 + dev_queue_xmit_sk+0x13/0x20 + ip_finish_output2+0x237/0x340 + ip_finish_output+0x113/0x1d0 + ip_output+0x66/0xc0 + ip_local_out_sk+0x31/0x40 + ip_send_skb+0x1a/0x50 + udp_send_skb+0x16d/0x270 + udp_sendmsg+0x2bf/0x980 + inet_sendmsg+0x67/0xa0 + sock_sendmsg+0x38/0x50 + SYSC_sendto+0xef/0x170 + } hitcount: 88 + { stacktrace: + _do_fork+0x18e/0x330 + SyS_clone+0x19/0x20 + entry_SYSCALL_64_fastpath+0x12/0x6a + } hitcount: 244 + + Totals: + Hits: 489 + Entries: 7 + Dropped: 0 + + +2.2 Inter-event hist triggers +----------------------------- + +Inter-event hist triggers are hist triggers that combine values from +one or more other events and create a histogram using that data. Data +from an inter-event histogram can in turn become the source for +further combined histograms, thus providing a chain of related +histograms, which is important for some applications. + +The most important example of an inter-event quantity that can be used +in this manner is latency, which is simply a difference in timestamps +between two events. Although latency is the most important +inter-event quantity, note that because the support is completely +general across the trace event subsystem, any event field can be used +in an inter-event quantity. + +An example of a histogram that combines data from other histograms +into a useful chain would be a 'wakeupswitch latency' histogram that +combines a 'wakeup latency' histogram and a 'switch latency' +histogram. + +Normally, a hist trigger specification consists of a (possibly +compound) key along with one or more numeric values, which are +continually updated sums associated with that key. A histogram +specification in this case consists of individual key and value +specifications that refer to trace event fields associated with a +single event type. + +The inter-event hist trigger extension allows fields from multiple +events to be referenced and combined into a multi-event histogram +specification. In support of this overall goal, a few enabling +features have been added to the hist trigger support: + + - In order to compute an inter-event quantity, a value from one + event needs to saved and then referenced from another event. This + requires the introduction of support for histogram 'variables'. + + - The computation of inter-event quantities and their combination + require some minimal amount of support for applying simple + expressions to variables (+ and -). + + - A histogram consisting of inter-event quantities isn't logically a + histogram on either event (so having the 'hist' file for either + event host the histogram output doesn't really make sense). To + address the idea that the histogram is associated with a + combination of events, support is added allowing the creation of + 'synthetic' events that are events derived from other events. + These synthetic events are full-fledged events just like any other + and can be used as such, as for instance to create the + 'combination' histograms mentioned previously. + + - A set of 'actions' can be associated with histogram entries - + these can be used to generate the previously mentioned synthetic + events, but can also be used for other purposes, such as for + example saving context when a 'max' latency has been hit. + + - Trace events don't have a 'timestamp' associated with them, but + there is an implicit timestamp saved along with an event in the + underlying ftrace ring buffer. This timestamp is now exposed as a + a synthetic field named '$common_timestamp' which can be used in + histograms as if it were any other event field. Note that it has + a '$' prefixed to it - this is meant to indicate that it isn't an + actual field in the trace format but rather is a synthesized value + that nonetheless can be used as if it were an actual field. By + default it is in units of nanoseconds; appending '.usecs' to a + common_timestamp field changes the units to microseconds. + +A note on inter-event timestamps: If $common_timestamp is used in a +histogram, the trace buffer is automatically switched over to using +absolute timestamps and the "global" trace clock, in order to avoid +bogus timestamp differences with other clocks that aren't coherent +across CPUs. This can be overridden by specifying one of the other +trace clocks instead, using the "clock=XXX" hist trigger attribute, +where XXX is any of the clocks listed in the tracing/trace_clock +pseudo-file. + +These features are described in more detail in the following sections. + +2.2.1 Histogram Variables +------------------------- + +Variables are simply named locations used for saving and retrieving +values between matching events. A 'matching' event is defined as an +event that has a matching key - if a variable is saved for a histogram +entry corresponding to that key, any subsequent event with a matching +key can access that variable. + +A variable's value is normally available to any subsequent event until +it is set to something else by a subsequent event. The one exception +to that rule is that any variable used in an expression is essentially +'read-once' - once it's used by an expression in a subsequent event, +it's reset to its 'unset' state, which means it can't be used again +unless it's set again. This ensures not only that an event doesn't +use an uninitialized variable in a calculation, but that that variable +is used only once and not for any unrelated subsequent match. + +The basic syntax for saving a variable is to simply prefix a unique +variable name not corresponding to any keyword along with an '=' sign +to any event field. + +Either keys or values can be saved and retrieved in this way. This +creates a variable named 'ts0' for a histogram entry with the key +'next_pid': + + # echo 'hist:keys=next_pid:vals=$ts0:ts0=$common_timestamp ... >> \ + event/trigger + +The ts0 variable can be accessed by any subsequent event having the +same pid as 'next_pid'. + +Variable references are formed by prepending the variable name with +the '$' sign. Thus for example, the ts0 variable above would be +referenced as '$ts0' in expressions. + +Because 'vals=' is used, the $common_timestamp variable value above +will also be summed as a normal histogram value would (though for a +timestamp it makes little sense). + +The below shows that a key value can also be saved in the same way: + + # echo 'hist:timer_pid=common_pid:key=timer_pid ...' >> event/trigger + +If a variable isn't a key variable or prefixed with 'vals=', the +associated event field will be saved in a variable but won't be summed +as a value: + + # echo 'hist:keys=next_pid:ts1=$common_timestamp ... >> event/trigger + +Multiple variables can be assigned at the same time. The below would +result in both ts0 and b being created as variables, with both +common_timestamp and field1 additionally being summed as values: + + # echo 'hist:keys=pid:vals=$ts0,$b:ts0=$common_timestamp,b=field1 ... >> \ + event/trigger + +Note that variable assignments can appear either preceding or +following their use. The command below behaves identically to the +command above: + + # echo 'hist:keys=pid:ts0=$common_timestamp,b=field1:vals=$ts0,$b ... >> \ + event/trigger + +Any number of variables not bound to a 'vals=' prefix can also be +assigned by simply separating them with colons. Below is the same +thing but without the values being summed in the histogram: + + # echo 'hist:keys=pid:ts0=$common_timestamp:b=field1 ... >> event/trigger + +Variables set as above can be referenced and used in expressions on +another event. + +For example, here's how a latency can be calculated: + + # echo 'hist:keys=pid,prio:ts0=$common_timestamp ... >> event1/trigger + # echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp-$ts0 ... >> event2/trigger + +In the first line above, the event's timetamp is saved into the +variable ts0. In the next line, ts0 is subtracted from the second +event's timestamp to produce the latency, which is then assigned into +yet another variable, 'wakeup_lat'. The hist trigger below in turn +makes use of the wakeup_lat variable to compute a combined latency +using the same key and variable from yet another event: + + # echo 'hist:key=pid:wakeupswitch_lat=$wakeup_lat+$switchtime_lat ... >> event3/trigger + +2.2.2 Synthetic Events +---------------------- + +Synthetic events are user-defined events generated from hist trigger +variables or fields associated with one or more other events. Their +purpose is to provide a mechanism for displaying data spanning +multiple events consistent with the existing and already familiar +usage for normal events. + +To define a synthetic event, the user writes a simple specification +consisting of the name of the new event along with one or more +variables and their types, which can be any valid field type, +separated by semicolons, to the tracing/synthetic_events file. + +For instance, the following creates a new event named 'wakeup_latency' +with 3 fields: lat, pid, and prio. Each of those fields is simply a +variable reference to a variable on another event: + + # echo 'wakeup_latency \ + u64 lat; \ + pid_t pid; \ + int prio' >> \ + /sys/kernel/debug/tracing/synthetic_events + +Reading the tracing/synthetic_events file lists all the currently +defined synthetic events, in this case the event defined above: + + # cat /sys/kernel/debug/tracing/synthetic_events + wakeup_latency u64 lat; pid_t pid; int prio + +An existing synthetic event definition can be removed by prepending +the command that defined it with a '!': + + # echo '!wakeup_latency u64 lat pid_t pid int prio' >> \ + /sys/kernel/debug/tracing/synthetic_events + +At this point, there isn't yet an actual 'wakeup_latency' event +instantiated in the event subsytem - for this to happen, a 'hist +trigger action' needs to be instantiated and bound to actual fields +and variables defined on other events (see Section 6.3.3 below). + +Once that is done, an event instance is created, and a histogram can +be defined using it: + + # echo 'hist:keys=pid,prio,lat.log2:sort=pid,lat' >> \ + /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger + +The new event is created under the tracing/events/synthetic/ directory +and looks and behaves just like any other event: + + # ls /sys/kernel/debug/tracing/events/synthetic/wakeup_latency + enable filter format hist id trigger + +Like any other event, once a histogram is enabled for the event, the +output can be displayed by reading the event's 'hist' file. + +2.2.3 Hist trigger 'actions' +---------------------------- + +A hist trigger 'action' is a function that's executed whenever a +histogram entry is added or updated. + +The default 'action' if no special function is explicity specified is +as it always has been, to simply update the set of values associated +with an entry. Some applications, however, may want to perform +additional actions at that point, such as generate another event, or +compare and save a maximum. + +The following additional actions are available. To specify an action +for a given event, simply specify the action between colons in the +hist trigger specification. + + - onmatch(matching.event).(param list) + + The 'onmatch(matching.event).(params)' hist + trigger action is invoked whenever an event matches and the + histogram entry would be added or updated. It causes the named + synthetic event to be generated with the values given in the + 'param list'. The result is the generation of a synthetic event + that consists of the values contained in those variables at the + time the invoking event was hit. + + The 'param list' consists of one or more parameters which may be + either variables or fields defined on either the 'matching.event' + or the target event. The variables or fields specified in the + param list may be either fully-qualified or unqualified. If a + variable is specified as unqualified, it must be unique between + the two events. A field name used as a param can be unqualified + if it refers to the target event, but must be fully qualified if + it refers to the matching event. A fully-qualified name is of the + form 'system.event_name.$var_name' or 'system.event_name.field'. + + The 'matching.event' specification is simply the fully qualified + event name of the event that matches the target event for the + onmatch() functionality, in the form 'system.event_name'. + + Finally, the number and type of variables/fields in the 'param + list' must match the number and types of the fields in the + synthetic event being generated. + + As an example the below defines a simple synthetic event and uses + a variable defined on the sched_wakeup_new event as a parameter + when invoking the synthetic event. Here we define the synthetic + event: + + # echo 'wakeup_new_test pid_t pid' >> \ + /sys/kernel/debug/tracing/synthetic_events + + # cat /sys/kernel/debug/tracing/synthetic_events + wakeup_new_test pid_t pid + + The following hist trigger both defines the missing testpid + variable and specifies an onmatch() action that generates a + wakeup_new_test synthetic event whenever a sched_wakeup_new event + occurs, which because of the 'if comm == "cyclictest"' filter only + happens when the executable is cyclictest: + + # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\ + wakeup_new_test($testpid) if comm=="cyclictest"' >> \ + /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger + + Creating and displaying a histogram based on those events is now + just a matter of using the fields and new synthetic event in the + tracing/events/synthetic directory, as usual: + + # echo 'hist:keys=pid:sort=pid' >> \ + /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/trigger + + Running 'cyclictest' should cause wakeup_new events to generate + wakeup_new_test synthetic events which should result in histogram + output in the wakeup_new_test event's hist file: + + # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_new_test/hist + + A more typical usage would be to use two events to calculate a + latency. The following example uses a set of hist triggers to + produce a 'wakeup_latency' histogram: + + First, we define a 'wakeup_latency' synthetic event: + + # echo 'wakeup_latency u64 lat; pid_t pid; int prio' >> \ + /sys/kernel/debug/tracing/synthetic_events + + Next, we specify that whenever we see a sched_waking event for a + cyclictest thread, save the timestamp in a 'ts0' variable: + + # echo 'hist:keys=$saved_pid:saved_pid=pid:ts0=$common_timestamp.usecs \ + if comm=="cyclictest"' >> \ + /sys/kernel/debug/tracing/events/sched/sched_waking/trigger + + Then, when the corresponding thread is actually scheduled onto the + CPU by a sched_switch event, calculate the latency and use that + along with another variable and an event field to generate a + wakeup_latency synthetic event: + + # echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts0:\ + onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,\ + $saved_pid,next_prio) if next_comm=="cyclictest"' >> \ + /sys/kernel/debug/tracing/events/sched/sched_switch/trigger + + We also need to create a histogram on the wakeup_latency synthetic + event in order to aggregate the generated synthetic event data: + + # echo 'hist:keys=pid,prio,lat:sort=pid,lat' >> \ + /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/trigger + + Finally, once we've run cyclictest to actually generate some + events, we can see the output by looking at the wakeup_latency + synthetic event's hist file: + + # cat /sys/kernel/debug/tracing/events/synthetic/wakeup_latency/hist + + - onmax(var).save(field,.. .) + + The 'onmax(var).save(field,...)' hist trigger action is invoked + whenever the value of 'var' associated with a histogram entry + exceeds the current maximum contained in that variable. + + The end result is that the trace event fields specified as the + onmax.save() params will be saved if 'var' exceeds the current + maximum for that hist trigger entry. This allows context from the + event that exhibited the new maximum to be saved for later + reference. When the histogram is displayed, additional fields + displaying the saved values will be printed. + + As an example the below defines a couple of hist triggers, one for + sched_waking and another for sched_switch, keyed on pid. Whenever + a sched_waking occurs, the timestamp is saved in the entry + corresponding to the current pid, and when the scheduler switches + back to that pid, the timestamp difference is calculated. If the + resulting latency, stored in wakeup_lat, exceeds the current + maximum latency, the values specified in the save() fields are + recoreded: + + # echo 'hist:keys=pid:ts0=$common_timestamp.usecs \ + if comm=="cyclictest"' >> \ + /sys/kernel/debug/tracing/events/sched/sched_waking/trigger + + # echo 'hist:keys=next_pid:\ + wakeup_lat=$common_timestamp.usecs-$ts0:\ + onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) \ + if next_comm=="cyclictest"' >> \ + /sys/kernel/debug/tracing/events/sched/sched_switch/trigger + + When the histogram is displayed, the max value and the saved + values corresponding to the max are displayed following the rest + of the fields: + + # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist + { next_pid: 2255 } hitcount: 239 + common_timestamp-ts0: 0 + max: 27 + next_comm: cyclictest + prev_pid: 0 prev_prio: 120 prev_comm: swapper/1 + + { next_pid: 2256 } hitcount: 2355 + common_timestamp-ts0: 0 + max: 49 next_comm: cyclictest + prev_pid: 0 prev_prio: 120 prev_comm: swapper/0 + + Totals: + Hits: 12970 + Entries: 2 + Dropped: 0 diff --git a/fs/jbd2/checkpoint.c b/fs/jbd2/checkpoint.c index bba2e5e6e917..4055f51617ef 100644 --- a/fs/jbd2/checkpoint.c +++ b/fs/jbd2/checkpoint.c @@ -116,8 +116,6 @@ void __jbd2_log_wait_for_space(journal_t *journal) nblocks = jbd2_space_needed(journal); while (jbd2_log_space_left(journal) < nblocks) { write_unlock(&journal->j_state_lock); - if (current->plug) - io_schedule(); mutex_lock(&journal->j_checkpoint_mutex); /* diff --git a/include/linux/hrtimer.h b/include/linux/hrtimer.h index 96d16ddd6410..3bd606859b0a 100644 --- a/include/linux/hrtimer.h +++ b/include/linux/hrtimer.h @@ -110,6 +110,7 @@ enum hrtimer_restart { * @base: pointer to the timer base (per cpu and per clock) * @state: state information (See bit values above) * @is_rel: Set if the timer was armed relative + * @is_soft: Set if hrtimer will be expired in soft interrupt context. * * The hrtimer structure must be initialized by hrtimer_init() */ diff --git a/kernel/sched/rt.c b/kernel/sched/rt.c index d76a47332502..e4f3246ea3a5 100644 --- a/kernel/sched/rt.c +++ b/kernel/sched/rt.c @@ -74,10 +74,6 @@ static void start_rt_bandwidth(struct rt_bandwidth *rt_b) raw_spin_unlock(&rt_b->rt_runtime_lock); } -#if defined(CONFIG_SMP) && defined(HAVE_RT_PUSH_IPI) -static void push_irq_work_func(struct irq_work *work); -#endif - void init_rt_rq(struct rt_rq *rt_rq) { struct rt_prio_array *array; @@ -97,14 +93,6 @@ void init_rt_rq(struct rt_rq *rt_rq) rt_rq->rt_nr_migratory = 0; rt_rq->overloaded = 0; plist_head_init(&rt_rq->pushable_tasks); - -#ifdef HAVE_RT_PUSH_IPI - rt_rq->push_flags = 0; - rt_rq->push_cpu = nr_cpu_ids; - raw_spin_lock_init(&rt_rq->push_lock); - init_irq_work(&rt_rq->push_work, push_irq_work_func); - rt_rq->push_work.flags |= IRQ_WORK_HARD_IRQ; -#endif #endif /* CONFIG_SMP */ /* We start is dequeued state, because no RT tasks are queued */ rt_rq->rt_queued = 0; @@ -1877,68 +1865,6 @@ static void push_rt_tasks(struct rq *rq) } #ifdef HAVE_RT_PUSH_IPI -/* - * The search for the next cpu always starts at rq->cpu and ends - * when we reach rq->cpu again. It will never return rq->cpu. - * This returns the next cpu to check, or nr_cpu_ids if the loop - * is complete. - * - * rq->rt.push_cpu holds the last cpu returned by this function, - * or if this is the first instance, it must hold rq->cpu. - */ -static int rto_next_cpu(struct rq *rq) -{ - int prev_cpu = rq->rt.push_cpu; - int cpu; - - cpu = cpumask_next(prev_cpu, rq->rd->rto_mask); - - /* - * If the previous cpu is less than the rq's CPU, then it already - * passed the end of the mask, and has started from the beginning. - * We end if the next CPU is greater or equal to rq's CPU. - */ - if (prev_cpu < rq->cpu) { - if (cpu >= rq->cpu) - return nr_cpu_ids; - - } else if (cpu >= nr_cpu_ids) { - /* - * We passed the end of the mask, start at the beginning. - * If the result is greater or equal to the rq's CPU, then - * the loop is finished. - */ - cpu = cpumask_first(rq->rd->rto_mask); - if (cpu >= rq->cpu) - return nr_cpu_ids; - } - rq->rt.push_cpu = cpu; - - /* Return cpu to let the caller know if the loop is finished or not */ - return cpu; -} - -static int find_next_push_cpu(struct rq *rq) -{ - struct rq *next_rq; - int cpu; - - while (1) { - cpu = rto_next_cpu(rq); - if (cpu >= nr_cpu_ids) - break; - next_rq = cpu_rq(cpu); - - /* Make sure the next rq can push to this rq */ - if (next_rq->rt.highest_prio.next < rq->rt.highest_prio.curr) - break; - } - - return cpu; -} - -#define RT_PUSH_IPI_EXECUTING 1 -#define RT_PUSH_IPI_RESTART 2 /* * When a high priority task schedules out from a CPU and a lower priority @@ -1948,170 +1874,157 @@ static int find_next_push_cpu(struct rq *rq) * tasks queued on it (overloaded) needs to be notified that a CPU has opened * up that may be able to run one of its non-running queued RT tasks. * - * On large CPU boxes, there's the case that several CPUs could schedule - * a lower priority task at the same time, in which case it will look for - * any overloaded CPUs that it could pull a task from. To do this, the runqueue - * lock must be taken from that overloaded CPU. Having 10s of CPUs all fighting - * for a single overloaded CPU's runqueue lock can produce a large latency. - * (This has actually been observed on large boxes running cyclictest). - * Instead of taking the runqueue lock of the overloaded CPU, each of the - * CPUs that scheduled a lower priority task simply sends an IPI to the - * overloaded CPU. An IPI is much cheaper than taking an runqueue lock with - * lots of contention. The overloaded CPU will look to push its non-running - * RT task off, and if it does, it can then ignore the other IPIs coming - * in, and just pass those IPIs off to any other overloaded CPU. + * All CPUs with overloaded RT tasks need to be notified as there is currently + * no way to know which of these CPUs have the highest priority task waiting + * to run. Instead of trying to take a spinlock on each of these CPUs, + * which has shown to cause large latency when done on machines with many + * CPUs, sending an IPI to the CPUs to have them push off the overloaded + * RT tasks waiting to run. * - * When a CPU schedules a lower priority task, it only sends an IPI to - * the "next" CPU that has overloaded RT tasks. This prevents IPI storms, - * as having 10 CPUs scheduling lower priority tasks and 10 CPUs with - * RT overloaded tasks, would cause 100 IPIs to go out at once. + * Just sending an IPI to each of the CPUs is also an issue, as on large + * count CPU machines, this can cause an IPI storm on a CPU, especially + * if its the only CPU with multiple RT tasks queued, and a large number + * of CPUs scheduling a lower priority task at the same time. * - * The overloaded RT CPU, when receiving an IPI, will try to push off its - * overloaded RT tasks and then send an IPI to the next CPU that has - * overloaded RT tasks. This stops when all CPUs with overloaded RT tasks - * have completed. Just because a CPU may have pushed off its own overloaded - * RT task does not mean it should stop sending the IPI around to other - * overloaded CPUs. There may be another RT task waiting to run on one of - * those CPUs that are of higher priority than the one that was just - * pushed. + * Each root domain has its own irq work function that can iterate over + * all CPUs with RT overloaded tasks. Since all CPUs with overloaded RT + * tassk must be checked if there's one or many CPUs that are lowering + * their priority, there's a single irq work iterator that will try to + * push off RT tasks that are waiting to run. * - * An optimization that could possibly be made is to make a CPU array similar - * to the cpupri array mask of all running RT tasks, but for the overloaded - * case, then the IPI could be sent to only the CPU with the highest priority - * RT task waiting, and that CPU could send off further IPIs to the CPU with - * the next highest waiting task. Since the overloaded case is much less likely - * to happen, the complexity of this implementation may not be worth it. - * Instead, just send an IPI around to all overloaded CPUs. + * When a CPU schedules a lower priority task, it will kick off the + * irq work iterator that will jump to each CPU with overloaded RT tasks. + * As it only takes the first CPU that schedules a lower priority task + * to start the process, the rto_start variable is incremented and if + * the atomic result is one, then that CPU will try to take the rto_lock. + * This prevents high contention on the lock as the process handles all + * CPUs scheduling lower priority tasks. * - * The rq->rt.push_flags holds the status of the IPI that is going around. - * A run queue can only send out a single IPI at a time. The possible flags - * for rq->rt.push_flags are: + * All CPUs that are scheduling a lower priority task will increment the + * rt_loop_next variable. This will make sure that the irq work iterator + * checks all RT overloaded CPUs whenever a CPU schedules a new lower + * priority task, even if the iterator is in the middle of a scan. Incrementing + * the rt_loop_next will cause the iterator to perform another scan. * - * (None or zero): No IPI is going around for the current rq - * RT_PUSH_IPI_EXECUTING: An IPI for the rq is being passed around - * RT_PUSH_IPI_RESTART: The priority of the running task for the rq - * has changed, and the IPI should restart - * circulating the overloaded CPUs again. - * - * rq->rt.push_cpu contains the CPU that is being sent the IPI. It is updated - * before sending to the next CPU. - * - * Instead of having all CPUs that schedule a lower priority task send - * an IPI to the same "first" CPU in the RT overload mask, they send it - * to the next overloaded CPU after their own CPU. This helps distribute - * the work when there's more than one overloaded CPU and multiple CPUs - * scheduling in lower priority tasks. - * - * When a rq schedules a lower priority task than what was currently - * running, the next CPU with overloaded RT tasks is examined first. - * That is, if CPU 1 and 5 are overloaded, and CPU 3 schedules a lower - * priority task, it will send an IPI first to CPU 5, then CPU 5 will - * send to CPU 1 if it is still overloaded. CPU 1 will clear the - * rq->rt.push_flags if RT_PUSH_IPI_RESTART is not set. - * - * The first CPU to notice IPI_RESTART is set, will clear that flag and then - * send an IPI to the next overloaded CPU after the rq->cpu and not the next - * CPU after push_cpu. That is, if CPU 1, 4 and 5 are overloaded when CPU 3 - * schedules a lower priority task, and the IPI_RESTART gets set while the - * handling is being done on CPU 5, it will clear the flag and send it back to - * CPU 4 instead of CPU 1. - * - * Note, the above logic can be disabled by turning off the sched_feature - * RT_PUSH_IPI. Then the rq lock of the overloaded CPU will simply be - * taken by the CPU requesting a pull and the waiting RT task will be pulled - * by that CPU. This may be fine for machines with few CPUs. */ -static void tell_cpu_to_push(struct rq *rq) +static int rto_next_cpu(struct rq *rq) { + struct root_domain *rd = rq->rd; + int next; int cpu; - if (rq->rt.push_flags & RT_PUSH_IPI_EXECUTING) { - raw_spin_lock(&rq->rt.push_lock); - /* Make sure it's still executing */ - if (rq->rt.push_flags & RT_PUSH_IPI_EXECUTING) { - /* - * Tell the IPI to restart the loop as things have - * changed since it started. - */ - rq->rt.push_flags |= RT_PUSH_IPI_RESTART; - raw_spin_unlock(&rq->rt.push_lock); - return; - } - raw_spin_unlock(&rq->rt.push_lock); + /* + * When starting the IPI RT pushing, the rto_cpu is set to -1, + * rt_next_cpu() will simply return the first CPU found in + * the rto_mask. + * + * If rto_next_cpu() is called with rto_cpu is a valid cpu, it + * will return the next CPU found in the rto_mask. + * + * If there are no more CPUs left in the rto_mask, then a check is made + * against rto_loop and rto_loop_next. rto_loop is only updated with + * the rto_lock held, but any CPU may increment the rto_loop_next + * without any locking. + */ + for (;;) { + + /* When rto_cpu is -1 this acts like cpumask_first() */ + cpu = cpumask_next(rd->rto_cpu, rd->rto_mask); + + rd->rto_cpu = cpu; + + if (cpu < nr_cpu_ids) + return cpu; + + rd->rto_cpu = -1; + + /* + * ACQUIRE ensures we see the @rto_mask changes + * made prior to the @next value observed. + * + * Matches WMB in rt_set_overload(). + */ + next = atomic_read_acquire(&rd->rto_loop_next); + + if (rd->rto_loop == next) + break; + + rd->rto_loop = next; } - /* When here, there's no IPI going around */ + return -1; +} - rq->rt.push_cpu = rq->cpu; - cpu = find_next_push_cpu(rq); - if (cpu >= nr_cpu_ids) +static inline bool rto_start_trylock(atomic_t *v) +{ + return !atomic_cmpxchg_acquire(v, 0, 1); +} + +static inline void rto_start_unlock(atomic_t *v) +{ + atomic_set_release(v, 0); +} + +static void tell_cpu_to_push(struct rq *rq) +{ + int cpu = -1; + + /* Keep the loop going if the IPI is currently active */ + atomic_inc(&rq->rd->rto_loop_next); + + /* Only one CPU can initiate a loop at a time */ + if (!rto_start_trylock(&rq->rd->rto_loop_start)) return; - rq->rt.push_flags = RT_PUSH_IPI_EXECUTING; + raw_spin_lock(&rq->rd->rto_lock); - irq_work_queue_on(&rq->rt.push_work, cpu); + /* + * The rto_cpu is updated under the lock, if it has a valid cpu + * then the IPI is still running and will continue due to the + * update to loop_next, and nothing needs to be done here. + * Otherwise it is finishing up and an ipi needs to be sent. + */ + if (rq->rd->rto_cpu < 0) + cpu = rto_next_cpu(rq); + + raw_spin_unlock(&rq->rd->rto_lock); + + rto_start_unlock(&rq->rd->rto_loop_start); + + if (cpu >= 0) + irq_work_queue_on(&rq->rd->rto_push_work, cpu); } /* Called from hardirq context */ -static void try_to_push_tasks(void *arg) +void rto_push_irq_work_func(struct irq_work *work) { - struct rt_rq *rt_rq = arg; - struct rq *rq, *src_rq; - int this_cpu; + struct rq *rq; int cpu; - this_cpu = rt_rq->push_cpu; + rq = this_rq(); - /* Paranoid check */ - BUG_ON(this_cpu != smp_processor_id()); - - rq = cpu_rq(this_cpu); - src_rq = rq_of_rt_rq(rt_rq); - -again: + /* + * We do not need to grab the lock to check for has_pushable_tasks. + * When it gets updated, a check is made if a push is possible. + */ if (has_pushable_tasks(rq)) { raw_spin_lock(&rq->lock); - push_rt_task(rq); + push_rt_tasks(rq); raw_spin_unlock(&rq->lock); } + raw_spin_lock(&rq->rd->rto_lock); + /* Pass the IPI to the next rt overloaded queue */ - raw_spin_lock(&rt_rq->push_lock); - /* - * If the source queue changed since the IPI went out, - * we need to restart the search from that CPU again. - */ - if (rt_rq->push_flags & RT_PUSH_IPI_RESTART) { - rt_rq->push_flags &= ~RT_PUSH_IPI_RESTART; - rt_rq->push_cpu = src_rq->cpu; - } + cpu = rto_next_cpu(rq); - cpu = find_next_push_cpu(src_rq); + raw_spin_unlock(&rq->rd->rto_lock); - if (cpu >= nr_cpu_ids) - rt_rq->push_flags &= ~RT_PUSH_IPI_EXECUTING; - raw_spin_unlock(&rt_rq->push_lock); - - if (cpu >= nr_cpu_ids) + if (cpu < 0) return; - /* - * It is possible that a restart caused this CPU to be - * chosen again. Don't bother with an IPI, just see if we - * have more to push. - */ - if (unlikely(cpu == rq->cpu)) - goto again; - /* Try the next RT overloaded CPU */ - irq_work_queue_on(&rt_rq->push_work, cpu); -} - -static void push_irq_work_func(struct irq_work *work) -{ - struct rt_rq *rt_rq = container_of(work, struct rt_rq, push_work); - - try_to_push_tasks(rt_rq); + irq_work_queue_on(&rq->rd->rto_push_work, cpu); } #endif /* HAVE_RT_PUSH_IPI */ diff --git a/kernel/sched/sched.h b/kernel/sched/sched.h index dbd5f0251e2f..220f10c3848b 100644 --- a/kernel/sched/sched.h +++ b/kernel/sched/sched.h @@ -502,7 +502,7 @@ static inline int rt_bandwidth_enabled(void) } /* RT IPI pull logic requires IRQ_WORK */ -#ifdef CONFIG_IRQ_WORK +#if defined(CONFIG_IRQ_WORK) && defined(CONFIG_SMP) # define HAVE_RT_PUSH_IPI #endif @@ -524,12 +524,6 @@ struct rt_rq { unsigned long rt_nr_total; int overloaded; struct plist_head pushable_tasks; -#ifdef HAVE_RT_PUSH_IPI - int push_flags; - int push_cpu; - struct irq_work push_work; - raw_spinlock_t push_lock; -#endif #endif /* CONFIG_SMP */ int rt_queued; @@ -638,6 +632,19 @@ struct root_domain { struct dl_bw dl_bw; struct cpudl cpudl; +#ifdef HAVE_RT_PUSH_IPI + /* + * For IPI pull requests, loop across the rto_mask. + */ + struct irq_work rto_push_work; + raw_spinlock_t rto_lock; + /* These are only updated and read within rto_lock */ + int rto_loop; + int rto_cpu; + /* These atomics are updated outside of a lock */ + atomic_t rto_loop_next; + atomic_t rto_loop_start; +#endif /* * The "RT overload" flag: it gets set if a CPU has more than * one runnable RT task. @@ -655,6 +662,9 @@ extern void init_defrootdomain(void); extern int sched_init_domains(const struct cpumask *cpu_map); extern void rq_attach_root(struct rq *rq, struct root_domain *rd); +#ifdef HAVE_RT_PUSH_IPI +extern void rto_push_irq_work_func(struct irq_work *work); +#endif #endif /* CONFIG_SMP */ /* diff --git a/kernel/sched/topology.c b/kernel/sched/topology.c index 6798276d29af..c88479dd4f5f 100644 --- a/kernel/sched/topology.c +++ b/kernel/sched/topology.c @@ -269,6 +269,13 @@ static int init_rootdomain(struct root_domain *rd) if (!zalloc_cpumask_var(&rd->rto_mask, GFP_KERNEL)) goto free_dlo_mask; +#ifdef HAVE_RT_PUSH_IPI + rd->rto_cpu = -1; + raw_spin_lock_init(&rd->rto_lock); + init_irq_work(&rd->rto_push_work, rto_push_irq_work_func); + rd->rto_push_work.flags |= IRQ_WORK_HARD_IRQ; +#endif + init_dl_bw(&rd->dl_bw); if (cpudl_init(&rd->cpudl) != 0) goto free_rto_mask; diff --git a/kernel/time/tick-internal.h b/kernel/time/tick-internal.h index a48132182ed8..e277284c2831 100644 --- a/kernel/time/tick-internal.h +++ b/kernel/time/tick-internal.h @@ -151,11 +151,10 @@ static inline void tick_nohz_init(void) { } #ifdef CONFIG_NO_HZ_COMMON extern unsigned long tick_nohz_active; extern void timers_update_nohz(void); - -#ifdef CONFIG_SMP +# ifdef CONFIG_SMP extern struct static_key_false timers_migration_enabled; -#endif -#else +# endif +#else /* CONFIG_NO_HZ_COMMON */ static inline void timers_update_nohz(void) { } #define tick_nohz_active (0) #endif diff --git a/kernel/time/timer.c b/kernel/time/timer.c index a116521f2d99..40ac38728b7a 100644 --- a/kernel/time/timer.c +++ b/kernel/time/timer.c @@ -276,14 +276,8 @@ static inline bool is_timers_nohz_active(void) { return static_branch_unlikely(&timers_nohz_active); } - #else - -static inline bool is_timers_nohz_active(void) -{ - return false; -} - +static inline bool is_timers_nohz_active(void) { return false; } #endif /* NO_HZ_COMMON */ static unsigned long round_jiffies_common(unsigned long j, int cpu, diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c index f78a1ad89f82..8c862ea52171 100644 --- a/kernel/trace/ring_buffer.c +++ b/kernel/trace/ring_buffer.c @@ -2246,7 +2246,7 @@ rb_move_tail(struct ring_buffer_per_cpu *cpu_buffer, } /* Slow path, do not inline */ -static struct noinline ring_buffer_event * +static noinline struct ring_buffer_event * rb_add_time_stamp(struct ring_buffer_event *event, u64 delta, bool abs) { if (abs) @@ -2519,10 +2519,6 @@ rb_update_write_stamp(struct ring_buffer_per_cpu *cpu_buffer, { u64 delta; - /* In TIME_STAMP mode, write_stamp is unused, nothing to do */ - if (event->type_len == RINGBUF_TYPE_TIME_STAMP) - return; - /* * The event first in the commit queue updates the * time stamp. @@ -2538,6 +2534,9 @@ rb_update_write_stamp(struct ring_buffer_per_cpu *cpu_buffer, else if (event->type_len == RINGBUF_TYPE_TIME_EXTEND) { delta = ring_buffer_event_time_stamp(event); cpu_buffer->write_stamp += delta; + } else if (event->type_len == RINGBUF_TYPE_TIME_STAMP) { + delta = ring_buffer_event_time_stamp(event); + cpu_buffer->write_stamp = delta; } else cpu_buffer->write_stamp += event->time_delta; } @@ -3459,7 +3458,8 @@ rb_update_read_stamp(struct ring_buffer_per_cpu *cpu_buffer, return; case RINGBUF_TYPE_TIME_STAMP: - /* In TIME_STAMP mode, write_stamp is unused, nothing to do */ + delta = ring_buffer_event_time_stamp(event); + cpu_buffer->read_stamp = delta; return; case RINGBUF_TYPE_DATA: @@ -3488,7 +3488,8 @@ rb_update_iter_read_stamp(struct ring_buffer_iter *iter, return; case RINGBUF_TYPE_TIME_STAMP: - /* In TIME_STAMP mode, write_stamp is unused, nothing to do */ + delta = ring_buffer_event_time_stamp(event); + iter->read_stamp = delta; return; case RINGBUF_TYPE_DATA: diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index a0240cf373a2..2ff4998b50dd 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -4548,6 +4548,9 @@ static const char readme_msg[] = #ifdef CONFIG_X86_64 " x86-tsc: TSC cycle counter\n" #endif + "\n timestamp_mode\t-view the mode used to timestamp events\n" + " delta: Delta difference against a buffer-wide timestamp\n" + " absolute: Absolute (standalone) timestamp\n" "\n trace_marker\t\t- Writes into this file writes into the kernel buffer\n" "\n trace_marker_raw\t\t- Writes into this file writes binary data into the kernel buffer\n" " tracing_cpumask\t- Limit which CPUs to trace\n" @@ -4724,8 +4727,9 @@ static const char readme_msg[] = "\t .sym display an address as a symbol\n" "\t .sym-offset display an address as a symbol and offset\n" "\t .execname display a common_pid as a program name\n" - "\t .syscall display a syscall id as a syscall name\n\n" - "\t .log2 display log2 value rather than raw number\n\n" + "\t .syscall display a syscall id as a syscall name\n" + "\t .log2 display log2 value rather than raw number\n" + "\t .usecs display a $common_timestamp in microseconds\n\n" "\t The 'pause' parameter can be used to pause an existing hist\n" "\t trigger or to start a hist trigger but not log any events\n" "\t until told to do so. 'continue' can be used to start or\n" @@ -6315,6 +6319,40 @@ static int tracing_clock_open(struct inode *inode, struct file *file) return ret; } +static int tracing_time_stamp_mode_show(struct seq_file *m, void *v) +{ + struct trace_array *tr = m->private; + + mutex_lock(&trace_types_lock); + + if (ring_buffer_time_stamp_abs(tr->trace_buffer.buffer)) + seq_puts(m, "delta [absolute]\n"); + else + seq_puts(m, "[delta] absolute\n"); + + mutex_unlock(&trace_types_lock); + + return 0; +} + +static int tracing_time_stamp_mode_open(struct inode *inode, struct file *file) +{ + struct trace_array *tr = inode->i_private; + int ret; + + if (tracing_disabled) + return -ENODEV; + + if (trace_array_get(tr)) + return -ENODEV; + + ret = single_open(file, tracing_time_stamp_mode_show, inode->i_private); + if (ret < 0) + trace_array_put(tr); + + return ret; +} + int tracing_set_time_stamp_abs(struct trace_array *tr, bool abs) { int ret = 0; @@ -6336,16 +6374,9 @@ int tracing_set_time_stamp_abs(struct trace_array *tr, bool abs) ring_buffer_set_time_stamp_abs(tr->trace_buffer.buffer, abs); - /* - * New timestamps may not be consistent with the previous setting. - * Reset the buffer so that it doesn't have incomparable timestamps. - */ - tracing_reset_online_cpus(&tr->trace_buffer); - #ifdef CONFIG_TRACER_MAX_TRACE if (tr->max_buffer.buffer) ring_buffer_set_time_stamp_abs(tr->max_buffer.buffer, abs); - tracing_reset_online_cpus(&tr->max_buffer); #endif out: mutex_unlock(&trace_types_lock); @@ -6600,6 +6631,13 @@ static const struct file_operations trace_clock_fops = { .write = tracing_clock_write, }; +static const struct file_operations trace_time_stamp_mode_fops = { + .open = tracing_time_stamp_mode_open, + .read = seq_read, + .llseek = seq_lseek, + .release = tracing_single_release_tr, +}; + #ifdef CONFIG_TRACER_SNAPSHOT static const struct file_operations snapshot_fops = { .open = tracing_snapshot_open, @@ -7928,6 +7966,9 @@ init_tracer_tracefs(struct trace_array *tr, struct dentry *d_tracer) trace_create_file("tracing_on", 0644, d_tracer, tr, &rb_simple_fops); + trace_create_file("timestamp_mode", 0444, d_tracer, tr, + &trace_time_stamp_mode_fops); + create_trace_options_dir(tr); #if defined(CONFIG_TRACER_MAX_TRACE) || defined(CONFIG_HWLAT_TRACER) diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c index e884d5d78551..eb821cd223b1 100644 --- a/kernel/trace/trace_events_hist.c +++ b/kernel/trace/trace_events_hist.c @@ -66,6 +66,8 @@ struct hist_field { struct hist_trigger_data *hist_data; struct hist_var var; enum field_op_id operator; + char *system; + char *event_name; char *name; unsigned int var_idx; unsigned int var_ref_idx; @@ -223,11 +225,10 @@ enum hist_field_flags { HIST_FIELD_FL_TIMESTAMP = 1 << 10, HIST_FIELD_FL_TIMESTAMP_USECS = 1 << 11, HIST_FIELD_FL_VAR = 1 << 12, - HIST_FIELD_FL_VAR_ONLY = 1 << 13, - HIST_FIELD_FL_EXPR = 1 << 14, - HIST_FIELD_FL_VAR_REF = 1 << 15, - HIST_FIELD_FL_CPU = 1 << 16, - HIST_FIELD_FL_ALIAS = 1 << 17, + HIST_FIELD_FL_EXPR = 1 << 13, + HIST_FIELD_FL_VAR_REF = 1 << 14, + HIST_FIELD_FL_CPU = 1 << 15, + HIST_FIELD_FL_ALIAS = 1 << 16, }; struct var_defs { @@ -273,7 +274,6 @@ struct hist_trigger_data { unsigned int n_keys; unsigned int n_fields; unsigned int n_vars; - unsigned int n_var_only; unsigned int key_size; struct tracing_map_sort_key sort_keys[TRACING_MAP_SORT_KEYS_MAX]; unsigned int n_sort_keys; @@ -575,7 +575,7 @@ static const char *synth_field_fmt(char *type) fmt = "%lu"; else if (strcmp(type, "pid_t") == 0) fmt = "%d"; - else if (strstr(type, "[") == 0) + else if (strchr(type, '[') != NULL) fmt = "%s"; return fmt; @@ -859,7 +859,6 @@ static struct synth_event *find_synth_event(const char *name) return NULL; } -/* This function releases synth_event_mutex */ static int register_synth_event(struct synth_event *event) { struct trace_event_call *call = &event->call; @@ -894,14 +893,7 @@ static int register_synth_event(struct synth_event *event) call->data = event; call->tp = event->tp; - /* - * trace_add_event_call() grabs event_mutex, but that can - * deadlock with a hist trigger cmd already holding it that - * can grab synth_event_mutex - */ - mutex_unlock(&synth_event_mutex); ret = trace_add_event_call(call); - mutex_lock(&synth_event_mutex); if (ret) { pr_warn("Failed to register synthetic event: %s\n", trace_event_name(call)); @@ -910,9 +902,7 @@ static int register_synth_event(struct synth_event *event) ret = set_synth_event_print_fmt(call); if (ret < 0) { - mutex_unlock(&synth_event_mutex); trace_remove_event_call(call); - mutex_lock(&synth_event_mutex); goto err; } out: @@ -922,42 +912,16 @@ static int register_synth_event(struct synth_event *event) goto out; } -/* This function releases synth_event_mutex */ static int unregister_synth_event(struct synth_event *event) { struct trace_event_call *call = &event->call; int ret; - mutex_unlock(&synth_event_mutex); ret = trace_remove_event_call(call); - mutex_lock(&synth_event_mutex); return ret; } -static int remove_synth_event(struct synth_event *event) -{ - int ret = unregister_synth_event(event); - - if (!ret) - list_del(&event->list); - - return ret; -} - -static int add_synth_event(struct synth_event *event) -{ - int ret; - - ret = register_synth_event(event); - if (ret) - return ret; - - list_add(&event->list, &synth_event_list); - - return 0; -} - static void free_synth_event(struct synth_event *event) { unsigned int i; @@ -995,7 +959,7 @@ static struct synth_event *alloc_synth_event(char *event_name, int n_fields, goto out; } - event->fields = kcalloc(n_fields, sizeof(event->fields), GFP_KERNEL); + event->fields = kcalloc(n_fields, sizeof(*event->fields), GFP_KERNEL); if (!event->fields) { free_synth_event(event); event = ERR_PTR(-ENOMEM); @@ -1025,7 +989,6 @@ struct hist_var_data { struct hist_trigger_data *hist_data; }; -/* This function releases synth_event_mutex */ static int create_synth_event(int argc, char **argv) { struct synth_field *field, *fields[SYNTH_FIELDS_MAX]; @@ -1057,14 +1020,14 @@ static int create_synth_event(int argc, char **argv) if (event) { if (delete_event) { if (event->ref) { + event = NULL; ret = -EBUSY; goto out; } - ret = remove_synth_event(event); - if (!ret) - free_synth_event(event); + list_del(&event->list); goto out; } + event = NULL; ret = -EEXIST; goto out; } else if (delete_event) @@ -1103,43 +1066,85 @@ static int create_synth_event(int argc, char **argv) event = NULL; goto err; } - - add_synth_event(event); out: mutex_unlock(&synth_event_mutex); + if (event) { + if (delete_event) { + ret = unregister_synth_event(event); + if (!ret) + free_synth_event(event); + else { + mutex_lock(&synth_event_mutex); + if (!find_synth_event(event->name)) + list_add(&event->list, &synth_event_list); + mutex_unlock(&synth_event_mutex); + } + } else { + ret = register_synth_event(event); + if (!ret) { + mutex_lock(&synth_event_mutex); + if (!find_synth_event(event->name)) + list_add(&event->list, &synth_event_list); + mutex_unlock(&synth_event_mutex); + } else + free_synth_event(event); + } + } + return ret; err: + mutex_unlock(&synth_event_mutex); + for (i = 0; i < n_fields; i++) free_synth_field(fields[i]); free_synth_event(event); - goto out; + return ret; } -/* This function releases synth_event_mutex */ static int release_all_synth_events(void) { + struct list_head release_events; struct synth_event *event, *e; - int ret = 0; + int ret = 0, err = 0; + + INIT_LIST_HEAD(&release_events); mutex_lock(&synth_event_mutex); list_for_each_entry(event, &synth_event_list, list) { if (event->ref) { - ret = -EBUSY; - goto out; + mutex_unlock(&synth_event_mutex); + return -EBUSY; } } list_for_each_entry_safe(event, e, &synth_event_list, list) { - ret = remove_synth_event(event); - if (!ret) - free_synth_event(event); + list_del(&event->list); + list_add(&event->list, &release_events); } - out: + mutex_unlock(&synth_event_mutex); + list_for_each_entry_safe(event, e, &release_events, list) { + list_del(&event->list); + + ret = unregister_synth_event(event); + if (ret == 0) + free_synth_event(event); + else { + err = ret; + mutex_lock(&synth_event_mutex); + if (!find_synth_event(event->name)) + list_add(&event->list, &synth_event_list); + mutex_unlock(&synth_event_mutex); + } + } + + if (err) + ret = err; + return ret; } @@ -1244,9 +1249,10 @@ static u64 hist_field_cpu(struct hist_field *hist_field, return cpu; } -static struct hist_field *check_var_ref(struct hist_field *hist_field, - struct hist_trigger_data *var_data, - unsigned int var_idx) +static struct hist_field * +check_field_for_var_ref(struct hist_field *hist_field, + struct hist_trigger_data *var_data, + unsigned int var_idx) { struct hist_field *found = NULL; @@ -1260,27 +1266,52 @@ static struct hist_field *check_var_ref(struct hist_field *hist_field, return found; } +static struct hist_field * +check_field_for_var_refs(struct hist_trigger_data *hist_data, + struct hist_field *hist_field, + struct hist_trigger_data *var_data, + unsigned int var_idx, + unsigned int level) +{ + struct hist_field *found = NULL; + unsigned int i; + + if (level > 2) + return found; + + if (!hist_field) + return found; + + found = check_field_for_var_ref(hist_field, var_data, var_idx); + if (found) + return found; + + for (i = 0; i < HIST_FIELD_OPERANDS_MAX; i++) { + struct hist_field *operand; + + operand = hist_field->operands[i]; + found = check_field_for_var_refs(hist_data, operand, var_data, + var_idx, level + 1); + if (found) + return found; + } + + return found; +} + static struct hist_field *find_var_ref(struct hist_trigger_data *hist_data, struct hist_trigger_data *var_data, unsigned int var_idx) { struct hist_field *hist_field, *found = NULL; - unsigned int i, j; + unsigned int i; for_each_hist_field(i, hist_data) { hist_field = hist_data->fields[i]; - found = check_var_ref(hist_field, var_data, var_idx); + found = check_field_for_var_refs(hist_data, hist_field, + var_data, var_idx, 0); if (found) return found; - - for (j = 0; j < HIST_FIELD_OPERANDS_MAX; j++) { - struct hist_field *operand; - - operand = hist_field->operands[j]; - found = check_var_ref(operand, var_data, var_idx); - if (found) - return found; - } } return found; @@ -1293,6 +1324,10 @@ static struct hist_field *find_any_var_ref(struct hist_trigger_data *hist_data, struct hist_field *found = NULL; struct hist_var_data *var_data; + found = find_var_ref(hist_data, hist_data, var_idx); + if (found) + return found; + list_for_each_entry(var_data, &tr->hist_vars, list) { found = find_var_ref(var_data->hist_data, hist_data, var_idx); if (found) @@ -1336,27 +1371,41 @@ static struct hist_var_data *find_hist_vars(struct hist_trigger_data *hist_data) return found; } +static bool field_has_hist_vars(struct hist_field *hist_field, + unsigned int level) +{ + int i; + + if (level > 2) + return false; + + if (!hist_field) + return false; + + if (hist_field->flags & HIST_FIELD_FL_VAR || + hist_field->flags & HIST_FIELD_FL_VAR_REF) + return true; + + for (i = 0; i < HIST_FIELD_OPERANDS_MAX; i++) { + struct hist_field *operand; + + operand = hist_field->operands[i]; + if (field_has_hist_vars(operand, level + 1)) + return true; + } + + return false; +} + static bool has_hist_vars(struct hist_trigger_data *hist_data) { struct hist_field *hist_field; - int i, j; + int i; for_each_hist_field(i, hist_data) { hist_field = hist_data->fields[i]; - if (hist_field && - (hist_field->flags & HIST_FIELD_FL_VAR || - hist_field->flags & HIST_FIELD_FL_VAR_REF)) + if (field_has_hist_vars(hist_field, 0)) return true; - - for (j = 0; j < HIST_FIELD_OPERANDS_MAX; j++) { - struct hist_field *operand; - - operand = hist_field->operands[j]; - if (operand && - (operand->flags & HIST_FIELD_FL_VAR || - operand->flags & HIST_FIELD_FL_VAR_REF)) - return true; - } } return false; @@ -1423,17 +1472,22 @@ static struct hist_field *find_var_field(struct hist_trigger_data *hist_data, return found; } -static struct hist_field *find_var(struct trace_event_file *file, +static struct hist_field *find_var(struct hist_trigger_data *hist_data, + struct trace_event_file *file, const char *var_name) { - struct hist_trigger_data *hist_data; + struct hist_trigger_data *test_data; struct event_trigger_data *test; struct hist_field *hist_field; + hist_field = find_var_field(hist_data, var_name); + if (hist_field) + return hist_field; + list_for_each_entry_rcu(test, &file->triggers, list) { if (test->cmd_ops->trigger_type == ETT_EVENT_HIST) { - hist_data = test->private_data; - hist_field = find_var_field(hist_data, var_name); + test_data = test->private_data; + hist_field = find_var_field(test_data, var_name); if (hist_field) return hist_field; } @@ -1443,25 +1497,33 @@ static struct hist_field *find_var(struct trace_event_file *file, } static struct trace_event_file *find_var_file(struct trace_array *tr, - const char *system, - const char *event_name, - const char *var_name) + char *system, + char *event_name, + char *var_name) { struct hist_trigger_data *var_hist_data; struct hist_var_data *var_data; struct trace_event_call *call; - struct trace_event_file *file; + struct trace_event_file *file, *found = NULL; const char *name; list_for_each_entry(var_data, &tr->hist_vars, list) { var_hist_data = var_data->hist_data; file = var_hist_data->event_file; + if (file == found) + continue; call = file->event_call; name = trace_event_name(call); if (!system || !event_name) { - if (find_var(file, var_name)) - return file; + if (find_var(var_hist_data, file, var_name)) { + if (found) { + hist_err_event("Variable name not unique, need to use fully qualified name (subsys.event.var) for variable: ", system, event_name, var_name); + return NULL; + } + + found = file; + } continue; } @@ -1470,10 +1532,11 @@ static struct trace_event_file *find_var_file(struct trace_array *tr, if (strcmp(system, call->class->system) != 0) continue; - return file; + found = file; + break; } - return NULL; + return found; } static struct hist_field *find_file_var(struct trace_event_file *file, @@ -1495,14 +1558,55 @@ static struct hist_field *find_file_var(struct trace_event_file *file, return NULL; } -static struct hist_field *find_event_var(struct trace_array *tr, - const char *system, - const char *event_name, - const char *var_name) +static struct hist_field * +find_match_var(struct hist_trigger_data *hist_data, char *var_name) { + struct trace_array *tr = hist_data->event_file->tr; + struct hist_field *hist_field, *found = NULL; + struct trace_event_file *file; + unsigned int i; + + for (i = 0; i < hist_data->n_actions; i++) { + struct action_data *data = hist_data->actions[i]; + + if (data->fn == action_trace) { + char *system = data->onmatch.match_event_system; + char *event_name = data->onmatch.match_event; + + file = find_var_file(tr, system, event_name, var_name); + if (!file) + continue; + hist_field = find_file_var(file, var_name); + if (hist_field) { + if (found) { + hist_err_event("Variable name not unique, need to use fully qualified name (subsys.event.var) for variable: ", system, event_name, var_name); + return ERR_PTR(-EINVAL); + } + + found = hist_field; + } + } + } + return found; +} + +static struct hist_field *find_event_var(struct hist_trigger_data *hist_data, + char *system, + char *event_name, + char *var_name) +{ + struct trace_array *tr = hist_data->event_file->tr; struct hist_field *hist_field = NULL; struct trace_event_file *file; + if (!system || !event_name) { + hist_field = find_match_var(hist_data, var_name); + if (IS_ERR(hist_field)) + return NULL; + if (hist_field) + return hist_field; + } + file = find_var_file(tr, system, event_name, var_name); if (!file) return NULL; @@ -1596,8 +1700,19 @@ static const char *hist_field_name(struct hist_field *field, else if (field->flags & HIST_FIELD_FL_CPU) field_name = "cpu"; else if (field->flags & HIST_FIELD_FL_EXPR || - field->flags & HIST_FIELD_FL_VAR_REF) - field_name = field->name; + field->flags & HIST_FIELD_FL_VAR_REF) { + if (field->system) { + static char full_name[MAX_FILTER_STR_VAL]; + + strcat(full_name, field->system); + strcat(full_name, "."); + strcat(full_name, field->event_name); + strcat(full_name, "."); + strcat(full_name, field->name); + field_name = full_name; + } else + field_name = field->name; + } if (field_name == NULL) field_name = ""; @@ -1762,6 +1877,7 @@ static int parse_assignment(char *str, struct hist_trigger_attrs *attrs) char *assignment; if (attrs->n_assignments == TRACING_MAP_VARS_MAX) { + hist_err("Too many variables defined: ", str); ret = -EINVAL; goto out; } @@ -2178,34 +2294,60 @@ static void destroy_hist_fields(struct hist_trigger_data *hist_data) } static int init_var_ref(struct hist_field *ref_field, - struct hist_field *var_field) + struct hist_field *var_field, + char *system, char *event_name) { + int err = 0; + ref_field->var.idx = var_field->var.idx; ref_field->var.hist_data = var_field->hist_data; ref_field->size = var_field->size; ref_field->is_signed = var_field->is_signed; + if (system) { + ref_field->system = kstrdup(system, GFP_KERNEL); + if (!ref_field->system) + return -ENOMEM; + } + + if (event_name) { + ref_field->event_name = kstrdup(event_name, GFP_KERNEL); + if (!ref_field->event_name) { + err = -ENOMEM; + goto free; + } + } + ref_field->name = kstrdup(var_field->var.name, GFP_KERNEL); - if (!ref_field->name) - return -ENOMEM; + if (!ref_field->name) { + err = -ENOMEM; + goto free; + } ref_field->type = kstrdup(var_field->type, GFP_KERNEL); if (!ref_field->type) { - kfree(ref_field->name); - return -ENOMEM; + err = -ENOMEM; + goto free; } + out: + return err; + free: + kfree(ref_field->system); + kfree(ref_field->event_name); + kfree(ref_field->name); - return 0; + goto out; } -static struct hist_field *create_var_ref(struct hist_field *var_field) +static struct hist_field *create_var_ref(struct hist_field *var_field, + char *system, char *event_name) { unsigned long flags = HIST_FIELD_FL_VAR_REF; struct hist_field *ref_field; ref_field = create_hist_field(var_field->hist_data, NULL, flags, NULL); if (ref_field) { - if (init_var_ref(ref_field, var_field)) { + if (init_var_ref(ref_field, var_field, system, event_name)) { destroy_hist_field(ref_field, 0); return NULL; } @@ -2262,7 +2404,7 @@ static char *local_field_var_ref(struct hist_trigger_data *hist_data, return field_name_from_var(hist_data, var_name); } -static struct hist_field *parse_var_ref(struct trace_array *tr, +static struct hist_field *parse_var_ref(struct hist_trigger_data *hist_data, char *system, char *event_name, char *var_name) { @@ -2273,9 +2415,9 @@ static struct hist_field *parse_var_ref(struct trace_array *tr, var_name++; - var_field = find_event_var(tr, system, event_name, var_name); + var_field = find_event_var(hist_data, system, event_name, var_name); if (var_field) - ref_field = create_var_ref(var_field); + ref_field = create_var_ref(var_field, system, event_name); if (!ref_field) hist_err_event("Couldn't find variable: $", @@ -2343,8 +2485,7 @@ static struct hist_field *create_alias(struct hist_trigger_data *hist_data, char *var_name) { struct hist_field *alias = NULL; - unsigned long flags = HIST_FIELD_FL_ALIAS | HIST_FIELD_FL_VAR | - HIST_FIELD_FL_VAR_ONLY; + unsigned long flags = HIST_FIELD_FL_ALIAS | HIST_FIELD_FL_VAR; alias = create_hist_field(hist_data, NULL, flags, var_name); if (!alias) @@ -2353,7 +2494,7 @@ static struct hist_field *create_alias(struct hist_trigger_data *hist_data, alias->fn = var_ref->fn; alias->operands[0] = var_ref; - if (init_var_ref(alias, var_ref)) { + if (init_var_ref(alias, var_ref, var_ref->system, var_ref->event_name)) { destroy_hist_field(alias, 0); return NULL; } @@ -2366,7 +2507,6 @@ struct hist_field *parse_atom(struct hist_trigger_data *hist_data, unsigned long *flags, char *var_name) { char *s, *ref_system = NULL, *ref_event = NULL, *ref_var = str; - struct trace_array *tr = hist_data->event_file->tr; struct ftrace_event_field *field = NULL; struct hist_field *hist_field = NULL; int ret = 0; @@ -2391,7 +2531,7 @@ struct hist_field *parse_atom(struct hist_trigger_data *hist_data, s = local_field_var_ref(hist_data, ref_var); if (!s) { - hist_field = parse_var_ref(tr, ref_system, ref_event, ref_var); + hist_field = parse_var_ref(hist_data, ref_system, ref_event, ref_var); if (hist_field) { hist_data->var_refs[hist_data->n_var_refs] = hist_field; hist_field->var_ref_idx = hist_data->n_var_refs++; @@ -2496,6 +2636,7 @@ static struct hist_field *parse_unary(struct hist_trigger_data *hist_data, return expr; free: + destroy_hist_field(expr, 0); return ERR_PTR(ret); } @@ -2714,9 +2855,55 @@ static struct trace_event_file *event_file(struct trace_array *tr, return file; } +static struct hist_field * +find_synthetic_field_var(struct hist_trigger_data *target_hist_data, + char *system, char *event_name, char *field_name) +{ + struct hist_field *event_var; + char *synthetic_name; + + synthetic_name = kzalloc(MAX_FILTER_STR_VAL, GFP_KERNEL); + if (!synthetic_name) + return ERR_PTR(-ENOMEM); + + strcpy(synthetic_name, "synthetic_"); + strcat(synthetic_name, field_name); + + event_var = find_event_var(target_hist_data, system, event_name, synthetic_name); + + kfree(synthetic_name); + + return event_var; +} + +/** + * create_field_var_hist - Automatically create a histogram and var for a field + * @target_hist_data: The target hist trigger + * @subsys_name: Optional subsystem name + * @event_name: Optional event name + * @field_name: The name of the field (and the resulting variable) + * + * Hist trigger actions fetch data from variables, not directly from + * events. However, for convenience, users are allowed to directly + * specify an event field in an action, which will be automatically + * converted into a variable on their behalf. + + * If a user specifies a field on an event that isn't the event the + * histogram currently being defined (the target event histogram), the + * only way that can be accomplished is if a new hist trigger is + * created and the field variable defined on that. + * + * This function creates a new histogram compatible with the target + * event (meaning a histogram with the same key as the target + * histogram), and creates a variable for the specified field, but + * with 'synthetic_' prepended to the variable name in order to avoid + * collision with normal field variables. + * + * Return: The variable created for the field. + */ static struct hist_field * create_field_var_hist(struct hist_trigger_data *target_hist_data, - char *system, char *event_name, char *field_name) + char *subsys_name, char *event_name, char *field_name) { struct trace_array *tr = target_hist_data->event_file->tr; struct hist_field *event_var = ERR_PTR(-EINVAL); @@ -2731,26 +2918,38 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data, if (target_hist_data->n_field_var_hists >= SYNTH_FIELDS_MAX) { hist_err_event("onmatch: Too many field variables defined: ", - system, event_name, field_name); + subsys_name, event_name, field_name); return ERR_PTR(-EINVAL); } - file = event_file(tr, system, event_name); + file = event_file(tr, subsys_name, event_name); if (IS_ERR(file)) { hist_err_event("onmatch: Event file not found: ", - system, event_name, field_name); + subsys_name, event_name, field_name); ret = PTR_ERR(file); return ERR_PTR(ret); } + /* + * Look for a histogram compatible with target. We'll use the + * found histogram specification to create a new matching + * histogram with our variable on it. target_hist_data is not + * yet a registered histogram so we can't use that. + */ hist_data = find_compatible_hist(target_hist_data, file); if (!hist_data) { hist_err_event("onmatch: Matching event histogram not found: ", - system, event_name, field_name); + subsys_name, event_name, field_name); return ERR_PTR(-EINVAL); } + /* See if a synthetic field variable has already been created */ + event_var = find_synthetic_field_var(target_hist_data, subsys_name, + event_name, field_name); + if (event_var && !IS_ERR(event_var)) + return event_var; + var_hist = kzalloc(sizeof(*var_hist), GFP_KERNEL); if (!var_hist) return ERR_PTR(-ENOMEM); @@ -2761,6 +2960,7 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data, return ERR_PTR(-ENOMEM); } + /* Use the same keys as the compatible histogram */ strcat(cmd, "keys="); for_each_hist_key_field(i, hist_data) { @@ -2771,11 +2971,13 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data, first = false; } + /* Create the synthetic field variable specification */ strcat(cmd, ":synthetic_"); strcat(cmd, field_name); strcat(cmd, "="); strcat(cmd, field_name); + /* Use the same filter as the compatible histogram */ saved_filter = find_trigger_filter(hist_data, file); if (saved_filter) { strcat(cmd, " if "); @@ -2789,8 +2991,10 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data, return ERR_PTR(-ENOMEM); } + /* Save the compatible histogram information */ var_hist->hist_data = hist_data; + /* Create the new histogram with our variable */ ret = event_hist_trigger_func(&trigger_hist_cmd, file, "", "hist", cmd); if (ret) { @@ -2798,20 +3002,21 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data, kfree(var_hist->cmd); kfree(var_hist); hist_err_event("onmatch: Couldn't create histogram for field: ", - system, event_name, field_name); + subsys_name, event_name, field_name); return ERR_PTR(ret); } - strcpy(cmd, "synthetic_"); - strcat(cmd, field_name); + kfree(cmd); - event_var = find_event_var(tr, system, event_name, cmd); - if (!event_var) { + /* If we can't find the variable, something went wrong */ + event_var = find_synthetic_field_var(target_hist_data, subsys_name, + event_name, field_name); + if (!event_var || IS_ERR(event_var)) { kfree(cmd); kfree(var_hist->cmd); kfree(var_hist); hist_err_event("onmatch: Couldn't find synthetic variable: ", - system, event_name, field_name); + subsys_name, event_name, field_name); return ERR_PTR(-EINVAL); } @@ -2824,12 +3029,12 @@ create_field_var_hist(struct hist_trigger_data *target_hist_data, static struct hist_field * find_target_event_var(struct hist_trigger_data *hist_data, - char *system, char *event_name, char *var_name) + char *subsys_name, char *event_name, char *var_name) { struct trace_event_file *file = hist_data->event_file; struct hist_field *hist_field = NULL; - if (system) { + if (subsys_name) { struct trace_event_call *call; if (!event_name) @@ -2837,7 +3042,7 @@ find_target_event_var(struct hist_trigger_data *hist_data, call = file->event_call; - if (strcmp(system, call->class->system) != 0) + if (strcmp(subsys_name, call->class->system) != 0) return NULL; if (strcmp(event_name, trace_event_name(call)) != 0) @@ -2904,7 +3109,7 @@ static struct hist_field *create_var(struct hist_trigger_data *hist_data, struct hist_field *var; int idx; - if (find_var(file, name) && !hist_data->remove) { + if (find_var(hist_data, file, name) && !hist_data->remove) { var = ERR_PTR(-EINVAL); goto out; } @@ -2985,13 +3190,33 @@ static struct field_var *create_field_var(struct hist_trigger_data *hist_data, goto out; } -static struct field_var * -create_target_field_var(struct hist_trigger_data *hist_data, - char *system, char *event_name, char *var_name) -{ - struct trace_event_file *file = hist_data->event_file; +/** + * create_target_field_var - Automatically create a variable for a field + * @target_hist_data: The target hist trigger + * @subsys_name: Optional subsystem name + * @event_name: Optional event name + * @var_name: The name of the field (and the resulting variable) + * + * Hist trigger actions fetch data from variables, not directly from + * events. However, for convenience, users are allowed to directly + * specify an event field in an action, which will be automatically + * converted into a variable on their behalf. - if (system) { + * This function creates a field variable with the name var_name on + * the hist trigger currently being defined on the target event. If + * subsys_name and event_name are specified, this function simply + * verifies that they do in fact match the target event subsystem and + * event name. + * + * Return: The variable created for the field. + */ +static struct field_var * +create_target_field_var(struct hist_trigger_data *target_hist_data, + char *subsys_name, char *event_name, char *var_name) +{ + struct trace_event_file *file = target_hist_data->event_file; + + if (subsys_name) { struct trace_event_call *call; if (!event_name) @@ -2999,14 +3224,14 @@ create_target_field_var(struct hist_trigger_data *hist_data, call = file->event_call; - if (strcmp(system, call->class->system) != 0) + if (strcmp(subsys_name, call->class->system) != 0) return NULL; if (strcmp(event_name, trace_event_name(call)) != 0) return NULL; } - return create_field_var(hist_data, file, var_name); + return create_field_var(target_hist_data, file, var_name); } static void onmax_print(struct seq_file *m, @@ -3105,7 +3330,7 @@ static int onmax_create(struct hist_trigger_data *hist_data, if (!ref_field) return -ENOMEM; - if (init_var_ref(ref_field, var_field)) { + if (init_var_ref(ref_field, var_field, NULL, NULL)) { destroy_hist_field(ref_field, 0); ret = -ENOMEM; goto out; @@ -3145,8 +3370,6 @@ static int onmax_create(struct hist_trigger_data *hist_data, kfree(param); } - - hist_data->actions[hist_data->n_actions++] = data; out: return ret; } @@ -3327,7 +3550,6 @@ static struct hist_field * onmatch_find_var(struct hist_trigger_data *hist_data, struct action_data *data, char *system, char *event, char *var) { - struct trace_array *tr = hist_data->event_file->tr; struct hist_field *hist_field; var++; /* skip '$' */ @@ -3339,7 +3561,7 @@ onmatch_find_var(struct hist_trigger_data *hist_data, struct action_data *data, event = data->onmatch.match_event; } - hist_field = find_event_var(tr, system, event, var); + hist_field = find_event_var(hist_data, system, event, var); } if (!hist_field) @@ -3356,19 +3578,36 @@ onmatch_create_field_var(struct hist_trigger_data *hist_data, struct hist_field *hist_field = NULL; struct field_var *field_var; + /* + * First try to create a field var on the target event (the + * currently being defined). This will create a variable for + * unqualified fields on the target event, or if qualified, + * target fields that have qualified names matching the target. + */ field_var = create_target_field_var(hist_data, system, event, var); - if (IS_ERR(field_var)) - goto out; - if (field_var) { + if (field_var && !IS_ERR(field_var)) { save_field_var(hist_data, field_var); hist_field = field_var->var; } else { + field_var = NULL; + /* + * If no explicit system.event is specfied, default to + * looking for fields on the onmatch(system.event.xxx) + * event. + */ if (!system) { system = data->onmatch.match_event_system; event = data->onmatch.match_event; } + /* + * At this point, we're looking at a field on another + * event. Because we can't modify a hist trigger on + * another event to add a variable for a field, we need + * to create a new trigger on that event and create the + * variable at the same time. + */ hist_field = create_field_var_hist(hist_data, system, event, var); if (IS_ERR(hist_field)) goto free; @@ -3441,7 +3680,7 @@ static int onmatch_create(struct hist_trigger_data *hist_data, } if (check_synth_field(event, hist_field, field_pos) == 0) { - var_ref = create_var_ref(hist_field); + var_ref = create_var_ref(hist_field, system, event_name); if (!var_ref) { kfree(p); ret = -ENOMEM; @@ -3470,7 +3709,6 @@ static int onmatch_create(struct hist_trigger_data *hist_data, data->fn = action_trace; data->onmatch.synth_event = event; data->onmatch.var_ref_idx = var_ref_idx; - hist_data->actions[hist_data->n_actions++] = data; event->ref++; out: return ret; @@ -3588,9 +3826,6 @@ static int __create_val_field(struct hist_trigger_data *hist_data, ++hist_data->n_vals; ++hist_data->n_fields; - if (hist_field->flags & HIST_FIELD_FL_VAR_ONLY) - hist_data->n_var_only++; - if (WARN_ON(hist_data->n_vals > TRACING_MAP_VALS_MAX + TRACING_MAP_VARS_MAX)) ret = -EINVAL; out: @@ -3618,19 +3853,15 @@ static int create_var_field(struct hist_trigger_data *hist_data, if (WARN_ON(val_idx >= TRACING_MAP_VALS_MAX + TRACING_MAP_VARS_MAX)) return -EINVAL; - if (find_var(file, var_name) && !hist_data->remove) { + if (find_var(hist_data, file, var_name) && !hist_data->remove) { hist_err("Variable already defined: ", var_name); return -EINVAL; } flags |= HIST_FIELD_FL_VAR; hist_data->n_vars++; - if (hist_data->n_vars > TRACING_MAP_VARS_MAX) { - hist_err("Too many variables defined: ", var_name); + if (WARN_ON(hist_data->n_vars > TRACING_MAP_VARS_MAX)) return -EINVAL; - } - - flags |= HIST_FIELD_FL_VAR_ONLY; return __create_val_field(hist_data, val_idx, file, var_name, expr_str, flags); } @@ -3704,6 +3935,7 @@ static int create_key_field(struct hist_trigger_data *hist_data, } if (hist_field->flags & HIST_FIELD_FL_VAR_REF) { + hist_err("Using variable references as keys not supported: ", field_str); destroy_hist_field(hist_field, 0); ret = -EINVAL; goto out; @@ -3822,6 +4054,12 @@ static int parse_var_defs(struct hist_trigger_data *hist_data) goto free; } + if (n_vars == TRACING_MAP_VARS_MAX) { + hist_err("Too many variables defined: ", var_name); + ret = -EINVAL; + goto free; + } + s = kstrdup(var_name, GFP_KERNEL); if (!s) { ret = -ENOMEM; @@ -3831,15 +4069,13 @@ static int parse_var_defs(struct hist_trigger_data *hist_data) s = kstrdup(field_str, GFP_KERNEL); if (!s) { + kfree(hist_data->attrs->var_defs.name[n_vars]); ret = -ENOMEM; goto free; } hist_data->attrs->var_defs.expr[n_vars++] = s; hist_data->attrs->var_defs.n_vars = n_vars; - - if (n_vars == TRACING_MAP_VARS_MAX) - goto free; } } @@ -3947,7 +4183,7 @@ static int create_sort_keys(struct hist_trigger_data *hist_data) unsigned int idx; hist_field = hist_data->fields[j]; - if (hist_field->flags & HIST_FIELD_FL_VAR_ONLY) + if (hist_field->flags & HIST_FIELD_FL_VAR) continue; idx = k++; @@ -3992,8 +4228,7 @@ static void destroy_actions(struct hist_trigger_data *hist_data) } } -static int create_actions(struct hist_trigger_data *hist_data, - struct trace_event_file *file) +static int parse_actions(struct hist_trigger_data *hist_data) { struct trace_array *tr = hist_data->event_file->tr; struct action_data *data; @@ -4008,26 +4243,49 @@ static int create_actions(struct hist_trigger_data *hist_data, char *action_str = str + strlen("onmatch("); data = onmatch_parse(tr, action_str); - if (IS_ERR(data)) - return PTR_ERR(data); - - ret = onmatch_create(hist_data, file, data); - if (ret) { - onmatch_destroy(data); - return ret; + if (IS_ERR(data)) { + ret = PTR_ERR(data); + break; } + data->fn = action_trace; } else if (strncmp(str, "onmax(", strlen("onmax(")) == 0) { char *action_str = str + strlen("onmax("); data = onmax_parse(action_str); - if (IS_ERR(data)) - return PTR_ERR(data); - - ret = onmax_create(hist_data, data); - if (ret) { - onmax_destroy(data); - return ret; + if (IS_ERR(data)) { + ret = PTR_ERR(data); + break; } + data->fn = onmax_save; + } else { + ret = -EINVAL; + break; + } + + hist_data->actions[hist_data->n_actions++] = data; + } + + return ret; +} + +static int create_actions(struct hist_trigger_data *hist_data, + struct trace_event_file *file) +{ + struct action_data *data; + unsigned int i; + int ret = 0; + + for (i = 0; i < hist_data->attrs->n_actions; i++) { + data = hist_data->actions[i]; + + if (data->fn == action_trace) { + ret = onmatch_create(hist_data, file, data); + if (ret) + return ret; + } else if (data->fn == onmax_save) { + ret = onmax_create(hist_data, data); + if (ret) + return ret; } } @@ -4191,6 +4449,10 @@ create_hist_data(unsigned int map_bits, hist_data->remove = remove; hist_data->event_file = file; + ret = parse_actions(hist_data); + if (ret) + goto free; + ret = create_hist_fields(hist_data, file); if (ret) goto free; @@ -4243,8 +4505,7 @@ static void hist_trigger_elt_update(struct hist_trigger_data *hist_data, if (hist_field->flags & HIST_FIELD_FL_VAR) { var_idx = hist_field->var.idx; tracing_map_set_var(elt, var_idx, hist_val); - if (hist_field->flags & HIST_FIELD_FL_VAR_ONLY) - continue; + continue; } tracing_map_update_sum(elt, i, hist_val); } @@ -4414,7 +4675,12 @@ hist_trigger_entry_print(struct seq_file *m, uval, str); } else if (key_field->flags & HIST_FIELD_FL_EXECNAME) { struct hist_elt_data *elt_data = elt->private_data; - char *comm = elt_data->comm; + char *comm; + + if (WARN_ON_ONCE(!elt_data)) + return; + + comm = elt_data->comm; uval = *(u64 *)(key + key_field->offset); seq_printf(m, "%s: %-16s[%10llu]", field_name, @@ -4459,8 +4725,7 @@ hist_trigger_entry_print(struct seq_file *m, field_name = hist_field_name(hist_data->fields[i], 0); if (hist_data->fields[i]->flags & HIST_FIELD_FL_VAR || - hist_data->fields[i]->flags & HIST_FIELD_FL_EXPR || - hist_data->fields[i]->flags & HIST_FIELD_FL_VAR_REF) + hist_data->fields[i]->flags & HIST_FIELD_FL_EXPR) continue; if (hist_data->fields[i]->flags & HIST_FIELD_FL_HEX) { @@ -4579,7 +4844,8 @@ static void hist_field_print(struct seq_file *m, struct hist_field *hist_field) else if (hist_field->flags & HIST_FIELD_FL_CPU) seq_puts(m, "cpu"); else if (field_name) { - if (hist_field->flags & HIST_FIELD_FL_ALIAS) + if (hist_field->flags & HIST_FIELD_FL_VAR_REF || + hist_field->flags & HIST_FIELD_FL_ALIAS) seq_putc(m, '$'); seq_printf(m, "%s", field_name); } @@ -4597,8 +4863,8 @@ static int event_hist_trigger_print(struct seq_file *m, struct event_trigger_data *data) { struct hist_trigger_data *hist_data = data->private_data; - bool have_var_only = false; struct hist_field *field; + bool have_var = false; unsigned int i; seq_puts(m, "hist:"); @@ -4624,8 +4890,8 @@ static int event_hist_trigger_print(struct seq_file *m, for_each_hist_val_field(i, hist_data) { field = hist_data->fields[i]; - if (field->flags & HIST_FIELD_FL_VAR_ONLY) { - have_var_only = true; + if (field->flags & HIST_FIELD_FL_VAR) { + have_var = true; continue; } @@ -4637,7 +4903,7 @@ static int event_hist_trigger_print(struct seq_file *m, } } - if (have_var_only) { + if (have_var) { unsigned int n = 0; seq_puts(m, ":"); @@ -4645,7 +4911,7 @@ static int event_hist_trigger_print(struct seq_file *m, for_each_hist_val_field(i, hist_data) { field = hist_data->fields[i]; - if (field->flags & HIST_FIELD_FL_VAR_ONLY) { + if (field->flags & HIST_FIELD_FL_VAR) { if (n++) seq_puts(m, ","); hist_field_print(m, field); @@ -4659,8 +4925,8 @@ static int event_hist_trigger_print(struct seq_file *m, struct tracing_map_sort_key *sort_key; unsigned int idx, first_key_idx; - /* skip VAR_ONLY vals */ - first_key_idx = hist_data->n_vals - hist_data->n_var_only; + /* skip VAR vals */ + first_key_idx = hist_data->n_vals - hist_data->n_vars; sort_key = &hist_data->sort_keys[i]; idx = sort_key->field_idx; @@ -4675,7 +4941,7 @@ static int event_hist_trigger_print(struct seq_file *m, seq_puts(m, "hitcount"); else { if (idx >= first_key_idx) - idx += hist_data->n_var_only; + idx += hist_data->n_vars; hist_field_print(m, hist_data->fields[idx]); } @@ -4969,7 +5235,7 @@ static int hist_trigger_enable(struct event_trigger_data *data, { int ret = 0; - list_add_rcu(&data->list, &file->triggers); + list_add_tail_rcu(&data->list, &file->triggers); update_cond_flag(file); @@ -4982,6 +5248,28 @@ static int hist_trigger_enable(struct event_trigger_data *data, return ret; } +static bool have_hist_trigger_match(struct event_trigger_data *data, + struct trace_event_file *file) +{ + struct hist_trigger_data *hist_data = data->private_data; + struct event_trigger_data *test, *named_data = NULL; + bool match = false; + + if (hist_data->attrs->name) + named_data = find_named_trigger(hist_data->attrs->name); + + list_for_each_entry_rcu(test, &file->triggers, list) { + if (test->cmd_ops->trigger_type == ETT_EVENT_HIST) { + if (hist_trigger_match(data, test, named_data, false)) { + match = true; + break; + } + } + } + + return match; +} + static bool hist_trigger_check_refs(struct event_trigger_data *data, struct trace_event_file *file) { @@ -5072,18 +5360,32 @@ static bool hist_file_check_refs(struct trace_event_file *file) static void hist_unreg_all(struct trace_event_file *file) { struct event_trigger_data *test, *n; + struct hist_trigger_data *hist_data; + struct synth_event *se; + const char *se_name; if (hist_file_check_refs(file)) return; list_for_each_entry_safe(test, n, &file->triggers, list) { if (test->cmd_ops->trigger_type == ETT_EVENT_HIST) { - unregister_field_var_hists(test->private_data); + hist_data = test->private_data; + unregister_field_var_hists(hist_data); list_del_rcu(&test->list); trace_event_trigger_enable_disable(file, 0); + + mutex_lock(&synth_event_mutex); + se_name = trace_event_name(file->event_call); + se = find_synth_event(se_name); + if (se) + se->ref--; + mutex_unlock(&synth_event_mutex); + update_cond_flag(file); if (test->ops->free) test->ops->free(test->ops, test); + if (hist_data->enable_timestamps) + tracing_set_time_stamp_abs(file->tr, false); } } } @@ -5118,19 +5420,33 @@ static int event_hist_trigger_func(struct event_command *cmd_ops, * separate the trigger from the filter (k:v [if filter]) * allowing for whitespace in the trigger */ - trigger = param; - p = strstr(param, " if"); - if (!p) - p = strstr(param, "\tif"); - if (p) { - if (p == trigger) + p = trigger = param; + do { + p = strstr(p, "if"); + if (!p) + break; + if (p == param) return -EINVAL; - param = p + 1; - param = strstrip(param); - *p = '\0'; - trigger = strstrip(trigger); - } else + if (*(p - 1) != ' ' && *(p - 1) != '\t') { + p++; + continue; + } + if (p >= param + strlen(param) - strlen("if") - 1) + return -EINVAL; + if (*(p + strlen("if")) != ' ' && *(p + strlen("if")) != '\t') { + p++; + continue; + } + break; + } while (p); + + if (!p) param = NULL; + else { + *(p - 1) = '\0'; + param = strstrip(p); + trigger = strstrip(trigger); + } attrs = parse_hist_trigger_attrs(trigger); if (IS_ERR(attrs)) @@ -5147,10 +5463,11 @@ static int event_hist_trigger_func(struct event_command *cmd_ops, trigger_ops = cmd_ops->get_trigger_ops(cmd, trigger); - ret = -ENOMEM; trigger_data = kzalloc(sizeof(*trigger_data), GFP_KERNEL); - if (!trigger_data) + if (!trigger_data) { + ret = -ENOMEM; goto out_free; + } trigger_data->count = -1; trigger_data->ops = trigger_ops; @@ -5169,6 +5486,9 @@ static int event_hist_trigger_func(struct event_command *cmd_ops, } if (remove) { + if (!have_hist_trigger_match(trigger_data, file)) + goto out_free; + if (hist_trigger_check_refs(trigger_data, file)) { ret = -EBUSY; goto out_free; @@ -5188,7 +5508,6 @@ static int event_hist_trigger_func(struct event_command *cmd_ops, } ret = cmd_ops->reg(glob, trigger_ops, trigger_data, file); - /* * The above returns on success the # of triggers registered, * but if it didn't register any it returns zero. Consider no @@ -5201,13 +5520,6 @@ static int event_hist_trigger_func(struct event_command *cmd_ops, } else if (ret < 0) goto out_free; - mutex_lock(&synth_event_mutex); - se_name = trace_event_name(file->event_call); - se = find_synth_event(se_name); - if (se) - se->ref++; - mutex_unlock(&synth_event_mutex); - if (get_named_trigger_data(trigger_data)) goto enable; @@ -5226,6 +5538,13 @@ static int event_hist_trigger_func(struct event_command *cmd_ops, if (ret) goto out_unreg; + mutex_lock(&synth_event_mutex); + se_name = trace_event_name(file->event_call); + se = find_synth_event(se_name); + if (se) + se->ref++; + mutex_unlock(&synth_event_mutex); + /* Just return zero, not the number of registered triggers */ ret = 0; out: diff --git a/localversion-rt b/localversion-rt index c3054d08a112..1445cd65885c 100644 --- a/localversion-rt +++ b/localversion-rt @@ -1 +1 @@ --rt2 +-rt3 diff --git a/mm/memcontrol.c b/mm/memcontrol.c index 25e0fd082f13..27549bf47139 100644 --- a/mm/memcontrol.c +++ b/mm/memcontrol.c @@ -1723,7 +1723,6 @@ struct memcg_stock_pcp { #define FLUSHING_CACHED_CHARGE 0 }; static DEFINE_PER_CPU(struct memcg_stock_pcp, memcg_stock); -static DEFINE_LOCAL_IRQ_LOCK(memcg_stock_ll); static DEFINE_MUTEX(percpu_charge_mutex); /** @@ -1746,7 +1745,7 @@ static bool consume_stock(struct mem_cgroup *memcg, unsigned int nr_pages) if (nr_pages > CHARGE_BATCH) return ret; - local_lock_irqsave(memcg_stock_ll, flags); + local_irq_save(flags); stock = this_cpu_ptr(&memcg_stock); if (memcg == stock->cached && stock->nr_pages >= nr_pages) { @@ -1754,7 +1753,7 @@ static bool consume_stock(struct mem_cgroup *memcg, unsigned int nr_pages) ret = true; } - local_unlock_irqrestore(memcg_stock_ll, flags); + local_irq_restore(flags); return ret; } @@ -1785,13 +1784,13 @@ static void drain_local_stock(struct work_struct *dummy) * The only protection from memory hotplug vs. drain_stock races is * that we always operate on local CPU stock here with IRQ disabled */ - local_lock_irqsave(memcg_stock_ll, flags); + local_irq_save(flags); stock = this_cpu_ptr(&memcg_stock); drain_stock(stock); clear_bit(FLUSHING_CACHED_CHARGE, &stock->flags); - local_unlock_irqrestore(memcg_stock_ll, flags); + local_irq_restore(flags); } /* @@ -1803,7 +1802,7 @@ static void refill_stock(struct mem_cgroup *memcg, unsigned int nr_pages) struct memcg_stock_pcp *stock; unsigned long flags; - local_lock_irqsave(memcg_stock_ll, flags); + local_irq_save(flags); stock = this_cpu_ptr(&memcg_stock); if (stock->cached != memcg) { /* reset if necessary */ @@ -1815,7 +1814,7 @@ static void refill_stock(struct mem_cgroup *memcg, unsigned int nr_pages) if (stock->nr_pages > CHARGE_BATCH) drain_stock(stock); - local_unlock_irqrestore(memcg_stock_ll, flags); + local_irq_restore(flags); } /* diff --git a/tools/testing/selftests/ftrace/test.d/functions b/tools/testing/selftests/ftrace/test.d/functions index f2019b37370d..17afa65c0b41 100644 --- a/tools/testing/selftests/ftrace/test.d/functions +++ b/tools/testing/selftests/ftrace/test.d/functions @@ -55,6 +55,13 @@ disable_events() { echo 0 > events/enable } +clear_synthetic_events() { # reset all current synthetic events + grep -v ^# synthetic_events | + while read line; do + echo "!$line" >> synthetic_events + done +} + initialize_ftrace() { # Reset ftrace to initial-state # As the initial state, ftrace will be set to nop tracer, # no events, no triggers, no filters, no function filters, diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc new file mode 100644 index 000000000000..f7691ffcef9c --- /dev/null +++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc @@ -0,0 +1,39 @@ +#!/bin/sh +# description: event trigger - test extended error support + + +do_reset() { + reset_trigger + echo > set_event + clear_trace +} + +fail() { #msg + do_reset + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f synthetic_events ]; then + echo "synthetic event is not supported" + exit_unsupported +fi + +reset_tracer +do_reset + +echo "Test extended error support" +echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="ping"' > events/sched/sched_wakeup/trigger +echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="ping"' >> events/sched/sched_wakeup/trigger &>/dev/null +if ! grep -q "ERROR:" events/sched/sched_wakeup/hist; then + fail "Failed to generate extended error in histogram" +fi + +do_reset + +exit 0 diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-field-variable-support.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-field-variable-support.tc new file mode 100644 index 000000000000..46657334ba9a --- /dev/null +++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-field-variable-support.tc @@ -0,0 +1,54 @@ +#!/bin/sh +# description: event trigger - test field variable support + +do_reset() { + reset_trigger + echo > set_event + clear_trace +} + +fail() { #msg + do_reset + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f synthetic_events ]; then + echo "synthetic event is not supported" + exit_unsupported +fi + +clear_synthetic_events +reset_tracer +do_reset + +echo "Test field variable support" + +echo 'wakeup_latency u64 lat; pid_t pid; int prio; char comm[16]' > synthetic_events +echo 'hist:keys=comm:ts0=$common_timestamp.usecs if comm=="ping"' > events/sched/sched_waking/trigger +echo 'hist:keys=next_comm:wakeup_lat=$common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,sched.sched_waking.prio,next_comm) if next_comm=="ping"' > events/sched/sched_switch/trigger +echo 'hist:keys=pid,prio,comm:vals=lat:sort=pid,prio' > events/synthetic/wakeup_latency/trigger + +ping localhost -c 3 +if ! grep -q "ping" events/synthetic/wakeup_latency/hist; then + fail "Failed to create inter-event histogram" +fi + +if ! grep -q "synthetic_prio=prio" events/sched/sched_waking/hist; then + fail "Failed to create histogram with field variable" +fi + +echo '!hist:keys=next_comm:wakeup_lat=$common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,next_pid,sched.sched_waking.prio,next_comm) if next_comm=="ping"' >> events/sched/sched_switch/trigger + +if grep -q "synthetic_prio=prio" events/sched/sched_waking/hist; then + fail "Failed to remove histogram with field variable" +fi + +do_reset + +exit 0 diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-inter-event-combined-hist.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-inter-event-combined-hist.tc new file mode 100644 index 000000000000..8d00064aa0b6 --- /dev/null +++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-inter-event-combined-hist.tc @@ -0,0 +1,58 @@ +#!/bin/sh +# description: event trigger - test inter-event combined histogram trigger + +do_reset() { + reset_trigger + echo > set_event + clear_trace +} + +fail() { #msg + do_reset + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f synthetic_events ]; then + echo "synthetic event is not supported" + exit_unsupported +fi + +reset_tracer +do_reset +clear_synthetic_events + +echo "Test create synthetic event" + +echo 'waking_latency u64 lat pid_t pid' > synthetic_events +if [ ! -d events/synthetic/waking_latency ]; then + fail "Failed to create waking_latency synthetic event" +fi + +echo "Test combined histogram" + +echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="ping"' > events/sched/sched_waking/trigger +echo 'hist:keys=pid:waking_lat=$common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).waking_latency($waking_lat,pid) if comm=="ping"' > events/sched/sched_wakeup/trigger +echo 'hist:keys=pid,lat:sort=pid,lat' > events/synthetic/waking_latency/trigger + +echo 'wakeup_latency u64 lat pid_t pid' >> synthetic_events +echo 'hist:keys=pid:ts1=$common_timestamp.usecs if comm=="ping"' >> events/sched/sched_wakeup/trigger +echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts1:onmatch(sched.sched_wakeup).wakeup_latency($wakeup_lat,next_pid) if next_comm=="ping"' > events/sched/sched_switch/trigger + +echo 'waking+wakeup_latency u64 lat; pid_t pid' >> synthetic_events +echo 'hist:keys=pid,lat:sort=pid,lat:ww_lat=$waking_lat+$wakeup_lat:onmatch(synthetic.wakeup_latency).waking+wakeup_latency($ww_lat,pid)' >> events/synthetic/wakeup_latency/trigger +echo 'hist:keys=pid,lat:sort=pid,lat' >> events/synthetic/waking+wakeup_latency/trigger + +ping localhost -c 3 +if ! grep -q "pid:" events/synthetic/waking+wakeup_latency/hist; then + fail "Failed to create combined histogram" +fi + +do_reset + +exit 0 diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc new file mode 100644 index 000000000000..ac13051d9cf8 --- /dev/null +++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-action-hist.tc @@ -0,0 +1,50 @@ +#!/bin/sh +# description: event trigger - test inter-event histogram trigger onmatch action + +do_reset() { + reset_trigger + echo > set_event + clear_trace +} + +fail() { #msg + do_reset + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f synthetic_events ]; then + echo "synthetic event is not supported" + exit_unsupported +fi + +clear_synthetic_events +reset_tracer +do_reset + +echo "Test create synthetic event" + +echo 'wakeup_latency u64 lat pid_t pid char comm[16]' > synthetic_events +if [ ! -d events/synthetic/wakeup_latency ]; then + fail "Failed to create wakeup_latency synthetic event" +fi + +echo "Test create histogram for synthetic event" +echo "Test histogram variables,simple expression support and onmatch action" + +echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="ping"' > events/sched/sched_wakeup/trigger +echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts0:onmatch(sched.sched_wakeup).wakeup_latency($wakeup_lat,next_pid,next_comm) if next_comm=="ping"' > events/sched/sched_switch/trigger +echo 'hist:keys=comm,pid,lat:wakeup_lat=lat:sort=lat' > events/synthetic/wakeup_latency/trigger +ping localhost -c 5 +if ! grep -q "ping" events/synthetic/wakeup_latency/hist; then + fail "Failed to create onmatch action inter-event histogram" +fi + +do_reset + +exit 0 diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-onmax-action-hist.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-onmax-action-hist.tc new file mode 100644 index 000000000000..39bf19d5cc2c --- /dev/null +++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmatch-onmax-action-hist.tc @@ -0,0 +1,50 @@ +#!/bin/sh +# description: event trigger - test inter-event histogram trigger onmatch-onmax action + +do_reset() { + reset_trigger + echo > set_event + clear_trace +} + +fail() { #msg + do_reset + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f synthetic_events ]; then + echo "synthetic event is not supported" + exit_unsupported +fi + +clear_synthetic_events +reset_tracer +do_reset + +echo "Test create synthetic event" + +echo 'wakeup_latency u64 lat pid_t pid char comm[16]' > synthetic_events +if [ ! -d events/synthetic/wakeup_latency ]; then + fail "Failed to create wakeup_latency synthetic event" +fi + +echo "Test create histogram for synthetic event" +echo "Test histogram variables,simple expression support and onmatch-onmax action" + +echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="ping"' > events/sched/sched_wakeup/trigger +echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts0:onmatch(sched.sched_wakeup).wakeup_latency($wakeup_lat,next_pid,next_comm):onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) if next_comm=="ping"' >> events/sched/sched_switch/trigger +echo 'hist:keys=comm,pid,lat:wakeup_lat=lat:sort=lat' > events/synthetic/wakeup_latency/trigger +ping localhost -c 5 +if [ ! grep -q "ping" events/synthetic/wakeup_latency/hist -o ! grep -q "max:" events/sched/sched_switch/hist]; then + fail "Failed to create onmatch-onmax action inter-event histogram" +fi + +do_reset + +exit 0 diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmax-action-hist.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmax-action-hist.tc new file mode 100644 index 000000000000..65f55a53126e --- /dev/null +++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-onmax-action-hist.tc @@ -0,0 +1,48 @@ +#!/bin/sh +# description: event trigger - test inter-event histogram trigger onmax action + +do_reset() { + reset_trigger + echo > set_event + clear_trace +} + +fail() { #msg + do_reset + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f synthetic_events ]; then + echo "synthetic event is not supported" + exit_unsupported +fi + +clear_synthetic_events +reset_tracer +do_reset + +echo "Test create synthetic event" + +echo 'wakeup_latency u64 lat pid_t pid char comm[16]' > synthetic_events +if [ ! -d events/synthetic/wakeup_latency ]; then + fail "Failed to create wakeup_latency synthetic event" +fi + +echo "Test onmax action" + +echo 'hist:keys=pid:ts0=$common_timestamp.usecs if comm=="ping"' >> events/sched/sched_waking/trigger +echo 'hist:keys=next_pid:wakeup_lat=$common_timestamp.usecs-$ts0:onmax($wakeup_lat).save(next_comm,prev_pid,prev_prio,prev_comm) if next_comm=="ping"' >> events/sched/sched_switch/trigger +ping localhost -c 3 +if ! grep -q "max:" events/sched/sched_switch/hist; then + fail "Failed to create onmax action inter-event histogram" +fi + +do_reset + +exit 0 diff --git a/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-createremove.tc b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-createremove.tc new file mode 100644 index 000000000000..cef11377dcbd --- /dev/null +++ b/tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-synthetic-event-createremove.tc @@ -0,0 +1,54 @@ +#!/bin/sh +# description: event trigger - test synthetic event create remove +do_reset() { + reset_trigger + echo > set_event + clear_trace +} + +fail() { #msg + do_reset + echo $1 + exit_fail +} + +if [ ! -f set_event ]; then + echo "event tracing is not supported" + exit_unsupported +fi + +if [ ! -f synthetic_events ]; then + echo "synthetic event is not supported" + exit_unsupported +fi + +clear_synthetic_events +reset_tracer +do_reset + +echo "Test create synthetic event" + +echo 'wakeup_latency u64 lat pid_t pid char comm[16]' > synthetic_events +if [ ! -d events/synthetic/wakeup_latency ]; then + fail "Failed to create wakeup_latency synthetic event" +fi + +reset_trigger + +echo "Test create synthetic event with an error" +echo 'wakeup_latency u64 lat pid_t pid char' > synthetic_events > /dev/null +if [ -d events/synthetic/wakeup_latency ]; then + fail "Created wakeup_latency synthetic event with an invalid format" +fi + +reset_trigger + +echo "Test remove synthetic event" +echo '!wakeup_latency u64 lat pid_t pid char comm[16]' > synthetic_events +if [ -d events/synthetic/wakeup_latency ]; then + fail "Failed to delete wakeup_latency synthetic event" +fi + +do_reset + +exit 0