Re: [PATCH 6/9] lockdep: Introduce wait-type checks

Re: [PATCH 6/9] lockdep: Introduce wait-type checks

[Geert Uytterhoeven]

Hi all,

On Fri, Mar 13, 2020 at 6:48 PM Sebastian Andrzej Siewior
<bigeasy@linutronix.de> wrote:
> From: Peter Zijlstra <peterz@infradead.org>
>
> Extend lockdep to validate lock wait-type context.
>
> The current wait-types are:
>
>         LD_WAIT_FREE,           /* wait free, rcu etc.. */
>         LD_WAIT_SPIN,           /* spin loops, raw_spinlock_t etc.. */
>         LD_WAIT_CONFIG,         /* CONFIG_PREEMPT_LOCK, spinlock_t etc.. */
>         LD_WAIT_SLEEP,          /* sleeping locks, mutex_t etc.. */
>
> Where lockdep validates that the current lock (the one being acquired)
> fits in the current wait-context (as generated by the held stack).
>
> This ensures that there is no attempt to acquire mutexes while holding
> spinlocks, to acquire spinlocks while holding raw_spinlocks and so on. In
> other words, its a more fancy might_sleep().
>
> Obviously RCU made the entire ordeal more complex than a simple single
> value test because RCU can be acquired in (pretty much) any context and
> while it presents a context to nested locks it is not the same as it
> got acquired in.
>
> Therefore its necessary to split the wait_type into two values, one
> representing the acquire (outer) and one representing the nested context
> (inner). For most 'normal' locks these two are the same.
>
> [ To make static initialization easier we have the rule that:
>   .outer == INV means .outer == .inner; because INV == 0. ]
>
> It further means that its required to find the minimal .inner of the held
> stack to compare against the outer of the new lock; because while 'normal'
> RCU presents a CONFIG type to nested locks, if it is taken while already
> holding a SPIN type it obviously doesn't relax the rules.
>
> Below is an example output generated by the trivial test code:
>
>   raw_spin_lock(&foo);
>   spin_lock(&bar);
>   spin_unlock(&bar);
>   raw_spin_unlock(&foo);
>
>  [ BUG: Invalid wait context ]
>  -----------------------------
>  swapper/0/1 is trying to lock:
>  ffffc90000013f20 (&bar){....}-{3:3}, at: kernel_init+0xdb/0x187
>  other info that might help us debug this:
>  1 lock held by swapper/0/1:
>   #0: ffffc90000013ee0 (&foo){+.+.}-{2:2}, at: kernel_init+0xd1/0x187
>
> The way to read it is to look at the new -{n,m} part in the lock
> description; -{3:3} for the attempted lock, and try and match that up to
> the held locks, which in this case is the one: -{2,2}.
>
> This tells that the acquiring lock requires a more relaxed environment than
> presented by the lock stack.
>
> Currently only the normal locks and RCU are converted, the rest of the
> lockdep users defaults to .inner = INV which is ignored. More conversions
> can be done when desired.
>
> The check for spinlock_t nesting is not enabled by default. It's a separate
> config option for now as there are known problems which are currently
> addressed. The config option allows to identify these problems and to
> verify that the solutions found are indeed solving them.
>
> The config switch will be removed and the checks will permanently enabled
> once the vast majority of issues has been addressed.
>
> [ bigeasy: Move LD_WAIT_FREE,… out of CONFIG_LOCKDEP to avoid compile
>            failure with CONFIG_DEBUG_SPINLOCK + !CONFIG_LOCKDEP]
> [ tglx: Add the config option ]
>
> Requested-by: Thomas Gleixner <tglx@linutronix.de>
> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org>
> Signed-off-by: Sebastian Andrzej Siewior <bigeasy@linutronix.de>

On arm64 (e.g. R-Car H3 ES2.0):

