Lines Matching +full:field +full:- +full:even +full:- +full:active
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 'common_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 .graph display a bar-graph of a value
87 Note that in general the semantics of a given field aren't
91 - only the 'hex' modifier can be used for values (because values
94 - the 'execname' modifier can only be used on a 'common_pid'. The
100 pid-specific comm fields in the event itself.
119 are in terms of hashtable entries - if a run uses more entries than
122 128 and 131072 (any non- power-of-2 number specified will be rounded
125 The 'sort' parameter can be used to specify a value field to sort
136 trigger and leave its current paused/active state.
145 value field which is not a 'raw hitcount'. For example,
149 - enable_hist/disable_hist
152 event conditionally start and stop another event's already-attached
190 ------------------------
195 field definition or format file. They are however available for any
196 event, and can be used anywhere an actual event field could be.
208 --------------------------
216 ---------------------------
226 field:unsigned short common_type; offset:0; size:2; signed:0;
227 field:unsigned char common_flags; offset:2; size:1; signed:0;
228 field:unsigned char common_preempt_count; offset:3; size:1; signed:0;
229 field:int common_pid; offset:4; size:4; signed:1;
231 field:unsigned long call_site; offset:8; size:8; signed:0;
232 field:const void * ptr; offset:16; size:8; signed:0;
233 field:size_t bytes_req; offset:24; size:8; signed:0;
234 field:size_t bytes_alloc; offset:32; size:8; signed:0;
235 field:gfp_t gfp_flags; offset:40; size:4; signed:0;
245 call_site field of the kmalloc event as the key for the table, which
257 # trigger info: hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
297 hist:keys=call_site:vals=bytes_req:sort=hitcount:size=2048 [active]
300 totals for the run. The 'Hits' field shows the total number of
301 times the event trigger was hit, the 'Entries' field shows the total
302 number of used entries in the hash table, and the 'Dropped' field
308 Notice in the above output that there's an extra field, 'hitcount',
315 absence of a user-specified sort parameter, is used as the default
316 sort field.
320 particular field summed and are mainly interested in hit
324 command history and re-execute it with a '!' prepended::
331 are displayed in hex. To have a numeric field displayed as a hex
332 value, simply append '.hex' to the field name in the trigger::
338 # trigger info: hist:keys=call_site.hex:vals=bytes_req:sort=hitcount:size=2048 [active]
372 Even that's only marginally more useful - while hex values do look
376 simply append '.sym' or '.sym-offset' to the field name in the
383 # trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=hitcount:size=2048 [active]
433 …# trigger info: hist:keys=call_site.sym:vals=bytes_req:sort=bytes_req.descending:size=2048 [active]
468 name, just use 'sym-offset' instead::
470 # echo 'hist:key=call_site.sym-offset:val=bytes_req:sort=bytes_req.descending' > \
474 …# trigger info: hist:keys=call_site.sym-offset:vals=bytes_req:sort=bytes_req.descending:size=2048 …
513 …: hist:keys=call_site.sym:vals=bytes_req,bytes_alloc:sort=bytes_alloc.descending:size=2048 [active]
564 …er info: hist:keys=common_stacktrace:vals=bytes_req,bytes_alloc:sort=bytes_alloc:size=2048 [active]
659 keeps a per-process sum of total bytes read::
665 … # trigger info: hist:keys=common_pid.execname:vals=count:sort=count.descending:size=2048 [active]
667 { common_pid: gnome-terminal [ 3196] } hitcount: 280 count: 1093512
671 { common_pid: dbus-daemon-lau [ 8703] } hitcount: 49 count: 47739
674 { common_pid: dbus-daemon [ 772] } hitcount: 10 count: 12396
676 { common_pid: nm-dhcp-client. [ 8701] } hitcount: 6 count: 7424
684 { common_pid: upstart-dbus-br [ 2740] } hitcount: 21 count: 21
685 { common_pid: nm-dispatcher.a [ 8696] } hitcount: 1 count: 16
686 { common_pid: indicator-datet [ 2904] } hitcount: 1 count: 16
688 { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8
706 # trigger info: hist:keys=id.syscall:vals=hitcount:sort=hitcount:size=2048 [active]
751 system call id and pid - the end result is essentially a table
752 that keeps a per-pid sum of system call hits. The results are
760 … hist:keys=id.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 [active]
762 …{ id: sys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: …
764 …{ id: sys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: …
766 …{ id: sys_read [ 0], common_pid: deja-dup-monito [ 3543] } hitcount: …
768 …{ id: sys_read [ 0], common_pid: evolution-calen [ 3048] } hitcount: …
770 …{ id: sys_read [ 0], common_pid: nm-applet [ 3022] } hitcount: …
777 …{ id: sys_ioctl [ 16], common_pid: gnome-terminal [ 3199] } hitcount: …
783 …{ id: sys_waitid [247], common_pid: upstart-dbus-br [ 2690] } hitcount: …
784 …{ id: sys_waitid [247], common_pid: upstart-dbus-br [ 2688] } hitcount: …
792 …{ id: sys_eventfd2 [290], common_pid: ibus-ui-gtk3 [ 2760] } hitcount: …
810 …d.syscall,common_pid.execname:vals=hitcount:sort=id.syscall,hitcount:size=2048 if id == 16 [active]
813 …{ id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: …
827 …{ id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: …
853 …: hist:keys=common_pid.execname,size:vals=hitcount:sort=common_pid.execname,size:size=2048 [active]
863 { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2
893 key is treated as a single entity for hashing purposes, the sub-keys
896 The next example uses a string field as the hash key and
906 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active]
909 { child_comm: ibus-daemon } hitcount: 1
915 { child_comm: evolution-alarm } hitcount: 2
920 { child_comm: evolution-sourc } hitcount: 4
923 { child_comm: nm-dispatcher.a } hitcount: 8
925 { child_comm: dbus-daemon } hitcount: 8
926 { child_comm: glib-pacrunner } hitcount: 10
948 { child_comm: ibus-daemon } hitcount: 1
950 { child_comm: evolution-alarm } hitcount: 2
955 { child_comm: evolution-sourc } hitcount: 4
961 { child_comm: dbus-daemon } hitcount: 20
962 { child_comm: nm-dispatcher.a } hitcount: 20
964 { child_comm: glib-pacrunner } hitcount: 59
972 :cont instead. Notice that the trigger info displays as [active]
979 # trigger info: hist:keys=child_comm:vals=hitcount:sort=hitcount:size=256 [active]
985 { child_comm: ibus-daemon } hitcount: 1
987 { child_comm: evolution-alarm } hitcount: 2
991 { child_comm: evolution-sourc } hitcount: 4
998 { child_comm: dbus-daemon } hitcount: 22
999 { child_comm: nm-dispatcher.a } hitcount: 22
1001 { child_comm: glib-pacrunner } hitcount: 59
1017 Of course, doing this manually can be difficult and error-prone, but
1023 netif_receive_skb event when downloading a decent-sized file using
1051 Whenever a process exits and the comm field of the disable_hist
1060 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1190 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1200 # entries-in-buffer/entries-written: 183/1426 #P:4
1202 # _-----=> irqs-off
1203 # / _----=> need-resched
1204 # | / _---=> hardirq/softirq
1205 # || / _--=> preempt-depth
1207 # TASK-PID CPU# |||| TIMESTAMP FUNCTION
1209 … wget-15108 [000] ..s1 31769.606929: netif_receive_skb: dev=lo skbaddr=ffff88009c353100 len=60
1210 … wget-15108 [000] ..s1 31769.606999: netif_receive_skb: dev=lo skbaddr=ffff88009c353200 len=60
1211 … dnsmasq-1382 [000] ..s1 31769.677652: netif_receive_skb: dev=lo skbaddr=ffff88009c352b00 len=130
1212 … dnsmasq-1382 [000] ..s1 31769.685917: netif_receive_skb: dev=lo skbaddr=ffff88009c352200 len=138
1214 …irq/29-iwlwifi-559 [002] ..s. 31772.031529: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d433d0…
1215 …irq/29-iwlwifi-559 [002] ..s. 31772.031572: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d43220…
1216 …irq/29-iwlwifi-559 [002] ..s. 31772.032196: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d43310…
1217 …irq/29-iwlwifi-559 [002] ..s. 31772.032761: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d43300…
1218 …irq/29-iwlwifi-559 [002] ..s. 31772.033220: netif_receive_skb: dev=wlan0 skbaddr=ffff88009d432e0…
1254 … # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active]
1281 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1318 …rigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [active]
1330 …rigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [active]
1354 …# trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active]
1368 field in the shared 'foo' histogram data::
1383 … # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1435 … # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
1487 any two events even if they don't share any 'compatible' fields
1504 …# trigger info: hist:name=bar:keys=common_stacktrace:vals=hitcount:sort=hitcount:size=2048 [active]
1611 2.2 Inter-event hist triggers
1612 -----------------------------
1614 Inter-event hist triggers are hist triggers that combine values from
1616 from an inter-event histogram can in turn become the source for
1620 The most important example of an inter-event quantity that can be used
1623 inter-event quantity, note that because the support is completely
1624 general across the trace event subsystem, any event field can be used
1625 in an inter-event quantity.
1639 The inter-event hist trigger extension allows fields from multiple
1640 events to be referenced and combined into a multi-event histogram
1644 - In order to compute an inter-event quantity, a value from one
1648 - The computation of inter-event quantities and their combination
1650 expressions to variables (+ and -).
1652 - A histogram consisting of inter-event quantities isn't logically a
1658 These synthetic events are full-fledged events just like any other
1662 - A set of 'actions' can be associated with histogram entries -
1667 - Trace events don't have a 'timestamp' associated with them, but
1670 a synthetic field named 'common_timestamp' which can be used in
1671 histograms as if it were any other event field; it isn't an actual
1672 field in the trace format but rather is a synthesized value that
1673 nonetheless can be used as if it were an actual field. By default
1675 common_timestamp field changes the units to microseconds.
1677 A note on inter-event timestamps: If common_timestamp is used in a
1684 pseudo-file.
1689 -------------------------
1693 event that has a matching key - if a variable is saved for a histogram
1700 'read-once' - once it's used by an expression in a subsequent event,
1708 to any event field.
1733 associated event field will be saved in a variable but won't be summed
1764 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp-$ts0 ...' >> event2/trigger
1776 division operators (+-\*/).
1779 divisor is not a constant), the result will be -1.
1790 Variables can even hold stacktraces, which are useful with synthetic events.
1793 ----------------------
1795 Synthetic events are user-defined events generated from hist trigger
1803 variables and their types, which can be any valid field type,
1808 If field_name contains [n], the field is considered to be a static array.
1810 If field_names contains[] (no subscript), the field is considered to
1814 A string field can be specified using either the static notation:
1847 instantiated in the event subsystem - for this to happen, a 'hist
1873 # trigger info: hist:keys=pid,prio,lat.log2:vals=hitcount:sort=lat.log2:size=2048 [active]
1921 …rigger info: hist:keys=pid,prio,lat.buckets=10:vals=hitcount:sort=lat.buckets=10:size=2048 [active]
1924 { pid: 2067, prio: 9, lat: ~ 0-9 } hitcount: 220
1925 { pid: 2068, prio: 9, lat: ~ 0-9 } hitcount: 157
1926 { pid: 2070, prio: 9, lat: ~ 0-9 } hitcount: 100
1927 { pid: 2067, prio: 120, lat: ~ 0-9 } hitcount: 6
1928 { pid: 2065, prio: 120, lat: ~ 0-9 } hitcount: 2
1929 { pid: 2066, prio: 120, lat: ~ 0-9 } hitcount: 2
1930 { pid: 2069, prio: 9, lat: ~ 0-9 } hitcount: 122
1931 { pid: 2069, prio: 120, lat: ~ 0-9 } hitcount: 8
1932 { pid: 2070, prio: 120, lat: ~ 0-9 } hitcount: 1
1933 { pid: 2068, prio: 120, lat: ~ 0-9 } hitcount: 7
1934 { pid: 2066, prio: 9, lat: ~ 0-9 } hitcount: 365
1935 { pid: 2064, prio: 120, lat: ~ 0-9 } hitcount: 35
1936 { pid: 2065, prio: 9, lat: ~ 0-9 } hitcount: 998
1937 { pid: 2071, prio: 9, lat: ~ 0-9 } hitcount: 85
1938 { pid: 2065, prio: 9, lat: ~ 10-19 } hitcount: 2
1939 { pid: 2064, prio: 120, lat: ~ 10-19 } hitcount: 2
1946 To save stacktraces, create a synthetic event with a field of type "unsigned long[]"
1947 or even just "long[]". For example, to see how long a task is blocked in an
1953 …# echo 'hist:keys=prev_pid:delta=common_timestamp.usecs-$ts,s=$st:onmax($delta).trace(block_lat,pr…
1959 # entries-in-buffer/entries-written: 2/2 #P:8
1961 # _-----=> irqs-off/BH-disabled
1962 # / _----=> need-resched
1963 # | / _---=> hardirq/softirq
1964 # || / _--=> preempt-depth
1965 # ||| / _-=> migrate-disable
1967 # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
1969 <idle>-0 [005] d..4. 521.164922: block_lat: pid=0 delta=8322 stack=STACK:
1981 <...>-2 [004] d..4. 525.184257: block_lat: pid=2 delta=76 stack=STACK:
1993 A synthetic event that has a stacktrace field may use it as a key in
2001 …ist:keys=delta.buckets=100,stack.stacktrace:vals=hitcount:sort=delta.buckets=100:size=2048 [active]
2003 { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
2015 { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
2031 { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
2047 { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
2062 { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
2075 { delta: ~ 100-199, stack.stacktrace __schedule+0xa19/0x1520
2098 -------------------------------------------
2119 trigger will fail with -EINVAL;
2133 - onmatch(matching.event) - invoke action on any addition or update
2134 - onmax(var) - invoke action if var exceeds current max
2135 - onchange(var) - invoke action if var changes
2139 - trace(<synthetic_event_name>,param list) - generate synthetic event
2140 - save(field,...) - save current event fields
2141 - snapshot() - snapshot the trace buffer
2143 The following commonly-used handler.action pairs are available:
2145 - onmatch(matching.event).trace(<synthetic_event_name>,param list)
2162 were a function call, with the event field values passed in as
2171 fields specified in the param list may be either fully-qualified
2173 must be unique between the two events. A field name used as a
2176 fully-qualified name is of the form 'system.event_name.$var_name'
2177 or 'system.event_name.field'.
2248 the latency and use that along with another variable and an event field
2251 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\
2268 - onmax(var).save(field,.. .)
2270 The 'onmax(var).save(field,...)' hist trigger action is invoked
2295 wakeup_lat=common_timestamp.usecs-$ts0:\
2306 common_timestamp-ts0: 0
2312 common_timestamp-ts0: 0
2321 - onmax(var).snapshot()
2337 to locate the corresponding bucket in the histogram for even more
2356 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \
2406 …<...>-2103 [005] d..3 309.873125: sched_switch: prev_comm=cyclictest prev_pid=2103 prev_prio=19…
2407 …<idle>-0 [005] d.h3 309.873611: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005
2408 …<idle>-0 [005] dNh4 309.873613: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005
2409 …<idle>-0 [005] d..3 309.873616: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 p…
2410 …<...>-2102 [005] d..3 309.873625: sched_switch: prev_comm=cyclictest prev_pid=2102 prev_prio=19…
2411 …<idle>-0 [005] d.h3 309.874624: sched_waking: comm=cyclictest pid=2102 prio=19 target_cpu=005
2412 …<idle>-0 [005] dNh4 309.874626: sched_wakeup: comm=cyclictest pid=2102 prio=19 target_cpu=005
2413 …<idle>-0 [005] dNh3 309.874628: sched_waking: comm=cyclictest pid=2103 prio=19 target_cpu=005
2414 …<idle>-0 [005] dNh4 309.874630: sched_wakeup: comm=cyclictest pid=2103 prio=19 target_cpu=005
2415 …<idle>-0 [005] d..3 309.874633: sched_switch: prev_comm=swapper/5 prev_pid=0 prev_prio=120 p…
2416 …<idle>-0 [004] d.h3 309.874757: sched_waking: comm=gnome-terminal- pid=1699 prio=120 target_…
2417 …<idle>-0 [004] dNh4 309.874762: sched_wakeup: comm=gnome-terminal- pid=1699 prio=120 target_…
2418 …<idle>-0 [004] d..3 309.874766: sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 p…
2419 …gnome-terminal--1699 [004] d.h2 309.874941: sched_stat_runtime: comm=gnome-terminal- pid=1699 r…
2420 … <idle>-0 [003] d.s4 309.874956: sched_waking: comm=rcu_sched pid=9 prio=120 target_cpu=007
2421 <idle>-0 [003] d.s5 309.874960: sched_wake_idle_without_ipi: cpu=7
2422 … <idle>-0 [003] d.s5 309.874961: sched_wakeup: comm=rcu_sched pid=9 prio=120 target_cpu=007
2423 …<idle>-0 [007] d..3 309.874963: sched_switch: prev_comm=swapper/7 prev_pid=0 prev_prio=120 p…
2424 …rcu_sched-9 [007] d..3 309.874973: sched_stat_runtime: comm=rcu_sched pid=9 runtime=13646 [n…
2425 …rcu_sched-9 [007] d..3 309.874978: sched_switch: prev_comm=rcu_sched prev_pid=9 prev_prio=12…
2426 …<...>-2102 [005] d..4 309.874994: sched_migrate_task: comm=cyclictest pid=2103 prio=19 orig_cpu…
2427 <...>-2102 [005] d..4 309.875185: sched_wake_idle_without_ipi: cpu=1
2428 …<idle>-0 [001] d..3 309.875200: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 p…
2430 - onchange(var).save(field,.. .)
2432 The 'onchange(var).save(field,...)' hist trigger action is invoked
2443 - onchange(var).snapshot()
2459 histogram for even more detail.
2463 cwnd field is checked against the current value stored in the
2520 …gnome-shell-1261 [006] dN.3 49.823113: sched_stat_runtime: comm=gnome-shell pid=1261 runtime=4…
2521 …kworker/u16:4-773 [003] d..3 49.823114: sched_switch: prev_comm=kworker/u16:4 prev_pid=773 pr…
2522 …gnome-shell-1261 [006] d..3 49.823114: sched_switch: prev_comm=gnome-shell prev_pid=1261 prev_…
2523 …kworker/3:2-135 [003] d..3 49.823118: sched_stat_runtime: comm=kworker/3:2 pid=135 runtime=53…
2524 …kworker/6:2-387 [006] d..3 49.823120: sched_stat_runtime: comm=kworker/6:2 pid=387 runtime=95…
2525 …kworker/6:2-387 [006] d..3 49.823122: sched_switch: prev_comm=kworker/6:2 prev_pid=387 prev_p…
2526 …kworker/3:2-135 [003] d..3 49.823123: sched_switch: prev_comm=kworker/3:2 prev_pid=135 prev_p…
2527 …<idle>-0 [004] ..s7 49.823798: tcp_probe: src=10.0.0.10:54326 dest=23.215.104.193:80 mark=0…
2530 --------------------------------
2559 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) i…
2571 # ./cyclictest -p80 -d0 -i250 -n -a -t --tracemark -b 1000
2573 -p80 : run threads at priority 80
2574 -d0 : have all threads run at the same interval
2575 -i250 : start the interval at 250 microseconds (all threads will do this)
2576 -n : sleep with nanosleep
2577 -a : affine all threads to a separate CPU
2578 -t : one thread per available CPU
2579 --tracemark : enable trace mark writing
2580 -b 1000 : stop if any latency is greater than 1000 microseconds
2582 Note, the -b 1000 is used just to make --tracemark available.
2589 # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]
2883 But this could easily be done in userspace. To make this even more
2890 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($…
2902 # trigger info: hist:keys=lat,common_pid:vals=hitcount:sort=lat:size=2048 [active]