Lines Matching +full:entry +full:- +full:latency +full:- +full:us
30 When a matching event is hit, an entry is added to a hash table
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
43 keyword. Hashing a compound key produces a unique entry in the
45 useful for providing more fine-grained summaries of event data.
66 entry is a simple list of the keys and values comprising the entry;
68 followed by the set of value fields for the entry. By default,
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 ------------------------
208 --------------------------
216 ---------------------------
246 just means that each unique call_site address will have an entry
248 the hist trigger that for each unique entry (call_site) in the
290 The output displays a line for each entry, beginning with the key
313 attributed to a given entry, called the 'hitcount'. That hitcount
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: …
800 The above list does give us a breakdown of the ioctl syscall by
801 pid, but it also gives us quite a bit more than that, which we
813 …{ id: sys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: …
827 …{ id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: …
845 key and 'size' as the secondary key allows us to display an
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
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
1621 in this manner is latency, which is simply a difference in timestamps
1622 between two events. Although latency is the most important
1623 inter-event quantity, note that because the support is completely
1625 in an inter-event quantity.
1628 into a useful chain would be a 'wakeupswitch latency' histogram that
1629 combines a 'wakeup latency' histogram and a 'switch latency'
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 -
1665 example saving context when a 'max' latency has been hit.
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
1694 entry corresponding to that key, any subsequent event with a matching
1700 'read-once' - once it's used by an expression in a subsequent event,
1711 creates a variable named 'ts0' for a histogram entry with the key
1761 For example, here's how a latency can be calculated::
1764 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp-$ts0 ...' >> event2/trigger
1768 event's timestamp to produce the latency, which is then assigned into
1770 makes use of the wakeup_lat variable to compute a combined latency
1776 division operators (+-\*/).
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
1864 The above shows the latency "lat" in a power of 2 grouping.
1913 The latency values can also be grouped linearly by a given size with
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 -------------------------------------------
2101 conditionally) whenever a histogram entry is added or updated.
2103 When a histogram entry is added or updated, a hist trigger 'handler'
2119 trigger will fail with -EINVAL;
2123 entry. Some applications, however, may want to perform additional
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)
2149 and the histogram entry would be added or updated. It causes the
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'
2231 latency. The following example uses a set of hist triggers to
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,.. .)
2271 whenever the value of 'var' associated with a histogram entry
2276 maximum for that hist trigger entry. This allows context from the
2283 a sched_waking occurs, the timestamp is saved in the entry
2286 resulting latency, stored in wakeup_lat, exceeds the current
2287 maximum latency, the values specified in the save() fields are
2295 wakeup_lat=common_timestamp.usecs-$ts0:\
2306 common_timestamp-ts0: 0
2312 common_timestamp-ts0: 0
2321 - onmax(var).snapshot()
2324 whenever the value of 'var' associated with a histogram entry
2329 maximum for any hist trigger entry.
2342 a sched_waking event occurs, the timestamp is saved in the entry
2345 resulting latency, stored in wakeup_lat, exceeds the current
2346 maximum latency, a snapshot is taken. As part of the setup, all
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,.. .)
2433 whenever the value of 'var' associated with a histogram entry
2438 hist trigger entry. This allows context from the event that
2443 - onchange(var).snapshot()
2446 whenever the value of 'var' associated with a histogram entry
2451 hist trigger entry.
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 --------------------------------
2557 # echo 'latency u64 lat' > synthetic_events
2559 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) i…
2560 # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
2562 The above created a synthetic event called "latency" and two histograms
2565 it will call the "latency" synthetic event with the calculated latency as its
2566 parameter. Finally, a histogram is added to the latency synthetic event to
2567 record the calculated latency along with the pid.
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.
2586 # cat events/synthetic/latency/hist
2888 # echo 'latency u64 lat' > synthetic_events
2890 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($…
2891 # echo 'hist:keys=lat,common_pid:sort=lat' > events/synthetic/latency/trigger
2894 the latency, the sched_waking event is used, matching the common_pid for the
2899 # cat events/synthetic/latency/hist
3069 This doesn't tell us any information about how late cyclictest may have
3070 woken up, but it does show us a nice histogram of how long it took from