diff mbox series

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

Message ID 20241223201541.898496620@goodmis.org (mailing list archive)
State New
Headers show
Series ftrace: Add function arguments to function tracers | expand

Checks

Context Check Description
netdev/tree_selection success Not a local patch, async

Commit Message

Steven Rostedt Dec. 23, 2024, 8:13 p.m. UTC 
From: Sven Schnelle <svens@linux.ibm.com>

Add a function to decode argument types with the help of BTF. Will
be used to display arguments in the function and function graph
tracer.

It can only handle simply arguments and up to FTRACE_REGS_MAX_ARGS number
of arguments. When it hits a max, it will print ", ...":

   page_to_skb(vi=0xffff8d53842dc980, rq=0xffff8d53843a0800, page=0xfffffc2e04337c00, offset=6160, len=64, truesize=1536, ...)

And if it hits an argument that is not recognized, it will print the raw
value and the type of argument it is:

   make_vfsuid(idmap=0xffffffff87f99db8, fs_userns=0xffffffff87e543c0, kuid=0x0 (STRUCT))
   __pti_set_user_pgtbl(pgdp=0xffff8d5384ab47f8, pgd=0x110e74067 (STRUCT))

Co-developed-by: Steven Rostedt (Google) <rostedt@goodmis.org>
Signed-off-by: Sven Schnelle <svens@linux.ibm.com>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
Changes since v1: https://lore.kernel.org/20240904065908.1009086-5-svens@linux.ibm.com

 - Added Config option FUNCTION_TRACE_ARGS to this patch
  (unconditional if dependencies are met)

 - Changed the print_function_args() function to take an array of
   unsigned long args and not the ftrace_regs pointer. The ftrace_regs
   should be opaque from generic code.

 - Have the function print the name of an BTF type that is not supported.

 - Added FTRACE_REGS_MAX_ARGS as the number of arguments saved in
   the event and printed out.

 - Print "...," if the number of arguments goes past FTRACE_REGS_MAX_ARGS.

 include/linux/ftrace_regs.h |  5 +++
 kernel/trace/Kconfig        |  6 +++
 kernel/trace/trace_output.c | 78 +++++++++++++++++++++++++++++++++++++
 kernel/trace/trace_output.h |  9 +++++
 4 files changed, 98 insertions(+)

Comments

Steven Rostedt Dec. 23, 2024, 9:36 p.m. UTC | #1 
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
diff mbox series

Patch

diff --git a/include/linux/ftrace_regs.h b/include/linux/ftrace_regs.h
index bbc1873ca6b8..15627ceea9bc 100644
--- a/include/linux/ftrace_regs.h
+++ b/include/linux/ftrace_regs.h
@@ -35,4 +35,9 @@  struct ftrace_regs;
 
 #endif /* HAVE_ARCH_FTRACE_REGS */
 
+/* This can be overridden by the architectures */
+#ifndef FTRACE_REGS_MAX_ARGS
+# define FTRACE_REGS_MAX_ARGS	6
+#endif
+
 #endif /* _LINUX_FTRACE_REGS_H */
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index d570b8b9c0a9..60412c1012ef 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -263,6 +263,12 @@  config FUNCTION_GRAPH_RETADDR
 	  the function is called. This feature is off by default, and you can
 	  enable it via the trace option funcgraph-retaddr.
 
+config FUNCTION_TRACE_ARGS
+       bool
+	depends on HAVE_FUNCTION_ARG_ACCESS_API
+	depends on DEBUG_INFO_BTF
+	default y
+
 config DYNAMIC_FTRACE
 	bool "enable/disable function tracing dynamically"
 	depends on FUNCTION_TRACER
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index da748b7cbc4d..40d6c7a9e0c4 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -12,8 +12,11 @@ 
 #include <linux/sched/clock.h>
 #include <linux/sched/mm.h>
 #include <linux/idr.h>
+#include <linux/btf.h>
+#include <linux/bpf.h>
 
 #include "trace_output.h"
+#include "trace_btf.h"
 
 /* must be a power of 2 */
 #define EVENT_HASHSIZE	128
@@ -680,6 +683,81 @@  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 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));
+			break;
+		}
+		if (i < nr - 1)
+			trace_seq_printf(s, ", ");
+	}
+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
diff --git a/kernel/trace/trace_output.h b/kernel/trace/trace_output.h
index dca40f1f1da4..2e305364f2a9 100644
--- a/kernel/trace/trace_output.h
+++ b/kernel/trace/trace_output.h
@@ -41,5 +41,14 @@  extern struct rw_semaphore trace_event_sem;
 #define SEQ_PUT_HEX_FIELD(s, x)				\
 	trace_seq_putmem_hex(s, &(x), sizeof(x))
 
+#ifdef CONFIG_FUNCTION_TRACE_ARGS
+void print_function_args(struct trace_seq *s, unsigned long *args,
+			 unsigned long func);
+#else
+static inline void print_function_args(struct trace_seq *s, unsigned long *args,
+				       unsigned long func) {
+	trace_seq_puts(s, "()");
+}
+#endif
 #endif