+=============================
+[ BUG: Invalid wait context ]
+5.6.0-salvator-x-09423-gb29514ba13a9c459-dirty #679 Not tainted
+-----------------------------
+swapper/5/0 is trying to lock:
+ffffff86ff76f398 (&pool->lock){..-.}-{3:3}, at: __queue_work+0x134/0x430
+other info that might help us debug this:
+1 lock held by swapper/5/0:
+ #0: ffffffc01103a4a0 (rcu_read_lock){....}-{1:3}, at:
rcu_lock_acquire.constprop.59+0x0/0x38
+stack backtrace:
+CPU: 5 PID: 0 Comm: swapper/5 Not tainted
5.6.0-salvator-x-09423-gb29514ba13a9c459-dirty #679
+Hardware name: Renesas Salvator-X 2nd version board based on r8a77951 (DT)
+Call trace:
+ dump_backtrace+0x0/0x180
+ show_stack+0x14/0x1c
+ dump_stack+0xdc/0x12c
+ __lock_acquire+0x37c/0xf9c
+ lock_acquire+0x258/0x288
+ _raw_spin_lock+0x34/0x48
+ __queue_work+0x134/0x430
+ queue_work_on+0x48/0x8c
+ timers_update_nohz+0x24/0x2c
+ tick_nohz_activate.isra.15.part.16+0x5c/0x80
+ tick_setup_sched_timer+0xe0/0xf0
+ hrtimer_run_queues+0x88/0xf8
+ run_local_timers+0x20/0x58
+ update_process_times+0x24/0x50
+ tick_periodic+0xd8/0xe8
+ tick_handle_periodic+0x30/0x98
+ arch_timer_handler_phys+0x28/0x3c
+ handle_percpu_devid_irq+0x64/0x110
+ generic_handle_irq+0x20/0x34
+ __handle_domain_irq+0x94/0x98
+ gic_handle_irq+0x78/0xbc
+ el1_irq+0xf4/0x1c0
+ arch_cpu_idle+0x38/0x54
+ default_idle_call+0x2c/0x30
+ do_idle+0x13c/0x244
+ cpu_startup_entry+0x20/0x24
+ secondary_start_kernel+0x1c4/0x1d8

On arm32 (e.g SH-Mobile AG5, using Cortex-A9 TWD):

+=============================
+[ BUG: Invalid wait context ]
+5.6.0-kzm9g-09424-g2698719b4c4f35db-dirty #253 Not tainted
+-----------------------------
+swapper/0/0 is trying to lock:
+dfbc5250 (&pool->lock){..-.}-{3:3}, at: __queue_work+0x14c/0x4d0
+other info that might help us debug this:
+1 lock held by swapper/0/0:
+ #0: c0a17074 (rcu_read_lock){....}-{1:3}, at:
rcu_lock_acquire.constprop.33+0x0/0x38
+stack backtrace:
+CPU: 0 PID: 0 Comm: swapper/0 Not tainted
5.6.0-kzm9g-09424-g2698719b4c4f35db-dirty #253
+Hardware name: Generic SH73A0 (Flattened Device Tree)
+[<c010f948>] (unwind_backtrace) from [<c010bbf0>] (show_stack+0x10/0x14)
+[<c010bbf0>] (show_stack) from [<c05c3e84>] (dump_stack+0xa8/0xe0)
+[<c05c3e84>] (dump_stack) from [<c017036c>] (__lock_acquire+0x398/0x1568)
+[<c017036c>] (__lock_acquire) from [<c0171e90>] (lock_acquire+0x274/0x2ac)
+[<c0171e90>] (lock_acquire) from [<c05dfb90>] (_raw_spin_lock+0x40/0x50)
+[<c05dfb90>] (_raw_spin_lock) from [<c013adc8>] (__queue_work+0x14c/0x4d0)
+[<c013adc8>] (__queue_work) from [<c013b194>] (queue_work_on+0x48/0x6c)
+[<c013b194>] (queue_work_on) from [<c01a89e8>]
(tick_setup_sched_timer+0x148/0x188)
+[<c01a89e8>] (tick_setup_sched_timer) from [<c0197ad8>]
(hrtimer_run_queues+0x74/0x114)
+[<c0197ad8>] (hrtimer_run_queues) from [<c0195e38>]
(run_local_timers+0x14/0x54)
+[<c0195e38>] (run_local_timers) from [<c0195e9c>]
(update_process_times+0x24/0x54)
+[<c0195e9c>] (update_process_times) from [<c01a5520>]
(tick_handle_periodic+0x28/0xa0)
+[<c01a5520>] (tick_handle_periodic) from [<c010eaf8>] (twd_handler+0x2c/0x38)
+[<c010eaf8>] (twd_handler) from [<c01829c0>]
(handle_percpu_devid_irq+0x58/0xfc)
+[<c01829c0>] (handle_percpu_devid_irq) from [<c017ccc4>]
(generic_handle_irq+0x28/0x38)
+[<c017ccc4>] (generic_handle_irq) from [<c017d2fc>]
(__handle_domain_irq+0x90/0xa0)
+[<c017d2fc>] (__handle_domain_irq) from [<c0392d70>] (gic_handle_irq+0x58/0x90)
+[<c0392d70>] (gic_handle_irq) from [<c0101ab0>] (__irq_svc+0x70/0x98)
+Exception stack(0xc0a01f40 to 0xc0a01f88)
+1f40: 00000001 00000006 c0a0bac0 00000000 00000001 ffffe000 c0a08ea8 c0a94532
+1f60: c0a08eec 00000001 c09278e0 00000000 ffffe000 c0a01f90 c0108448 c010844c
+1f80: 60000013 ffffffff
+[<c0101ab0>] (__irq_svc) from [<c010844c>] (arch_cpu_idle+0x20/0x3c)
+[<c010844c>] (arch_cpu_idle) from [<c0152350>] (do_idle+0xe8/0x13c)
+[<c0152350>] (do_idle) from [<c0152718>] (cpu_startup_entry+0x18/0x1c)
+[<c0152718>] (cpu_startup_entry) from [<c0900d54>] (start_kernel+0x3f0/0x49c)
+[<c0900d54>] (start_kernel) from [<00000000>] (0x0)

