Re: [PATCH 6/7] tracing: add support for function argument to graph tracer

[Steven Rostedt]

On Wed,  4 Sep 2024 08:59:00 +0200
Sven Schnelle <svens@xxxxxxxxxxxxx> wrote:

> Wire up the code to print function arguments in the function graph
> tracer. This functionality can be enabled/disabled during compile
> time by setting CONFIG_FUNCTION_TRACE_ARGS and during runtime with
> options/funcgraph-args.

I finally got around to looking at your patches. Do you plan on still
working on them? I really like this feature, and I'm willing to do the work
too if you have other things on your plate.

> 
> 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    |     }
> 
> Signed-off-by: Sven Schnelle <svens@xxxxxxxxxxxxx>
> ---
>  include/linux/ftrace.h               |  1 +
>  kernel/trace/fgraph.c                |  6 ++-
>  kernel/trace/trace_functions_graph.c | 74 ++++++++++++++--------------
>  3 files changed, 44 insertions(+), 37 deletions(-)

BTW, this is missing:

diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 2f8017f8d34d..8a218b39d11d 100644
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -879,6 +879,7 @@ static __always_inline bool ftrace_hash_empty(struct ftrace_hash *hash)
 #define TRACE_GRAPH_GRAPH_TIME          0x400
 #define TRACE_GRAPH_PRINT_RETVAL        0x800
 #define TRACE_GRAPH_PRINT_RETVAL_HEX    0x1000
+#define TRACE_GRAPH_ARGS		0x2000
 #define TRACE_GRAPH_PRINT_FILL_SHIFT	28
 #define TRACE_GRAPH_PRINT_FILL_MASK	(0x3 << TRACE_GRAPH_PRINT_FILL_SHIFT)
 
that you added in patch 7, but is needed for this patch, where it does not
build without it.

> 
> diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
> index 56d91041ecd2..5d0ff66f8a70 100644
> --- a/include/linux/ftrace.h
> +++ b/include/linux/ftrace.h
> @@ -1010,6 +1010,7 @@ static inline void ftrace_init(void) { }
>   * to remove extra padding at the end.
>   */
>  struct ftrace_graph_ent {
> +	struct ftrace_regs regs;
>  	unsigned long func; /* Current function */
>  	int depth;
>  } __packed;

This should have a different event type, to not waste the ring buffer when
not needed.

struct ftrace_graph_ent_args {
	struct ftrace_regs_args fargs;
	unsigned long func; /* Current function */
	int depth;
} __packed;

But also, we need to create a new structure, as nothing should depend on
the size of ftrace_regs (we plan on hiding that completely). I can add a
"struct ftrace_regs_args" that will hold just the args for each arch.
Especially for archs (like x86) where ftrace_regs can be pt_regs in size,
where most of the space is just wasted. Then we can do a:

	ftrace_regs_copy_args(fregs, &entry->addr);

And then:

	char buf[ftrace_regs_size()];
	struct ftrace_regs *fregs = &buf;

	ftrace_regs_from_args(fregs, &entry->addr);

to get the arguments.




