| Message ID | 20230312022826.10367-1-pengdonglin@sangfor.com.cn (mailing list archive) |
|---|---|
| State | Superseded |
| Headers | show |
| Series | [RFC,v2] function_graph: Support recording and outputing the return value of function | expand |
Hi Donglin, This looks really interesting. There is fprobe and I'm trying introduce the fprobe event, but that is an event trace. So this is another way to trace the return values. On Sat, 11 Mar 2023 18:28:26 -0800 Donglin Peng <pengdonglin@sangfor.com.cn> wrote: > 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. Hm, this will confuse the output parser. The output should be human readable but also machine readable. I think you can introduce an option (tracefs/options/*) to show "smart" output or hexadecimal output always. treacefs/options/graph_retval_hex If this is 1, the return value is printed always in hexadecimal. If it is 0, when the IS_ERR(retval) is true, it will show it in signed decimal, or hexadecimal (with "0x" prefix). > Currently, this modification supports the following commonly used processor > architectures: x64, x86, arm64, arm, riscv. This may also need to be reviewed by each arch maintainer. So we need CONFIG_HAVE_FUNCTION_GRAPH_RETVAL which indicates that this architecture support ftrace-graph retval and CONFIG_FUNCTION_GRAPH_RETVAL which switches this retval is printed or not. > > 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. Yeah, but I think that is no problem. We can notify user that this retval is always be shown even if the function return type is void. > I think the BTF files 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 trace logs based on BTF information. Agreed. Anyway for some specific functions, we can use fprobe events. Thank you. > > 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 */ > ... > > Signed-off-by: Donglin Peng <pengdonglin@sangfor.com.cn> > --- > 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(-) > > diff --git a/arch/arm/kernel/entry-ftrace.S b/arch/arm/kernel/entry-ftrace.S > index 3e7bcaca5e07..c6666c0d909c 100644 > --- a/arch/arm/kernel/entry-ftrace.S > +++ b/arch/arm/kernel/entry-ftrace.S > @@ -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 > diff --git a/arch/arm64/kernel/entry-ftrace.S b/arch/arm64/kernel/entry-ftrace.S > index 350ed81324ac..0eb9a0e3ba3d 100644 > --- a/arch/arm64/kernel/entry-ftrace.S > +++ b/arch/arm64/kernel/entry-ftrace.S > @@ -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 > diff --git a/arch/riscv/kernel/mcount.S b/arch/riscv/kernel/mcount.S > index 30102aadc4d7..afce5abcbcd2 100644 > --- a/arch/riscv/kernel/mcount.S > +++ b/arch/riscv/kernel/mcount.S > @@ -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 > diff --git a/arch/x86/kernel/ftrace_32.S b/arch/x86/kernel/ftrace_32.S > index a0ed0e4a2c0c..7611374ccce8 100644 > --- a/arch/x86/kernel/ftrace_32.S > +++ b/arch/x86/kernel/ftrace_32.S > @@ -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 > diff --git a/arch/x86/kernel/ftrace_64.S b/arch/x86/kernel/ftrace_64.S > index 1265ad519249..d685b773e7ad 100644 > --- a/arch/x86/kernel/ftrace_64.S > +++ b/arch/x86/kernel/ftrace_64.S > @@ -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 > > diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h > index 366c730beaa3..157fd25be2b7 100644 > --- a/include/linux/ftrace.h > +++ b/include/linux/ftrace.h > @@ -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; > diff --git a/kernel/trace/fgraph.c b/kernel/trace/fgraph.c > index 218cd95bf8e4..006b39a98dc3 100644 > --- a/kernel/trace/fgraph.c > +++ b/kernel/trace/fgraph.c > @@ -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); > /* > diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h > index 616e1aa1c4da..5ef32c6e1d45 100644 > --- a/kernel/trace/trace.h > +++ b/kernel/trace/trace.h > @@ -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) > > diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h > index cd41e863b51c..d798cb17546f 100644 > --- a/kernel/trace/trace_entries.h > +++ b/kernel/trace/trace_entries.h > @@ -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) > ); > > /* > diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c > index 203204cadf92..706d3e5c2156 100644 > --- a/kernel/trace/trace_functions_graph.c > +++ b/kernel/trace/trace_functions_graph.c > @@ -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) > -- > 2.25.1 >
On 2023/3/12 17:58, Masami Hiramatsu (Google) wrote: > Hi Donglin, > > This looks really interesting. There is fprobe and I'm trying introduce the > fprobe event, but that is an event trace. So this is another way to trace > the return values. Thank you. I have seen your patches, and fprobe is better than kprobe,and I am learning it. > > On Sat, 11 Mar 2023 18:28:26 -0800 > Donglin Peng <pengdonglin@sangfor.com.cn> wrote: > >> 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. > > Hm, this will confuse the output parser. The output should be human readable > but also machine readable. I think you can introduce an option (tracefs/options/*) > to show "smart" output or hexadecimal output always. > > treacefs/options/graph_retval_hex > > If this is 1, the return value is printed always in hexadecimal. If it is 0, > when the IS_ERR(retval) is true, it will show it in signed decimal, or > hexadecimal (with "0x" prefix). Good idea,i will add this in v4. > >> Currently, this modification supports the following commonly used processor >> architectures: x64, x86, arm64, arm, riscv. > > This may also need to be reviewed by each arch maintainer. So we need > CONFIG_HAVE_FUNCTION_GRAPH_RETVAL which indicates that this architecture > support ftrace-graph retval and CONFIG_FUNCTION_GRAPH_RETVAL which > switches this retval is printed or not. > Yeah,I will modify this in v4. >> >> 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. > > Yeah, but I think that is no problem. We can notify user that this retval > is always be shown even if the function return type is void. > Yeah.I implement a simple tool to deal with the trace logs using BTF information just now, the processed trace logs are added in v3. >> I think the BTF files 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 trace logs based on BTF information. > > Agreed. Anyway for some specific functions, we can use fprobe events. > Yeah. > Thank you. > >> >> 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 */ >> ... >> >> Signed-off-by: Donglin Peng <pengdonglin@sangfor.com.cn> >> --- >> 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(-) >> >> diff --git a/arch/arm/kernel/entry-ftrace.S b/arch/arm/kernel/entry-ftrace.S >> index 3e7bcaca5e07..c6666c0d909c 100644 >> --- a/arch/arm/kernel/entry-ftrace.S >> +++ b/arch/arm/kernel/entry-ftrace.S >> @@ -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 >> diff --git a/arch/arm64/kernel/entry-ftrace.S b/arch/arm64/kernel/entry-ftrace.S >> index 350ed81324ac..0eb9a0e3ba3d 100644 >> --- a/arch/arm64/kernel/entry-ftrace.S >> +++ b/arch/arm64/kernel/entry-ftrace.S >> @@ -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 >> diff --git a/arch/riscv/kernel/mcount.S b/arch/riscv/kernel/mcount.S >> index 30102aadc4d7..afce5abcbcd2 100644 >> --- a/arch/riscv/kernel/mcount.S >> +++ b/arch/riscv/kernel/mcount.S >> @@ -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 >> diff --git a/arch/x86/kernel/ftrace_32.S b/arch/x86/kernel/ftrace_32.S >> index a0ed0e4a2c0c..7611374ccce8 100644 >> --- a/arch/x86/kernel/ftrace_32.S >> +++ b/arch/x86/kernel/ftrace_32.S >> @@ -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 >> diff --git a/arch/x86/kernel/ftrace_64.S b/arch/x86/kernel/ftrace_64.S >> index 1265ad519249..d685b773e7ad 100644 >> --- a/arch/x86/kernel/ftrace_64.S >> +++ b/arch/x86/kernel/ftrace_64.S >> @@ -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 >> >> diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h >> index 366c730beaa3..157fd25be2b7 100644 >> --- a/include/linux/ftrace.h >> +++ b/include/linux/ftrace.h >> @@ -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; >> diff --git a/kernel/trace/fgraph.c b/kernel/trace/fgraph.c >> index 218cd95bf8e4..006b39a98dc3 100644 >> --- a/kernel/trace/fgraph.c >> +++ b/kernel/trace/fgraph.c >> @@ -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); >> /* >> diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h >> index 616e1aa1c4da..5ef32c6e1d45 100644 >> --- a/kernel/trace/trace.h >> +++ b/kernel/trace/trace.h >> @@ -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) >> >> diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h >> index cd41e863b51c..d798cb17546f 100644 >> --- a/kernel/trace/trace_entries.h >> +++ b/kernel/trace/trace_entries.h >> @@ -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) >> ); >> >> /* >> diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c >> index 203204cadf92..706d3e5c2156 100644 >> --- a/kernel/trace/trace_functions_graph.c >> +++ b/kernel/trace/trace_functions_graph.c >> @@ -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) >> -- >> 2.25.1 >> > >
diff --git a/arch/arm/kernel/entry-ftrace.S b/arch/arm/kernel/entry-ftrace.S index 3e7bcaca5e07..c6666c0d909c 100644 --- a/arch/arm/kernel/entry-ftrace.S +++ b/arch/arm/kernel/entry-ftrace.S @@ -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 diff --git a/arch/arm64/kernel/entry-ftrace.S b/arch/arm64/kernel/entry-ftrace.S index 350ed81324ac..0eb9a0e3ba3d 100644 --- a/arch/arm64/kernel/entry-ftrace.S +++ b/arch/arm64/kernel/entry-ftrace.S @@ -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 diff --git a/arch/riscv/kernel/mcount.S b/arch/riscv/kernel/mcount.S index 30102aadc4d7..afce5abcbcd2 100644 --- a/arch/riscv/kernel/mcount.S +++ b/arch/riscv/kernel/mcount.S @@ -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 diff --git a/arch/x86/kernel/ftrace_32.S b/arch/x86/kernel/ftrace_32.S index a0ed0e4a2c0c..7611374ccce8 100644 --- a/arch/x86/kernel/ftrace_32.S +++ b/arch/x86/kernel/ftrace_32.S @@ -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 diff --git a/arch/x86/kernel/ftrace_64.S b/arch/x86/kernel/ftrace_64.S index 1265ad519249..d685b773e7ad 100644 --- a/arch/x86/kernel/ftrace_64.S +++ b/arch/x86/kernel/ftrace_64.S @@ -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 diff --git a/include/linux/ftrace.h b/include/linux/ftrace.h index 366c730beaa3..157fd25be2b7 100644 --- a/include/linux/ftrace.h +++ b/include/linux/ftrace.h @@ -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; diff --git a/kernel/trace/fgraph.c b/kernel/trace/fgraph.c index 218cd95bf8e4..006b39a98dc3 100644 --- a/kernel/trace/fgraph.c +++ b/kernel/trace/fgraph.c @@ -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); /* diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h index 616e1aa1c4da..5ef32c6e1d45 100644 --- a/kernel/trace/trace.h +++ b/kernel/trace/trace.h @@ -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) diff --git a/kernel/trace/trace_entries.h b/kernel/trace/trace_entries.h index cd41e863b51c..d798cb17546f 100644 --- a/kernel/trace/trace_entries.h +++ b/kernel/trace/trace_entries.h @@ -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) ); /* diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c index 203204cadf92..706d3e5c2156 100644 --- a/kernel/trace/trace_functions_graph.c +++ b/kernel/trace/trace_functions_graph.c @@ -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 files 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 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 */ ... Signed-off-by: Donglin Peng <pengdonglin@sangfor.com.cn> --- 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(-)