softirq: reorder trace_softirqs_on to prevent lockdep splat

PATCH In review Joel Fernandes 3 participants 8 messages Apr 27, 2018 – Jun 20, 2018

lore

Share & tools

lore

Joel Fernandes

author

2018-04-27 04:11 UTC #0 lore raw

PATCH 1/1 softirq: reorder trace_softirqs_on to prevent lockdep splat

I'm able to reproduce a lockdep splat when CONFIG_PROVE_LOCKING=y and CONFIG_PREEMPTIRQ_EVENTS=y.

$ echo 1 > /d/tracing/events/preemptirq/preempt_enable/enable
---
[   26.112609] DEBUG_LOCKS_WARN_ON(current->softirqs_enabled)
[   26.112636] WARNING: CPU: 0 PID: 118 at kernel/locking/lockdep.c:3854
[...]
[   26.144229] Call Trace:
[   26.144926]  <IRQ>
[   26.145506]  lock_acquire+0x55/0x1b0
[   26.146499]  ? __do_softirq+0x46f/0x4d9
[   26.147571]  ? __do_softirq+0x46f/0x4d9
[   26.148646]  trace_preempt_on+0x8f/0x240
[   26.149744]  ? trace_preempt_on+0x4d/0x240
[   26.150862]  ? __do_softirq+0x46f/0x4d9
[   26.151930]  preempt_count_sub+0x18a/0x1a0
[   26.152985]  __do_softirq+0x46f/0x4d9
[   26.153937]  irq_exit+0x68/0xe0
[   26.154755]  smp_apic_timer_interrupt+0x271/0x280
[   26.156056]  apic_timer_interrupt+0xf/0x20
[   26.157105]  </IRQ>

The problem is the softirqs annotation in lockdep goes out of sync with the reality of the world that softirq is still off. This causes a lockdep splat because the preempt_count_sub can call into a preemptoff tracer or the trace events code, which inturn can call into lockdep *before* softirqs are really turned back on, which can cause a softirqs invalid annotation splat in lockdep.

The same issue was fixed in local_bh_disable_ip which has a comment so:
/*
* The preempt tracer hooks into preempt_count_add and will break
* lockdep because it calls back into lockdep after SOFTIRQ_OFFSET
* is set and before current->softirq_enabled is cleared.
* We must manually increment preempt_count here and manually
* call the trace_preempt_off later.
*/

I have done a similar change to the local_bh_enable path to fix it.

Cc Steven Rostedt <[email protected]>

Cc Peter Zilstra <[email protected]>

Cc Ingo Molnar <[email protected]>

Cc Mathieu Desnoyers <[email protected]>

Cc Tom Zanussi <[email protected]>

Cc Namhyung Kim <[email protected]>

Cc Thomas Glexiner <[email protected]>

Cc Boqun Feng <[email protected]>

Cc Paul McKenney <[email protected]>

Cc Frederic Weisbecker <[email protected]>

Cc Randy Dunlap <[email protected]>

Cc Masami Hiramatsu <[email protected]>

Cc Fenguang Wu <[email protected]>

Cc Baohong Liu <[email protected]>

Cc Vedang Patel <[email protected]>

Cc [email protected]

Signed-off-by Joel Fernandes <[email protected]>

---
 kernel/softirq.c | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)

kernel/softirq.c +5 -1

