[PATCH] lockdep: Have assert functions test for actual interrupts disabled

[PATCH] lockdep: Have assert functions test for actual interrupts disabled

[Steven Rostedt]

From: Steven Rostedt (VMware) <rostedt@goodmis.org>

While working on irqs disabled tracepoints, I triggered the following
warning:

 ------------[ cut here ]------------
 IRQs not disabled as expected
 WARNING: CPU: 0 PID: 0 at kernel/softirq.c:144 __local_bh_enable+0x9b/0xe0
 Modules linked in:
 CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W         4.18.0-rc6-test+ #1099
 Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v03.03 07/14/2016
 RIP: 0010:__local_bh_enable+0x9b/0xe0
 Code: 5b d2 30 00 8b 85 98 08 00 00 85 c0 74 bf 80 3d ff eb 06 02 00 75 b6 48 c7 c7 80 89 46 8c c6 05 ef eb 06 02 01 e8 15 4e ff ff <0f> 0b eb 9f 48 8b 7c 24 10 e8 67 5f 09 00 eb b2 48 8b 6c 24 10 48 
 RSP: 0018:ffff8800d3e07f50 EFLAGS: 00010082
 RAX: 0000000000000000 RBX: 0000000000000100 RCX: 0000000000000000
 RDX: 0000000000000102 RSI: dffffc0000000000 RDI: ffffffff8e57dc00
 RBP: ffffffff8cc1f980 R08: fffffbfff199f449 R09: fffffbfff199f448
 R10: ffff8800d3e2643f R11: ffffed001a7c4c88 R12: 0000000000000007
 R13: 0000000000000008 R14: 0000000000000007 R15: 0000000000000000
 FS:  0000000000000000(0000) GS:ffff8800d3e00000(0000) knlGS:0000000000000000
 CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
 CR2: 0000000000000000 CR3: 00000000cac14001 CR4: 00000000001606f0
 Call Trace:
  <IRQ>
  __do_softirq+0x4a0/0x55a
  irq_exit+0x128/0x130
  reschedule_interrupt+0xf/0x20
  </IRQ>
 RIP: 0010:cpuidle_enter_state+0xcc/0x430
 Code: 63 55 ff 48 89 04 24 0f 1f 44 00 00 31 ff e8 7b 8d 55 ff 80 7c 24 10 00 0f 85 fb 02 00 00 e8 eb a8 69 ff fb 66 0f 1f 44 00 00 <4c> 8b 3c 24 4c 2b 7c 24 08 48 ba cf f7 53 e3 a5 9b c4 20 48 8d 7b 
 RSP: 0018:ffffffff8cc07d18 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff02
 RAX: 0000000000025140 RBX: ffff8800d3e34f00 RCX: ffffffff8b1cec2e
 RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffffffff8cd4a868
 RBP: ffffffff8cf1b660 R08: ffffed001a7c43db R09: 0000000000000000
 R10: ffff8800d3e2643f R11: ffffed001a7c4c88 R12: ffffffff8cf1b7f8
 R13: 0000000000000004 R14: ffffffff8cf1b7e0 R15: ffffffff8cf1b820
  ? __srcu_read_unlock+0x1e/0x40
  ? cpuidle_enter_state+0xc5/0x430
  do_idle+0x28f/0x300
  ? arch_cpu_idle_exit+0x40/0x40
  ? schedule_idle+0x39/0x50
  cpu_startup_entry+0xc2/0xd0
  ? cpu_in_idle+0x20/0x20
  ? preempt_count_sub+0xaa/0x100
  ? preempt_count_add+0xaf/0xd0
  start_kernel+0x640/0x67d
  ? thread_stack_cache_init+0x6/0x6
  ? load_ucode_intel_bsp+0x5f/0xa5
  ? load_ucode_intel_bsp+0x5f/0xa5
  ? init_intel_microcode+0xb0/0xb0
  ? load_ucode_bsp+0xbb/0x156
  secondary_startup_64+0xa5/0xb0
 irq event stamp: 9229434
 hardirqs last  enabled at (9229434): [<ffffffff8b004453>] trace_hardirqs_on_thunk+0x1a/0x1c
 hardirqs last disabled at (9229433): [<ffffffff8b00446f>] trace_hardirqs_off_thunk+0x1a/0x1c
 softirqs last  enabled at (9229416): [<ffffffff8b10d35c>] irq_enter+0x7c/0x80
 softirqs last disabled at (9229417): [<ffffffff8b10d488>] irq_exit+0x128/0x130
 ---[ end trace 35ba8f92a3c06fd6 ]---
 ------------[ cut here ]------------

