From 8be098a9eb2710bc5381ba1ebaac660f8d9b6963 Mon Sep 17 00:00:00 2001 From: "Masami Hiramatsu (Google)" Date: Thu, 2 Feb 2023 00:56:55 +0900 Subject: docs: tracing: Update fprobe documentation Update fprobe.rst for - the private entry_data argument - the return value of the entry handler - the nr_rethook_node field. Link: https://lkml.kernel.org/r/167526701579.433354.3057889264263546659.stgit@mhiramat.roam.corp.google.com Cc: Florent Revest Cc: Mark Rutland Cc: Will Deacon Signed-off-by: Masami Hiramatsu (Google) Signed-off-by: Steven Rostedt (Google) --- Documentation/trace/fprobe.rst | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) (limited to 'Documentation') diff --git a/Documentation/trace/fprobe.rst b/Documentation/trace/fprobe.rst index b64bec1ce144..40dd2fbce861 100644 --- a/Documentation/trace/fprobe.rst +++ b/Documentation/trace/fprobe.rst @@ -87,14 +87,16 @@ returns as same as unregister_ftrace_function(). The fprobe entry/exit handler ============================= -The prototype of the entry/exit callback function is as follows: +The prototype of the entry/exit callback function are as follows: .. code-block:: c - void callback_func(struct fprobe *fp, unsigned long entry_ip, struct pt_regs *regs); + int entry_callback(struct fprobe *fp, unsigned long entry_ip, struct pt_regs *regs, void *entry_data); -Note that both entry and exit callbacks have same ptototype. The @entry_ip is -saved at function entry and passed to exit handler. + void exit_callback(struct fprobe *fp, unsigned long entry_ip, struct pt_regs *regs, void *entry_data); + +Note that the @entry_ip is saved at function entry and passed to exit handler. +If the entry callback function returns !0, the corresponding exit callback will be cancelled. @fp This is the address of `fprobe` data structure related to this handler. @@ -113,6 +115,12 @@ saved at function entry and passed to exit handler. to use @entry_ip. On the other hand, in the exit_handler, the instruction pointer of @regs is set to the currect return address. +@entry_data + This is a local storage to share the data between entry and exit handlers. + This storage is NULL by default. If the user specify `exit_handler` field + and `entry_data_size` field when registering the fprobe, the storage is + allocated and passed to both `entry_handler` and `exit_handler`. + Share the callbacks with kprobes ================================ -- cgit v1.2.3-58-ga151 From 80a76994b2d88161697bd92b8b6367d9040dbe2a Mon Sep 17 00:00:00 2001 From: "Steven Rostedt (Google)" Date: Tue, 28 Mar 2023 14:51:56 -0400 Subject: tracing: Add "fields" option to show raw trace event fields The hex, raw and bin formats come from the old PREEMPT_RT patch set latency tracer. That actually gave real alternatives to reading the ascii buffer. But they have started to bit rot and they do not give a good representation of the tracing data. Add "fields" option that will read the trace event fields and parse the data from how the fields are defined: With "fields" = 0 (default) echo 1 > events/sched/sched_switch/enable cat trace -0 [003] d..2. 540.078653: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/3:1 next_pid=83 next_prio=120 kworker/3:1-83 [003] d..2. 540.078860: sched_switch: prev_comm=kworker/3:1 prev_pid=83 prev_prio=120 prev_state=I ==> next_comm=swapper/3 next_pid=0 next_prio=120 -0 [003] d..2. 540.206423: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=sshd next_pid=807 next_prio=120 sshd-807 [003] d..2. 540.206531: sched_switch: prev_comm=sshd prev_pid=807 prev_prio=120 prev_state=S ==> next_comm=swapper/3 next_pid=0 next_prio=120 -0 [001] d..2. 540.206597: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/u16:4 next_pid=58 next_prio=120 kworker/u16:4-58 [001] d..2. 540.206617: sched_switch: prev_comm=kworker/u16:4 prev_pid=58 prev_prio=120 prev_state=I ==> next_comm=bash next_pid=830 next_prio=120 bash-830 [001] d..2. 540.206678: sched_switch: prev_comm=bash prev_pid=830 prev_prio=120 prev_state=R ==> next_comm=kworker/u16:4 next_pid=58 next_prio=120 kworker/u16:4-58 [001] d..2. 540.206696: sched_switch: prev_comm=kworker/u16:4 prev_pid=58 prev_prio=120 prev_state=I ==> next_comm=bash next_pid=830 next_prio=120 bash-830 [001] d..2. 540.206713: sched_switch: prev_comm=bash prev_pid=830 prev_prio=120 prev_state=R ==> next_comm=kworker/u16:4 next_pid=58 next_prio=120 echo 1 > options/fields <...>-998 [002] d..2. 538.643732: sched_switch: next_prio=0x78 (120) next_pid=0x0 (0) next_comm=swapper/2 prev_state=0x20 (32) prev_prio=0x78 (120) prev_pid=0x3e6 (998) prev_comm=trace-cmd -0 [001] d..2. 538.643806: sched_switch: next_prio=0x78 (120) next_pid=0x33e (830) next_comm=bash prev_state=0x0 (0) prev_prio=0x78 (120) prev_pid=0x0 (0) prev_comm=swapper/1 bash-830 [001] d..2. 538.644106: sched_switch: next_prio=0x78 (120) next_pid=0x3a (58) next_comm=kworker/u16:4 prev_state=0x0 (0) prev_prio=0x78 (120) prev_pid=0x33e (830) prev_comm=bash kworker/u16:4-58 [001] d..2. 538.644130: sched_switch: next_prio=0x78 (120) next_pid=0x33e (830) next_comm=bash prev_state=0x80 (128) prev_prio=0x78 (120) prev_pid=0x3a (58) prev_comm=kworker/u16:4 bash-830 [001] d..2. 538.644180: sched_switch: next_prio=0x78 (120) next_pid=0x3a (58) next_comm=kworker/u16:4 prev_state=0x0 (0) prev_prio=0x78 (120) prev_pid=0x33e (830) prev_comm=bash kworker/u16:4-58 [001] d..2. 538.644185: sched_switch: next_prio=0x78 (120) next_pid=0x33e (830) next_comm=bash prev_state=0x80 (128) prev_prio=0x78 (120) prev_pid=0x3a (58) prev_comm=kworker/u16:4 bash-830 [001] d..2. 538.644204: sched_switch: next_prio=0x78 (120) next_pid=0x0 (0) next_comm=swapper/1 prev_state=0x1 (1) prev_prio=0x78 (120) prev_pid=0x33e (830) prev_comm=bash -0 [003] d..2. 538.644211: sched_switch: next_prio=0x78 (120) next_pid=0x327 (807) next_comm=sshd prev_state=0x0 (0) prev_prio=0x78 (120) prev_pid=0x0 (0) prev_comm=swapper/3 sshd-807 [003] d..2. 538.644340: sched_switch: next_prio=0x78 (120) next_pid=0x0 (0) next_comm=swapper/3 prev_state=0x1 (1) prev_prio=0x78 (120) prev_pid=0x327 (807) prev_comm=sshd It traces the data safely without using the trace print formatting. Link: https://lore.kernel.org/linux-trace-kernel/20230328145156.497651be@gandalf.local.home Cc: Masami Hiramatsu Cc: Mark Rutland Cc: Beau Belgrave Signed-off-by: Steven Rostedt (Google) --- Documentation/trace/ftrace.rst | 6 ++ kernel/trace/trace.c | 7 +- kernel/trace/trace.h | 2 + kernel/trace/trace_output.c | 168 +++++++++++++++++++++++++++++++++++++++++ kernel/trace/trace_output.h | 2 + 5 files changed, 183 insertions(+), 2 deletions(-) (limited to 'Documentation') diff --git a/Documentation/trace/ftrace.rst b/Documentation/trace/ftrace.rst index b927fb2b94dc..aaebb821912e 100644 --- a/Documentation/trace/ftrace.rst +++ b/Documentation/trace/ftrace.rst @@ -1027,6 +1027,7 @@ To see what is available, simply cat the file:: nohex nobin noblock + nofields trace_printk annotate nouserstacktrace @@ -1110,6 +1111,11 @@ Here are the available options: block When set, reading trace_pipe will not block when polled. + fields + Print the fields as described by their types. This is a better + option than using hex, bin or raw, as it gives a better parsing + of the content of the event. + trace_printk Can disable trace_printk() from writing into the buffer. diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c index 937e9676dfd4..076d893d2965 100644 --- a/kernel/trace/trace.c +++ b/kernel/trace/trace.c @@ -3726,7 +3726,7 @@ __find_next_entry(struct trace_iterator *iter, int *ent_cpu, #define STATIC_FMT_BUF_SIZE 128 static char static_fmt_buf[STATIC_FMT_BUF_SIZE]; -static char *trace_iter_expand_format(struct trace_iterator *iter) +char *trace_iter_expand_format(struct trace_iterator *iter) { char *tmp; @@ -4446,8 +4446,11 @@ static enum print_line_t print_trace_fmt(struct trace_iterator *iter) if (trace_seq_has_overflowed(s)) return TRACE_TYPE_PARTIAL_LINE; - if (event) + if (event) { + if (tr->trace_flags & TRACE_ITER_FIELDS) + return print_event_fields(iter, event); return event->funcs->trace(iter, sym_flags, event); + } trace_seq_printf(s, "Unknown type %d\n", entry->type); diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h index 616e1aa1c4da..79bdefe9261b 100644 --- a/kernel/trace/trace.h +++ b/kernel/trace/trace.h @@ -619,6 +619,7 @@ bool trace_is_tracepoint_string(const char *str); const char *trace_event_format(struct trace_iterator *iter, const char *fmt); void trace_check_vprintf(struct trace_iterator *iter, const char *fmt, va_list ap) __printf(2, 0); +char *trace_iter_expand_format(struct trace_iterator *iter); int trace_empty(struct trace_iterator *iter); @@ -1199,6 +1200,7 @@ extern int trace_get_user(struct trace_parser *parser, const char __user *ubuf, C(HEX, "hex"), \ C(BIN, "bin"), \ C(BLOCK, "block"), \ + C(FIELDS, "fields"), \ C(PRINTK, "trace_printk"), \ C(ANNOTATE, "annotate"), \ C(USERSTACKTRACE, "userstacktrace"), \ diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c index bd475a00f96d..780c6971c944 100644 --- a/kernel/trace/trace_output.c +++ b/kernel/trace/trace_output.c @@ -808,6 +808,174 @@ EXPORT_SYMBOL_GPL(unregister_trace_event); * Standard events */ +static void print_array(struct trace_iterator *iter, void *pos, + struct ftrace_event_field *field) +{ + int offset; + int len; + int i; + + offset = *(int *)pos & 0xffff; + len = *(int *)pos >> 16; + + if (field) + offset += field->offset; + + if (offset + len >= iter->ent_size) { + trace_seq_puts(&iter->seq, ""); + return; + } + + for (i = 0; i < len; i++, pos++) { + if (i) + trace_seq_putc(&iter->seq, ','); + trace_seq_printf(&iter->seq, "%02x", *(unsigned char *)pos); + } +} + +static void print_fields(struct trace_iterator *iter, struct trace_event_call *call, + struct list_head *head) +{ + struct ftrace_event_field *field; + int offset; + int len; + int ret; + void *pos; + + list_for_each_entry(field, head, link) { + trace_seq_printf(&iter->seq, " %s=", field->name); + if (field->offset + field->size > iter->ent_size) { + trace_seq_puts(&iter->seq, ""); + continue; + } + pos = (void *)iter->ent + field->offset; + + switch (field->filter_type) { + case FILTER_COMM: + case FILTER_STATIC_STRING: + trace_seq_printf(&iter->seq, "%.*s", field->size, (char *)pos); + break; + case FILTER_RDYN_STRING: + case FILTER_DYN_STRING: + offset = *(int *)pos & 0xffff; + len = *(int *)pos >> 16; + + if (field->filter_type == FILTER_RDYN_STRING) + offset += field->offset; + + if (offset + len >= iter->ent_size) { + trace_seq_puts(&iter->seq, ""); + break; + } + pos = (void *)iter->ent + offset; + trace_seq_printf(&iter->seq, "%.*s", len, (char *)pos); + break; + case FILTER_PTR_STRING: + if (!iter->fmt_size) + trace_iter_expand_format(iter); + pos = *(void **)pos; + ret = strncpy_from_kernel_nofault(iter->fmt, pos, + iter->fmt_size); + if (ret < 0) + trace_seq_printf(&iter->seq, "(0x%px)", pos); + else + trace_seq_printf(&iter->seq, "(0x%px:%s)", + pos, iter->fmt); + break; + case FILTER_TRACE_FN: + pos = *(void **)pos; + trace_seq_printf(&iter->seq, "%pS", pos); + break; + case FILTER_CPU: + case FILTER_OTHER: + switch (field->size) { + case 1: + if (isprint(*(char *)pos)) { + trace_seq_printf(&iter->seq, "'%c'", + *(unsigned char *)pos); + } + trace_seq_printf(&iter->seq, "(%d)", + *(unsigned char *)pos); + break; + case 2: + trace_seq_printf(&iter->seq, "0x%x (%d)", + *(unsigned short *)pos, + *(unsigned short *)pos); + break; + case 4: + /* dynamic array info is 4 bytes */ + if (strstr(field->type, "__data_loc")) { + print_array(iter, pos, NULL); + break; + } + + if (strstr(field->type, "__rel_loc")) { + print_array(iter, pos, field); + break; + } + + trace_seq_printf(&iter->seq, "0x%x (%d)", + *(unsigned int *)pos, + *(unsigned int *)pos); + break; + case 8: + trace_seq_printf(&iter->seq, "0x%llx (%lld)", + *(unsigned long long *)pos, + *(unsigned long long *)pos); + break; + default: + trace_seq_puts(&iter->seq, ""); + break; + } + break; + default: + trace_seq_puts(&iter->seq, ""); + } + } + trace_seq_putc(&iter->seq, '\n'); +} + +enum print_line_t print_event_fields(struct trace_iterator *iter, + struct trace_event *event) +{ + struct trace_event_call *call; + struct list_head *head; + + /* ftrace defined events have separate call structures */ + if (event->type <= __TRACE_LAST_TYPE) { + bool found = false; + + down_read(&trace_event_sem); + list_for_each_entry(call, &ftrace_events, list) { + if (call->event.type == event->type) { + found = true; + break; + } + /* No need to search all events */ + if (call->event.type > __TRACE_LAST_TYPE) + break; + } + up_read(&trace_event_sem); + if (!found) { + trace_seq_printf(&iter->seq, "UNKNOWN TYPE %d\n", event->type); + goto out; + } + } else { + call = container_of(event, struct trace_event_call, event); + } + head = trace_get_fields(call); + + trace_seq_printf(&iter->seq, "%s:", trace_event_name(call)); + + if (head && !list_empty(head)) + print_fields(iter, call, head); + else + trace_seq_puts(&iter->seq, "No fields found\n"); + + out: + return trace_handle_return(&iter->seq); +} + enum print_line_t trace_nop_print(struct trace_iterator *iter, int flags, struct trace_event *event) { diff --git a/kernel/trace/trace_output.h b/kernel/trace/trace_output.h index 4c954636caf0..dca40f1f1da4 100644 --- a/kernel/trace/trace_output.h +++ b/kernel/trace/trace_output.h @@ -19,6 +19,8 @@ seq_print_ip_sym(struct trace_seq *s, unsigned long ip, extern void trace_seq_print_sym(struct trace_seq *s, unsigned long address, bool offset); extern int trace_print_context(struct trace_iterator *iter); extern int trace_print_lat_context(struct trace_iterator *iter); +extern enum print_line_t print_event_fields(struct trace_iterator *iter, + struct trace_event *event); extern void trace_event_read_lock(void); extern void trace_event_read_unlock(void); -- cgit v1.2.3-58-ga151 From 27dc2ae7c8d88a23014a74171b2194f8d47ecca7 Mon Sep 17 00:00:00 2001 From: Beau Belgrave Date: Tue, 28 Mar 2023 16:52:16 -0700 Subject: tracing/user_events: Update documentation for ABI The ABI for user_events has changed from mmap() based to remote writes. Update the documentation to reflect these changes, add new section for unregistering events since lifetime is now tied to tasks instead of files. Link: https://lkml.kernel.org/r/20230328235219.203-10-beaub@linux.microsoft.com Signed-off-by: Beau Belgrave Signed-off-by: Steven Rostedt (Google) --- Documentation/trace/user_events.rst | 167 +++++++++++++++++++++--------------- 1 file changed, 97 insertions(+), 70 deletions(-) (limited to 'Documentation') diff --git a/Documentation/trace/user_events.rst b/Documentation/trace/user_events.rst index 422802ef4025..f79987e16cf4 100644 --- a/Documentation/trace/user_events.rst +++ b/Documentation/trace/user_events.rst @@ -20,11 +20,10 @@ dynamic_events is the same as the ioctl with the u: prefix applied. Typically programs will register a set of events that they wish to expose to tools that can read trace_events (such as ftrace and perf). The registration -process gives back two ints to the program for each event. The first int is -the status bit. This describes which bit in little-endian format in the -/sys/kernel/tracing/user_events_status file represents this event. The -second int is the write index which describes the data when a write() or -writev() is called on the /sys/kernel/tracing/user_events_data file. +process tells the kernel which address and bit to reflect if any tool has +enabled the event and data should be written. The registration will give back +a write index which describes the data when a write() or writev() is called +on the /sys/kernel/tracing/user_events_data file. The structures referenced in this document are contained within the /include/uapi/linux/user_events.h file in the source tree. @@ -41,23 +40,64 @@ DIAG_IOCSREG. This command takes a packed struct user_reg as an argument:: struct user_reg { - u32 size; - u64 name_args; - u32 status_bit; - u32 write_index; - }; + /* Input: Size of the user_reg structure being used */ + __u32 size; + + /* Input: Bit in enable address to use */ + __u8 enable_bit; + + /* Input: Enable size in bytes at address */ + __u8 enable_size; + + /* Input: Flags for future use, set to 0 */ + __u16 flags; + + /* Input: Address to update when enabled */ + __u64 enable_addr; + + /* Input: Pointer to string with event name, description and flags */ + __u64 name_args; + + /* Output: Index of the event to use when writing data */ + __u32 write_index; + } __attribute__((__packed__)); + +The struct user_reg requires all the above inputs to be set appropriately. + ++ size: This must be set to sizeof(struct user_reg). -The struct user_reg requires two inputs, the first is the size of the structure -to ensure forward and backward compatibility. The second is the command string -to issue for registering. Upon success two outputs are set, the status bit -and the write index. ++ enable_bit: The bit to reflect the event status at the address specified by + enable_addr. + ++ enable_size: The size of the value specified by enable_addr. + This must be 4 (32-bit) or 8 (64-bit). 64-bit values are only allowed to be + used on 64-bit kernels, however, 32-bit can be used on all kernels. + ++ flags: The flags to use, if any. For the initial version this must be 0. + Callers should first attempt to use flags and retry without flags to ensure + support for lower versions of the kernel. If a flag is not supported -EINVAL + is returned. + ++ enable_addr: The address of the value to use to reflect event status. This + must be naturally aligned and write accessible within the user program. + ++ name_args: The name and arguments to describe the event, see command format + for details. + +Upon successful registration the following is set. + ++ write_index: The index to use for this file descriptor that represents this + event when writing out data. The index is unique to this instance of the file + descriptor that was used for the registration. See writing data for details. User based events show up under tracefs like any other event under the subsystem named "user_events". This means tools that wish to attach to the events need to use /sys/kernel/tracing/events/user_events/[name]/enable or perf record -e user_events:[name] when attaching/recording. -**NOTE:** *The write_index returned is only valid for the FD that was used* +**NOTE:** The event subsystem name by default is "user_events". Callers should +not assume it will always be "user_events". Operators reserve the right in the +future to change the subsystem name per-process to accomodate event isolation. Command Format ^^^^^^^^^^^^^^ @@ -94,7 +134,7 @@ Would be represented by the following field:: struct mytype myname 20 Deleting ------------ +-------- Deleting an event from within a user process is done via ioctl() out to the /sys/kernel/tracing/user_events_data file. The command to issue is DIAG_IOCSDEL. @@ -104,92 +144,79 @@ its name. Delete will only succeed if there are no references left to the event (in both user and kernel space). User programs should use a separate file to request deletes than the one used for registration due to this. -Status ------- -When tools attach/record user based events the status of the event is updated -in realtime. This allows user programs to only incur the cost of the write() or -writev() calls when something is actively attached to the event. - -User programs call mmap() on /sys/kernel/tracing/user_events_status to -check the status for each event that is registered. The bit to check in the -file is given back after the register ioctl() via user_reg.status_bit. The bit -is always in little-endian format. Programs can check if the bit is set either -using a byte-wise index with a mask or a long-wise index with a little-endian -mask. +Unregistering +------------- +If after registering an event it is no longer wanted to be updated then it can +be disabled via ioctl() out to the /sys/kernel/tracing/user_events_data file. +The command to issue is DIAG_IOCSUNREG. This is different than deleting, where +deleting actually removes the event from the system. Unregistering simply tells +the kernel your process is no longer interested in updates to the event. -Currently the size of user_events_status is a single page, however, custom -kernel configurations can change this size to allow more user based events. In -all cases the size of the file is a multiple of a page size. +This command takes a packed struct user_unreg as an argument:: -For example, if the register ioctl() gives back a status_bit of 3 you would -check byte 0 (3 / 8) of the returned mmap data and then AND the result with 8 -(1 << (3 % 8)) to see if anything is attached to that event. + struct user_unreg { + /* Input: Size of the user_unreg structure being used */ + __u32 size; -A byte-wise index check is performed as follows:: + /* Input: Bit to unregister */ + __u8 disable_bit; - int index, mask; - char *status_page; + /* Input: Reserved, set to 0 */ + __u8 __reserved; - index = status_bit / 8; - mask = 1 << (status_bit % 8); - - ... + /* Input: Reserved, set to 0 */ + __u16 __reserved2; - if (status_page[index] & mask) { - /* Enabled */ - } + /* Input: Address to unregister */ + __u64 disable_addr; + } __attribute__((__packed__)); -A long-wise index check is performed as follows:: +The struct user_unreg requires all the above inputs to be set appropriately. - #include - #include ++ size: This must be set to sizeof(struct user_unreg). - #if __BITS_PER_LONG == 64 - #define endian_swap(x) htole64(x) - #else - #define endian_swap(x) htole32(x) - #endif ++ disable_bit: This must be set to the bit to disable (same bit that was + previously registered via enable_bit). - long index, mask, *status_page; ++ disable_addr: This must be set to the address to disable (same address that was + previously registered via enable_addr). - index = status_bit / __BITS_PER_LONG; - mask = 1L << (status_bit % __BITS_PER_LONG); - mask = endian_swap(mask); +**NOTE:** Events are automatically unregistered when execve() is invoked. During +fork() the registered events will be retained and must be unregistered manually +in each process if wanted. - ... +Status +------ +When tools attach/record user based events the status of the event is updated +in realtime. This allows user programs to only incur the cost of the write() or +writev() calls when something is actively attached to the event. - if (status_page[index] & mask) { - /* Enabled */ - } +The kernel will update the specified bit that was registered for the event as +tools attach/detach from the event. User programs simply check if the bit is set +to see if something is attached or not. Administrators can easily check the status of all registered events by reading the user_events_status file directly via a terminal. The output is as follows:: - Byte:Name [# Comments] + Name [# Comments] ... Active: ActiveCount Busy: BusyCount - Max: MaxCount For example, on a system that has a single event the output looks like this:: - 1:test + test Active: 1 Busy: 0 - Max: 32768 If a user enables the user event via ftrace, the output would change to this:: - 1:test # Used by ftrace + test # Used by ftrace Active: 1 Busy: 1 - Max: 32768 - -**NOTE:** *A status bit of 0 will never be returned. This allows user programs -to have a bit that can be used on error cases.* Writing Data ------------ @@ -217,7 +244,7 @@ For example, if I have a struct like this:: int src; int dst; int flags; - }; + } __attribute__((__packed__)); It's advised for user programs to do the following:: -- cgit v1.2.3-58-ga151