Lines Matching +full:len +full:- +full:or +full:- +full:define
19 aggregates event hits into a hash table keyed on one or more trace
20 event format fields (or stacktrace) and a set of running totals
21 derived from one or more trace event format fields and/or event
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
38 Keys can be any field, or the special string 'common_stacktrace', which
40 'keys' or 'key' can be used to specify keys, and the keywords
41 'values', 'vals', or 'val' can be used to specify values. Compound
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.
105 # echo 'hist:keys=skbaddr.hex:vals=len' > \
110 # echo '!hist:keys=skbaddr.hex:vals=len' > \
118 parameter can be used to specify more or fewer than that. The units
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
131 or to start a hist trigger but not log any events until told to do
132 so. 'continue' or 'cont' can be used to start or restart a paused
143 The 'nohitcount' (or NOHC) parameter will suppress display of
149 - enable_hist/disable_hist
152 event conditionally start and stop another event's already-attached
162 Instead of enabling or disabling the tracing of the target event
164 enable/disable_hist triggers enable or disable the aggregation of
172 # echo 'hist:keys=skbaddr.hex:vals=len:pause' > \
190 ------------------------
193 keys or values in a hist trigger. These look like and behave as if
195 field definition or format file. They are however available for any
208 --------------------------
216 ---------------------------
239 the kernel that made one or more calls to kmalloc::
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
1029 # echo 'hist:key=common_stacktrace:vals=len:pause' > \
1060 $ wget https://www.kernel.org/pub/linux/kernel/v3.x/patch-3.19.xz
1063 # trigger info: hist:keys=common_stacktrace:vals=len:sort=hitcount:size=2048 [paused]
1081 } hitcount: 85 len: 28884
1099 } hitcount: 98 len: 664329
1117 } hitcount: 115 len: 13030
1129 } hitcount: 934 len: 5512212
1145 # echo 'hist:key=common_stacktrace:vals=len:clear' >> \
1152 # trigger info: hist:keys=common_stacktrace:vals=len:sort=hitcount:size=2048 [paused]
1184 In other words, whenever either of the sched_process_exec or
1185 sched_process_exit events is hit and matches 'wget', it enables or
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…
1226 events, or for comparing the effects of different filters, among
1229 # echo 'hist:keys=skbaddr.hex:vals=len if len < 0' >> \
1231 # echo 'hist:keys=skbaddr.hex:vals=len if len > 4096' >> \
1233 # echo 'hist:keys=skbaddr.hex:vals=len if len == 256' >> \
1235 # echo 'hist:keys=skbaddr.hex:vals=len' >> \
1237 # echo 'hist:keys=len:vals=common_preempt_count' >> \
1254 … # trigger info: hist:keys=len:vals=hitcount,common_preempt_count:sort=hitcount:size=2048 [active]
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
1267 { len: 1280 } hitcount: 66 common_preempt_count: 0
1268 { len: 116 } hitcount: 81 common_preempt_count: 40
1269 { len: 708 } hitcount: 112 common_preempt_count: 0
1270 { len: 46 } hitcount: 221 common_preempt_count: 0
1271 { len: 1264 } hitcount: 458 common_preempt_count: 0
1281 # trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
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
1300 { skbaddr: ffff88009fe0be00 } hitcount: 27 len: 24677
1301 { skbaddr: ffff88009fe0a400 } hitcount: 27 len: 23052
1302 { skbaddr: ffff88009fe0b700 } hitcount: 31 len: 25589
1303 { skbaddr: ffff88009fe0b600 } hitcount: 32 len: 27326
1304 { skbaddr: ffff88006a462800 } hitcount: 68 len: 71678
1305 { skbaddr: ffff88006a463700 } hitcount: 70 len: 72678
1306 { skbaddr: ffff88006a462b00 } hitcount: 71 len: 77589
1307 { skbaddr: ffff88006a463600 } hitcount: 73 len: 71307
1308 { skbaddr: ffff88006a462200 } hitcount: 81 len: 81032
1318 …# trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len == 256 [act…
1330 …# trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len > 4096 [act…
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
1343 { skbaddr: ffff8800d2bcdc00 } hitcount: 2 len: 24420
1344 { skbaddr: ffff8800d2bcc200 } hitcount: 2 len: 12996
1354 …# trigger info: hist:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 if len < 0 [active]
1367 For example, these two triggers when hit will update the same 'len'
1370 # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \
1372 # echo 'hist:name=foo:keys=skbaddr.hex:vals=len' > \
1383 … # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
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
1411 { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676
1412 { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107
1413 { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92
1414 { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142
1415 { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220
1416 { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92
1417 { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92
1418 { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675
1419 { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138
1420 { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138
1421 { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184
1422 { skbaddr: ffff880064504400 } hitcount: 4 len: 184
1423 { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184
1424 { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230
1425 { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196
1426 { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276
1427 { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276
1435 … # trigger info: hist:name=foo:keys=skbaddr.hex:vals=hitcount,len:sort=hitcount:size=2048 [active]
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
1463 { skbaddr: ffff8800a1f32c00 } hitcount: 2 len: 676
1464 { skbaddr: ffff88000ad52600 } hitcount: 2 len: 107
1465 { skbaddr: ffff8800a1f91e00 } hitcount: 2 len: 92
1466 { skbaddr: ffff8800af5a0200 } hitcount: 2 len: 142
1467 { skbaddr: ffff8800d2bcc600 } hitcount: 2 len: 220
1468 { skbaddr: ffff8800ba36f500 } hitcount: 2 len: 92
1469 { skbaddr: ffff8800d021f800 } hitcount: 2 len: 92
1470 { skbaddr: ffff8800a1f33600 } hitcount: 2 len: 675
1471 { skbaddr: ffff8800a8bfff00 } hitcount: 3 len: 138
1472 { skbaddr: ffff8800d62a1300 } hitcount: 3 len: 138
1473 { skbaddr: ffff88002e37a100 } hitcount: 4 len: 184
1474 { skbaddr: ffff880064504400 } hitcount: 4 len: 184
1475 { skbaddr: ffff8800a8bfec00 } hitcount: 4 len: 184
1476 { skbaddr: ffff88000ad53700 } hitcount: 5 len: 230
1477 { skbaddr: ffff8800d2bcdb00 } hitcount: 5 len: 196
1478 { skbaddr: ffff8800a1f90000 } hitcount: 6 len: 276
1479 { skbaddr: ffff88006a54f900 } hitcount: 6 len: 276
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.
1633 compound) key along with one or more numeric values, which are
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,
1710 Either keys or values can be saved and retrieved in this way. This
1732 If a variable isn't a key variable or prefixed with 'vals=', the
1745 Note that variable assignments can appear either preceding or
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.
1785 or assigned to a variable and referenced in a subsequent expression::
1793 ----------------------
1795 Synthetic events are user-defined events generated from hist trigger
1796 variables or fields associated with one or more other events. Their
1801 To define a synthetic event, the user writes a simple specification
1802 consisting of the name of the new event along with one or more
1818 Or the dynamic:
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
1947 or even just "long[]". For example, to see how long a task is blocked in an
1953 …# echo 'hist:keys=prev_pid:delta=common_timestamp.usecs-$ts,s=$st:onmax($delta).trace(block_lat,pr…
1959 # entries-in-buffer/entries-written: 2/2 #P:8
1961 # _-----=> irqs-off/BH-disabled
1962 # / _----=> need-resched
1963 # | / _---=> hardirq/softirq
1964 # || / _--=> preempt-depth
1965 # ||| / _-=> migrate-disable
1967 # TASK-PID CPU# ||||| TIMESTAMP FUNCTION
1969 <idle>-0 [005] d..4. 521.164922: block_lat: pid=0 delta=8322 stack=STACK:
1981 <...>-2 [004] d..4. 525.184257: block_lat: pid=2 delta=76 stack=STACK:
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'
2105 or not.
2119 trigger will fail with -EINVAL;
2124 actions at that point, such as generate another event, or compare and
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
2168 In either case, the 'param list' consists of one or more
2169 parameters which may be either variables or fields defined on
2170 either the 'matching.event' or the target event. The variables or
2171 fields specified in the param list may be either fully-qualified
2172 or unqualified. If a variable is specified as unqualified, it
2176 fully-qualified name is of the form 'system.event_name.$var_name'
2177 or 'system.event_name.field'.
2192 when invoking the synthetic event. Here we define the synthetic
2211 Or, equivalently, using the 'trace' keyword syntax::
2234 First, we define a 'wakeup_latency' synthetic event::
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: \
2398 And finally, looking at the snapshot data should show at or near
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()
2515 And finally, looking at the snapshot data should show at or near
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.
2890 …# echo 'hist:keys=common_pid:lat=common_timestamp.usecs-$ts0:onmatch(sched.sched_waking).latency($…