[PATCH v4 0/4] ftrace: Add function arguments to function tracers

[PATCH v4 0/4] ftrace: Add function arguments to function tracers

[Steven Rostedt]

These patches add support for printing function arguments in ftrace.

Example usage:

function tracer:

 ~# cd /sys/kernel/tracing/
 ~# echo icmp_rcv >set_ftrace_filter
 ~# echo function >current_tracer
 ~# echo 1 >options/func-args
 ~# ping -c 10 127.0.0.1
[..]
 ~# cat trace
[..]
            ping-1277    [030] ..s1.    39.120939: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    39.120946: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    40.179724: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    40.179730: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    41.219700: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    41.219706: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    42.259717: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    42.259725: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    43.299735: icmp_rcv(skb=0xa0ecab00) <-ip_protocol_deliver_rcu
            ping-1277    [030] ..s1.    43.299742: icmp_rcv(skb=0xa0ecac00) <-ip_protocol_deliver_rcu

function graph:

 ~# cd /sys/kernel/tracing
 ~# echo icmp_rcv >set_graph_function
 ~# echo function_graph >current_tracer
 ~# echo 1 >options/funcgraph-args

 ~# ping -c 1 127.0.0.1

 ~# cat trace

 30)               |  icmp_rcv(skb=0xa0ecab00) {
 30)               |    __skb_checksum_complete(skb=0xa0ecab00) {
 30)               |      skb_checksum(skb=0xa0ecab00, offset=0, len=64, csum=0) {
 30)               |        __skb_checksum(skb=0xa0ecab00, offset=0, len=64, csum=0, ops=0x232e0327a88) {
 30)   0.418 us    |          csum_partial(buff=0xa0d20924, len=64, sum=0)
 30)   0.985 us    |        }
 30)   1.463 us    |      }
 30)   2.039 us    |    }
[..]

This was last posted by Sven Schnelle here:

  https://lore.kernel.org/all/20240904065908.1009086-1-svens@linux.ibm.com/

As Sven hasn't worked on it since, I decided to continue to push it
through. I'm keeping Sven as original author and added myself as
"Co-developed-by".

Changes since v3: https://lore.kernel.org/linux-trace-kernel/20250225222601.423129938@goodmis.org/

- kernel test robot flagged that this broke builds of archictecuters
  that do not support function args access.
  This was due to missing #ifdefs around calls of functions those archs
  do not implement.

- For archs that do not support function graph tracer, the irqsoff trace
  uses trace_function, but that now has a new parameter.

- Here's the diff between v3 and this series:

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 86d828b9dc7c..cb13c88abfd6 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2895,10 +2895,12 @@ trace_function(struct trace_array *tr, unsigned long ip, unsigned long
 	entry->ip			= ip;
 	entry->parent_ip		= parent_ip;
 
+#ifdef CONFIG_HAVE_FUNCTION_ARG_ACCESS_API
 	if (fregs) {
 		for (int i = 0; i < FTRACE_REGS_MAX_ARGS; i++)
 			entry->args[i] = ftrace_regs_get_argument(fregs, i);
 	}
+#endif
 
 	if (static_branch_unlikely(&trace_function_exports_enabled))
 		ftrace_exports(event, TRACE_EXPORT_FUNCTION);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 472ec5d623db..32da87f45010 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -21,6 +21,7 @@
 #include <linux/workqueue.h>
 #include <linux/ctype.h>
 #include <linux/once_lite.h>
+#include <linux/ftrace_regs.h>
 
 #include "pid_list.h"
 
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 49fcf665cb58..71b2fb068b6b 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -132,10 +132,12 @@ static int __graph_entry(struct trace_array *tr, struct ftrace_graph_ent *trace,
 	entry = ring_buffer_event_data(event);
 	entry->graph_ent = *trace;
 
+#ifdef CONFIG_HAVE_FUNCTION_ARG_ACCESS_API
 	if (fregs) {
 		for (int i = 0; i < FTRACE_REGS_MAX_ARGS; i++)
 			entry->args[i] = ftrace_regs_get_argument(fregs, i);
 	}
+#endif
 
 	trace_buffer_unlock_commit_nostack(buffer, event);
 
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 0ce00fe66d0c..c8bfa7310a91 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -299,7 +299,13 @@ __trace_function(struct trace_array *tr,
 }
 
 #else
-#define __trace_function trace_function
+static inline void
+__trace_function(struct trace_array *tr,
+		 unsigned long ip, unsigned long parent_ip,
+		 unsigned int trace_ctx)
+{
+	return trace_function(tr, ip, parent_ip, trace_ctx, NULL);
+}
 
 static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
 {

Changes since v2: https://lore.kernel.org/linux-trace-kernel/20241223201347.609298489@goodmis.org/

- Removed unneeded headers

- Put back removed '\n' that was accidentally erased.

- Do not use bpf_get_btf_vmlinux() to get btf element as
  btf_find_func_proto() will handle that.

- Fixed how structures are printed

Changes since Sven's work:

- Made the kconfig option unconditional if all the dependencies are set.

- Not save ftrace_regs in the ring buffer, as that is an abstract
  descriptor defined by the architectures and should remain opaque from
  generic code. Instead, the args are read at the time they are recorded
  (with the ftrace_regs passed to the callback function), and saved into
  the ring buffer. Then the print function only takes an array of elements.

  This could allow archs to retrieve arguments that are on the stack where
  as, post processing ftrace_regs could cause undesirable results.

- Made the function and function graph entry events dynamically sized
  to allow the arguments to be appended to the event in the ring buffer.
  The print function only looks to see if the event saved in the ring
  buffer is big enough to hold all the arguments defined by the new
  FTRACE_REGS_MAX_ARGS macro and if so, it will assume there are arguments
  there and print them. This also means user space will not break on
  reading these events as arguments will simply be ignored.

- The printing of the arguments has some more data when things are not
  processed by BPF. Any unsupported argument will have the type printed
  out in the ring buffer. 

- Also removed the spaces around the '=' as that's more in line to how
  trace events show their fields.

- One new patch I added to convert function graph tracing over to using
  args as soon as the user sets the option even if function graph tracing
  is enabled. Function tracer did this already by default.



Steven Rostedt (1):
      ftrace: Have funcgraph-args take affect during tracing

Sven Schnelle (3):
      ftrace: Add print_function_args()
      ftrace: Add support for function argument to graph tracer
      ftrace: Add arguments to function tracer

----
 include/linux/ftrace_regs.h          |   5 +
 kernel/trace/Kconfig                 |  12 +++
 kernel/trace/trace.c                 |  14 ++-
 kernel/trace/trace.h                 |   5 +-
 kernel/trace/trace_entries.h         |  12 ++-
 kernel/trace/trace_functions.c       |  46 +++++++++-
 kernel/trace/trace_functions_graph.c | 172 ++++++++++++++++++++++++++++-------
 kernel/trace/trace_irqsoff.c         |  12 ++-
 kernel/trace/trace_output.c          | 103 ++++++++++++++++++++-
 kernel/trace/trace_output.h          |   9 ++
 kernel/trace/trace_sched_wakeup.c    |   4 +-
 11 files changed, 340 insertions(+), 54 deletions(-)

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

[Steven Rostedt]

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))

Reviewed-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
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>
---
 include/linux/ftrace_regs.h |  5 +++
 kernel/trace/Kconfig        |  6 +++
 kernel/trace/trace_output.c | 85 +++++++++++++++++++++++++++++++++++++
 kernel/trace/trace_output.h |  9 ++++
 4 files changed, 105 insertions(+)

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 03d56f711ad1..4b721cd4f21d 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
@@ -684,6 +687,88 @@ 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;
+
+	/* TODO: Pass module name here too */
+	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
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
 
-- 
2.47.2

[PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

From: Sven Schnelle <svens@linux.ibm.com>

Wire up the code to print function arguments in the function graph
tracer. This functionality can be enabled/disabled during runtime with
options/funcgraph-args.

Example usage:

6)              | dummy_xmit [dummy](skb = 0x8887c100, dev = 0x872ca000) {
6)              |   consume_skb(skb = 0x8887c100) {
6)              |     skb_release_head_state(skb = 0x8887c100) {
6)  0.178 us    |       sock_wfree(skb = 0x8887c100)
6)  0.627 us    |     }

Reviewed-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
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>
---
 kernel/trace/Kconfig                 |   6 ++
 kernel/trace/trace.h                 |   1 +
 kernel/trace/trace_entries.h         |   7 +-
 kernel/trace/trace_functions_graph.c | 145 +++++++++++++++++++++------
 4 files changed, 124 insertions(+), 35 deletions(-)

diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index 60412c1012ef..033fba0633cf 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -268,6 +268,12 @@ config FUNCTION_TRACE_ARGS
 	depends on HAVE_FUNCTION_ARG_ACCESS_API
 	depends on DEBUG_INFO_BTF
 	default y
+	help
+	  If supported with function argument access API and BTF, then
+	  the function tracer and function graph tracer will support printing
+	  of function arguments. This feature is off by default, and can be
+	  enabled via the trace option func-args (for the function tracer) and
+	  funcgraph-args (for the function graph tracer)
 
 config DYNAMIC_FTRACE
 	bool "enable/disable function tracing dynamically"
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 9c21ba45b7af..6963cd83b6da 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -897,6 +897,7 @@ static __always_inline bool ftrace_hash_empty(struct ftrace_hash *hash)
 #define TRACE_GRAPH_PRINT_RETVAL        0x800
 #define TRACE_GRAPH_PRINT_RETVAL_HEX    0x1000
 #define TRACE_GRAPH_PRINT_RETADDR       0x2000
+#define TRACE_GRAPH_ARGS		0x4000
 #define TRACE_GRAPH_PRINT_FILL_SHIFT	28
 #define TRACE_GRAPH_PRINT_FILL_MASK	(0x3 << TRACE_GRAPH_PRINT_FILL_SHIFT)
 
diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h
index fbfb396905a6..77a8ba3bc1e3 100644
--- a/kernel/trace/trace_entries.h
+++ b/kernel/trace/trace_entries.h
@@ -72,17 +72,18 @@ FTRACE_ENTRY_REG(function, ftrace_entry,
 );
 
 /* Function call entry */