I also see it on other arm32 platforms using Renesas-specific timers,
but I'll ignore those until the issues with "standard" ARM timers have
been resolved ;-)

Thanks!

Gr{oetje,eeting}s,

                        Geert


--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: [PATCH 6/9] lockdep: Introduce wait-type checks

[Sebastian Andrzej Siewior]

On 2020-03-31 15:25:21 [+0200], Geert Uytterhoeven wrote:
> Hi all,
Hi Geert,

> On arm64 (e.g. R-Car H3 ES2.0):
> 
> +=============================
> +[ BUG: Invalid wait context ]
> +5.6.0-salvator-x-09423-gb29514ba13a9c459-dirty #679 Not tainted
> +-----------------------------
> +swapper/5/0 is trying to lock:
> +ffffff86ff76f398 (&pool->lock){..-.}-{3:3}, at: __queue_work+0x134/0x430

The pool->lock is not yet converted.
…
> On arm32 (e.g SH-Mobile AG5, using Cortex-A9 TWD):
> 
> +=============================
> +[ BUG: Invalid wait context ]
> +5.6.0-kzm9g-09424-g2698719b4c4f35db-dirty #253 Not tainted
> +-----------------------------
> +swapper/0/0 is trying to lock:
> +dfbc5250 (&pool->lock){..-.}-{3:3}, at: __queue_work+0x14c/0x4d0

same issue.

> I also see it on other arm32 platforms using Renesas-specific timers,
> but I'll ignore those until the issues with "standard" ARM timers have
> been resolved ;-)

There are some known culprits, like the work infrastructure. The printk
is another one. From Kconfig:

|   NOTE: There are known nesting problems. So if you enable this
|   option expect lockdep splats until these problems have been fully
|   addressed which is work in progress. This config switch allows to
|   identify and analyze these problems. It will be removed and the
|   check permanentely enabled once the main issues have been fixed.


> Thanks!
> 
> Gr{oetje,eeting}s,
> 
>                         Geert
> 
> 

Sebastian

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: [PATCH 6/9] lockdep: Introduce wait-type checks

[Peter Zijlstra]

On Tue, Mar 31, 2020 at 03:25:21PM +0200, Geert Uytterhoeven wrote:
> On arm64 (e.g. R-Car H3 ES2.0):
> 
> +=============================
> +[ BUG: Invalid wait context ]
> +5.6.0-salvator-x-09423-gb29514ba13a9c459-dirty #679 Not tainted
> +-----------------------------
> +swapper/5/0 is trying to lock:
> +ffffff86ff76f398 (&pool->lock){..-.}-{3:3}, at: __queue_work+0x134/0x430
> +other info that might help us debug this:
> +1 lock held by swapper/5/0:
> + #0: ffffffc01103a4a0 (rcu_read_lock){....}-{1:3}, at:
> rcu_lock_acquire.constprop.59+0x0/0x38
> +stack backtrace:
> +CPU: 5 PID: 0 Comm: swapper/5 Not tainted
> 5.6.0-salvator-x-09423-gb29514ba13a9c459-dirty #679
> +Hardware name: Renesas Salvator-X 2nd version board based on r8a77951 (DT)
> +Call trace:
> + dump_backtrace+0x0/0x180
> + show_stack+0x14/0x1c
> + dump_stack+0xdc/0x12c
> + __lock_acquire+0x37c/0xf9c
> + lock_acquire+0x258/0x288
> + _raw_spin_lock+0x34/0x48
> + __queue_work+0x134/0x430
> + queue_work_on+0x48/0x8c
> + timers_update_nohz+0x24/0x2c
> + tick_nohz_activate.isra.15.part.16+0x5c/0x80
> + tick_setup_sched_timer+0xe0/0xf0
> + hrtimer_run_queues+0x88/0xf8

