@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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;
@@ -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);
/*
@@ -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)
@@ -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)
);
/*
@@ -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)
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. Currently, this modification supports the following commonly used processor architectures: x64, x86, arm64, arm, riscv. 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. I think the BTF file 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 the trace logs based on BTF information. 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 */ ... After processing the trace.log above with the btf tool: ... 0) | cgroup_migrate() { 0) 0.521 us | cgroup_migrate_add_task(); 0) 0.500 us | cgroup_migrate_add_task(); 0) 0.441 us | cgroup_migrate_add_task(); 0) 0.521 us | cgroup_migrate_add_task(); 0) 0.421 us | cgroup_migrate_add_task(); 0) 0.431 us | cgroup_migrate_add_task(); 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 => -22 */ 0) 3.717 us | } /* cgroup_migrate_execute => -22 */ 0) 9.959 us | } /* cgroup_migrate => -22 */ ... Signed-off-by: Donglin Peng <pengdonglin@sangfor.com.cn> --- v3: - modify the commit message: add trace logs processed with the btf tool v2: - modify the commit message: use BTF to get the return type of function --- 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(-)