Lines Matching +full:field +full:- +full:active +full:- +full:even
33 numeric fields - on an event hit, the value(s) will be added to a
34 sum kept for that field. The special string 'hitcount' can be used
35 in place of an explicit value field - this is simply a count of
38 Keys can be any field, or the special string 'stacktrace', which
45 useful for providing more fine-grained summaries of event data.
47 specified by the 'sort' keyword. If more than one field is
69 numeric fields are displayed as base-10 integers. This can be
70 modified by appending any of the following modifiers to the field
76 .sym-offset display an address as a symbol and offset
83 Note that in general the semantics of a given field aren't
87 - only the 'hex' modifier can be used for values (because values
90 - the 'execname' modifier can only be used on a 'common_pid'. The
96 pid-specific comm fields in the event itself.
115 are in terms of hashtable entries - if a run uses more entries than
118 128 and 131072 (any non- power-of-2 number specified will be rounded
121 The 'sort' parameter can be used to specify a value field to sort
132 trigger and leave its current paused/active state.
139 - enable_hist/disable_hist
142 event conditionally start and stop another event's already-attached
180 ------------------------
185 field definition or format file. They are however available for any
186 event, and can be used anywhere an actual event field could be.
198 --------------------------
206 ---------------------------
216 field:unsigned short common_type; offset:0; size:2; signed:0;
217 field:unsigned char common_flags; offset:2; size:1; signed:0;
218 field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
219 field:int common_pid; offset:4; size:4; signed:1;
221 field:unsigned long call_site; offset:8; size:8; signed:0;
222 field:const void * ptr; offset:16; size:8; signed:0;
223 field:size_t bytes_req; offset:24; size:8; signed:0;
224 field:size_t bytes_alloc; offset:32; size:8; signed:0;
225 field:gfp_t gfp_flags; offset:40; size:4; signed:0;
235 call_site field of the kmalloc event as the key for the table, which
247 # trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
287 hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
290 totals for the run. The 'Hits' field shows the total number of
291 times the event trigger was hit, the 'Entries' field shows the total
292 number of used entries in the hash table, and the 'Dropped' field
298 Notice in the above output that there's an extra field, 'hitcount',
305 absence of a user-specified sort parameter, is used as the default
306 sort field.
310 particular field summed and are mainly interested in hit
314 command history and re-execute it with a '!' prepended::
321 are displayed in hex. To have a numeric field displayed as a hex
322 value, simply append '.hex' to the field name in the trigger::
328 # trigger info: hist:keys=call_site.hex:vals=bytes_req:sort=hitcount:size=2048 [active]
362 Even that's only marginally more useful - while hex values do look
366 simply append '.sym' or '.sym-offset' to the field name in the
373 # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=hitcount:size=2048 [active]
423 …# trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=bytes_req.descending:size=2048 [active]
458 name, just use 'sym-offset' instead::
460 # echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \
464 …# trigger info: hist:keys=call_site.sym-offset:vals=bytes_req:sort=bytes_req.descending:size=2048 …
503 …: hist:keys=call_site.sym:vals=bytes_req,bytes_alloc:sort=bytes_alloc.descending:size=2048 [active]
554 …# trigger info: hist:keys=stacktrace:vals=bytes_req,bytes_alloc:sort=bytes_alloc:size=2048 [active]
649 keeps a per-process sum of total bytes read::
655 … # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active]
657 { common_pid: gnome-terminal [ 3196] } hitcount: 280 count: 1093512
661 { common_pid: dbus-daemon-lau [ 8703] } hitcount: 49 count: 47739
664 { common_pid: dbus-daemon [ 772] } hitcount: 10 count: 12396
666 { common_pid: nm-dhcp-client. [ 8701] } hitcount: 6 count: 7424
674 { common_pid: upstart-dbus-br [ 2740] } hitcount: 21 count: 21
675 { common_pid: nm-dispatcher.a [ 8696] } hitcount: 1 count: 16
676 { common_pid: indicator-datet [ 2904] } hitcount: 1 count: 16
678 { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8
696 # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active]
741 system call id and pid - the end result is essentially a table
742 that keeps a per-pid sum of system call hits. The results are
750 … hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active]
752 …{ id: sys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: …
754 …{ id: sys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: …
756 …{ id: sys_read [ 0], common_pid: deja-dup-monito [ 3543] } hitcount: …
758 …{ id: sys_read [ 0], common_pid: evolution-calen [ 3048] } hitcount: …
760 …{ id: sys_read [ 0], common_pid: nm-applet [ 3022] } hitcount: …
767 …{ id: sys_ioctl [ 16], common_pid: gnome-terminal [ 3199] } hitcount: …
773 …{ id: sys_waitid [247], common_pid: upstart-dbus-br [ 2690] } hitcount: …
774 …{ id: sys_waitid [247], common_pid: upstart-dbus-br [ 2688] } hitcount: …
782 …{ id: sys_eventfd2 [290], common_pid: ibus-ui-gtk3 [ 2760] } hitcount: …
800 …d.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 if id == 16 [active]
803 …{ id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: …
817 …{ id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: …
843 …: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:size=2048 [active]
853 { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2
883 key is treated as a single entity for hashing purposes, the sub-keys
886 The next example uses a string field as the hash key and
896 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active]
899 { child_comm: ibus-daemon } hitcount: 1
905 { child_comm: evolution-alarm } hitcount: 2
910 { child_comm: evolution-sourc } hitcount: 4
913 { child_comm: nm-dispatcher.a } hitcount: 8
915 { child_comm: dbus-daemon } hitcount: 8
916 { child_comm: glib-pacrunner } hitcount: 10
938 { child_comm: ibus-daemon } hitcount: 1
940 { child_comm: evolution-alarm } hitcount: 2
945 { child_comm: evolution-sourc } hitcount: 4
951 { child_comm: dbus-daemon } hitcount: 20
952 { child_comm: nm-dispatcher.a } hitcount: 20
954 { child_comm: glib-pacrunner } hitcount: 59
962 :cont instead. Notice that the trigger info displays as [active]
969 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active]
975 { child_comm: ibus-daemon } hitcount: 1
977 { child_comm: evolution-alarm } hitcount: 2
981 { child_comm: evolution-sourc } hitcount: 4
988 { child_comm: dbus-daemon } hitcount: 22
989 { child_comm: nm-dispatcher.a } hitcount: 22
991 { child_comm: glib-pacrunner } hitcount: 59
1007 Of course, doing this manually can be difficult and error-prone, but
1013 netif_receive_skb event when downloading a decent-sized file using
1041 Whenever a process exits and the comm field of the disable_hist
1050 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1180 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1190 # entries-in-buffer/entries-written: 183/1426 #P:4
1192 # _-----=> irqs-off
1193 # / _----=> need-resched
1194 # | / _---=> hardirq/softirq
1195 # || / _--=> preempt-depth
1197 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
1199 … wget-15108 [000] ..s1 31769.606929: netif_receive_skb: dev=lo skbaddr=ffff88009c353100 len=60
1200 … wget-15108 [000] ..s1 31769.606999: netif_receive_skb: dev=lo skbaddr=ffff88009c353200 len=60
1201 … dnsmasq-1382 [000] ..s1 31769.677652: netif_receive_skb: dev=lo skbaddr=ffff88009c352b00 len=130
1202 … dnsmasq-1382 [000] ..s1 31769.685917: netif_receive_skb: dev=lo skbaddr=ffff88009c352200 len=138
1204 …irq/29-iwlwifi-559 [002] ..s. 31772.031529: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433d0…
1205 …irq/29-iwlwifi-559 [002] ..s. 31772.031572: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d43220…
1206 …irq/29-iwlwifi-559 [002] ..s. 31772.032196: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d43310…
1207 …irq/29-iwlwifi-559 [002] ..s. 31772.032761: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d43300…
1208 …irq/29-iwlwifi-559 [002] ..s. 31772.033220: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432e0…
1244 … # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active]
1271 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1308 …rigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [active]
1320 …rigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [active]
1344 …# trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active]
1358 field in the shared 'foo' histogram data::
1373 … # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1425 … # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1477 any two events even if they don't share any 'compatible' fields
1494 # trigger info: hist:name=bar:keys=stacktrace:vals=hitcount:sort=hitcount:size=2048 [active]
1601 2.2 Inter-event hist triggers
1602 -----------------------------
1604 Inter-event hist triggers are hist triggers that combine values from
1606 from an inter-event histogram can in turn become the source for
1610 The most important example of an inter-event quantity that can be used
1613 inter-event quantity, note that because the support is completely
1614 general across the trace event subsystem, any event field can be used
1615 in an inter-event quantity.
1629 The inter-event hist trigger extension allows fields from multiple
1630 events to be referenced and combined into a multi-event histogram
1634 - In order to compute an inter-event quantity, a value from one
1638 - The computation of inter-event quantities and their combination
1640 expressions to variables (+ and -).
1642 - A histogram consisting of inter-event quantities isn't logically a
1648 These synthetic events are full-fledged events just like any other
1652 - A set of 'actions' can be associated with histogram entries -
1657 - Trace events don't have a 'timestamp' associated with them, but
1660 a synthetic field named 'common_timestamp' which can be used in
1661 histograms as if it were any other event field; it isn't an actual
1662 field in the trace format but rather is a synthesized value that
1663 nonetheless can be used as if it were an actual field. By default
1665 common_timestamp field changes the units to microseconds.
1667 A note on inter-event timestamps: If common_timestamp is used in a
1674 pseudo-file.
1679 -------------------------
1683 event that has a matching key - if a variable is saved for a histogram
1690 'read-once' - once it's used by an expression in a subsequent event,
1698 to any event field.
1723 associated event field will be saved in a variable but won't be summed
1754 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp-$ts0 ...' >> event2/trigger
1766 ----------------------
1768 Synthetic events are user-defined events generated from hist trigger
1776 variables and their types, which can be any valid field type,
1781 If field_name contains [n], the field is considered to be a static array.
1783 If field_names contains[] (no subscript), the field is considered to
1787 A string field can be specified using either the static notation:
1820 instantiated in the event subsystem - for this to happen, a 'hist
1841 -------------------------------------------
1862 trigger will fail with -EINVAL;
1876 - onmatch(matching.event) - invoke action on any addition or update
1877 - onmax(var) - invoke action if var exceeds current max
1878 - onchange(var) - invoke action if var changes
1882 - trace(<synthetic_event_name>,param list) - generate synthetic event
1883 - save(field,...) - save current event fields
1884 - snapshot() - snapshot the trace buffer
1886 The following commonly-used handler.action pairs are available:
1888 - onmatch(matching.event).trace(<synthetic_event_name>,param list)
1905 were a function call, with the event field values passed in as
1914 fields specified in the param list may be either fully-qualified
1916 must be unique between the two events. A field name used as a
1919 fully-qualified name is of the form 'system.event_name.$var_name'
1920 or 'system.event_name.field'.
1991 the latency and use that along with another variable and an event field
1994 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\
2011 - onmax(var).save(field,.. .)
2013 The 'onmax(var).save(field,...)' hist trigger action is invoked
2038 wakeup_lat=common_timestamp.usecs-$ts0:\
2049 common_timestamp-ts0: 0
2055 common_timestamp-ts0: 0
2064 - onmax(var).snapshot()
2080 to locate the corresponding bucket in the histogram for even more
2099 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \
2149 …<...>-2103 [005] d..3 309.873125: sched_switch: prev_comm=cyclictest prev_pid=2103 prev_prio=19…
2150 …<idle>-0 [005] d.h3 309.873611: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005
2151 …<idle>-0 [005] dNh4 309.873613: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005
2152 …<idle>-0 [005] d..3 309.873616: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 p…
2153 …<...>-2102 [005] d..3 309.873625: sched_switch: prev_comm=cyclictest prev_pid=2102 prev_prio=19…
2154 …<idle>-0 [005] d.h3 309.874624: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005
2155 …<idle>-0 [005] dNh4 309.874626: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005
2156 …<idle>-0 [005] dNh3 309.874628: sched_waking: comm=cyclictest pid=2103 prio=19 target_cpu=005
2157 …<idle>-0 [005] dNh4 309.874630: sched_wakeup: comm=cyclictest pid=2103 prio=19 target_cpu=005
2158 …<idle>-0 [005] d..3 309.874633: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 p…
2159 …<idle>-0 [004] d.h3 309.874757: sched_waking: comm=gnome-terminal- pid=1699 prio=120 target_…
2160 …<idle>-0 [004] dNh4 309.874762: sched_wakeup: comm=gnome-terminal- pid=1699 prio=120 target_…
2161 …<idle>-0 [004] d..3 309.874766: sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 p…
2162 …gnome-terminal--1699 [004] d.h2 309.874941: sched_stat_runtime: comm=gnome-terminal- pid=1699 r…
2163 … <idle>-0 [003] d.s4 309.874956: sched_waking: comm=rcu_sched pid=9 prio=120 target_cpu=007
2164 <idle>-0 [003] d.s5 309.874960: sched_wake_idle_without_ipi: cpu=7
2165 … <idle>-0 [003] d.s5 309.874961: sched_wakeup: comm=rcu_sched pid=9 prio=120 target_cpu=007
2166 …<idle>-0 [007] d..3 309.874963: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
2167 …rcu_sched-9 [007] d..3 309.874973: sched_stat_runtime: comm=rcu_sched pid=9 runtime=13646 [n…
2168 …rcu_sched-9 [007] d..3 309.874978: sched_switch: prev_comm=rcu_sched prev_pid=9 prev_prio=12…
2169 …<...>-2102 [005] d..4 309.874994: sched_migrate_task: comm=cyclictest pid=2103 prio=19 orig_cpu…
2170 <...>-2102 [005] d..4 309.875185: sched_wake_idle_without_ipi: cpu=1
2171 …<idle>-0 [001] d..3 309.875200: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 p…
2173 - onchange(var).save(field,.. .)
2175 The 'onchange(var).save(field,...)' hist trigger action is invoked
2186 - onchange(var).snapshot()
2202 histogram for even more detail.
2206 cwnd field is checked against the current value stored in the
2263 …gnome-shell-1261 [006] dN.3 49.823113: sched_stat_runtime: comm=gnome-shell pid=1261 runtime=4…
2264 …kworker/u16:4-773 [003] d..3 49.823114: sched_switch: prev_comm=kworker/u16:4 prev_pid=773 pr…
2265 …gnome-shell-1261 [006] d..3 49.823114: sched_switch: prev_comm=gnome-shell prev_pid=1261 prev_…
2266 …kworker/3:2-135 [003] d..3 49.823118: sched_stat_runtime: comm=kworker/3:2 pid=135 runtime=53…
2267 …kworker/6:2-387 [006] d..3 49.823120: sched_stat_runtime: comm=kworker/6:2 pid=387 runtime=95…
2268 …kworker/6:2-387 [006] d..3 49.823122: sched_switch: prev_comm=kworker/6:2 prev_pid=387 prev_p…
2269 …kworker/3:2-135 [003] d..3 49.823123: sched_switch: prev_comm=kworker/3:2 prev_pid=135 prev_p…
2270 …<idle>-0 [004] ..s7 49.823798: tcp_probe: src=10.0.0.10:54326 dest=23.215.104.193:80 mark=0…
2273 --------------------------------
2302 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) i…
2314 # ./cyclictest -p80 -d0 -i250 -n -a -t --tracemark -b 1000
2316 -p80 : run threads at priority 80
2317 -d0 : have all threads run at the same interval
2318 -i250 : start the interval at 250 microseconds (all threads will do this)
2319 -n : sleep with nanosleep
2320 -a : affine all threads to a separate CPU
2321 -t : one thread per available CPU
2322 --tracemark : enable trace mark writing
2323 -b 1000 : stop if any latency is greater than 1000 microseconds
2325 Note, the -b 1000 is used just to make --tracemark available.
2332 # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
2626 But this could easily be done in userspace. To make this even more
2633 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($…
2645 # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]