When investigating, I found that interrupts were actually disabled, but
the bug was that lockdep was confused. As the asserts for expecting
interrupts disabled is now done by lockdep state tracking, it would be
nice to know if the bug is the interrupts not being disabled or lockdep
just thinking that they are disabled. Add a check within the WARN_ON()
to do the actual irqs_disabled() check (which only gets done when
lockdep thinks there's an error), and show that lockdep is broken if it
does not match up with the real state of interrupts.

Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
----
diff --git a/include/linux/lockdep.h b/include/linux/lockdep.h
index a8113357ceeb..c50c80eea41d 100644
--- a/include/linux/lockdep.h
+++ b/include/linux/lockdep.h
@@ -601,12 +601,16 @@ do {									\
 #define lockdep_assert_irqs_enabled()	do {				\
 		WARN_ONCE(debug_locks && !current->lockdep_recursion &&	\
 			  !current->hardirqs_enabled,			\
-			  "IRQs not enabled as expected\n");		\
+			  irqs_disabled() ?				\
+			  "IRQs not enabled as expected\n" :		\
+			  "IRQs enabled but lockdep reports they are disabled\n"); \
 	} while (0)
 
 #define lockdep_assert_irqs_disabled()	do {				\
 		WARN_ONCE(debug_locks && !current->lockdep_recursion &&	\
 			  current->hardirqs_enabled,			\
+			  irqs_disabled() ?				\
+			  "IRQs disabled but lockdep reports they are enabled\n" : \
 			  "IRQs not disabled as expected\n");		\
 	} while (0)
 

Re: [PATCH] lockdep: Have assert functions test for actual interrupts disabled

[Steven Rostedt]

Peter, you OK with this patch? I'm currently triggering a bug (in rc2)
where this patch is telling me that lockdep is getting it wrong. It
would be good to have this upstream such that we know if it is really a
bug in the code itself, or if lockdep didn't keep up properly.

-- Steve


