Date:   Sun, 12 Mar 2023 18:58:53 +0900
From:   Masami Hiramatsu (Google) <mhiramat@kernel.org>
To:     Donglin Peng <pengdonglin@sangfor.com.cn>
Cc:     rostedt@goodmis.org, xiehuan09@gmail.com, dinghui@sangfor.com.cn,
        huangcun@sangfor.com.cn, linux-trace-kernel@vger.kernel.org,
        linux-kernel@vger.kernel.org
Subject: Re: [RFC v2] function_graph: Support recording and outputing the
 return value of function
Message-Id: <20230312185853.1b85d63cfda11824fc609e18@kernel.org>
In-Reply-To: <20230312022826.10367-1-pengdonglin@sangfor.com.cn>
References: <20230312022826.10367-1-pengdonglin@sangfor.com.cn>
Mime-Version: 1.0
Content-Type: text/plain; charset=US-ASCII
Content-Transfer-Encoding: 7bit
Precedence: bulk

Hi Donglin,

This looks really interesting. There is fprobe and I'm trying introduce the
fprobe event, but that is an event trace. So this is another way to trace
the return values.

On Sat, 11 Mar 2023 18:28:26 -0800
Donglin Peng <pengdonglin@sangfor.com.cn> wrote:

> When using function_graph to analyze the reasons for system call failures,
> we need to spend a considerable amount of time analyzing the logs and
> cannot quickly locate the error. This modification aims to make this
> process easier by recording the return values of each traced function.
> When outputting trace logs, the tracing option funcgraph-retval can be
> used to control whether to display the return values. If the return value
> looks like an error code, it will be output in both hexadecimal and signed
> decimal, otherwise only hexadecimal.

