On Wed, Oct 28, 2020 at 10:39:47AM -0400, Qian Cai wrote:
> On Tue, 2020-10-27 at 20:01 -0700, Paul E. McKenney wrote:
> > If I have the right email thread associated with the right fixes, these
> > commits in -rcu should be what you are looking for:
> >
> > 73b658b6b7d5 ("rcu: Prevent lockdep-RCU splats on lock acquisition/release")
> > 626b79aa935a ("x86/smpboot: Move rcu_cpu_starting() earlier")
> >
> > And maybe this one as well:
> >
> > 3a6f638cb95b ("rcu,ftrace: Fix ftrace recursion")
> >
> > Please let me know if these commits do not fix things.
> While those patches silence the warnings for x86. Other arches are still
> suffering. It is only after applying the patch from Boqun below fixed
> everything.
Fair point!
> Is it a good idea for Boqun to write a formal patch or we should fix all arches
> individually like "x86/smpboot: Move rcu_cpu_starting() earlier"?
By Boqun's patch, you mean the change to debug_lockdep_rcu_enabled()
shown below? Peter Zijlstra showed that real failures can happen, so we
do not want to cover them up. So we are firmly in "fix all architectures"
space here, sorry!
I am happy to accumulate those patches, but cannot commit to creating
or testing them.
Thanx, Paul
> > > > diff --git a/kernel/rcu/update.c b/kernel/rcu/update.c
> > > > index 39334d2d2b37..35d9bab65b75 100644
> > > > --- a/kernel/rcu/update.c
> > > > +++ b/kernel/rcu/update.c
> > > > @@ -275,8 +275,8 @@ EXPORT_SYMBOL_GPL(rcu_callback_map);
> > > >
> > > > noinstr int notrace debug_lockdep_rcu_enabled(void)
> > > > {
> > > > - return rcu_scheduler_active != RCU_SCHEDULER_INACTIVE && debug_locks &&
> > > > - current->lockdep_recursion == 0;
> > > > + return rcu_scheduler_active != RCU_SCHEDULER_INACTIVE &&
> > > > + __lockdep_enabled;
> > > > }
> > > > EXPORT_SYMBOL_GPL(debug_lockdep_rcu_enabled);
>
> The warnings for each arch are:
>
> == powerpc ==
> [ 0.176044][ T1] smp: Bringing up secondary CPUs ...
> [ 0.179731][ T0]
> [ 0.179734][ T0] =============================
> [ 0.179736][ T0] WARNING: suspicious RCU usage
> [ 0.179739][ T0] 5.10.0-rc1-next-20201028+ #2 Not tainted
> [ 0.179741][ T0] -----------------------------
> [ 0.179744][ T0] kernel/locking/lockdep.c:3497 RCU-list traversed in non-reader section!!
> [ 0.179745][ T0]
> [ 0.179745][ T0] other info that might help us debug this:
> [ 0.179745][ T0]
> [ 0.179748][ T0]
> [ 0.179748][ T0] RCU used illegally from offline CPU!
> [ 0.179748][ T0] rcu_scheduler_active = 1, debug_locks = 1
> [ 0.179750][ T0] no locks held by swapper/1/0.
> [ 0.179752][ T0]
> [ 0.179752][ T0] stack backtrace:
> [ 0.179757][ T0] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.10.0-rc1-next-20201028+ #2
> [ 0.179759][ T0] Call Trace:
> [ 0.179767][ T0] [c000000015b27ab0] [c000000000657188] dump_stack+0xec/0x144 (unreliable)
> [ 0.179776][ T0] [c000000015b27af0] [c00000000014d0d4] lockdep_rcu_suspicious+0x128/0x14c
> [ 0.179782][ T0] [c000000015b27b70] [c000000000148920] __lock_acquire+0x1060/0x1c60
> [ 0.179788][ T0] [c000000015b27ca0] [c00000000014a1d0] lock_acquire+0x140/0x5f0
> [ 0.179794][ T0] [c000000015b27d90] [c0000000008f22f4] _raw_spin_lock_irqsave+0x64/0xb0
> [ 0.179801][ T0] [c000000015b27dd0] [c0000000001a1094] clockevents_register_device+0x74/0x270
> [ 0.179808][ T0] [c000000015b27e80] [c00000000001f194] register_decrementer_clockevent+0x94/0x110
> [ 0.179814][ T0] [c000000015b27ef0] [c00000000003fd84] start_secondary+0x134/0x800
> [ 0.179819][ T0] [c000000015b27f90] [c00000000000c454] start_secondary_prolog+0x10/0x14
> [ 0.179855][ T0]
> [ 0.179857][ T0] =============================
> [ 0.179858][ T0] WARNING: suspicious RCU usage
> [ 0.179860][ T0] 5.10.0-rc1-next-20201028+ #2 Not tainted
> [ 0.179862][ T0] -----------------------------
> [ 0.179864][ T0] kernel/locking/lockdep.c:886 RCU-list traversed in non-reader section!!
> [ 0.179866][ T0]
> [ 0.179866][ T0] other info that might help us debug this:
> [ 0.179866][ T0]
> [ 0.179868][ T0]
> [ 0.179868][ T0] RCU used illegally from offline CPU!
> [ 0.179868][ T0] rcu_scheduler_active = 1, debug_locks = 1
> [ 0.179870][ T0] no locks held by swapper/1/0.
> [ 0.179871][ T0]
> [ 0.179871][ T0] stack backtrace:
> [ 0.179875][ T0] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.10.0-rc1-next-20201028+ #2
> [ 0.179876][ T0] Call Trace:
> [ 0.179880][ T0] [c000000015b27980] [c000000000657188] dump_stack+0xec/0x144 (unreliable)
> [ 0.179886][ T0] [c000000015b279c0] [c00000000014d0d4] lockdep_rcu_suspicious+0x128/0x14c
> [ 0.179892][ T0] [c000000015b27a40] [c00000000014b010] register_lock_class+0x680/0xc70
> [ 0.179896][ T0] [c000000015b27b50] [c00000000014795c] __lock_acquire+0x9c/0x1c60
> [ 0.179901][ T0] [c000000015b27c80] [c00000000014a1d0] lock_acquire+0x140/0x5f0
> [ 0.179906][ T0] [c000000015b27d70] [c0000000008f22f4] _raw_spin_lock_irqsave+0x64/0xb0
> [ 0.179912][ T0] [c000000015b27db0] [c0000000003a2fb4] __delete_object+0x44/0x80
> [ 0.179917][ T0] [c000000015b27de0] [c00000000035a964] slab_free_freelist_hook+0x174/0x300
> [ 0.179921][ T0] [c000000015b27e50] [c00000000035f848] kfree+0xf8/0x500
> [ 0.179926][ T0] [c000000015b27ed0] [c000000000656878] free_cpumask_var+0x18/0x30
> [ 0.179931][ T0] [c000000015b27ef0] [c00000000003fff0] start_secondary+0x3a0/0x800
> add_cpu_to_masks at arch/powerpc/kernel/smp.c:1390
> (inlined by) start_secondary at arch/powerpc/kernel/smp.c:1420
> [ 0.179936][ T0] [c000000015b27f90] [c00000000000c454] start_secondary_prolog+0x10/0x14
> [ 0.955418][ T1] smp: Brought up 2 nodes, 128 CPUs
>
> == arm64 ==
> [ 0.473124][ T0] CPU1: Booted secondary processor 0x0000000100 [0x431f0af1]
> [ 0.473180][ C1]
> [ 0.473183][ C1] =============================
> [ 0.473186][ C1] WARNING: suspicious RCU usage
> [ 0.473188][ C1] 5.10.0-rc1-next-20201028+ #3 Not tainted
> [ 0.473190][ C1] -----------------------------
> [ 0.473193][ C1] kernel/locking/lockdep.c:3497 RCU-list traversed in non-reader section!!
> [ 0.473194][ C1]
> [ 0.473197][ C1] other info that might help us debug this:
> [ 0.473198][ C1]
> [ 0.473200][ C1]
> [ 0.473202][ C1] RCU used illegally from offline CPU!
> [ 0.473204][ C1] rcu_scheduler_active = 1, debug_locks = 1
> [ 0.473206][ C1] no locks held by swapper/1/0.
> [ 0.473208][ C1]
> [ 0.473210][ C1] stack backtrace:
> [ 0.473212][ C1] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.10.0-rc1-next-20201028+ #3
> [ 0.473215][ C1] Call trace:
> [ 0.473217][ C1] dump_backtrace+0x0/0x3c8
> [ 0.473219][ C1] show_stack+0x14/0x60
> [ 0.473221][ C1] dump_stack+0x14c/0x1c4
> [ 0.473223][ C1] lockdep_rcu_suspicious+0x134/0x14c
> [ 0.473225][ C1] __lock_acquire+0x1c30/0x2600
> [ 0.473227][ C1] lock_acquire+0x274/0xc48
> [ 0.473229][ C1] _raw_spin_lock+0xc8/0x140
> [ 0.473231][ C1] vprintk_emit+0x90/0x3d0
> [ 0.473233][ C1] vprintk_default+0x34/0x40
> [ 0.473235][ C1] vprintk_func+0x378/0x590
> [ 0.473236][ C1] printk+0xa8/0xd4
> [ 0.473239][ C1] __cpuinfo_store_cpu+0x71c/0x868
> [ 0.473241][ C1] cpuinfo_store_cpu+0x2c/0xc8
> [ 0.473243][ C1] secondary_start_kernel+0x244/0x318
> [ 0.547541][ T0] Detected PIPT I-cache on CPU2
> [ 0.547562][ T0] GICv3: CPU2: found redistributor 200 region 0:0x0000000401100000
>
> == s390 ==
> 00: [ 0.603404] WARNING: suspicious RCU usage
> 00: [ 0.603408] 5.10.0-rc1-next-20201027 #1 Not tainted
> 00: [ 0.603409] -----------------------------
> 00: [ 0.603459] kernel/locking/lockdep.c:3497 RCU-list traversed in non-reade
> 00: r section!!
> 00: [ 0.603460]
> 00: [ 0.603460] other info that might help us debug this:
> 00: [ 0.603460]
> 00: [ 0.603462]
> 00: [ 0.603462] RCU used illegally from offline CPU!
> 00: [ 0.603462] rcu_scheduler_active = 1, debug_locks = 1
> 00: [ 0.603463] no locks held by swapper/1/0.
> 00: [ 0.603464]
> 00: [ 0.603464] stack backtrace:
> 00: [ 0.603467] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.10.0-rc1-next-202
> 00: 01027 #1
> 00: [ 0.603469] Hardware name: IBM 2964 N96 400 (z/VM 6.4.0)
> 00: [ 0.603471] Call Trace:
> 00: [ 0.603484] [<00000000d262a778>] show_stack+0x158/0x1f0
> 00: [ 0.603487] [<00000000d2635872>] dump_stack+0x1f2/0x238
> 00: [ 0.603491] [<00000000d167a550>] __lock_acquire+0x2640/0x4dd0
> 00: [ 0.603493] [<00000000d167eda8>] lock_acquire+0x3a8/0xd08
> 00: [ 0.603498] [<00000000d265b088>] _raw_spin_lock_irqsave+0xc0/0xf0
> 00: [ 0.603502] [<00000000d17103f8>] clockevents_register_device+0xa8/0x528
> 00:
> 00: [ 0.603516] [<00000000d14f5246>] init_cpu_timer+0x33e/0x468
> 00: [ 0.603521] [<00000000d151f44a>] smp_init_secondary+0x11a/0x328
> 00: [ 0.603525] [<00000000d151f32a>] smp_start_secondary+0x82/0x88
>
