Re: [PATCH v2 1/4] ftrace: Add print_function_args()

[Steven Rostedt <rostedt@goodmis.org>]

On Mon, 23 Dec 2024 15:13:48 -0500
Steven Rostedt <rostedt@goodmis.org> 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