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
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
139 - enable_hist/disable_hist
142 event conditionally start and stop another event's already-attached
180 ------------------------
198 --------------------------
206 ---------------------------
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;
249 { call_site: 18446744072106379007 } hitcount: 1 bytes_req: 176
250 { call_site: 18446744071579557049 } hitcount: 1 bytes_req: 1024
251 { call_site: 18446744071580608289 } hitcount: 1 bytes_req: 16384
252 { call_site: 18446744071581827654 } hitcount: 1 bytes_req: 24
253 { call_site: 18446744071580700980 } hitcount: 1 bytes_req: 8
254 { call_site: 18446744071579359876 } hitcount: 1 bytes_req: 152
305 absence of a user-specified sort parameter, is used as the default
314 command history and re-execute it with a '!' prepended::
330 { call_site: ffffffffa026b291 } hitcount: 1 bytes_req: 433
331 { call_site: ffffffffa07186ff } hitcount: 1 bytes_req: 176
332 { call_site: ffffffff811ae721 } hitcount: 1 bytes_req: 16384
333 { call_site: ffffffff811c5134 } hitcount: 1 bytes_req: 8
334 { call_site: ffffffffa04a9ebb } hitcount: 1 bytes_req: 511
335 { call_site: ffffffff8122e0a6 } hitcount: 1 bytes_req: 12
336 { call_site: ffffffff8107da84 } hitcount: 1 bytes_req: 152
337 { call_site: ffffffff812d8246 } hitcount: 1 bytes_req: 24
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
375 …10adcb9] syslog_print_all } hitcount: 1 bytes_req: 10…
376 …154bc62] usb_control_msg } hitcount: 1 bytes_req: …
377 …00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: …
378 …154acbe] usb_alloc_urb } hitcount: 1 bytes_req: 1…
379 …00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: …
380 …11e3a25] __seq_open_private } hitcount: 1 bytes_req: …
444 …1200ba6] inotify_new_group } hitcount: 1 bytes_req: …
445 …027121a] drm_getmagic [drm] } hitcount: 1 bytes_req: …
446 …11e3a25] __seq_open_private } hitcount: 1 bytes_req: …
448 …154bc62] usb_control_msg } hitcount: 1 bytes_req: …
449 …00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: …
450 …00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: …
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 …
485 …sb_control_msg+0x42/0x110 } hitcount: 1 bytes_req: …
486 …idraw_send_report+0x7e/0x1a0 [hid] } hitcount: 1 bytes_req: …
487 …idraw_report_event+0x8a/0x120 [hid] } hitcount: 1 bytes_req: …
526 …1079a2e] kthread_create_on_node } hitcount: 1 bytes_req: …
527 …00bf6fe] hidraw_send_report [hid] } hitcount: 1 bytes_req: …
528 …154bc62] usb_control_msg } hitcount: 1 bytes_req: …
529 …00bf1ca] hidraw_report_event [hid] } hitcount: 1 bytes_req: …
597 } hitcount: 1 bytes_req: 32 bytes_alloc: 32
649 keeps a per-process sum of total bytes read::
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
677 { common_pid: gdbus [ 2998] } hitcount: 1 count: 16
678 { common_pid: rtkit-daemon [ 2052] } hitcount: 1 count: 8
679 { common_pid: init [ 1] } hitcount: 2 count: 2
698 { id: sys_fsync [ 74] } hitcount: 1
699 { id: sys_newuname [ 63] } hitcount: 1
700 { id: sys_prctl [157] } hitcount: 1
701 { id: sys_statfs [137] } hitcount: 1
702 { id: sys_symlink [ 88] } hitcount: 1
703 { id: sys_sendmmsg [307] } hitcount: 1
704 { id: sys_semctl [ 66] } hitcount: 1
718 { id: sys_write [ 1] } hitcount: 2689
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
752 …ys_read [ 0], common_pid: rtkit-daemon [ 1877] } hitcount: 1
753 …ys_read [ 0], common_pid: gdbus [ 2976] } hitcount: 1
754 …ys_read [ 0], common_pid: console-kit-dae [ 3400] } hitcount: 1
755 …ys_read [ 0], common_pid: postgres [ 1865] } hitcount: 1
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: …
765 …ys_ioctl [ 16], common_pid: bash [ 8479] } hitcount: 1
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: …
802 …ys_ioctl [ 16], common_pid: gmain [ 2769] } hitcount: 1
803 …ys_ioctl [ 16], common_pid: evolution-addre [ 8571] } hitcount: 1
804 …ys_ioctl [ 16], common_pid: gmain [ 3003] } hitcount: 1
805 …ys_ioctl [ 16], common_pid: gmain [ 2781] } hitcount: 1
806 …ys_ioctl [ 16], common_pid: gmain [ 2829] } hitcount: 1
807 …ys_ioctl [ 16], common_pid: bash [ 8726] } hitcount: 1
808 …ys_ioctl [ 16], common_pid: bash [ 8508] } hitcount: 1
809 …ys_ioctl [ 16], common_pid: gmain [ 2970] } hitcount: 1
810 …ys_ioctl [ 16], common_pid: gmain [ 2768] } hitcount: 1
817 …{ id: sys_ioctl [ 16], common_pid: avahi-daemon [ 896] } hitcount: …
845 { common_pid: smbd [ 784], size: 4 } hitcount: 1
850 { common_pid: bamfdaemon [ 2787], size: 14360 } hitcount: 1
851 { common_pid: compiz [ 2994], size: 8 } hitcount: 1
853 { common_pid: gnome-terminal [ 3199], size: 4 } hitcount: 2
854 { common_pid: firefox [ 8817], size: 4 } hitcount: 1
857 { common_pid: firefox [ 8817], size: 628 } hitcount: 1
858 { common_pid: firefox [ 8817], size: 6944 } hitcount: 1
863 { common_pid: firefox [ 8822], size: 352 } hitcount: 1
874 { common_pid: pool [ 8929], size: 1982 } hitcount: 1
875 { common_pid: pool [ 8929], size: 2048 } hitcount: 1
883 key is treated as a single entity for hashing purposes, the sub-keys
898 { child_comm: dconf worker } hitcount: 1
899 { child_comm: ibus-daemon } hitcount: 1
900 { child_comm: whoopsie } hitcount: 1
901 { child_comm: smbd } hitcount: 1
902 { child_comm: gdbus } hitcount: 1
903 { child_comm: kthreadd } hitcount: 1
904 { child_comm: dconf worker } 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
934 { child_comm: dconf worker } hitcount: 1
935 { child_comm: kthreadd } hitcount: 1
936 { child_comm: dconf worker } hitcount: 1
937 { child_comm: gdbus } hitcount: 1
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
971 { child_comm: dconf worker } hitcount: 1
972 { child_comm: dconf worker } hitcount: 1
973 { child_comm: kthreadd } hitcount: 1
974 { child_comm: gdbus } hitcount: 1
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
1050 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1132 into the histogram. In order to avoid having to set everything up
1133 again, we can just clear the histogram first::
1176 disables both the histogram and the event log, and what you end up
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…
1242 # event histogram
1247 { len: 176 } hitcount: 1 common_preempt_count: 0
1248 { len: 223 } hitcount: 1 common_preempt_count: 0
1249 { len: 4854 } hitcount: 1 common_preempt_count: 0
1250 { len: 395 } hitcount: 1 common_preempt_count: 0
1251 { len: 177 } hitcount: 1 common_preempt_count: 0
1252 { len: 446 } hitcount: 1 common_preempt_count: 0
1253 { len: 1601 } hitcount: 1 common_preempt_count: 0
1269 # event histogram
1274 { skbaddr: ffff8800baee5e00 } hitcount: 1 len: 130
1275 { skbaddr: ffff88005f3d5600 } hitcount: 1 len: 1280
1276 { skbaddr: ffff88005f3d4900 } hitcount: 1 len: 1280
1277 { skbaddr: ffff88009fed6300 } hitcount: 1 len: 115
1278 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 115
1279 { skbaddr: ffff88008cdb1900 } hitcount: 1 len: 46
1280 { skbaddr: ffff880064b5ef00 } hitcount: 1 len: 118
1281 { skbaddr: ffff880044e3c700 } hitcount: 1 len: 60
1282 { skbaddr: ffff880100065900 } hitcount: 1 len: 46
1283 { skbaddr: ffff8800d46bd500 } hitcount: 1 len: 116
1284 { skbaddr: ffff88005f3d5f00 } hitcount: 1 len: 1280
1285 { skbaddr: ffff880100064700 } hitcount: 1 len: 365
1286 { skbaddr: ffff8800badb6f00 } hitcount: 1 len: 60
1306 # event histogram
1318 # event histogram
1323 { skbaddr: ffff88009fd2c300 } hitcount: 1 len: 7212
1324 { skbaddr: ffff8800d2bcce00 } hitcount: 1 len: 7212
1325 { skbaddr: ffff8800d2bcd700 } hitcount: 1 len: 7212
1326 { skbaddr: ffff8800d2bcda00 } hitcount: 1 len: 21492
1327 { skbaddr: ffff8800ae2e2d00 } hitcount: 1 len: 7212
1328 { skbaddr: ffff8800d2bcdb00 } hitcount: 1 len: 7212
1329 { skbaddr: ffff88006a4df500 } hitcount: 1 len: 4854
1330 { skbaddr: ffff88008ce47b00 } hitcount: 1 len: 18636
1331 { skbaddr: ffff8800ae2e2200 } hitcount: 1 len: 12924
1332 { skbaddr: ffff88005f3e1000 } hitcount: 1 len: 4356
1342 # event histogram
1354 histogram data. This capability is mostly useful for combining the
1358 field in the shared 'foo' histogram data::
1365 You can see that they're updating common histogram data by reading
1371 # event histogram
1376 { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46
1377 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76
1378 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46
1379 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468
1380 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46
1381 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52
1382 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168
1383 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46
1384 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260
1385 { skbaddr: ffff880064505000 } hitcount: 1 len: 46
1386 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32
1387 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46
1388 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44
1389 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168
1390 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40
1391 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40
1392 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174
1393 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160
1394 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76
1395 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46
1396 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32
1397 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46
1398 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988
1399 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46
1400 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44
1423 # event histogram
1428 { skbaddr: ffff88000ad53500 } hitcount: 1 len: 46
1429 { skbaddr: ffff8800af5a1500 } hitcount: 1 len: 76
1430 { skbaddr: ffff8800d62a1900 } hitcount: 1 len: 46
1431 { skbaddr: ffff8800d2bccb00 } hitcount: 1 len: 468
1432 { skbaddr: ffff8800d3c69900 } hitcount: 1 len: 46
1433 { skbaddr: ffff88009ff09100 } hitcount: 1 len: 52
1434 { skbaddr: ffff88010f13ab00 } hitcount: 1 len: 168
1435 { skbaddr: ffff88006a54f400 } hitcount: 1 len: 46
1436 { skbaddr: ffff8800d2bcc500 } hitcount: 1 len: 260
1437 { skbaddr: ffff880064505000 } hitcount: 1 len: 46
1438 { skbaddr: ffff8800baf24e00 } hitcount: 1 len: 32
1439 { skbaddr: ffff88009fe0ad00 } hitcount: 1 len: 46
1440 { skbaddr: ffff8800d3edff00 } hitcount: 1 len: 44
1441 { skbaddr: ffff88009fe0b400 } hitcount: 1 len: 168
1442 { skbaddr: ffff8800a1c55a00 } hitcount: 1 len: 40
1443 { skbaddr: ffff8800d2bcd100 } hitcount: 1 len: 40
1444 { skbaddr: ffff880064505f00 } hitcount: 1 len: 174
1445 { skbaddr: ffff8800a8bff200 } hitcount: 1 len: 160
1446 { skbaddr: ffff880044e3cc00 } hitcount: 1 len: 76
1447 { skbaddr: ffff8800a8bfe700 } hitcount: 1 len: 46
1448 { skbaddr: ffff8800d2bcdc00 } hitcount: 1 len: 32
1449 { skbaddr: ffff8800a1f64800 } hitcount: 1 len: 46
1450 { skbaddr: ffff8800d2bcde00 } hitcount: 1 len: 988
1451 { skbaddr: ffff88006a5dea00 } hitcount: 1 len: 46
1452 { skbaddr: ffff88002e37a200 } hitcount: 1 len: 44
1476 And here's an example that shows how to combine histogram data from
1492 # event histogram
1502 } hitcount: 1
1520 } hitcount: 1
1601 2.2 Inter-event hist triggers
1602 -----------------------------
1604 Inter-event hist triggers are hist triggers that combine values from
1605 one or more other events and create a histogram using that data. Data
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
1615 in an inter-event quantity.
1617 An example of a histogram that combines data from other histograms
1618 into a useful chain would be a 'wakeupswitch latency' histogram that
1619 combines a 'wakeup latency' histogram and a 'switch latency'
1620 histogram.
1624 continually updated sums associated with that key. A histogram
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
1636 requires the introduction of support for histogram 'variables'.
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
1643 histogram on either event (so having the 'hist' file for either
1644 event host the histogram output doesn't really make sense). To
1645 address the idea that the histogram is associated with 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
1667 A note on inter-event timestamps: If common_timestamp is used in a
1668 histogram, the trace buffer is automatically switched over to using
1674 pseudo-file.
1678 2.2.1 Histogram Variables
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,
1701 creates a variable named 'ts0' for a histogram entry with the key
1715 will also be summed as a normal histogram value would (though for a
1744 thing but without the values being summed in the histogram::
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
1820 instantiated in the event subsystem - for this to happen, a 'hist
1826 A histogram can now be defined for the new synthetic event::
1837 Like any other event, once a histogram is enabled for the event, the
1841 -------------------------------------------
1844 conditionally) whenever a histogram entry is added or updated.
1846 When a histogram entry is added or updated, a hist trigger 'handler'
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)
1892 and the histogram entry would be added or updated. It causes the
1914 fields specified in the param list may be either fully-qualified
1919 fully-qualified name is of the form 'system.event_name.$var_name'
1924 onmatch() functionality, in the form 'system.event_name'. Histogram
1926 multiple histogram keys are used, they all must match in the specified
1960 Creating and displaying a histogram based on those events is now
1968 wakeup_new_test synthetic events which should result in histogram
1975 produce a 'wakeup_latency' histogram.
1994 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\
1999 We also need to create a histogram on the wakeup_latency synthetic
2011 - onmax(var).save(field,.. .)
2014 whenever the value of 'var' associated with a histogram entry
2021 reference. When the histogram is displayed, additional fields
2038 wakeup_lat=common_timestamp.usecs-$ts0:\
2043 When the histogram is displayed, the max value and the saved
2049 common_timestamp-ts0: 0
2052 prev_pid: 0 prev_prio: 120 prev_comm: swapper/1
2055 common_timestamp-ts0: 0
2064 - onmax(var).snapshot()
2067 whenever the value of 'var' associated with a histogram entry
2076 the histogram. The key of the specific trace event that caused
2080 to locate the corresponding bucket in the histogram for even more
2093 # echo 1 > /sys/kernel/debug/tracing/events/sched/enable
2099 # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \
2105 When the histogram is displayed, for each bucket the max value
2119 prev_pid: 0 prev_prio: 120 prev_comm: swapper/1
2136 2103 as the key, you'll find the additional values save()'d along
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,.. .)
2176 whenever the value of 'var' associated with a histogram entry
2183 histogram is displayed, additional fields displaying the saved
2186 - onchange(var).snapshot()
2189 whenever the value of 'var' associated with a histogram entry
2202 histogram for even more detail.
2212 # echo 1 > /sys/kernel/debug/tracing/events/sched/enable
2213 # echo 1 > /sys/kernel/debug/tracing/events/tcp/enable
2220 When the histogram is displayed, for each bucket the tracked value
2253 the key, you'll find the additional values save()'d along with 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 --------------------------------
2297 We can make a histogram from this::
2302 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(ftrace.print).latency($lat) i…
2309 parameter. Finally, a histogram is added to the latency synthetic event to
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.
2327 Then we can see the histogram created by this with::
2330 # event histogram
2335 { lat: 107, common_pid: 2039 } hitcount: 1
2336 { lat: 122, common_pid: 2041 } hitcount: 1
2337 { lat: 166, common_pid: 2039 } hitcount: 1
2338 { lat: 174, common_pid: 2039 } hitcount: 1
2339 { lat: 194, common_pid: 2041 } hitcount: 1
2340 { lat: 196, common_pid: 2036 } hitcount: 1
2341 { lat: 197, common_pid: 2038 } hitcount: 1
2342 { lat: 198, common_pid: 2039 } hitcount: 1
2343 { lat: 199, common_pid: 2039 } hitcount: 1
2344 { lat: 200, common_pid: 2041 } hitcount: 1
2346 { lat: 202, common_pid: 2038 } hitcount: 1
2347 { lat: 202, common_pid: 2043 } hitcount: 1
2348 { lat: 203, common_pid: 2039 } hitcount: 1
2349 { lat: 203, common_pid: 2036 } hitcount: 1
2350 { lat: 203, common_pid: 2041 } hitcount: 1
2352 { lat: 207, common_pid: 2039 } hitcount: 1
2353 { lat: 207, common_pid: 2036 } hitcount: 1
2354 { lat: 208, common_pid: 2040 } hitcount: 1
2355 { lat: 209, common_pid: 2043 } hitcount: 1
2356 { lat: 210, common_pid: 2039 } hitcount: 1
2358 { lat: 212, common_pid: 2043 } hitcount: 1
2360 { lat: 213, common_pid: 2039 } hitcount: 1
2361 { lat: 214, common_pid: 2038 } hitcount: 1
2363 { lat: 214, common_pid: 2042 } hitcount: 1
2364 { lat: 215, common_pid: 2039 } hitcount: 1
2365 { lat: 217, common_pid: 2036 } hitcount: 1
2366 { lat: 217, common_pid: 2040 } hitcount: 1
2367 { lat: 217, common_pid: 2039 } hitcount: 1
2372 { lat: 221, common_pid: 2042 } hitcount: 1
2374 { lat: 223, common_pid: 2036 } hitcount: 1
2377 { lat: 224, common_pid: 2037 } hitcount: 1
2380 { lat: 225, common_pid: 2042 } hitcount: 1
2385 { lat: 227, common_pid: 2043 } hitcount: 1
2390 { lat: 229, common_pid: 2038 } hitcount: 1
2393 { lat: 230, common_pid: 2043 } hitcount: 1
2395 { lat: 231, common_pid: 2041 } hitcount: 1
2397 { lat: 231, common_pid: 2043 } hitcount: 1
2399 { lat: 232, common_pid: 2037 } hitcount: 1
2403 { lat: 232, common_pid: 2043 } hitcount: 1
2410 { lat: 234, common_pid: 2040 } hitcount: 1
2417 { lat: 235, common_pid: 2041 } hitcount: 1
2419 { lat: 236, common_pid: 2037 } hitcount: 1
2424 { lat: 237, common_pid: 2037 } hitcount: 1
2425 { lat: 237, common_pid: 2040 } hitcount: 1
2432 { lat: 238, common_pid: 2040 } hitcount: 1
2434 { lat: 238, common_pid: 2038 } hitcount: 1
2435 { lat: 238, common_pid: 2039 } hitcount: 1
2438 { lat: 239, common_pid: 2041 } hitcount: 1
2443 { lat: 239, common_pid: 2040 } hitcount: 1
2448 { lat: 240, common_pid: 2039 } hitcount: 1
2450 { lat: 240, common_pid: 2038 } hitcount: 1
2518 { lat: 249, common_pid: 2038 } hitcount: 1
2525 { lat: 250, common_pid: 2038 } hitcount: 1
2530 { lat: 250, common_pid: 2041 } hitcount: 1
2534 { lat: 251, common_pid: 2039 } hitcount: 1
2537 { lat: 251, common_pid: 2041 } hitcount: 1
2540 { lat: 252, common_pid: 2040 } hitcount: 1
2548 { lat: 253, common_pid: 2040 } hitcount: 1
2551 { lat: 254, common_pid: 2041 } hitcount: 1
2552 { lat: 254, common_pid: 2042 } hitcount: 1
2553 { lat: 254, common_pid: 2039 } hitcount: 1
2555 { lat: 255, common_pid: 2043 } hitcount: 1
2559 { lat: 256, common_pid: 2043 } hitcount: 1
2579 { lat: 265, common_pid: 2039 } hitcount: 1
2580 { lat: 266, common_pid: 2036 } hitcount: 1
2582 { lat: 267, common_pid: 2036 } hitcount: 1
2584 { lat: 268, common_pid: 2036 } hitcount: 1
2586 { lat: 269, common_pid: 2036 } hitcount: 1
2587 { lat: 269, common_pid: 2043 } hitcount: 1
2589 { lat: 270, common_pid: 2040 } hitcount: 1
2591 { lat: 271, common_pid: 2041 } hitcount: 1
2596 { lat: 275, common_pid: 2039 } hitcount: 1
2598 { lat: 276, common_pid: 2037 } hitcount: 1
2599 { lat: 276, common_pid: 2038 } hitcount: 1
2600 { lat: 277, common_pid: 2039 } hitcount: 1
2601 { lat: 277, common_pid: 2042 } hitcount: 1
2602 { lat: 278, common_pid: 2039 } hitcount: 1
2604 { lat: 279, common_pid: 2043 } hitcount: 1
2607 { lat: 284, common_pid: 2039 } hitcount: 1
2608 { lat: 284, common_pid: 2043 } hitcount: 1
2609 { lat: 288, common_pid: 2039 } hitcount: 1
2610 { lat: 289, common_pid: 2039 } hitcount: 1
2611 { lat: 300, common_pid: 2039 } hitcount: 1
2612 { lat: 384, common_pid: 2039 } hitcount: 1
2627 interesting, we can mix the histogram between events that happened in the
2633 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($…
2643 # event histogram
2652 { lat: 7, common_pid: 2306 } hitcount: 1
2690 { lat: 12, common_pid: 2303 } hitcount: 1
2693 { lat: 13, common_pid: 2301 } hitcount: 1
2696 { lat: 13, common_pid: 2305 } hitcount: 1
2697 { lat: 13, common_pid: 2303 } hitcount: 1
2705 { lat: 14, common_pid: 2299 } hitcount: 1
2707 { lat: 15, common_pid: 2305 } hitcount: 1
2711 { lat: 15, common_pid: 2301 } hitcount: 1
2713 { lat: 15, common_pid: 2303 } hitcount: 1
2719 { lat: 17, common_pid: 2303 } hitcount: 1
2720 { lat: 18, common_pid: 2304 } hitcount: 1
2722 { lat: 18, common_pid: 2299 } hitcount: 1
2723 { lat: 18, common_pid: 2301 } hitcount: 1
2728 { lat: 19, common_pid: 2306 } hitcount: 1
2733 { lat: 20, common_pid: 2305 } hitcount: 1
2737 { lat: 21, common_pid: 2305 } hitcount: 1
2741 { lat: 21, common_pid: 2300 } hitcount: 1
2745 { lat: 22, common_pid: 2303 } hitcount: 1
2748 { lat: 22, common_pid: 2300 } hitcount: 1
2749 { lat: 22, common_pid: 2299 } hitcount: 1
2750 { lat: 22, common_pid: 2305 } hitcount: 1
2751 { lat: 22, common_pid: 2304 } hitcount: 1
2752 { lat: 23, common_pid: 2299 } hitcount: 1
2756 { lat: 24, common_pid: 2300 } hitcount: 1
2758 { lat: 24, common_pid: 2305 } hitcount: 1
2759 { lat: 24, common_pid: 2299 } hitcount: 1
2760 { lat: 25, common_pid: 2300 } hitcount: 1
2763 { lat: 27, common_pid: 2305 } hitcount: 1
2764 { lat: 27, common_pid: 2300 } hitcount: 1
2766 { lat: 28, common_pid: 2306 } hitcount: 1
2768 { lat: 29, common_pid: 2302 } hitcount: 1
2770 { lat: 29, common_pid: 2306 } hitcount: 1
2771 { lat: 29, common_pid: 2304 } hitcount: 1
2774 { lat: 32, common_pid: 2302 } hitcount: 1
2775 { lat: 33, common_pid: 2299 } hitcount: 1
2778 { lat: 35, common_pid: 2302 } hitcount: 1
2779 { lat: 35, common_pid: 2304 } hitcount: 1
2784 { lat: 39, common_pid: 2304 } hitcount: 1
2787 { lat: 41, common_pid: 2304 } hitcount: 1
2790 { lat: 42, common_pid: 2304 } hitcount: 1
2797 { lat: 48, common_pid: 2301 } hitcount: 1
2800 { lat: 50, common_pid: 2302 } hitcount: 1
2801 { lat: 50, common_pid: 2301 } hitcount: 1
2803 { lat: 51, common_pid: 2301 } hitcount: 1
2804 { lat: 61, common_pid: 2302 } hitcount: 1
2805 { lat: 110, common_pid: 2302 } hitcount: 1
2813 woken up, but it does show us a nice histogram of how long it took from