Re: [PATCH 3/3] compiler: inline does not imply notrace

From: Steven Rostedt
Date: Mon Nov 28 2022 - 23:15:52 EST

On Tue, 29 Nov 2022 02:36:22 +0000
Nadav Amit <namit@xxxxxxxxxx> wrote:

> On Nov 22, 2022, at 12:51 PM, Nadav Amit <namit@xxxxxxxxxx> wrote:
>
> > But more importantly, the current “inline”->”notrace” solution just papers
> > over missing “notrace” annotations. Anyone can remove the “inline” at any
> > given moment since there is no direct (or indirect) relationship between
> > “inline” and “notrace”. It seems to me all random and bound to fail at some
> > point.
>
> Peter, Steven, (and others),
>
> Beyond the issues that are addressed in this patch-set, I encountered one
> more, which reiterates the fact that the heuristics of marking “inline”
> functions as “notrace” is not good enough.
>
> Before I send a patch, I would like to get your feedback. I include a splat
> below. It appeaers the execution might get stuck since some functions that
> can be used for function tracing can be traced themselves.
>
> For example, __kernel_text_address() and unwind_get_return_address() are
> traceable. I think that we need to disallow the tracing of all functions
> that are called directly and indirectly from function_stack_trace_call()
> (i.e., they are in the dynamic extent of function_stack_trace_call).

How did this happen. It should be able to handle recursion:

static void
function_stack_trace_call(unsigned long ip, unsigned long parent_ip,
struct ftrace_ops *op, struct ftrace_regs *fregs)
{
struct trace_array *tr = op->private;
struct trace_array_cpu *data;
unsigned long flags;
long disabled;
int cpu;
unsigned int trace_ctx;

if (unlikely(!tr->function_enabled))
return;

/*
* Need to use raw, since this must be called before the
* recursive protection is performed.
*/
local_irq_save(flags);
cpu = raw_smp_processor_id();
data = per_cpu_ptr(tr->array_buffer.data, cpu);
disabled = atomic_inc_return(&data->disabled);

if (likely(disabled == 1)) { <<<---- This stops recursion

trace_ctx = tracing_gen_ctx_flags(flags);
trace_function(tr, ip, parent_ip, trace_ctx);
__trace_stack(tr, trace_ctx, STACK_SKIP);
}

atomic_dec(&data->disabled);
local_irq_restore(flags);
}

Each of the stack trace functions may recurse back into this function, but
it will not recurse further. How did it crash?

-- Steve


