| Message ID | 20241010101510.1487477-9-mark.rutland@arm.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | arm64: stacktrace: improve unwind reporting | expand |
On Thu, Oct 10, 2024 at 11:15:08AM +0100, Mark Rutland wrote: > The flags recorded are: > "F" - the PC was recovered from fgraph > "K" - the PC was recovered from kretprobes > These flags are recorded and logged in addition to the original source > of the unwound PC. This should be very useful. Reviewed-by: Mark Brown <broonie@kernel.org>
On Thu, 10 Oct 2024, Mark Rutland wrote: > When analysing a stacktrace it can be useful to know whether an unwound > PC has been rewritten by fgraph or kretprobes, as in some situations > these may be suspect or be known to be unreliable. > > This patch adds flags to track when an unwind entry has recovered the PC > from fgraph and/or kretprobes, and updates dump_backtrace() to log when > this is the case. > > The flags recorded are: > > "F" - the PC was recovered from fgraph > "K" - the PC was recovered from kretprobes > > These flags are recorded and logged in addition to the original source > of the unwound PC. > > For example, with the ftrace_graph profiler enabled globally, and > kretprobes installed on generic_handle_domain_irq() and > do_interrupt_handler(), a backtrace triggered by magic-sysrq + L > reports: > > | Call trace: > | show_stack+0x20/0x40 (CF) > | dump_stack_lvl+0x60/0x80 (F) > | dump_stack+0x18/0x28 > | nmi_cpu_backtrace+0xfc/0x140 > | nmi_trigger_cpumask_backtrace+0x1c8/0x200 > | arch_trigger_cpumask_backtrace+0x20/0x40 > | sysrq_handle_showallcpus+0x24/0x38 (F) > | __handle_sysrq+0xa8/0x1b0 (F) > | handle_sysrq+0x38/0x50 (F) > | pl011_int+0x460/0x5a8 (F) > | __handle_irq_event_percpu+0x60/0x220 (F) > | handle_irq_event+0x54/0xc0 (F) > | handle_fasteoi_irq+0xa8/0x1d0 (F) > | generic_handle_domain_irq+0x34/0x58 (F) > | gic_handle_irq+0x54/0x140 (FK) > | call_on_irq_stack+0x24/0x58 (F) > | do_interrupt_handler+0x88/0xa0 > | el1_interrupt+0x34/0x68 (FK) > | el1h_64_irq_handler+0x18/0x28 > | el1h_64_irq+0x64/0x68 > | default_idle_call+0x34/0x180 > | do_idle+0x204/0x268 > | cpu_startup_entry+0x40/0x50 (F) > | rest_init+0xe4/0xf0 > | start_kernel+0x744/0x750 > | __primary_switched+0x80/0x90 > > Note that as these flags are reported next to the recovered PC value, > they appear on the callers of instrumented functions, e.g. > gic_handle_irq has a "K" marker because generic_handle_domain_irq was > instrumented with kretprobes and had its return addredd (gic_handle_irq) address Also, you might want to add () to all the functions here to keep it consistent with the rest of the changelog even though the call trace does not have them obviously. Miroslav
On Fri, Oct 11, 2024 at 02:58:11PM +0200, Miroslav Benes wrote: > On Thu, 10 Oct 2024, Mark Rutland wrote: > > Note that as these flags are reported next to the recovered PC value, > > they appear on the callers of instrumented functions, e.g. > > gic_handle_irq has a "K" marker because generic_handle_domain_irq was > > instrumented with kretprobes and had its return addredd (gic_handle_irq) > > address > > Also, you might want to add () to all the functions here to keep it > consistent with the rest of the changelog even though the call trace does > not have them obviously. I was on the fence about what was clearer when I wrote this; my preference is also to have the '()', so I'll go add that in for consistency. Mark.
diff --git a/arch/arm64/kernel/stacktrace.c b/arch/arm64/kernel/stacktrace.c index 83ab37e13159e..f8e231683dad9 100644 --- a/arch/arm64/kernel/stacktrace.c +++ b/arch/arm64/kernel/stacktrace.c @@ -28,6 +28,14 @@ enum kunwind_source { KUNWIND_SOURCE_REGS_PC, }; +union unwind_flags { + unsigned long all; + struct { + unsigned long fgraph : 1, + kretprobe : 1; + }; +}; + /* * Kernel unwind state * @@ -46,6 +54,7 @@ struct kunwind_state { struct llist_node *kr_cur; #endif enum kunwind_source source; + union unwind_flags flags; }; static __always_inline void @@ -55,6 +64,7 @@ kunwind_init(struct kunwind_state *state, unwind_init_common(&state->common); state->task = task; state->source = KUNWIND_SOURCE_UNKNOWN; + state->flags.all = 0; } /* @@ -127,6 +137,7 @@ kunwind_recover_return_address(struct kunwind_state *state) if (WARN_ON_ONCE(state->common.pc == orig_pc)) return -EINVAL; state->common.pc = orig_pc; + state->flags.fgraph = 1; } #endif /* CONFIG_FUNCTION_GRAPH_TRACER */ @@ -137,6 +148,7 @@ kunwind_recover_return_address(struct kunwind_state *state) (void *)state->common.fp, &state->kr_cur); state->common.pc = orig_pc; + state->flags.kretprobe = 1; } #endif /* CONFIG_KRETPROBES */ @@ -157,6 +169,8 @@ kunwind_next(struct kunwind_state *state) unsigned long fp = state->common.fp; int err; + state->flags.all = 0; + /* Final frame; nothing to unwind */ if (fp == (unsigned long)&task_pt_regs(tsk)->stackframe) return -ENOENT; @@ -331,12 +345,18 @@ static const char *state_source_string(const struct kunwind_state *state) static bool dump_backtrace_entry(const struct kunwind_state *state, void *arg) { const char *source = state_source_string(state); + union unwind_flags flags = state->flags; + bool has_info = source || flags.all; char *loglvl = arg; - printk("%s %pSb%s%s%s\n", loglvl, + + printk("%s %pSb%s%s%s%s%s\n", loglvl, (void *)state->common.pc, - source ? " (" : "", + has_info ? " (" : "", source ? source : "", - source ? ")" : ""); + flags.fgraph ? "F" : "", + flags.kretprobe ? "K" : "", + has_info ? ")" : ""); + return true; }
When analysing a stacktrace it can be useful to know whether an unwound PC has been rewritten by fgraph or kretprobes, as in some situations these may be suspect or be known to be unreliable. This patch adds flags to track when an unwind entry has recovered the PC from fgraph and/or kretprobes, and updates dump_backtrace() to log when this is the case. The flags recorded are: "F" - the PC was recovered from fgraph "K" - the PC was recovered from kretprobes These flags are recorded and logged in addition to the original source of the unwound PC. For example, with the ftrace_graph profiler enabled globally, and kretprobes installed on generic_handle_domain_irq() and do_interrupt_handler(), a backtrace triggered by magic-sysrq + L reports: | Call trace: | show_stack+0x20/0x40 (CF) | dump_stack_lvl+0x60/0x80 (F) | dump_stack+0x18/0x28 | nmi_cpu_backtrace+0xfc/0x140 | nmi_trigger_cpumask_backtrace+0x1c8/0x200 | arch_trigger_cpumask_backtrace+0x20/0x40 | sysrq_handle_showallcpus+0x24/0x38 (F) | __handle_sysrq+0xa8/0x1b0 (F) | handle_sysrq+0x38/0x50 (F) | pl011_int+0x460/0x5a8 (F) | __handle_irq_event_percpu+0x60/0x220 (F) | handle_irq_event+0x54/0xc0 (F) | handle_fasteoi_irq+0xa8/0x1d0 (F) | generic_handle_domain_irq+0x34/0x58 (F) | gic_handle_irq+0x54/0x140 (FK) | call_on_irq_stack+0x24/0x58 (F) | do_interrupt_handler+0x88/0xa0 | el1_interrupt+0x34/0x68 (FK) | el1h_64_irq_handler+0x18/0x28 | el1h_64_irq+0x64/0x68 | default_idle_call+0x34/0x180 | do_idle+0x204/0x268 | cpu_startup_entry+0x40/0x50 (F) | rest_init+0xe4/0xf0 | start_kernel+0x744/0x750 | __primary_switched+0x80/0x90 Note that as these flags are reported next to the recovered PC value, they appear on the callers of instrumented functions, e.g. gic_handle_irq has a "K" marker because generic_handle_domain_irq was instrumented with kretprobes and had its return addredd (gic_handle_irq) rewritten. Signed-off-by: Mark Rutland <mark.rutland@arm.com> Cc: Ard Biesheuvel <ardb@kernel.org> Cc: Josh Poimboeuf <jpoimboe@kernel.org> Cc: Kalesh Singh <kaleshsingh@google.com> Cc: Madhavan T. Venkataraman <madvenka@linux.microsoft.com> Cc: Marc Zyngier <maz@kernel.org> Cc: Mark Brown <broonie@kernel.org> Cc: Miroslav Benes <mbenes@suse.cz> Cc: Puranjay Mohan <puranjay12@gmail.com> Cc: Will Deacon <will@kernel.org> --- arch/arm64/kernel/stacktrace.c | 26 +++++++++++++++++++++++--- 1 file changed, 23 insertions(+), 3 deletions(-)