> diff --git a/kernel/trace/fgraph.c b/kernel/trace/fgraph.c
> index fa62ebfa0711..f4bb10c0aa52 100644
> --- a/kernel/trace/fgraph.c
> +++ b/kernel/trace/fgraph.c
> @@ -614,7 +614,7 @@ ftrace_push_return_trace(unsigned long ret, unsigned long func,
>  /* If the caller does not use ftrace, call this function. */
>  int function_graph_enter(unsigned long ret, unsigned long func,
>  			 unsigned long frame_pointer, unsigned long *retp,
> -			struct ftrace_regs *fregs)
> +			 struct ftrace_regs *fregs)
>  {
>  	struct ftrace_graph_ent trace;
>  	unsigned long bitmap = 0;
> @@ -623,6 +623,10 @@ int function_graph_enter(unsigned long ret, unsigned long func,
>  
>  	trace.func = func;
>  	trace.depth = ++current->curr_ret_depth;
> +	if (IS_ENABLED(CONFIG_FUNCTION_TRACE_ARGS) && fregs)
> +		trace.regs = *fregs;
> +	else
> +		memset(&trace.regs, 0, sizeof(struct ftrace_regs));
>  
>  	offset = ftrace_push_return_trace(ret, func, frame_pointer, retp, 0);
>  	if (offset < 0)
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index 13d0387ac6a6..be0cee52944a 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -12,6 +12,8 @@
>  #include <linux/interrupt.h>
>  #include <linux/slab.h>
>  #include <linux/fs.h>
> +#include <linux/btf.h>
> +#include <linux/bpf.h>
>  
>  #include "trace.h"
>  #include "trace_output.h"
> @@ -63,6 +65,9 @@ static struct tracer_opt trace_opts[] = {
>  	{ TRACER_OPT(funcgraph-retval, TRACE_GRAPH_PRINT_RETVAL) },
>  	/* Display function return value in hexadecimal format ? */
>  	{ TRACER_OPT(funcgraph-retval-hex, TRACE_GRAPH_PRINT_RETVAL_HEX) },
> +#endif
> +#ifdef CONFIG_FUNCTION_TRACE_ARGS
> +	{ 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) },
> @@ -653,7 +658,7 @@ print_graph_duration(struct trace_array *tr, unsigned long long duration,
>  #define __TRACE_GRAPH_PRINT_RETVAL TRACE_GRAPH_PRINT_RETVAL
>  
>  static void print_graph_retval(struct trace_seq *s, unsigned long retval,
> -				bool leaf, void *func, bool hex_format)
> +			       bool hex_format)
>  {
>  	unsigned long err_code = 0;
>  
> @@ -673,28 +678,17 @@ static void print_graph_retval(struct trace_seq *s, unsigned long retval,
>  		err_code = 0;
>  
>  done:
> -	if (leaf) {
> -		if (hex_format || (err_code == 0))
> -			trace_seq_printf(s, "%ps(); /* = 0x%lx */\n",
> -					func, retval);
> -		else
> -			trace_seq_printf(s, "%ps(); /* = %ld */\n",
> -					func, err_code);
> -	} else {
> -		if (hex_format || (err_code == 0))
> -			trace_seq_printf(s, "} /* %ps = 0x%lx */\n",
> -					func, retval);
> -		else
> -			trace_seq_printf(s, "} /* %ps = %ld */\n",
> -					func, err_code);
> -	}
> +	if (hex_format || (err_code == 0))
> +		trace_seq_printf(s, " /* = 0x%lx */", retval);
> +	else
> +		trace_seq_printf(s, " /* = %ld */", err_code);
>  }
>  
>  #else
>  
>  #define __TRACE_GRAPH_PRINT_RETVAL 0
>  
> -#define print_graph_retval(_seq, _retval, _leaf, _func, _format) do {} while (0)
> +#define print_graph_retval(_seq, _retval, _format) do {} while (0)
>  
>  #endif
>  
> @@ -741,16 +735,20 @@ print_graph_entry_leaf(struct trace_iterator *iter,
>  	/* Function */
>  	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++)
>  		trace_seq_putc(s, ' ');
> +	trace_seq_printf(s, "%ps", (void *)graph_ret->func);
> +	if (flags & TRACE_GRAPH_ARGS)
> +		print_function_args(s, &call->regs, graph_ret->func);

Ideally, the flag is going to be set when args is recorded and not used for
printing. If the event is the ftrace_ent_args() this will print the
arguments, otherwise it does not.

To simplify these functions, we probably need to have a:

union fgraph_entry {
	struct ftrace_graph_ent		*normal;
	struct ftrace_graph_ent_args	*args;
};

And switch depending which is which (the header of both is the same as is
for all entries).

-- Steve


> +	else
> +		trace_seq_puts(s, "();");
>  
>  	/*
>  	 * Write out the function return value if the option function-retval is
>  	 * enabled.
>  	 */
>  	if (flags & __TRACE_GRAPH_PRINT_RETVAL)
> -		print_graph_retval(s, graph_ret->retval, true, (void *)call->func,
> -				!!(flags & TRACE_GRAPH_PRINT_RETVAL_HEX));
> -	else
> -		trace_seq_printf(s, "%ps();\n", (void *)call->func);
> +		print_graph_retval(s, graph_ret->retval,
> +				   !!(flags & TRACE_GRAPH_PRINT_RETVAL_HEX));
> +	trace_seq_printf(s, "\n");
>  
>  	print_graph_irq(iter, graph_ret->func, TRACE_GRAPH_RET,
>  			cpu, iter->ent->pid, flags);
> @@ -788,7 +786,12 @@ print_graph_entry_nested(struct trace_iterator *iter,
>  	for (i = 0; i < call->depth * TRACE_GRAPH_INDENT; i++)
>  		trace_seq_putc(s, ' ');
>  
> -	trace_seq_printf(s, "%ps() {\n", (void *)call->func);
> +	trace_seq_printf(s, "%ps", (void *)call->func);
> +	if (flags & TRACE_GRAPH_ARGS)
> +		print_function_args(s, &call->regs, call->func);
> +	else
> +		trace_seq_puts(s, "()");
> +	trace_seq_printf(s, " {\n");
>  
>  	if (trace_seq_has_overflowed(s))
>  		return TRACE_TYPE_PARTIAL_LINE;
> @@ -1028,27 +1031,26 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
>  	for (i = 0; i < trace->depth * TRACE_GRAPH_INDENT; i++)
>  		trace_seq_putc(s, ' ');
>  
> +	/*
> +	 * If the return function does not have a matching entry,
> +	 * then the entry was lost. Instead of just printing
> +	 * the '}' and letting the user guess what function this
> +	 * belongs to, write out the function name. Always do
> +	 * that if the funcgraph-tail option is enabled.
> +	 */
> +	if (func_match && !(flags & TRACE_GRAPH_PRINT_TAIL))
> +		trace_seq_puts(s, "}");
> +	else
> +		trace_seq_printf(s, "} /* %ps */", (void *)trace->func);
>  	/*
>  	 * Always write out the function name and its return value if the
>  	 * function-retval option is enabled.
>  	 */
>  	if (flags & __TRACE_GRAPH_PRINT_RETVAL) {
> -		print_graph_retval(s, trace->retval, false, (void *)trace->func,
> +		print_graph_retval(s, trace->retval,
>  			!!(flags & TRACE_GRAPH_PRINT_RETVAL_HEX));
> -	} else {
> -		/*
> -		 * If the return function does not have a matching entry,
> -		 * then the entry was lost. Instead of just printing
> -		 * the '}' and letting the user guess what function this
> -		 * belongs to, write out the function name. Always do
> -		 * that if the funcgraph-tail option is enabled.
> -		 */
> -		if (func_match && !(flags & TRACE_GRAPH_PRINT_TAIL))
> -			trace_seq_puts(s, "}\n");
> -		else
> -			trace_seq_printf(s, "} /* %ps */\n", (void *)trace->func);
>  	}
> -
> +	trace_seq_printf(s, "\n");
>  	/* Overrun */
>  	if (flags & TRACE_GRAPH_PRINT_OVERRUN)
>  		trace_seq_printf(s, " (Overruns: %u)\n",