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(-)
diff --git a/kernel/softirq.c b/kernel/softirq.c
index 177de3640c78..8a040bcaa033 100644
--- a/kernel/softirq.c
+++ b/kernel/softirq.c
@@ -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);
}
/*
--
2.17.0.441.gb46fe60e1d-goog
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>
I'm not able to trigger this. Is there more to it?
-- Steve
>
> 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(-)
>
> diff --git a/kernel/softirq.c b/kernel/softirq.c
> index 177de3640c78..8a040bcaa033 100644
> --- a/kernel/softirq.c
> +++ b/kernel/softirq.c
> @@ -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);
> }
>
> /*
On Mon, Apr 30, 2018 at 9:38 AM Steven Rostedt <[email protected]> wrote:
> 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>
> 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
On Mon, Apr 30, 2018 at 9:52 AM Joel Fernandes <[email protected]> wrote:
> On Mon, Apr 30, 2018 at 9:38 AM Steven Rostedt <[email protected]>
wrote:
> > 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>
> > 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
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
> 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
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>
>
> 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
> 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(-)
>
> diff --git a/kernel/softirq.c b/kernel/softirq.c
> index 177de3640c78..8a040bcaa033 100644
> --- a/kernel/softirq.c
> +++ b/kernel/softirq.c
> @@ -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);
> }
>
> /*
Peter, can you ack this.
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 :-/
> [ 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.
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
>
> 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(-)
>
> diff --git a/kernel/softirq.c b/kernel/softirq.c
> index 177de3640c78..8a040bcaa033 100644
> --- a/kernel/softirq.c
> +++ b/kernel/softirq.c
> @@ -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);
> }
>
> /*
On Wed, Jun 20, 2018 at 04:05:13PM -0400, Steven Rostedt wrote:
>
> Peter, can you ack this.
>
> 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 :-/
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