index 177de3640c78..8a040bcaa033 100644
@@ -139,9 +139,13 @@ static void __local_bh_enable(unsigned int cnt)
 {
 	lockdep_assert_irqs_disabled();
 
+	if (preempt_count() == cnt)
+		trace_preempt_on(CALLER_ADDR0, get_lock_parent_ip());
+
 	if (softirq_count() == (cnt & SOFTIRQ_MASK))
 		trace_softirqs_on(_RET_IP_);
-	preempt_count_sub(cnt);
+
+	__preempt_count_sub(cnt);
 }
 
 /*

Signature · 1 line

2.17.0.441.gb46fe60e1d-goog

Steven Rostedt

2018-04-30 16:38 UTC #1 lore raw

Quoted 14 lines · On Thu, 26 Apr 2018 21:11:00 -0700 Joel Fernandes <[email protected]> wrote:

I'm able to reproduce a lockdep splat when CONFIG_PROVE_LOCKING=y and CONFIG_PREEMPTIRQ_EVENTS=y.

$ echo 1 > /d/tracing/events/preemptirq/preempt_enable/enable
---
[   26.112609] DEBUG_LOCKS_WARN_ON(current->softirqs_enabled)
[   26.112636] WARNING: CPU: 0 PID: 118 at kernel/locking/lockdep.c:3854
[...]
[   26.144229] Call Trace:
[   26.144926]  <IRQ>
[   26.145506]  lock_acquire+0x55/0x1b0
[   26.146499]  ? __do_softirq+0x46f/0x4d9
[   26.147571]  ? __do_softirq+0x46f/0x4d9
[   26.148646]  trace_preempt_on+0x8f/0x240

Quoted 8 lines

[   26.149744]  ? trace_preempt_on+0x4d/0x240
[   26.150862]  ? __do_softirq+0x46f/0x4d9
[   26.151930]  preempt_count_sub+0x18a/0x1a0
[   26.152985]  __do_softirq+0x46f/0x4d9
[   26.153937]  irq_exit+0x68/0xe0
[   26.154755]  smp_apic_timer_interrupt+0x271/0x280
[   26.156056]  apic_timer_interrupt+0xf/0x20
[   26.157105]  </IRQ>

I'm not able to trigger this. Is there more to it?

-- Steve

Quoted 59 lines

The problem is the softirqs annotation in lockdep goes out of sync with the reality of the world that softirq is still off. This causes a lockdep splat because the preempt_count_sub can call into a preemptoff tracer or the trace events code, which inturn can call into lockdep *before* softirqs are really turned back on, which can cause a softirqs invalid annotation splat in lockdep.
The same issue was fixed in local_bh_disable_ip which has a comment so:
/*
* The preempt tracer hooks into preempt_count_add and will break
* lockdep because it calls back into lockdep after SOFTIRQ_OFFSET
* is set and before current->softirq_enabled is cleared.
* We must manually increment preempt_count here and manually
* call the trace_preempt_off later.
*/
I have done a similar change to the local_bh_enable path to fix it.
Cc Steven Rostedt <[email protected]>
Cc Peter Zilstra <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Mathieu Desnoyers <[email protected]>
Cc Tom Zanussi <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Thomas Glexiner <[email protected]>
Cc Boqun Feng <[email protected]>
Cc Paul McKenney <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Randy Dunlap <[email protected]>
Cc Masami Hiramatsu <[email protected]>
Cc Fenguang Wu <[email protected]>
Cc Baohong Liu <[email protected]>
Cc Vedang Patel <[email protected]>
Cc [email protected]
Signed-off-by Joel Fernandes <[email protected]>
---
 kernel/softirq.c | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)
