vault

The TRACE_EVENT Macro

13 min read

The TRACE_EVENT Macro

TRACE_EVENT is the single developer-facing macro that defines a tracepoint together with all of its trace-event plumbing — the ring-buffer record layout, the code that copies arguments into that record, the human-readable format string, and the /sys/kernel/tracing/events/<system>/<event>/format description — in one declaration. The author writes the hook once, with five clauses — TP_PROTO (the probe signature), TP_ARGS (the argument names), TP_STRUCT__entry (the binary record fields), TP_fast_assign (how to fill those fields), and TP_printk (how to render them) — and the kernel’s multi-pass header preprocessing expands that single macro into roughly a dozen distinct C constructs (include/trace/trace_events.h). The header source comment captures the intent perfectly: “Think about this whole construct as the trace_sched_switch() function from now on.” This is what makes Linux tracepoints self-documenting and uniformly consumable by ftrace, perf, and eBPF — the same five clauses generate the call site, the record, and the metadata that tools read.

This note dissects the macro and its expansion. The underlying hook semantics (static-key guard, probe registration, ABI status) live in Tracepoints; the runtime subsystem that owns the ring buffers and events/ directory is The Trace Event Subsystem; the format file it emits is detailed in Trace Event Format Files.

Mental Model — One Declaration, Many Generated Artifacts

The mental shift is to stop reading TRACE_EVENT(...) as a function call and start reading it as a specification that a code generator consumes. The five clauses are not executed where they are written; they are captured as macro arguments and replayed by trace_events.h, which #includes the same event header seven times in a row, each time having #undef-ed and redefined TRACE_EVENT/DECLARE_EVENT_CLASS/DEFINE_EVENT to emit a different artifact. One textual TRACE_EVENT therefore produces: a tracepoint (the actual hook), a C struct for the record, a function to compute variable-length sizes, a probe that builds the record, an output function that renders it, a fields-description table, a printk format string, and the struct trace_event_call that ties them all together and is registered with the subsystem.

flowchart TB
  TE["TRACE_EVENT(sched_switch,<br/>TP_PROTO, TP_ARGS,<br/>TP_STRUCT__entry,<br/>TP_fast_assign, TP_printk)"]
  TE --> H["tracepoint.h pass:<br/>TRACE_EVENT → DECLARE_TRACE<br/>= the actual hook"]
  TE --> S1["stage 1: struct trace_event_raw_sched_switch<br/>{ trace_entry ent; ...fields...; }"]
  TE --> S3["stage 3: trace_raw_output_sched_switch()<br/>(renders record via TP_printk)"]
  TE --> S4["stage 4: trace_event_fields[]<br/>(drives the format file)"]
  TE --> S6["stage 6: trace_event_raw_event_sched_switch()<br/>(the probe: reserve + TP_fast_assign + commit)"]
  TE --> S7["stage 7: print_fmt[] + event_class +<br/>struct trace_event_call (registered in _ftrace_events)"]
  H -.-> TP["__tracepoint_sched_switch<br/>+ trace_sched_switch()"]
  S6 -.-> TP
  S7 -.-> FMT["/sys/kernel/tracing/events/<br/>sched/sched_switch/format"]

What it shows: a single TRACE_EVENT declaration fanning out into the hook (via tracepoint.h) and the trace-event artifacts (via the seven-stage trace_events.h). The insight: the same five clauses appear in every stage but mean something different each pass — TP_STRUCT__entry becomes a struct in stage 1, a fields table in stage 4, and a size calculator in stage 5; TP_fast_assign becomes the body of the probe in stage 6; TP_printk becomes both the renderer (stage 3) and the print_fmt string in the format file (stage 7).

The Five Clauses, Walked

Take the canonical scheduler event from include/trace/events/sched.h, lightly trimmed:

TRACE_EVENT(sched_switch,
 
    TP_PROTO(bool preempt, struct task_struct *prev,
             struct task_struct *next, unsigned int prev_state),
 
    TP_ARGS(preempt, prev, next, prev_state),
 
    TP_STRUCT__entry(
        __array(  char,  prev_comm,  TASK_COMM_LEN )
        __field(  pid_t, prev_pid                  )
        __field(  int,   prev_prio                 )
        __field(  long,  prev_state                )
        __array(  char,  next_comm,  TASK_COMM_LEN )
        __field(  pid_t, next_pid                  )
        __field(  int,   next_prio                 )
    ),
 
    TP_fast_assign(
        memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN);
        __entry->prev_pid   = prev->pid;
        __entry->prev_prio  = prev->prio;
        __entry->prev_state = __trace_sched_switch_state(preempt, prev_state, prev);
        memcpy(__entry->next_comm, next->comm, TASK_COMM_LEN);
        __entry->next_pid   = next->pid;
        __entry->next_prio  = next->prio;
    ),
 
    TP_printk("prev_comm=%s prev_pid=%d prev_prio=%d ... ==> next_comm=%s next_pid=%d next_prio=%d",
        __entry->prev_comm, __entry->prev_pid, __entry->prev_prio, /* ... */
        __entry->next_comm, __entry->next_pid, __entry->next_prio)
);

