Lines Matching +full:1 +full:d +full:- +full:histogram
7 1. Introduction
10 Histogram triggers are special event triggers that can be used to
15 2. Histogram Trigger Command
18 A histogram trigger command is an event trigger command that
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.
51 its histogram data will be shared with other triggers of the same
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
144 raw hitcount in the histogram. This option requires at least one
149 - enable_hist/disable_hist
152 event conditionally start and stop another event's already-attached
190 ------------------------
208 --------------------------
216 ---------------------------
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;
259 { call_site: 18446744072106379007 } hitcount: 1 bytes_req: 176
260 { call_site: 18446744071579557049 } hitcount: 1 bytes_req: 1024
261 { call_site: 18446744071580608289 } hitcount: 1 bytes_req: 16384
262 { call_site: 18446744071581827654 } hitcount: 1 bytes_req: 24
263 { call_site: 18446744071580700980 } hitcount: 1 bytes_req: 8
264 { call_site: 18446744071579359876 } hitcount: 1 bytes_req: 152
315 absence of a user-specified sort parameter, is used as the default
324 command history and re-execute it with a '!' prepended::
340 { call_site: ffffffffa026b291 } hitcount: 1 bytes_req: 433
341 { call_site: ffffffffa07186ff } hitcount: 1 bytes_req: 176
342 { call_site: ffffffff811ae721 } hitcount: 1 bytes_req: 16384
343 { call_site: ffffffff811c5134 } hitcount: 1 bytes_req: 8
344 { call_site: ffffffffa04a9ebb } hitcount: 1 bytes_req: 511
345 { call_site: ffffffff8122e0a6 } hitcount: 1 bytes_req: 12
346 { call_site: ffffffff8107da84 } hitcount: 1 bytes_req: 152
347 { call_site: ffffffff812d8246 } hitcount: 1 bytes_req: 24
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
385 …10adcb9] syslog_print_all } hitcount: 1 bytes_req: 10…
386 …154bc62] usb_control_msg } hitcount: 1 bytes_req: …
387 …00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: …
388 …154acbe] usb_alloc_urb } hitcount: 1 bytes_req: 1…
389 …00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: …
390 …11e3a25] __seq_open_private } hitcount: 1 bytes_req: …
454 …1200ba6] inotify_new_group } hitcount: 1 bytes_req: …
455 …027121a] drm_getmagic [drm] } hitcount: 1 bytes_req: …
456 …11e3a25] __seq_open_private } hitcount: 1 bytes_req: …
458 …154bc62] usb_control_msg } hitcount: 1 bytes_req: …
459 …00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: …
460 …00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: …
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 …
495 …sb_control_msg+0x42/0x110 } hitcount: 1 bytes_req: …
496 …idraw_send_report+0x7e/0x1a0 [hid] } hitcount: 1 bytes_req: …
497 …idraw_report_event+0x8a/0x120 [hid] } hitcount: 1 bytes_req: …
536 …1079a2e] kthread_create_on_node } hitcount: 1 bytes_req: …
537 …00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: …
538 …154bc62] usb_control_msg } hitcount: 1 bytes_req: …
539 …00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: …
607 } hitcount: 1 bytes_req: 32 bytes_alloc: 32
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
687 { common_pid: gdbus [ 2998] } hitcount: 1 count: 16
688 { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8
689 { common_pid: init [ 1] } hitcount: 2 count: 2
708 { id: sys_fsync [ 74] } hitcount: 1
709 { id: sys_newuname [ 63] } hitcount: 1
710 { id: sys_prctl [157] } hitcount: 1
711 { id: sys_statfs [137] } hitcount: 1
712 { id: sys_symlink [ 88] } hitcount: 1
713 { id: sys_sendmmsg [307] } hitcount: 1
714 { id: sys_semctl [ 66] } hitcount: 1
728 { id: sys_write [ 1] } hitcount: 2689
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 …ys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: 1
763 …ys_read [ 0], common_pid: gdbus [ 2976] } hitcount: 1
764 …ys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: 1
765 …ys_read [ 0], common_pid: postgres [ 1865] } hitcount: 1
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: …
775 …ys_ioctl [ 16], common_pid: bash [ 8479] } hitcount: 1
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: …
812 …ys_ioctl [ 16], common_pid: gmain [ 2769] } hitcount: 1
813 …ys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: 1
814 …ys_ioctl [ 16], common_pid: gmain [ 3003] } hitcount: 1
815 …ys_ioctl [ 16], common_pid: gmain [ 2781] } hitcount: 1
816 …ys_ioctl [ 16], common_pid: gmain [ 2829] } hitcount: 1
817 …ys_ioctl [ 16], common_pid: bash [ 8726] } hitcount: 1
818 …ys_ioctl [ 16], common_pid: bash [ 8508] } hitcount: 1
819 …ys_ioctl [ 16], common_pid: gmain [ 2970] } hitcount: 1
820 …ys_ioctl [ 16], common_pid: gmain [ 2768] } hitcount: 1
827 …{ id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: …
855 { common_pid: smbd [ 784], size: 4 } hitcount: 1
860 { common_pid: bamfdaemon [ 2787], size: 14360 } hitcount: 1
861 { common_pid: compiz [ 2994], size: 8 } hitcount: 1
863 { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2
864 { common_pid: firefox [ 8817], size: 4 } hitcount: 1
867 { common_pid: firefox [ 8817], size: 628 } hitcount: 1
868 { common_pid: firefox [ 8817], size: 6944 } hitcount: 1
873 { common_pid: firefox [ 8822], size: 352 } hitcount: 1
884 { common_pid: pool [ 8929], size: 1982 } hitcount: 1
885 { common_pid: pool [ 8929], size: 2048 } hitcount: 1
893 key is treated as a single entity for hashing purposes, the sub-keys
908 { child_comm: dconf worker } hitcount: 1
909 { child_comm: ibus-daemon } hitcount: 1
910 { child_comm: whoopsie } hitcount: 1
911 { child_comm: smbd } hitcount: 1
912 { child_comm: gdbus } hitcount: 1
913 { child_comm: kthreadd } hitcount: 1
914 { child_comm: dconf worker } 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
944 { child_comm: dconf worker } hitcount: 1
945 { child_comm: kthreadd } hitcount: 1
946 { child_comm: dconf worker } hitcount: 1
947 { child_comm: gdbus } hitcount: 1
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
981 { child_comm: dconf worker } hitcount: 1
982 { child_comm: dconf worker } hitcount: 1
983 { child_comm: kthreadd } hitcount: 1
984 { child_comm: gdbus } hitcount: 1
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
1142 into the histogram. In order to avoid having to set everything up
1143 again, we can just clear the histogram first::
1186 disables both the histogram and the event log, and what you end up
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…
1252 # event histogram
1257 { len: 176 } hitcount: 1 common_preempt_count: 0
1258 { len: 223 } hitcount: 1 common_preempt_count: 0
1259 { len: 4854 } hitcount: 1 common_preempt_count: 0
1260 { len: 395 } hitcount: 1 common_preempt_count: 0
1261 { len: 177 } hitcount: 1 common_preempt_count: 0
1262 { len: 446 } hitcount: 1 common_preempt_count: 0
1263 { len: 1601 } hitcount: 1 common_preempt_count: 0
1279 # event histogram
1284 { skbaddr: ffff8800baee5e00 } hitcount: 1 len: 130
1285 { skbaddr: ffff88005f3d5600 } hitcount: 1 len: 1280
1286 { skbaddr: ffff88005f3d4900 } hitcount: 1 len: 1280
1287 { skbaddr: ffff88009fed6300 } hitcount: 1 len: 115
1288 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 115
1289 { skbaddr: ffff88008cdb1900 } hitcount: 1 len: 46
1290 { skbaddr: ffff880064b5ef00 } hitcount: 1 len: 118
1291 { skbaddr: ffff880044e3c700 } hitcount: 1 len: 60
1292 { skbaddr: ffff880100065900 } hitcount: 1 len: 46
1293 { skbaddr: ffff8800d46bd500 } hitcount: 1 len: 116
1294 { skbaddr: ffff88005f3d5f00 } hitcount: 1 len: 1280
1295 { skbaddr: ffff880100064700 } hitcount: 1 len: 365
1296 { skbaddr: ffff8800badb6f00 } hitcount: 1 len: 60
1316 # event histogram
1328 # event histogram
1333 { skbaddr: ffff88009fd2c300 } hitcount: 1 len: 7212
1334 { skbaddr: ffff8800d2bcce00 } hitcount: 1 len: 7212
1335 { skbaddr: ffff8800d2bcd700 } hitcount: 1 len: 7212
1336 { skbaddr: ffff8800d2bcda00 } hitcount: 1 len: 21492
1337 { skbaddr: ffff8800ae2e2d00 } hitcount: 1 len: 7212
1338 { skbaddr: ffff8800d2bcdb00 } hitcount: 1 len: 7212
1339 { skbaddr: ffff88006a4df500 } hitcount: 1 len: 4854
1340 { skbaddr: ffff88008ce47b00 } hitcount: 1 len: 18636
1341 { skbaddr: ffff8800ae2e2200 } hitcount: 1 len: 12924
1342 { skbaddr: ffff88005f3e1000 } hitcount: 1 len: 4356
1352 # event histogram
1364 histogram data. This capability is mostly useful for combining the
1368 field in the shared 'foo' histogram data::
1375 You can see that they're updating common histogram data by reading
1381 # event histogram
1386 { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46
1387 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76
1388 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46
1389 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468
1390 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46
1391 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52
1392 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168
1393 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46
1394 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260
1395 { skbaddr: ffff880064505000 } hitcount: 1 len: 46
1396 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32
1397 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46
1398 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44
1399 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168
1400 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40
1401 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40
1402 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174
1403 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160
1404 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76
1405 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46
1406 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32
1407 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46
1408 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988
1409 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46
1410 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44
1433 # event histogram
1438 { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46
1439 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76
1440 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46
1441 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468
1442 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46
1443 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52
1444 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168
1445 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46
1446 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260
1447 { skbaddr: ffff880064505000 } hitcount: 1 len: 46
1448 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32
1449 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46
1450 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44
1451 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168
1452 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40
1453 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40
1454 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174
1455 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160
1456 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76
1457 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46
1458 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32
1459 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46
1460 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988
1461 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46
1462 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44
1486 And here's an example that shows how to combine histogram data from
1502 # event histogram
1512 } hitcount: 1
1530 } hitcount: 1
1611 2.2 Inter-event hist triggers
1612 -----------------------------
1614 Inter-event hist triggers are hist triggers that combine values from
1615 one or more other events and create a histogram using that data. Data
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.
1627 An example of a histogram that combines data from other histograms
1628 into a useful chain would be a 'wakeupswitch latency' histogram that
1629 combines a 'wakeup latency' histogram and a 'switch latency'
1630 histogram.
1634 continually updated sums associated with that key. A histogram
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
1646 requires the introduction of support for histogram 'variables'.
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
1653 histogram on either event (so having the 'hist' file for either
1654 event host the histogram output doesn't really make sense). To
1655 address the idea that the histogram is associated with 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
1678 histogram, the trace buffer is automatically switched over to using
1684 pseudo-file.
1688 2.2.1 Histogram Variables
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,
1711 creates a variable named 'ts0' for a histogram entry with the key
1725 will also be summed as a normal histogram value would (though for a
1754 thing but without the values being summed in the histogram::
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.
1793 ----------------------
1795 Synthetic events are user-defined events generated from hist trigger
1847 instantiated in the event subsystem - for this to happen, a 'hist
1859 A histogram can now be defined for the new synthetic event::
1866 Like any other event, once a histogram is enabled for the event, the
1871 # event histogram
1883 { pid: 2032, prio: 120, lat: ~ 2^2 } hitcount: 1
1893 { pid: 2030, prio: 120, lat: ~ 2^3 } hitcount: 1
1902 { pid: 2028, prio: 120, lat: ~ 2^4 } hitcount: 1
1904 { pid: 2031, prio: 120, lat: ~ 2^7 } hitcount: 1
1905 { pid: 2032, prio: 120, lat: ~ 2^7 } hitcount: 1
1919 # event histogram
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…
1954 # echo 1 > events/synthetic/block_lat/enable
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:
1994 histogram::
1999 # event histogram
2003 { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
2014 } hitcount: 1
2015 { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
2030 } hitcount: 1
2031 { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
2047 { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
2061 } hitcount: 1
2062 { delta: ~ 0-99, stack.stacktrace __schedule+0xa19/0x1520
2074 } hitcount: 1
2075 { delta: ~ 100-199, stack.stacktrace __schedule+0xa19/0x1520
2090 } hitcount: 1
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;
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'
2181 onmatch() functionality, in the form 'system.event_name'. Histogram
2183 multiple histogram keys are used, they all must match in the specified
2217 Creating and displaying a histogram based on those events is now
2225 wakeup_new_test synthetic events which should result in histogram
2232 produce a 'wakeup_latency' histogram.
2251 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\
2256 We also need to create a histogram on the wakeup_latency synthetic
2268 - onmax(var).save(field,.. .)
2271 whenever the value of 'var' associated with a histogram entry
2278 reference. When the histogram is displayed, additional fields
2295 wakeup_lat=common_timestamp.usecs-$ts0:\
2300 When the histogram is displayed, the max value and the saved
2306 common_timestamp-ts0: 0
2309 prev_pid: 0 prev_prio: 120 prev_comm: swapper/1
2312 common_timestamp-ts0: 0
2321 - onmax(var).snapshot()
2324 whenever the value of 'var' associated with a histogram entry
2333 the histogram. The key of the specific trace event that caused
2337 to locate the corresponding bucket in the histogram for even more
2350 # echo 1 > /sys/kernel/tracing/events/sched/enable
2356 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \
2362 When the histogram is displayed, for each bucket the max value
2376 prev_pid: 0 prev_prio: 120 prev_comm: swapper/1
2393 2103 as the key, you'll find the additional values save()'d along
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
2440 histogram is displayed, additional fields displaying the saved
2443 - onchange(var).snapshot()
2446 whenever the value of 'var' associated with a histogram entry
2459 histogram for even more detail.
2469 # echo 1 > /sys/kernel/tracing/events/sched/enable
2470 # echo 1 > /sys/kernel/tracing/events/tcp/enable
2477 When the histogram is displayed, for each bucket the tracked value
2510 the key, you'll find the additional values save()'d along with 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 --------------------------------
2554 We can make a histogram from this::
2559 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) i…
2566 parameter. Finally, a histogram is added to the latency synthetic event to
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.
2584 Then we can see the histogram created by this with::
2587 # event histogram
2592 { lat: 107, common_pid: 2039 } hitcount: 1
2593 { lat: 122, common_pid: 2041 } hitcount: 1
2594 { lat: 166, common_pid: 2039 } hitcount: 1
2595 { lat: 174, common_pid: 2039 } hitcount: 1
2596 { lat: 194, common_pid: 2041 } hitcount: 1
2597 { lat: 196, common_pid: 2036 } hitcount: 1
2598 { lat: 197, common_pid: 2038 } hitcount: 1
2599 { lat: 198, common_pid: 2039 } hitcount: 1
2600 { lat: 199, common_pid: 2039 } hitcount: 1
2601 { lat: 200, common_pid: 2041 } hitcount: 1
2603 { lat: 202, common_pid: 2038 } hitcount: 1
2604 { lat: 202, common_pid: 2043 } hitcount: 1
2605 { lat: 203, common_pid: 2039 } hitcount: 1
2606 { lat: 203, common_pid: 2036 } hitcount: 1
2607 { lat: 203, common_pid: 2041 } hitcount: 1
2609 { lat: 207, common_pid: 2039 } hitcount: 1
2610 { lat: 207, common_pid: 2036 } hitcount: 1
2611 { lat: 208, common_pid: 2040 } hitcount: 1
2612 { lat: 209, common_pid: 2043 } hitcount: 1
2613 { lat: 210, common_pid: 2039 } hitcount: 1
2615 { lat: 212, common_pid: 2043 } hitcount: 1
2617 { lat: 213, common_pid: 2039 } hitcount: 1
2618 { lat: 214, common_pid: 2038 } hitcount: 1
2620 { lat: 214, common_pid: 2042 } hitcount: 1
2621 { lat: 215, common_pid: 2039 } hitcount: 1
2622 { lat: 217, common_pid: 2036 } hitcount: 1
2623 { lat: 217, common_pid: 2040 } hitcount: 1
2624 { lat: 217, common_pid: 2039 } hitcount: 1
2629 { lat: 221, common_pid: 2042 } hitcount: 1
2631 { lat: 223, common_pid: 2036 } hitcount: 1
2634 { lat: 224, common_pid: 2037 } hitcount: 1
2637 { lat: 225, common_pid: 2042 } hitcount: 1
2642 { lat: 227, common_pid: 2043 } hitcount: 1
2647 { lat: 229, common_pid: 2038 } hitcount: 1
2650 { lat: 230, common_pid: 2043 } hitcount: 1
2652 { lat: 231, common_pid: 2041 } hitcount: 1
2654 { lat: 231, common_pid: 2043 } hitcount: 1
2656 { lat: 232, common_pid: 2037 } hitcount: 1
2660 { lat: 232, common_pid: 2043 } hitcount: 1
2667 { lat: 234, common_pid: 2040 } hitcount: 1
2674 { lat: 235, common_pid: 2041 } hitcount: 1
2676 { lat: 236, common_pid: 2037 } hitcount: 1
2681 { lat: 237, common_pid: 2037 } hitcount: 1
2682 { lat: 237, common_pid: 2040 } hitcount: 1
2689 { lat: 238, common_pid: 2040 } hitcount: 1
2691 { lat: 238, common_pid: 2038 } hitcount: 1
2692 { lat: 238, common_pid: 2039 } hitcount: 1
2695 { lat: 239, common_pid: 2041 } hitcount: 1
2700 { lat: 239, common_pid: 2040 } hitcount: 1
2705 { lat: 240, common_pid: 2039 } hitcount: 1
2707 { lat: 240, common_pid: 2038 } hitcount: 1
2775 { lat: 249, common_pid: 2038 } hitcount: 1
2782 { lat: 250, common_pid: 2038 } hitcount: 1
2787 { lat: 250, common_pid: 2041 } hitcount: 1
2791 { lat: 251, common_pid: 2039 } hitcount: 1
2794 { lat: 251, common_pid: 2041 } hitcount: 1
2797 { lat: 252, common_pid: 2040 } hitcount: 1
2805 { lat: 253, common_pid: 2040 } hitcount: 1
2808 { lat: 254, common_pid: 2041 } hitcount: 1
2809 { lat: 254, common_pid: 2042 } hitcount: 1
2810 { lat: 254, common_pid: 2039 } hitcount: 1
2812 { lat: 255, common_pid: 2043 } hitcount: 1
2816 { lat: 256, common_pid: 2043 } hitcount: 1
2836 { lat: 265, common_pid: 2039 } hitcount: 1
2837 { lat: 266, common_pid: 2036 } hitcount: 1
2839 { lat: 267, common_pid: 2036 } hitcount: 1
2841 { lat: 268, common_pid: 2036 } hitcount: 1
2843 { lat: 269, common_pid: 2036 } hitcount: 1
2844 { lat: 269, common_pid: 2043 } hitcount: 1
2846 { lat: 270, common_pid: 2040 } hitcount: 1
2848 { lat: 271, common_pid: 2041 } hitcount: 1
2853 { lat: 275, common_pid: 2039 } hitcount: 1
2855 { lat: 276, common_pid: 2037 } hitcount: 1
2856 { lat: 276, common_pid: 2038 } hitcount: 1
2857 { lat: 277, common_pid: 2039 } hitcount: 1
2858 { lat: 277, common_pid: 2042 } hitcount: 1
2859 { lat: 278, common_pid: 2039 } hitcount: 1
2861 { lat: 279, common_pid: 2043 } hitcount: 1
2864 { lat: 284, common_pid: 2039 } hitcount: 1
2865 { lat: 284, common_pid: 2043 } hitcount: 1
2866 { lat: 288, common_pid: 2039 } hitcount: 1
2867 { lat: 289, common_pid: 2039 } hitcount: 1
2868 { lat: 300, common_pid: 2039 } hitcount: 1
2869 { lat: 384, common_pid: 2039 } hitcount: 1
2884 interesting, we can mix the histogram between events that happened in the
2890 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($…
2900 # event histogram
2909 { lat: 7, common_pid: 2306 } hitcount: 1
2947 { lat: 12, common_pid: 2303 } hitcount: 1
2950 { lat: 13, common_pid: 2301 } hitcount: 1
2953 { lat: 13, common_pid: 2305 } hitcount: 1
2954 { lat: 13, common_pid: 2303 } hitcount: 1
2962 { lat: 14, common_pid: 2299 } hitcount: 1
2964 { lat: 15, common_pid: 2305 } hitcount: 1
2968 { lat: 15, common_pid: 2301 } hitcount: 1
2970 { lat: 15, common_pid: 2303 } hitcount: 1
2976 { lat: 17, common_pid: 2303 } hitcount: 1
2977 { lat: 18, common_pid: 2304 } hitcount: 1
2979 { lat: 18, common_pid: 2299 } hitcount: 1
2980 { lat: 18, common_pid: 2301 } hitcount: 1
2985 { lat: 19, common_pid: 2306 } hitcount: 1
2990 { lat: 20, common_pid: 2305 } hitcount: 1
2994 { lat: 21, common_pid: 2305 } hitcount: 1
2998 { lat: 21, common_pid: 2300 } hitcount: 1
3002 { lat: 22, common_pid: 2303 } hitcount: 1
3005 { lat: 22, common_pid: 2300 } hitcount: 1
3006 { lat: 22, common_pid: 2299 } hitcount: 1
3007 { lat: 22, common_pid: 2305 } hitcount: 1
3008 { lat: 22, common_pid: 2304 } hitcount: 1
3009 { lat: 23, common_pid: 2299 } hitcount: 1
3013 { lat: 24, common_pid: 2300 } hitcount: 1
3015 { lat: 24, common_pid: 2305 } hitcount: 1
3016 { lat: 24, common_pid: 2299 } hitcount: 1
3017 { lat: 25, common_pid: 2300 } hitcount: 1
3020 { lat: 27, common_pid: 2305 } hitcount: 1
3021 { lat: 27, common_pid: 2300 } hitcount: 1
3023 { lat: 28, common_pid: 2306 } hitcount: 1
3025 { lat: 29, common_pid: 2302 } hitcount: 1
3027 { lat: 29, common_pid: 2306 } hitcount: 1
3028 { lat: 29, common_pid: 2304 } hitcount: 1
3031 { lat: 32, common_pid: 2302 } hitcount: 1
3032 { lat: 33, common_pid: 2299 } hitcount: 1
3035 { lat: 35, common_pid: 2302 } hitcount: 1
3036 { lat: 35, common_pid: 2304 } hitcount: 1
3041 { lat: 39, common_pid: 2304 } hitcount: 1
3044 { lat: 41, common_pid: 2304 } hitcount: 1
3047 { lat: 42, common_pid: 2304 } hitcount: 1
3054 { lat: 48, common_pid: 2301 } hitcount: 1
3057 { lat: 50, common_pid: 2302 } hitcount: 1
3058 { lat: 50, common_pid: 2301 } hitcount: 1
3060 { lat: 51, common_pid: 2301 } hitcount: 1
3061 { lat: 61, common_pid: 2302 } hitcount: 1
3062 { lat: 110, common_pid: 2302 } hitcount: 1
3070 woken up, but it does show us a nice histogram of how long it took from