So this is complaining that it cannot take pool->lock, which is
WAIT_CONFIG while holding RCU, which presents a WAIT_CONFIG context.

This seems to implicate something is amiss, because that should be
allowed. The thing it doesn't print is the context, which in the above
case is a (hrtimer) interrupt.

I suspect this really is a hardirq context and the next patch won't cure
things. It looks nohz (full?) related.

Frederic, can you untangle this?

---

diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
index 1511690e4de7..ac10db66cc63 100644
--- a/kernel/locking/lockdep.c
+++ b/kernel/locking/lockdep.c
@@ -3952,10 +3952,36 @@ static int mark_lock(struct task_struct *curr, struct held_lock *this,
 	return ret;
 }
 
+static inline short task_wait_context(struct task_struct *curr)
+{
+	/*
+	 * Set appropriate wait type for the context; for IRQs we have to take
+	 * into account force_irqthread as that is implied by PREEMPT_RT.
+	 */
+	if (curr->hardirq_context) {
+		/*
+		 * Check if force_irqthreads will run us threaded.
+		 */
+		if (curr->hardirq_threaded || curr->irq_config)
+			return LD_WAIT_CONFIG;
+
+		return LD_WAIT_SPIN;
+	} else if (curr->softirq_context) {
+		/*
+		 * Softirqs are always threaded.
+		 */
+		return LD_WAIT_CONFIG;
+	}
+
+	return LD_WAIT_MAX;
+}
+
 static int
 print_lock_invalid_wait_context(struct task_struct *curr,
 				struct held_lock *hlock)
 {
+	short curr_inner;
+
 	if (!debug_locks_off())
 		return 0;
 	if (debug_locks_silent)
@@ -3971,6 +3997,10 @@ print_lock_invalid_wait_context(struct task_struct *curr,
 	print_lock(hlock);
 
 	pr_warn("other info that might help us debug this:\n");
+
+	curr_inner = task_wait_context(curr);
+	pr_warn("context-{%d:%d}\n", curr_inner, curr_inner);
+
 	lockdep_print_held_locks(curr);
 
 	pr_warn("stack backtrace:\n");
@@ -4017,26 +4047,7 @@ static int check_wait_context(struct task_struct *curr, struct held_lock *next)
 	}
 	depth++;
 
-	/*
-	 * Set appropriate wait type for the context; for IRQs we have to take
-	 * into account force_irqthread as that is implied by PREEMPT_RT.
-	 */
-	if (curr->hardirq_context) {
-		/*
-		 * Check if force_irqthreads will run us threaded.
-		 */
-		if (curr->hardirq_threaded || curr->irq_config)
-			curr_inner = LD_WAIT_CONFIG;
-		else
-			curr_inner = LD_WAIT_SPIN;
-	} else if (curr->softirq_context) {
-		/*
-		 * Softirqs are always threaded.
-		 */
-		curr_inner = LD_WAIT_CONFIG;
-	} else {
-		curr_inner = LD_WAIT_MAX;
-	}
+	curr_inner = task_wait_context(curr);
 
 	for (; depth < curr->lockdep_depth; depth++) {
 		struct held_lock *prev = curr->held_locks + depth;

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: [PATCH 6/9] lockdep: Introduce wait-type checks

[Peter Zijlstra]

On Tue, Mar 31, 2020 at 04:55:15PM +0200, Peter Zijlstra wrote:
> On Tue, Mar 31, 2020 at 03:25:21PM +0200, Geert Uytterhoeven wrote:
> > On arm64 (e.g. R-Car H3 ES2.0):
> > 
> > +=============================
> > +[ BUG: Invalid wait context ]
> > +5.6.0-salvator-x-09423-gb29514ba13a9c459-dirty #679 Not tainted
> > +-----------------------------
> > +swapper/5/0 is trying to lock:
> > +ffffff86ff76f398 (&pool->lock){..-.}-{3:3}, at: __queue_work+0x134/0x430
> > +other info that might help us debug this:
> > +1 lock held by swapper/5/0:
> > + #0: ffffffc01103a4a0 (rcu_read_lock){....}-{1:3}, at:
> > rcu_lock_acquire.constprop.59+0x0/0x38
> > +stack backtrace:
> > +CPU: 5 PID: 0 Comm: swapper/5 Not tainted
> > 5.6.0-salvator-x-09423-gb29514ba13a9c459-dirty #679
> > +Hardware name: Renesas Salvator-X 2nd version board based on r8a77951 (DT)
> > +Call trace:
> > + dump_backtrace+0x0/0x180
> > + show_stack+0x14/0x1c
> > + dump_stack+0xdc/0x12c
> > + __lock_acquire+0x37c/0xf9c
> > + lock_acquire+0x258/0x288
> > + _raw_spin_lock+0x34/0x48
> > + __queue_work+0x134/0x430
> > + queue_work_on+0x48/0x8c
> > + timers_update_nohz+0x24/0x2c
> > + tick_nohz_activate.isra.15.part.16+0x5c/0x80
> > + tick_setup_sched_timer+0xe0/0xf0
> > + hrtimer_run_queues+0x88/0xf8
> 
> So this is complaining that it cannot take pool->lock, which is
> WAIT_CONFIG while holding RCU, which presents a WAIT_CONFIG context.
> 
> This seems to implicate something is amiss, because that should be
> allowed. The thing it doesn't print is the context, which in the above
> case is a (hrtimer) interrupt.
> 
> I suspect this really is a hardirq context and the next patch won't cure
> things. It looks nohz (full?) related.
> 
> Frederic, can you untangle this?

Sebastian is right; I completely forgot the workqueue thing was still
pending.


_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel

Re: [PATCH 6/9] lockdep: Introduce wait-type checks

[Frederic Weisbecker]

On Tue, Mar 31, 2020 at 05:28:50PM +0200, Peter Zijlstra wrote:
> On Tue, Mar 31, 2020 at 04:55:15PM +0200, Peter Zijlstra wrote:
> > On Tue, Mar 31, 2020 at 03:25:21PM +0200, Geert Uytterhoeven wrote:
> > > On arm64 (e.g. R-Car H3 ES2.0):
> > > 
> > > +=============================
> > > +[ BUG: Invalid wait context ]
> > > +5.6.0-salvator-x-09423-gb29514ba13a9c459-dirty #679 Not tainted
> > > +-----------------------------
> > > +swapper/5/0 is trying to lock:
> > > +ffffff86ff76f398 (&pool->lock){..-.}-{3:3}, at: __queue_work+0x134/0x430
> > > +other info that might help us debug this:
> > > +1 lock held by swapper/5/0:
> > > + #0: ffffffc01103a4a0 (rcu_read_lock){....}-{1:3}, at:
> > > rcu_lock_acquire.constprop.59+0x0/0x38
> > > +stack backtrace:
> > > +CPU: 5 PID: 0 Comm: swapper/5 Not tainted
> > > 5.6.0-salvator-x-09423-gb29514ba13a9c459-dirty #679
> > > +Hardware name: Renesas Salvator-X 2nd version board based on r8a77951 (DT)
> > > +Call trace:
> > > + dump_backtrace+0x0/0x180
> > > + show_stack+0x14/0x1c
> > > + dump_stack+0xdc/0x12c
> > > + __lock_acquire+0x37c/0xf9c
> > > + lock_acquire+0x258/0x288
> > > + _raw_spin_lock+0x34/0x48
> > > + __queue_work+0x134/0x430
> > > + queue_work_on+0x48/0x8c
> > > + timers_update_nohz+0x24/0x2c
> > > + tick_nohz_activate.isra.15.part.16+0x5c/0x80
> > > + tick_setup_sched_timer+0xe0/0xf0
> > > + hrtimer_run_queues+0x88/0xf8
> > 
> > So this is complaining that it cannot take pool->lock, which is
> > WAIT_CONFIG while holding RCU, which presents a WAIT_CONFIG context.
> > 
> > This seems to implicate something is amiss, because that should be
> > allowed. The thing it doesn't print is the context, which in the above
> > case is a (hrtimer) interrupt.
> > 
> > I suspect this really is a hardirq context and the next patch won't cure
> > things. It looks nohz (full?) related.
> > 
> > Frederic, can you untangle this?
> 
> Sebastian is right; I completely forgot the workqueue thing was still
> pending.
> 

Ok good, because I had no better answer :)

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel