Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 1 | ============= |
| 2 | Event Tracing |
| 3 | ============= |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 4 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 5 | :Author: Theodore Ts'o |
| 6 | :Updated: Li Zefan and Tom Zanussi |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 7 | |
Li Zefan | 143c145 | 2009-05-19 14:43:15 +0800 | [diff] [blame] | 8 | 1. Introduction |
| 9 | =============== |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 10 | |
Mauro Carvalho Chehab | ec15872 | 2018-05-08 18:54:36 -0300 | [diff] [blame] | 11 | Tracepoints (see Documentation/trace/tracepoints.rst) can be used |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 12 | without creating custom kernel modules to register probe functions |
| 13 | using the event tracing infrastructure. |
| 14 | |
| 15 | Not all tracepoints can be traced using the event tracing system; |
| 16 | the kernel developer must provide code snippets which define how the |
| 17 | tracing information is saved into the tracing buffer, and how the |
Li Zefan | 143c145 | 2009-05-19 14:43:15 +0800 | [diff] [blame] | 18 | tracing information should be printed. |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 19 | |
Li Zefan | 143c145 | 2009-05-19 14:43:15 +0800 | [diff] [blame] | 20 | 2. Using Event Tracing |
| 21 | ====================== |
| 22 | |
| 23 | 2.1 Via the 'set_event' interface |
| 24 | --------------------------------- |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 25 | |
| 26 | The events which are available for tracing can be found in the file |
GeunSik Lim | 52ad51e | 2009-09-07 21:37:17 +0900 | [diff] [blame] | 27 | /sys/kernel/debug/tracing/available_events. |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 28 | |
| 29 | To enable a particular event, such as 'sched_wakeup', simply echo it |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 30 | to /sys/kernel/debug/tracing/set_event. For example:: |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 31 | |
GeunSik Lim | 52ad51e | 2009-09-07 21:37:17 +0900 | [diff] [blame] | 32 | # echo sched_wakeup >> /sys/kernel/debug/tracing/set_event |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 33 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 34 | .. Note:: '>>' is necessary, otherwise it will firstly disable all the events. |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 35 | |
| 36 | To disable an event, echo the event name to the set_event file prefixed |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 37 | with an exclamation point:: |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 38 | |
GeunSik Lim | 52ad51e | 2009-09-07 21:37:17 +0900 | [diff] [blame] | 39 | # echo '!sched_wakeup' >> /sys/kernel/debug/tracing/set_event |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 40 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 41 | To disable all events, echo an empty line to the set_event file:: |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 42 | |
GeunSik Lim | 52ad51e | 2009-09-07 21:37:17 +0900 | [diff] [blame] | 43 | # echo > /sys/kernel/debug/tracing/set_event |
Li Zefan | 143c145 | 2009-05-19 14:43:15 +0800 | [diff] [blame] | 44 | |
Jonathan Corbet | 6234c7b | 2018-03-07 10:44:08 -0700 | [diff] [blame] | 45 | To enable all events, echo ``*:*`` or ``*:`` to the set_event file:: |
Li Zefan | 143c145 | 2009-05-19 14:43:15 +0800 | [diff] [blame] | 46 | |
GeunSik Lim | 52ad51e | 2009-09-07 21:37:17 +0900 | [diff] [blame] | 47 | # echo *:* > /sys/kernel/debug/tracing/set_event |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 48 | |
| 49 | The events are organized into subsystems, such as ext4, irq, sched, |
| 50 | etc., and a full event name looks like this: <subsystem>:<event>. The |
| 51 | subsystem name is optional, but it is displayed in the available_events |
| 52 | file. All of the events in a subsystem can be specified via the syntax |
Jonathan Corbet | 6234c7b | 2018-03-07 10:44:08 -0700 | [diff] [blame] | 53 | ``<subsystem>:*``; for example, to enable all irq events, you can use the |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 54 | command:: |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 55 | |
GeunSik Lim | 52ad51e | 2009-09-07 21:37:17 +0900 | [diff] [blame] | 56 | # echo 'irq:*' > /sys/kernel/debug/tracing/set_event |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 57 | |
Li Zefan | 143c145 | 2009-05-19 14:43:15 +0800 | [diff] [blame] | 58 | 2.2 Via the 'enable' toggle |
| 59 | --------------------------- |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 60 | |
GeunSik Lim | 52ad51e | 2009-09-07 21:37:17 +0900 | [diff] [blame] | 61 | The events available are also listed in /sys/kernel/debug/tracing/events/ hierarchy |
Li Zefan | 143c145 | 2009-05-19 14:43:15 +0800 | [diff] [blame] | 62 | of directories. |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 63 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 64 | To enable event 'sched_wakeup':: |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 65 | |
GeunSik Lim | 52ad51e | 2009-09-07 21:37:17 +0900 | [diff] [blame] | 66 | # echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 67 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 68 | To disable it:: |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 69 | |
GeunSik Lim | 52ad51e | 2009-09-07 21:37:17 +0900 | [diff] [blame] | 70 | # echo 0 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 71 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 72 | To enable all events in sched subsystem:: |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 73 | |
GeunSik Lim | 52ad51e | 2009-09-07 21:37:17 +0900 | [diff] [blame] | 74 | # echo 1 > /sys/kernel/debug/tracing/events/sched/enable |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 75 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 76 | To enable all events:: |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 77 | |
GeunSik Lim | 52ad51e | 2009-09-07 21:37:17 +0900 | [diff] [blame] | 78 | # echo 1 > /sys/kernel/debug/tracing/events/enable |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 79 | |
Li Zefan | 143c145 | 2009-05-19 14:43:15 +0800 | [diff] [blame] | 80 | When reading one of these enable files, there are four results: |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 81 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 82 | - 0 - all events this file affects are disabled |
| 83 | - 1 - all events this file affects are enabled |
| 84 | - X - there is a mixture of events enabled and disabled |
| 85 | - ? - this file does not affect any event |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 86 | |
Li Zefan | 020e5f8 | 2009-07-01 10:47:05 +0800 | [diff] [blame] | 87 | 2.3 Boot option |
| 88 | --------------- |
| 89 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 90 | In order to facilitate early boot debugging, use boot option:: |
Li Zefan | 020e5f8 | 2009-07-01 10:47:05 +0800 | [diff] [blame] | 91 | |
| 92 | trace_event=[event-list] |
| 93 | |
Li Zefan | 03d646e | 2009-12-21 14:27:24 +0800 | [diff] [blame] | 94 | event-list is a comma separated list of events. See section 2.1 for event |
| 95 | format. |
Li Zefan | 020e5f8 | 2009-07-01 10:47:05 +0800 | [diff] [blame] | 96 | |
Li Zefan | 143c145 | 2009-05-19 14:43:15 +0800 | [diff] [blame] | 97 | 3. Defining an event-enabled tracepoint |
| 98 | ======================================= |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 99 | |
Li Zefan | 143c145 | 2009-05-19 14:43:15 +0800 | [diff] [blame] | 100 | See The example provided in samples/trace_events |
Theodore Ts'o | abd4144 | 2009-04-11 15:51:18 -0400 | [diff] [blame] | 101 | |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 102 | 4. Event formats |
| 103 | ================ |
| 104 | |
| 105 | Each trace event has a 'format' file associated with it that contains |
| 106 | a description of each field in a logged event. This information can |
| 107 | be used to parse the binary trace stream, and is also the place to |
| 108 | find the field names that can be used in event filters (see section 5). |
| 109 | |
| 110 | It also displays the format string that will be used to print the |
| 111 | event in text mode, along with the event name and ID used for |
| 112 | profiling. |
| 113 | |
Jonathan Corbet | 6234c7b | 2018-03-07 10:44:08 -0700 | [diff] [blame] | 114 | Every event has a set of ``common`` fields associated with it; these are |
| 115 | the fields prefixed with ``common_``. The other fields vary between |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 116 | events and correspond to the fields defined in the TRACE_EVENT |
| 117 | definition for that event. |
| 118 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 119 | Each field in the format has the form:: |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 120 | |
| 121 | field:field-type field-name; offset:N; size:N; |
| 122 | |
| 123 | where offset is the offset of the field in the trace record and size |
| 124 | is the size of the data item, in bytes. |
| 125 | |
| 126 | For example, here's the information displayed for the 'sched_wakeup' |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 127 | event:: |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 128 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 129 | # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/format |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 130 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 131 | name: sched_wakeup |
| 132 | ID: 60 |
| 133 | format: |
| 134 | field:unsigned short common_type; offset:0; size:2; |
| 135 | field:unsigned char common_flags; offset:2; size:1; |
| 136 | field:unsigned char common_preempt_count; offset:3; size:1; |
| 137 | field:int common_pid; offset:4; size:4; |
| 138 | field:int common_tgid; offset:8; size:4; |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 139 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 140 | field:char comm[TASK_COMM_LEN]; offset:12; size:16; |
| 141 | field:pid_t pid; offset:28; size:4; |
| 142 | field:int prio; offset:32; size:4; |
| 143 | field:int success; offset:36; size:4; |
| 144 | field:int cpu; offset:40; size:4; |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 145 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 146 | print fmt: "task %s:%d [%d] success=%d [%03d]", REC->comm, REC->pid, |
| 147 | REC->prio, REC->success, REC->cpu |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 148 | |
| 149 | This event contains 10 fields, the first 5 common and the remaining 5 |
| 150 | event-specific. All the fields for this event are numeric, except for |
| 151 | 'comm' which is a string, a distinction important for event filtering. |
| 152 | |
| 153 | 5. Event filtering |
| 154 | ================== |
| 155 | |
| 156 | Trace events can be filtered in the kernel by associating boolean |
| 157 | 'filter expressions' with them. As soon as an event is logged into |
| 158 | the trace buffer, its fields are checked against the filter expression |
| 159 | associated with that event type. An event with field values that |
| 160 | 'match' the filter will appear in the trace output, and an event whose |
| 161 | values don't match will be discarded. An event with no filter |
| 162 | associated with it matches everything, and is the default when no |
| 163 | filter has been set for an event. |
| 164 | |
| 165 | 5.1 Expression syntax |
| 166 | --------------------- |
| 167 | |
| 168 | A filter expression consists of one or more 'predicates' that can be |
| 169 | combined using the logical operators '&&' and '||'. A predicate is |
| 170 | simply a clause that compares the value of a field contained within a |
| 171 | logged event with a constant value and returns either 0 or 1 depending |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 172 | on whether the field value matched (1) or didn't match (0):: |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 173 | |
| 174 | field-name relational-operator value |
| 175 | |
| 176 | Parentheses can be used to provide arbitrary logical groupings and |
| 177 | double-quotes can be used to prevent the shell from interpreting |
| 178 | operators as shell metacharacters. |
| 179 | |
| 180 | The field-names available for use in filters can be found in the |
| 181 | 'format' files for trace events (see section 4). |
| 182 | |
| 183 | The relational-operators depend on the type of the field being tested: |
| 184 | |
| 185 | The operators available for numeric fields are: |
| 186 | |
Steven Rostedt | 1a891cf | 2013-06-12 13:16:25 -0400 | [diff] [blame] | 187 | ==, !=, <, <=, >, >=, & |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 188 | |
| 189 | And for string fields they are: |
| 190 | |
Steven Rostedt (Red Hat) | c3e13c7 | 2013-06-17 10:59:17 -0400 | [diff] [blame] | 191 | ==, !=, ~ |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 192 | |
Jonathan Corbet | 6234c7b | 2018-03-07 10:44:08 -0700 | [diff] [blame] | 193 | The glob (~) accepts a wild card character (\*,?) and character classes |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 194 | ([). For example:: |
Steven Rostedt (Red Hat) | c3e13c7 | 2013-06-17 10:59:17 -0400 | [diff] [blame] | 195 | |
| 196 | prev_comm ~ "*sh" |
| 197 | prev_comm ~ "sh*" |
| 198 | prev_comm ~ "*sh*" |
Masami Hiramatsu | 60f1d5e | 2016-10-05 20:58:15 +0900 | [diff] [blame] | 199 | prev_comm ~ "ba*sh" |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 200 | |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 201 | 5.2 Setting filters |
| 202 | ------------------- |
| 203 | |
| 204 | A filter for an individual event is set by writing a filter expression |
| 205 | to the 'filter' file for the given event. |
| 206 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 207 | For example:: |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 208 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 209 | # cd /sys/kernel/debug/tracing/events/sched/sched_wakeup |
| 210 | # echo "common_preempt_count > 4" > filter |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 211 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 212 | A slightly more involved example:: |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 213 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 214 | # cd /sys/kernel/debug/tracing/events/signal/signal_generate |
| 215 | # echo "((sig >= 10 && sig < 15) || sig == 17) && comm != bash" > filter |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 216 | |
| 217 | If there is an error in the expression, you'll get an 'Invalid |
| 218 | argument' error when setting it, and the erroneous string along with |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 219 | an error message can be seen by looking at the filter e.g.:: |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 220 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 221 | # cd /sys/kernel/debug/tracing/events/signal/signal_generate |
| 222 | # echo "((sig >= 10 && sig < 15) || dsig == 17) && comm != bash" > filter |
| 223 | -bash: echo: write error: Invalid argument |
| 224 | # cat filter |
| 225 | ((sig >= 10 && sig < 15) || dsig == 17) && comm != bash |
| 226 | ^ |
| 227 | parse_error: Field not found |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 228 | |
| 229 | Currently the caret ('^') for an error always appears at the beginning of |
| 230 | the filter string; the error message should still be useful though |
| 231 | even without more accurate position info. |
| 232 | |
| 233 | 5.3 Clearing filters |
| 234 | -------------------- |
| 235 | |
| 236 | To clear the filter for an event, write a '0' to the event's filter |
| 237 | file. |
| 238 | |
| 239 | To clear the filters for all events in a subsystem, write a '0' to the |
| 240 | subsystem's filter file. |
| 241 | |
| 242 | 5.3 Subsystem filters |
| 243 | --------------------- |
| 244 | |
| 245 | For convenience, filters for every event in a subsystem can be set or |
| 246 | cleared as a group by writing a filter expression into the filter file |
Thomas Weber | 8839316 | 2010-03-16 11:47:56 +0100 | [diff] [blame] | 247 | at the root of the subsystem. Note however, that if a filter for any |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 248 | event within the subsystem lacks a field specified in the subsystem |
| 249 | filter, or if the filter can't be applied for any other reason, the |
| 250 | filter for that event will retain its previous setting. This can |
| 251 | result in an unintended mixture of filters which could lead to |
| 252 | confusing (to the user who might think different filters are in |
| 253 | effect) trace output. Only filters that reference just the common |
| 254 | fields can be guaranteed to propagate successfully to all events. |
| 255 | |
| 256 | Here are a few subsystem filter examples that also illustrate the |
| 257 | above points: |
| 258 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 259 | Clear the filters on all events in the sched subsystem:: |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 260 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 261 | # cd /sys/kernel/debug/tracing/events/sched |
| 262 | # echo 0 > filter |
| 263 | # cat sched_switch/filter |
| 264 | none |
| 265 | # cat sched_wakeup/filter |
| 266 | none |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 267 | |
| 268 | Set a filter using only common fields for all events in the sched |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 269 | subsystem (all events end up with the same filter):: |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 270 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 271 | # cd /sys/kernel/debug/tracing/events/sched |
| 272 | # echo common_pid == 0 > filter |
| 273 | # cat sched_switch/filter |
| 274 | common_pid == 0 |
| 275 | # cat sched_wakeup/filter |
| 276 | common_pid == 0 |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 277 | |
| 278 | Attempt to set a filter using a non-common field for all events in the |
Thomas Weber | 8839316 | 2010-03-16 11:47:56 +0100 | [diff] [blame] | 279 | sched subsystem (all events but those that have a prev_pid field retain |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 280 | their old filters):: |
Tom Zanussi | 95b6960 | 2009-09-10 23:13:51 -0500 | [diff] [blame] | 281 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 282 | # cd /sys/kernel/debug/tracing/events/sched |
| 283 | # echo prev_pid == 0 > filter |
| 284 | # cat sched_switch/filter |
| 285 | prev_pid == 0 |
| 286 | # cat sched_wakeup/filter |
| 287 | common_pid == 0 |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 288 | |
Steven Rostedt (Red Hat) | 627645f | 2015-11-03 16:37:15 -0500 | [diff] [blame] | 289 | 5.4 PID filtering |
| 290 | ----------------- |
| 291 | |
| 292 | The set_event_pid file in the same directory as the top events directory |
| 293 | exists, will filter all events from tracing any task that does not have the |
| 294 | PID listed in the set_event_pid file. |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 295 | :: |
Steven Rostedt (Red Hat) | 627645f | 2015-11-03 16:37:15 -0500 | [diff] [blame] | 296 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 297 | # cd /sys/kernel/debug/tracing |
| 298 | # echo $$ > set_event_pid |
| 299 | # echo 1 > events/enable |
Steven Rostedt (Red Hat) | 627645f | 2015-11-03 16:37:15 -0500 | [diff] [blame] | 300 | |
| 301 | Will only trace events for the current task. |
| 302 | |
| 303 | To add more PIDs without losing the PIDs already included, use '>>'. |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 304 | :: |
Steven Rostedt (Red Hat) | 627645f | 2015-11-03 16:37:15 -0500 | [diff] [blame] | 305 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 306 | # echo 123 244 1 >> set_event_pid |
Steven Rostedt (Red Hat) | 627645f | 2015-11-03 16:37:15 -0500 | [diff] [blame] | 307 | |
| 308 | |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 309 | 6. Event triggers |
| 310 | ================= |
| 311 | |
| 312 | Trace events can be made to conditionally invoke trigger 'commands' |
| 313 | which can take various forms and are described in detail below; |
| 314 | examples would be enabling or disabling other trace events or invoking |
| 315 | a stack trace whenever the trace event is hit. Whenever a trace event |
| 316 | with attached triggers is invoked, the set of trigger commands |
| 317 | associated with that event is invoked. Any given trigger can |
| 318 | additionally have an event filter of the same form as described in |
| 319 | section 5 (Event filtering) associated with it - the command will only |
| 320 | be invoked if the event being invoked passes the associated filter. |
| 321 | If no filter is associated with the trigger, it always passes. |
| 322 | |
| 323 | Triggers are added to and removed from a particular event by writing |
| 324 | trigger expressions to the 'trigger' file for the given event. |
| 325 | |
| 326 | A given event can have any number of triggers associated with it, |
| 327 | subject to any restrictions that individual commands may have in that |
| 328 | regard. |
| 329 | |
| 330 | Event triggers are implemented on top of "soft" mode, which means that |
| 331 | whenever a trace event has one or more triggers associated with it, |
| 332 | the event is activated even if it isn't actually enabled, but is |
| 333 | disabled in a "soft" mode. That is, the tracepoint will be called, |
| 334 | but just will not be traced, unless of course it's actually enabled. |
| 335 | This scheme allows triggers to be invoked even for events that aren't |
| 336 | enabled, and also allows the current event filter implementation to be |
| 337 | used for conditionally invoking triggers. |
| 338 | |
| 339 | The syntax for event triggers is roughly based on the syntax for |
| 340 | set_ftrace_filter 'ftrace filter commands' (see the 'Filter commands' |
Steven Rostedt (VMware) | d3439f9 | 2018-05-11 15:41:24 -0400 | [diff] [blame] | 341 | section of Documentation/trace/ftrace.rst), but there are major |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 342 | differences and the implementation isn't currently tied to it in any |
| 343 | way, so beware about making generalizations between the two. |
| 344 | |
Steven Rostedt (VMware) | d3439f9 | 2018-05-11 15:41:24 -0400 | [diff] [blame] | 345 | Note: Writing into trace_marker (See Documentation/trace/ftrace.rst) |
| 346 | can also enable triggers that are written into |
| 347 | /sys/kernel/tracing/events/ftrace/print/trigger |
| 348 | |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 349 | 6.1 Expression syntax |
| 350 | --------------------- |
| 351 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 352 | Triggers are added by echoing the command to the 'trigger' file:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 353 | |
| 354 | # echo 'command[:count] [if filter]' > trigger |
| 355 | |
| 356 | Triggers are removed by echoing the same command but starting with '!' |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 357 | to the 'trigger' file:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 358 | |
| 359 | # echo '!command[:count] [if filter]' > trigger |
| 360 | |
| 361 | The [if filter] part isn't used in matching commands when removing, so |
| 362 | leaving that off in a '!' command will accomplish the same thing as |
| 363 | having it in. |
| 364 | |
| 365 | The filter syntax is the same as that described in the 'Event |
| 366 | filtering' section above. |
| 367 | |
| 368 | For ease of use, writing to the trigger file using '>' currently just |
| 369 | adds or removes a single trigger and there's no explicit '>>' support |
| 370 | ('>' actually behaves like '>>') or truncation support to remove all |
| 371 | triggers (you have to use '!' for each one added.) |
| 372 | |
| 373 | 6.2 Supported trigger commands |
| 374 | ------------------------------ |
| 375 | |
| 376 | The following commands are supported: |
| 377 | |
| 378 | - enable_event/disable_event |
| 379 | |
| 380 | These commands can enable or disable another trace event whenever |
| 381 | the triggering event is hit. When these commands are registered, |
| 382 | the other trace event is activated, but disabled in a "soft" mode. |
| 383 | That is, the tracepoint will be called, but just will not be traced. |
| 384 | The event tracepoint stays in this mode as long as there's a trigger |
| 385 | in effect that can trigger it. |
| 386 | |
| 387 | For example, the following trigger causes kmalloc events to be |
| 388 | traced when a read system call is entered, and the :1 at the end |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 389 | specifies that this enablement happens only once:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 390 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 391 | # echo 'enable_event:kmem:kmalloc:1' > \ |
| 392 | /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 393 | |
| 394 | The following trigger causes kmalloc events to stop being traced |
| 395 | when a read system call exits. This disablement happens on every |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 396 | read system call exit:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 397 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 398 | # echo 'disable_event:kmem:kmalloc' > \ |
| 399 | /sys/kernel/debug/tracing/events/syscalls/sys_exit_read/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 400 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 401 | The format is:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 402 | |
| 403 | enable_event:<system>:<event>[:count] |
| 404 | disable_event:<system>:<event>[:count] |
| 405 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 406 | To remove the above commands:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 407 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 408 | # echo '!enable_event:kmem:kmalloc:1' > \ |
| 409 | /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 410 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 411 | # echo '!disable_event:kmem:kmalloc' > \ |
| 412 | /sys/kernel/debug/tracing/events/syscalls/sys_exit_read/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 413 | |
| 414 | Note that there can be any number of enable/disable_event triggers |
| 415 | per triggering event, but there can only be one trigger per |
| 416 | triggered event. e.g. sys_enter_read can have triggers enabling both |
| 417 | kmem:kmalloc and sched:sched_switch, but can't have two kmem:kmalloc |
| 418 | versions such as kmem:kmalloc and kmem:kmalloc:1 or 'kmem:kmalloc if |
| 419 | bytes_req == 256' and 'kmem:kmalloc if bytes_alloc == 256' (they |
| 420 | could be combined into a single filter on kmem:kmalloc though). |
| 421 | |
| 422 | - stacktrace |
| 423 | |
| 424 | This command dumps a stacktrace in the trace buffer whenever the |
| 425 | triggering event occurs. |
| 426 | |
| 427 | For example, the following trigger dumps a stacktrace every time the |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 428 | kmalloc tracepoint is hit:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 429 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 430 | # echo 'stacktrace' > \ |
| 431 | /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 432 | |
| 433 | The following trigger dumps a stacktrace the first 5 times a kmalloc |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 434 | request happens with a size >= 64K:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 435 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 436 | # echo 'stacktrace:5 if bytes_req >= 65536' > \ |
| 437 | /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 438 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 439 | The format is:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 440 | |
| 441 | stacktrace[:count] |
| 442 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 443 | To remove the above commands:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 444 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 445 | # echo '!stacktrace' > \ |
| 446 | /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 447 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 448 | # echo '!stacktrace:5 if bytes_req >= 65536' > \ |
| 449 | /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 450 | |
| 451 | The latter can also be removed more simply by the following (without |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 452 | the filter):: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 453 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 454 | # echo '!stacktrace:5' > \ |
| 455 | /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 456 | |
| 457 | Note that there can be only one stacktrace trigger per triggering |
| 458 | event. |
| 459 | |
| 460 | - snapshot |
| 461 | |
| 462 | This command causes a snapshot to be triggered whenever the |
| 463 | triggering event occurs. |
| 464 | |
| 465 | The following command creates a snapshot every time a block request |
| 466 | queue is unplugged with a depth > 1. If you were tracing a set of |
| 467 | events or functions at the time, the snapshot trace buffer would |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 468 | capture those events when the trigger event occurred:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 469 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 470 | # echo 'snapshot if nr_rq > 1' > \ |
| 471 | /sys/kernel/debug/tracing/events/block/block_unplug/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 472 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 473 | To only snapshot once:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 474 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 475 | # echo 'snapshot:1 if nr_rq > 1' > \ |
| 476 | /sys/kernel/debug/tracing/events/block/block_unplug/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 477 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 478 | To remove the above commands:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 479 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 480 | # echo '!snapshot if nr_rq > 1' > \ |
| 481 | /sys/kernel/debug/tracing/events/block/block_unplug/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 482 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 483 | # echo '!snapshot:1 if nr_rq > 1' > \ |
| 484 | /sys/kernel/debug/tracing/events/block/block_unplug/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 485 | |
| 486 | Note that there can be only one snapshot trigger per triggering |
| 487 | event. |
| 488 | |
| 489 | - traceon/traceoff |
| 490 | |
| 491 | These commands turn tracing on and off when the specified events are |
| 492 | hit. The parameter determines how many times the tracing system is |
| 493 | turned on and off. If unspecified, there is no limit. |
| 494 | |
| 495 | The following command turns tracing off the first time a block |
| 496 | request queue is unplugged with a depth > 1. If you were tracing a |
| 497 | set of events or functions at the time, you could then examine the |
| 498 | trace buffer to see the sequence of events that led up to the |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 499 | trigger event:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 500 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 501 | # echo 'traceoff:1 if nr_rq > 1' > \ |
| 502 | /sys/kernel/debug/tracing/events/block/block_unplug/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 503 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 504 | To always disable tracing when nr_rq > 1:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 505 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 506 | # echo 'traceoff if nr_rq > 1' > \ |
| 507 | /sys/kernel/debug/tracing/events/block/block_unplug/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 508 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 509 | To remove the above commands:: |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 510 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 511 | # echo '!traceoff:1 if nr_rq > 1' > \ |
| 512 | /sys/kernel/debug/tracing/events/block/block_unplug/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 513 | |
Changbin Du | 73d9812 | 2018-02-17 13:39:42 +0800 | [diff] [blame] | 514 | # echo '!traceoff if nr_rq > 1' > \ |
| 515 | /sys/kernel/debug/tracing/events/block/block_unplug/trigger |
Tom Zanussi | ac38fb8 | 2013-10-24 08:59:30 -0500 | [diff] [blame] | 516 | |
| 517 | Note that there can be only one traceon or traceoff trigger per |
| 518 | triggering event. |
Tom Zanussi | 0fc3813 | 2016-03-03 12:54:56 -0600 | [diff] [blame] | 519 | |
| 520 | - hist |
| 521 | |
| 522 | This command aggregates event hits into a hash table keyed on one or |
| 523 | more trace event format fields (or stacktrace) and a set of running |
| 524 | totals derived from one or more trace event format fields and/or |
| 525 | event counts (hitcount). |
| 526 | |
Mauro Carvalho Chehab | ea27225 | 2018-06-26 06:49:11 -0300 | [diff] [blame] | 527 | See Documentation/trace/histogram.rst for details and examples. |
Tom Zanussi | 34ed635 | 2020-01-29 12:59:32 -0600 | [diff] [blame] | 528 | |
| 529 | 6.3 In-kernel trace event API |
| 530 | ----------------------------- |
| 531 | |
| 532 | In most cases, the command-line interface to trace events is more than |
| 533 | sufficient. Sometimes, however, applications might find the need for |
| 534 | more complex relationships than can be expressed through a simple |
| 535 | series of linked command-line expressions, or putting together sets of |
| 536 | commands may be simply too cumbersome. An example might be an |
| 537 | application that needs to 'listen' to the trace stream in order to |
| 538 | maintain an in-kernel state machine detecting, for instance, when an |
| 539 | illegal kernel state occurs in the scheduler. |
| 540 | |
| 541 | The trace event subsystem provides an in-kernel API allowing modules |
| 542 | or other kernel code to generate user-defined 'synthetic' events at |
| 543 | will, which can be used to either augment the existing trace stream |
| 544 | and/or signal that a particular important state has occurred. |
| 545 | |
| 546 | A similar in-kernel API is also available for creating kprobe and |
| 547 | kretprobe events. |
| 548 | |
| 549 | Both the synthetic event and k/ret/probe event APIs are built on top |
| 550 | of a lower-level "dynevent_cmd" event command API, which is also |
| 551 | available for more specialized applications, or as the basis of other |
| 552 | higher-level trace event APIs. |
| 553 | |
| 554 | The API provided for these purposes is describe below and allows the |
| 555 | following: |
| 556 | |
| 557 | - dynamically creating synthetic event definitions |
| 558 | - dynamically creating kprobe and kretprobe event definitions |
| 559 | - tracing synthetic events from in-kernel code |
| 560 | - the low-level "dynevent_cmd" API |
| 561 | |
| 562 | 6.3.1 Dyamically creating synthetic event definitions |
| 563 | ----------------------------------------------------- |
| 564 | |
| 565 | There are a couple ways to create a new synthetic event from a kernel |
| 566 | module or other kernel code. |
| 567 | |
| 568 | The first creates the event in one step, using synth_event_create(). |
| 569 | In this method, the name of the event to create and an array defining |
| 570 | the fields is supplied to synth_event_create(). If successful, a |
| 571 | synthetic event with that name and fields will exist following that |
| 572 | call. For example, to create a new "schedtest" synthetic event: |
| 573 | |
| 574 | ret = synth_event_create("schedtest", sched_fields, |
| 575 | ARRAY_SIZE(sched_fields), THIS_MODULE); |
| 576 | |
| 577 | The sched_fields param in this example points to an array of struct |
| 578 | synth_field_desc, each of which describes an event field by type and |
| 579 | name: |
| 580 | |
| 581 | static struct synth_field_desc sched_fields[] = { |
| 582 | { .type = "pid_t", .name = "next_pid_field" }, |
| 583 | { .type = "char[16]", .name = "next_comm_field" }, |
| 584 | { .type = "u64", .name = "ts_ns" }, |
| 585 | { .type = "u64", .name = "ts_ms" }, |
| 586 | { .type = "unsigned int", .name = "cpu" }, |
| 587 | { .type = "char[64]", .name = "my_string_field" }, |
| 588 | { .type = "int", .name = "my_int_field" }, |
| 589 | }; |
| 590 | |
| 591 | See synth_field_size() for available types. If field_name contains [n] |
| 592 | the field is considered to be an array. |
| 593 | |
| 594 | If the event is created from within a module, a pointer to the module |
| 595 | must be passed to synth_event_create(). This will ensure that the |
| 596 | trace buffer won't contain unreadable events when the module is |
| 597 | removed. |
| 598 | |
| 599 | At this point, the event object is ready to be used for generating new |
| 600 | events. |
| 601 | |
| 602 | In the second method, the event is created in several steps. This |
| 603 | allows events to be created dynamically and without the need to create |
| 604 | and populate an array of fields beforehand. |
| 605 | |
| 606 | To use this method, an empty or partially empty synthetic event should |
| 607 | first be created using synth_event_gen_cmd_start() or |
| 608 | synth_event_gen_cmd_array_start(). For synth_event_gen_cmd_start(), |
| 609 | the name of the event along with one or more pairs of args each pair |
| 610 | representing a 'type field_name;' field specification should be |
| 611 | supplied. For synth_event_gen_cmd_array_start(), the name of the |
| 612 | event along with an array of struct synth_field_desc should be |
| 613 | supplied. Before calling synth_event_gen_cmd_start() or |
| 614 | synth_event_gen_cmd_array_start(), the user should create and |
| 615 | initialize a dynevent_cmd object using synth_event_cmd_init(). |
| 616 | |
| 617 | For example, to create a new "schedtest" synthetic event with two |
| 618 | fields: |
| 619 | |
| 620 | struct dynevent_cmd cmd; |
| 621 | char *buf; |
| 622 | |
| 623 | /* Create a buffer to hold the generated command */ |
| 624 | buf = kzalloc(MAX_DYNEVENT_CMD_LEN, GFP_KERNEL); |
| 625 | |
| 626 | /* Before generating the command, initialize the cmd object */ |
| 627 | synth_event_cmd_init(&cmd, buf, MAX_DYNEVENT_CMD_LEN); |
| 628 | |
| 629 | ret = synth_event_gen_cmd_start(&cmd, "schedtest", THIS_MODULE, |
| 630 | "pid_t", "next_pid_field", |
| 631 | "u64", "ts_ns"); |
| 632 | |
| 633 | Alternatively, using an array of struct synth_field_desc fields |
| 634 | containing the same information: |
| 635 | |
| 636 | ret = synth_event_gen_cmd_array_start(&cmd, "schedtest", THIS_MODULE, |
| 637 | fields, n_fields); |
| 638 | |
| 639 | Once the synthetic event object has been created, it can then be |
| 640 | populated with more fields. Fields are added one by one using |
| 641 | synth_event_add_field(), supplying the dynevent_cmd object, a field |
| 642 | type, and a field name. For example, to add a new int field named |
| 643 | "intfield", the following call should be made: |
| 644 | |
| 645 | ret = synth_event_add_field(&cmd, "int", "intfield"); |
| 646 | |
| 647 | See synth_field_size() for available types. If field_name contains [n] |
| 648 | the field is considered to be an array. |
| 649 | |
| 650 | A group of fields can also be added all at once using an array of |
| 651 | synth_field_desc with add_synth_fields(). For example, this would add |
| 652 | just the first four sched_fields: |
| 653 | |
| 654 | ret = synth_event_add_fields(&cmd, sched_fields, 4); |
| 655 | |
| 656 | If you already have a string of the form 'type field_name', |
| 657 | synth_event_add_field_str() can be used to add it as-is; it will |
| 658 | also automatically append a ';' to the string. |
| 659 | |
| 660 | Once all the fields have been added, the event should be finalized and |
| 661 | registered by calling the synth_event_gen_cmd_end() function: |
| 662 | |
| 663 | ret = synth_event_gen_cmd_end(&cmd); |
| 664 | |
| 665 | At this point, the event object is ready to be used for tracing new |
| 666 | events. |
| 667 | |
| 668 | 6.3.3 Tracing synthetic events from in-kernel code |
| 669 | -------------------------------------------------- |
| 670 | |
| 671 | To trace a synthetic event, there are several options. The first |
| 672 | option is to trace the event in one call, using synth_event_trace() |
| 673 | with a variable number of values, or synth_event_trace_array() with an |
| 674 | array of values to be set. A second option can be used to avoid the |
| 675 | need for a pre-formed array of values or list of arguments, via |
| 676 | synth_event_trace_start() and synth_event_trace_end() along with |
| 677 | synth_event_add_next_val() or synth_event_add_val() to add the values |
| 678 | piecewise. |
| 679 | |
| 680 | 6.3.3.1 Tracing a synthetic event all at once |
| 681 | --------------------------------------------- |
| 682 | |
| 683 | To trace a synthetic event all at once, the synth_event_trace() or |
| 684 | synth_event_trace_array() functions can be used. |
| 685 | |
| 686 | The synth_event_trace() function is passed the trace_event_file |
| 687 | representing the synthetic event (which can be retrieved using |
| 688 | trace_get_event_file() using the synthetic event name, "synthetic" as |
| 689 | the system name, and the trace instance name (NULL if using the global |
| 690 | trace array)), along with an variable number of u64 args, one for each |
| 691 | synthetic event field, and the number of values being passed. |
| 692 | |
| 693 | So, to trace an event corresponding to the synthetic event definition |
| 694 | above, code like the following could be used: |
| 695 | |
| 696 | ret = synth_event_trace(create_synth_test, 7, /* number of values */ |
| 697 | 444, /* next_pid_field */ |
| 698 | (u64)"clackers", /* next_comm_field */ |
| 699 | 1000000, /* ts_ns */ |
| 700 | 1000, /* ts_ms */ |
| 701 | smp_processor_id(),/* cpu */ |
| 702 | (u64)"Thneed", /* my_string_field */ |
| 703 | 999); /* my_int_field */ |
| 704 | |
| 705 | All vals should be cast to u64, and string vals are just pointers to |
| 706 | strings, cast to u64. Strings will be copied into space reserved in |
| 707 | the event for the string, using these pointers. |
| 708 | |
| 709 | Alternatively, the synth_event_trace_array() function can be used to |
| 710 | accomplish the same thing. It is passed the trace_event_file |
| 711 | representing the synthetic event (which can be retrieved using |
| 712 | trace_get_event_file() using the synthetic event name, "synthetic" as |
| 713 | the system name, and the trace instance name (NULL if using the global |
| 714 | trace array)), along with an array of u64, one for each synthetic |
| 715 | event field. |
| 716 | |
| 717 | To trace an event corresponding to the synthetic event definition |
| 718 | above, code like the following could be used: |
| 719 | |
| 720 | u64 vals[7]; |
| 721 | |
| 722 | vals[0] = 777; /* next_pid_field */ |
| 723 | vals[1] = (u64)"tiddlywinks"; /* next_comm_field */ |
| 724 | vals[2] = 1000000; /* ts_ns */ |
| 725 | vals[3] = 1000; /* ts_ms */ |
| 726 | vals[4] = smp_processor_id(); /* cpu */ |
| 727 | vals[5] = (u64)"thneed"; /* my_string_field */ |
| 728 | vals[6] = 398; /* my_int_field */ |
| 729 | |
| 730 | The 'vals' array is just an array of u64, the number of which must |
| 731 | match the number of field in the synthetic event, and which must be in |
| 732 | the same order as the synthetic event fields. |
| 733 | |
| 734 | All vals should be cast to u64, and string vals are just pointers to |
| 735 | strings, cast to u64. Strings will be copied into space reserved in |
| 736 | the event for the string, using these pointers. |
| 737 | |
| 738 | In order to trace a synthetic event, a pointer to the trace event file |
| 739 | is needed. The trace_get_event_file() function can be used to get |
| 740 | it - it will find the file in the given trace instance (in this case |
| 741 | NULL since the top trace array is being used) while at the same time |
| 742 | preventing the instance containing it from going away: |
| 743 | |
| 744 | schedtest_event_file = trace_get_event_file(NULL, "synthetic", |
| 745 | "schedtest"); |
| 746 | |
| 747 | Before tracing the event, it should be enabled in some way, otherwise |
| 748 | the synthetic event won't actually show up in the trace buffer. |
| 749 | |
| 750 | To enable a synthetic event from the kernel, trace_array_set_clr_event() |
| 751 | can be used (which is not specific to synthetic events, so does need |
| 752 | the "synthetic" system name to be specified explicitly). |
| 753 | |
| 754 | To enable the event, pass 'true' to it: |
| 755 | |
| 756 | trace_array_set_clr_event(schedtest_event_file->tr, |
| 757 | "synthetic", "schedtest", true); |
| 758 | |
| 759 | To disable it pass false: |
| 760 | |
| 761 | trace_array_set_clr_event(schedtest_event_file->tr, |
| 762 | "synthetic", "schedtest", false); |
| 763 | |
| 764 | Finally, synth_event_trace_array() can be used to actually trace the |
| 765 | event, which should be visible in the trace buffer afterwards: |
| 766 | |
| 767 | ret = synth_event_trace_array(schedtest_event_file, vals, |
| 768 | ARRAY_SIZE(vals)); |
| 769 | |
| 770 | To remove the synthetic event, the event should be disabled, and the |
| 771 | trace instance should be 'put' back using trace_put_event_file(): |
| 772 | |
| 773 | trace_array_set_clr_event(schedtest_event_file->tr, |
| 774 | "synthetic", "schedtest", false); |
| 775 | trace_put_event_file(schedtest_event_file); |
| 776 | |
| 777 | If those have been successful, synth_event_delete() can be called to |
| 778 | remove the event: |
| 779 | |
| 780 | ret = synth_event_delete("schedtest"); |
| 781 | |
| 782 | 6.3.3.1 Tracing a synthetic event piecewise |
| 783 | ------------------------------------------- |
| 784 | |
| 785 | To trace a synthetic using the piecewise method described above, the |
| 786 | synth_event_trace_start() function is used to 'open' the synthetic |
| 787 | event trace: |
| 788 | |
| 789 | struct synth_trace_state trace_state; |
| 790 | |
| 791 | ret = synth_event_trace_start(schedtest_event_file, &trace_state); |
| 792 | |
| 793 | It's passed the trace_event_file representing the synthetic event |
| 794 | using the same methods as described above, along with a pointer to a |
| 795 | struct synth_trace_state object, which will be zeroed before use and |
| 796 | used to maintain state between this and following calls. |
| 797 | |
| 798 | Once the event has been opened, which means space for it has been |
| 799 | reserved in the trace buffer, the individual fields can be set. There |
| 800 | are two ways to do that, either one after another for each field in |
| 801 | the event, which requires no lookups, or by name, which does. The |
| 802 | tradeoff is flexibility in doing the assignments vs the cost of a |
| 803 | lookup per field. |
| 804 | |
| 805 | To assign the values one after the other without lookups, |
| 806 | synth_event_add_next_val() should be used. Each call is passed the |
| 807 | same synth_trace_state object used in the synth_event_trace_start(), |
| 808 | along with the value to set the next field in the event. After each |
| 809 | field is set, the 'cursor' points to the next field, which will be set |
| 810 | by the subsequent call, continuing until all the fields have been set |
| 811 | in order. The same sequence of calls as in the above examples using |
| 812 | this method would be (without error-handling code): |
| 813 | |
| 814 | /* next_pid_field */ |
| 815 | ret = synth_event_add_next_val(777, &trace_state); |
| 816 | |
| 817 | /* next_comm_field */ |
| 818 | ret = synth_event_add_next_val((u64)"slinky", &trace_state); |
| 819 | |
| 820 | /* ts_ns */ |
| 821 | ret = synth_event_add_next_val(1000000, &trace_state); |
| 822 | |
| 823 | /* ts_ms */ |
| 824 | ret = synth_event_add_next_val(1000, &trace_state); |
| 825 | |
| 826 | /* cpu */ |
| 827 | ret = synth_event_add_next_val(smp_processor_id(), &trace_state); |
| 828 | |
| 829 | /* my_string_field */ |
| 830 | ret = synth_event_add_next_val((u64)"thneed_2.01", &trace_state); |
| 831 | |
| 832 | /* my_int_field */ |
| 833 | ret = synth_event_add_next_val(395, &trace_state); |
| 834 | |
| 835 | To assign the values in any order, synth_event_add_val() should be |
| 836 | used. Each call is passed the same synth_trace_state object used in |
| 837 | the synth_event_trace_start(), along with the field name of the field |
| 838 | to set and the value to set it to. The same sequence of calls as in |
| 839 | the above examples using this method would be (without error-handling |
| 840 | code): |
| 841 | |
| 842 | ret = synth_event_add_val("next_pid_field", 777, &trace_state); |
| 843 | ret = synth_event_add_val("next_comm_field", (u64)"silly putty", |
| 844 | &trace_state); |
| 845 | ret = synth_event_add_val("ts_ns", 1000000, &trace_state); |
| 846 | ret = synth_event_add_val("ts_ms", 1000, &trace_state); |
| 847 | ret = synth_event_add_val("cpu", smp_processor_id(), &trace_state); |
| 848 | ret = synth_event_add_val("my_string_field", (u64)"thneed_9", |
| 849 | &trace_state); |
| 850 | ret = synth_event_add_val("my_int_field", 3999, &trace_state); |
| 851 | |
| 852 | Note that synth_event_add_next_val() and synth_event_add_val() are |
| 853 | incompatible if used within the same trace of an event - either one |
| 854 | can be used but not both at the same time. |
| 855 | |
| 856 | Finally, the event won't be actually traced until it's 'closed', |
| 857 | which is done using synth_event_trace_end(), which takes only the |
| 858 | struct synth_trace_state object used in the previous calls: |
| 859 | |
| 860 | ret = synth_event_trace_end(&trace_state); |
| 861 | |
| 862 | Note that synth_event_trace_end() must be called at the end regardless |
| 863 | of whether any of the add calls failed (say due to a bad field name |
| 864 | being passed in). |
| 865 | |
| 866 | 6.3.4 Dyamically creating kprobe and kretprobe event definitions |
| 867 | ---------------------------------------------------------------- |
| 868 | |
| 869 | To create a kprobe or kretprobe trace event from kernel code, the |
| 870 | kprobe_event_gen_cmd_start() or kretprobe_event_gen_cmd_start() |
| 871 | functions can be used. |
| 872 | |
| 873 | To create a kprobe event, an empty or partially empty kprobe event |
| 874 | should first be created using kprobe_event_gen_cmd_start(). The name |
| 875 | of the event and the probe location should be specfied along with one |
| 876 | or args each representing a probe field should be supplied to this |
| 877 | function. Before calling kprobe_event_gen_cmd_start(), the user |
| 878 | should create and initialize a dynevent_cmd object using |
| 879 | kprobe_event_cmd_init(). |
| 880 | |
| 881 | For example, to create a new "schedtest" kprobe event with two fields: |
| 882 | |
| 883 | struct dynevent_cmd cmd; |
| 884 | char *buf; |
| 885 | |
| 886 | /* Create a buffer to hold the generated command */ |
| 887 | buf = kzalloc(MAX_DYNEVENT_CMD_LEN, GFP_KERNEL); |
| 888 | |
| 889 | /* Before generating the command, initialize the cmd object */ |
| 890 | kprobe_event_cmd_init(&cmd, buf, MAX_DYNEVENT_CMD_LEN); |
| 891 | |
| 892 | /* |
| 893 | * Define the gen_kprobe_test event with the first 2 kprobe |
| 894 | * fields. |
| 895 | */ |
| 896 | ret = kprobe_event_gen_cmd_start(&cmd, "gen_kprobe_test", "do_sys_open", |
| 897 | "dfd=%ax", "filename=%dx"); |
| 898 | |
| 899 | Once the kprobe event object has been created, it can then be |
| 900 | populated with more fields. Fields can be added using |
| 901 | kprobe_event_add_fields(), supplying the dynevent_cmd object along |
| 902 | with a variable arg list of probe fields. For example, to add a |
| 903 | couple additional fields, the following call could be made: |
| 904 | |
| 905 | ret = kprobe_event_add_fields(&cmd, "flags=%cx", "mode=+4($stack)"); |
| 906 | |
| 907 | Once all the fields have been added, the event should be finalized and |
| 908 | registered by calling the kprobe_event_gen_cmd_end() or |
| 909 | kretprobe_event_gen_cmd_end() functions, depending on whether a kprobe |
| 910 | or kretprobe command was started: |
| 911 | |
| 912 | ret = kprobe_event_gen_cmd_end(&cmd); |
| 913 | |
| 914 | or |
| 915 | |
| 916 | ret = kretprobe_event_gen_cmd_end(&cmd); |
| 917 | |
| 918 | At this point, the event object is ready to be used for tracing new |
| 919 | events. |
| 920 | |
| 921 | Similarly, a kretprobe event can be created using |
| 922 | kretprobe_event_gen_cmd_start() with a probe name and location and |
| 923 | additional params such as $retval: |
| 924 | |
| 925 | ret = kretprobe_event_gen_cmd_start(&cmd, "gen_kretprobe_test", |
| 926 | "do_sys_open", "$retval"); |
| 927 | |
| 928 | Similar to the synthetic event case, code like the following can be |
| 929 | used to enable the newly created kprobe event: |
| 930 | |
| 931 | gen_kprobe_test = trace_get_event_file(NULL, "kprobes", "gen_kprobe_test"); |
| 932 | |
| 933 | ret = trace_array_set_clr_event(gen_kprobe_test->tr, |
| 934 | "kprobes", "gen_kprobe_test", true); |
| 935 | |
| 936 | Finally, also similar to synthetic events, the following code can be |
| 937 | used to give the kprobe event file back and delete the event: |
| 938 | |
| 939 | trace_put_event_file(gen_kprobe_test); |
| 940 | |
| 941 | ret = kprobe_event_delete("gen_kprobe_test"); |
| 942 | |
| 943 | 6.3.4 The "dynevent_cmd" low-level API |
| 944 | -------------------------------------- |
| 945 | |
| 946 | Both the in-kernel synthetic event and kprobe interfaces are built on |
| 947 | top of a lower-level "dynevent_cmd" interface. This interface is |
| 948 | meant to provide the basis for higher-level interfaces such as the |
| 949 | synthetic and kprobe interfaces, which can be used as examples. |
| 950 | |
| 951 | The basic idea is simple and amounts to providing a general-purpose |
| 952 | layer that can be used to generate trace event commands. The |
| 953 | generated command strings can then be passed to the command-parsing |
| 954 | and event creation code that already exists in the trace event |
| 955 | subystem for creating the corresponding trace events. |
| 956 | |
| 957 | In a nutshell, the way it works is that the higher-level interface |
| 958 | code creates a struct dynevent_cmd object, then uses a couple |
| 959 | functions, dynevent_arg_add() and dynevent_arg_pair_add() to build up |
| 960 | a command string, which finally causes the command to be executed |
| 961 | using the dynevent_create() function. The details of the interface |
| 962 | are described below. |
| 963 | |
| 964 | The first step in building a new command string is to create and |
| 965 | initialize an instance of a dynevent_cmd. Here, for instance, we |
| 966 | create a dynevent_cmd on the stack and initialize it: |
| 967 | |
| 968 | struct dynevent_cmd cmd; |
| 969 | char *buf; |
| 970 | int ret; |
| 971 | |
| 972 | buf = kzalloc(MAX_DYNEVENT_CMD_LEN, GFP_KERNEL); |
| 973 | |
| 974 | dynevent_cmd_init(cmd, buf, maxlen, DYNEVENT_TYPE_FOO, |
| 975 | foo_event_run_command); |
| 976 | |
| 977 | The dynevent_cmd initialization needs to be given a user-specified |
| 978 | buffer and the length of the buffer (MAX_DYNEVENT_CMD_LEN can be used |
| 979 | for this purpose - at 2k it's generally too big to be comfortably put |
| 980 | on the stack, so is dynamically allocated), a dynevent type id, which |
| 981 | is meant to be used to check that further API calls are for the |
| 982 | correct command type, and a pointer to an event-specific run_command() |
| 983 | callback that will be called to actually execute the event-specific |
| 984 | command function. |
| 985 | |
| 986 | Once that's done, the command string can by built up by successive |
| 987 | calls to argument-adding functions. |
| 988 | |
| 989 | To add a single argument, define and initialize a struct dynevent_arg |
| 990 | or struct dynevent_arg_pair object. Here's an example of the simplest |
| 991 | possible arg addition, which is simply to append the given string as |
| 992 | a whitespace-separated argument to the command: |
| 993 | |
| 994 | struct dynevent_arg arg; |
| 995 | |
| 996 | dynevent_arg_init(&arg, NULL, 0); |
| 997 | |
| 998 | arg.str = name; |
| 999 | |
| 1000 | ret = dynevent_arg_add(cmd, &arg); |
| 1001 | |
| 1002 | The arg object is first initialized using dynevent_arg_init() and in |
| 1003 | this case the parameters are NULL or 0, which means there's no |
| 1004 | optional sanity-checking function or separator appended to the end of |
| 1005 | the arg. |
| 1006 | |
| 1007 | Here's another more complicated example using an 'arg pair', which is |
| 1008 | used to create an argument that consists of a couple components added |
| 1009 | together as a unit, for example, a 'type field_name;' arg or a simple |
| 1010 | expression arg e.g. 'flags=%cx': |
| 1011 | |
| 1012 | struct dynevent_arg_pair arg_pair; |
| 1013 | |
| 1014 | dynevent_arg_pair_init(&arg_pair, dynevent_foo_check_arg_fn, 0, ';'); |
| 1015 | |
| 1016 | arg_pair.lhs = type; |
| 1017 | arg_pair.rhs = name; |
| 1018 | |
| 1019 | ret = dynevent_arg_pair_add(cmd, &arg_pair); |
| 1020 | |
| 1021 | Again, the arg_pair is first initialized, in this case with a callback |
| 1022 | function used to check the sanity of the args (for example, that |
| 1023 | neither part of the pair is NULL), along with a character to be used |
| 1024 | to add an operator between the pair (here none) and a separator to be |
| 1025 | appended onto the end of the arg pair (here ';'). |
| 1026 | |
| 1027 | There's also a dynevent_str_add() function that can be used to simply |
| 1028 | add a string as-is, with no spaces, delimeters, or arg check. |
| 1029 | |
| 1030 | Any number of dynevent_*_add() calls can be made to build up the string |
| 1031 | (until its length surpasses cmd->maxlen). When all the arguments have |
| 1032 | been added and the command string is complete, the only thing left to |
| 1033 | do is run the command, which happens by simply calling |
| 1034 | dynevent_create(): |
| 1035 | |
| 1036 | ret = dynevent_create(&cmd); |
| 1037 | |
| 1038 | At that point, if the return value is 0, the dynamic event has been |
| 1039 | created and is ready to use. |
| 1040 | |
| 1041 | See the dynevent_cmd function definitions themselves for the details |
| 1042 | of the API. |