On Mon, 6 Aug 2018 21:41:07 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> From: Steven Rostedt (VMware) <rostedt@goodmis.org>
> 
> While working on irqs disabled tracepoints, I triggered the following
> warning:
> 
>  ------------[ cut here ]------------
>  IRQs not disabled as expected
>  WARNING: CPU: 0 PID: 0 at kernel/softirq.c:144 __local_bh_enable+0x9b/0xe0
>  Modules linked in:
>  CPU: 0 PID: 0 Comm: swapper/0 Tainted: G        W         4.18.0-rc6-test+ #1099
>  Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v03.03 07/14/2016
>  RIP: 0010:__local_bh_enable+0x9b/0xe0
>  Code: 5b d2 30 00 8b 85 98 08 00 00 85 c0 74 bf 80 3d ff eb 06 02 00 75 b6 48 c7 c7 80 89 46 8c c6 05 ef eb 06 02 01 e8 15 4e ff ff <0f> 0b eb 9f 48 8b 7c 24 10 e8 67 5f 09 00 eb b2 48 8b 6c 24 10 48 
>  RSP: 0018:ffff8800d3e07f50 EFLAGS: 00010082
>  RAX: 0000000000000000 RBX: 0000000000000100 RCX: 0000000000000000
>  RDX: 0000000000000102 RSI: dffffc0000000000 RDI: ffffffff8e57dc00
>  RBP: ffffffff8cc1f980 R08: fffffbfff199f449 R09: fffffbfff199f448
>  R10: ffff8800d3e2643f R11: ffffed001a7c4c88 R12: 0000000000000007
>  R13: 0000000000000008 R14: 0000000000000007 R15: 0000000000000000
>  FS:  0000000000000000(0000) GS:ffff8800d3e00000(0000) knlGS:0000000000000000
>  CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>  CR2: 0000000000000000 CR3: 00000000cac14001 CR4: 00000000001606f0
>  Call Trace:
>   <IRQ>
>   __do_softirq+0x4a0/0x55a
>   irq_exit+0x128/0x130
>   reschedule_interrupt+0xf/0x20
>   </IRQ>
>  RIP: 0010:cpuidle_enter_state+0xcc/0x430
>  Code: 63 55 ff 48 89 04 24 0f 1f 44 00 00 31 ff e8 7b 8d 55 ff 80 7c 24 10 00 0f 85 fb 02 00 00 e8 eb a8 69 ff fb 66 0f 1f 44 00 00 <4c> 8b 3c 24 4c 2b 7c 24 08 48 ba cf f7 53 e3 a5 9b c4 20 48 8d 7b 
>  RSP: 0018:ffffffff8cc07d18 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff02
>  RAX: 0000000000025140 RBX: ffff8800d3e34f00 RCX: ffffffff8b1cec2e
>  RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffffffff8cd4a868
>  RBP: ffffffff8cf1b660 R08: ffffed001a7c43db R09: 0000000000000000
>  R10: ffff8800d3e2643f R11: ffffed001a7c4c88 R12: ffffffff8cf1b7f8
>  R13: 0000000000000004 R14: ffffffff8cf1b7e0 R15: ffffffff8cf1b820
>   ? __srcu_read_unlock+0x1e/0x40
>   ? cpuidle_enter_state+0xc5/0x430
>   do_idle+0x28f/0x300
>   ? arch_cpu_idle_exit+0x40/0x40
>   ? schedule_idle+0x39/0x50
>   cpu_startup_entry+0xc2/0xd0
>   ? cpu_in_idle+0x20/0x20
>   ? preempt_count_sub+0xaa/0x100
>   ? preempt_count_add+0xaf/0xd0
>   start_kernel+0x640/0x67d
>   ? thread_stack_cache_init+0x6/0x6
>   ? load_ucode_intel_bsp+0x5f/0xa5
>   ? load_ucode_intel_bsp+0x5f/0xa5
>   ? init_intel_microcode+0xb0/0xb0
>   ? load_ucode_bsp+0xbb/0x156
>   secondary_startup_64+0xa5/0xb0
>  irq event stamp: 9229434
>  hardirqs last  enabled at (9229434): [<ffffffff8b004453>] trace_hardirqs_on_thunk+0x1a/0x1c
>  hardirqs last disabled at (9229433): [<ffffffff8b00446f>] trace_hardirqs_off_thunk+0x1a/0x1c
>  softirqs last  enabled at (9229416): [<ffffffff8b10d35c>] irq_enter+0x7c/0x80
>  softirqs last disabled at (9229417): [<ffffffff8b10d488>] irq_exit+0x128/0x130
>  ---[ end trace 35ba8f92a3c06fd6 ]---
>  ------------[ cut here ]------------
> 
> When investigating, I found that interrupts were actually disabled, but
> the bug was that lockdep was confused. As the asserts for expecting
> interrupts disabled is now done by lockdep state tracking, it would be
> nice to know if the bug is the interrupts not being disabled or lockdep
> just thinking that they are disabled. Add a check within the WARN_ON()
> to do the actual irqs_disabled() check (which only gets done when
> lockdep thinks there's an error), and show that lockdep is broken if it
> does not match up with the real state of interrupts.
> 
> Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
> ----
> diff --git a/include/linux/lockdep.h b/include/linux/lockdep.h
> index a8113357ceeb..c50c80eea41d 100644
> --- a/include/linux/lockdep.h
> +++ b/include/linux/lockdep.h
> @@ -601,12 +601,16 @@ do {									\
>  #define lockdep_assert_irqs_enabled()	do {				\
>  		WARN_ONCE(debug_locks && !current->lockdep_recursion &&	\
>  			  !current->hardirqs_enabled,			\
> -			  "IRQs not enabled as expected\n");		\
> +			  irqs_disabled() ?				\
> +			  "IRQs not enabled as expected\n" :		\
> +			  "IRQs enabled but lockdep reports they are disabled\n"); \
>  	} while (0)
>  
>  #define lockdep_assert_irqs_disabled()	do {				\
>  		WARN_ONCE(debug_locks && !current->lockdep_recursion &&	\
>  			  current->hardirqs_enabled,			\
> +			  irqs_disabled() ?				\
> +			  "IRQs disabled but lockdep reports they are enabled\n" : \
>  			  "IRQs not disabled as expected\n");		\
>  	} while (0)
>  

Re: [PATCH] lockdep: Have assert functions test for actual interrupts disabled

[Peter Zijlstra]

On Wed, Sep 05, 2018 at 11:20:31AM -0400, Steven Rostedt wrote:
> 
> Peter, you OK with this patch? I'm currently triggering a bug (in rc2)
> where this patch is telling me that lockdep is getting it wrong. It
> would be good to have this upstream such that we know if it is really a
> bug in the code itself, or if lockdep didn't keep up properly.

