diff options
| -rw-r--r-- | Documentation/trace/ftrace.rst | 96 | ||||
| -rw-r--r-- | kernel/trace/Kconfig | 2 | ||||
| -rw-r--r-- | kernel/trace/Makefile | 2 | ||||
| -rw-r--r-- | kernel/trace/ftrace.c | 32 | ||||
| -rw-r--r-- | kernel/trace/trace_btf.c | 86 | ||||
| -rw-r--r-- | kernel/trace/trace_btf.h | 18 | ||||
| -rw-r--r-- | kernel/trace/trace_functions.c | 5 | ||||
| -rw-r--r-- | kernel/trace/trace_functions_graph.c | 56 |
8 files changed, 239 insertions, 58 deletions
diff --git a/Documentation/trace/ftrace.rst b/Documentation/trace/ftrace.rst index 7261f25f8b4b..9423722848c6 100644 --- a/Documentation/trace/ftrace.rst +++ b/Documentation/trace/ftrace.rst @@ -1483,6 +1483,10 @@ Options for function_graph tracer: printed in hexadecimal format. By default, this option is off. + funcgraph-retaddr + When set, the return address will always be printed. + By default, this option is off. + sleep-time When running function graph tracer, to include the time a task schedules out in its function. @@ -2829,7 +2833,7 @@ It is default disabled. 0) 2.861 us | } /* putname() */ The return value of each traced function can be displayed after -an equal sign "=". When encountering system call failures, it +an equal sign "ret=". When encountering system call failures, it can be very helpful to quickly locate the function that first returns an error code. @@ -2839,16 +2843,16 @@ returns an error code. Example with funcgraph-retval:: 1) | cgroup_migrate() { - 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */ + 1) 0.651 us | cgroup_migrate_add_task(); /* ret=0xffff93fcfd346c00 */ 1) | cgroup_migrate_execute() { 1) | cpu_cgroup_can_attach() { 1) | cgroup_taskset_first() { - 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */ - 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */ - 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */ - 1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */ - 1) 4.369 us | } /* cgroup_migrate_execute = -22 */ - 1) 7.143 us | } /* cgroup_migrate = -22 */ + 1) 0.732 us | cgroup_taskset_next(); /* ret=0xffff93fc8fb20000 */ + 1) 1.232 us | } /* cgroup_taskset_first ret=0xffff93fc8fb20000 */ + 1) 0.380 us | sched_rt_can_attach(); /* ret=0x0 */ + 1) 2.335 us | } /* cpu_cgroup_can_attach ret=-22 */ + 1) 4.369 us | } /* cgroup_migrate_execute ret=-22 */ + 1) 7.143 us | } /* cgroup_migrate ret=-22 */ The above example shows that the function cpu_cgroup_can_attach returned the error code -22 firstly, then we can read the code @@ -2859,43 +2863,55 @@ be displayed in a smart way. Specifically, if it is an error code, it will be printed in signed decimal format, otherwise it will printed in hexadecimal format. +When CONFIG_DEBUG_INFO_BTF is enabled, the smart format also takes the +declared return type into account. Signed integer and signed enum return +values are printed in signed decimal format, unsigned enum return values +are printed in unsigned decimal format, and unsigned integer, pointer, and +aggregate return values are printed in hexadecimal format. Boolean return +values are printed as ``true`` or ``false``. If the BTF type is unavailable, +the legacy error-code detection is used. + - smart: echo nofuncgraph-retval-hex > trace_options - hexadecimal: echo funcgraph-retval-hex > trace_options Example with funcgraph-retval-hex:: 1) | cgroup_migrate() { - 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */ + 1) 0.651 us | cgroup_migrate_add_task(); /* ret=0xffff93fcfd346c00 */ 1) | cgroup_migrate_execute() { 1) | cpu_cgroup_can_attach() { 1) | cgroup_taskset_first() { - 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */ - 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */ - 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */ - 1) 2.335 us | } /* cpu_cgroup_can_attach = 0xffffffea */ - 1) 4.369 us | } /* cgroup_migrate_execute = 0xffffffea */ - 1) 7.143 us | } /* cgroup_migrate = 0xffffffea */ - -At present, there are some limitations when using the funcgraph-retval -option, and these limitations will be eliminated in the future: - -- Even if the function return type is void, a return value will still - be printed, and you can just ignore it. - -- Even if return values are stored in multiple registers, only the - value contained in the first register will be recorded and printed. - To illustrate, in the x86 architecture, eax and edx are used to store - a 64-bit return value, with the lower 32 bits saved in eax and the - upper 32 bits saved in edx. However, only the value stored in eax - will be recorded and printed. - -- In certain procedure call standards, such as arm64's AAPCS64, when a - type is smaller than a GPR, it is the responsibility of the consumer - to perform the narrowing, and the upper bits may contain UNKNOWN values. - Therefore, it is advisable to check the code for such cases. For instance, - when using a u8 in a 64-bit GPR, bits [63:8] may contain arbitrary values, - especially when larger types are truncated, whether explicitly or implicitly. - Here are some specific cases to illustrate this point: + 1) 0.732 us | cgroup_taskset_next(); /* ret=0xffff93fc8fb20000 */ + 1) 1.232 us | } /* cgroup_taskset_first ret=0xffff93fc8fb20000 */ + 1) 0.380 us | sched_rt_can_attach(); /* ret=0x0 */ + 1) 2.335 us | } /* cpu_cgroup_can_attach ret=0xffffffea */ + 1) 4.369 us | } /* cgroup_migrate_execute ret=0xffffffea */ + 1) 7.143 us | } /* cgroup_migrate ret=0xffffffea */ + +Note that there are some limitations when using the funcgraph-retval +option: + +- If CONFIG_DEBUG_INFO_BTF is disabled (n), a return value is printed even for + functions with a void return type. When CONFIG_DEBUG_INFO_BTF is enabled (y), + the return value is printed only for non-void functions. + +- If a return value occupies multiple registers, only the value in the first + register is recorded and printed. For example, on the x86 architecture, a + 64-bit return value is stored across eax (lower 32 bits) and edx (upper 32 bits), + but only the contents of eax are captured. If CONFIG_DEBUG_INFO_BTF is enabled, + the suffix "(trunc)" is appended to the printed value to indicate that the + output may be truncated because high-order register contents are omitted. + +- Under certain procedure-call standards (e.g., arm64's AAPCS64), when the return + type is smaller than a general-purpose register (GPR), the caller is responsible + for narrowing the value; the upper bits of the register may contain undefined data. + For instance, when a u8 is returned in 64-bit GPR, bits [63:8] can hold arbitrary + values, especially when larger types are truncated (explicitly or implicitly). It + is therefore advisable to inspect the code in such cases. If CONFIG_DEBUG_INFO_BTF + is enabled (y), the return value is automatically trimmed to the width of the return + type. + + The following examples illustrate the behavior: **Case One**: @@ -2914,7 +2930,9 @@ option, and these limitations will be eliminated in the future: RET If you pass 0x123456789abcdef to this function and want to narrow it, - it may be recorded as 0x123456789abcdef instead of 0xef. + it may be recorded as 0x123456789abcdef instead of 0xef. When + CONFIG_DEBUG_INFO_BTF is enabled, the value will be correctly truncated + to 0xef based on the size constraints of the u8 type. **Case Two**: @@ -2939,7 +2957,9 @@ option, and these limitations will be eliminated in the future: RET When passing 0x2_0000_0000 to it, the return value may be recorded as - 0x2_0000_0000 instead of 0. + 0x2_0000_0000 instead of 0. When CONFIG_DEBUG_INFO_BTF is enabled, the + value will be correctly truncated to 0 based on the size constraints of + the int type. You can put some comments on specific functions by using trace_printk() For example, if you want to put a comment inside diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig index 0ab5916575a9..d8faeb659cfc 100644 --- a/kernel/trace/Kconfig +++ b/kernel/trace/Kconfig @@ -770,7 +770,7 @@ config FPROBE_EVENTS config PROBE_EVENTS_BTF_ARGS depends on HAVE_FUNCTION_ARG_ACCESS_API depends on FPROBE_EVENTS || KPROBE_EVENTS - depends on DEBUG_INFO_BTF && BPF_SYSCALL + depends on DEBUG_INFO_BTF bool "Support BTF function arguments for probe events" default y help diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile index 3860bc53a4be..1f925cd1b9f8 100644 --- a/kernel/trace/Makefile +++ b/kernel/trace/Makefile @@ -119,7 +119,7 @@ obj-$(CONFIG_KGDB_KDB) += trace_kdb.o endif obj-$(CONFIG_DYNAMIC_EVENTS) += trace_dynevent.o obj-$(CONFIG_PROBE_EVENTS) += trace_probe.o -obj-$(CONFIG_PROBE_EVENTS_BTF_ARGS) += trace_btf.o +obj-$(CONFIG_DEBUG_INFO_BTF) += trace_btf.o obj-$(CONFIG_UPROBE_EVENTS) += trace_uprobe.o obj-$(CONFIG_BOOTTIME_TRACING) += trace_boot.o obj-$(CONFIG_FTRACE_RECORD_RECURSION) += trace_recursion_record.o diff --git a/kernel/trace/ftrace.c b/kernel/trace/ftrace.c index 673a54fdf392..c7d74b33d36d 100644 --- a/kernel/trace/ftrace.c +++ b/kernel/trace/ftrace.c @@ -428,6 +428,7 @@ struct ftrace_profile { #ifdef CONFIG_FUNCTION_GRAPH_TRACER unsigned long long time; unsigned long long time_squared; + unsigned long long time_max; #endif }; @@ -530,9 +531,9 @@ static int function_stat_headers(struct seq_file *m) { #ifdef CONFIG_FUNCTION_GRAPH_TRACER seq_puts(m, " Function " - "Hit Time Avg s^2\n" + "Hit Time Avg s^2 max\n" " -------- " - "--- ---- --- ---\n"); + "--- ---- --- --- ---\n"); #else seq_puts(m, " Function Hit\n" " -------- ---\n"); @@ -613,6 +614,8 @@ static int function_stat_show(struct seq_file *m, void *v) trace_print_graph_duration(avg, &s); trace_seq_puts(&s, " "); trace_print_graph_duration(stddev, &s); + trace_seq_puts(&s, " "); + trace_print_graph_duration(rec->time_max, &s); trace_print_seq(m, &s); #endif seq_putc(m, '\n'); @@ -920,6 +923,8 @@ static void profile_graph_return(struct ftrace_graph_ret *trace, if (rec) { rec->time += calltime; rec->time_squared += calltime * calltime; + if (calltime > rec->time_max) + rec->time_max = calltime; } } @@ -4426,9 +4431,9 @@ subsys_initcall(ftrace_check_for_weak_functions); static int print_rec(struct seq_file *m, unsigned long ip) { - unsigned long offset; + unsigned long offset = 0; char str[KSYM_SYMBOL_LEN]; - char *modname; + char *modname = NULL; const char *ret; ret = kallsyms_lookup(ip, NULL, &offset, &modname, str); @@ -7702,6 +7707,11 @@ static int ftrace_process_locs(struct module *mod, } addr = ftrace_call_adjust(addr); + /* The architecture may return 0 to reject a patch site */ + if (!addr) { + skipped++; + continue; + } end_offset = (pg->index+1) * sizeof(pg->records[0]); if (end_offset > PAGE_SIZE << pg->order) { @@ -7715,6 +7725,20 @@ static int ftrace_process_locs(struct module *mod, rec->ip = addr; } + /* + * ftrace_release_mod() finds a module's page groups by their first + * record. If every entry was skipped there is none, so unlink the + * new page groups and free them now. + */ + if (mod && !start_pg->index) { + ftrace_pages->next = NULL; + mutex_unlock(&ftrace_lock); + /* Need to synchronize with ftrace_location_range() */ + synchronize_rcu(); + ftrace_free_pages(start_pg); + return 0; + } + if (pg->next) { pg_unuse = pg->next; pg->next = NULL; diff --git a/kernel/trace/trace_btf.c b/kernel/trace/trace_btf.c index ee7a04886bf6..adefd3969b1b 100644 --- a/kernel/trace/trace_btf.c +++ b/kernel/trace/trace_btf.c @@ -2,6 +2,7 @@ #include <linux/btf.h> #include <linux/kernel.h> #include <linux/slab.h> +#include <linux/kallsyms.h> #include "trace_btf.h" @@ -15,6 +16,9 @@ const struct btf_type *btf_find_func_proto(const char *func_name, struct btf **b const struct btf_type *t; s32 id; + if (unlikely(in_atomic() || irqs_disabled())) + return NULL; + id = bpf_find_btf_id(func_name, BTF_KIND_FUNC, btf_p); if (id < 0) return NULL; @@ -123,3 +127,85 @@ out: return member; } +void btf_trim_retval(unsigned long func, unsigned long *retval, bool *print_retval, + int *fmt, bool hex) +{ + const struct btf_type *t; + char name[KSYM_NAME_LEN]; + struct btf *btf; + u32 v, msb; + bool signed_type; + int kind; + + if (lookup_symbol_name(func, name)) + return; + + t = btf_find_func_proto(name, &btf); + if (IS_ERR_OR_NULL(t)) + return; + + t = btf_type_skip_modifiers(btf, t->type, NULL); + kind = t ? BTF_INFO_KIND(t->info) : BTF_KIND_UNKN; + switch (kind) { + case BTF_KIND_UNKN: + *print_retval = false; + break; + case BTF_KIND_STRUCT: + case BTF_KIND_UNION: + case BTF_KIND_ENUM: + case BTF_KIND_ENUM64: + if (kind == BTF_KIND_STRUCT || kind == BTF_KIND_UNION) { + *fmt = RETVAL_FMT_HEX; + signed_type = false; + } else { + *fmt = RETVAL_FMT_DEC; + signed_type = btf_type_kflag(t); + if (!signed_type) + *fmt |= RETVAL_FMT_UNSIGNED; + } + + if (t->size > sizeof(unsigned long)) { + *fmt |= RETVAL_FMT_TRUNC; + msb = BITS_PER_LONG - 1; + } else { + msb = min_t(u32, BITS_PER_BYTE * t->size - 1, + BITS_PER_LONG - 1); + *retval &= GENMASK(msb, 0); + } + if (signed_type && t->size && !hex) + *retval = sign_extend64(*retval, msb); + break; + case BTF_KIND_INT: + v = *(u32 *)(t + 1); + signed_type = false; + if (BTF_INT_ENCODING(v) == BTF_INT_BOOL) { + *fmt = RETVAL_FMT_BOOL; + msb = 0; + } else { + signed_type = BTF_INT_ENCODING(v) & BTF_INT_SIGNED; + if (signed_type) + *fmt = RETVAL_FMT_DEC; + else + *fmt = RETVAL_FMT_HEX; + + if (t->size > sizeof(unsigned long)) { + *fmt |= RETVAL_FMT_TRUNC; + msb = BITS_PER_LONG - 1; + } else { + msb = min_t(u32, BTF_INT_BITS(v) - 1, + BITS_PER_LONG - 1); + } + } + *retval &= GENMASK(msb, 0); + if (signed_type && !hex) + *retval = sign_extend64(*retval, msb); + break; + default: + *fmt = RETVAL_FMT_HEX; + break; + } + + if (*print_retval) + *fmt |= RETVAL_FMT_BTF; + btf_put(btf); +} diff --git a/kernel/trace/trace_btf.h b/kernel/trace/trace_btf.h index 4bd26bceae23..20cbc3d4ae0e 100644 --- a/kernel/trace/trace_btf.h +++ b/kernel/trace/trace_btf.h @@ -1,6 +1,15 @@ /* SPDX-License-Identifier: GPL-2.0 */ #include <linux/btf.h> +enum { + RETVAL_FMT_HEX = BIT(0), + RETVAL_FMT_DEC = BIT(1), + RETVAL_FMT_BOOL = BIT(2), + RETVAL_FMT_TRUNC = BIT(3), + RETVAL_FMT_BTF = BIT(4), + RETVAL_FMT_UNSIGNED = BIT(5), +}; + const struct btf_type *btf_find_func_proto(const char *func_name, struct btf **btf_p); const struct btf_param *btf_get_func_param(const struct btf_type *func_proto, @@ -10,3 +19,12 @@ const struct btf_member *btf_find_struct_member(struct btf *btf, const char *member_name, u32 *anon_offset, const struct btf_type **member_type); +#ifdef CONFIG_DEBUG_INFO_BTF +void btf_trim_retval(unsigned long func, unsigned long *retval, bool *print_retval, + int *fmt, bool hex); +#else +static inline void btf_trim_retval(unsigned long func, unsigned long *retval, + bool *print_retval, int *fmt, bool hex) +{ +} +#endif diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c index c879d43a5fbb..acaba990aaaa 100644 --- a/kernel/trace/trace_functions.c +++ b/kernel/trace/trace_functions.c @@ -121,6 +121,7 @@ static ftrace_func_t select_trace_function(u32 flags_val) case TRACE_FUNC_OPT_ARGS: return function_args_trace_call; case TRACE_FUNC_OPT_STACK: + case TRACE_FUNC_OPT_STACK | TRACE_FUNC_OPT_ARGS: return function_stack_trace_call; case TRACE_FUNC_OPT_NO_REPEATS: return function_no_repeats_trace_call; @@ -295,7 +296,9 @@ function_stack_trace_call(unsigned long ip, unsigned long parent_ip, if (likely(disabled == 1)) { trace_ctx = tracing_gen_ctx_flags(flags); - trace_function(tr, ip, parent_ip, trace_ctx, NULL); + if (!(tr->current_trace_flags->val & TRACE_FUNC_OPT_ARGS)) + fregs = NULL; + trace_function(tr, ip, parent_ip, trace_ctx, fregs); #ifdef CONFIG_UNWINDER_FRAME_POINTER if (ftrace_pids_enabled(op)) skip++; diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c index c5befd0c5b9a..78a608315dd3 100644 --- a/kernel/trace/trace_functions_graph.c +++ b/kernel/trace/trace_functions_graph.c @@ -15,6 +15,7 @@ #include "trace.h" #include "trace_output.h" +#include "trace_btf.h" /* When set, irq functions might be ignored */ static int ftrace_graph_skip_irqs; @@ -876,9 +877,10 @@ static void print_graph_retval(struct trace_seq *s, struct ftrace_graph_ent_entr { unsigned long err_code = 0; unsigned long retval = 0; + bool hex_format; bool print_retaddr = false; bool print_retval = false; - bool hex_format = !!(opt_flags & TRACE_GRAPH_PRINT_RETVAL_HEX); + int retval_fmt = 0; #ifdef CONFIG_FUNCTION_GRAPH_RETVAL retval = graph_ret->retval; @@ -889,17 +891,38 @@ static void print_graph_retval(struct trace_seq *s, struct ftrace_graph_ent_entr print_retaddr = !!(opt_flags & TRACE_GRAPH_PRINT_RETADDR); #endif - if (print_retval && retval && !hex_format) { - /* Check if the return value matches the negative format */ - if (IS_ENABLED(CONFIG_64BIT) && (retval & BIT(31)) && - (((u64)retval) >> 32) == 0) { - err_code = sign_extend64(retval, 31); - } else { - err_code = retval; + if (print_retval) { + int fmt = RETVAL_FMT_HEX; + + hex_format = !!(opt_flags & TRACE_GRAPH_PRINT_RETVAL_HEX); + btf_trim_retval((unsigned long)func, &retval, &print_retval, &fmt, + hex_format); + if (print_retval) { + if (hex_format) + retval_fmt = RETVAL_FMT_HEX; + + if (retval && retval_fmt != RETVAL_FMT_HEX && + !(fmt & RETVAL_FMT_BTF)) { + /* Check if the return value matches the negative format */ + if (IS_ENABLED(CONFIG_64BIT) && (retval & BIT(31)) && + (((u64)retval) >> 32) == 0) { + err_code = sign_extend64(retval, 31); + } else { + err_code = retval; + } + + if (!IS_ERR_VALUE(err_code)) + err_code = 0; + } + + if (retval_fmt == RETVAL_FMT_HEX) { + retval_fmt |= (fmt & RETVAL_FMT_TRUNC); + } else { + if (err_code && fmt & RETVAL_FMT_HEX) + fmt = (fmt & ~RETVAL_FMT_HEX) | RETVAL_FMT_DEC; + retval_fmt = fmt; + } } - - if (!IS_ERR_VALUE(err_code)) - err_code = 0; } if (entry) { @@ -926,10 +949,17 @@ static void print_graph_retval(struct trace_seq *s, struct ftrace_graph_ent_entr trace_flags, false); if (print_retval) { - if (hex_format || (err_code == 0)) + if (retval_fmt & RETVAL_FMT_HEX) trace_seq_printf(s, " ret=0x%lx", retval); + else if (retval_fmt & RETVAL_FMT_BOOL) + trace_seq_printf(s, " ret=%s", retval ? "true" : "false"); + else if (retval_fmt & RETVAL_FMT_UNSIGNED) + trace_seq_printf(s, " ret=%lu", retval); else - trace_seq_printf(s, " ret=%ld", err_code); + trace_seq_printf(s, " ret=%ld", err_code ?: retval); + + if (retval_fmt & RETVAL_FMT_TRUNC) + trace_seq_printf(s, "(trunc)"); } if (!entry || print_retval || print_retaddr) |