.. | .. |
---|
25 | 25 | |
---|
26 | 26 | hist:keys=<field1[,field2,...]>[:values=<field1[,field2,...]>] |
---|
27 | 27 | [:sort=<field1[,field2,...]>][:size=#entries][:pause][:continue] |
---|
28 | | - [:clear][:name=histname1] [if <filter>] |
---|
| 28 | + [:clear][:name=histname1][:<handler>.<action>] [if <filter>] |
---|
29 | 29 | |
---|
30 | 30 | When a matching event is hit, an entry is added to a hash table |
---|
31 | 31 | using the key(s) and value(s) named. Keys and values correspond to |
---|
.. | .. |
---|
39 | 39 | will use the event's kernel stacktrace as the key. The keywords |
---|
40 | 40 | 'keys' or 'key' can be used to specify keys, and the keywords |
---|
41 | 41 | 'values', 'vals', or 'val' can be used to specify values. Compound |
---|
42 | | - keys consisting of up to two fields can be specified by the 'keys' |
---|
| 42 | + keys consisting of up to three fields can be specified by the 'keys' |
---|
43 | 43 | keyword. Hashing a compound key produces a unique entry in the |
---|
44 | 44 | table for each unique combination of component keys, and can be |
---|
45 | 45 | useful for providing more fine-grained summaries of event data. |
---|
.. | .. |
---|
199 | 199 | |
---|
200 | 200 | For some error conditions encountered when invoking a hist trigger |
---|
201 | 201 | command, extended error information is available via the |
---|
202 | | - corresponding event's 'hist' file. Reading the hist file after an |
---|
203 | | - error will display more detailed information about what went wrong, |
---|
204 | | - if information is available. This extended error information will |
---|
205 | | - be available until the next hist trigger command for that event. |
---|
206 | | - |
---|
207 | | - If available for a given error condition, the extended error |
---|
208 | | - information and usage takes the following form:: |
---|
209 | | - |
---|
210 | | - # echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger |
---|
211 | | - echo: write error: Invalid argument |
---|
212 | | - |
---|
213 | | - # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/hist |
---|
214 | | - ERROR: Couldn't yyy: zzz |
---|
215 | | - Last command: xxx |
---|
| 202 | + tracing/error_log file. See Error Conditions in |
---|
| 203 | + :file:`Documentation/trace/ftrace.rst` for details. |
---|
216 | 204 | |
---|
217 | 205 | 6.2 'hist' trigger examples |
---|
218 | 206 | --------------------------- |
---|
.. | .. |
---|
1022 | 1010 | |
---|
1023 | 1011 | For example, suppose we wanted to take a look at the relative |
---|
1024 | 1012 | weights in terms of skb length for each callpath that leads to a |
---|
1025 | | - netif_receieve_skb event when downloading a decent-sized file using |
---|
| 1013 | + netif_receive_skb event when downloading a decent-sized file using |
---|
1026 | 1014 | wget. |
---|
1027 | 1015 | |
---|
1028 | 1016 | First we set up an initially paused stacktrace trigger on the |
---|
.. | .. |
---|
1507 | 1495 | # |
---|
1508 | 1496 | |
---|
1509 | 1497 | { stacktrace: |
---|
1510 | | - _do_fork+0x18e/0x330 |
---|
| 1498 | + kernel_clone+0x18e/0x330 |
---|
1511 | 1499 | kernel_thread+0x29/0x30 |
---|
1512 | 1500 | kthreadd+0x154/0x1b0 |
---|
1513 | 1501 | ret_from_fork+0x3f/0x70 |
---|
.. | .. |
---|
1600 | 1588 | SYSC_sendto+0xef/0x170 |
---|
1601 | 1589 | } hitcount: 88 |
---|
1602 | 1590 | { stacktrace: |
---|
1603 | | - _do_fork+0x18e/0x330 |
---|
| 1591 | + kernel_clone+0x18e/0x330 |
---|
1604 | 1592 | SyS_clone+0x19/0x20 |
---|
1605 | 1593 | entry_SYSCALL_64_fastpath+0x12/0x6a |
---|
1606 | 1594 | } hitcount: 244 |
---|
.. | .. |
---|
1765 | 1753 | # echo 'hist:keys=pid,prio:ts0=common_timestamp ...' >> event1/trigger |
---|
1766 | 1754 | # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp-$ts0 ...' >> event2/trigger |
---|
1767 | 1755 | |
---|
1768 | | -In the first line above, the event's timetamp is saved into the |
---|
| 1756 | +In the first line above, the event's timestamp is saved into the |
---|
1769 | 1757 | variable ts0. In the next line, ts0 is subtracted from the second |
---|
1770 | 1758 | event's timestamp to produce the latency, which is then assigned into |
---|
1771 | 1759 | yet another variable, 'wakeup_lat'. The hist trigger below in turn |
---|
.. | .. |
---|
1787 | 1775 | consisting of the name of the new event along with one or more |
---|
1788 | 1776 | variables and their types, which can be any valid field type, |
---|
1789 | 1777 | separated by semicolons, to the tracing/synthetic_events file. |
---|
| 1778 | + |
---|
| 1779 | +See synth_field_size() for available types. |
---|
| 1780 | + |
---|
| 1781 | +If field_name contains [n], the field is considered to be a static array. |
---|
| 1782 | + |
---|
| 1783 | +If field_names contains[] (no subscript), the field is considered to |
---|
| 1784 | +be a dynamic array, which will only take as much space in the event as |
---|
| 1785 | +is required to hold the array. |
---|
| 1786 | + |
---|
| 1787 | +A string field can be specified using either the static notation: |
---|
| 1788 | + |
---|
| 1789 | + char name[32]; |
---|
| 1790 | + |
---|
| 1791 | +Or the dynamic: |
---|
| 1792 | + |
---|
| 1793 | + char name[]; |
---|
| 1794 | + |
---|
| 1795 | +The size limit for either is 256. |
---|
1790 | 1796 | |
---|
1791 | 1797 | For instance, the following creates a new event named 'wakeup_latency' |
---|
1792 | 1798 | with 3 fields: lat, pid, and prio. Each of those fields is simply a |
---|
.. | .. |
---|
1811 | 1817 | /sys/kernel/debug/tracing/synthetic_events |
---|
1812 | 1818 | |
---|
1813 | 1819 | At this point, there isn't yet an actual 'wakeup_latency' event |
---|
1814 | | -instantiated in the event subsytem - for this to happen, a 'hist |
---|
| 1820 | +instantiated in the event subsystem - for this to happen, a 'hist |
---|
1815 | 1821 | trigger action' needs to be instantiated and bound to actual fields |
---|
1816 | 1822 | and variables defined on other events (see Section 2.2.3 below on |
---|
1817 | 1823 | how that is done using hist trigger 'onmatch' action). Once that is |
---|
.. | .. |
---|
1831 | 1837 | Like any other event, once a histogram is enabled for the event, the |
---|
1832 | 1838 | output can be displayed by reading the event's 'hist' file. |
---|
1833 | 1839 | |
---|
1834 | | -2.2.3 Hist trigger 'actions' |
---|
1835 | | ----------------------------- |
---|
| 1840 | +2.2.3 Hist trigger 'handlers' and 'actions' |
---|
| 1841 | +------------------------------------------- |
---|
1836 | 1842 | |
---|
1837 | | -A hist trigger 'action' is a function that's executed whenever a |
---|
1838 | | -histogram entry is added or updated. |
---|
| 1843 | +A hist trigger 'action' is a function that's executed (in most cases |
---|
| 1844 | +conditionally) whenever a histogram entry is added or updated. |
---|
1839 | 1845 | |
---|
1840 | | -The default 'action' if no special function is explicity specified is |
---|
1841 | | -as it always has been, to simply update the set of values associated |
---|
1842 | | -with an entry. Some applications, however, may want to perform |
---|
1843 | | -additional actions at that point, such as generate another event, or |
---|
1844 | | -compare and save a maximum. |
---|
| 1846 | +When a histogram entry is added or updated, a hist trigger 'handler' |
---|
| 1847 | +is what decides whether the corresponding action is actually invoked |
---|
| 1848 | +or not. |
---|
1845 | 1849 | |
---|
1846 | | -The following additional actions are available. To specify an action |
---|
1847 | | -for a given event, simply specify the action between colons in the |
---|
1848 | | -hist trigger specification. |
---|
| 1850 | +Hist trigger handlers and actions are paired together in the general |
---|
| 1851 | +form: |
---|
1849 | 1852 | |
---|
1850 | | - - onmatch(matching.event).<synthetic_event_name>(param list) |
---|
| 1853 | + <handler>.<action> |
---|
1851 | 1854 | |
---|
1852 | | - The 'onmatch(matching.event).<synthetic_event_name>(params)' hist |
---|
1853 | | - trigger action is invoked whenever an event matches and the |
---|
1854 | | - histogram entry would be added or updated. It causes the named |
---|
1855 | | - synthetic event to be generated with the values given in the |
---|
| 1855 | +To specify a handler.action pair for a given event, simply specify |
---|
| 1856 | +that handler.action pair between colons in the hist trigger |
---|
| 1857 | +specification. |
---|
| 1858 | + |
---|
| 1859 | +In theory, any handler can be combined with any action, but in |
---|
| 1860 | +practice, not every handler.action combination is currently supported; |
---|
| 1861 | +if a given handler.action combination isn't supported, the hist |
---|
| 1862 | +trigger will fail with -EINVAL; |
---|
| 1863 | + |
---|
| 1864 | +The default 'handler.action' if none is explicitly specified is as it |
---|
| 1865 | +always has been, to simply update the set of values associated with an |
---|
| 1866 | +entry. Some applications, however, may want to perform additional |
---|
| 1867 | +actions at that point, such as generate another event, or compare and |
---|
| 1868 | +save a maximum. |
---|
| 1869 | + |
---|
| 1870 | +The supported handlers and actions are listed below, and each is |
---|
| 1871 | +described in more detail in the following paragraphs, in the context |
---|
| 1872 | +of descriptions of some common and useful handler.action combinations. |
---|
| 1873 | + |
---|
| 1874 | +The available handlers are: |
---|
| 1875 | + |
---|
| 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 |
---|
| 1879 | + |
---|
| 1880 | +The available actions are: |
---|
| 1881 | + |
---|
| 1882 | + - trace(<synthetic_event_name>,param list) - generate synthetic event |
---|
| 1883 | + - save(field,...) - save current event fields |
---|
| 1884 | + - snapshot() - snapshot the trace buffer |
---|
| 1885 | + |
---|
| 1886 | +The following commonly-used handler.action pairs are available: |
---|
| 1887 | + |
---|
| 1888 | + - onmatch(matching.event).trace(<synthetic_event_name>,param list) |
---|
| 1889 | + |
---|
| 1890 | + The 'onmatch(matching.event).trace(<synthetic_event_name>,param |
---|
| 1891 | + list)' hist trigger action is invoked whenever an event matches |
---|
| 1892 | + and the histogram entry would be added or updated. It causes the |
---|
| 1893 | + named synthetic event to be generated with the values given in the |
---|
1856 | 1894 | 'param list'. The result is the generation of a synthetic event |
---|
1857 | 1895 | that consists of the values contained in those variables at the |
---|
1858 | | - time the invoking event was hit. |
---|
| 1896 | + time the invoking event was hit. For example, if the synthetic |
---|
| 1897 | + event name is 'wakeup_latency', a wakeup_latency event is |
---|
| 1898 | + generated using onmatch(event).trace(wakeup_latency,arg1,arg2). |
---|
1859 | 1899 | |
---|
1860 | | - The 'param list' consists of one or more parameters which may be |
---|
1861 | | - either variables or fields defined on either the 'matching.event' |
---|
1862 | | - or the target event. The variables or fields specified in the |
---|
1863 | | - param list may be either fully-qualified or unqualified. If a |
---|
1864 | | - variable is specified as unqualified, it must be unique between |
---|
1865 | | - the two events. A field name used as a param can be unqualified |
---|
1866 | | - if it refers to the target event, but must be fully qualified if |
---|
1867 | | - it refers to the matching event. A fully-qualified name is of the |
---|
1868 | | - form 'system.event_name.$var_name' or 'system.event_name.field'. |
---|
| 1900 | + There is also an equivalent alternative form available for |
---|
| 1901 | + generating synthetic events. In this form, the synthetic event |
---|
| 1902 | + name is used as if it were a function name. For example, using |
---|
| 1903 | + the 'wakeup_latency' synthetic event name again, the |
---|
| 1904 | + wakeup_latency event would be generated by invoking it as if it |
---|
| 1905 | + were a function call, with the event field values passed in as |
---|
| 1906 | + arguments: onmatch(event).wakeup_latency(arg1,arg2). The syntax |
---|
| 1907 | + for this form is: |
---|
| 1908 | + |
---|
| 1909 | + onmatch(matching.event).<synthetic_event_name>(param list) |
---|
| 1910 | + |
---|
| 1911 | + In either case, the 'param list' consists of one or more |
---|
| 1912 | + parameters which may be either variables or fields defined on |
---|
| 1913 | + either the 'matching.event' or the target event. The variables or |
---|
| 1914 | + fields specified in the param list may be either fully-qualified |
---|
| 1915 | + or unqualified. If a variable is specified as unqualified, it |
---|
| 1916 | + must be unique between the two events. A field name used as a |
---|
| 1917 | + param can be unqualified if it refers to the target event, but |
---|
| 1918 | + must be fully qualified if it refers to the matching event. A |
---|
| 1919 | + fully-qualified name is of the form 'system.event_name.$var_name' |
---|
| 1920 | + or 'system.event_name.field'. |
---|
1869 | 1921 | |
---|
1870 | 1922 | The 'matching.event' specification is simply the fully qualified |
---|
1871 | 1923 | event name of the event that matches the target event for the |
---|
1872 | | - onmatch() functionality, in the form 'system.event_name'. |
---|
| 1924 | + onmatch() functionality, in the form 'system.event_name'. Histogram |
---|
| 1925 | + keys of both events are compared to find if events match. In case |
---|
| 1926 | + multiple histogram keys are used, they all must match in the specified |
---|
| 1927 | + order. |
---|
1873 | 1928 | |
---|
1874 | 1929 | Finally, the number and type of variables/fields in the 'param |
---|
1875 | 1930 | list' must match the number and types of the fields in the |
---|
.. | .. |
---|
1895 | 1950 | # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\ |
---|
1896 | 1951 | wakeup_new_test($testpid) if comm=="cyclictest"' >> \ |
---|
1897 | 1952 | /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger |
---|
| 1953 | + |
---|
| 1954 | + Or, equivalently, using the 'trace' keyword syntax: |
---|
| 1955 | + |
---|
| 1956 | + # echo 'hist:keys=$testpid:testpid=pid:onmatch(sched.sched_wakeup_new).\ |
---|
| 1957 | + trace(wakeup_new_test,$testpid) if comm=="cyclictest"' >> \ |
---|
| 1958 | + /sys/kernel/debug/tracing/events/sched/sched_wakeup_new/trigger |
---|
1898 | 1959 | |
---|
1899 | 1960 | Creating and displaying a histogram based on those events is now |
---|
1900 | 1961 | just a matter of using the fields and new synthetic event in the |
---|
.. | .. |
---|
1926 | 1987 | /sys/kernel/debug/tracing/events/sched/sched_waking/trigger |
---|
1927 | 1988 | |
---|
1928 | 1989 | Then, when the corresponding thread is actually scheduled onto the |
---|
1929 | | - CPU by a sched_switch event, calculate the latency and use that |
---|
1930 | | - along with another variable and an event field to generate a |
---|
1931 | | - wakeup_latency synthetic event:: |
---|
| 1990 | + CPU by a sched_switch event (saved_pid matches next_pid), calculate |
---|
| 1991 | + the latency and use that along with another variable and an event field |
---|
| 1992 | + to generate a wakeup_latency synthetic event:: |
---|
1932 | 1993 | |
---|
1933 | 1994 | # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0:\ |
---|
1934 | 1995 | onmatch(sched.sched_waking).wakeup_latency($wakeup_lat,\ |
---|
.. | .. |
---|
2000 | 2061 | Entries: 2 |
---|
2001 | 2062 | Dropped: 0 |
---|
2002 | 2063 | |
---|
| 2064 | + - onmax(var).snapshot() |
---|
| 2065 | + |
---|
| 2066 | + The 'onmax(var).snapshot()' hist trigger action is invoked |
---|
| 2067 | + whenever the value of 'var' associated with a histogram entry |
---|
| 2068 | + exceeds the current maximum contained in that variable. |
---|
| 2069 | + |
---|
| 2070 | + The end result is that a global snapshot of the trace buffer will |
---|
| 2071 | + be saved in the tracing/snapshot file if 'var' exceeds the current |
---|
| 2072 | + maximum for any hist trigger entry. |
---|
| 2073 | + |
---|
| 2074 | + Note that in this case the maximum is a global maximum for the |
---|
| 2075 | + current trace instance, which is the maximum across all buckets of |
---|
| 2076 | + the histogram. The key of the specific trace event that caused |
---|
| 2077 | + the global maximum and the global maximum itself are displayed, |
---|
| 2078 | + along with a message stating that a snapshot has been taken and |
---|
| 2079 | + where to find it. The user can use the key information displayed |
---|
| 2080 | + to locate the corresponding bucket in the histogram for even more |
---|
| 2081 | + detail. |
---|
| 2082 | + |
---|
| 2083 | + As an example the below defines a couple of hist triggers, one for |
---|
| 2084 | + sched_waking and another for sched_switch, keyed on pid. Whenever |
---|
| 2085 | + a sched_waking event occurs, the timestamp is saved in the entry |
---|
| 2086 | + corresponding to the current pid, and when the scheduler switches |
---|
| 2087 | + back to that pid, the timestamp difference is calculated. If the |
---|
| 2088 | + resulting latency, stored in wakeup_lat, exceeds the current |
---|
| 2089 | + maximum latency, a snapshot is taken. As part of the setup, all |
---|
| 2090 | + the scheduler events are also enabled, which are the events that |
---|
| 2091 | + will show up in the snapshot when it is taken at some point: |
---|
| 2092 | + |
---|
| 2093 | + # echo 1 > /sys/kernel/debug/tracing/events/sched/enable |
---|
| 2094 | + |
---|
| 2095 | + # echo 'hist:keys=pid:ts0=common_timestamp.usecs \ |
---|
| 2096 | + if comm=="cyclictest"' >> \ |
---|
| 2097 | + /sys/kernel/debug/tracing/events/sched/sched_waking/trigger |
---|
| 2098 | + |
---|
| 2099 | + # echo 'hist:keys=next_pid:wakeup_lat=common_timestamp.usecs-$ts0: \ |
---|
| 2100 | + onmax($wakeup_lat).save(next_prio,next_comm,prev_pid,prev_prio, \ |
---|
| 2101 | + prev_comm):onmax($wakeup_lat).snapshot() \ |
---|
| 2102 | + if next_comm=="cyclictest"' >> \ |
---|
| 2103 | + /sys/kernel/debug/tracing/events/sched/sched_switch/trigger |
---|
| 2104 | + |
---|
| 2105 | + When the histogram is displayed, for each bucket the max value |
---|
| 2106 | + and the saved values corresponding to the max are displayed |
---|
| 2107 | + following the rest of the fields. |
---|
| 2108 | + |
---|
| 2109 | + If a snapshot was taken, there is also a message indicating that, |
---|
| 2110 | + along with the value and event that triggered the global maximum: |
---|
| 2111 | + |
---|
| 2112 | + # cat /sys/kernel/debug/tracing/events/sched/sched_switch/hist |
---|
| 2113 | + { next_pid: 2101 } hitcount: 200 |
---|
| 2114 | + max: 52 next_prio: 120 next_comm: cyclictest \ |
---|
| 2115 | + prev_pid: 0 prev_prio: 120 prev_comm: swapper/6 |
---|
| 2116 | + |
---|
| 2117 | + { next_pid: 2103 } hitcount: 1326 |
---|
| 2118 | + max: 572 next_prio: 19 next_comm: cyclictest \ |
---|
| 2119 | + prev_pid: 0 prev_prio: 120 prev_comm: swapper/1 |
---|
| 2120 | + |
---|
| 2121 | + { next_pid: 2102 } hitcount: 1982 \ |
---|
| 2122 | + max: 74 next_prio: 19 next_comm: cyclictest \ |
---|
| 2123 | + prev_pid: 0 prev_prio: 120 prev_comm: swapper/5 |
---|
| 2124 | + |
---|
| 2125 | + Snapshot taken (see tracing/snapshot). Details: |
---|
| 2126 | + triggering value { onmax($wakeup_lat) }: 572 \ |
---|
| 2127 | + triggered by event with key: { next_pid: 2103 } |
---|
| 2128 | + |
---|
| 2129 | + Totals: |
---|
| 2130 | + Hits: 3508 |
---|
| 2131 | + Entries: 3 |
---|
| 2132 | + Dropped: 0 |
---|
| 2133 | + |
---|
| 2134 | + In the above case, the event that triggered the global maximum has |
---|
| 2135 | + the key with next_pid == 2103. If you look at the bucket that has |
---|
| 2136 | + 2103 as the key, you'll find the additional values save()'d along |
---|
| 2137 | + with the local maximum for that bucket, which should be the same |
---|
| 2138 | + as the global maximum (since that was the same value that |
---|
| 2139 | + triggered the global snapshot). |
---|
| 2140 | + |
---|
| 2141 | + And finally, looking at the snapshot data should show at or near |
---|
| 2142 | + the end the event that triggered the snapshot (in this case you |
---|
| 2143 | + can verify the timestamps between the sched_waking and |
---|
| 2144 | + sched_switch events, which should match the time displayed in the |
---|
| 2145 | + global maximum):: |
---|
| 2146 | + |
---|
| 2147 | + # cat /sys/kernel/debug/tracing/snapshot |
---|
| 2148 | + |
---|
| 2149 | + <...>-2103 [005] d..3 309.873125: sched_switch: prev_comm=cyclictest prev_pid=2103 prev_prio=19 prev_state=D ==> next_comm=swapper/5 next_pid=0 next_prio=120 |
---|
| 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 prev_state=S ==> next_comm=cyclictest next_pid=2102 next_prio=19 |
---|
| 2153 | + <...>-2102 [005] d..3 309.873625: sched_switch: prev_comm=cyclictest prev_pid=2102 prev_prio=19 prev_state=D ==> next_comm=swapper/5 next_pid=0 next_prio=120 |
---|
| 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 prev_state=S ==> next_comm=cyclictest next_pid=2102 next_prio=19 |
---|
| 2159 | + <idle>-0 [004] d.h3 309.874757: sched_waking: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004 |
---|
| 2160 | + <idle>-0 [004] dNh4 309.874762: sched_wakeup: comm=gnome-terminal- pid=1699 prio=120 target_cpu=004 |
---|
| 2161 | + <idle>-0 [004] d..3 309.874766: sched_switch: prev_comm=swapper/4 prev_pid=0 prev_prio=120 prev_state=S ==> next_comm=gnome-terminal- next_pid=1699 next_prio=120 |
---|
| 2162 | + gnome-terminal--1699 [004] d.h2 309.874941: sched_stat_runtime: comm=gnome-terminal- pid=1699 runtime=180706 [ns] vruntime=1126870572 [ns] |
---|
| 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 prev_state=S ==> next_comm=rcu_sched next_pid=9 next_prio=120 |
---|
| 2167 | + rcu_sched-9 [007] d..3 309.874973: sched_stat_runtime: comm=rcu_sched pid=9 runtime=13646 [ns] vruntime=22531430286 [ns] |
---|
| 2168 | + rcu_sched-9 [007] d..3 309.874978: sched_switch: prev_comm=rcu_sched prev_pid=9 prev_prio=120 prev_state=R+ ==> next_comm=swapper/7 next_pid=0 next_prio=120 |
---|
| 2169 | + <...>-2102 [005] d..4 309.874994: sched_migrate_task: comm=cyclictest pid=2103 prio=19 orig_cpu=5 dest_cpu=1 |
---|
| 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 prev_state=S ==> next_comm=cyclictest next_pid=2103 next_prio=19 |
---|
| 2172 | + |
---|
| 2173 | + - onchange(var).save(field,.. .) |
---|
| 2174 | + |
---|
| 2175 | + The 'onchange(var).save(field,...)' hist trigger action is invoked |
---|
| 2176 | + whenever the value of 'var' associated with a histogram entry |
---|
| 2177 | + changes. |
---|
| 2178 | + |
---|
| 2179 | + The end result is that the trace event fields specified as the |
---|
| 2180 | + onchange.save() params will be saved if 'var' changes for that |
---|
| 2181 | + hist trigger entry. This allows context from the event that |
---|
| 2182 | + changed the value to be saved for later reference. When the |
---|
| 2183 | + histogram is displayed, additional fields displaying the saved |
---|
| 2184 | + values will be printed. |
---|
| 2185 | + |
---|
| 2186 | + - onchange(var).snapshot() |
---|
| 2187 | + |
---|
| 2188 | + The 'onchange(var).snapshot()' hist trigger action is invoked |
---|
| 2189 | + whenever the value of 'var' associated with a histogram entry |
---|
| 2190 | + changes. |
---|
| 2191 | + |
---|
| 2192 | + The end result is that a global snapshot of the trace buffer will |
---|
| 2193 | + be saved in the tracing/snapshot file if 'var' changes for any |
---|
| 2194 | + hist trigger entry. |
---|
| 2195 | + |
---|
| 2196 | + Note that in this case the changed value is a global variable |
---|
| 2197 | + associated with current trace instance. The key of the specific |
---|
| 2198 | + trace event that caused the value to change and the global value |
---|
| 2199 | + itself are displayed, along with a message stating that a snapshot |
---|
| 2200 | + has been taken and where to find it. The user can use the key |
---|
| 2201 | + information displayed to locate the corresponding bucket in the |
---|
| 2202 | + histogram for even more detail. |
---|
| 2203 | + |
---|
| 2204 | + As an example the below defines a hist trigger on the tcp_probe |
---|
| 2205 | + event, keyed on dport. Whenever a tcp_probe event occurs, the |
---|
| 2206 | + cwnd field is checked against the current value stored in the |
---|
| 2207 | + $cwnd variable. If the value has changed, a snapshot is taken. |
---|
| 2208 | + As part of the setup, all the scheduler and tcp events are also |
---|
| 2209 | + enabled, which are the events that will show up in the snapshot |
---|
| 2210 | + when it is taken at some point: |
---|
| 2211 | + |
---|
| 2212 | + # echo 1 > /sys/kernel/debug/tracing/events/sched/enable |
---|
| 2213 | + # echo 1 > /sys/kernel/debug/tracing/events/tcp/enable |
---|
| 2214 | + |
---|
| 2215 | + # echo 'hist:keys=dport:cwnd=snd_cwnd: \ |
---|
| 2216 | + onchange($cwnd).save(snd_wnd,srtt,rcv_wnd): \ |
---|
| 2217 | + onchange($cwnd).snapshot()' >> \ |
---|
| 2218 | + /sys/kernel/debug/tracing/events/tcp/tcp_probe/trigger |
---|
| 2219 | + |
---|
| 2220 | + When the histogram is displayed, for each bucket the tracked value |
---|
| 2221 | + and the saved values corresponding to that value are displayed |
---|
| 2222 | + following the rest of the fields. |
---|
| 2223 | + |
---|
| 2224 | + If a snapshot was taken, there is also a message indicating that, |
---|
| 2225 | + along with the value and event that triggered the snapshot:: |
---|
| 2226 | + |
---|
| 2227 | + # cat /sys/kernel/debug/tracing/events/tcp/tcp_probe/hist |
---|
| 2228 | + |
---|
| 2229 | + { dport: 1521 } hitcount: 8 |
---|
| 2230 | + changed: 10 snd_wnd: 35456 srtt: 154262 rcv_wnd: 42112 |
---|
| 2231 | + |
---|
| 2232 | + { dport: 80 } hitcount: 23 |
---|
| 2233 | + changed: 10 snd_wnd: 28960 srtt: 19604 rcv_wnd: 29312 |
---|
| 2234 | + |
---|
| 2235 | + { dport: 9001 } hitcount: 172 |
---|
| 2236 | + changed: 10 snd_wnd: 48384 srtt: 260444 rcv_wnd: 55168 |
---|
| 2237 | + |
---|
| 2238 | + { dport: 443 } hitcount: 211 |
---|
| 2239 | + changed: 10 snd_wnd: 26960 srtt: 17379 rcv_wnd: 28800 |
---|
| 2240 | + |
---|
| 2241 | + Snapshot taken (see tracing/snapshot). Details:: |
---|
| 2242 | + |
---|
| 2243 | + triggering value { onchange($cwnd) }: 10 |
---|
| 2244 | + triggered by event with key: { dport: 80 } |
---|
| 2245 | + |
---|
| 2246 | + Totals: |
---|
| 2247 | + Hits: 414 |
---|
| 2248 | + Entries: 4 |
---|
| 2249 | + Dropped: 0 |
---|
| 2250 | + |
---|
| 2251 | + In the above case, the event that triggered the snapshot has the |
---|
| 2252 | + key with dport == 80. If you look at the bucket that has 80 as |
---|
| 2253 | + the key, you'll find the additional values save()'d along with the |
---|
| 2254 | + changed value for that bucket, which should be the same as the |
---|
| 2255 | + global changed value (since that was the same value that triggered |
---|
| 2256 | + the global snapshot). |
---|
| 2257 | + |
---|
| 2258 | + And finally, looking at the snapshot data should show at or near |
---|
| 2259 | + the end the event that triggered the snapshot:: |
---|
| 2260 | + |
---|
| 2261 | + # cat /sys/kernel/debug/tracing/snapshot |
---|
| 2262 | + |
---|
| 2263 | + gnome-shell-1261 [006] dN.3 49.823113: sched_stat_runtime: comm=gnome-shell pid=1261 runtime=49347 [ns] vruntime=1835730389 [ns] |
---|
| 2264 | + kworker/u16:4-773 [003] d..3 49.823114: sched_switch: prev_comm=kworker/u16:4 prev_pid=773 prev_prio=120 prev_state=R+ ==> next_comm=kworker/3:2 next_pid=135 next_prio=120 |
---|
| 2265 | + gnome-shell-1261 [006] d..3 49.823114: sched_switch: prev_comm=gnome-shell prev_pid=1261 prev_prio=120 prev_state=R+ ==> next_comm=kworker/6:2 next_pid=387 next_prio=120 |
---|
| 2266 | + kworker/3:2-135 [003] d..3 49.823118: sched_stat_runtime: comm=kworker/3:2 pid=135 runtime=5339 [ns] vruntime=17815800388 [ns] |
---|
| 2267 | + kworker/6:2-387 [006] d..3 49.823120: sched_stat_runtime: comm=kworker/6:2 pid=387 runtime=9594 [ns] vruntime=14589605367 [ns] |
---|
| 2268 | + kworker/6:2-387 [006] d..3 49.823122: sched_switch: prev_comm=kworker/6:2 prev_pid=387 prev_prio=120 prev_state=R+ ==> next_comm=gnome-shell next_pid=1261 next_prio=120 |
---|
| 2269 | + kworker/3:2-135 [003] d..3 49.823123: sched_switch: prev_comm=kworker/3:2 prev_pid=135 prev_prio=120 prev_state=T ==> next_comm=swapper/3 next_pid=0 next_prio=120 |
---|
| 2270 | + <idle>-0 [004] ..s7 49.823798: tcp_probe: src=10.0.0.10:54326 dest=23.215.104.193:80 mark=0x0 length=32 snd_nxt=0xe3ae2ff5 snd_una=0xe3ae2ecd snd_cwnd=10 ssthresh=2147483647 snd_wnd=28960 srtt=19604 rcv_wnd=29312 |
---|
| 2271 | + |
---|
2003 | 2272 | 3. User space creating a trigger |
---|
2004 | 2273 | -------------------------------- |
---|
2005 | 2274 | |
---|