-FTRACE_ENTRY_PACKED(funcgraph_entry, ftrace_graph_ent_entry,
+FTRACE_ENTRY(funcgraph_entry, ftrace_graph_ent_entry,
 
 	TRACE_GRAPH_ENT,
 
 	F_STRUCT(
 		__field_struct(	struct ftrace_graph_ent,	graph_ent	)
 		__field_packed(	unsigned long,	graph_ent,	func		)
-		__field_packed(	int,		graph_ent,	depth		)
+		__field_packed(	unsigned long,	graph_ent,	depth		)
+		__dynamic_array(unsigned long,	args				)
 	),
 
-	F_printk("--> %ps (%d)", (void *)__entry->func, __entry->depth)
+	F_printk("--> %ps (%lu)", (void *)__entry->func, __entry->depth)
 );
 
 #ifdef CONFIG_FUNCTION_GRAPH_RETADDR
diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 136c750b0b4d..5049fe25ceef 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -70,6 +70,10 @@ static struct tracer_opt trace_opts[] = {
 #ifdef CONFIG_FUNCTION_GRAPH_RETADDR
 	/* Display function return address ? */
 	{ TRACER_OPT(funcgraph-retaddr, TRACE_GRAPH_PRINT_RETADDR) },
+#endif
+#ifdef CONFIG_FUNCTION_TRACE_ARGS
+	/* Display function arguments ? */
+	{ TRACER_OPT(funcgraph-args, TRACE_GRAPH_ARGS) },
 #endif
 	/* Include sleep time (scheduled out) between entry and return */
 	{ TRACER_OPT(sleep-time, TRACE_GRAPH_SLEEP_TIME) },
@@ -110,25 +114,43 @@ static void
 print_graph_duration(struct trace_array *tr, unsigned long long duration,
 		     struct trace_seq *s, u32 flags);
 
-int __trace_graph_entry(struct trace_array *tr,
-				struct ftrace_graph_ent *trace,
-				unsigned int trace_ctx)
+static int __graph_entry(struct trace_array *tr, struct ftrace_graph_ent *trace,
+			 unsigned int trace_ctx, struct ftrace_regs *fregs)
 {
 	struct ring_buffer_event *event;
 	struct trace_buffer *buffer = tr->array_buffer.buffer;
 	struct ftrace_graph_ent_entry *entry;
+	int size;
 
-	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_ENT,
-					  sizeof(*entry), trace_ctx);
+	/* If fregs is defined, add FTRACE_REGS_MAX_ARGS long size words */
+	size = sizeof(*entry) + (FTRACE_REGS_MAX_ARGS * !!fregs * sizeof(long));
+
+	event = trace_buffer_lock_reserve(buffer, TRACE_GRAPH_ENT, size, trace_ctx);
 	if (!event)
 		return 0;
-	entry	= ring_buffer_event_data(event);
-	entry->graph_ent			= *trace;
+
+	entry = ring_buffer_event_data(event);
+	entry->graph_ent = *trace;
+
+#ifdef CONFIG_HAVE_FUNCTION_ARG_ACCESS_API
+	if (fregs) {
+		for (int i = 0; i < FTRACE_REGS_MAX_ARGS; i++)
+			entry->args[i] = ftrace_regs_get_argument(fregs, i);
+	}
+#endif
+
 	trace_buffer_unlock_commit_nostack(buffer, event);
 
 	return 1;
 }
 
+int __trace_graph_entry(struct trace_array *tr,
+				struct ftrace_graph_ent *trace,
+				unsigned int trace_ctx)
+{
+	return __graph_entry(tr, trace, trace_ctx, NULL);
+}
+
 #ifdef CONFIG_FUNCTION_GRAPH_RETADDR
 int __trace_graph_retaddr_entry(struct trace_array *tr,
 				struct ftrace_graph_ent *trace,
@@ -174,9 +196,9 @@ struct fgraph_times {
 	unsigned long long		sleeptime; /* may be optional! */
 };
 
-int trace_graph_entry(struct ftrace_graph_ent *trace,
-		      struct fgraph_ops *gops,
-		      struct ftrace_regs *fregs)
+static int graph_entry(struct ftrace_graph_ent *trace,
+		       struct fgraph_ops *gops,
+		       struct ftrace_regs *fregs)
 {
 	unsigned long *task_var = fgraph_get_task_var(gops);
 	struct trace_array *tr = gops->private;
@@ -246,7 +268,7 @@ int trace_graph_entry(struct ftrace_graph_ent *trace,
 			unsigned long retaddr = ftrace_graph_top_ret_addr(current);
 			ret = __trace_graph_retaddr_entry(tr, trace, trace_ctx, retaddr);
 		} else {
-			ret = __trace_graph_entry(tr, trace, trace_ctx);
+			ret = __graph_entry(tr, trace, trace_ctx, fregs);
 		}
 	}
 	preempt_enable_notrace();
@@ -254,6 +276,20 @@ int trace_graph_entry(struct ftrace_graph_ent *trace,
 	return ret;
 }
 
+int trace_graph_entry(struct ftrace_graph_ent *trace,
+		      struct fgraph_ops *gops,
+		      struct ftrace_regs *fregs)
+{
+	return graph_entry(trace, gops, NULL);
+}
+
+static int trace_graph_entry_args(struct ftrace_graph_ent *trace,
+				  struct fgraph_ops *gops,
+				  struct ftrace_regs *fregs)
+{
+	return graph_entry(trace, gops, fregs);
+}
+
 static void
 __trace_graph_function(struct trace_array *tr,
 		unsigned long ip, unsigned int trace_ctx)
@@ -418,7 +454,10 @@ static int graph_trace_init(struct trace_array *tr)
 {
 	int ret;
 
-	tr->gops->entryfunc = trace_graph_entry;
+	if (tracer_flags_is_set(TRACE_GRAPH_ARGS))
+		tr->gops->entryfunc = trace_graph_entry_args;
+	else
+		tr->gops->entryfunc = trace_graph_entry;
 
 	if (tracing_thresh)
 		tr->gops->retfunc = trace_graph_thresh_return;
@@ -775,7 +814,7 @@ static void print_graph_retaddr(struct trace_seq *s, struct fgraph_retaddr_ent_e
 
 static void print_graph_retval(struct trace_seq *s, struct ftrace_graph_ent_entry *entry,
 				struct ftrace_graph_ret *graph_ret, void *func,
-				u32 opt_flags, u32 trace_flags)
+				u32 opt_flags, u32 trace_flags, int args_size)
 {
 	unsigned long err_code = 0;
 	unsigned long retval = 0;
@@ -809,7 +848,14 @@ static void print_graph_retval(struct trace_seq *s, struct ftrace_graph_ent_entr
 		if (entry->ent.type != TRACE_GRAPH_RETADDR_ENT)
 			print_retaddr = false;
 
-		trace_seq_printf(s, "%ps();", func);
+		trace_seq_printf(s, "%ps", func);
+
+		if (args_size >= FTRACE_REGS_MAX_ARGS * sizeof(long)) {
+			print_function_args(s, entry->args, (unsigned long)func);
+			trace_seq_putc(s, ';');
+		} else
+			trace_seq_puts(s, "();");
+
 		if (print_retval || print_retaddr)
 			trace_seq_puts(s, " /*");
 		else
@@ -836,7 +882,8 @@ static void print_graph_retval(struct trace_seq *s, struct ftrace_graph_ent_entr
 
 #else
 
-#define print_graph_retval(_seq, _ent, _ret, _func, _opt_flags, _trace_flags) do {} while (0)
+#define print_graph_retval(_seq, _ent, _ret, _func, _opt_flags, _trace_flags, args_size) \
+	do {} while (0)
 
 #endif
 
@@ -852,10 +899,14 @@ print_graph_entry_leaf(struct trace_iterator *iter,
 	struct ftrace_graph_ret *graph_ret;
 	struct ftrace_graph_ent *call;
 	unsigned long long duration;
+	unsigned long ret_func;
 	unsigned long func;
+	int args_size;
 	int cpu = iter->cpu;
 	int i;
 
+	args_size = iter->ent_size - offsetof(struct ftrace_graph_ent_entry, args);
+
 	graph_ret = &ret_entry->ret;
 	call = &entry->graph_ent;
 	duration = ret_entry->rettime - ret_entry->calltime;
@@ -887,16 +938,25 @@ print_graph_entry_leaf(struct trace_iterator *iter,
 	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++)
 		trace_seq_putc(s, ' ');
 
+	ret_func = graph_ret->func + iter->tr->text_delta;
+
 	/*
 	 * Write out the function return value or return address
 	 */
 	if (flags & (__TRACE_GRAPH_PRINT_RETVAL | __TRACE_GRAPH_PRINT_RETADDR)) {
 		print_graph_retval(s, entry, graph_ret,
 				   (void *)graph_ret->func + iter->tr->text_delta,
-				   flags, tr->trace_flags);
+				   flags, tr->trace_flags, args_size);
 	} else {
-		trace_seq_printf(s, "%ps();\n", (void *)func);
+		trace_seq_printf(s, "%ps", (void *)ret_func);
+
+		if (args_size >= FTRACE_REGS_MAX_ARGS * sizeof(long)) {
+			print_function_args(s, entry->args, ret_func);
+			trace_seq_putc(s, ';');
+		} else
+			trace_seq_puts(s, "();");
 	}
+	trace_seq_printf(s, "\n");
 
 	print_graph_irq(iter, graph_ret->func, TRACE_GRAPH_RET,
 			cpu, iter->ent->pid, flags);
@@ -913,6 +973,7 @@ print_graph_entry_nested(struct trace_iterator *iter,
 	struct fgraph_data *data = iter->private;
 	struct trace_array *tr = iter->tr;
 	unsigned long func;
+	int args_size;
 	int i;
 
 	if (data) {
@@ -937,7 +998,17 @@ print_graph_entry_nested(struct trace_iterator *iter,
 
 	func = call->func + iter->tr->text_delta;
 
-	trace_seq_printf(s, "%ps() {", (void *)func);
+	trace_seq_printf(s, "%ps", (void *)func);
+
+	args_size = iter->ent_size - offsetof(struct ftrace_graph_ent_entry, args);
+
+	if (args_size >= FTRACE_REGS_MAX_ARGS * sizeof(long))
+		print_function_args(s, entry->args, func);
+	else
+		trace_seq_puts(s, "()");
+
+	trace_seq_puts(s, " {");
+
 	if (flags & __TRACE_GRAPH_PRINT_RETADDR  &&
 		entry->ent.type == TRACE_GRAPH_RETADDR_ENT)
 		print_graph_retaddr(s, (struct fgraph_retaddr_ent_entry *)entry,
@@ -1107,21 +1178,38 @@ print_graph_entry(struct ftrace_graph_ent_entry *field, struct trace_seq *s,
 			struct trace_iterator *iter, u32 flags)
 {
 	struct fgraph_data *data = iter->private;
-	struct ftrace_graph_ent *call = &field->graph_ent;
+	struct ftrace_graph_ent *call;
 	struct ftrace_graph_ret_entry *leaf_ret;
 	static enum print_line_t ret;
 	int cpu = iter->cpu;
+	/*
+	 * print_graph_entry() may consume the current event,
+	 * thus @field may become invalid, so we need to save it.
+	 * sizeof(struct ftrace_graph_ent_entry) is very small,
+	 * it can be safely saved at the stack.
+	 */
+	struct ftrace_graph_ent_entry *entry;
+	u8 save_buf[sizeof(*entry) + FTRACE_REGS_MAX_ARGS * sizeof(long)];
+
+	/* The ent_size is expected to be as big as the entry */
+	if (iter->ent_size > sizeof(save_buf))
+		iter->ent_size = sizeof(save_buf);
+
+	entry = (void *)save_buf;
+	memcpy(entry, field, iter->ent_size);
+
+	call = &entry->graph_ent;
 
 	if (check_irq_entry(iter, flags, call->func, call->depth))
 		return TRACE_TYPE_HANDLED;
 
 	print_graph_prologue(iter, s, TRACE_GRAPH_ENT, call->func, flags);
 
-	leaf_ret = get_return_for_leaf(iter, field);
+	leaf_ret = get_return_for_leaf(iter, entry);
 	if (leaf_ret)
-		ret = print_graph_entry_leaf(iter, field, leaf_ret, s, flags);
+		ret = print_graph_entry_leaf(iter, entry, leaf_ret, s, flags);
 	else
-		ret = print_graph_entry_nested(iter, field, s, cpu, flags);
+		ret = print_graph_entry_nested(iter, entry, s, cpu, flags);
 
 	if (data) {
 		/*
@@ -1195,7 +1283,8 @@ print_graph_return(struct ftrace_graph_ret_entry *retentry, struct trace_seq *s,
 	 * funcgraph-retval option is enabled.
 	 */
 	if (flags & __TRACE_GRAPH_PRINT_RETVAL) {
-		print_graph_retval(s, NULL, trace, (void *)func, flags, tr->trace_flags);
+		print_graph_retval(s, NULL, trace, (void *)func, flags,
+				   tr->trace_flags, 0);
 	} else {
 		/*
 		 * If the return function does not have a matching entry,
@@ -1323,16 +1412,8 @@ print_graph_function_flags(struct trace_iterator *iter, u32 flags)
 
 	switch (entry->type) {
 	case TRACE_GRAPH_ENT: {
-		/*
-		 * print_graph_entry() may consume the current event,
-		 * thus @field may become invalid, so we need to save it.
-		 * sizeof(struct ftrace_graph_ent_entry) is very small,
-		 * it can be safely saved at the stack.
-		 */
-		struct ftrace_graph_ent_entry saved;
 		trace_assign_type(field, entry);
-		saved = *field;
-		return print_graph_entry(&saved, s, iter, flags);
+		return print_graph_entry(field, s, iter, flags);
 	}
 #ifdef CONFIG_FUNCTION_GRAPH_RETADDR
 	case TRACE_GRAPH_RETADDR_ENT: {
-- 
2.47.2

[PATCH v4 3/4] ftrace: Have funcgraph-args take affect during tracing

[Steven Rostedt]

From: Steven Rostedt <rostedt@goodmis.org>

Currently, when function_graph is started, it looks at the option
funcgraph-args, and if it is set, it will enable tracing of the arguments.

But if tracing is already running, and the user enables funcgraph-args, it
will have no effect. Instead, it should enable argument tracing when it is
enabled, even if it means disabling the function graph tracing for a short
time in order to do the transition.

Acked-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
---
 kernel/trace/trace_functions_graph.c | 27 ++++++++++++++++++++++++++-
 1 file changed, 26 insertions(+), 1 deletion(-)

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 5049fe25ceef..71b2fb068b6b 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -464,7 +464,7 @@ static int graph_trace_init(struct trace_array *tr)
 	else
 		tr->gops->retfunc = trace_graph_return;
 
-	/* Make gops functions are visible before we start tracing */
+	/* Make gops functions visible before we start tracing */
 	smp_mb();
 
 	ret = register_ftrace_graph(tr->gops);
@@ -475,6 +475,28 @@ static int graph_trace_init(struct trace_array *tr)
 	return 0;
 }
 
+static int ftrace_graph_trace_args(struct trace_array *tr, int set)
+{
+	trace_func_graph_ent_t entry;
+
+	if (set)
+		entry = trace_graph_entry_args;
+	else
+		entry = trace_graph_entry;
+
+	/* See if there's any changes */
+	if (tr->gops->entryfunc == entry)
+		return 0;
+
+	unregister_ftrace_graph(tr->gops);
+
+	tr->gops->entryfunc = entry;
+
+	/* Make gops functions visible before we start tracing */
+	smp_mb();
+	return register_ftrace_graph(tr->gops);
+}
+
 static void graph_trace_reset(struct trace_array *tr)
 {
 	tracing_stop_cmdline_record();
@@ -1607,6 +1629,9 @@ func_graph_set_flag(struct trace_array *tr, u32 old_flags, u32 bit, int set)
 	if (bit == TRACE_GRAPH_GRAPH_TIME)
 		ftrace_graph_graph_time_control(set);
 
+	if (bit == TRACE_GRAPH_ARGS)
+		return ftrace_graph_trace_args(tr, set);
+
 	return 0;
 }
 
-- 
2.47.2

[PATCH v4 4/4] ftrace: Add arguments to function tracer

[Steven Rostedt]

From: Sven Schnelle <svens@linux.ibm.com>

Wire up the code to print function arguments in the function tracer.
This functionality can be enabled/disabled during runtime with
options/func-args.

        ping-689     [004] b....    77.170220: dummy_xmit(skb = 0x82904800, dev = 0x882d0000) <-dev_hard_start_xmit

Reviewed-by: Masami Hiramatsu (Google) <mhiramat@kernel.org>
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>
---
 kernel/trace/trace.c              | 14 ++++++++--
 kernel/trace/trace.h              |  4 ++-
 kernel/trace/trace_entries.h      |  5 ++--
 kernel/trace/trace_functions.c    | 46 +++++++++++++++++++++++++++----
 kernel/trace/trace_irqsoff.c      | 12 ++++++--
 kernel/trace/trace_output.c       | 18 ++++++++++--
 kernel/trace/trace_sched_wakeup.c |  4 +--
 7 files changed, 85 insertions(+), 18 deletions(-)

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index 0e6d517e74e0..cb13c88abfd6 100644
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -2878,13 +2878,16 @@ trace_buffer_unlock_commit_nostack(struct trace_buffer *buffer,
 
 void
 trace_function(struct trace_array *tr, unsigned long ip, unsigned long
-	       parent_ip, unsigned int trace_ctx)
+	       parent_ip, unsigned int trace_ctx, struct ftrace_regs *fregs)
 {
 	struct trace_buffer *buffer = tr->array_buffer.buffer;
 	struct ring_buffer_event *event;
 	struct ftrace_entry *entry;
+	int size = sizeof(*entry);
 
-	event = __trace_buffer_lock_reserve(buffer, TRACE_FN, sizeof(*entry),
+	size += FTRACE_REGS_MAX_ARGS * !!fregs * sizeof(long);
+
+	event = __trace_buffer_lock_reserve(buffer, TRACE_FN, size,
 					    trace_ctx);
 	if (!event)
 		return;
@@ -2892,6 +2895,13 @@ trace_function(struct trace_array *tr, unsigned long ip, unsigned long
 	entry->ip			= ip;
 	entry->parent_ip		= parent_ip;
 
+#ifdef CONFIG_HAVE_FUNCTION_ARG_ACCESS_API
+	if (fregs) {
+		for (int i = 0; i < FTRACE_REGS_MAX_ARGS; i++)
+			entry->args[i] = ftrace_regs_get_argument(fregs, i);
+	}
+#endif
+
 	if (static_branch_unlikely(&trace_function_exports_enabled))
 		ftrace_exports(event, TRACE_EXPORT_FUNCTION);
 	__buffer_unlock_commit(buffer, event);
diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 6963cd83b6da..32da87f45010 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -21,6 +21,7 @@
 #include <linux/workqueue.h>
 #include <linux/ctype.h>
 #include <linux/once_lite.h>
+#include <linux/ftrace_regs.h>
 
 #include "pid_list.h"
 
@@ -697,7 +698,8 @@ unsigned long trace_total_entries(struct trace_array *tr);
 void trace_function(struct trace_array *tr,
 		    unsigned long ip,
 		    unsigned long parent_ip,
-		    unsigned int trace_ctx);
+		    unsigned int trace_ctx,
+		    struct ftrace_regs *regs);
 void trace_graph_function(struct trace_array *tr,
 		    unsigned long ip,
 		    unsigned long parent_ip,
diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h
index 77a8ba3bc1e3..ee40d4e6ad1c 100644
--- a/kernel/trace/trace_entries.h
+++ b/kernel/trace/trace_entries.h
@@ -61,8 +61,9 @@ FTRACE_ENTRY_REG(function, ftrace_entry,
 	TRACE_FN,
 
 	F_STRUCT(
-		__field_fn(	unsigned long,	ip		)
-		__field_fn(	unsigned long,	parent_ip	)
+		__field_fn(	unsigned long,		ip		)
+		__field_fn(	unsigned long,		parent_ip	)
+		__dynamic_array( unsigned long,		args		)
 	),
 
 	F_printk(" %ps <-- %ps",
diff --git a/kernel/trace/trace_functions.c b/kernel/trace/trace_functions.c
index df56f9b76010..98ccf3f00c51 100644
--- a/kernel/trace/trace_functions.c
+++ b/kernel/trace/trace_functions.c
@@ -25,6 +25,9 @@ static void
 function_trace_call(unsigned long ip, unsigned long parent_ip,
 		    struct ftrace_ops *op, struct ftrace_regs *fregs);
 static void
+function_args_trace_call(unsigned long ip, unsigned long parent_ip,
+			 struct ftrace_ops *op, struct ftrace_regs *fregs);
+static void
 function_stack_trace_call(unsigned long ip, unsigned long parent_ip,
 			  struct ftrace_ops *op, struct ftrace_regs *fregs);
 static void
@@ -42,9 +45,10 @@ enum {
 	TRACE_FUNC_NO_OPTS		= 0x0, /* No flags set. */
 	TRACE_FUNC_OPT_STACK		= 0x1,
 	TRACE_FUNC_OPT_NO_REPEATS	= 0x2,
+	TRACE_FUNC_OPT_ARGS		= 0x4,
 
 	/* Update this to next highest bit. */
-	TRACE_FUNC_OPT_HIGHEST_BIT	= 0x4
+	TRACE_FUNC_OPT_HIGHEST_BIT	= 0x8
 };
 
 #define TRACE_FUNC_OPT_MASK	(TRACE_FUNC_OPT_HIGHEST_BIT - 1)
@@ -114,6 +118,8 @@ static ftrace_func_t select_trace_function(u32 flags_val)
 	switch (flags_val & TRACE_FUNC_OPT_MASK) {
 	case TRACE_FUNC_NO_OPTS:
 		return function_trace_call;
+	case TRACE_FUNC_OPT_ARGS:
+		return function_args_trace_call;
 	case TRACE_FUNC_OPT_STACK:
 		return function_stack_trace_call;
 	case TRACE_FUNC_OPT_NO_REPEATS:
@@ -220,7 +226,34 @@ function_trace_call(unsigned long ip, unsigned long parent_ip,
 
 	data = this_cpu_ptr(tr->array_buffer.data);
 	if (!atomic_read(&data->disabled))
-		trace_function(tr, ip, parent_ip, trace_ctx);
+		trace_function(tr, ip, parent_ip, trace_ctx, NULL);
+
+	ftrace_test_recursion_unlock(bit);
+}
+
+static void
+function_args_trace_call(unsigned long ip, unsigned long parent_ip,
+			 struct ftrace_ops *op, struct ftrace_regs *fregs)
+{
+	struct trace_array *tr = op->private;
+	struct trace_array_cpu *data;
+	unsigned int trace_ctx;
+	int bit;
+	int cpu;
+
+	if (unlikely(!tr->function_enabled))
+		return;
+
+	bit = ftrace_test_recursion_trylock(ip, parent_ip);
+	if (bit < 0)
+		return;
+
+	trace_ctx = tracing_gen_ctx();
+
+	cpu = smp_processor_id();
+	data = per_cpu_ptr(tr->array_buffer.data, cpu);
+	if (!atomic_read(&data->disabled))
+		trace_function(tr, ip, parent_ip, trace_ctx, fregs);
 
 	ftrace_test_recursion_unlock(bit);
 }
@@ -270,7 +303,7 @@ 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);
+		trace_function(tr, ip, parent_ip, trace_ctx, NULL);
 #ifdef CONFIG_UNWINDER_FRAME_POINTER
 		if (ftrace_pids_enabled(op))
 			skip++;
@@ -349,7 +382,7 @@ function_no_repeats_trace_call(unsigned long ip, unsigned long parent_ip,
 	trace_ctx = tracing_gen_ctx_dec();
 	process_repeats(tr, ip, parent_ip, last_info, trace_ctx);
 
-	trace_function(tr, ip, parent_ip, trace_ctx);
+	trace_function(tr, ip, parent_ip, trace_ctx, NULL);
 
 out:
 	ftrace_test_recursion_unlock(bit);
@@ -389,7 +422,7 @@ function_stack_no_repeats_trace_call(unsigned long ip, unsigned long parent_ip,
 		trace_ctx = tracing_gen_ctx_flags(flags);
 		process_repeats(tr, ip, parent_ip, last_info, trace_ctx);
 
-		trace_function(tr, ip, parent_ip, trace_ctx);
+		trace_function(tr, ip, parent_ip, trace_ctx, NULL);
 		__trace_stack(tr, trace_ctx, STACK_SKIP);
 	}
 
@@ -403,6 +436,9 @@ static struct tracer_opt func_opts[] = {
 	{ TRACER_OPT(func_stack_trace, TRACE_FUNC_OPT_STACK) },
 #endif
 	{ TRACER_OPT(func-no-repeats, TRACE_FUNC_OPT_NO_REPEATS) },
+#ifdef CONFIG_FUNCTION_TRACE_ARGS
+	{ TRACER_OPT(func-args, TRACE_FUNC_OPT_ARGS) },
+#endif
 	{ } /* Always set a last empty entry */
 };
 
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index 7294ad676379..c8bfa7310a91 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -150,7 +150,7 @@ irqsoff_tracer_call(unsigned long ip, unsigned long parent_ip,
 
 	trace_ctx = tracing_gen_ctx_flags(flags);
 
-	trace_function(tr, ip, parent_ip, trace_ctx);
+	trace_function(tr, ip, parent_ip, trace_ctx, fregs);
 
 	atomic_dec(&data->disabled);
 }
@@ -295,11 +295,17 @@ __trace_function(struct trace_array *tr,
 	if (is_graph(tr))
 		trace_graph_function(tr, ip, parent_ip, trace_ctx);
 	else
-		trace_function(tr, ip, parent_ip, trace_ctx);
+		trace_function(tr, ip, parent_ip, trace_ctx, NULL);
 }
 
 #else
-#define __trace_function trace_function
+static inline void
+__trace_function(struct trace_array *tr,
+		 unsigned long ip, unsigned long parent_ip,
+		 unsigned int trace_ctx)
+{
+	return trace_function(tr, ip, parent_ip, trace_ctx, NULL);
+}
 
 static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
 {
diff --git a/kernel/trace/trace_output.c b/kernel/trace/trace_output.c
index 4b721cd4f21d..b51ee9373773 100644
--- a/kernel/trace/trace_output.c
+++ b/kernel/trace/trace_output.c
@@ -1090,12 +1090,15 @@ enum print_line_t trace_nop_print(struct trace_iterator *iter, int flags,
 }
 
 static void print_fn_trace(struct trace_seq *s, unsigned long ip,
-			   unsigned long parent_ip, long delta, int flags)
+			   unsigned long parent_ip, long delta,
+			   unsigned long *args, int flags)
 {
 	ip += delta;
 	parent_ip += delta;
 
 	seq_print_ip_sym(s, ip, flags);
+	if (args)
+		print_function_args(s, args, ip);
 
 	if ((flags & TRACE_ITER_PRINT_PARENT) && parent_ip) {
 		trace_seq_puts(s, " <-");
@@ -1109,10 +1112,19 @@ static enum print_line_t trace_fn_trace(struct trace_iterator *iter, int flags,
 {
 	struct ftrace_entry *field;
 	struct trace_seq *s = &iter->seq;
+	unsigned long *args;
+	int args_size;
 
 	trace_assign_type(field, iter->ent);
 
-	print_fn_trace(s, field->ip, field->parent_ip, iter->tr->text_delta, flags);
+	args_size = iter->ent_size - offsetof(struct ftrace_entry, args);
+	if (args_size >= FTRACE_REGS_MAX_ARGS * sizeof(long))
+		args = field->args;
+	else
+		args = NULL;
+
+	print_fn_trace(s, field->ip, field->parent_ip, iter->tr->text_delta,
+		       args, flags);
 	trace_seq_putc(s, '\n');
 
 	return trace_handle_return(s);
@@ -1785,7 +1797,7 @@ trace_func_repeats_print(struct trace_iterator *iter, int flags,
 
 	trace_assign_type(field, iter->ent);
 
-	print_fn_trace(s, field->ip, field->parent_ip, iter->tr->text_delta, flags);
+	print_fn_trace(s, field->ip, field->parent_ip, iter->tr->text_delta, NULL, flags);
 	trace_seq_printf(s, " (repeats: %u, last_ts:", field->count);
 	trace_print_time(s, iter,
 			 iter->ts - FUNC_REPEATS_GET_DELTA_TS(field));
diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c
index af30586f1aea..c9ba4259e03e 100644
--- a/kernel/trace/trace_sched_wakeup.c
+++ b/kernel/trace/trace_sched_wakeup.c
@@ -242,7 +242,7 @@ wakeup_tracer_call(unsigned long ip, unsigned long parent_ip,
 		return;
 
 	local_irq_save(flags);
-	trace_function(tr, ip, parent_ip, trace_ctx);
+	trace_function(tr, ip, parent_ip, trace_ctx, fregs);
 	local_irq_restore(flags);
 
 	atomic_dec(&data->disabled);
@@ -327,7 +327,7 @@ __trace_function(struct trace_array *tr,
 	if (is_graph(tr))
 		trace_graph_function(tr, ip, parent_ip, trace_ctx);
 	else
-		trace_function(tr, ip, parent_ip, trace_ctx);
+		trace_function(tr, ip, parent_ip, trace_ctx, NULL);
 }
 
 static int wakeup_flag_changed(struct trace_array *tr, u32 mask, int set)
-- 
2.47.2

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Mark Brown]

[-- Attachment #1: Type: text/plain, Size: 5446 bytes --]

On Thu, Feb 27, 2025 at 01:58:06PM -0500, Steven Rostedt wrote:
> From: Sven Schnelle <svens@linux.ibm.com>
> 
> Wire up the code to print function arguments in the function graph
> tracer. This functionality can be enabled/disabled during runtime with
> options/funcgraph-args.

We've been seeing the PID filters selftest failing for a while on
several arm64 systems, a bisect I managed to run without running into
any confounding issues pointed to this patch which is in mainline as
ff5c9c576e75.  It's in the ftrace code, but I'm not immediately seeing
the relevance.  Output from a failing run:

 6190 18:38:41.261255  # not ok 48 ftrace - function pid filters
 6191 18:38:41.274039  # # execute: /lava-922575/1/tests/2_kselftest-ftrace/automated/linux/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc
 6192 18:38:41.285261  # # + checkreq /lava-922575/1/tests/2_kselftest-ftrace/automated/linux/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc
 6193 18:38:41.296551  # # + grep ^#[ t]*requires: /lava-922575/1/tests/2_kselftest-ftrace/automated/linux/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc
 6194 18:38:41.307877  # # + cut -f2- -d:
 6195 18:38:41.308157  # # + requires= set_ftrace_pid set_ftrace_filter function:tracer
 6196 18:38:41.319397  # # + eval check_requires  set_ftrace_pid set_ftrace_filter function:tracer
 6197 18:38:41.319681  # # + check_requires set_ftrace_pid set_ftrace_filter function:tracer
 6198 18:38:41.319905  # # + p=set_ftrace_pid
 6199 18:38:41.330653  # # + r=set_ftrace_pid
 6200 18:38:41.330936  # # + t=set_ftrace_pid
 6201 18:38:41.331161  # # + [ set_ftrace_pid != set_ftrace_pid ]
 6202 18:38:41.331367  # # + [ set_ftrace_pid != set_ftrace_pid ]
 6203 18:38:41.342045  # # + [ set_ftrace_pid != set_ftrace_pid ]
 6204 18:38:41.342330  # # + [ ! -e set_ftrace_pid ]
 .......
 6364 18:39:15.411636  # # + grep -v 7190
 6365 18:39:15.411865  # # + wc -l
 6366 18:39:15.412073  # # + count_other=3
 6367 18:39:15.412554  # # + [ 2 -eq 0 -o 3 -ne 0 ]
 6368 18:39:15.412773  # # + fail PID filtering not working?
 6369 18:39:15.422776  # # + do_reset
 6370 18:39:15.423055  # # + [ 1 -eq 1 ]
 6371 18:39:15.423278  # # + echo nofunction-fork
 6372 18:39:15.423485  # # + [ 1 -eq 1 ]
 6373 18:39:15.423681  # # + echo 0
 6374 18:39:15.423873  # # + echo PID filtering not working?
 6375 18:39:15.434095  # # PID filtering not working?
 6376 18:39:15.434377  # # + exit_fail
 6377 18:39:15.434602  # # + exit 1

bisect log:

git bisect start
# status: waiting for both good and bad commits
# good: [38fec10eb60d687e30c8c6b5420d86e8149f7557] Linux 6.14
git bisect good 38fec10eb60d687e30c8c6b5420d86e8149f7557
# status: waiting for bad commit, 1 good commit known
# bad: [46086739de22d72319e37c37a134d32db52e1c5c] Add linux-next specific files for 20250409
git bisect bad 46086739de22d72319e37c37a134d32db52e1c5c
# bad: [390513642ee6763c7ada07f0a1470474986e6c1c] io_uring: always do atomic put from iowq
git bisect bad 390513642ee6763c7ada07f0a1470474986e6c1c
# good: [9b960d8cd6f712cb2c03e2bdd4d5ca058238037f] Merge tag 'for-6.15/block-20250322' of git://git.kernel.dk/linux
git bisect good 9b960d8cd6f712cb2c03e2bdd4d5ca058238037f
# good: [023b1e9d265ca0662111a9df23d22b4632717a8a] Merge git://git.kernel.org/pub/scm/linux/kernel/git/netdev/net
git bisect good 023b1e9d265ca0662111a9df23d22b4632717a8a
# good: [3a90a72aca0a98125f0c7350ffb7cc63665f8047] Merge tag 'asm-generic-6.15-2' of git://git.kernel.org/pub/scm/linux/kernel/git/arnd/asm-generic
git bisect good 3a90a72aca0a98125f0c7350ffb7cc63665f8047
# good: [4a4b30ea80d8cb5e8c4c62bb86201f4ea0d9b030] Merge tag 'bcachefs-2025-03-24' of git://evilpiepirate.org/bcachefs
git bisect good 4a4b30ea80d8cb5e8c4c62bb86201f4ea0d9b030
# bad: [a7e135fe59a516b2a981fc5820e7a1e2118b427e] Merge tag 'probes-v6.15' of git://git.kernel.org/pub/scm/linux/kernel/git/trace/linux-trace
git bisect bad a7e135fe59a516b2a981fc5820e7a1e2118b427e
# bad: [31eb415bf6f06c90fdd9b635caf3a6c5110a38b6] Merge tag 'ftrace-v6.15' of git://git.kernel.org/pub/scm/linux/kernel/git/trace/linux-trace
git bisect bad 31eb415bf6f06c90fdd9b635caf3a6c5110a38b6
# good: [e8eac9fc4832976af800628ba8cbd351edc7f841] ext4: remove unneeded forward declaration in namei.c
git bisect good e8eac9fc4832976af800628ba8cbd351edc7f841
# good: [129245cfbd6d79c6d603f357f428010ccc0f0ee7] ext4: correct the error handle in ext4_fallocate()
git bisect good 129245cfbd6d79c6d603f357f428010ccc0f0ee7
# good: [dc208c69c033d3caba0509da1ae065d2b5ff165f] scripts/sorttable: Allow matches to functions before function entry
git bisect good dc208c69c033d3caba0509da1ae065d2b5ff165f
# bad: [5ba8f4a39ecd160c7b6ef8ef1373375799710a97] function_graph: Remove the unused variable func
git bisect bad 5ba8f4a39ecd160c7b6ef8ef1373375799710a97
# good: [533c20b062d7c25cbcbadb31e3ecb95a08ddb877] ftrace: Add print_function_args()
git bisect good 533c20b062d7c25cbcbadb31e3ecb95a08ddb877
# bad: [c7a60a733c373eed0094774c141bf2934237e7ff] ftrace: Have funcgraph-args take affect during tracing
git bisect bad c7a60a733c373eed0094774c141bf2934237e7ff
# bad: [ff5c9c576e754563b3be4922c3968bc3b0269541] ftrace: Add support for function argument to graph tracer
git bisect bad ff5c9c576e754563b3be4922c3968bc3b0269541
# first bad commit: [ff5c9c576e754563b3be4922c3968bc3b0269541] ftrace: Add support for function argument to graph tracer

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Wed, 9 Apr 2025 23:34:16 +0100
Mark Brown <broonie@kernel.org> wrote:

> We've been seeing the PID filters selftest failing for a while on
> several arm64 systems, a bisect I managed to run without running into
> any confounding issues pointed to this patch which is in mainline as
> ff5c9c576e75.  It's in the ftrace code, but I'm not immediately seeing
> the relevance.  Output from a failing run:
> 
>  6190 18:38:41.261255  # not ok 48 ftrace - function pid filters
>  6191 18:38:41.274039  # # execute: /lava-922575/1/tests/2_kselftest-ftrace/automated/linux/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc
>  6192 18:38:41.285261  # # + checkreq /lava-922575/1/tests/2_kselftest-ftrace/automated/linux/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc
>  6193 18:38:41.296551  # # + grep ^#[ t]*requires: /lava-922575/1/tests/2_kselftest-ftrace/automated/linux/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc
>  6194 18:38:41.307877  # # + cut -f2- -d:
>  6195 18:38:41.308157  # # + requires= set_ftrace_pid set_ftrace_filter function:tracer
>  6196 18:38:41.319397  # # + eval check_requires  set_ftrace_pid set_ftrace_filter function:tracer
>  6197 18:38:41.319681  # # + check_requires set_ftrace_pid set_ftrace_filter function:tracer
>  6198 18:38:41.319905  # # + p=set_ftrace_pid
>  6199 18:38:41.330653  # # + r=set_ftrace_pid
>  6200 18:38:41.330936  # # + t=set_ftrace_pid
>  6201 18:38:41.331161  # # + [ set_ftrace_pid != set_ftrace_pid ]
>  6202 18:38:41.331367  # # + [ set_ftrace_pid != set_ftrace_pid ]
>  6203 18:38:41.342045  # # + [ set_ftrace_pid != set_ftrace_pid ]
>  6204 18:38:41.342330  # # + [ ! -e set_ftrace_pid ]
>  .......
>  6364 18:39:15.411636  # # + grep -v 7190
>  6365 18:39:15.411865  # # + wc -l
>  6366 18:39:15.412073  # # + count_other=3
>  6367 18:39:15.412554  # # + [ 2 -eq 0 -o 3 -ne 0 ]
>  6368 18:39:15.412773  # # + fail PID filtering not working?
>  6369 18:39:15.422776  # # + do_reset
>  6370 18:39:15.423055  # # + [ 1 -eq 1 ]
>  6371 18:39:15.423278  # # + echo nofunction-fork
>  6372 18:39:15.423485  # # + [ 1 -eq 1 ]
>  6373 18:39:15.423681  # # + echo 0
>  6374 18:39:15.423873  # # + echo PID filtering not working?
>  6375 18:39:15.434095  # # PID filtering not working?
>  6376 18:39:15.434377  # # + exit_fail
>  6377 18:39:15.434602  # # + exit 1

Hmm, I wonder if there's junk being added into the trace.

Can you add this patch, and show me the output when it fails again?

-- Steve

diff --git a/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc b/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc
index 8dcce001881d..0699ec6d7554 100644
--- a/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc
+++ b/tools/testing/selftests/ftrace/test.d/ftrace/func-filter-pid.tc
@@ -72,6 +72,7 @@ do_test() {
 
     # count_other should be 0
     if [ $count_pid -eq 0 -o $count_other -ne 0 ]; then
+	cat trace
 	fail "PID filtering not working?"
     fi
 
@@ -79,6 +80,7 @@ do_test() {
     clear_trace
 
     if [ $do_function_fork -eq 0 ]; then
+	cat trace
 	return
     fi
 
@@ -93,6 +95,7 @@ do_test() {
 
     # count_other should NOT be 0
     if [ $count_pid -eq 0 -o $count_other -eq 0 ]; then
+	cat trace
 	fail "PID filtering not following fork?"
     fi
 }

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Mark Brown]

[-- Attachment #1: Type: text/plain, Size: 1714 bytes --]

On Thu, Apr 10, 2025 at 01:17:45PM -0400, Steven Rostedt wrote:
> Mark Brown <broonie@kernel.org> wrote:

> > We've been seeing the PID filters selftest failing for a while on
> > several arm64 systems, a bisect I managed to run without running into
> > any confounding issues pointed to this patch which is in mainline as
> > ff5c9c576e75.  It's in the ftrace code, but I'm not immediately seeing
> > the relevance.  Output from a failing run:

> Hmm, I wonder if there's junk being added into the trace.

> Can you add this patch, and show me the output when it fails again?

# # + cat trace
# # # tracer: function_graph
# # #
# # # CPU  TASK/PID         DURATION                  FUNCTION CALLS
# # # |     |    |           |   |                     |   |   |   |
# # 0)  ftracet-5190  | ! 537.633 us  |  kernel_clone(); /* ret=0x1470 */
# # 
# # 0)  ftracet-5190  | ! 508.253 us  |  kernel_clone(); /* ret=0x1471 */
# # 
# # 0)  ftracet-5190  | ! 215.716 us  |  kernel_clone(); /* ret=0x1476 */
# # 
# # 0)  ftracet-5190  | ! 493.890 us  |  kernel_clone(); /* ret=0x147b */
# # 
# # + fail PID filtering not working?

...

# # + cat trace
# # # tracer: function_graph
# # #
# # # CPU  TASK/PID         DURATION                  FUNCTION CALLS
# # # |     |    |           |   |                     |   |   |   |
# # 0) ftracet-12279  | ! 598.118 us  |  kernel_clone(); /* ret=0x301f */
# # 
# # 0) ftracet-12279  | ! 492.539 us  |  kernel_clone(); /* ret=0x3020 */
# # 
# # 0) ftracet-12279  | ! 231.104 us  |  kernel_clone(); /* ret=0x3025 */
# # 
# # 0) ftracet-12279  | ! 555.566 us  |  kernel_clone(); /* ret=0x302a */
# # 
# # + fail PID filtering not working?

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Fri, 11 Apr 2025 14:00:40 +0100
Mark Brown <broonie@kernel.org> wrote:

> On Thu, Apr 10, 2025 at 01:17:45PM -0400, Steven Rostedt wrote:
> > Mark Brown <broonie@kernel.org> wrote:  
> 
> > > We've been seeing the PID filters selftest failing for a while on
> > > several arm64 systems, a bisect I managed to run without running into
> > > any confounding issues pointed to this patch which is in mainline as
> > > ff5c9c576e75.  It's in the ftrace code, but I'm not immediately seeing
> > > the relevance.  Output from a failing run:  
> 
> > Hmm, I wonder if there's junk being added into the trace.  
> 
> > Can you add this patch, and show me the output when it fails again?  
> 

Can you show the information before this output, to see what it is actually
testing?

> # # + cat trace
> # # # tracer: function_graph
> # # #
> # # # CPU  TASK/PID         DURATION                  FUNCTION CALLS
> # # # |     |    |           |   |                     |   |   |   |
> # # 0)  ftracet-5190  | ! 537.633 us  |  kernel_clone(); /* ret=0x1470 */
> # # 
> # # 0)  ftracet-5190  | ! 508.253 us  |  kernel_clone(); /* ret=0x1471 */
> # # 
> # # 0)  ftracet-5190  | ! 215.716 us  |  kernel_clone(); /* ret=0x1476 */
> # # 
> # # 0)  ftracet-5190  | ! 493.890 us  |  kernel_clone(); /* ret=0x147b */
> # # 
> # # + fail PID filtering not working?
> 
> ...
> 
> # # + cat trace
> # # # tracer: function_graph
> # # #
> # # # CPU  TASK/PID         DURATION                  FUNCTION CALLS
> # # # |     |    |           |   |                     |   |   |   |
> # # 0) ftracet-12279  | ! 598.118 us  |  kernel_clone(); /* ret=0x301f */
> # # 
> # # 0) ftracet-12279  | ! 492.539 us  |  kernel_clone(); /* ret=0x3020 */
> # # 
> # # 0) ftracet-12279  | ! 231.104 us  |  kernel_clone(); /* ret=0x3025 */
> # # 
> # # 0) ftracet-12279  | ! 555.566 us  |  kernel_clone(); /* ret=0x302a */
> # # 
> # # + fail PID filtering not working?

Also, is it possible to just enable function_graph tarcing and see if it
adds these blank lines between events?

-- Steve

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Fri, 11 Apr 2025 12:45:52 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> Also, is it possible to just enable function_graph tarcing and see if it
> adds these blank lines between events?

Never mind. When I enable the funcgraph-retval option, I get the blank
lines too.

There's likely an added '\n' that shouldn't be. Let me go look.

Thanks,

-- Steve

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Mark Brown]

[-- Attachment #1: Type: text/plain, Size: 5776 bytes --]

On Fri, Apr 11, 2025 at 12:45:52PM -0400, Steven Rostedt wrote:
> Mark Brown <broonie@kernel.org> wrote:
> > On Thu, Apr 10, 2025 at 01:17:45PM -0400, Steven Rostedt wrote:

> > > Hmm, I wonder if there's junk being added into the trace.  

> > > Can you add this patch, and show me the output when it fails again?  

> Can you show the information before this output, to see what it is actually
> testing?

Here's a bit more of the context - this is literally just the ftrace
selftests so it'll be doing whatever that does, there's a huge amount of
log splat generated when enumerating all the triggers.  I do note that
it appears to assume there's a ping binary which might confusing things,
though I'm surprised that'd be a regression rather than something that
just never worked:

# # + reset_ftrace_filter
# # + [ ! -f set_ftrace_filter ]
# # + echo
# # + grep -v ^# set_ftrace_filter
# # + read t
# # + disable_events
# # + echo 0
# # + clear_dynamic_events
# # + again=1
# # + stop=1
# # + [ 1 -eq 1 ]
# # + stop=2
# # + [ 2 -gt 10 ]
# # + again=2
# # + grep -v ^# dynamic_events
# # + read line
# # + [ 2 -eq 1 ]
# # + [ -f set_event_pid ]
# # + echo
# # + [ -f set_ftrace_pid ]
# # + echo
# # + [ -f set_ftrace_notrace ]
# # + echo
# # + [ -f set_graph_function ]
# # + echo
# # + tee set_graph_function set_graph_notrace
# # 
# # + [ -f stack_trace_filter ]
# # + echo
# # + [ -f kprobe_events ]
# # + echo
# # + [ -f uprobe_events ]
# # + echo
# # + [ -f synthetic_events ]
# # + echo
# # + [ -f snapshot ]
# # + echo 0
# # + [ -f options/pause-on-trace ]
# # + echo 1
# # + clear_trace
# # + echo
# # + enable_tracing
# # + echo 1
# # + . /opt/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc
# # + do_function_fork=1
# # + do_funcgraph_proc=1
# # + [ ! -f options/function-fork ]
# # + [ ! -f options/funcgraph-proc ]
# # + read PID _
# # + [ 1 -eq 1 ]
# # + grep function-fork trace_options
# # + orig_value=nofunction-fork
# # + [ 1 -eq 1 ]
# # + cat options/funcgraph-proc
# # + orig_value2=0
# # + echo 1
# # + do_test function
# # + TRACER=function
# # + disable_tracing
# # + echo 0
# # + echo do_execve*
# # + echo kernel_clone
# # + echo 5190
# # + echo function
# # + [ 1 -eq 1 ]
# # + echo nofunction-fork
# # + enable_tracing
# # + echo 1
# # + yield
# # + ping 127.0.0.1 -c 1
# # ./ftracetest: 179: /opt/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc: ping: not found
# # + sleep .001
# # + cat trace
# # + grep -v ^#
# # + grep 5190
# # + wc -l
# # + count_pid=2
# # + cat trace
# # + grep -v ^#
# # + grep -v 5190
# # + wc -l
# # + count_other=0
# # + [ 2 -eq 0 -o 0 -ne 0 ]
# # + disable_tracing
# # + echo 0
# # + clear_trace
# # + echo
# # + [ 1 -eq 0 ]
# # + echo function-fork
# # + enable_tracing
# # + echo 1
# # + yield
# # + ping 127.0.0.1 -c 1
# # ./ftracetest: 179: /opt/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc: ping: not found
# # + sleep .001
# # + cat trace
# # + grep -v ^#
# # + grep 5190
# # + wc -l
# # + count_pid=2
# # + cat trace
# # + grep -v ^#
# # + grep -v 5190
# # + wc -l
# # + count_other=17
# # + [ 2 -eq 0 -o 17 -eq 0 ]
# # + grep -s function_graph available_tracers
# # function_graph wakeup_dl wakeup_rt wakeup preemptirqsoff preemptoff irqsoff function nop
# # + do_test function_graph
# # + TRACER=function_graph
# # + disable_tracing
# # + echo 0
# # + echo do_execve*
# # + echo kernel_clone
# # + echo 5190
# # + echo function_graph
# # + [ 1 -eq 1 ]
# # + echo nofunction-fork
# # + enable_tracing
# # + echo 1
# # + yield
# # + ping 127.0.0.1 -c 1
# # ./ftracetest: 179: /opt/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc: ping: not found
# # + sleep .001
# # + cat trace
# # + grep -v ^#
# # + grep 5190
# # + wc -l
# # + count_pid=2
# # + cat trace
# # + grep -v ^#
# # + grep -v 5190
# # + wc -l
# # + count_other=3
# # + [ 2 -eq 0 -o 3 -ne 0 ]
# # + cat trace
# # # tracer: function_graph
# # #
# # # CPU  TASK/PID         DURATION                  FUNCTION CALLS
# # # |     |    |           |   |                     |   |   |   |
# # 0)  ftracet-5190  | ! 537.633 us  |  kernel_clone(); /* ret=0x1470 */
# # 
# # 0)  ftracet-5190  | ! 508.253 us  |  kernel_clone(); /* ret=0x1471 */
# # 
# # 0)  ftracet-5190  | ! 215.716 us  |  kernel_clone(); /* ret=0x1476 */
# # 
# # 0)  ftracet-5190  | ! 493.890 us  |  kernel_clone(); /* ret=0x147b */
# # 
# # + fail PID filtering not working?
# # + do_reset
# # + [ 1 -eq 1 ]
# # + echo nofunction-fork
# # + [ 1 -eq 1 ]
# # + echo 0
# # + echo PID filtering not working?
# # PID filtering not working?
# # + exit_fail
# # + exit 1

> > # # + cat trace
> > # # # tracer: function_graph
> > # # #
> > # # # CPU  TASK/PID         DURATION                  FUNCTION CALLS
> > # # # |     |    |           |   |                     |   |   |   |
> > # # 0) ftracet-12279  | ! 598.118 us  |  kernel_clone(); /* ret=0x301f */
> > # # 
> > # # 0) ftracet-12279  | ! 492.539 us  |  kernel_clone(); /* ret=0x3020 */
> > # # 
> > # # 0) ftracet-12279  | ! 231.104 us  |  kernel_clone(); /* ret=0x3025 */
> > # # 
> > # # 0) ftracet-12279  | ! 555.566 us  |  kernel_clone(); /* ret=0x302a */
> > # # 
> > # # + fail PID filtering not working?

> Also, is it possible to just enable function_graph tarcing and see if it
> adds these blank lines between events?

That'll take a bit more arranging, I'm running these tests as batch jobs
in CI infrastructure.  I'll try to have a look.  The only other test
that actually failed was:

# not ok 25 Checking dynamic events limitations

which isn't flagged as a regression (there's some other UNRESOLVED ones).

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Fri, 11 Apr 2025 12:48:49 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Fri, 11 Apr 2025 12:45:52 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > Also, is it possible to just enable function_graph tarcing and see if it
> > adds these blank lines between events?  
> 
> Never mind. When I enable the funcgraph-retval option, I get the blank
> lines too.
> 
> There's likely an added '\n' that shouldn't be. Let me go look.
> 

Found it, and yes it is the commit you bisected it to:

It added a '\n' when the retval option would print one too.

This should fix it:

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 2f077d4158e5..718f6e84cc83 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -971,11 +971,10 @@ print_graph_entry_leaf(struct trace_iterator *iter,
 
 		if (args_size >= FTRACE_REGS_MAX_ARGS * sizeof(long)) {
 			print_function_args(s, entry->args, ret_func);
-			trace_seq_putc(s, ';');
+			trace_seq_puts(s, ";\n");
 		} else
-			trace_seq_puts(s, "();");
+			trace_seq_puts(s, "();\n");
 	}
-	trace_seq_printf(s, "\n");
 
 	print_graph_irq(iter, graph_ret->func, TRACE_GRAPH_RET,
 			cpu, iter->ent->pid, flags);
-- Steve

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Fri, 11 Apr 2025 17:58:32 +0100
Mark Brown <broonie@kernel.org> wrote:

> On Fri, Apr 11, 2025 at 12:45:52PM -0400, Steven Rostedt wrote:
> > Mark Brown <broonie@kernel.org> wrote:  
> > > On Thu, Apr 10, 2025 at 01:17:45PM -0400, Steven Rostedt wrote:  
> 
> > > > Hmm, I wonder if there's junk being added into the trace.    
> 
> > > > Can you add this patch, and show me the output when it fails again?    
> 
> > Can you show the information before this output, to see what it is actually
> > testing?  
> 
> Here's a bit more of the context - this is literally just the ftrace
> selftests so it'll be doing whatever that does, there's a huge amount of
> log splat generated when enumerating all the triggers.  I do note that
> it appears to assume there's a ping binary which might confusing things,
> though I'm surprised that'd be a regression rather than something that
> just never worked:

Thanks, even though I figured it out...

> # # + yield
> # # + ping 127.0.0.1 -c 1
> # # ./ftracetest: 179: /opt/kselftest/ftrace/test.d/ftrace/func-filter-pid.tc: ping: not found

The ping was just a way to add some extra noise, as sometimes, the system
just went totally idle, and nothing else showed up.

> # # + sleep .001
> # # + cat trace
> # # + grep -v ^#
> # # + grep 5190
> # # + wc -l
> # # + count_pid=2
> # # + cat trace
> # # + grep -v ^#
> # # + grep -v 5190
> # # + wc -l
> # # + count_other=3

This is what I was looking for. The "count_other" is the number of lines of
output that wasn't due to a '#' or something with '5190'.

> # # + [ 2 -eq 0 -o 3 -ne 0 ]

And it was expecting zero.

> # # + cat trace
> # # # tracer: function_graph
> # # #
> # # # CPU  TASK/PID         DURATION                  FUNCTION CALLS
> # # # |     |    |           |   |                     |   |   |   |
> # # 0)  ftracet-5190  | ! 537.633 us  |  kernel_clone(); /* ret=0x1470 */
> # # 
> # # 0)  ftracet-5190  | ! 508.253 us  |  kernel_clone(); /* ret=0x1471 */
> # # 
> # # 0)  ftracet-5190  | ! 215.716 us  |  kernel_clone(); /* ret=0x1476 */
> # # 
> # # 0)  ftracet-5190  | ! 493.890 us  |  kernel_clone(); /* ret=0x147b */

But it found 3 blank lines!

> That'll take a bit more arranging, I'm running these tests as batch jobs
> in CI infrastructure.  I'll try to have a look.  The only other test
> that actually failed was:
> 
> # not ok 25 Checking dynamic events limitations
> 
> which isn't flagged as a regression (there's some other UNRESOLVED ones).

Hmm, don't know about that one.

-- Steve

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Fri, 11 Apr 2025 13:02:00 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index 2f077d4158e5..718f6e84cc83 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -971,11 +971,10 @@ print_graph_entry_leaf(struct trace_iterator *iter,
>  
>  		if (args_size >= FTRACE_REGS_MAX_ARGS * sizeof(long)) {
>  			print_function_args(s, entry->args, ret_func);
> -			trace_seq_putc(s, ';');
> +			trace_seq_puts(s, ";\n");
>  		} else
> -			trace_seq_puts(s, "();");
> +			trace_seq_puts(s, "();\n");
>  	}
> -	trace_seq_printf(s, "\n");
>  
>  	print_graph_irq(iter, graph_ret->func, TRACE_GRAPH_RET,
>  			cpu, iter->ent->pid, flags);

I changed the patch to have print_graph_retval() simply not add a newline,
and instead just have the caller always print the newline.

I should have never let that function do that. But when it was added, there
wasn't as many options, so it didn't look so bad, so I didn't ask for that
to be changed.

-- Steve

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Mark Brown]

[-- Attachment #1: Type: text/plain, Size: 1914 bytes --]

On Fri, Apr 11, 2025 at 01:12:54PM -0400, Steven Rostedt wrote:
> Mark Brown <broonie@kernel.org> wrote:

> > That'll take a bit more arranging, I'm running these tests as batch jobs
> > in CI infrastructure.  I'll try to have a look.  The only other test
> > that actually failed was:

> > # not ok 25 Checking dynamic events limitations

> > which isn't flagged as a regression (there's some other UNRESOLVED ones).

> Hmm, don't know about that one.

The tail end of the log there is:

# # + TEST_STRING=p vfs_read 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127
# # + TEST_STRING=p vfs_read 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128
# # + echo p vfs_read 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128
# # ./ftracetest: 16: echo: echo: I/O error

which smells a bit of a shell incompatibility issue.  I'll try to find
time to have a look.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Mark Brown]

[-- Attachment #1: Type: text/plain, Size: 609 bytes --]

On Fri, Apr 11, 2025 at 06:39:12PM +0100, Mark Brown wrote:
> On Fri, Apr 11, 2025 at 01:12:54PM -0400, Steven Rostedt wrote:
> > Mark Brown <broonie@kernel.org> wrote:

> > > # not ok 25 Checking dynamic events limitations

> > > which isn't flagged as a regression (there's some other UNRESOLVED ones).

> > Hmm, don't know about that one.

...

> which smells a bit of a shell incompatibility issue.  I'll try to find
> time to have a look.

Yeah, if I bodge ftracetest to be a bash script then the test runs fine
so it'll be a bashism.  We're running the tests in a Debian rootfs so
/bin/sh will be dash.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Fri, 11 Apr 2025 19:16:29 +0100
Mark Brown <broonie@kernel.org> wrote:

> > which smells a bit of a shell incompatibility issue.  I'll try to find
> > time to have a look.  
> 
> Yeah, if I bodge ftracetest to be a bash script then the test runs fine
> so it'll be a bashism.  We're running the tests in a Debian rootfs so
> /bin/sh will be dash.

Interesting, as one of the ftracetests checks for bashisms:

  test.d/selftest/bashisms.tc

Did it not catch something?

-- Steve

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Mark Brown]

[-- Attachment #1: Type: text/plain, Size: 520 bytes --]

On Fri, Apr 11, 2025 at 02:24:27PM -0400, Steven Rostedt wrote:
> Mark Brown <broonie@kernel.org> wrote:

> > Yeah, if I bodge ftracetest to be a bash script then the test runs fine
> > so it'll be a bashism.  We're running the tests in a Debian rootfs so
> > /bin/sh will be dash.

> Interesting, as one of the ftracetests checks for bashisms:

>   test.d/selftest/bashisms.tc

> Did it not catch something?

# not ok 90 Meta-selftest: Checkbashisms # UNRESOLVED

Which will be because checkbashishms is not installed.

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 488 bytes --]

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Fri, 11 Apr 2025 14:24:27 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> > Yeah, if I bodge ftracetest to be a bash script then the test runs fine
> > so it'll be a bashism.  We're running the tests in a Debian rootfs so
> > /bin/sh will be dash.  
> 
> Interesting, as one of the ftracetests checks for bashisms:
> 
>   test.d/selftest/bashisms.tc
> 
> Did it not catch something?

Hmm, I just tested this, and it fails on my box too (I test on a debian VM).

It fails with and without setting it to bash. I'll take a look too.

-- Steve

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Fri, 11 Apr 2025 14:31:32 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> Hmm, I just tested this, and it fails on my box too (I test on a debian VM).
> 
> It fails with and without setting it to bash. I'll take a look too.

Hmm, maybe it is a bashism.

The test has this:

  # Max arguments limitation
  MAX_ARGS=128
  EXCEED_ARGS=$((MAX_ARGS + 1))

  check_max_args() { # event_header
    TEST_STRING=$1
    # Acceptable
    for i in `seq 1 $MAX_ARGS`; do
      TEST_STRING="$TEST_STRING \\$i"
    done
    echo "$TEST_STRING" >> dynamic_events
    echo > dynamic_events
    # Error
    TEST_STRING="$TEST_STRING \\$EXCEED_ARGS"
    ! echo "$TEST_STRING" >> dynamic_events
    return 0
  }

  # Kprobe max args limitation
  if grep -q "kprobe_events" README; then
    check_max_args "p vfs_read"
  fi

So I tried manually executing this in bash:

--------------------------8<--------------------------
# TEST_STRING='p vfs_read'
# for i in `seq 1 128`; do TEST_STRING="$TEST_STRING \\$i" ; done
# echo $TEST_STRING
p vfs_read \1 \2 \3 \4 \5 \6 \7 \8 \9 \10 \11 \12 \13 \14 \15 \16 \17 \18 \19 \20 \21 \22 \23 \24 \25 \26 \27 \28 \29 \30 \31 \32 \33 \34 \35 \36 \37 \38 \39 \40 \41 \42 \43 \44 \45 \46 \47 \48 \49 \50 \51 \52 \53 \54 \55 \56 \57 \58 \59 \60 \61 \62 \63 \64 \65 \66 \67 \68 \69 \70 \71 \72 \73 \74 \75 \76 \77 \78 \79 \80 \81 \82 \83 \84 \85 \86 \87 \88 \89 \90 \91 \92 \93 \94 \95 \96 \97 \98 \99 \100 \101 \102 \103 \104 \105 \106 \107 \108 \109 \110 \111 \112 \113 \114 \115 \116 \117 \118 \119 \120 \121 \122 \123 \124 \125 \126 \127 \128
# echo "$TEST_STRING" >> /sys/kernel/tracing/dynamic_events
# echo $?
0
# cat /sys/kernel/tracing/dynamic_events
p:kprobes/p_vfs_read_0 vfs_read arg1=\1 arg2=\2 arg3=\3 arg4=\4 arg5=\5 arg6=\6 arg7=\7 arg8=\8 arg9=\9 arg10=\10 arg11=\11 arg12=\12 arg13=\13 arg14=\14 arg15=\15 arg16=\16 arg17=\17 arg18=\18 arg19=\19 arg20=\20 arg21=\21 arg22=\22 arg23=\23 arg24=\24 arg25=\25 arg26=\26 arg27=\27 arg28=\28 arg29=\29 arg30=\30 arg31=\31 arg32=\32 arg33=\33 arg34=\34 arg35=\35 arg36=\36 arg37=\37 arg38=\38 arg39=\39 arg40=\40 arg41=\41 arg42=\42 arg43=\43 arg44=\44 arg45=\45 arg46=\46 arg47=\47 arg48=\48 arg49=\49 arg50=\50 arg51=\51 arg52=\52 arg53=\53 arg54=\54 arg55=\55 arg56=\56 arg57=\57 arg58=\58 arg59=\59 arg60=\60 arg61=\61 arg62=\62 arg63=\63 arg64=\64 arg65=\65 arg66=\66 arg67=\67 arg68=\68 arg69=\69 arg70=\70 arg71=\71 arg72=\72 arg73=\73 arg74=\74 arg75=\75 arg76=\76 arg77=\77 arg78=\78 arg79=\79 arg80=\80 arg81=\81 arg82=\82 arg83=\83 arg84=\84 arg85=\85 arg86=\86 arg87=\87 arg88=\88 arg89=\89 arg90=\90 arg91=\91 arg92=\92 arg93=\93 arg94=\94 arg95=\95 arg96=\96 arg97=\97 arg98=\98 arg99=\99 arg100=\100 arg101=\101 arg102=\102 arg103=\103 arg104=\104 arg105=\105 arg106=\106 arg107=\107 arg108=\108 arg109=\109 arg110=\110 arg111=\111 arg112=\112 arg113=\113 arg114=\114 arg115=\115 arg116=\116 arg117=\117 arg118=\118 arg119=\119 arg120=\120 arg121=\121 arg122=\122 arg123=\123 arg124=\124 arg125=\125 arg126=\126 arg127=\127 arg128=\128
-------------------------->8--------------------------

Doing the same in dash:

--------------------------8<--------------------------
# dash
# TEST_STRING='p vfs_read'
# for i in `seq 1 128`; do TEST_STRING="$TEST_STRING \\$i" ; done
# echo $TEST_STRING
p vfs_read         \8 \9 	 
 
  
   8 9         8 9   ␦  9   ! " # $ % & ' 8 9 ( ) * + , - . / 8 9 0 1 2 3 4 5 6 7 8 9 8 9 : ; < = > ? 8 9 \80 \81 \82 \83 \84 \85 \86 \87 \88 \89 \90 \91 \92 \93 \94 \95 \96 \97 \98 \99 @ A B C D E F G89 H I J K L M N O 	8 	9 P Q R S T U V W 
8
# echo "$TEST_STRING" >> /sys/kernel/tracing/dynamic_events
dash: 8: echo: echo: I/O error
-------------------------->8--------------------------

Looks like dash will translate those "\#" into the ASCII equivalent,
whereas bash does not.

This patch seems to fix it:

diff --git a/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc b/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc
index 6b94b678741a..ebe2a34cbf92 100644
--- a/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc
+++ b/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc
@@ -11,7 +11,7 @@ check_max_args() { # event_header
   TEST_STRING=$1
   # Acceptable
   for i in `seq 1 $MAX_ARGS`; do
-    TEST_STRING="$TEST_STRING \\$i"
+    TEST_STRING="$TEST_STRING \\\\$i"
   done
   echo "$TEST_STRING" >> dynamic_events
   echo > dynamic_events


Masami, you just recently added this test (it's dated March 27th 2025), did
you mean to write in the ASCII characters? Why the backslash?

-- Steve

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

Replying to my email as it appears gmail blocked it. Probably due to all
the escape characters my output had. Resending with that cut out.

Masami, I was sent a message from gmail that it blocked this from you.

If you want to see the original email:

  https://lore.kernel.org/all/20250411151358.1d4fd8c7@gandalf.local.home/

-- Steve

On Fri, 11 Apr 2025 15:13:58 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Fri, 11 Apr 2025 14:31:32 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > Hmm, I just tested this, and it fails on my box too (I test on a debian VM).
> > 
> > It fails with and without setting it to bash. I'll take a look too.  
> 
> Hmm, maybe it is a bashism.
> 
> The test has this:
> 
>   # Max arguments limitation
>   MAX_ARGS=128
>   EXCEED_ARGS=$((MAX_ARGS + 1))
> 
>   check_max_args() { # event_header
>     TEST_STRING=$1
>     # Acceptable
>     for i in `seq 1 $MAX_ARGS`; do
>       TEST_STRING="$TEST_STRING \\$i"
>     done
>     echo "$TEST_STRING" >> dynamic_events
>     echo > dynamic_events
>     # Error
>     TEST_STRING="$TEST_STRING \\$EXCEED_ARGS"
>     ! echo "$TEST_STRING" >> dynamic_events
>     return 0
>   }
> 
>   # Kprobe max args limitation
>   if grep -q "kprobe_events" README; then
>     check_max_args "p vfs_read"
>   fi
> 
> So I tried manually executing this in bash:
> 
> --------------------------8<--------------------------
> # TEST_STRING='p vfs_read'
> # for i in `seq 1 128`; do TEST_STRING="$TEST_STRING \\$i" ; done
> # echo $TEST_STRING
> p vfs_read \1 \2

[ This  is cut out to see if it doesn't trigger gmail blocking it again! ]

> # echo "$TEST_STRING" >> /sys/kernel/tracing/dynamic_events
> # echo $?
> 0
> # cat /sys/kernel/tracing/dynamic_events
> p:kprobes/p_vfs_read_0 vfs_read arg1=\1

[ This  is cut out to see if it doesn't trigger gmail blocking it again! ]

> -------------------------->8--------------------------  
> 
> Doing the same in dash:
> 
> --------------------------8<--------------------------
> # dash
> # TEST_STRING='p vfs_read'
> # for i in `seq 1 128`; do TEST_STRING="$TEST_STRING \\$i" ; done
> # echo $TEST_STRING
> p vfs_read         \8 \9 	 

[ This  is cut out to see if it doesn't trigger gmail blocking it again! ]

> # echo "$TEST_STRING" >> /sys/kernel/tracing/dynamic_events
> dash: 8: echo: echo: I/O error
> -------------------------->8--------------------------  
> 
> Looks like dash will translate those "\#" into the ASCII equivalent,
> whereas bash does not.
> 
> This patch seems to fix it:
> 
> diff --git a/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc b/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc
> index 6b94b678741a..ebe2a34cbf92 100644
> --- a/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc
> +++ b/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc
> @@ -11,7 +11,7 @@ check_max_args() { # event_header
>    TEST_STRING=$1
>    # Acceptable
>    for i in `seq 1 $MAX_ARGS`; do
> -    TEST_STRING="$TEST_STRING \\$i"
> +    TEST_STRING="$TEST_STRING \\\\$i"
>    done
>    echo "$TEST_STRING" >> dynamic_events
>    echo > dynamic_events
> 
> 
> Masami, you just recently added this test (it's dated March 27th 2025), did
> you mean to write in the ASCII characters? Why the backslash?
> 
> -- Steve

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Fri, 11 Apr 2025 15:26:10 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> Replying to my email as it appears gmail blocked it. Probably due to all
> the escape characters my output had. Resending with that cut out.
> 
> Masami, I was sent a message from gmail that it blocked this from you.
> 
> If you want to see the original email:
> 
>   https://lore.kernel.org/all/20250411151358.1d4fd8c7@gandalf.local.home/
>

Bah! gmail blocked that one too :-p

-- Steve

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Masami Hiramatsu]

On Fri, 11 Apr 2025 15:26:10 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> 
> Replying to my email as it appears gmail blocked it. Probably due to all
> the escape characters my output had. Resending with that cut out.
> 
> Masami, I was sent a message from gmail that it blocked this from you.

Hi, I could find it. Let me reply!

> 
> If you want to see the original email:
> 
>   https://lore.kernel.org/all/20250411151358.1d4fd8c7@gandalf.local.home/
> 
> -- Steve
> 
> On Fri, 11 Apr 2025 15:13:58 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > On Fri, 11 Apr 2025 14:31:32 -0400
> > Steven Rostedt <rostedt@goodmis.org> wrote:
> > 
> > > Hmm, I just tested this, and it fails on my box too (I test on a debian VM).
> > > 
> > > It fails with and without setting it to bash. I'll take a look too.  
> > 
> > Hmm, maybe it is a bashism.
> > 
> > The test has this:
> > 
> >   # Max arguments limitation
> >   MAX_ARGS=128
> >   EXCEED_ARGS=$((MAX_ARGS + 1))
> > 
> >   check_max_args() { # event_header
> >     TEST_STRING=$1
> >     # Acceptable
> >     for i in `seq 1 $MAX_ARGS`; do
> >       TEST_STRING="$TEST_STRING \\$i"
> >     done
> >     echo "$TEST_STRING" >> dynamic_events
> >     echo > dynamic_events
> >     # Error
> >     TEST_STRING="$TEST_STRING \\$EXCEED_ARGS"
> >     ! echo "$TEST_STRING" >> dynamic_events
> >     return 0
> >   }
> > 
> >   # Kprobe max args limitation
> >   if grep -q "kprobe_events" README; then
> >     check_max_args "p vfs_read"
> >   fi
> > 
> > So I tried manually executing this in bash:
> > 
> > --------------------------8<--------------------------
> > # TEST_STRING='p vfs_read'
> > # for i in `seq 1 128`; do TEST_STRING="$TEST_STRING \\$i" ; done
> > # echo $TEST_STRING
> > p vfs_read \1 \2
> 
> [ This  is cut out to see if it doesn't trigger gmail blocking it again! ]
> 
> > # echo "$TEST_STRING" >> /sys/kernel/tracing/dynamic_events
> > # echo $?
> > 0
> > # cat /sys/kernel/tracing/dynamic_events
> > p:kprobes/p_vfs_read_0 vfs_read arg1=\1
> 
> [ This  is cut out to see if it doesn't trigger gmail blocking it again! ]
> 
> > -------------------------->8--------------------------  
> > 
> > Doing the same in dash:
> > 
> > --------------------------8<--------------------------
> > # dash
> > # TEST_STRING='p vfs_read'
> > # for i in `seq 1 128`; do TEST_STRING="$TEST_STRING \\$i" ; done
> > # echo $TEST_STRING
> > p vfs_read         \8 \9 	 
> 
> [ This  is cut out to see if it doesn't trigger gmail blocking it again! ]
> 
> > # echo "$TEST_STRING" >> /sys/kernel/tracing/dynamic_events
> > dash: 8: echo: echo: I/O error
> > -------------------------->8--------------------------  
> > 
> > Looks like dash will translate those "\#" into the ASCII equivalent,
> > whereas bash does not.
> > 
> > This patch seems to fix it:
> > 
> > diff --git a/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc b/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc
> > index 6b94b678741a..ebe2a34cbf92 100644
> > --- a/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc
> > +++ b/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc
> > @@ -11,7 +11,7 @@ check_max_args() { # event_header
> >    TEST_STRING=$1
> >    # Acceptable
> >    for i in `seq 1 $MAX_ARGS`; do
> > -    TEST_STRING="$TEST_STRING \\$i"
> > +    TEST_STRING="$TEST_STRING \\\\$i"
> >    done
> >    echo "$TEST_STRING" >> dynamic_events
> >    echo > dynamic_events
> > 
> > 
> > Masami, you just recently added this test (it's dated March 27th 2025), did
> > you mean to write in the ASCII characters? Why the backslash?
> > 
> > -- Steve
> 


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Masami Hiramatsu]

On Fri, 11 Apr 2025 15:13:58 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> On Fri, 11 Apr 2025 14:31:32 -0400
> Steven Rostedt <rostedt@goodmis.org> wrote:
> 
> > Hmm, I just tested this, and it fails on my box too (I test on a debian VM).
> > 
> > It fails with and without setting it to bash. I'll take a look too.
> 
> Hmm, maybe it is a bashism.
> 
> The test has this:
> 
>   # Max arguments limitation
>   MAX_ARGS=128
>   EXCEED_ARGS=$((MAX_ARGS + 1))
> 
>   check_max_args() { # event_header
>     TEST_STRING=$1
>     # Acceptable
>     for i in `seq 1 $MAX_ARGS`; do
>       TEST_STRING="$TEST_STRING \\$i"
>     done
>     echo "$TEST_STRING" >> dynamic_events
>     echo > dynamic_events
>     # Error
>     TEST_STRING="$TEST_STRING \\$EXCEED_ARGS"
>     ! echo "$TEST_STRING" >> dynamic_events
>     return 0
>   }
> 
>   # Kprobe max args limitation
>   if grep -q "kprobe_events" README; then
>     check_max_args "p vfs_read"
>   fi
> 
> So I tried manually executing this in bash:
> 
> --------------------------8<--------------------------
> # TEST_STRING='p vfs_read'
> # for i in `seq 1 128`; do TEST_STRING="$TEST_STRING \\$i" ; done
> # echo $TEST_STRING
> p vfs_read \1 \2 \3 \4 \5 \6 \7 \8 \9 \10 \11 \12 \13 \14 \15 \16 \17 \18 \19 \20 \21 \22 \23 \24 \25 \26 \27 \28 \29 \30 \31 \32 \33 \34 \35 \36 \37 \38 \39 \40 \41 \42 \43 \44 \45 \46 \47 \48 \49 \50 \51 \52 \53 \54 \55 \56 \57 \58 \59 \60 \61 \62 \63 \64 \65 \66 \67 \68 \69 \70 \71 \72 \73 \74 \75 \76 \77 \78 \79 \80 \81 \82 \83 \84 \85 \86 \87 \88 \89 \90 \91 \92 \93 \94 \95 \96 \97 \98 \99 \100 \101 \102 \103 \104 \105 \106 \107 \108 \109 \110 \111 \112 \113 \114 \115 \116 \117 \118 \119 \120 \121 \122 \123 \124 \125 \126 \127 \128
> # echo "$TEST_STRING" >> /sys/kernel/tracing/dynamic_events
> # echo $?
> 0
> # cat /sys/kernel/tracing/dynamic_events
> p:kprobes/p_vfs_read_0 vfs_read arg1=\1 arg2=\2 arg3=\3 arg4=\4 arg5=\5 arg6=\6 arg7=\7 arg8=\8 arg9=\9 arg10=\10 arg11=\11 arg12=\12 arg13=\13 arg14=\14 arg15=\15 arg16=\16 arg17=\17 arg18=\18 arg19=\19 arg20=\20 arg21=\21 arg22=\22 arg23=\23 arg24=\24 arg25=\25 arg26=\26 arg27=\27 arg28=\28 arg29=\29 arg30=\30 arg31=\31 arg32=\32 arg33=\33 arg34=\34 arg35=\35 arg36=\36 arg37=\37 arg38=\38 arg39=\39 arg40=\40 arg41=\41 arg42=\42 arg43=\43 arg44=\44 arg45=\45 arg46=\46 arg47=\47 arg48=\48 arg49=\49 arg50=\50 arg51=\51 arg52=\52 arg53=\53 arg54=\54 arg55=\55 arg56=\56 arg57=\57 arg58=\58 arg59=\59 arg60=\60 arg61=\61 arg62=\62 arg63=\63 arg64=\64 arg65=\65 arg66=\66 arg67=\67 arg68=\68 arg69=\69 arg70=\70 arg71=\71 arg72=\72 arg73=\73 arg74=\74 arg75=\75 arg76=\76 arg77=\77 arg78=\78 arg79=\79 arg80=\80 arg81=\81 arg82=\82 arg83=\83 arg84=\84 arg85=\85 arg86=\86 arg87=\87 arg88=\88 arg89=\89 arg90=\90 arg91=\91 arg92=\92 arg93=\93 arg94=\94 arg95=\95 arg96=\96 arg97=\97 arg98=\98 arg99=\99 arg100=\100 arg101=\101 arg102=\102 arg103=\103 arg104=\104 arg105=\105 arg106=\106 arg107=\107 arg108=\108 arg109=\109 arg110=\110 arg111=\111 arg112=\112 arg113=\113 arg114=\114 arg115=\115 arg116=\116 arg117=\117 arg118=\118 arg119=\119 arg120=\120 arg121=\121 arg122=\122 arg123=\123 arg124=\124 arg125=\125 arg126=\126 arg127=\127 arg128=\128
> -------------------------->8--------------------------
> 
> Doing the same in dash:
> 
> --------------------------8<--------------------------
> # dash
> # TEST_STRING='p vfs_read'
> # for i in `seq 1 128`; do TEST_STRING="$TEST_STRING \\$i" ; done
> # echo $TEST_STRING
> p vfs_read         \8 \9 	 
>  
>   
>    8 9         8 9   ␦  9   ! " # $ % & ' 8 9 ( ) * + , - . / 8 9 0 1 2 3 4 5 6 7 8 9 8 9 : ; < = > ? 8 9 \80 \81 \82 \83 \84 \85 \86 \87 \88 \89 \90 \91 \92 \93 \94 \95 \96 \97 \98 \99 @ A B C D E F G89 H I J K L M N O 	8 	9 P Q R S T U V W 
> 8
> # echo "$TEST_STRING" >> /sys/kernel/tracing/dynamic_events
> dash: 8: echo: echo: I/O error
> -------------------------->8--------------------------

Oops...

> 
> Looks like dash will translate those "\#" into the ASCII equivalent,
> whereas bash does not.

Ah, I didn't know that.

> 
> This patch seems to fix it:
> 
> diff --git a/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc b/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc
> index 6b94b678741a..ebe2a34cbf92 100644
> --- a/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc
> +++ b/tools/testing/selftests/ftrace/test.d/dynevent/dynevent_limitations.tc
> @@ -11,7 +11,7 @@ check_max_args() { # event_header
>    TEST_STRING=$1
>    # Acceptable
>    for i in `seq 1 $MAX_ARGS`; do
> -    TEST_STRING="$TEST_STRING \\$i"
> +    TEST_STRING="$TEST_STRING \\\\$i"
>    done
>    echo "$TEST_STRING" >> dynamic_events
>    echo > dynamic_events
> 
> 
> Masami, you just recently added this test (it's dated March 27th 2025), did
> you mean to write in the ASCII characters? Why the backslash?

No, the kprobe_event accepts raw digit values to record in the trace buffer
which is for the probe points which uses a fixed digit value for the actual
local variable (or function parameter), e.g. constant propagation with
optimized function instances.

In this case, can we use below?

TEST_STRING="$TEST_STRING "'\\'$i


Thank you,

> 
> -- Steve
> 


-- 
Masami Hiramatsu (Google) <mhiramat@kernel.org>

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Mon, 14 Apr 2025 12:08:58 +0900
Masami Hiramatsu (Google) <mhiramat@kernel.org> wrote:

> In this case, can we use below?
> 
> TEST_STRING="$TEST_STRING "'\\'$i

Just tried it and it too still doesn't work.

What does work seems to be:

  TEST_STRING="$TEST_STRING "\\\\$i

-- Steve

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Fri, 11 Apr 2025 18:39:05 +0100
Mark Brown <broonie@kernel.org> wrote:

> The tail end of the log there is:
> 
> # # + TEST_STRING=p vfs_read 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127
> # # + TEST_STRING=p vfs_read 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128
> # # + echo p vfs_read 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128
> # # ./ftracetest: 16: echo: echo: I/O error
> 
> which smells a bit of a shell incompatibility issue.  I'll try to find
> time to have a look.

Mark, can you test this patch to see if it fixes this?:

(I need to update the "Closes:" tag to be this email and not the top of the thread)

  https://lore.kernel.org/all/20250414210900.4de5e8b9@gandalf.local.home/

-- Steve

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Sasha Levin]

Hi folks,

I've been trying to track down an issue that started appearing a while
back:

[   73.078526] ------------[ cut here ]------------
[   73.083194] WARNING: CPU: 2 PID: 4002 at kernel/trace/trace_functions_graph.c:991 print_graph_entry+0x579/0x590
[   73.093544] Modules linked in: x86_pkg_temp_thermal fuse
[   73.098939] CPU: 2 UID: 0 PID: 4002 Comm: cat Tainted: G S                  6.16.0 #1 PREEMPT(voluntary)
[   73.108587] Tainted: [S]=CPU_OUT_OF_SPEC
[   73.112664] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS 2.7 12/07/2021
[   73.120126] RIP: 0010:print_graph_entry+0x579/0x590
[   73.125198] Code: 49 89 40 20 49 8b 46 08 49 89 40 28 49 8b 46 10 49 89 40 30 49 8b 46 18 49 89 40 38 49 8b 46 20 49 89 40 40 e9 27 fe ff ff 90 <0f> 0b 90 e9 e2 fe ff ff 90 0f 0b 90 e9 8e fc ff ff e8 91 d8 10 01
[   73.144001] RSP: 0018:ffffa6af02d37c58 EFLAGS: 00010282
[   73.149369] RAX: ffffc6aeffd986f0 RBX: ffff9d70c83b0000 RCX: 00000000fefefefe
[   73.156621] RDX: ffffffffbb374080 RSI: 0000000000000001 RDI: ffffffffbaf773ea
[   73.163839] RBP: ffffa6af02d37cf0 R08: ffff9d70c1790cc0 R09: 0000000000000020
[   73.171023] R10: 0000000000000000 R11: 0000000000000004 R12: ffff9d70c83b2090
[   73.178216] R13: 0000000000000003 R14: ffff9d70c83b0000 R15: ffff9d70c1790cc0
[   73.185412] FS:  00007fd8c6872740(0000) GS:ffff9d72741a9000(0000) knlGS:0000000000000000
[   73.193584] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   73.199391] CR2: 00007ffedaf50fbc CR3: 00000001049f4006 CR4: 00000000003726f0
[   73.206570] Call Trace:
[   73.209086]  <TASK>
[   73.211313]  ? trace_event_raw_event_preemptirq_template+0x66/0xc0
[   73.217573]  ? __pfx_put_cpu_partial+0x10/0x10
[   73.222093]  ? __pfx_put_cpu_partial+0x10/0x10
[   73.226635]  print_graph_function_flags+0x27c/0x530
[   73.231607]  ? peek_next_entry+0x9d/0xb0
[   73.235618]  print_graph_function+0x13/0x20
[   73.239895]  print_trace_line+0xbb/0x530
[   73.243909]  tracing_read_pipe+0x1d6/0x380
[   73.248121]  vfs_read+0xbb/0x380
[   73.251495]  ? vfs_read+0x9/0x380
[   73.254929]  ksys_read+0x7b/0xf0
[   73.258258]  __x64_sys_read+0x1d/0x30
[   73.261995]  x64_sys_call+0x1ada/0x20d0
[   73.265936]  do_syscall_64+0xb2/0x2b0
[   73.269694]  entry_SYSCALL_64_after_hwframe+0x77/0x7f
[   73.274818] RIP: 0033:0x7fd8c6904687
[   73.278491] Code: 48 89 fa 4c 89 df e8 58 b3 00 00 8b 93 08 03 00 00 59 5e 48 83 f8 fc 74 1a 5b c3 0f 1f 84 00 00 00 00 00 48 8b 44 24 10 0f 05 <5b> c3 0f 1f 80 00 00 00 00 83 e2 39 83 fa 08 75 de e8 23 ff ff ff
[   73.297320] RSP: 002b:00007ffe8bb08e60 EFLAGS: 00000202 ORIG_RAX: 0000000000000000
[   73.304974] RAX: ffffffffffffffda RBX: 00007fd8c6872740 RCX: 00007fd8c6904687
[   73.312185] RDX: 0000000000040000 RSI: 00007fd8c6831000 RDI: 0000000000000003
[   73.319369] RBP: 0000000000040000 R08: 0000000000000000 R09: 0000000000000000
[   73.326588] R10: 0000000000000000 R11: 0000000000000202 R12: 00007fd8c6831000
[   73.333801] R13: 0000000000000003 R14: 0000000000000000 R15: 0000000000040000
[   73.341050]  </TASK>
[   73.343324] ---[ end trace 0000000000000000 ]---
[   73.804718] ------------[ cut here ]------------
[   73.809372] WARNING: CPU: 1 PID: 4002 at kernel/trace/trace_functions_graph.c:933 print_graph_entry+0x582/0x590
[   73.819492] Modules linked in: x86_pkg_temp_thermal fuse
[   73.824888] CPU: 1 UID: 0 PID: 4002 Comm: cat Tainted: G S      W           6.16.0 #1 PREEMPT(voluntary)
[   73.834477] Tainted: [S]=CPU_OUT_OF_SPEC, [W]=WARN
[   73.839314] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS 2.7 12/07/2021
[   73.846739] RIP: 0010:print_graph_entry+0x582/0x590
[   73.851662] Code: 89 40 28 49 8b 46 10 49 89 40 30 49 8b 46 18 49 89 40 38 49 8b 46 20 49 89 40 40 e9 27 fe ff ff 90 0f 0b 90 e9 e2 fe ff ff 90 <0f> 0b 90 e9 8e fc ff ff e8 91 d8 10 01 90 90 90 90 90 90 90 90 90
[   73.870458] RSP: 0018:ffffa6af02d37c58 EFLAGS: 00010282
[   73.875733] RAX: ffffc6aeffd186f0 RBX: ffff9d70c83b0000 RCX: 00000011792c5f40
[   73.882906] RDX: ffffffffbb374080 RSI: 00000000fefefefd RDI: 00000011792c5ff6
[   73.890079] RBP: ffffa6af02d37cf0 R08: ffff9d70c1790cc0 R09: 0000000000000020
[   73.897249] R10: 00000000fefefefe R11: 0000000000000004 R12: ffff9d70c83b2090
[   73.904424] R13: 0000000000000001 R14: ffff9d70c1790ce0 R15: ffff9d70c1790cc0
[   73.911609] FS:  00007fd8c6872740(0000) GS:ffff9d7274129000(0000) knlGS:0000000000000000
[   73.919740] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   73.925528] CR2: 0000559a316ca3c0 CR3: 00000001049f4003 CR4: 00000000003726f0
[   73.932705] Call Trace:
[   73.935200]  <TASK>
[   73.937350]  ? __legitimize_mnt+0x4/0xb0
[   73.941342]  print_graph_function_flags+0x27c/0x530
[   73.946269]  ? trace_hardirqs_on+0x2f/0x90
[   73.950401]  ? ring_buffer_empty_cpu+0x86/0xd0
[   73.954912]  print_graph_function+0x13/0x20
[   73.959149]  print_trace_line+0xbb/0x530
[   73.963135]  tracing_read_pipe+0x1d6/0x380
[   73.967291]  vfs_read+0xbb/0x380
[   73.970580]  ? vfs_read+0x9/0x380
[   73.973954]  ksys_read+0x7b/0xf0
[   73.977244]  __x64_sys_read+0x1d/0x30
[   73.980952]  x64_sys_call+0x1ada/0x20d0
[   73.984839]  do_syscall_64+0xb2/0x2b0
[   73.988558]  entry_SYSCALL_64_after_hwframe+0x77/0x7f
[   73.993657] RIP: 0033:0x7fd8c6904687
[   73.997278] Code: 48 89 fa 4c 89 df e8 58 b3 00 00 8b 93 08 03 00 00 59 5e 48 83 f8 fc 74 1a 5b c3 0f 1f 84 00 00 00 00 00 48 8b 44 24 10 0f 05 <5b> c3 0f 1f 80 00 00 00 00 83 e2 39 83 fa 08 75 de e8 23 ff ff ff
[   74.016084] RSP: 002b:00007ffe8bb08e60 EFLAGS: 00000202 ORIG_RAX: 0000000000000000
[   74.023743] RAX: ffffffffffffffda RBX: 00007fd8c6872740 RCX: 00007fd8c6904687
[   74.030920] RDX: 0000000000040000 RSI: 00007fd8c6831000 RDI: 0000000000000003
[   74.038101] RBP: 0000000000040000 R08: 0000000000000000 R09: 0000000000000000
[   74.045277] R10: 0000000000000000 R11: 0000000000000202 R12: 00007fd8c6831000
[   74.052484] R13: 0000000000000003 R14: 0000000000000000 R15: 0000000000040000
[   74.059724]  </TASK>
[   74.061974] ---[ end trace 0000000000000000 ]---

This patch was within the window where the issue started happening, and
on inspection I found something suspicious (but couldn't verify since
I'm traveling).

On Thu, Feb 27, 2025 at 01:58:06PM -0500, Steven Rostedt wrote:
>diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h
>index fbfb396905a6..77a8ba3bc1e3 100644
>--- a/kernel/trace/trace_entries.h
>+++ b/kernel/trace/trace_entries.h
>@@ -72,17 +72,18 @@ FTRACE_ENTRY_REG(function, ftrace_entry,
> );
>
> /* Function call entry */
>-FTRACE_ENTRY_PACKED(funcgraph_entry, ftrace_graph_ent_entry,
>+FTRACE_ENTRY(funcgraph_entry, ftrace_graph_ent_entry,
>
> 	TRACE_GRAPH_ENT,
>
> 	F_STRUCT(
> 		__field_struct(	struct ftrace_graph_ent,	graph_ent	)
> 		__field_packed(	unsigned long,	graph_ent,	func		)
>-		__field_packed(	int,		graph_ent,	depth		)
>+		__field_packed(	unsigned long,	graph_ent,	depth		)
>+		__dynamic_array(unsigned long,	args				)

So we've added a dynamically sized array to the end of
ftrace_graph_ent_entry, but in struct fgraph_data, the saved entry is
defined as:

   struct fgraph_data {
       ...
       union {
           struct ftrace_graph_ent_entry ent;
           struct fgraph_retaddr_ent_entry rent;
       } ent;
       ...
   }

Which doesn't seem to have room for args?

The code in get_return_for_leaf() does:

   data->ent.ent = *curr;

This copies the struct, but curr points to a larger entry with args
data. The copy operation only copies sizeof(struct
ftrace_graph_ent_entry) bytes, which doesn't include the dynamic args
array.

And then later functions (like print_graph_entry()) would go ahead and
assume that iter->ent_size is sane and make a mess out of everything.

I can't test right now whether this actually fixes the issues or not,
but I wanted to bring this up as this looks somewhat odd and I'm not too
familiar with this code.

-- 
Thanks,
Sasha

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Fri, 8 Aug 2025 22:24:05 -0400
Sasha Levin <sashal@kernel.org> wrote:

> So we've added a dynamically sized array to the end of
> ftrace_graph_ent_entry, but in struct fgraph_data, the saved entry is
> defined as:
> 
>    struct fgraph_data {
>        ...
>        union {
>            struct ftrace_graph_ent_entry ent;
>            struct fgraph_retaddr_ent_entry rent;
>        } ent;
>        ...
>    }
> 
> Which doesn't seem to have room for args?

No it doesn't :-p

> 
> The code in get_return_for_leaf() does:
> 
>    data->ent.ent = *curr;
> 
> This copies the struct, but curr points to a larger entry with args
> data. The copy operation only copies sizeof(struct
> ftrace_graph_ent_entry) bytes, which doesn't include the dynamic args
> array.
> 
> And then later functions (like print_graph_entry()) would go ahead and
> assume that iter->ent_size is sane and make a mess out of everything.
> 
> I can't test right now whether this actually fixes the issues or not,
> but I wanted to bring this up as this looks somewhat odd and I'm not too
> familiar with this code.

Thanks for the detail analysis, can you test this patch?

-- Steve

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 66e1a527cf1a..25ea71edb8da 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -35,6 +35,11 @@ struct fgraph_data {
 		struct ftrace_graph_ent_entry	ent;
 		struct fgraph_retaddr_ent_entry	rent;
 	} ent;
+	/*
+	 * The @args must be right after @ent, as it is where they
+	 * are stored in case the function graph tracer has arguments.
+	 */
+	unsigned long			args[FTRACE_REGS_MAX_ARGS];
 	struct ftrace_graph_ret_entry	ret;
 	int				failed;
 	int				cpu;
@@ -623,14 +628,29 @@ get_return_for_leaf(struct trace_iterator *iter,
 		next = ring_buffer_event_data(event);
 
 		if (data) {
+			int args_size;
+			int size;
+
 			/*
 			 * Save current and next entries for later reference
 			 * if the output fails.
 			 */
-			if (unlikely(curr->ent.type == TRACE_GRAPH_RETADDR_ENT))
+			if (unlikely(curr->ent.type == TRACE_GRAPH_RETADDR_ENT)) {
 				data->ent.rent = *(struct fgraph_retaddr_ent_entry *)curr;
-			else
+				size = offsetof(struct fgraph_retaddr_ent_entry, args);
+			} else {
 				data->ent.ent = *curr;
+				size = offsetof(struct ftrace_graph_ent_entry, args);
+			}
+
+			/* If this has args, then append them to after the ent. */
+			args_size = iter->ent_size - size;
+			if (args_size > sizeof(long) * FTRACE_REGS_MAX_ARGS)
+				args_size = sizeof(long) * FTRACE_REGS_MAX_ARGS;
+
+			if (args_size >= sizeof(long))
+				memcpy((void *)&data->ent.ent + size,
+				       (void*)curr + size, args_size);
 			/*
 			 * If the next event is not a return type, then
 			 * we only care about what type it is. Otherwise we can

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Sasha Levin]

On Wed, Aug 13, 2025 at 07:53:17PM -0400, Steven Rostedt wrote:
>On Fri, 8 Aug 2025 22:24:05 -0400
>Sasha Levin <sashal@kernel.org> wrote:
>
>> So we've added a dynamically sized array to the end of
>> ftrace_graph_ent_entry, but in struct fgraph_data, the saved entry is
>> defined as:
>>
>>    struct fgraph_data {
>>        ...
>>        union {
>>            struct ftrace_graph_ent_entry ent;
>>            struct fgraph_retaddr_ent_entry rent;
>>        } ent;
>>        ...
>>    }
>>
>> Which doesn't seem to have room for args?
>
>No it doesn't :-p
>
>>
>> The code in get_return_for_leaf() does:
>>
>>    data->ent.ent = *curr;
>>
>> This copies the struct, but curr points to a larger entry with args
>> data. The copy operation only copies sizeof(struct
>> ftrace_graph_ent_entry) bytes, which doesn't include the dynamic args
>> array.
>>
>> And then later functions (like print_graph_entry()) would go ahead and
>> assume that iter->ent_size is sane and make a mess out of everything.
>>
>> I can't test right now whether this actually fixes the issues or not,
>> but I wanted to bring this up as this looks somewhat odd and I'm not too
>> familiar with this code.
>
>Thanks for the detail analysis, can you test this patch?
>
>-- Steve
>
>diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
>index 66e1a527cf1a..25ea71edb8da 100644
>--- a/kernel/trace/trace_functions_graph.c
>+++ b/kernel/trace/trace_functions_graph.c
>@@ -35,6 +35,11 @@ struct fgraph_data {
> 		struct ftrace_graph_ent_entry	ent;
> 		struct fgraph_retaddr_ent_entry	rent;
> 	} ent;
>+	/*
>+	 * The @args must be right after @ent, as it is where they
>+	 * are stored in case the function graph tracer has arguments.
>+	 */
>+	unsigned long			args[FTRACE_REGS_MAX_ARGS];
> 	struct ftrace_graph_ret_entry	ret;
> 	int				failed;
> 	int				cpu;
>@@ -623,14 +628,29 @@ get_return_for_leaf(struct trace_iterator *iter,
> 		next = ring_buffer_event_data(event);
>
> 		if (data) {
>+			int args_size;
>+			int size;
>+
> 			/*
> 			 * Save current and next entries for later reference
> 			 * if the output fails.
> 			 */
>-			if (unlikely(curr->ent.type == TRACE_GRAPH_RETADDR_ENT))
>+			if (unlikely(curr->ent.type == TRACE_GRAPH_RETADDR_ENT)) {
> 				data->ent.rent = *(struct fgraph_retaddr_ent_entry *)curr;
>-			else
>+				size = offsetof(struct fgraph_retaddr_ent_entry, args);
>+			} else {
> 				data->ent.ent = *curr;
>+				size = offsetof(struct ftrace_graph_ent_entry, args);
>+			}
>+
>+			/* If this has args, then append them to after the ent. */
>+			args_size = iter->ent_size - size;
>+			if (args_size > sizeof(long) * FTRACE_REGS_MAX_ARGS)
>+				args_size = sizeof(long) * FTRACE_REGS_MAX_ARGS;
>+
>+			if (args_size >= sizeof(long))
>+				memcpy((void *)&data->ent.ent + size,
>+				       (void*)curr + size, args_size);
> 			/*
> 			 * If the next event is not a return type, then
> 			 * we only care about what type it is. Otherwise we can

Got a small build error:

kernel/trace/trace_functions_graph.c: In function ‘get_return_for_leaf’:
./include/linux/stddef.h:16:33: error: ‘struct fgraph_retaddr_ent_entry’ has no member named ‘args’
    16 | #define offsetof(TYPE, MEMBER)  __builtin_offsetof(TYPE, MEMBER)
       |                                 ^~~~~~~~~~~~~~~~~~
kernel/trace/trace_functions_graph.c:640:40: note: in expansion of macro ‘offsetof’
   640 |                                 size = offsetof(struct fgraph_retaddr_ent_entry, args);
       |                                        ^~~~~~~~

Does this look right on top of your patch:

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 25ea71edb8da..f0f37356ef29 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -637,20 +637,21 @@ get_return_for_leaf(struct trace_iterator *iter,
                          */
                         if (unlikely(curr->ent.type == TRACE_GRAPH_RETADDR_ENT)) {
                                 data->ent.rent = *(struct fgraph_retaddr_ent_entry *)curr;
-                               size = offsetof(struct fgraph_retaddr_ent_entry, args);
+                               /* fgraph_retaddr_ent_entry doesn't have args field */
+                               size = sizeof(struct fgraph_retaddr_ent_entry);
+                               args_size = 0;
                         } else {
                                 data->ent.ent = *curr;
                                 size = offsetof(struct ftrace_graph_ent_entry, args);
+                               /* If this has args, then append them to after the ent. */
+                               args_size = iter->ent_size - size;
+                               if (args_size > sizeof(long) * FTRACE_REGS_MAX_ARGS)
+                                       args_size = sizeof(long) * FTRACE_REGS_MAX_ARGS;
+
+                               if (args_size >= sizeof(long))
+                                       memcpy((void *)&data->ent.ent + size,
+                                              (void*)curr + size, args_size);
                         }
-
-                       /* If this has args, then append them to after the ent. */
-                       args_size = iter->ent_size - size;
-                       if (args_size > sizeof(long) * FTRACE_REGS_MAX_ARGS)
-                               args_size = sizeof(long) * FTRACE_REGS_MAX_ARGS;
-
-                       if (args_size >= sizeof(long))
-                               memcpy((void *)&data->ent.ent + size,
-                                      (void*)curr + size, args_size);
                         /*
                          * If the next event is not a return type, then
                          * we only care about what type it is. Otherwise we can

-- 
Thanks,
Sasha

Re: [PATCH v4 2/4] ftrace: Add support for function argument to graph tracer

[Steven Rostedt]

On Thu, 14 Aug 2025 13:05:35 -0400
Sasha Levin <sashal@kernel.org> wrote:

> On Wed, 
> Got a small build error:
> 
> kernel/trace/trace_functions_graph.c: In function ‘get_return_for_leaf’:
> ./include/linux/stddef.h:16:33: error: ‘struct fgraph_retaddr_ent_entry’ has no member named ‘args’
>     16 | #define offsetof(TYPE, MEMBER)  __builtin_offsetof(TYPE, MEMBER)
>        |                                 ^~~~~~~~~~~~~~~~~~
> kernel/trace/trace_functions_graph.c:640:40: note: in expansion of macro ‘offsetof’
>    640 |                                 size = offsetof(struct fgraph_retaddr_ent_entry, args);
>        |                                        ^~~~~~~~
> 
> Does this look right on top of your patch:

Bah, it was on the todo list to add args to retaddr. But it never was done.

> 
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index 25ea71edb8da..f0f37356ef29 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -637,20 +637,21 @@ get_return_for_leaf(struct trace_iterator *iter,
>                           */
>                          if (unlikely(curr->ent.type == TRACE_GRAPH_RETADDR_ENT)) {
>                                  data->ent.rent = *(struct fgraph_retaddr_ent_entry *)curr;
> -                               size = offsetof(struct fgraph_retaddr_ent_entry, args);
> +                               /* fgraph_retaddr_ent_entry doesn't have args field */

"doesn't have args field" yet!

> +                               size = sizeof(struct fgraph_retaddr_ent_entry);
> +                               args_size = 0;
>                          } else {
>                                  data->ent.ent = *curr;
>                                  size = offsetof(struct ftrace_graph_ent_entry, args);
> +                               /* If this has args, then append them to after the ent. */
> +                               args_size = iter->ent_size - size;
> +                               if (args_size > sizeof(long) * FTRACE_REGS_MAX_ARGS)
> +                                       args_size = sizeof(long) * FTRACE_REGS_MAX_ARGS;
> +
> +                               if (args_size >= sizeof(long))
> +                                       memcpy((void *)&data->ent.ent + size,
> +                                              (void*)curr + size, args_size);
>                          }

Here's a different update:

-- Steve


diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index 66e1a527cf1a..a7f4b9a47a71 100644
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -27,14 +27,21 @@ struct fgraph_cpu_data {
 	unsigned long	enter_funcs[FTRACE_RETFUNC_DEPTH];
 };
 
+struct fgraph_ent_args {
+	struct ftrace_graph_ent_entry	ent;
+	/* Force the sizeof of args[] to have FTRACE_REGS_MAX_ARGS entries */
+	unsigned long			args[FTRACE_REGS_MAX_ARGS];
+};
+
 struct fgraph_data {
 	struct fgraph_cpu_data __percpu *cpu_data;
 
 	/* Place to preserve last processed entry. */
 	union {
-		struct ftrace_graph_ent_entry	ent;
+		struct fgraph_ent_args		ent;
+		/* TODO allow retaddr to have args */
 		struct fgraph_retaddr_ent_entry	rent;
-	} ent;
+	};
 	struct ftrace_graph_ret_entry	ret;
 	int				failed;
 	int				cpu;
@@ -627,10 +634,13 @@ get_return_for_leaf(struct trace_iterator *iter,
 			 * Save current and next entries for later reference
 			 * if the output fails.
 			 */
-			if (unlikely(curr->ent.type == TRACE_GRAPH_RETADDR_ENT))
-				data->ent.rent = *(struct fgraph_retaddr_ent_entry *)curr;
-			else
-				data->ent.ent = *curr;
+			if (unlikely(curr->ent.type == TRACE_GRAPH_RETADDR_ENT)) {
+				data->rent = *(struct fgraph_retaddr_ent_entry *)curr;
+			} else {
+				int size = min((int)sizeof(data->ent), (int)iter->ent_size);
+
+				memcpy(&data->ent, curr, size);
+			}
 			/*
 			 * If the next event is not a return type, then
 			 * we only care about what type it is. Otherwise we can