0001 =============
0002 Event Tracing
0003 =============
0004
0005 :Author: Theodore Ts'o
0006 :Updated: Li Zefan and Tom Zanussi
0007
0008 1. Introduction
0009 ===============
0010
0011 Tracepoints (see Documentation/trace/tracepoints.rst) can be used
0012 without creating custom kernel modules to register probe functions
0013 using the event tracing infrastructure.
0014
0015 Not all tracepoints can be traced using the event tracing system;
0016 the kernel developer must provide code snippets which define how the
0017 tracing information is saved into the tracing buffer, and how the
0018 tracing information should be printed.
0019
0020 2. Using Event Tracing
0021 ======================
0022
0023 2.1 Via the 'set_event' interface
0024 ---------------------------------
0025
0026 The events which are available for tracing can be found in the file
0027 /sys/kernel/debug/tracing/available_events.
0028
0029 To enable a particular event, such as 'sched_wakeup', simply echo it
0030 to /sys/kernel/debug/tracing/set_event. For example::
0031
0032 # echo sched_wakeup >> /sys/kernel/debug/tracing/set_event
0033
0034 .. Note:: '>>' is necessary, otherwise it will firstly disable all the events.
0035
0036 To disable an event, echo the event name to the set_event file prefixed
0037 with an exclamation point::
0038
0039 # echo '!sched_wakeup' >> /sys/kernel/debug/tracing/set_event
0040
0041 To disable all events, echo an empty line to the set_event file::
0042
0043 # echo > /sys/kernel/debug/tracing/set_event
0044
0045 To enable all events, echo ``*:*`` or ``*:`` to the set_event file::
0046
0047 # echo *:* > /sys/kernel/debug/tracing/set_event
0048
0049 The events are organized into subsystems, such as ext4, irq, sched,
0050 etc., and a full event name looks like this: <subsystem>:<event>. The
0051 subsystem name is optional, but it is displayed in the available_events
0052 file. All of the events in a subsystem can be specified via the syntax
0053 ``<subsystem>:*``; for example, to enable all irq events, you can use the
0054 command::
0055
0056 # echo 'irq:*' > /sys/kernel/debug/tracing/set_event
0057
0058 2.2 Via the 'enable' toggle
0059 ---------------------------
0060
0061 The events available are also listed in /sys/kernel/debug/tracing/events/ hierarchy
0062 of directories.
0063
0064 To enable event 'sched_wakeup'::
0065
0066 # echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
0067
0068 To disable it::
0069
0070 # echo 0 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
0071
0072 To enable all events in sched subsystem::
0073
0074 # echo 1 > /sys/kernel/debug/tracing/events/sched/enable
0075
0076 To enable all events::
0077
0078 # echo 1 > /sys/kernel/debug/tracing/events/enable
0079
0080 When reading one of these enable files, there are four results:
0081
0082 - 0 - all events this file affects are disabled
0083 - 1 - all events this file affects are enabled
0084 - X - there is a mixture of events enabled and disabled
0085 - ? - this file does not affect any event
0086
0087 2.3 Boot option
0088 ---------------
0089
0090 In order to facilitate early boot debugging, use boot option::
0091
0092 trace_event=[event-list]
0093
0094 event-list is a comma separated list of events. See section 2.1 for event
0095 format.
0096
0097 3. Defining an event-enabled tracepoint
0098 =======================================
0099
0100 See The example provided in samples/trace_events
0101
0102 4. Event formats
0103 ================
0104
0105 Each trace event has a 'format' file associated with it that contains
0106 a description of each field in a logged event. This information can
0107 be used to parse the binary trace stream, and is also the place to
0108 find the field names that can be used in event filters (see section 5).
0109
0110 It also displays the format string that will be used to print the
0111 event in text mode, along with the event name and ID used for
0112 profiling.
0113
0114 Every event has a set of ``common`` fields associated with it; these are
0115 the fields prefixed with ``common_``. The other fields vary between
0116 events and correspond to the fields defined in the TRACE_EVENT
0117 definition for that event.
0118
0119 Each field in the format has the form::
0120
0121 field:field-type field-name; offset:N; size:N;
0122
0123 where offset is the offset of the field in the trace record and size
0124 is the size of the data item, in bytes.
0125
0126 For example, here's the information displayed for the 'sched_wakeup'
0127 event::
0128
0129 # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/format
0130
0131 name: sched_wakeup
0132 ID: 60
0133 format:
0134 field:unsigned short common_type; offset:0; size:2;
0135 field:unsigned char common_flags; offset:2; size:1;
0136 field:unsigned char common_preempt_count; offset:3; size:1;
0137 field:int common_pid; offset:4; size:4;
0138 field:int common_tgid; offset:8; size:4;
0139
0140 field:char comm[TASK_COMM_LEN]; offset:12; size:16;
0141 field:pid_t pid; offset:28; size:4;
0142 field:int prio; offset:32; size:4;
0143 field:int success; offset:36; size:4;
0144 field:int cpu; offset:40; size:4;
0145
0146 print fmt: "task %s:%d [%d] success=%d [%03d]", REC->comm, REC->pid,
0147 REC->prio, REC->success, REC->cpu
0148
0149 This event contains 10 fields, the first 5 common and the remaining 5
0150 event-specific. All the fields for this event are numeric, except for
0151 'comm' which is a string, a distinction important for event filtering.
0152
0153 5. Event filtering
0154 ==================
0155
0156 Trace events can be filtered in the kernel by associating boolean
0157 'filter expressions' with them. As soon as an event is logged into
0158 the trace buffer, its fields are checked against the filter expression
0159 associated with that event type. An event with field values that
0160 'match' the filter will appear in the trace output, and an event whose
0161 values don't match will be discarded. An event with no filter
0162 associated with it matches everything, and is the default when no
0163 filter has been set for an event.
0164
0165 5.1 Expression syntax
0166 ---------------------
0167
0168 A filter expression consists of one or more 'predicates' that can be
0169 combined using the logical operators '&&' and '||'. A predicate is
0170 simply a clause that compares the value of a field contained within a
0171 logged event with a constant value and returns either 0 or 1 depending
0172 on whether the field value matched (1) or didn't match (0)::
0173
0174 field-name relational-operator value
0175
0176 Parentheses can be used to provide arbitrary logical groupings and
0177 double-quotes can be used to prevent the shell from interpreting
0178 operators as shell metacharacters.
0179
0180 The field-names available for use in filters can be found in the
0181 'format' files for trace events (see section 4).
0182
0183 The relational-operators depend on the type of the field being tested:
0184
0185 The operators available for numeric fields are:
0186
0187 ==, !=, <, <=, >, >=, &
0188
0189 And for string fields they are:
0190
0191 ==, !=, ~
0192
0193 The glob (~) accepts a wild card character (\*,?) and character classes
0194 ([). For example::
0195
0196 prev_comm ~ "*sh"
0197 prev_comm ~ "sh*"
0198 prev_comm ~ "*sh*"
0199 prev_comm ~ "ba*sh"
0200
0201 If the field is a pointer that points into user space (for example
0202 "filename" from sys_enter_openat), then you have to append ".ustring" to the
0203 field name::
0204
0205 filename.ustring ~ "password"
0206
0207 As the kernel will have to know how to retrieve the memory that the pointer
0208 is at from user space.
0209
0210 5.2 Setting filters
0211 -------------------
0212
0213 A filter for an individual event is set by writing a filter expression
0214 to the 'filter' file for the given event.
0215
0216 For example::
0217
0218 # cd /sys/kernel/debug/tracing/events/sched/sched_wakeup
0219 # echo "common_preempt_count > 4" > filter
0220
0221 A slightly more involved example::
0222
0223 # cd /sys/kernel/debug/tracing/events/signal/signal_generate
0224 # echo "((sig >= 10 && sig < 15) || sig == 17) && comm != bash" > filter
0225
0226 If there is an error in the expression, you'll get an 'Invalid
0227 argument' error when setting it, and the erroneous string along with
0228 an error message can be seen by looking at the filter e.g.::
0229
0230 # cd /sys/kernel/debug/tracing/events/signal/signal_generate
0231 # echo "((sig >= 10 && sig < 15) || dsig == 17) && comm != bash" > filter
0232 -bash: echo: write error: Invalid argument
0233 # cat filter
0234 ((sig >= 10 && sig < 15) || dsig == 17) && comm != bash
0235 ^
0236 parse_error: Field not found
0237
0238 Currently the caret ('^') for an error always appears at the beginning of
0239 the filter string; the error message should still be useful though
0240 even without more accurate position info.
0241
0242 5.2.1 Filter limitations
0243 ------------------------
0244
0245 If a filter is placed on a string pointer ``(char *)`` that does not point
0246 to a string on the ring buffer, but instead points to kernel or user space
0247 memory, then, for safety reasons, at most 1024 bytes of the content is
0248 copied onto a temporary buffer to do the compare. If the copy of the memory
0249 faults (the pointer points to memory that should not be accessed), then the
0250 string compare will be treated as not matching.
0251
0252 5.3 Clearing filters
0253 --------------------
0254
0255 To clear the filter for an event, write a '0' to the event's filter
0256 file.
0257
0258 To clear the filters for all events in a subsystem, write a '0' to the
0259 subsystem's filter file.
0260
0261 5.3 Subsystem filters
0262 ---------------------
0263
0264 For convenience, filters for every event in a subsystem can be set or
0265 cleared as a group by writing a filter expression into the filter file
0266 at the root of the subsystem. Note however, that if a filter for any
0267 event within the subsystem lacks a field specified in the subsystem
0268 filter, or if the filter can't be applied for any other reason, the
0269 filter for that event will retain its previous setting. This can
0270 result in an unintended mixture of filters which could lead to
0271 confusing (to the user who might think different filters are in
0272 effect) trace output. Only filters that reference just the common
0273 fields can be guaranteed to propagate successfully to all events.
0274
0275 Here are a few subsystem filter examples that also illustrate the
0276 above points:
0277
0278 Clear the filters on all events in the sched subsystem::
0279
0280 # cd /sys/kernel/debug/tracing/events/sched
0281 # echo 0 > filter
0282 # cat sched_switch/filter
0283 none
0284 # cat sched_wakeup/filter
0285 none
0286
0287 Set a filter using only common fields for all events in the sched
0288 subsystem (all events end up with the same filter)::
0289
0290 # cd /sys/kernel/debug/tracing/events/sched
0291 # echo common_pid == 0 > filter
0292 # cat sched_switch/filter
0293 common_pid == 0
0294 # cat sched_wakeup/filter
0295 common_pid == 0
0296
0297 Attempt to set a filter using a non-common field for all events in the
0298 sched subsystem (all events but those that have a prev_pid field retain
0299 their old filters)::
0300
0301 # cd /sys/kernel/debug/tracing/events/sched
0302 # echo prev_pid == 0 > filter
0303 # cat sched_switch/filter
0304 prev_pid == 0
0305 # cat sched_wakeup/filter
0306 common_pid == 0
0307
0308 5.4 PID filtering
0309 -----------------
0310
0311 The set_event_pid file in the same directory as the top events directory
0312 exists, will filter all events from tracing any task that does not have the
0313 PID listed in the set_event_pid file.
0314 ::
0315
0316 # cd /sys/kernel/debug/tracing
0317 # echo $$ > set_event_pid
0318 # echo 1 > events/enable
0319
0320 Will only trace events for the current task.
0321
0322 To add more PIDs without losing the PIDs already included, use '>>'.
0323 ::
0324
0325 # echo 123 244 1 >> set_event_pid
0326
0327
0328 6. Event triggers
0329 =================
0330
0331 Trace events can be made to conditionally invoke trigger 'commands'
0332 which can take various forms and are described in detail below;
0333 examples would be enabling or disabling other trace events or invoking
0334 a stack trace whenever the trace event is hit. Whenever a trace event
0335 with attached triggers is invoked, the set of trigger commands
0336 associated with that event is invoked. Any given trigger can
0337 additionally have an event filter of the same form as described in
0338 section 5 (Event filtering) associated with it - the command will only
0339 be invoked if the event being invoked passes the associated filter.
0340 If no filter is associated with the trigger, it always passes.
0341
0342 Triggers are added to and removed from a particular event by writing
0343 trigger expressions to the 'trigger' file for the given event.
0344
0345 A given event can have any number of triggers associated with it,
0346 subject to any restrictions that individual commands may have in that
0347 regard.
0348
0349 Event triggers are implemented on top of "soft" mode, which means that
0350 whenever a trace event has one or more triggers associated with it,
0351 the event is activated even if it isn't actually enabled, but is
0352 disabled in a "soft" mode. That is, the tracepoint will be called,
0353 but just will not be traced, unless of course it's actually enabled.
0354 This scheme allows triggers to be invoked even for events that aren't
0355 enabled, and also allows the current event filter implementation to be
0356 used for conditionally invoking triggers.
0357
0358 The syntax for event triggers is roughly based on the syntax for
0359 set_ftrace_filter 'ftrace filter commands' (see the 'Filter commands'
0360 section of Documentation/trace/ftrace.rst), but there are major
0361 differences and the implementation isn't currently tied to it in any
0362 way, so beware about making generalizations between the two.
0363
0364 .. Note::
0365 Writing into trace_marker (See Documentation/trace/ftrace.rst)
0366 can also enable triggers that are written into
0367 /sys/kernel/tracing/events/ftrace/print/trigger
0368
0369 6.1 Expression syntax
0370 ---------------------
0371
0372 Triggers are added by echoing the command to the 'trigger' file::
0373
0374 # echo 'command[:count] [if filter]' > trigger
0375
0376 Triggers are removed by echoing the same command but starting with '!'
0377 to the 'trigger' file::
0378
0379 # echo '!command[:count] [if filter]' > trigger
0380
0381 The [if filter] part isn't used in matching commands when removing, so
0382 leaving that off in a '!' command will accomplish the same thing as
0383 having it in.
0384
0385 The filter syntax is the same as that described in the 'Event
0386 filtering' section above.
0387
0388 For ease of use, writing to the trigger file using '>' currently just
0389 adds or removes a single trigger and there's no explicit '>>' support
0390 ('>' actually behaves like '>>') or truncation support to remove all
0391 triggers (you have to use '!' for each one added.)
0392
0393 6.2 Supported trigger commands
0394 ------------------------------
0395
0396 The following commands are supported:
0397
0398 - enable_event/disable_event
0399
0400 These commands can enable or disable another trace event whenever
0401 the triggering event is hit. When these commands are registered,
0402 the other trace event is activated, but disabled in a "soft" mode.
0403 That is, the tracepoint will be called, but just will not be traced.
0404 The event tracepoint stays in this mode as long as there's a trigger
0405 in effect that can trigger it.
0406
0407 For example, the following trigger causes kmalloc events to be
0408 traced when a read system call is entered, and the :1 at the end
0409 specifies that this enablement happens only once::
0410
0411 # echo 'enable_event:kmem:kmalloc:1' > \
0412 /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
0413
0414 The following trigger causes kmalloc events to stop being traced
0415 when a read system call exits. This disablement happens on every
0416 read system call exit::
0417
0418 # echo 'disable_event:kmem:kmalloc' > \
0419 /sys/kernel/debug/tracing/events/syscalls/sys_exit_read/trigger
0420
0421 The format is::
0422
0423 enable_event:<system>:<event>[:count]
0424 disable_event:<system>:<event>[:count]
0425
0426 To remove the above commands::
0427
0428 # echo '!enable_event:kmem:kmalloc:1' > \
0429 /sys/kernel/debug/tracing/events/syscalls/sys_enter_read/trigger
0430
0431 # echo '!disable_event:kmem:kmalloc' > \
0432 /sys/kernel/debug/tracing/events/syscalls/sys_exit_read/trigger
0433
0434 Note that there can be any number of enable/disable_event triggers
0435 per triggering event, but there can only be one trigger per
0436 triggered event. e.g. sys_enter_read can have triggers enabling both
0437 kmem:kmalloc and sched:sched_switch, but can't have two kmem:kmalloc
0438 versions such as kmem:kmalloc and kmem:kmalloc:1 or 'kmem:kmalloc if
0439 bytes_req == 256' and 'kmem:kmalloc if bytes_alloc == 256' (they
0440 could be combined into a single filter on kmem:kmalloc though).
0441
0442 - stacktrace
0443
0444 This command dumps a stacktrace in the trace buffer whenever the
0445 triggering event occurs.
0446
0447 For example, the following trigger dumps a stacktrace every time the
0448 kmalloc tracepoint is hit::
0449
0450 # echo 'stacktrace' > \
0451 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
0452
0453 The following trigger dumps a stacktrace the first 5 times a kmalloc
0454 request happens with a size >= 64K::
0455
0456 # echo 'stacktrace:5 if bytes_req >= 65536' > \
0457 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
0458
0459 The format is::
0460
0461 stacktrace[:count]
0462
0463 To remove the above commands::
0464
0465 # echo '!stacktrace' > \
0466 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
0467
0468 # echo '!stacktrace:5 if bytes_req >= 65536' > \
0469 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
0470
0471 The latter can also be removed more simply by the following (without
0472 the filter)::
0473
0474 # echo '!stacktrace:5' > \
0475 /sys/kernel/debug/tracing/events/kmem/kmalloc/trigger
0476
0477 Note that there can be only one stacktrace trigger per triggering
0478 event.
0479
0480 - snapshot
0481
0482 This command causes a snapshot to be triggered whenever the
0483 triggering event occurs.
0484
0485 The following command creates a snapshot every time a block request
0486 queue is unplugged with a depth > 1. If you were tracing a set of
0487 events or functions at the time, the snapshot trace buffer would
0488 capture those events when the trigger event occurred::
0489
0490 # echo 'snapshot if nr_rq > 1' > \
0491 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
0492
0493 To only snapshot once::
0494
0495 # echo 'snapshot:1 if nr_rq > 1' > \
0496 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
0497
0498 To remove the above commands::
0499
0500 # echo '!snapshot if nr_rq > 1' > \
0501 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
0502
0503 # echo '!snapshot:1 if nr_rq > 1' > \
0504 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
0505
0506 Note that there can be only one snapshot trigger per triggering
0507 event.
0508
0509 - traceon/traceoff
0510
0511 These commands turn tracing on and off when the specified events are
0512 hit. The parameter determines how many times the tracing system is
0513 turned on and off. If unspecified, there is no limit.
0514
0515 The following command turns tracing off the first time a block
0516 request queue is unplugged with a depth > 1. If you were tracing a
0517 set of events or functions at the time, you could then examine the
0518 trace buffer to see the sequence of events that led up to the
0519 trigger event::
0520
0521 # echo 'traceoff:1 if nr_rq > 1' > \
0522 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
0523
0524 To always disable tracing when nr_rq > 1::
0525
0526 # echo 'traceoff if nr_rq > 1' > \
0527 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
0528
0529 To remove the above commands::
0530
0531 # echo '!traceoff:1 if nr_rq > 1' > \
0532 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
0533
0534 # echo '!traceoff if nr_rq > 1' > \
0535 /sys/kernel/debug/tracing/events/block/block_unplug/trigger
0536
0537 Note that there can be only one traceon or traceoff trigger per
0538 triggering event.
0539
0540 - hist
0541
0542 This command aggregates event hits into a hash table keyed on one or
0543 more trace event format fields (or stacktrace) and a set of running
0544 totals derived from one or more trace event format fields and/or
0545 event counts (hitcount).
0546
0547 See Documentation/trace/histogram.rst for details and examples.
0548
0549 7. In-kernel trace event API
0550 ============================
0551
0552 In most cases, the command-line interface to trace events is more than
0553 sufficient. Sometimes, however, applications might find the need for
0554 more complex relationships than can be expressed through a simple
0555 series of linked command-line expressions, or putting together sets of
0556 commands may be simply too cumbersome. An example might be an
0557 application that needs to 'listen' to the trace stream in order to
0558 maintain an in-kernel state machine detecting, for instance, when an
0559 illegal kernel state occurs in the scheduler.
0560
0561 The trace event subsystem provides an in-kernel API allowing modules
0562 or other kernel code to generate user-defined 'synthetic' events at
0563 will, which can be used to either augment the existing trace stream
0564 and/or signal that a particular important state has occurred.
0565
0566 A similar in-kernel API is also available for creating kprobe and
0567 kretprobe events.
0568
0569 Both the synthetic event and k/ret/probe event APIs are built on top
0570 of a lower-level "dynevent_cmd" event command API, which is also
0571 available for more specialized applications, or as the basis of other
0572 higher-level trace event APIs.
0573
0574 The API provided for these purposes is describe below and allows the
0575 following:
0576
0577 - dynamically creating synthetic event definitions
0578 - dynamically creating kprobe and kretprobe event definitions
0579 - tracing synthetic events from in-kernel code
0580 - the low-level "dynevent_cmd" API
0581
0582 7.1 Dyamically creating synthetic event definitions
0583 ---------------------------------------------------
0584
0585 There are a couple ways to create a new synthetic event from a kernel
0586 module or other kernel code.
0587
0588 The first creates the event in one step, using synth_event_create().
0589 In this method, the name of the event to create and an array defining
0590 the fields is supplied to synth_event_create(). If successful, a
0591 synthetic event with that name and fields will exist following that
0592 call. For example, to create a new "schedtest" synthetic event::
0593
0594 ret = synth_event_create("schedtest", sched_fields,
0595 ARRAY_SIZE(sched_fields), THIS_MODULE);
0596
0597 The sched_fields param in this example points to an array of struct
0598 synth_field_desc, each of which describes an event field by type and
0599 name::
0600
0601 static struct synth_field_desc sched_fields[] = {
0602 { .type = "pid_t", .name = "next_pid_field" },
0603 { .type = "char[16]", .name = "next_comm_field" },
0604 { .type = "u64", .name = "ts_ns" },
0605 { .type = "u64", .name = "ts_ms" },
0606 { .type = "unsigned int", .name = "cpu" },
0607 { .type = "char[64]", .name = "my_string_field" },
0608 { .type = "int", .name = "my_int_field" },
0609 };
0610
0611 See synth_field_size() for available types.
0612
0613 If field_name contains [n], the field is considered to be a static array.
0614
0615 If field_names contains[] (no subscript), the field is considered to
0616 be a dynamic array, which will only take as much space in the event as
0617 is required to hold the array.
0618
0619 Because space for an event is reserved before assigning field values
0620 to the event, using dynamic arrays implies that the piecewise
0621 in-kernel API described below can't be used with dynamic arrays. The
0622 other non-piecewise in-kernel APIs can, however, be used with dynamic
0623 arrays.
0624
0625 If the event is created from within a module, a pointer to the module
0626 must be passed to synth_event_create(). This will ensure that the
0627 trace buffer won't contain unreadable events when the module is
0628 removed.
0629
0630 At this point, the event object is ready to be used for generating new
0631 events.
0632
0633 In the second method, the event is created in several steps. This
0634 allows events to be created dynamically and without the need to create
0635 and populate an array of fields beforehand.
0636
0637 To use this method, an empty or partially empty synthetic event should
0638 first be created using synth_event_gen_cmd_start() or
0639 synth_event_gen_cmd_array_start(). For synth_event_gen_cmd_start(),
0640 the name of the event along with one or more pairs of args each pair
0641 representing a 'type field_name;' field specification should be
0642 supplied. For synth_event_gen_cmd_array_start(), the name of the
0643 event along with an array of struct synth_field_desc should be
0644 supplied. Before calling synth_event_gen_cmd_start() or
0645 synth_event_gen_cmd_array_start(), the user should create and
0646 initialize a dynevent_cmd object using synth_event_cmd_init().
0647
0648 For example, to create a new "schedtest" synthetic event with two
0649 fields::
0650
0651 struct dynevent_cmd cmd;
0652 char *buf;
0653
0654 /* Create a buffer to hold the generated command */
0655 buf = kzalloc(MAX_DYNEVENT_CMD_LEN, GFP_KERNEL);
0656
0657 /* Before generating the command, initialize the cmd object */
0658 synth_event_cmd_init(&cmd, buf, MAX_DYNEVENT_CMD_LEN);
0659
0660 ret = synth_event_gen_cmd_start(&cmd, "schedtest", THIS_MODULE,
0661 "pid_t", "next_pid_field",
0662 "u64", "ts_ns");
0663
0664 Alternatively, using an array of struct synth_field_desc fields
0665 containing the same information::
0666
0667 ret = synth_event_gen_cmd_array_start(&cmd, "schedtest", THIS_MODULE,
0668 fields, n_fields);
0669
0670 Once the synthetic event object has been created, it can then be
0671 populated with more fields. Fields are added one by one using
0672 synth_event_add_field(), supplying the dynevent_cmd object, a field
0673 type, and a field name. For example, to add a new int field named
0674 "intfield", the following call should be made::
0675
0676 ret = synth_event_add_field(&cmd, "int", "intfield");
0677
0678 See synth_field_size() for available types. If field_name contains [n]
0679 the field is considered to be an array.
0680
0681 A group of fields can also be added all at once using an array of
0682 synth_field_desc with add_synth_fields(). For example, this would add
0683 just the first four sched_fields::
0684
0685 ret = synth_event_add_fields(&cmd, sched_fields, 4);
0686
0687 If you already have a string of the form 'type field_name',
0688 synth_event_add_field_str() can be used to add it as-is; it will
0689 also automatically append a ';' to the string.
0690
0691 Once all the fields have been added, the event should be finalized and
0692 registered by calling the synth_event_gen_cmd_end() function::
0693
0694 ret = synth_event_gen_cmd_end(&cmd);
0695
0696 At this point, the event object is ready to be used for tracing new
0697 events.
0698
0699 7.2 Tracing synthetic events from in-kernel code
0700 ------------------------------------------------
0701
0702 To trace a synthetic event, there are several options. The first
0703 option is to trace the event in one call, using synth_event_trace()
0704 with a variable number of values, or synth_event_trace_array() with an
0705 array of values to be set. A second option can be used to avoid the
0706 need for a pre-formed array of values or list of arguments, via
0707 synth_event_trace_start() and synth_event_trace_end() along with
0708 synth_event_add_next_val() or synth_event_add_val() to add the values
0709 piecewise.
0710
0711 7.2.1 Tracing a synthetic event all at once
0712 -------------------------------------------
0713
0714 To trace a synthetic event all at once, the synth_event_trace() or
0715 synth_event_trace_array() functions can be used.
0716
0717 The synth_event_trace() function is passed the trace_event_file
0718 representing the synthetic event (which can be retrieved using
0719 trace_get_event_file() using the synthetic event name, "synthetic" as
0720 the system name, and the trace instance name (NULL if using the global
0721 trace array)), along with an variable number of u64 args, one for each
0722 synthetic event field, and the number of values being passed.
0723
0724 So, to trace an event corresponding to the synthetic event definition
0725 above, code like the following could be used::
0726
0727 ret = synth_event_trace(create_synth_test, 7, /* number of values */
0728 444, /* next_pid_field */
0729 (u64)"clackers", /* next_comm_field */
0730 1000000, /* ts_ns */
0731 1000, /* ts_ms */
0732 smp_processor_id(),/* cpu */
0733 (u64)"Thneed", /* my_string_field */
0734 999); /* my_int_field */
0735
0736 All vals should be cast to u64, and string vals are just pointers to
0737 strings, cast to u64. Strings will be copied into space reserved in
0738 the event for the string, using these pointers.
0739
0740 Alternatively, the synth_event_trace_array() function can be used to
0741 accomplish the same thing. It is passed the trace_event_file
0742 representing the synthetic event (which can be retrieved using
0743 trace_get_event_file() using the synthetic event name, "synthetic" as
0744 the system name, and the trace instance name (NULL if using the global
0745 trace array)), along with an array of u64, one for each synthetic
0746 event field.
0747
0748 To trace an event corresponding to the synthetic event definition
0749 above, code like the following could be used::
0750
0751 u64 vals[7];
0752
0753 vals[0] = 777; /* next_pid_field */
0754 vals[1] = (u64)"tiddlywinks"; /* next_comm_field */
0755 vals[2] = 1000000; /* ts_ns */
0756 vals[3] = 1000; /* ts_ms */
0757 vals[4] = smp_processor_id(); /* cpu */
0758 vals[5] = (u64)"thneed"; /* my_string_field */
0759 vals[6] = 398; /* my_int_field */
0760
0761 The 'vals' array is just an array of u64, the number of which must
0762 match the number of field in the synthetic event, and which must be in
0763 the same order as the synthetic event fields.
0764
0765 All vals should be cast to u64, and string vals are just pointers to
0766 strings, cast to u64. Strings will be copied into space reserved in
0767 the event for the string, using these pointers.
0768
0769 In order to trace a synthetic event, a pointer to the trace event file
0770 is needed. The trace_get_event_file() function can be used to get
0771 it - it will find the file in the given trace instance (in this case
0772 NULL since the top trace array is being used) while at the same time
0773 preventing the instance containing it from going away::
0774
0775 schedtest_event_file = trace_get_event_file(NULL, "synthetic",
0776 "schedtest");
0777
0778 Before tracing the event, it should be enabled in some way, otherwise
0779 the synthetic event won't actually show up in the trace buffer.
0780
0781 To enable a synthetic event from the kernel, trace_array_set_clr_event()
0782 can be used (which is not specific to synthetic events, so does need
0783 the "synthetic" system name to be specified explicitly).
0784
0785 To enable the event, pass 'true' to it::
0786
0787 trace_array_set_clr_event(schedtest_event_file->tr,
0788 "synthetic", "schedtest", true);
0789
0790 To disable it pass false::
0791
0792 trace_array_set_clr_event(schedtest_event_file->tr,
0793 "synthetic", "schedtest", false);
0794
0795 Finally, synth_event_trace_array() can be used to actually trace the
0796 event, which should be visible in the trace buffer afterwards::
0797
0798 ret = synth_event_trace_array(schedtest_event_file, vals,
0799 ARRAY_SIZE(vals));
0800
0801 To remove the synthetic event, the event should be disabled, and the
0802 trace instance should be 'put' back using trace_put_event_file()::
0803
0804 trace_array_set_clr_event(schedtest_event_file->tr,
0805 "synthetic", "schedtest", false);
0806 trace_put_event_file(schedtest_event_file);
0807
0808 If those have been successful, synth_event_delete() can be called to
0809 remove the event::
0810
0811 ret = synth_event_delete("schedtest");
0812
0813 7.2.2 Tracing a synthetic event piecewise
0814 -----------------------------------------
0815
0816 To trace a synthetic using the piecewise method described above, the
0817 synth_event_trace_start() function is used to 'open' the synthetic
0818 event trace::
0819
0820 struct synth_event_trace_state trace_state;
0821
0822 ret = synth_event_trace_start(schedtest_event_file, &trace_state);
0823
0824 It's passed the trace_event_file representing the synthetic event
0825 using the same methods as described above, along with a pointer to a
0826 struct synth_event_trace_state object, which will be zeroed before use and
0827 used to maintain state between this and following calls.
0828
0829 Once the event has been opened, which means space for it has been
0830 reserved in the trace buffer, the individual fields can be set. There
0831 are two ways to do that, either one after another for each field in
0832 the event, which requires no lookups, or by name, which does. The
0833 tradeoff is flexibility in doing the assignments vs the cost of a
0834 lookup per field.
0835
0836 To assign the values one after the other without lookups,
0837 synth_event_add_next_val() should be used. Each call is passed the
0838 same synth_event_trace_state object used in the synth_event_trace_start(),
0839 along with the value to set the next field in the event. After each
0840 field is set, the 'cursor' points to the next field, which will be set
0841 by the subsequent call, continuing until all the fields have been set
0842 in order. The same sequence of calls as in the above examples using
0843 this method would be (without error-handling code)::
0844
0845 /* next_pid_field */
0846 ret = synth_event_add_next_val(777, &trace_state);
0847
0848 /* next_comm_field */
0849 ret = synth_event_add_next_val((u64)"slinky", &trace_state);
0850
0851 /* ts_ns */
0852 ret = synth_event_add_next_val(1000000, &trace_state);
0853
0854 /* ts_ms */
0855 ret = synth_event_add_next_val(1000, &trace_state);
0856
0857 /* cpu */
0858 ret = synth_event_add_next_val(smp_processor_id(), &trace_state);
0859
0860 /* my_string_field */
0861 ret = synth_event_add_next_val((u64)"thneed_2.01", &trace_state);
0862
0863 /* my_int_field */
0864 ret = synth_event_add_next_val(395, &trace_state);
0865
0866 To assign the values in any order, synth_event_add_val() should be
0867 used. Each call is passed the same synth_event_trace_state object used in
0868 the synth_event_trace_start(), along with the field name of the field
0869 to set and the value to set it to. The same sequence of calls as in
0870 the above examples using this method would be (without error-handling
0871 code)::
0872
0873 ret = synth_event_add_val("next_pid_field", 777, &trace_state);
0874 ret = synth_event_add_val("next_comm_field", (u64)"silly putty",
0875 &trace_state);
0876 ret = synth_event_add_val("ts_ns", 1000000, &trace_state);
0877 ret = synth_event_add_val("ts_ms", 1000, &trace_state);
0878 ret = synth_event_add_val("cpu", smp_processor_id(), &trace_state);
0879 ret = synth_event_add_val("my_string_field", (u64)"thneed_9",
0880 &trace_state);
0881 ret = synth_event_add_val("my_int_field", 3999, &trace_state);
0882
0883 Note that synth_event_add_next_val() and synth_event_add_val() are
0884 incompatible if used within the same trace of an event - either one
0885 can be used but not both at the same time.
0886
0887 Finally, the event won't be actually traced until it's 'closed',
0888 which is done using synth_event_trace_end(), which takes only the
0889 struct synth_event_trace_state object used in the previous calls::
0890
0891 ret = synth_event_trace_end(&trace_state);
0892
0893 Note that synth_event_trace_end() must be called at the end regardless
0894 of whether any of the add calls failed (say due to a bad field name
0895 being passed in).
0896
0897 7.3 Dyamically creating kprobe and kretprobe event definitions
0898 --------------------------------------------------------------
0899
0900 To create a kprobe or kretprobe trace event from kernel code, the
0901 kprobe_event_gen_cmd_start() or kretprobe_event_gen_cmd_start()
0902 functions can be used.
0903
0904 To create a kprobe event, an empty or partially empty kprobe event
0905 should first be created using kprobe_event_gen_cmd_start(). The name
0906 of the event and the probe location should be specfied along with one
0907 or args each representing a probe field should be supplied to this
0908 function. Before calling kprobe_event_gen_cmd_start(), the user
0909 should create and initialize a dynevent_cmd object using
0910 kprobe_event_cmd_init().
0911
0912 For example, to create a new "schedtest" kprobe event with two fields::
0913
0914 struct dynevent_cmd cmd;
0915 char *buf;
0916
0917 /* Create a buffer to hold the generated command */
0918 buf = kzalloc(MAX_DYNEVENT_CMD_LEN, GFP_KERNEL);
0919
0920 /* Before generating the command, initialize the cmd object */
0921 kprobe_event_cmd_init(&cmd, buf, MAX_DYNEVENT_CMD_LEN);
0922
0923 /*
0924 * Define the gen_kprobe_test event with the first 2 kprobe
0925 * fields.
0926 */
0927 ret = kprobe_event_gen_cmd_start(&cmd, "gen_kprobe_test", "do_sys_open",
0928 "dfd=%ax", "filename=%dx");
0929
0930 Once the kprobe event object has been created, it can then be
0931 populated with more fields. Fields can be added using
0932 kprobe_event_add_fields(), supplying the dynevent_cmd object along
0933 with a variable arg list of probe fields. For example, to add a
0934 couple additional fields, the following call could be made::
0935
0936 ret = kprobe_event_add_fields(&cmd, "flags=%cx", "mode=+4($stack)");
0937
0938 Once all the fields have been added, the event should be finalized and
0939 registered by calling the kprobe_event_gen_cmd_end() or
0940 kretprobe_event_gen_cmd_end() functions, depending on whether a kprobe
0941 or kretprobe command was started::
0942
0943 ret = kprobe_event_gen_cmd_end(&cmd);
0944
0945 or::
0946
0947 ret = kretprobe_event_gen_cmd_end(&cmd);
0948
0949 At this point, the event object is ready to be used for tracing new
0950 events.
0951
0952 Similarly, a kretprobe event can be created using
0953 kretprobe_event_gen_cmd_start() with a probe name and location and
0954 additional params such as $retval::
0955
0956 ret = kretprobe_event_gen_cmd_start(&cmd, "gen_kretprobe_test",
0957 "do_sys_open", "$retval");
0958
0959 Similar to the synthetic event case, code like the following can be
0960 used to enable the newly created kprobe event::
0961
0962 gen_kprobe_test = trace_get_event_file(NULL, "kprobes", "gen_kprobe_test");
0963
0964 ret = trace_array_set_clr_event(gen_kprobe_test->tr,
0965 "kprobes", "gen_kprobe_test", true);
0966
0967 Finally, also similar to synthetic events, the following code can be
0968 used to give the kprobe event file back and delete the event::
0969
0970 trace_put_event_file(gen_kprobe_test);
0971
0972 ret = kprobe_event_delete("gen_kprobe_test");
0973
0974 7.4 The "dynevent_cmd" low-level API
0975 ------------------------------------
0976
0977 Both the in-kernel synthetic event and kprobe interfaces are built on
0978 top of a lower-level "dynevent_cmd" interface. This interface is
0979 meant to provide the basis for higher-level interfaces such as the
0980 synthetic and kprobe interfaces, which can be used as examples.
0981
0982 The basic idea is simple and amounts to providing a general-purpose
0983 layer that can be used to generate trace event commands. The
0984 generated command strings can then be passed to the command-parsing
0985 and event creation code that already exists in the trace event
0986 subystem for creating the corresponding trace events.
0987
0988 In a nutshell, the way it works is that the higher-level interface
0989 code creates a struct dynevent_cmd object, then uses a couple
0990 functions, dynevent_arg_add() and dynevent_arg_pair_add() to build up
0991 a command string, which finally causes the command to be executed
0992 using the dynevent_create() function. The details of the interface
0993 are described below.
0994
0995 The first step in building a new command string is to create and
0996 initialize an instance of a dynevent_cmd. Here, for instance, we
0997 create a dynevent_cmd on the stack and initialize it::
0998
0999 struct dynevent_cmd cmd;
1000 char *buf;
1001 int ret;
1002
1003 buf = kzalloc(MAX_DYNEVENT_CMD_LEN, GFP_KERNEL);
1004
1005 dynevent_cmd_init(cmd, buf, maxlen, DYNEVENT_TYPE_FOO,
1006 foo_event_run_command);
1007
1008 The dynevent_cmd initialization needs to be given a user-specified
1009 buffer and the length of the buffer (MAX_DYNEVENT_CMD_LEN can be used
1010 for this purpose - at 2k it's generally too big to be comfortably put
1011 on the stack, so is dynamically allocated), a dynevent type id, which
1012 is meant to be used to check that further API calls are for the
1013 correct command type, and a pointer to an event-specific run_command()
1014 callback that will be called to actually execute the event-specific
1015 command function.
1016
1017 Once that's done, the command string can by built up by successive
1018 calls to argument-adding functions.
1019
1020 To add a single argument, define and initialize a struct dynevent_arg
1021 or struct dynevent_arg_pair object. Here's an example of the simplest
1022 possible arg addition, which is simply to append the given string as
1023 a whitespace-separated argument to the command::
1024
1025 struct dynevent_arg arg;
1026
1027 dynevent_arg_init(&arg, NULL, 0);
1028
1029 arg.str = name;
1030
1031 ret = dynevent_arg_add(cmd, &arg);
1032
1033 The arg object is first initialized using dynevent_arg_init() and in
1034 this case the parameters are NULL or 0, which means there's no
1035 optional sanity-checking function or separator appended to the end of
1036 the arg.
1037
1038 Here's another more complicated example using an 'arg pair', which is
1039 used to create an argument that consists of a couple components added
1040 together as a unit, for example, a 'type field_name;' arg or a simple
1041 expression arg e.g. 'flags=%cx'::
1042
1043 struct dynevent_arg_pair arg_pair;
1044
1045 dynevent_arg_pair_init(&arg_pair, dynevent_foo_check_arg_fn, 0, ';');
1046
1047 arg_pair.lhs = type;
1048 arg_pair.rhs = name;
1049
1050 ret = dynevent_arg_pair_add(cmd, &arg_pair);
1051
1052 Again, the arg_pair is first initialized, in this case with a callback
1053 function used to check the sanity of the args (for example, that
1054 neither part of the pair is NULL), along with a character to be used
1055 to add an operator between the pair (here none) and a separator to be
1056 appended onto the end of the arg pair (here ';').
1057
1058 There's also a dynevent_str_add() function that can be used to simply
1059 add a string as-is, with no spaces, delimeters, or arg check.
1060
1061 Any number of dynevent_*_add() calls can be made to build up the string
1062 (until its length surpasses cmd->maxlen). When all the arguments have
1063 been added and the command string is complete, the only thing left to
1064 do is run the command, which happens by simply calling
1065 dynevent_create()::
1066
1067 ret = dynevent_create(&cmd);
1068
1069 At that point, if the return value is 0, the dynamic event has been
1070 created and is ready to use.
1071
1072 See the dynevent_cmd function definitions themselves for the details
1073 of the API.