TP_PROTO — the probe signature. This is the C prototype of trace_sched_switch() and of every probe that will attach to it. As shown in Tracepoints, TP_PROTO is a pass-through macro; its real purpose is type safety: the prototype name-mangles register_trace_sched_switch() so the compiler rejects any probe whose signature does not match exactly. The arguments here (preempt, prev, next, prev_state) are the raw kernel objects available at the call site — this is what a raw_tracepoint BPF program receives.

TP_ARGS — the argument names. Just the parameter names from the prototype, with no types. The header comment explains the design choice: “we use this instead of a TP_PROTO1/TP_PROTO2/TP_PROTO3 ugliness” — the macro machinery needs the names separately from the typed prototype to forward them into generated calls, so the author supplies both rather than the macros trying to parse one out of the other. TP_ARGS() can wrap helpers like __perf_task(p) to feed perf-specific metadata.

TP_STRUCT__entry — the ring-buffer record layout. This is what gets saved into the ring buffer, and it is deliberately not the same as the prototype. The author chooses a compact binary record: here, two fixed char[TASK_COMM_LEN] arrays for the command names plus several integers — not the two task_struct * pointers, which would be useless to a userspace reader. The field macros are a small DSL: __field(type, name) declares a scalar (pid_t prev_pid;), __array(type, name, len) a fixed array (char prev_comm[TASK_COMM_LEN];), and (not shown here) __dynamic_array, __string, and friends declare variable-length tails. The header comment states it plainly: “This is how the trace record is structured and will be saved into the ring buffer. These are the fields that will be exposed to user-space in /sys/kernel/tracing/events/<*>/format.” The local variable holding the record is always called __entry.

TP_fast_assign — fill the record. A block of arbitrary C, run every time the event fires on an enabled tracepoint, that copies the TP_PROTO arguments into __entry. This is where pointers are dereferenced into stored values: memcpy(__entry->prev_comm, prev->comm, TASK_COMM_LEN) flattens the task’s name, __entry->prev_pid = prev->pid snapshots the PID. Because this runs on the hot path inside the probe, it must be fast and must not sleep. The header comment warns: “this C code will execute every time a trace event happens, on an active tracepoint.”

TP_printk — the human-readable format. A printf-style format string plus arguments referencing __entry fields, used to render the record as text for the tracefs trace file and trace_pipe, and stored verbatim as print_fmt in the format file. The header notes that “raw-binary tracing won’t actually perform this step” — perf and BPF read the binary record and apply their own formatting, so TP_printk is purely for the textual ftrace view and for tools that parse print_fmt. The sched_switch TP_printk uses __print_flags(...) to decode prev_state into letters like S/D/R — these __print_* helpers are also emitted into the format file so userspace can reproduce the decoding.

Mechanical Walk-through — The Seven-Stage Expansion

The magic is in trace_events.h, which is #included once per stage with the macros redefined. Each stage #undefs DECLARE_EVENT_CLASS/DEFINE_EVENT and re-#includes the same event header (#include TRACE_INCLUDE(TRACE_INCLUDE_FILE)), so the author’s TRACE_EVENT(sched_switch, ...) is re-read each time and emits a different construct. Here is what each pass produces, verified against the v6.12 source.

First, the hook (via tracepoint.h, not trace_events.h). Before any of the stages, when the event header is included without CREATE_TRACE_POINTS, TRACE_EVENT reduces straight to DECLARE_TRACE (line 586 of tracepoint.h): #define TRACE_EVENT(name, proto, args, struct, assign, print) DECLARE_TRACE(name, PARAMS(proto), PARAMS(args)). So the TP_STRUCT__entry/TP_fast_assign/TP_printk clauses are thrown away and only the tracepoint hook is generated. This is the path most kernel .c files see — they get trace_sched_switch() and nothing else.

Stage 1 — the record struct. trace_events.h redefines DECLARE_EVENT_CLASS to emit:

struct trace_event_raw_sched_switch {
    struct trace_entry ent;   /* common header: type, flags, preempt_count, pid */
    char  prev_comm[TASK_COMM_LEN];   /* from __array */
    pid_t prev_pid;                   /* from __field */
    /* ... the rest of TP_STRUCT__entry ... */
    char  __data[];           /* tail for dynamic arrays */
};

The tstruct argument (your TP_STRUCT__entry) is pasted in verbatim because the __field/__array macros are, in this stage, defined to expand to plain C declarations. Every record begins with struct trace_entry ent — the common header carrying the event type id, flags, and PID — which is why the format file always lists common_type, common_flags, common_preempt_count, and common_pid before your fields.

