Re: [PATCH v2 10/11] lockdep: Only trace IRQ edges

[Guenter Roeck <linux@roeck-us.net>]

On Fri, Aug 21, 2020 at 10:47:48AM +0200, Peter Zijlstra wrote:
> From: Nicholas Piggin <npiggin@gmail.com>
> 
> Problem:
> 
> 	raw_local_irq_save();
> 	local_irq_save();
> 	...
> 	local_irq_restore();
> 	raw_local_irq_restore();
> 
> existing instances:
> 
>  - lock_acquire()
>      raw_local_irq_save()
>      __lock_acquire()
>        arch_spin_lock(&graph_lock)
>          pv_wait() := kvm_wait() (same or worse for Xen/HyperV)
>            local_irq_save()
> 
>  - trace_clock_global()
>      raw_local_irq_save()
>      arch_spin_lock()
>        pv_wait() := kvm_wait()
> 	 local_irq_save()
> 
>  - apic_retrigger_irq()
>      raw_local_irq_save()
>      apic->send_IPI() := default_send_IPI_single_phys()
>        local_irq_save()
> 
> Possible solutions:
> 
>  A) make it work by enabling the tracing inside raw_*()
>  B) make it work by keeping tracing disabled inside raw_*()
> 
> Now, given that the only reason to use the raw_* variant is because you don't
> want tracing, A) seems like a weird option (although it can be done), so we
> pick B) and declare any code that ends up doing:
> 
> 	raw_local_irq_save()
> 	local_irq_save()
> 	lockdep_assert_irqs_disabled();
> 
> broken. AFAICT this problem has existed forever, the only reason it came
> up is because I changed IRQ tracing vs lockdep recursion and the first
> instance is fairly common, the other cases hardly ever happen.
> 

On sparc64, this patch results in the traceback below. The traceback is gone
after reverting the patch.

Guenter

---
[    0.000000] WARNING: CPU: 0 PID: 0 at kernel/locking/lockdep.c:4875 check_flags.part.39+0x280/0x2a0
[    0.000000] DEBUG_LOCKS_WARN_ON(lockdep_hardirqs_enabled())
[    0.000000] Modules linked in:
[    0.000000] CPU: 0 PID: 0 Comm: swapper Not tainted 5.9.0-rc3 #1
[    0.000000] Call Trace:
[    0.000000] [<0000000000469890>] __warn+0xb0/0xe0
[    0.000000] [<00000000004698fc>] warn_slowpath_fmt+0x3c/0x80
[    0.000000] [<00000000004cfce0>] check_flags.part.39+0x280/0x2a0
[    0.000000] [<00000000004cff18>] lock_acquire+0x218/0x4e0
[    0.000000] [<0000000000d740c8>] _raw_spin_lock+0x28/0x40
[    0.000000] [<00000000009870f4>] p1275_cmd_direct+0x14/0x60
[    0.000000] [<00000000009872cc>] prom_getproplen+0x4c/0x60
[    0.000000] [<0000000000987308>] prom_getproperty+0x8/0x80
[    0.000000] [<0000000000987390>] prom_getint+0x10/0x40
[    0.000000] [<00000000017df4b4>] prom_init+0x38/0x8c
[    0.000000] [<0000000000d6b558>] tlb_fixup_done+0x44/0x6c
[    0.000000] [<00000000ffd0e930>] 0xffd0e930
[    0.000000] irq event stamp: 1
[    0.000000] hardirqs last  enabled at (1): [<0000000000987124>] p1275_cmd_direct+0x44/0x60
[    0.000000] hardirqs last disabled at (0): [<0000000000000000>] 0x0
[    0.000000] softirqs last  enabled at (0): [<0000000000000000>] 0x0
[    0.000000] softirqs last disabled at (0): [<0000000000000000>] 0x0
[    0.000000] random: get_random_bytes called from print_oops_end_marker+0x30/0x60 with crng_init=0
[    0.000000] ---[ end trace 0000000000000000 ]---
[    0.000000] possible reason: unannotated irqs-off.

---
bisect log:

# bad: [f75aef392f869018f78cfedf3c320a6b3fcfda6b] Linux 5.9-rc3
# good: [1127b219ce9481c84edad9711626d856127d5e51] Merge tag 'fallthrough-fixes-5.9-rc3' of git://git.kernel.org/pub/scm/linux/kernel/git/gustavoars/linux
git bisect start 'f75aef392f86' '1127b219ce94'
# good: [8bb5021cc2ee5d5dd129a9f2f5ad2bb76eea297d] Merge tag 'powerpc-5.9-4' of git://git.kernel.org/pub/scm/linux/kernel/git/powerpc/linux
git bisect good 8bb5021cc2ee5d5dd129a9f2f5ad2bb76eea297d
# good: [ceb2465c51195967f11f6507538579816ac67cb8] Merge tag 'irqchip-fixes-5.9-2' of git://git.kernel.org/pub/scm/linux/kernel/git/maz/arm-platforms into irq/urgent
git bisect good ceb2465c51195967f11f6507538579816ac67cb8
# bad: [b69bea8a657b681442765b06be92a2607b1bd875] Merge tag 'locking-urgent-2020-08-30' of git://git.kernel.org/pub/scm/linux/kernel/git/tip/tip
git bisect bad b69bea8a657b681442765b06be92a2607b1bd875
# good: [00b0ed2d4997af6d0a93edef820386951fd66d94] locking/lockdep: Cleanup
git bisect good 00b0ed2d4997af6d0a93edef820386951fd66d94
# bad: [044d0d6de9f50192f9697583504a382347ee95ca] lockdep: Only trace IRQ edges
git bisect bad 044d0d6de9f50192f9697583504a382347ee95ca
# good: [021c109330ebc1f54b546c63a078ea3c31356ecb] arm64: Implement arch_irqs_disabled()
git bisect good 021c109330ebc1f54b546c63a078ea3c31356ecb
# good: [99dc56feb7932020502d40107a712fa302b32082] mips: Implement arch_irqs_disabled()
git bisect good 99dc56feb7932020502d40107a712fa302b32082
# first bad commit: [044d0d6de9f50192f9697583504a382347ee95ca] lockdep: Only trace IRQ edges