Re: [RFC PATCH] function_graph: Support recording and printing the function return address

From: Jeff Xie
Date: Mon Sep 09 2024 - 21:08:10 EST

On Sun, Sep 8, 2024 at 10:26 PM Donglin Peng <dolinux.peng@xxxxxxxxx> wrote:
>
> When using function_graph tracer to analyze the flow of kernel function
> execution, it is often necessary to quickly locate the exact line of code
> where the call occurs. While this may be easy at times, it can be more
> time-consuming when some functions are inlined or the flow is too long.
>
> This feature aims to simplify the process by recording the return address
> of traced funcions and printing it when outputing trace logs.
>
> To distinguish the return value, 'V=' is used as the prefix for the kernel
> return value, and 'A=' is used as the prefix for the return address in trace
> logs. A new trace option named 'funcgraph-retaddr' has been added, and the
> option 'sym-addr' can control the format of the return address.
>
> See below logs with both funcgraph-retval and funcgraph-retaddr enabled.
>
> 4) | load_elf_binary() { /* A=bprm_execve+0x249/0x600 */
> 4) | load_elf_phdrs() { /* A=load_elf_binary+0x84/0x1730 */
> 4) | __kmalloc_noprof() { /* A=load_elf_phdrs+0x4a/0xb0 */
> 4) + 47.910 us | __cond_resched(); /* V=0x0 A=__kmalloc_noprof+0x28c/0x390 */
> 4) ! 204.142 us | } /* __kmalloc_noprof V=0xffff888201e32c00 */
> 4) | kernel_read() { /* A=load_elf_phdrs+0x6c/0xb0 */
> 4) | rw_verify_area() { /* A=kernel_read+0x2b/0x50 */
> 4) | security_file_permission() {
> 4) | selinux_file_permission() { /* A=security_file_permission+0x26/0x40 */
> 4) | __inode_security_revalidate() { /* A=selinux_file_permission+0x6d/0x140 */
> 4) 1.182 us | __cond_resched(); /* V=0x0 A=__inode_security_revalidate+0x5f/0x80 */
> 4) 4.138 us | } /* __inode_security_revalidate V=0x0 */
> 4) 1.513 us | avc_policy_seqno(); /* V=0x0 A=selinux_file_permission+0x107/0x140 */
> 4) + 12.133 us | } /* selinux_file_permission V=0x0 */
> 4) + 39.834 us | } /* security_file_permission V=0x0 */
> 4) + 42.710 us | } /* rw_verify_area V=0x0 */
>
> Then, we can use the faddr2line to locate the source code, for example:
>
> $ ./scripts/faddr2line ./vmlinux load_elf_phdrs+0x6c/0xb0
> load_elf_phdrs+0x6c/0xb0:
> elf_read at fs/binfmt_elf.c:471
> (inlined by) load_elf_phdrs at fs/binfmt_elf.c:531

That's a great idea; I often use it that way. However, I used both the
function tracer and the function graph simultaneously
because the function tracer can also show context messages, such as
displaying 'd.h3.'

Example:
<idle>-0 [001] d.h3. 41.119330: __napi_schedule+0x4/0x90 <-e1000_intr+0x8d/0x110

I suggest that we consider displaying the results of both the function
tracer and the function graph together in the same instance ;-)