Stage 2 — data offsets. Emits struct trace_event_data_offsets_sched_switch, a parallel struct of u32 offsets used to place variable-length (__dynamic_array/__string) data in the record’s __data[] tail. For an all-fixed event like sched_switch it is effectively empty.

Stage 3 — the output function. Emits trace_raw_output_sched_switch(), which casts the ring-buffer entry back to struct trace_event_raw_sched_switch * and calls trace_event_printf(iter, print) with your TP_printk format. This is the function ftrace invokes to render a record as a line of text. It is wired into a struct trace_event_functions whose .trace member points at it.

Stage 4 — the fields table. Emits trace_event_fields_sched_switch[], an array of struct trace_event_fields describing each field’s type name, field name, size, alignment, and signedness. This array is the source of the format file — when you cat .../format, the subsystem walks this table. It is also what the kernel’s predicate-based event filtering compiles against.

Stage 5 — the size calculator. Emits trace_event_get_offsets_sched_switch(), which computes __data_size (the dynamic tail length) so the probe knows how many bytes to reserve in the ring buffer.

Stage 6 — the probe. This is the heart. DECLARE_EVENT_CLASS emits trace_event_raw_event_sched_switch(void *__data, proto) — the function that actually runs when the tracepoint fires:

static notrace void
trace_event_raw_event_sched_switch(void *__data, /* TP_PROTO args */) {
    struct trace_event_file *trace_file = __data;
    struct trace_event_buffer fbuffer;
    struct trace_event_raw_sched_switch *entry;
    int __data_size;
 
    if (trace_trigger_soft_disabled(trace_file))   /* per-instance off / filtered */
        return;
    __data_size = trace_event_get_offsets_sched_switch(&__data_offsets, args);  /* stage 5 */
    entry = trace_event_buffer_reserve(&fbuffer, trace_file,
                       sizeof(*entry) + __data_size);   /* grab ring-buffer slot */
    if (!entry)
        return;
    { assign; }    /* <-- YOUR TP_fast_assign runs here, filling *entry */
    trace_event_buffer_commit(&fbuffer);   /* publish the record */
}

So TP_fast_assign becomes the body sandwiched between reserve and commit: reserve a correctly sized slot in the per-CPU ring buffer, run the author’s copy code into it, then commit. This probe is exactly what gets registered with the tracepoint via register_trace_<name>() when you echo 1 > .../enable.

Stage 7 — the glue (trace_event_call). Finally, DECLARE_EVENT_CLASS emits the print_fmt[] string (= print) and the struct trace_event_class, while DEFINE_EVENT emits the per-event struct trace_event_call:

static char print_fmt_sched_switch[] = /* your TP_printk */;
static struct trace_event_class event_class_sched_switch = {
    .system     = TRACE_SYSTEM_STRING,       /* "sched" */
    .fields_array = trace_event_fields_sched_switch,   /* stage 4 */
    .raw_init   = trace_event_raw_init,
    .probe      = trace_event_raw_event_sched_switch,  /* stage 6 */
    .reg        = trace_event_reg,
    .perf_probe = perf_trace_sched_switch,   /* if CONFIG_PERF_EVENTS */
};
static struct trace_event_call __used event_sched_switch = {
    .class    = &event_class_sched_switch,
    { .tp     = &__tracepoint_sched_switch },   /* the hook from tracepoint.h */
    .print_fmt = print_fmt_sched_switch,
    .flags    = TRACE_EVENT_FL_TRACEPOINT,
};
static struct trace_event_call __used
__section("_ftrace_events") *__event_sched_switch = &event_sched_switch;

The pointer dropped into the _ftrace_events ELF section is how The Trace Event Subsystem discovers every trace event at boot: it walks that section and, for each trace_event_call, creates the events/<system>/<event>/ directory in tracefs with its enable, filter, trigger, id, and format files. The .tp member links the trace event back to its tracepoint hook; the .probe is what registration attaches.

DECLARE_EVENT_CLASS and DEFINE_EVENT — Sharing a Layout

Many events share an identical record layout and differ only in name and call site. Emitting the full stage-1-through-7 machinery for each would bloat the kernel badly. The fix is to split TRACE_EVENT into its two halves:

  • DECLARE_EVENT_CLASS(name, proto, args, tstruct, assign, print) generates the shared heavy machinery once — the record struct, the probe, the output function, the fields table, the size calculator, the class.
  • DEFINE_EVENT(class, name, proto, args) generates only the light per-event bits — a distinct tracepoint hook and a trace_event_call that reuses the class’s probe and layout.

TRACE_EVENT itself is literally defined as a DECLARE_EVENT_CLASS immediately followed by a one-to-one DEFINE_EVENT (line 38 of trace_events.h):

