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

[Donglin Peng]

On Mon, Sep 9, 2024 at 11:04 PM Steven Rostedt <rostedt@xxxxxxxxxxx> wrote:
>
> On Sun,  8 Sep 2024 07:25:44 -0700
> Donglin Peng <dolinux.peng@xxxxxxxxx> wrote:
>
> Hi Donglin!
>
> > 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 */
>
> I wonder if we should make this look more like the function tracer when it
> shows the parent. That is:
>
>   4)               |  load_elf_binary() { /* <-bprm_execve+0x249/0x600 */

Nice, Is it necessary to add a prefix letter for the return value? For
example, when
 both funcgraph-retval and funcgraph-retaddr are enabled, like this:

         avc_policy_seqno(); /* <-selinux_file_permission+0x107/0x140 V=0x0 */

>
> > 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
> >
> > 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           )
> >       ),
> >
>
> Let's make this a new event, so that when this option is not enabled, we
> don't waste the ring buffer. For function tracing, every element added to
> the event will add megabytes extra to the ring buffer.
>
> It should be possible to switch what event gets created at the time of the
> trace. Even calling different functions to do it.

Sounds good, we may create a new event as follows:

struct ftrace_graph_ent {
unsigned long func; /* Current function */
unsigned long retaddr;
int depth;
} __packed;

FTRACE_ENTRY_PACKED(funcgraph_retaddr_entry, ftrace_graph_ent_readdr_entry,

TRACE_GRAPH_RETADDR_ENT,

F_STRUCT(
__field_struct( struct ftrace_graph_retaddr_ent, graph_retaddr_ent )
__field_packed( unsigned long, graph_retaddr_ent, func )
__field_packed( unsigned long, graph_retaddr_ent, retaddr )
__field_packed( int, graph_retaddr_ent, depth )
),

F_printk("--> %ps (%d)", (void *)__entry->func, __entry->depth)
);

If we were to introduce another new feature such as funcgraph-args which
adds a `ftrace_regs` to the `ftrace_graph_ent`, would it be necessary to
create yet another new event?

 In the scenario where both funcgrah-retaddr and funcgraph-args are enabled,
it is possible that an additional new event may also be required.

>
> Thanks,
>
> -- Steve
>
>
> > @@ -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,