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