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. Link: http://lkml.kernel.org/r/20180607201143.247775-1-joel@joelfernandes.org
Unified · Split
| @@ -139,9 +139,13 @@ static void __local_bh_enable(unsigned int cnt) · 138 unmodified lines | |||
| 139 | { | 139 | { |
| 140 | lockdep_assert_irqs_disabled(); | 140 | lockdep_assert_irqs_disabled(); |
| 141 | 141 | ||
| 142 | if (preempt_count() == cnt) | ||
| 143 | trace_preempt_on(CALLER_ADDR0, get_lock_parent_ip()); | ||
| 144 | |||
| 142 | if (softirq_count() == (cnt & SOFTIRQ_MASK)) | 145 | if (softirq_count() == (cnt & SOFTIRQ_MASK)) |
| 143 | trace_softirqs_on(_RET_IP_); | 146 | trace_softirqs_on(_RET_IP_); |
| 144 | preempt_count_sub(cnt); | 147 | |
| 148 | __preempt_count_sub(cnt); | ||
| 145 | } | 149 | } |
| 146 | 150 | ||
| 147 | /* | 151 | /* |