From: "Joel Fernandes (Google)" <[email protected]>
I'm able to reproduce a lockdep splat with config options:
CONFIG_PROVE_LOCKING=y,
CONFIG_DEBUG_LOCK_ALLOC=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 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.
Cc: Steven Rostedt <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Linus Torvalds <[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: Masami Hiramatsu <[email protected]>
Cc: Todd Kjos <[email protected]>
Cc: Erick Reyes <[email protected]>
Cc: Julia Cartwright <[email protected]>
Cc: Byungchul Park <[email protected]>
Cc: [email protected]
Reviewed-by: Steven Rostedt (VMware) <[email protected]>
Fixes: d59158162e032 ("tracing: Add support for preempt and irq enable/disable events")
Signed-off-by: Joel Fernandes (Google) <[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.1.1185.g55be947832-goog
* Joel Fernandes <[email protected]> wrote:
> From: "Joel Fernandes (Google)" <[email protected]>
>
> I'm able to reproduce a lockdep splat with config options:
> CONFIG_PROVE_LOCKING=y,
> CONFIG_DEBUG_LOCK_ALLOC=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 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.
>
> Cc: Steven Rostedt <[email protected]>
> Cc: Peter Zijlstra <[email protected]>
> Cc: Ingo Molnar <[email protected]>
> Cc: Linus Torvalds <[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: Masami Hiramatsu <[email protected]>
> Cc: Todd Kjos <[email protected]>
> Cc: Erick Reyes <[email protected]>
> Cc: Julia Cartwright <[email protected]>
> Cc: Byungchul Park <[email protected]>
> Cc: [email protected]
> Reviewed-by: Steven Rostedt (VMware) <[email protected]>
> Fixes: d59158162e032 ("tracing: Add support for preempt and irq enable/disable events")
> Signed-off-by: Joel Fernandes (Google) <[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);
> }
Acked-by: Ingo Molnar <[email protected]>
Steve, wanna queue this up? Splat should only occur with tracing AFAICT.
Thanks,
Ingo
On Thu, 21 Jun 2018 15:08:48 +0200
Ingo Molnar <[email protected]> wrote:
> Acked-by: Ingo Molnar <[email protected]>
Thanks a lot Ingo!
>
> Steve, wanna queue this up? Splat should only occur with tracing AFAICT.
Yeah, I'll take this in my tree.
-- Steve