>
> In the lack of a proper automated static analysis tool for the matter, I
> suggest the following solution, but I would like to check that you are ok
> with the granularity of the “notrace” as I propose. Again, note that this is
> not caused by this “inline” patch, but an issue that existed before.
>
> -- >8 --
>
> Author: Nadav Amit <namit@xxxxxxxxxx>
> Date: Tue Nov 29 02:25:12 2022 +0000
>
> trace: Disable tracing of code called from function_stack_trace_call()
>
> Signed-off-by: Nadav Amit <namit@xxxxxxxxxx>
>
> diff --git a/arch/x86/kernel/Makefile b/arch/x86/kernel/Makefile
> index a20a5ebfacd7..185933222d08 100644
> --- a/arch/x86/kernel/Makefile
> +++ b/arch/x86/kernel/Makefile
> @@ -21,6 +21,10 @@ CFLAGS_REMOVE_ftrace.o = -pg
> CFLAGS_REMOVE_early_printk.o = -pg
> CFLAGS_REMOVE_head64.o = -pg
> CFLAGS_REMOVE_sev.o = -pg
> +CFLAGS_REMOVE_unwind_frame.o = -pg
> +CFLAGS_REMOVE_unwind_guess.o = -pg
> +CFLAGS_REMOVE_unwind_orc.o = -pg
> +CFLAGS_REMOVE_stacktrace.o = -pg
> endif
>
> KASAN_SANITIZE_head$(BITS).o := n
> diff --git a/kernel/Makefile b/kernel/Makefile
> index 318789c728d3..d688eab1e1f8 100644
> --- a/kernel/Makefile
> +++ b/kernel/Makefile
> @@ -19,6 +19,8 @@ obj-$(CONFIG_MULTIUSER) += groups.o
> ifdef CONFIG_FUNCTION_TRACER
> # Do not trace internal ftrace files
> CFLAGS_REMOVE_irq_work.o = $(CC_FLAGS_FTRACE)
> +CFLAGS_REMOVE_stacktrace.o = $(CC_FLAGS_FTRACE)
> +CFLAGS_REMOVE_extable.o = $(CC_FLAGS_FTRACE)
> endif
>
> # Prevents flicker of uninteresting __do_softirq()/__local_bh_disable_ip()
>
>
> ---
>
>
> [531394.447185] sched: RT throttling activated
> [531394.874541] NMI watchdog: Watchdog detected hard LOCKUP on cpu 26
> [531394.874745] Modules linked in: zram
> [531394.875224] CPU: 26 PID: 0 Comm: swapper/26 Not tainted 6.0.0-rc6umem+ #29
> [531394.875426] Hardware name: Cisco Systems Inc UCSC-C220-M5SX/UCSC-C220-M5SX, BIOS C220M5.4.0.1i.0.0522190226 05/22/2019
> [531394.875623] RIP: 0010:poke_int3_handler (arch/x86/kernel/alternative.c:1435)
> [531394.875903] Code: 45 01 48 8b 0d c8 0a 45 01 49 8d 70 ff 83 f8 01 7f 1c 48 63 39 31 c0 48 81 c7 00 00 00 81 48 39 fe 74 3c f0 ff 0d b3 0a 45 01 <c3> 31 c0 c3 49 89 ca 49 89 c1 49 d1 e9 4c 89 c9 48 c1 e1 04 4c 01
> All code
> ========
> 0: 45 01 48 8b add %r9d,-0x75(%r8)
> 4: 0d c8 0a 45 01 or $0x1450ac8,%eax
> 9: 49 8d 70 ff lea -0x1(%r8),%rsi
> d: 83 f8 01 cmp $0x1,%eax
> 10: 7f 1c jg 0x2e
> 12: 48 63 39 movslq (%rcx),%rdi
> 15: 31 c0 xor %eax,%eax
> 17: 48 81 c7 00 00 00 81 add $0xffffffff81000000,%rdi
> 1e: 48 39 fe cmp %rdi,%rsi
> 21: 74 3c je 0x5f
> 23: f0 ff 0d b3 0a 45 01 lock decl 0x1450ab3(%rip) # 0x1450add
> 2a:* c3 ret <-- trapping instruction
> 2b: 31 c0 xor %eax,%eax
> 2d: c3 ret
> 2e: 49 89 ca mov %rcx,%r10
> 31: 49 89 c1 mov %rax,%r9
> 34: 49 d1 e9 shr %r9
> 37: 4c 89 c9 mov %r9,%rcx
> 3a: 48 c1 e1 04 shl $0x4,%rcx
> 3e: 4c rex.WR
> 3f: 01 .byte 0x1
>
> Code starting with the faulting instruction
> ===========================================
> 0: c3 ret
> 1: 31 c0 xor %eax,%eax
> 3: c3 ret
> 4: 49 89 ca mov %rcx,%r10
> 7: 49 89 c1 mov %rax,%r9
> a: 49 d1 e9 shr %r9
> d: 4c 89 c9 mov %r9,%rcx
> 10: 48 c1 e1 04 shl $0x4,%rcx
> 14: 4c rex.WR
> 15: 01 .byte 0x1
> [531394.876031] RSP: 0018:ffffc9000cd387b0 EFLAGS: 00000003
> [531394.876320] RAX: 0000000000000001 RBX: 0000000000000000 RCX: ffffc9000cd388a8
> [531394.876482] RDX: ffffc9000cd387d8 RSI: ffffffff812ba310 RDI: ffffffffc0409094
> [531394.876652] RBP: ffffc9000cd387c8 R08: ffffffffc0409099 R09: 0000000000000000
> [531394.876782] R10: 0000000000000000 R11: 0000000000000000 R12: ffffc9000cd387d8
> [531394.876927] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
> [531394.877180] FS: 0000000000000000(0000) GS:ffff88afdf900000(0000) knlGS:0000000000000000
> [531394.877371] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [531394.877503] CR2: 00007efd1e47b01c CR3: 0000000006a0a001 CR4: 00000000007706e0
> [531394.877641] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [531394.877822] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [531394.877993] PKRU: 55555554
> [531394.878164] Call Trace:
> [531394.878356] <IRQ>
> [531394.878573] ? exc_int3 (arch/x86/kernel/traps.c:817)
> [531394.879306] asm_exc_int3 (./arch/x86/include/asm/idtentry.h:569)
> [531394.879725] RIP: 0010:function_stack_trace_call (kernel/trace/trace_functions.c:219)
> [531394.880058] Code: 2b 81 48 c7 c7 e0 e2 33 83 e8 1c fa fd ff 48 c7 c7 80 e6 1c 83 e8 40 61 fe 00 5d c3 cc cc cc cc cc cc cc cc cc cc cc cc cc cc <55> 48 89 e5 41 57 41 56 41 55 41 54 53 48 83 ec 08 4c 8b 62 18 41
> All code
> ========
> 0: 2b 81 48 c7 c7 e0 sub -0x1f3838b8(%rcx),%eax
> 6: e2 33 loop 0x3b
> 8: 83 e8 1c sub $0x1c,%eax
> b: fa cli
> c: fd std
> d: ff 48 c7 decl -0x39(%rax)
> 10: c7 80 e6 1c 83 e8 40 movl $0xfe6140,-0x177ce31a(%rax)
> 17: 61 fe 00
> 1a: 5d pop %rbp
> 1b: c3 ret
> 1c: cc int3
> 1d: cc int3
> 1e: cc int3
> 1f: cc int3
> 20: cc int3
> 21: cc int3
> 22: cc int3
> 23: cc int3
> 24: cc int3
> 25: cc int3
> 26: cc int3
> 27: cc int3
> 28: cc int3
> 29: cc int3
> 2a:* 55 push %rbp <-- trapping instruction
> 2b: 48 89 e5 mov %rsp,%rbp
> 2e: 41 57 push %r15
> 30: 41 56 push %r14
> 32: 41 55 push %r13
> 34: 41 54 push %r12
> 36: 53 push %rbx
> 37: 48 83 ec 08 sub $0x8,%rsp
> 3b: 4c 8b 62 18 mov 0x18(%rdx),%r12
> 3f: 41 rex.B
>
> Code starting with the faulting instruction
> ===========================================
> 0: 55 push %rbp
> 1: 48 89 e5 mov %rsp,%rbp
> 4: 41 57 push %r15
> 6: 41 56 push %r14
> 8: 41 55 push %r13
> a: 41 54 push %r12
> c: 53 push %rbx
> d: 48 83 ec 08 sub $0x8,%rsp
> 11: 4c 8b 62 18 mov 0x18(%rdx),%r12
> 15: 41 rex.B
> [531394.880225] RSP: 0018:ffffc9000cd388a8 EFLAGS: 00000082
> [531394.880538] RAX: 0000000000000002 RBX: ffffc9000cd389a8 RCX: ffffc9000cd388b0
> [531394.880702] RDX: ffffffff831cbec0 RSI: ffffffff8111893f RDI: ffffffff811b2c80
> [531394.880884] RBP: ffffc9000cd38958 R08: ffffc900082f7f48 R09: 0000000000000001
> [531394.881055] R10: 0000000000000e00 R11: 0000000000000001 R12: ffffc9000cd38a50
> [531394.881225] R13: 0000000000000000 R14: ffff889846ecc080 R15: 0000000000000004
> [531394.883694] ? unwind_get_return_address (arch/x86/kernel/unwind_frame.c:19 arch/x86/kernel/unwind_frame.c:14)
> [531394.883984] ? kernel_text_address (kernel/extable.c:78)
> [531394.885410] ? 0xffffffffc0409095
> [531394.886432] ? 0xffffffffc0409099
> [531394.887278] ? 0xffffffffc0409099
> [531394.889561] ? __trace_stack (kernel/trace/trace.c:3119)
> [531394.890036] ? __kernel_text_address (kernel/extable.c:78)
> [531394.891196] __kernel_text_address (kernel/extable.c:78)
> [531394.891658] unwind_get_return_address (arch/x86/kernel/unwind_frame.c:19 arch/x86/kernel/unwind_frame.c:14)
> [531394.892112] ? __kernel_text_address (kernel/extable.c:78)
> [531394.892382] ? unwind_get_return_address (arch/x86/kernel/unwind_frame.c:19 arch/x86/kernel/unwind_frame.c:14)
> [531394.892789] ? write_profile (kernel/stacktrace.c:83)
> [531394.893260] arch_stack_walk (arch/x86/kernel/stacktrace.c:26)
> [531394.895650] ? __trace_stack (kernel/trace/trace.c:3119)
> [531394.897209] stack_trace_save (kernel/stacktrace.c:123)
> [531394.898344] __ftrace_trace_stack (kernel/trace/trace.c:3061)
> [531394.899500] ? rt_mutex_postunlock (kernel/printk/printk.c:2894)
> [531394.899975] __trace_stack (kernel/trace/trace.c:3119)
> [531394.901025] function_stack_trace_call (./arch/x86/include/asm/atomic.h:108 ./include/linux/atomic/atomic-instrumented.h:258 kernel/trace/trace_functions.c:245)
> [531394.901356] ? fbcon_redraw.constprop.0 (drivers/video/fbdev/core/fbcon.c:1661)
> [531394.902748] 0xffffffffc0409099
> [531394.904289] ? fb_get_color_depth (drivers/video/fbdev/core/fbmem.c:92)
> [531394.906173] ? console_conditional_schedule (kernel/printk/printk.c:2895)
> [531394.907244] console_conditional_schedule (kernel/printk/printk.c:2895)
> [531394.907727] fbcon_redraw.constprop.0 (drivers/video/fbdev/core/fbcon.c:1661)
> [531394.908200] ? console_conditional_schedule (kernel/printk/printk.c:2895)
> [531394.908506] ? fbcon_redraw.constprop.0 (drivers/video/fbdev/core/fbcon.c:1661)
> [531394.911230] fbcon_scroll (drivers/video/fbdev/core/fbcon.c:1838)
> [531394.912743] con_scroll (drivers/tty/vt/vt.c:630 (discriminator 1))
> [531394.914360] lf (drivers/tty/vt/vt.c:1507)
> [531394.914680] ? lf (drivers/tty/vt/vt.c:1502)
> [531394.915779] vt_console_print (drivers/tty/vt/vt.c:3126)
> [531394.918248] console_emit_next_record.constprop.0 (kernel/printk/printk.c:1945 kernel/printk/printk.c:2732)
> [531394.922365] console_unlock (kernel/printk/printk.c:2794 kernel/printk/printk.c:2861)
> [531394.924129] vprintk_emit (kernel/printk/printk.c:2272)
> [531394.925782] vprintk_default (kernel/printk/printk.c:2283)
> [531394.926306] vprintk (kernel/printk/printk_safe.c:50)
> [531394.926943] _printk (kernel/printk/printk.c:2296)
> [531394.929016] perf_duration_warn.cold (kernel/events/core.c:510 kernel/events/core.c:508)
> [531394.929518] irq_work_single (kernel/irq_work.c:211)
> [531394.930449] irq_work_run_list (kernel/irq_work.c:241 (discriminator 3))
> [531394.931169] irq_work_run (kernel/irq_work.c:253)
> [531394.931816] __sysvec_irq_work (./arch/x86/include/asm/jump_label.h:27 ./include/linux/jump_label.h:207 ./arch/x86/include/asm/trace/irq_vectors.h:64 arch/x86/kernel/irq_work.c:23)
> [531394.932259] sysvec_irq_work (arch/x86/kernel/irq_work.c:17 (discriminator 14))
> [531394.932660] </IRQ>
> [531394.932854] <TASK>
> [531394.933607] asm_sysvec_irq_work (./arch/x86/include/asm/idtentry.h:675)
>
>
>
>
>