> Signed-off-by: Donglin Peng <dolinux.peng@xxxxxxxxx>
> ---
> include/linux/ftrace.h | 1 +
> kernel/trace/fgraph.c | 1 +
> kernel/trace/trace.h | 1 +
> kernel/trace/trace_entries.h | 19 ++++-
> kernel/trace/trace_functions_graph.c | 105 ++++++++++++++++++---------
> 5 files changed, 92 insertions(+), 35 deletions(-)
>
> diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h
> index fd5e84d0ec47..bdf51163b3b8 100644
> --- a/include/linux/ftrace.h
> +++ b/include/linux/ftrace.h
> @@ -1011,6 +1011,7 @@ static inline void ftrace_init(void) { }
> */
> struct ftrace_graph_ent {
> unsigned long func; /* Current function */
> + unsigned long retaddr; /* Return address */
> int depth;
> } __packed;
>
> diff --git a/kernel/trace/fgraph.c b/kernel/trace/fgraph.c
> index d7d4fb403f6f..fcc4162c10f6 100644
> --- a/kernel/trace/fgraph.c
> +++ b/kernel/trace/fgraph.c
> @@ -622,6 +622,7 @@ int function_graph_enter(unsigned long ret, unsigned long func,
>
> trace.func = func;
> trace.depth = ++current->curr_ret_depth;
> + trace.retaddr = ret;
>
> offset = ftrace_push_return_trace(ret, func, frame_pointer, retp, 0);
> if (offset < 0)
> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
> index bd3e3069300e..87e02815b030 100644
> --- a/kernel/trace/trace.h
> +++ b/kernel/trace/trace.h
> @@ -870,6 +870,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_PRINT_RETADDR 0x2000
> #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 c47422b20908..8b8753319dd3 100644
> --- a/kernel/trace/trace_entries.h
> +++ b/kernel/trace/trace_entries.h
> @@ -71,6 +71,7 @@ FTRACE_ENTRY_REG(function, ftrace_entry,
> perf_ftrace_event_register
> );
>
> +#ifdef CONFIG_FUNCTION_GRAPH_RETVAL
> /* Function call entry */
> FTRACE_ENTRY_PACKED(funcgraph_entry, ftrace_graph_ent_entry,
>
> @@ -79,6 +80,7 @@ FTRACE_ENTRY_PACKED(funcgraph_entry, ftrace_graph_ent_entry,
> F_STRUCT(
> __field_struct( struct ftrace_graph_ent, graph_ent )
> __field_packed( unsigned long, graph_ent, func )
> + __field_packed( unsigned long, graph_ent, retaddr )
> __field_packed( int, graph_ent, depth )
> ),
>
> @@ -86,8 +88,6 @@ FTRACE_ENTRY_PACKED(funcgraph_entry, ftrace_graph_ent_entry,
> );
>
> /* Function return entry */
> -#ifdef CONFIG_FUNCTION_GRAPH_RETVAL
> -
> FTRACE_ENTRY_PACKED(funcgraph_exit, ftrace_graph_ret_entry,
>
> TRACE_GRAPH_RET,
> @@ -110,6 +110,21 @@ FTRACE_ENTRY_PACKED(funcgraph_exit, ftrace_graph_ret_entry,
>
> #else
>
> +/* Function call entry */
> +FTRACE_ENTRY_PACKED(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 )
> + ),
> +
> + F_printk("--> %ps (%d)", (void *)__entry->func, __entry->depth)
> +);
> +
> +/* Function return entry */
> FTRACE_ENTRY_PACKED(funcgraph_exit, ftrace_graph_ret_entry,
>
> TRACE_GRAPH_RET,
> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
> index 13d0387ac6a6..655535d57763 100644
> --- a/kernel/trace/trace_functions_graph.c
> +++ b/kernel/trace/trace_functions_graph.c
> @@ -63,6 +63,8 @@ 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) },
> + /* Display function return address ? */
> + { TRACER_OPT(funcgraph-retaddr, TRACE_GRAPH_PRINT_RETADDR) },
> #endif
> /* Include sleep time (scheduled out) between entry and return */
> { TRACER_OPT(sleep-time, TRACE_GRAPH_SLEEP_TIME) },
> @@ -651,50 +653,86 @@ print_graph_duration(struct trace_array *tr, unsigned long long duration,
> #ifdef CONFIG_FUNCTION_GRAPH_RETVAL
>
> #define __TRACE_GRAPH_PRINT_RETVAL TRACE_GRAPH_PRINT_RETVAL
> +#define __TRACE_GRAPH_PRINT_RETADDR TRACE_GRAPH_PRINT_RETADDR
>
> -static void print_graph_retval(struct trace_seq *s, unsigned long retval,
> - bool leaf, void *func, bool hex_format)
> +static bool print_graph_retaddr(struct trace_seq *s, struct ftrace_graph_ent *graph_ent,
> + u32 trace_flags, bool comment)
> {
> - unsigned long err_code = 0;
> + if (unlikely(graph_ent->retaddr ==
> + (unsigned long)dereference_kernel_function_descriptor(return_to_handler)))
> + return false;
>
> - if (retval == 0 || hex_format)
> - goto done;
> + if (comment)
> + trace_seq_puts(s, " /*");
>
> - /* Check if the return value matches the negative format */
> - if (IS_ENABLED(CONFIG_64BIT) && (retval & BIT(31)) &&
> - (((u64)retval) >> 32) == 0) {
> - /* sign extension */
> - err_code = (unsigned long)(s32)retval;
> - } else {
> - err_code = retval;
> + trace_seq_puts(s, " A=");
> + seq_print_ip_sym(s, graph_ent->retaddr, trace_flags | TRACE_ITER_SYM_OFFSET);
> +
> + if (comment)
> + trace_seq_puts(s, " */");
> +
> + return true;
> +}
> +
> +static void print_graph_retval(struct trace_seq *s, struct ftrace_graph_ent *graph_ent,
> + struct ftrace_graph_ret *graph_ret,
> + u32 opt_flags, u32 trace_flags)
> +{
> + unsigned long err_code = 0;
> + unsigned long retval = graph_ret->retval;
> + bool hex_format = !!(opt_flags & TRACE_GRAPH_PRINT_RETVAL_HEX);
> + bool print_retaddr = !!(opt_flags & TRACE_GRAPH_PRINT_RETADDR);
> + bool print_retval = !!(opt_flags & TRACE_GRAPH_PRINT_RETVAL);
> + void *func = (void *)graph_ret->func;
> +
> + if (print_retval && retval && !hex_format) {
> + /* Check if the return value matches the negative format */
> + if (IS_ENABLED(CONFIG_64BIT) && (retval & BIT(31)) &&
> + (((u64)retval) >> 32) == 0) {
> + err_code = sign_extend64(retval, 31);
> + } else {
> + err_code = retval;
> + }
> +
> + if (!IS_ERR_VALUE(err_code))
> + err_code = 0;
> }
>
> - if (!IS_ERR_VALUE(err_code))
> - err_code = 0;
> + if (print_retaddr && graph_ent && unlikely(graph_ent->retaddr ==
> + (unsigned long)dereference_kernel_function_descriptor(return_to_handler)))
> + print_retaddr = false;
>
> -done:
> - if (leaf) {
> - if (hex_format || (err_code == 0))
> - trace_seq_printf(s, "%ps(); /* = 0x%lx */\n",
> - func, retval);
> + if (graph_ent) {
> + trace_seq_printf(s, "%ps();", func);
> + if (print_retval || print_retaddr)
> + trace_seq_puts(s, " /*");
> else
> - trace_seq_printf(s, "%ps(); /* = %ld */\n",
> - func, err_code);
> + trace_seq_putc(s, '\n');
> } else {
> + print_retaddr = false;
> + trace_seq_printf(s, "} /* %ps", func);
> + }
> +
> + if (print_retval) {
> if (hex_format || (err_code == 0))
> - trace_seq_printf(s, "} /* %ps = 0x%lx */\n",
> - func, retval);
> + trace_seq_printf(s, " V=0x%lx", retval);
> else
> - trace_seq_printf(s, "} /* %ps = %ld */\n",
> - func, err_code);
> + trace_seq_printf(s, " V=%ld", err_code);
> }
> +
> + if (print_retaddr)
> + print_graph_retaddr(s, graph_ent, trace_flags, false);
> +
> + if (!graph_ent || print_retval || print_retaddr)
> + trace_seq_puts(s, " */\n");
> }
>
> #else
>
> #define __TRACE_GRAPH_PRINT_RETVAL 0
> +#define __TRACE_GRAPH_PRINT_RETADDR 0
>
> -#define print_graph_retval(_seq, _retval, _leaf, _func, _format) do {} while (0)
> +#define print_graph_retval(_seq, _ent, _ret, _opt_flags, _trace_flags) do {} while (0)
>
> #endif
>
> @@ -746,9 +784,8 @@ print_graph_entry_leaf(struct trace_iterator *iter,
> * 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));
> + if (flags & (__TRACE_GRAPH_PRINT_RETVAL | __TRACE_GRAPH_PRINT_RETADDR))
> + print_graph_retval(s, call, graph_ret, flags, tr->trace_flags);
> else
> trace_seq_printf(s, "%ps();\n", (void *)call->func);
>
> @@ -788,7 +825,10 @@ 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_PRINT_RETADDR)
> + print_graph_retaddr(s, call, tr->trace_flags, true);
> + trace_seq_putc(s, '\n');
>
> if (trace_seq_has_overflowed(s))
> return TRACE_TYPE_PARTIAL_LINE;
> @@ -1032,9 +1072,8 @@ print_graph_return(struct ftrace_graph_ret *trace, struct trace_seq *s,
> * 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,
> - !!(flags & TRACE_GRAPH_PRINT_RETVAL_HEX));
> + if (flags & (__TRACE_GRAPH_PRINT_RETVAL | __TRACE_GRAPH_PRINT_RETADDR)) {
> + print_graph_retval(s, NULL, trace, flags, tr->trace_flags);
> } else {
> /*
> * If the return function does not have a matching entry,
> --
> 2.25.1
>
>


--
Thanks,
JeffXie