Re: [RFC PATCH] function_graph: Support recording and printing the function return address
From: Song Chen
Date: Sun Sep 08 2024 - 22:03:42 EST
it's a practical improvement for me, save time to read code. btw, how is
the overhead?
/Song
在 2024/9/8 22:25, Donglin Peng 写道:
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
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,