kernel/softirq.c +5 -1
index 177de3640c78..8a040bcaa033 100644
@@ -139,9 +139,13 @@ static void __local_bh_enable(unsigned int cnt)
 {
 	lockdep_assert_irqs_disabled();
 
+	if (preempt_count() == cnt)
+		trace_preempt_on(CALLER_ADDR0, get_lock_parent_ip());
+
 	if (softirq_count() == (cnt & SOFTIRQ_MASK))
 		trace_softirqs_on(_RET_IP_);
-	preempt_count_sub(cnt);
+
+	__preempt_count_sub(cnt);
 }
 
 /*

Joel Fernandes

author

2018-04-30 16:52 UTC #2 lore raw

Quoted 26 lines · Steven Rostedt

Quoted 14 lines · On Thu, 26 Apr 2018 21:11:00 -0700 Joel Fernandes <[email protected]> wrote:

I'm able to reproduce a lockdep splat when CONFIG_PROVE_LOCKING=y and CONFIG_PREEMPTIRQ_EVENTS=y.

$ echo 1 > /d/tracing/events/preemptirq/preempt_enable/enable
---
[   26.112609] DEBUG_LOCKS_WARN_ON(current->softirqs_enabled)
[   26.112636] WARNING: CPU: 0 PID: 118 at kernel/locking/lockdep.c:3854
[...]
[   26.144229] Call Trace:
[   26.144926]  <IRQ>
[   26.145506]  lock_acquire+0x55/0x1b0
[   26.146499]  ? __do_softirq+0x46f/0x4d9
[   26.147571]  ? __do_softirq+0x46f/0x4d9
[   26.148646]  trace_preempt_on+0x8f/0x240

Quoted 8 lines

[   26.149744]  ? trace_preempt_on+0x4d/0x240
[   26.150862]  ? __do_softirq+0x46f/0x4d9
[   26.151930]  preempt_count_sub+0x18a/0x1a0
[   26.152985]  __do_softirq+0x46f/0x4d9
[   26.153937]  irq_exit+0x68/0xe0
[   26.154755]  smp_apic_timer_interrupt+0x271/0x280
[   26.156056]  apic_timer_interrupt+0xf/0x20
[   26.157105]  </IRQ>

Quoted 1 line

I'm not able to trigger this. Is there more to it?

No that should be it. I have a 100% repro on v4.16. I will try on a newer kernel and let you know.

thanks,

- Joel

Joel Fernandes

author

2018-04-30 17:01 UTC #3 lore raw

Quoted 1 line · Joel Fernandes

On Mon, Apr 30, 2018 at 9:38 AM Steven Rostedt <[email protected]>

Quoted 10 lines · wrote:

Quoted 10 lines
Quoted 7 lines · On Thu, 26 Apr 2018 21:11:00 -0700 Joel Fernandes <[email protected]> wrote:
I'm able to reproduce a lockdep splat when CONFIG_PROVE_LOCKING=y and CONFIG_PREEMPTIRQ_EVENTS=y.
$ echo 1 > /d/tracing/events/preemptirq/preempt_enable/enable
---
[   26.112609] DEBUG_LOCKS_WARN_ON(current->softirqs_enabled)
[   26.112636] WARNING: CPU: 0 PID: 118 at

kernel/locking/lockdep.c:3854

Quoted 16 lines

Quoted 15 lines

[...]

[   26.144229] Call Trace:
[   26.144926]  <IRQ>
[   26.145506]  lock_acquire+0x55/0x1b0
[   26.146499]  ? __do_softirq+0x46f/0x4d9
[   26.147571]  ? __do_softirq+0x46f/0x4d9
[   26.148646]  trace_preempt_on+0x8f/0x240
[   26.149744]  ? trace_preempt_on+0x4d/0x240
[   26.150862]  ? __do_softirq+0x46f/0x4d9
[   26.151930]  preempt_count_sub+0x18a/0x1a0
[   26.152985]  __do_softirq+0x46f/0x4d9
[   26.153937]  irq_exit+0x68/0xe0
[   26.154755]  smp_apic_timer_interrupt+0x271/0x280
[   26.156056]  apic_timer_interrupt+0xf/0x20
[   26.157105]  </IRQ>

Quoted 4 lines

Quoted 1 line
I'm not able to trigger this. Is there more to it?
No that should be it. I have a 100% repro on v4.16. I will try on a newer kernel and let you know.

Tried 4.17-rc3 and see it too. Could be difference in configs? Also, the environment is a Qemu system with single CPU 1GB memory. Attached is the config.

I think when I had multiple CPUs it was harder to trigger it, but can't really remember now. There was a time when triggering it was quite intermittent.

thanks,

- Joel

Steven Rostedt

2018-04-30 22:00 UTC #4 lore raw

On Mon, 30 Apr 2018 17:01:04 +0000
Joel Fernandes <[email protected]> wrote:
Tried 4.17-rc3 and see it too. Could be difference in configs? Also, the

Quoted 7 lines

environment is a Qemu system with single CPU 1GB memory. Attached is the config.
I think when I had multiple CPUs it was harder to trigger it, but can't really remember now. There was a time when triggering it was quite intermittent.

Bah, I didn't have CONFIG_DEBUG_LOCKDEP enabled, and that is what does the backtrace.

-- Steve

Steven Rostedt

Reviewed-by on v1 1/1

2018-05-01 13:49 UTC #5 lore raw

In reply to Joel Fernandes

Quoted 23 lines · On Thu, 26 Apr 2018 21:11:00 -0700 Joel Fernandes <[email protected]> wrote:

I'm able to reproduce a lockdep splat when CONFIG_PROVE_LOCKING=y and CONFIG_PREEMPTIRQ_EVENTS=y.

$ echo 1 > /d/tracing/events/preemptirq/preempt_enable/enable
---
[   26.112609] DEBUG_LOCKS_WARN_ON(current->softirqs_enabled)
[   26.112636] WARNING: CPU: 0 PID: 118 at kernel/locking/lockdep.c:3854
[...]
[   26.144229] Call Trace:
[   26.144926]  <IRQ>
[   26.145506]  lock_acquire+0x55/0x1b0
[   26.146499]  ? __do_softirq+0x46f/0x4d9
[   26.147571]  ? __do_softirq+0x46f/0x4d9
[   26.148646]  trace_preempt_on+0x8f/0x240
[   26.149744]  ? trace_preempt_on+0x4d/0x240
[   26.150862]  ? __do_softirq+0x46f/0x4d9
[   26.151930]  preempt_count_sub+0x18a/0x1a0
[   26.152985]  __do_softirq+0x46f/0x4d9
[   26.153937]  irq_exit+0x68/0xe0
[   26.154755]  smp_apic_timer_interrupt+0x271/0x280
[   26.156056]  apic_timer_interrupt+0xf/0x20
[   26.157105]  </IRQ>

Quoted 7 lines

The problem is the softirqs annotation in lockdep goes out of sync with the reality of the world that softirq is still off. This causes a lockdep splat because the preempt_count_sub can call into a preemptoff tracer or the trace events code, which inturn can call into lockdep *before* softirqs are really turned back on, which can cause a softirqs invalid annotation splat in lockdep.

OK, so the issue was this:

preempt_count = 1 << SOFTIRQ_SHIFT

	__local_bh_enable(cnt = 1 << SOFTIRQ_SHIFT) {
		if (softirq_count() == (cnt && SOFTIRQ_MASK)) {
			trace_softirqs_on() {
				current->softirqs_enabled = 1;
			}
		}
		preempt_count_sub(cnt) {
			trace_preempt_on() {
				tracepoint() {
					rcu_read_lock_sched() {
						// jumps into lockdep

Where preempt_count still has softirqs disabled, but current->softirqs_enabled is true, and we get a splat.

Your patch makes the tracing happen before we monkey with softirqs.

Yeah, looks good to me.

Reviewed-by Steven Rostedt (VMware) <[email protected]>

Thomas, you want to take this?

-- Steve

Quoted 51 lines

The same issue was fixed in local_bh_disable_ip which has a comment so:
/*
* The preempt tracer hooks into preempt_count_add and will break
* lockdep because it calls back into lockdep after SOFTIRQ_OFFSET
* is set and before current->softirq_enabled is cleared.
* We must manually increment preempt_count here and manually
* call the trace_preempt_off later.
*/
I have done a similar change to the local_bh_enable path to fix it.
Cc Steven Rostedt <[email protected]>
Cc Peter Zilstra <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Mathieu Desnoyers <[email protected]>
Cc Tom Zanussi <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Thomas Glexiner <[email protected]>
Cc Boqun Feng <[email protected]>
Cc Paul McKenney <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Randy Dunlap <[email protected]>
Cc Masami Hiramatsu <[email protected]>
Cc Fenguang Wu <[email protected]>
Cc Baohong Liu <[email protected]>
Cc Vedang Patel <[email protected]>
Cc [email protected]
Signed-off-by Joel Fernandes <[email protected]>
---
 kernel/softirq.c | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)
