Lines Matching +full:timer +full:- +full:cannot +full:- +full:wake +full:- +full:cpu
33 numeric fields - on an event hit, the value(s) will be added to a
35 in place of an explicit value field - this is simply a count of
45 useful for providing more fine-grained summaries of event data.
69 numeric fields are displayed as base-10 integers. This can be
76 .sym-offset display an address as a symbol and offset
83 .graph display a bar-graph of a value
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
149 - enable_hist/disable_hist
152 event conditionally start and stop another event's already-attached
190 ------------------------
204 common_cpu int the cpu on which the event occurred.
208 --------------------------
216 ---------------------------
315 absence of a user-specified sort parameter, is used as the default
324 command history and re-execute it with a '!' prepended::
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
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 …
659 keeps a per-process sum of total bytes read::
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
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
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: …
813 …{ id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: …
827 …{ id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: …
863 { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2
893 key is treated as a single entity for hashing purposes, the sub-keys
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
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
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
1213 ##### CPU 2 buffer started ####
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…
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
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
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,
1764 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp-$ts0 ...' >> event2/trigger
1776 division operators (+-\*/).
1778 Note if division by zero cannot be detected at parse time (i.e. the
1779 divisor is not a constant), the result will be -1.
1793 ----------------------
1795 Synthetic events are user-defined events generated from hist trigger
1847 instantiated in the event subsystem - for this to happen, a 'hist
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
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:
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)
2171 fields specified in the param list may be either fully-qualified
2176 fully-qualified name is of the form 'system.event_name.$var_name'
2247 CPU by a sched_switch event (saved_pid matches next_pid), calculate
2251 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\
2268 - onmax(var).save(field,.. .)
2295 wakeup_lat=common_timestamp.usecs-$ts0:\
2306 common_timestamp-ts0: 0
2312 common_timestamp-ts0: 0
2321 - onmax(var).snapshot()
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,.. .)
2443 - onchange(var).snapshot()
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.
2879 iteration comes in late, the next one will set the timer to wake up less that
2880 250. That is, if an iteration came in 50 microseconds late, the next wake up
2890 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($…