On Mon, 23 Dec 2024 15:13:48 -0500
Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:
> +#ifdef CONFIG_FUNCTION_TRACE_ARGS
> +void print_function_args(struct trace_seq *s, unsigned long *args,
> + unsigned long func)
> +{
> + const struct btf_param *param;
> + const struct btf_type *t;
> + const char *param_name;
> + char name[KSYM_NAME_LEN];
> + unsigned long arg;
> + struct btf *btf;
> + s32 tid, nr = 0;
> + int i;
> +
> + trace_seq_printf(s, "(");
> +
> + if (!args)
> + goto out;
> + if (lookup_symbol_name(func, name))
> + goto out;
> +
> + btf = bpf_get_btf_vmlinux();
> + if (IS_ERR_OR_NULL(btf))
> + goto out;
> +
> + t = btf_find_func_proto(name, &btf);
> + if (IS_ERR_OR_NULL(t))
> + goto out;
> +
> + param = btf_get_func_param(t, &nr);
> + if (!param)
> + goto out_put;
> +
> + for (i = 0; i < nr; i++) {
> + /* This only prints what the arch allows (6 args by default) */
> + if (i == FTRACE_REGS_MAX_ARGS) {
> + trace_seq_puts(s, "...");
> + break;
> + }
> +
> + arg = args[i];
> +
> + param_name = btf_name_by_offset(btf, param[i].name_off);
> + if (param_name)
> + trace_seq_printf(s, "%s=", param_name);
> + t = btf_type_skip_modifiers(btf, param[i].type, &tid);
> +
> + switch (t ? BTF_INFO_KIND(t->info) : BTF_KIND_UNKN) {
> + case BTF_KIND_UNKN:
> + trace_seq_putc(s, '?');
> + /* Still print unknown type values */
> + fallthrough;
> + case BTF_KIND_PTR:
> + trace_seq_printf(s, "0x%lx", arg);
> + break;
> + case BTF_KIND_INT:
> + trace_seq_printf(s, "%ld", arg);
> + break;
> + case BTF_KIND_ENUM:
> + trace_seq_printf(s, "%ld", arg);
> + break;
> + default:
> + /* This does not handle complex arguments */
> + trace_seq_printf(s, "0x%lx (%s)", arg, btf_type_str(t));
This will need to take into account the size of the type. STRUCTs show up,
and most of the time they are simply the size of the architecture's word.
But I hit this:
timespec64_add_safe(lhs=0x6c2 (STRUCT), rhs=0x39c4153f (STRUCT))
Where it definitely isn't correct, as we have:
struct timespec64 {
time64_t tv_sec; /* seconds */
long tv_nsec; /* nanoseconds */
};
struct timespec64 timespec64_add_safe(const struct timespec64 lhs,
const struct timespec64 rhs)
> + break;
> + }
> + if (i < nr - 1)
> + trace_seq_printf(s, ", ");
> + }
> +out_put:
> + btf_put(btf);
> +out:
> + trace_seq_printf(s, ")");
> +}
> +#endif
> +
I updated to this (separating the args array from the BTF parameters):
@@ -684,6 +683,91 @@ int trace_print_lat_context(struct trace_iterator *iter)
return !trace_seq_has_overflowed(s);
}
+#ifdef CONFIG_FUNCTION_TRACE_ARGS
+void print_function_args(struct trace_seq *s, unsigned long *args,
+ unsigned long func)
+{
+ const struct btf_param *param;
+ const struct btf_type *t;
+ const char *param_name;
+ char name[KSYM_NAME_LEN];
+ unsigned long arg;
+ struct btf *btf;
+ s32 tid, nr = 0;
+ int a, p, x;
+
+ trace_seq_printf(s, "(");
+
+ if (!args)
+ goto out;
+ if (lookup_symbol_name(func, name))
+ goto out;
+
+ btf = bpf_get_btf_vmlinux();
+ if (IS_ERR_OR_NULL(btf))
+ goto out;
+
+ t = btf_find_func_proto(name, &btf);
+ if (IS_ERR_OR_NULL(t))
+ goto out;
+
+ param = btf_get_func_param(t, &nr);
+ if (!param)
+ goto out_put;
+
+ for (a = 0, p = 0; p < nr; a++, p++) {
+ if (p)
+ trace_seq_puts(s, ", ");
+
+ /* This only prints what the arch allows (6 args by default) */
+ if (a == FTRACE_REGS_MAX_ARGS) {
+ trace_seq_puts(s, "...");
+ break;
+ }
+
+ arg = args[a];
+
+ param_name = btf_name_by_offset(btf, param[p].name_off);
+ if (param_name)
+ trace_seq_printf(s, "%s=", param_name);
+ t = btf_type_skip_modifiers(btf, param[p].type, &tid);
+
+ switch (t ? BTF_INFO_KIND(t->info) : BTF_KIND_UNKN) {
+ case BTF_KIND_UNKN:
+ trace_seq_putc(s, '?');
+ /* Still print unknown type values */
+ fallthrough;
+ case BTF_KIND_PTR:
+ trace_seq_printf(s, "0x%lx", arg);
+ break;
+ case BTF_KIND_INT:
+ trace_seq_printf(s, "%ld", arg);
+ break;
+ case BTF_KIND_ENUM:
+ trace_seq_printf(s, "%ld", arg);
+ break;
+ default:
+ /* This does not handle complex arguments */
+ trace_seq_printf(s, "(%s)[0x%lx", btf_type_str(t), arg);
+ for (x = sizeof(long); x < t->size; x += sizeof(long)) {
+ trace_seq_putc(s, ':');
+ if (++a == FTRACE_REGS_MAX_ARGS) {
+ trace_seq_puts(s, "...]");
+ goto out_put;
+ }
+ trace_seq_printf(s, "0x%lx", args[a]);
+ }
+ trace_seq_putc(s, ']');
+ break;
+ }
+ }
+out_put:
+ btf_put(btf);
+out:
+ trace_seq_printf(s, ")");
+}
+#endif
+
/**
* ftrace_find_event - find a registered event
* @type: the type of event to look for
And now I get this as output:
less-912 [006] ...1. 240.085082: timespec64_add_safe(lhs=(STRUCT)[0xef:0x10c8f152], rhs=(STRUCT)[0x4:0x0]) <-__se_sys_poll
less-914 [006] ...1. 241.241416: timespec64_add_safe(lhs=(STRUCT)[0xf0:0x1a1af859], rhs=(STRUCT)[0x4:0x0]) <-__se_sys_poll
less-916 [006] ...1. 242.653586: timespec64_add_safe(lhs=(STRUCT)[0xf1:0x32ac56c9], rhs=(STRUCT)[0x4:0x0]) <-__se_sys_poll
wpa_supplicant-488 [004] ...1. 246.771910: timespec64_add_safe(lhs=(STRUCT)[0xf5:0x39ba39d3], rhs=(STRUCT)[0x9:0x3b9ac618]) <-__se_sys_pselect6
wpa_supplicant-488 [004] ...1. 256.783841: timespec64_add_safe(lhs=(STRUCT)[0xff:0x3a714d62], rhs=(STRUCT)[0xa:0x0]) <-__se_sys_pselect6
NetworkManager-485 [006] ...1. 257.008653: timespec64_add_safe(lhs=(STRUCT)[0x100:0xc3ce7d5], rhs=(STRUCT)[0x0:0x16358818]) <-__se_sys_ppoll
NetworkManager-485 [006] ...1. 257.008676: timespec64_add_safe(lhs=(STRUCT)[0x100:0xc3d477e], rhs=(STRUCT)[0x0:0x16352288]) <-__se_sys_ppoll
NetworkManager-485 [006] ...1. 257.383973: timespec64_add_safe(lhs=(STRUCT)[0x100:0x229be0b6], rhs=(STRUCT)[0x11:0x11c46e70]) <-__se_sys_ppoll
Which looks much more reasonable.
-- Steve