kernel/softirq.c +5 -1
index 177de3640c78..8a040bcaa033 100644
@@ -139,9 +139,13 @@ static void __local_bh_enable(unsigned int cnt)
 {
 	lockdep_assert_irqs_disabled();
 
+	if (preempt_count() == cnt)
+		trace_preempt_on(CALLER_ADDR0, get_lock_parent_ip());
+
 	if (softirq_count() == (cnt & SOFTIRQ_MASK))
 		trace_softirqs_on(_RET_IP_);
-	preempt_count_sub(cnt);
+
+	__preempt_count_sub(cnt);
 }
 
 /*

Steven Rostedt

2018-06-20 20:05 UTC #6 lore raw

In reply to Joel Fernandes

Peter, can you ack this.

Quoted 5 lines · On Thu, 26 Apr 2018 21:11:00 -0700 Joel Fernandes <[email protected]> wrote:

I'm able to reproduce a lockdep splat when CONFIG_PROVE_LOCKING=y and CONFIG_PREEMPTIRQ_EVENTS=y.
$ echo 1 > /d/tracing/events/preemptirq/preempt_enable/enable
---

BTW, the "---" here causes git to ignore everything underneath it :-/

Quoted 34 lines

[   26.112609] DEBUG_LOCKS_WARN_ON(current->softirqs_enabled)
[   26.112636] WARNING: CPU: 0 PID: 118 at kernel/locking/lockdep.c:3854
[...]
[   26.144229] Call Trace:
[   26.144926]  <IRQ>
[   26.145506]  lock_acquire+0x55/0x1b0
[   26.146499]  ? __do_softirq+0x46f/0x4d9
[   26.147571]  ? __do_softirq+0x46f/0x4d9
[   26.148646]  trace_preempt_on+0x8f/0x240
[   26.149744]  ? trace_preempt_on+0x4d/0x240
[   26.150862]  ? __do_softirq+0x46f/0x4d9
[   26.151930]  preempt_count_sub+0x18a/0x1a0
[   26.152985]  __do_softirq+0x46f/0x4d9
[   26.153937]  irq_exit+0x68/0xe0
[   26.154755]  smp_apic_timer_interrupt+0x271/0x280
[   26.156056]  apic_timer_interrupt+0xf/0x20
[   26.157105]  </IRQ>
The problem is the softirqs annotation in lockdep goes out of sync with the reality of the world that softirq is still off. This causes a lockdep splat because the preempt_count_sub can call into a preemptoff tracer or the trace events code, which inturn can call into lockdep *before* softirqs are really turned back on, which can cause a softirqs invalid annotation splat in lockdep.
The same issue was fixed in local_bh_disable_ip which has a comment so:
/*
* The preempt tracer hooks into preempt_count_add and will break
* lockdep because it calls back into lockdep after SOFTIRQ_OFFSET
* is set and before current->softirq_enabled is cleared.
* We must manually increment preempt_count here and manually
* call the trace_preempt_off later.
*/

