[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <CAErzpmtJHhZpFg0sHtffexM0Lu6y2xzbVZ1SXGxKob_Dz0+Bfw@mail.gmail.com>
Date: Tue, 10 Sep 2024 14:15:39 +0800
From: Donglin Peng <dolinux.peng@...il.com>
To: Steven Rostedt <rostedt@...dmis.org>
Cc: mhiramat@...nel.org, mark.rutland@....com, mathieu.desnoyers@...icios.com,
linux-trace-kernel@...r.kernel.org, linux-kernel@...r.kernel.org
Subject: Re: [RFC PATCH] function_graph: Support recording and printing the
function return address
On Mon, Sep 9, 2024 at 11:04 PM Steven Rostedt <rostedt@...dmis.org> wrote:
>
> On Sun, 8 Sep 2024 07:25:44 -0700
> Donglin Peng <dolinux.peng@...il.com> 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@...il.com>
> > ---
> > 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,
Powered by blists - more mailing lists