ftrace: Add function arguments to function tracers

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/[email protected]/

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/[email protected]/

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

index 86d828b9dc7c..cb13c88abfd6 100644
@@ -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);

index 472ec5d623db..32da87f45010 100644
@@ -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"
 

index 49fcf665cb58..71b2fb068b6b 100644
@@ -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);
 

index 0ce00fe66d0c..c8bfa7310a91 100644
@@ -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/[email protected]/

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

From: Sven Schnelle <[email protected]>

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

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

index bbc1873ca6b8..15627ceea9bc 100644
@@ -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 */

index d570b8b9c0a9..60412c1012ef 100644
@@ -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

index dca40f1f1da4..2e305364f2a9 100644
@@ -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

From: Sven Schnelle <[email protected]>

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

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

index 60412c1012ef..033fba0633cf 100644
@@ -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"

index 9c21ba45b7af..6963cd83b6da 100644
@@ -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)
 

index fbfb396905a6..77a8ba3bc1e3 100644
@@ -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

2.47.2

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

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

index 8dcce001881d..0699ec6d7554 100644
@@ -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
 }

# # + 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?

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

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

-- Steve

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

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:

index 2f077d4158e5..718f6e84cc83 100644
@@ -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

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

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

Thanks, even though I figured it out...

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

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'.

And it was expecting zero.

But it found 3 blank lines!

Hmm, don't know about that one.

-- Steve

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.

...

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

# not ok 90 Meta-selftest: Checkbashisms # UNRESOLVED

Which will be because checkbashishms is not installed.

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

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:

index 6b94b678741a..ebe2a34cbf92 100644
@@ -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

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/[email protected]/

-- Steve

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

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

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

Bah! gmail blocked that one too :-p

-- Steve

Hi, I could find it. Let me reply!

Masami Hiramatsu (Google) <[email protected]>

Oops...

Ah, I didn't know that.

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,

Masami Hiramatsu (Google) <[email protected]>

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

What does work seems to be:

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

-- Steve

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/[email protected]/

-- Steve

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

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

  data->ent.ent = *curr;

Thanks,
Sasha

No it doesn't :-p

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

-- Steve

index 66e1a527cf1a..25ea71edb8da 100644
@@ -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

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

index 66e1a527cf1a..a7f4b9a47a71 100644
@@ -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

From: Steven Rostedt <[email protected]>

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.

---
 kernel/trace/trace_functions_graph.c | 27 ++++++++++++++++++++++++++-
 1 file changed, 26 insertions(+), 1 deletion(-)

index 5049fe25ceef..71b2fb068b6b 100644
@@ -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

From: Sven Schnelle <[email protected]>

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

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

index 0e6d517e74e0..cb13c88abfd6 100644
@@ -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);

index 6963cd83b6da..32da87f45010 100644
@@ -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,

index 77a8ba3bc1e3..ee40d4e6ad1c 100644
@@ -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",

index 7294ad676379..c8bfa7310a91 100644
@@ -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)
 {

index 4b721cd4f21d..b51ee9373773 100644
@@ -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));

index af30586f1aea..c9ba4259e03e 100644
@@ -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