Quoted 1 line

I have done a similar change to the local_bh_enable path to fix it.

I now have a config that triggers this with this test:

tools/testing/selftests/ftrace/ftracetest test.d/event/toplevel-enable.tc

and I see it never was Acked-by by Peter.

Peter, can you ack this and I can apply it. It does fix a lockdep corruption issue.

Thanks!

-- Steve

Quoted 41 lines

Cc Steven Rostedt <[email protected]>
Cc Peter Zilstra <[email protected]>
Cc Ingo Molnar <[email protected]>
Cc Mathieu Desnoyers <[email protected]>
Cc Tom Zanussi <[email protected]>
Cc Namhyung Kim <[email protected]>
Cc Thomas Glexiner <[email protected]>
Cc Boqun Feng <[email protected]>
Cc Paul McKenney <[email protected]>
Cc Frederic Weisbecker <[email protected]>
Cc Randy Dunlap <[email protected]>
Cc Masami Hiramatsu <[email protected]>
Cc Fenguang Wu <[email protected]>
Cc Baohong Liu <[email protected]>
Cc Vedang Patel <[email protected]>
Cc [email protected]
Signed-off-by Joel Fernandes <[email protected]>
---
 kernel/softirq.c | 6 +++++-
 1 file changed, 5 insertions(+), 1 deletion(-)
kernel/softirq.c +5 -1
index 177de3640c78..8a040bcaa033 100644
@@ -139,9 +139,13 @@ static void __local_bh_enable(unsigned int cnt)
 {
 	lockdep_assert_irqs_disabled();
 
+	if (preempt_count() == cnt)
+		trace_preempt_on(CALLER_ADDR0, get_lock_parent_ip());
+
 	if (softirq_count() == (cnt & SOFTIRQ_MASK))
 		trace_softirqs_on(_RET_IP_);
-	preempt_count_sub(cnt);
+
+	__preempt_count_sub(cnt);
 }
 
 /*

Joel Fernandes

2018-06-20 20:20 UTC #7 lore raw

Quoted 6 lines · Steven Rostedt

Peter, can you ack this.
On Thu, 26 Apr 2018 21:11:00 -0700
Joel Fernandes <[email protected]> wrote:

Quoted 7 lines

Quoted 5 lines
I'm able to reproduce a lockdep splat when CONFIG_PROVE_LOCKING=y and CONFIG_PREEMPTIRQ_EVENTS=y.
$ echo 1 > /d/tracing/events/preemptirq/preempt_enable/enable
---
BTW, the "---" here causes git to ignore everything underneath it :-/

Oh ok, I actually already fixed the '---' issue in the change log since then:

Here's a recent posting of the patch: https://patchwork.kernel.org/patch/10453483/
(patch is the same, only the commit log is fixed to remove '---').

thanks,

- Joel