#define TRACE_EVENT(name, proto, args, tstruct, assign, print) \
    DECLARE_EVENT_CLASS(name, PARAMS(proto), PARAMS(args), \
                        PARAMS(tstruct), PARAMS(assign), PARAMS(print)); \
    DEFINE_EVENT(name, name, PARAMS(proto), PARAMS(args));

The scheduler’s wakeup events are the textbook example of the manual split — one class, three events (sched.h):

DECLARE_EVENT_CLASS(sched_wakeup_template,
    TP_PROTO(struct task_struct *p),
    TP_ARGS(__perf_task(p)),
    TP_STRUCT__entry( __array(char, comm, TASK_COMM_LEN) __field(pid_t, pid)
                      __field(int, prio) __field(int, target_cpu) ),
    TP_fast_assign( memcpy(__entry->comm, p->comm, TASK_COMM_LEN);
                    __entry->pid = p->pid; __entry->prio = p->prio;
                    __entry->target_cpu = task_cpu(p); ),
    TP_printk("comm=%s pid=%d prio=%d target_cpu=%03d",
              __entry->comm, __entry->pid, __entry->prio, __entry->target_cpu)
);
 
DEFINE_EVENT(sched_wakeup_template, sched_waking,     TP_PROTO(struct task_struct *p), TP_ARGS(p));
DEFINE_EVENT(sched_wakeup_template, sched_wakeup,     TP_PROTO(struct task_struct *p), TP_ARGS(p));
DEFINE_EVENT(sched_wakeup_template, sched_wakeup_new, TP_PROTO(struct task_struct *p), TP_ARGS(p));

The record struct and probe are emitted once for sched_wakeup_template; the three events sched_waking, sched_wakeup, sched_wakeup_new each get their own tracepoint hook and events/sched/<name>/ directory but share all the generated code. There is also DEFINE_EVENT_PRINT (override just the TP_printk for one event of a class) and DEFINE_EVENT_CONDITION (add a runtime cond). For events needing custom register/unregister work there is the TRACE_EVENT_FN variant, which threads reg/unreg callbacks through to the tracepoint — this is how the syscall and a few other special families hook in (see Syscall Tracepoints sys_enter and sys_exit).

Failure Modes and Common Misunderstandings

Confusing the prototype with the record. A frequent beginner error is making TP_STRUCT__entry mirror TP_PROTO and storing raw pointers. The record must hold self-contained values a userspace reader can use; storing a task_struct * yields a meaningless kernel address in the trace. sched_switch deliberately stores prev_comm/prev_pid, not prev.

TP_fast_assign doing slow or sleeping work. The assign block runs inside the probe, on the hot path, with preemption disabled around the call. Blocking, allocating with GFP_KERNEL, or heavy computation there will hurt or deadlock. Expensive preparation belongs behind a trace_<name>_enabled() guard at the call site (see Tracepoints), not in TP_fast_assign.

CREATE_TRACE_POINTS in more than one .c. The instantiating define must appear in exactly one translation unit; duplicate it and the linker reports multiple definitions of __tracepoint_<name> and the event-call symbols.

Forgetting #include <trace/define_trace.h> outside the header guard. The seven-stage re-inclusion relies on define_trace.h re-reading the header with TRACE_HEADER_MULTI_READ; placing it inside the #ifndef _TRACE_..._H guard silently disables generation, and the event never appears under events/.

Expecting TP_printk to affect perf/BPF. It does not — those consumers read the binary record. Changing only TP_printk changes the ftrace text and the format file’s print fmt line, nothing about the binary layout.

Production Notes and History

TRACE_EVENT landed in 2009 (2.6.31 era) to replace the earlier, more manual tracepoint-plus-handler boilerplate; the design was introduced by Steven Rostedt and explained in a three-part LWN series (part 1, part 2, part 3) — the tracepoints.rst doc still points readers there. Its payoff is structural: because the same five clauses generate the hook, the binary record, and the format description, a trace event is self-documenting — cat /sys/kernel/tracing/events/sched/sched_switch/format shows exactly the fields stage 4 emitted, and that file is precisely what perf, libtraceevent, and BPF CO-RE tooling parse to decode records without hard-coded offsets. This is also what keeps tracepoints loosely ABI-compatible (see Tracepoints): a tool that reads format adapts to field changes that would break a tool with baked-in layout assumptions.

Uncertain

Verify: the exact kernel release that first shipped TRACE_EVENT (stated here as the 2.6.31 era, 2009). Reason: dated from the LWN series timeline rather than a changelog I fetched at v6.12. To resolve: git log --oneline --reverse on include/trace/trace_events.h / include/linux/tracepoint.h in a kernel tree, or the historical Documentation changelog. The mechanism described (seven-stage expansion, _ftrace_events section) is verified directly against the v6.12 trace_events.h source. uncertain

See Also

Graph View

Backlinks