Re: boot flooded with unwind: Index not found

Corentin Labbe
2022-03-01T18:19:42Z

Le Tue, Mar 01, 2022 at 05:52:30PM +0100, Ard Biesheuvel a écrit :
> On Tue, 1 Mar 2022 at 17:37, Ard Biesheuvel <ardb@kernel.org> wrote:
> >
> > On Tue, 1 Mar 2022 at 16:52, Russell King (Oracle)
> > <linux@armlinux.org.uk> wrote:
> > >
> > > On Tue, Mar 01, 2022 at 04:48:25PM +0100, Corentin Labbe wrote:
> > > > Hello
> > > >
> > > > I booted today linux-next (20220301) and my boot is flooded with:
> > > > [ 0.000000] unwind: Index not found c0f0c440
> > > > [ 0.000000] unwind: Index not found 00000000
> > > > [ 0.000000] unwind: Index not found c0f0c440
> > > > [ 0.000000] unwind: Index not found 00000000
> > > >
> > > > This happen on a sun8i-a83t-bananapi-m3
> > >
> > > Have you enabled vmapped stacks?
> > >
> >
> > This is probably related to
> >
> > 538b9265c063 ARM: unwind: track location of LR value in stack frame
> >
> > which removes a kernel_text_address() check on frame->pc as it is
> > essentially redundant, given that we won't find unwind data otherwise.
> > Unfortunately, I failed to realise that the other check carries a
> > pr_warn(), which may apparently fire spuriously in some cases.
> >
> > The 0x0 value can easily be filtered out, but i would be interesting
> > where the other value originates from. We might be able to solve this
> > with a simple .nounwind directive in a asm routine somewhere.
> >
> > I'll prepare a patch that disregards the 0x0 value - could you check
> > in the mean time what the address 0xcf0c440 coincides with in your
> > build?
>
> Something like the below should restore the previous behavior, while
> taking the kernel_text_address() check out of the hot path.
>
> --- a/arch/arm/kernel/unwind.c
> +++ b/arch/arm/kernel/unwind.c
> @@ -400,7 +400,8 @@ int unwind_frame(struct stackframe *frame)
>
> idx = unwind_find_idx(frame->pc);
> if (!idx) {
> - pr_warn("unwind: Index not found %08lx\n", frame->pc);
> + if (frame->pc && kernel_text_address(frame->pc))
> + pr_warn("unwind: Index not found %08lx\n", frame->pc);
> return -URC_FAILURE;
> }