I thought we had something for that under CONFIG_DEBUG_LOCKDEP.

/me checks and finds:

  kernel/locking/lockdep.c:check_flags()

Doesn't that work?

Re: [PATCH] lockdep: Have assert functions test for actual interrupts disabled

[Steven Rostedt]

On Thu, 6 Sep 2018 15:52:58 +0200
Peter Zijlstra <peterz@infradead.org> wrote:

> On Wed, Sep 05, 2018 at 11:20:31AM -0400, Steven Rostedt wrote:
> > 
> > Peter, you OK with this patch? I'm currently triggering a bug (in rc2)
> > where this patch is telling me that lockdep is getting it wrong. It
> > would be good to have this upstream such that we know if it is really a
> > bug in the code itself, or if lockdep didn't keep up properly.  
> 
> I thought we had something for that under CONFIG_DEBUG_LOCKDEP.
> 
> /me checks and finds:
> 
>   kernel/locking/lockdep.c:check_flags()
> 
> Doesn't that work?

Perhaps it does, but DEBUG_LOCKDEP wasn't set. Thus, when a use case
like this happens it will confuse developers because all they see is:

------------[ cut here ]------------
IRQs not enabled as expected
[...]


And there's no reason to assume that lockdep is broken.

Commits like ebf3adbad012b ("timers/nohz: Use lockdep to assert IRQs
are disabled/enabled") which replace WARN_ON_ONCE(!irqs_disabled())
with lockdep_assert_irqs_disabled(), were done for performance reasons
(which I agree with). My patch doesn't affect performance as it only
does the "irqs_disabled()" check when the WARN_ONCE() actually
triggers. And gives useful information.

If I haven't worked on lockdep in the past, I would have been spending
a lot more time trying to figure out why interrupts were disabled here
and never looking into the fact that the report was wrong.

I still think checking if IRQS are really disabled or not when lockdep
thinks it is (or not) is valuable and doesn't cause any other problems.

-- Steve

Re: [PATCH] lockdep: Have assert functions test for actual interrupts disabled

[Peter Zijlstra]

On Thu, Sep 06, 2018 at 10:17:01AM -0400, Steven Rostedt wrote:
> I still think checking if IRQS are really disabled or not when lockdep
> thinks it is (or not) is valuable and doesn't cause any other problems.

Since check_flags() is a relatively cheap thing I would rather do
something like so..

---
 include/linux/lockdep.h  |  6 ++++--
 kernel/locking/lockdep.c | 36 +++++++++++++++++++++++-------------
 2 files changed, 27 insertions(+), 15 deletions(-)

diff --git a/include/linux/lockdep.h b/include/linux/lockdep.h
index b0d0b51c4d85..24ff6302c04b 100644
--- a/include/linux/lockdep.h
+++ b/include/linux/lockdep.h
@@ -596,15 +596,17 @@ do {									\
 	lock_release(&(lock)->dep_map, 0, _THIS_IP_);			\
 } while (0)
 
+extern bool lockdep_check_flags(void);
+
 #define lockdep_assert_irqs_enabled()	do {				\
 		WARN_ONCE(debug_locks && !current->lockdep_recursion &&	\
-			  !current->hardirqs_enabled,			\
+			  !current->hardirqs_enabled && lockdep_check_flags(), \
 			  "IRQs not enabled as expected\n");		\
 	} while (0)
 
 #define lockdep_assert_irqs_disabled()	do {				\
 		WARN_ONCE(debug_locks && !current->lockdep_recursion &&	\
-			  current->hardirqs_enabled,			\
+			  current->hardirqs_enabled && lockdep_check_flags(), \
 			  "IRQs not disabled as expected\n");		\
 	} while (0)
 
diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c
index e406c5fdb41e..6cc58a16f2fe 100644
--- a/kernel/locking/lockdep.c
+++ b/kernel/locking/lockdep.c
@@ -3807,10 +3807,9 @@ static void __lock_unpin_lock(struct lockdep_map *lock, struct pin_cookie cookie
 /*
  * Check whether we follow the irq-flags state precisely:
  */
-static void check_flags(unsigned long flags)
+void __lockdep_check_flags(unsigned long flags)
 {
-#if defined(CONFIG_PROVE_LOCKING) && defined(CONFIG_DEBUG_LOCKDEP) && \
-    defined(CONFIG_TRACE_IRQFLAGS)
+#if defined(CONFIG_PROVE_LOCKING) && defined(CONFIG_TRACE_IRQFLAGS)
 	if (!debug_locks)
 		return;
 
@@ -3844,6 +3843,17 @@ static void check_flags(unsigned long flags)
 #endif
 }
 
+bool lockdep_check_flags(void)
+{
+	unsigned long flags;
+
+	raw_local_irq_save(flags);
+	__lockdep_check_flags(flags);
+	raw_local_irq_restore(flags);
+
+	return true;
+}
+
 void lock_set_class(struct lockdep_map *lock, const char *name,
 		    struct lock_class_key *key, unsigned int subclass,
 		    unsigned long ip)
@@ -3855,7 +3865,7 @@ void lock_set_class(struct lockdep_map *lock, const char *name,
 
 	raw_local_irq_save(flags);
 	current->lockdep_recursion = 1;
-	check_flags(flags);
+	__lockdep_check_flags(flags);
 	if (__lock_set_class(lock, name, key, subclass, ip))
 		check_chain_key(current);
 	current->lockdep_recursion = 0;
@@ -3872,7 +3882,7 @@ void lock_downgrade(struct lockdep_map *lock, unsigned long ip)
 
 	raw_local_irq_save(flags);
 	current->lockdep_recursion = 1;
-	check_flags(flags);
+	__lockdep_check_flags(flags);
 	if (__lock_downgrade(lock, ip))
 		check_chain_key(current);
 	current->lockdep_recursion = 0;
@@ -3894,7 +3904,7 @@ void lock_acquire(struct lockdep_map *lock, unsigned int subclass,
 		return;
 
 	raw_local_irq_save(flags);
-	check_flags(flags);
+	__lockdep_check_flags(flags);
 
 	current->lockdep_recursion = 1;
 	trace_lock_acquire(lock, subclass, trylock, read, check, nest_lock, ip);
@@ -3914,7 +3924,7 @@ void lock_release(struct lockdep_map *lock, int nested,
 		return;
 
 	raw_local_irq_save(flags);
-	check_flags(flags);
+	__lockdep_check_flags(flags);
 	current->lockdep_recursion = 1;
 	trace_lock_release(lock, ip);
 	if (__lock_release(lock, nested, ip))
@@ -3933,7 +3943,7 @@ int lock_is_held_type(const struct lockdep_map *lock, int read)
 		return 1; /* avoid false negative lockdep_assert_held() */
 
 	raw_local_irq_save(flags);
-	check_flags(flags);
+	__lockdep_check_flags(flags);
 
 	current->lockdep_recursion = 1;
 	ret = __lock_is_held(lock, read);
@@ -3953,7 +3963,7 @@ struct pin_cookie lock_pin_lock(struct lockdep_map *lock)
 		return cookie;
 
 	raw_local_irq_save(flags);
-	check_flags(flags);
+	__lockdep_check_flags(flags);
 
 	current->lockdep_recursion = 1;
 	cookie = __lock_pin_lock(lock);
@@ -3972,7 +3982,7 @@ void lock_repin_lock(struct lockdep_map *lock, struct pin_cookie cookie)
 		return;
 
 	raw_local_irq_save(flags);
-	check_flags(flags);
+	__lockdep_check_flags(flags);
 
 	current->lockdep_recursion = 1;
 	__lock_repin_lock(lock, cookie);
@@ -3989,7 +3999,7 @@ void lock_unpin_lock(struct lockdep_map *lock, struct pin_cookie cookie)
 		return;
 
 	raw_local_irq_save(flags);
-	check_flags(flags);
+	__lockdep_check_flags(flags);
 
 	current->lockdep_recursion = 1;
 	__lock_unpin_lock(lock, cookie);
@@ -4130,7 +4140,7 @@ void lock_contended(struct lockdep_map *lock, unsigned long ip)
 		return;
 
 	raw_local_irq_save(flags);
-	check_flags(flags);
+	__lockdep_check_flags(flags);
 	current->lockdep_recursion = 1;
 	trace_lock_contended(lock, ip);
 	__lock_contended(lock, ip);
@@ -4150,7 +4160,7 @@ void lock_acquired(struct lockdep_map *lock, unsigned long ip)
 		return;
 
 	raw_local_irq_save(flags);
-	check_flags(flags);
+	__lockdep_check_flags(flags);
 	current->lockdep_recursion = 1;
 	__lock_acquired(lock, ip);
 	current->lockdep_recursion = 0;