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