Hm, this will confuse the output parser. The output should be human readable
but also machine readable. I think you can introduce an option (tracefs/options/*)
to show "smart" output or hexadecimal output always.

treacefs/options/graph_retval_hex

If this is 1, the return value is printed always in hexadecimal. If it is 0,
when the IS_ERR(retval) is true, it will show it in signed decimal, or
hexadecimal (with "0x" prefix).

> Currently, this modification supports the following commonly used processor
> architectures: x64, x86, arm64, arm, riscv.

This may also need to be reviewed by each arch maintainer. So we need
CONFIG_HAVE_FUNCTION_GRAPH_RETVAL which indicates that this architecture
support ftrace-graph retval and CONFIG_FUNCTION_GRAPH_RETVAL which
switches this retval is printed or not.

> 
> One drawback is that even if a function's return type is void, the value
> stored in the return value register will still be recorded and output.

Yeah, but I think that is no problem. We can notify user that this retval
is always be shown even if the function return type is void.

> I think the BTF files can be used to obtain the return type of kernel
> functions, but the search cost is a bit high. Therefore, we can
> implement a tool to process trace logs based on BTF information.

Agreed. Anyway for some specific functions, we can use fprobe events.

Thank you.

> 
> For example:
> 
> I want to attach the demo process to a cpu cgroup, but it failed:
> 
> echo `pidof demo` > /sys/fs/cgroup/cpu/test/tasks
> -bash: echo: write error: Invalid argument
> 
> The strace logs tells that the write system call returned -EINVAL(-22):
> ...
> write(1, "273\n", 4)                    = -1 EINVAL (Invalid argument)
> ...
> 
> Use the following commands to capture trace logs when calling the write
> system call:
> 
> cd /sys/kernel/debug/tracing/
> echo 0 > tracing_on
> echo > trace
> echo *sys_write > set_graph_function
> echo *spin* > set_graph_notrace
> echo *rcu* >> set_graph_notrace
> echo *alloc* >> set_graph_notrace
> echo preempt* >> set_graph_notrace
> echo kfree* >> set_graph_notrace
> echo $$ > set_ftrace_pid
> echo function_graph > current_tracer
> echo 1 > tracing_on
> echo `pidof demo` > /sys/fs/cgroup/cpu/test/tasks
> echo 0 > tracing_on
> echo 1 > options/funcgraph-retval
> cat trace > ~/trace.log
> 
> Search -22 directly in the trace.log and find that the function
> cpu_cgroup_can_attach returned -22 first, then read the code of this
> function to get the root cause.
> 
> ...
>  0)            |  cgroup_migrate() {
>  0)  0.521 us  |    cgroup_migrate_add_task(); /* => ffff88800cbaa000 */
>  0)  0.500 us  |    cgroup_migrate_add_task(); /* => ffff88800cbaa000 */
>  0)  0.441 us  |    cgroup_migrate_add_task(); /* => ffff88800cbaa000 */
>  0)  0.521 us  |    cgroup_migrate_add_task(); /* => ffff88800cbaa000 */
>  0)  0.421 us  |    cgroup_migrate_add_task(); /* => ffff88800cbaa000 */
>  0)  0.431 us  |    cgroup_migrate_add_task(); /* => ffff88800cbaa000 */
>  0)            |    cgroup_migrate_execute() {
>  0)            |      cpu_cgroup_can_attach() {
>  0)            |        cgroup_taskset_first() {
>  0)  0.221 us  |          cgroup_taskset_next(); /* => ffff88800e13c000 */
>  0)  0.641 us  |        } /* cgroup_taskset_first => ffff88800e13c000 */
>  0)  0.320 us  |        sched_rt_can_attach(); /* => 0 */
>  0)  1.713 us  |      } /* cpu_cgroup_can_attach => ffffffea -22 */
>  0)  3.717 us  |    } /* cgroup_migrate_execute => ffffffea -22 */
>  0)  9.959 us  |  } /* cgroup_migrate => ffffffea -22 */
> ...
> 
> Signed-off-by: Donglin Peng <pengdonglin@sangfor.com.cn>
> ---
>  arch/arm/kernel/entry-ftrace.S       |  1 +
>  arch/arm64/kernel/entry-ftrace.S     |  1 +
>  arch/riscv/kernel/mcount.S           |  2 +
>  arch/x86/kernel/ftrace_32.S          |  1 +
>  arch/x86/kernel/ftrace_64.S          |  2 +
>  include/linux/ftrace.h               |  1 +
>  kernel/trace/fgraph.c                |  3 +-
>  kernel/trace/trace.h                 |  1 +
>  kernel/trace/trace_entries.h         |  5 +-
>  kernel/trace/trace_functions_graph.c | 70 ++++++++++++++++++++++++----
>  10 files changed, 74 insertions(+), 13 deletions(-)
> 
> diff --git a/arch/arm/kernel/entry-ftrace.S b/arch/arm/kernel/entry-ftrace.S
> index 3e7bcaca5e07..c6666c0d909c 100644
> --- a/arch/arm/kernel/entry-ftrace.S
> +++ b/arch/arm/kernel/entry-ftrace.S
> @@ -258,6 +258,7 @@ ENDPROC(ftrace_graph_regs_caller)
>  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
>  ENTRY(return_to_handler)
>  	stmdb	sp!, {r0-r3}
> +	mov	r1, r0			@ pass the return value
>  	add	r0, sp, #16		@ sp at exit of instrumented routine
>  	bl	ftrace_return_to_handler
>  	mov	lr, r0			@ r0 has real ret addr
> diff --git a/arch/arm64/kernel/entry-ftrace.S b/arch/arm64/kernel/entry-ftrace.S
> index 350ed81324ac..0eb9a0e3ba3d 100644
> --- a/arch/arm64/kernel/entry-ftrace.S
> +++ b/arch/arm64/kernel/entry-ftrace.S
> @@ -276,6 +276,7 @@ SYM_CODE_START(return_to_handler)
>  	stp x4, x5, [sp, #32]
>  	stp x6, x7, [sp, #48]
>  
> +	mov	x1, x0			// pass the return value
>  	mov	x0, x29			//     parent's fp
>  	bl	ftrace_return_to_handler// addr = ftrace_return_to_hander(fp);
>  	mov	x30, x0			// restore the original return address
> diff --git a/arch/riscv/kernel/mcount.S b/arch/riscv/kernel/mcount.S
> index 30102aadc4d7..afce5abcbcd2 100644
> --- a/arch/riscv/kernel/mcount.S
> +++ b/arch/riscv/kernel/mcount.S
> @@ -69,6 +69,8 @@ ENTRY(return_to_handler)
>  	mv	t6, s0
>  #endif
>  	SAVE_RET_ABI_STATE
> +	/* pass the return value to ftrace_return_to_handler */
> +	mv	a1, a0
>  #ifdef HAVE_FUNCTION_GRAPH_FP_TEST
>  	mv	a0, t6
>  #endif
> diff --git a/arch/x86/kernel/ftrace_32.S b/arch/x86/kernel/ftrace_32.S
> index a0ed0e4a2c0c..7611374ccce8 100644
> --- a/arch/x86/kernel/ftrace_32.S
> +++ b/arch/x86/kernel/ftrace_32.S
> @@ -184,6 +184,7 @@ SYM_CODE_END(ftrace_graph_caller)
>  return_to_handler:
>  	pushl	%eax
>  	pushl	%edx
> +	movl	%eax, %edx	#  2nd argument: the return value
>  	movl	$0, %eax
>  	call	ftrace_return_to_handler
>  	movl	%eax, %ecx
> diff --git a/arch/x86/kernel/ftrace_64.S b/arch/x86/kernel/ftrace_64.S
> index 1265ad519249..d685b773e7ad 100644
> --- a/arch/x86/kernel/ftrace_64.S
> +++ b/arch/x86/kernel/ftrace_64.S
> @@ -348,6 +348,8 @@ SYM_CODE_START(return_to_handler)
>  	movq %rax, (%rsp)
>  	movq %rdx, 8(%rsp)
>  	movq %rbp, %rdi
> +	/* Pass the return value to ftrace_return_to_handler */
> +	movq %rax, %rsi
>  
>  	call ftrace_return_to_handler
>  
> diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
> index 366c730beaa3..157fd25be2b7 100644
> --- a/include/linux/ftrace.h
> +++ b/include/linux/ftrace.h
> @@ -1032,6 +1032,7 @@ struct ftrace_graph_ent {
>   */
>  struct ftrace_graph_ret {
>  	unsigned long func; /* Current function */
> +	unsigned long retval;
>  	int depth;
>  	/* Number of functions that overran the depth limit for current task */
>  	unsigned int overrun;
> diff --git a/kernel/trace/fgraph.c b/kernel/trace/fgraph.c
> index 218cd95bf8e4..006b39a98dc3 100644
> --- a/kernel/trace/fgraph.c
> +++ b/kernel/trace/fgraph.c
> @@ -240,12 +240,13 @@ static struct notifier_block ftrace_suspend_notifier = {
>   * Send the trace to the ring-buffer.
>   * @return the original return address.
>   */
> -unsigned long ftrace_return_to_handler(unsigned long frame_pointer)
> +unsigned long ftrace_return_to_handler(unsigned long frame_pointer, unsigned long retval)
>  {
>  	struct ftrace_graph_ret trace;
>  	unsigned long ret;
>  
>  	ftrace_pop_return_trace(&trace, &ret, frame_pointer);
> +	trace.retval = retval;
>  	trace.rettime = trace_clock_local();
>  	ftrace_graph_return(&trace);
>  	/*
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index 616e1aa1c4da..5ef32c6e1d45 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -831,6 +831,7 @@ static __always_inline bool ftrace_hash_empty(struct ftrace_hash *hash)
>  #define TRACE_GRAPH_PRINT_TAIL          0x100
>  #define TRACE_GRAPH_SLEEP_TIME          0x200
>  #define TRACE_GRAPH_GRAPH_TIME          0x400
> +#define TRACE_GRAPH_PRINT_RETVAL        0x800
>  #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 cd41e863b51c..d798cb17546f 100644
> --- a/kernel/trace/trace_entries.h
> +++ b/kernel/trace/trace_entries.h
> @@ -93,16 +93,17 @@ FTRACE_ENTRY_PACKED(funcgraph_exit, ftrace_graph_ret_entry,
>  	F_STRUCT(
>  		__field_struct(	struct ftrace_graph_ret,	ret	)
>  		__field_packed(	unsigned long,	ret,		func	)
> +		__field_packed(	unsigned long,	ret,		retval	)
>  		__field_packed(	int,		ret,		depth	)
>  		__field_packed(	unsigned int,	ret,		overrun	)
>  		__field_packed(	unsigned long long, ret,	calltime)
>  		__field_packed(	unsigned long long, ret,	rettime	)
>  	),
>  
> -	F_printk("<-- %ps (%d) (start: %llx  end: %llx) over: %d",
> +	F_printk("<-- %ps (%d) (start: %llx  end: %llx) over: %d retval: %lx",
>  		 (void *)__entry->func, __entry->depth,
>  		 __entry->calltime, __entry->rettime,
> -		 __entry->depth)
> +		 __entry->depth, __entry->retval)
>  );
>  
>  /*
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index 203204cadf92..706d3e5c2156 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -58,6 +58,8 @@ static struct tracer_opt trace_opts[] = {
>  	{ TRACER_OPT(funcgraph-irqs, TRACE_GRAPH_PRINT_IRQS) },
>  	/* Display function name after trailing } */
>  	{ TRACER_OPT(funcgraph-tail, TRACE_GRAPH_PRINT_TAIL) },
> +	/* Display function return value */
> +	{ TRACER_OPT(funcgraph-retval, TRACE_GRAPH_PRINT_RETVAL) },
>  	/* Include sleep time (scheduled out) between entry and return */
>  	{ TRACER_OPT(sleep-time, TRACE_GRAPH_SLEEP_TIME) },
>  
> @@ -619,6 +621,43 @@ print_graph_duration(struct trace_array *tr, unsigned long long duration,
>  	trace_seq_puts(s, "|  ");
>  }
>  
> +static void print_graph_retval(struct trace_seq *s, unsigned long retval,
> +				bool leaf, void *func)
> +{
> +	unsigned long err_code = 0;
> +
> +	if (retval == 0)
> +		goto done;
> +
> +	/* Guess whether the retval looks like an error code */
> +	if ((retval & BIT(7)) && (retval >> 8) == 0)
> +		err_code = (unsigned long)(s8)retval;
> +	else if ((retval & BIT(15)) && (retval >> 16) == 0)
> +		err_code = (unsigned long)(s16)retval;
> +	else if ((retval & BIT(31)) && (((u64)retval) >> 32) == 0)
> +		err_code = (unsigned long)(s32)retval;
> +	else
> +		err_code = retval;
> +
> +	if (!IS_ERR_VALUE(err_code))
> +		err_code = 0;
> +
> +done:
> +	if (leaf) {
> +		if (err_code != 0)
> +			trace_seq_printf(s, "%ps(); /* => %lx %ld */\n",
> +				func, retval, err_code);
> +		else
> +			trace_seq_printf(s, "%ps(); /* => %lx */\n", func, retval);
> +	} else {
> +		if (err_code != 0)
> +			trace_seq_printf(s, "} /* %ps => %lx %ld */\n",
> +				func, retval, err_code);
> +		else
> +			trace_seq_printf(s, "} /* %ps => %lx */\n", func, retval);
> +	}
> +}
> +
>  /* Case of a leaf function on its call entry */
>  static enum print_line_t
>  print_graph_entry_leaf(struct trace_iterator *iter,
> @@ -663,7 +702,10 @@ print_graph_entry_leaf(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);
> +	if (flags & TRACE_GRAPH_PRINT_RETVAL)
> +		print_graph_retval(s, graph_ret->retval, true, (void *)call->func);
> +	else
> +		trace_seq_printf(s, "%ps();\n", (void *)call->func);
>  
>  	print_graph_irq(iter, graph_ret->func, TRACE_GRAPH_RET,
>  			cpu, iter->ent->pid, flags);
> @@ -942,16 +984,24 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
>  		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.
> +	 * Always write out the function name and its return value if the
> +	 * function-retval 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);
> +	if (flags & TRACE_GRAPH_PRINT_RETVAL) {
> +		print_graph_retval(s, trace->retval, false, (void *)trace->func);
> +	} 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);
> +	}
>  
>  	/* Overrun */
>  	if (flags & TRACE_GRAPH_PRINT_OVERRUN)
> -- 
> 2.25.1
> 


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