Thanks, message are not shown anymore.
But now I have other errors (perhaps not related):
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[ 0.000000] OF: fdt: Machine model: Banana Pi BPI-M3
[ 0.000000] earlycon: uart0 at MMIO32 0x01c28000 (options '')
[ 0.000000] printk: bootconsole [uart0] enabled
[ 0.000000] Memory policy: Data cache writealloc
[ 0.000000] cma: Reserved 16 MiB at 0xbf000000
[ 0.000000] Zone ranges:
[ 0.000000] Normal [mem 0x0000000040000000-0x000000006fffffff]
[ 0.000000] HighMem [mem 0x0000000070000000-0x00000000bfffffff]
[ 0.000000] Movable zone start for each node
[ 0.000000] Early memory node ranges
[ 0.000000] node 0: [mem 0x0000000040000000-0x00000000bfffffff]
[ 0.000000] Initmem setup node 0 [mem 0x0000000040000000-0x00000000bfffffff]
[ 0.000000] percpu: Embedded 16 pages/cpu s34740 r8192 d22604 u65536
[ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 522752
[ 0.000000] Kernel command line: console=ttyS0,115200n8 root=/dev/ram0 earlycon=uart,mmio32,0x01c28000 ip=dhcp
[ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
[ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
[ 0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[ 0.000000] Memory: 2016360K/2097152K available (9216K kernel code, 1534K rwdata, 3328K rodata, 1024K init, 7189K bss, 64408K reserved, 16384K cma-reserved, 1294336K highmem)
[ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=8, Nodes=1
[ 0.000000] trace event string verifier disabled
[ 0.000000] Running RCU self tests
[ 0.000000] rcu: Hierarchical RCU implementation.
[ 0.000000] rcu: RCU event tracing is enabled.
[ 0.000000] rcu: RCU lockdep checking is enabled.
[ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[ 0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[ 0.000000] rcu: srcu_init: Setting srcu_struct sizes based on contention.
[ 0.000000] random: get_random_bytes called from start_kernel+0x534/0x6cc with crng_init=0
[ 0.000000] arch_timer: cp15 timer(s) running at 24.00MHz (virt).
[ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x588fe9dc0, max_idle_ns: 440795202592 ns
[ 0.000003] sched_clock: 56 bits at 24MHz, resolution 41ns, wraps every 4398046511097ns
[ 0.008660] Switching to timer-based delay loop, resolution 41ns
[ 0.015599] clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 79635851949 ns
[ 0.026635] Console: colour dummy device 80x30
[ 0.031549] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[ 0.039999] ... MAX_LOCKDEP_SUBCLASSES: 8
[ 0.044452] ... MAX_LOCK_DEPTH: 48
[ 0.049004] ... MAX_LOCKDEP_KEYS: 8192
[ 0.053774] ... CLASSHASH_SIZE: 4096
[ 0.058511] ... MAX_LOCKDEP_ENTRIES: 32768
[ 0.063349] ... MAX_LOCKDEP_CHAINS: 65536
[ 0.068222] ... CHAINHASH_SIZE: 32768
[ 0.073054] memory used by lock dependency info: 4061 kB
[ 0.078950] memory used for stack traces: 2112 kB
[ 0.084155] per task-struct memory footprint: 1536 bytes
[ 0.090209] Calibrating delay loop (skipped), value calculated using timer frequency.. 48.00 BogoMIPS (lpj=240000)
[ 0.101504] pid_max: default: 32768 minimum: 301
[ 0.107656] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[ 0.115669] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[ 0.127831] CPU: Testing write buffer coherency: ok
[ 0.135293] /cpus/cpu@0 missing clock-frequency property
[ 0.141394] /cpus/cpu@1 missing clock-frequency property
[ 0.147356] /cpus/cpu@2 missing clock-frequency property
[ 0.153422] /cpus/cpu@3 missing clock-frequency property
[ 0.159447] /cpus/cpu@100 missing clock-frequency property
[ 0.165760] /cpus/cpu@101 missing clock-frequency property
[ 0.172058] /cpus/cpu@102 missing clock-frequency property
[ 0.178452] /cpus/cpu@103 missing clock-frequency property
[ 0.184451] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[ 0.196487] Setting up static identity map for 0x40100000 - 0x40100060
[ 0.206468] ARM CCI driver probed
[ 0.211477] sunxi multi cluster SMP support installed
[ 0.218724] rcu: Hierarchical SRCU implementation.
[ 0.229044] smp: Bringing up secondary CPUs ...
[ 0.239387] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[ 0.239462]
[ 0.239468]
[ 0.239476] =============================
[ 0.239479] WARNING: suspicious RCU usage
[ 0.239485] 5.17.0-rc6-next-20220301-00132-gc96ac15508a4-dirty #197 Not tainted
[ 0.239493] -----------------------------
[ 0.239497] include/trace/events/lock.h:58 suspicious rcu_dereference_check() usage!
[ 0.239505]
[ 0.239505] other info that might help us debug this:
[ 0.239505]
[ 0.239509]
[ 0.239509] rcu_scheduler_active = 1, debug_locks = 1
[ 0.239516] RCU used illegally from extended quiescent state!
[ 0.239521] 1 lock held by swapper/0/0:
[ 0.239527] #0: c0f15b4c ((console_sem).lock){-...}-{2:2}, at: down_trylock+0xc/0x2c
[ 0.239598]
[ 0.239598] stack backtrace:
[ 0.239607] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.17.0-rc6-next-20220301-00132-gc96ac15508a4-dirty #197
[ 0.239619] Hardware name: Allwinner A83t board
[ 0.239629] unwind_backtrace from show_stack+0x10/0x14
[ 0.239654] show_stack from init_stack+0x1c54/0x2000
[ 0.343881] =============================
[ 0.348205] WARNING: suspicious RCU usage
[ 0.352529] 5.17.0-rc6-next-20220301-00132-gc96ac15508a4-dirty #197 Not tainted
[ 0.360417] -----------------------------
[ 0.364741] include/trace/events/lock.h:13 suspicious rcu_dereference_check() usage!
[ 0.373098]
[ 0.373098] other info that might help us debug this:
[ 0.373098]
[ 0.381738]
[ 0.381738] rcu_scheduler_active = 1, debug_locks = 1
[ 0.388787] RCU used illegally from extended quiescent state!
[ 0.394992] no locks held by swapper/0/0.
[ 0.399317]
[ 0.399317] stack backtrace:
[ 0.404014] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.17.0-rc6-next-20220301-00132-gc96ac15508a4-dirty #197
[ 0.414706] Hardware name: Allwinner A83t board
[ 0.419595] unwind_backtrace from show_stack+0x10/0x14
[ 0.425251] show_stack from init_stack+0x1d5c/0x2000