Date:   Tue, 1 Sep 2020 20:51:46 -0700
From:   Guenter Roeck <linux@...ck-us.net>
To:     Peter Zijlstra <peterz@...radead.org>
Cc:     linux-kernel@...r.kernel.org, mingo@...nel.org, will@...nel.org,
        npiggin@...il.com, elver@...gle.com, jgross@...e.com,
        paulmck@...nel.org, rostedt@...dmis.org, rjw@...ysocki.net,
        joel@...lfernandes.org, svens@...ux.ibm.com, tglx@...utronix.de
Subject: Re: [PATCH v2 11/11] lockdep,trace: Expose tracepoints

On Fri, Aug 21, 2020 at 10:47:49AM +0200, Peter Zijlstra wrote:
> The lockdep tracepoints are under the lockdep recursion counter, this
> has a bunch of nasty side effects:
> 
>  - TRACE_IRQFLAGS doesn't work across the entire tracepoint
> 
>  - RCU-lockdep doesn't see the tracepoints either, hiding numerous
>    "suspicious RCU usage" warnings.
> 
> Pull the trace_lock_*() tracepoints completely out from under the
> lockdep recursion handling and completely rely on the trace level
> recusion handling -- also, tracing *SHOULD* not be taking locks in any
> case.
> 

Wonder what is worse - the problem or its fix. This patch results in
a number of WARNING backtraces for several archtectures/platforms.
Reverting it fixes the problems.

Guenter

---
arm:

[   27.055084]
[   27.056213] =============================
[   27.056274] WARNING: suspicious RCU usage
[   27.056335] 5.9.0-rc3 #1 Not tainted
[   27.056396] -----------------------------
[   27.056457] include/trace/events/lock.h:13 suspicious rcu_dereference_check() usage!
[   27.056549]
[   27.056549] other info that might help us debug this:
[   27.056549]
[   27.056640]
[   27.056640] rcu_scheduler_active = 2, debug_locks = 1
[   27.056732] RCU used illegally from extended quiescent state!
[   27.056793] no locks held by swapper/0/0.
[   27.056854]
[   27.056854] stack backtrace:
[   27.056915] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.9.0-rc3 #1
[   27.057006] Hardware name: Generic OMAP3-GP (Flattened Device Tree)
[   27.057098] [<c03125b4>] (unwind_backtrace) from [<c030c32c>] (show_stack+0x10/0x14)
[   27.057189] [<c030c32c>] (show_stack) from [<c08e7a4c>] (dump_stack+0xd8/0xf8)
[   27.057312] [<c08e7a4c>] (dump_stack) from [<c03b04bc>] (lock_acquire+0x4d8/0x4dc)
[   27.057464] [<c03b04bc>] (lock_acquire) from [<c12457e8>] (_raw_spin_lock_irqsave+0x58/0x74)
[   27.057617] [<c12457e8>] (_raw_spin_lock_irqsave) from [<c0338198>] (pwrdm_lock+0x10/0x18)
[   27.057739] [<c0338198>] (pwrdm_lock) from [<c033a214>] (clkdm_deny_idle+0x10/0x24)
[   27.057891] [<c033a214>] (clkdm_deny_idle) from [<c0332e10>] (omap3_enter_idle_bm+0xd4/0x1b8)
[   27.058044] [<c0332e10>] (omap3_enter_idle_bm) from [<c0f740d4>] (cpuidle_enter_state+0x16c/0x620)
[   27.058197] [<c0f740d4>] (cpuidle_enter_state) from [<c0f745ec>] (cpuidle_enter+0x50/0x54)
[   27.058349] [<c0f745ec>] (cpuidle_enter) from [<c0383aac>] (do_idle+0x228/0x2b8)
[   27.058471] [<c0383aac>] (do_idle) from [<c0383f34>] (cpu_startup_entry+0x18/0x1c)
[   27.058624] [<c0383f34>] (cpu_startup_entry) from [<c1c00e8c>] (start_kernel+0x518/0x558)
[   27.059692]
[   27.059753] =============================
[   27.059753] WARNING: suspicious RCU usage
[   27.059753] 5.9.0-rc3 #1 Not tainted
[   27.059753] -----------------------------
[   27.059753] include/trace/events/lock.h:58 suspicious rcu_dereference_check() usage!
[   27.059783]
[   27.059783] other info that might help us debug this:
[   27.059783]
[   27.059783]
[   27.059783] rcu_scheduler_active = 2, debug_locks = 1
[   27.059783] RCU used illegally from extended quiescent state!
[   27.059783] 1 lock held by swapper/0/0:
[   27.059814]  #0: c1e30f3c (logbuf_lock){-...}-{2:2}, at: vprintk_emit+0x60/0x38c
[   27.059906]
[   27.059936] stack backtrace:
[   27.059936] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.9.0-rc3 #1
[   27.059936] Hardware name: Generic OMAP3-GP (Flattened Device Tree)
[   27.059936] [<c03125b4>] (unwind_backtrace) from [<c030c32c>] (show_stack+0x10/0x14)
[   27.059936] [<c030c32c>] (show_stack) from [<c08e7a4c>] (dump_stack+0xd8/0xf8)
[   27.059936] [<c08e7a4c>] (dump_stack) from [<c03b4e70>] (lock_release+0x41c/0x420)
[   27.059936] [<c03b4e70>] (lock_release) from [<c124598c>] (_raw_spin_unlock+0x14/0x38)
[   27.059967] [<c124598c>] (_raw_spin_unlock) from [<c03c34c8>] (vprintk_emit+0xb4/0x38c)
[   27.059967] [<c03c34c8>] (vprintk_emit) from [<c03c37c0>] (vprintk_default+0x20/0x28)
[   27.059967] [<c03c37c0>] (vprintk_default) from [<c03c4088>] (printk+0x30/0x5c)
[   27.059967] [<c03c4088>] (printk) from [<c03b6c0c>] (lockdep_rcu_suspicious+0x2c/0xec)
[   27.059967] [<c03b6c0c>] (lockdep_rcu_suspicious) from [<c03b04bc>] (lock_acquire+0x4d8/0x4dc)
[   27.059967] [<c03b04bc>] (lock_acquire) from [<c12457e8>] (_raw_spin_lock_irqsave+0x58/0x74)
[   27.059997] [<c12457e8>] (_raw_spin_lock_irqsave) from [<c0338198>] (pwrdm_lock+0x10/0x18)
[   27.059997] [<c0338198>] (pwrdm_lock) from [<c033a214>] (clkdm_deny_idle+0x10/0x24)
[   27.059997] [<c033a214>] (clkdm_deny_idle) from [<c0332e10>] (omap3_enter_idle_bm+0xd4/0x1b8)
[   27.059997] [<c0332e10>] (omap3_enter_idle_bm) from [<c0f740d4>] (cpuidle_enter_state+0x16c/0x620)
[   27.059997] [<c0f740d4>] (cpuidle_enter_state) from [<c0f745ec>] (cpuidle_enter+0x50/0x54)
[   27.059997] [<c0f745ec>] (cpuidle_enter) from [<c0383aac>] (do_idle+0x228/0x2b8)
[   27.059997] [<c0383aac>] (do_idle) from [<c0383f34>] (cpu_startup_entry+0x18/0x1c)
[   27.060028] [<c0383f34>] (cpu_startup_entry) from [<c1c00e8c>] (start_kernel+0x518/0x558)

s390:

[   19.490586] =============================
[   19.490752] WARNING: suspicious RCU usage
[   19.490921] 5.9.0-rc3 #1 Not tainted
[   19.491086] -----------------------------
[   19.491253] include/trace/events/lock.h:37 suspicious rcu_dereference_check() usage!
[   19.491418]
[   19.491418] other info that might help us debug this:
[   19.491418]
[   19.491613]
[   19.491613] rcu_scheduler_active = 2, debug_locks = 1
[   19.491779] RCU used illegally from extended quiescent state!
[   19.491950] no locks held by swapper/0/0.
[   19.492118]
[   19.492118] stack backtrace:
[   19.492292] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.9.0-rc3 #1
[   19.492458] Hardware name: QEMU 2964 QEMU (KVM/Linux)
[   19.492622] Call Trace:
[   19.492798]  [<00000000001164f2>] show_stack+0x9a/0x100
[   19.492972]  [<0000000000982b94>] dump_stack+0x9c/0xd0
[   19.493147]  [<00000000001d5de2>] lock_acquire+0x41a/0x498
[   19.493320]  [<0000000000103b72>] enabled_wait+0xca/0x198
[   19.493493]  [<0000000000103f80>] arch_cpu_idle+0x20/0x38
[   19.493667]  [<0000000000e03c30>] default_idle_call+0x98/0x300
[   19.493847]  [<000000000019958c>] do_idle+0xe4/0x190
[   19.494021]  [<00000000001998f4>] cpu_startup_entry+0x34/0x38
[   19.494196]  [<00000000013a297a>] arch_call_rest_init+0x92/0x98
[   19.494362] no locks held by swapper/0/0.
[   19.497570]
[   19.497595] =============================
[   19.497605] WARNING: suspicious RCU usage
[   19.497614] 5.9.0-rc3 #1 Not tainted
[   19.497624] -----------------------------
[   19.497634] include/trace/events/lock.h:63 suspicious rcu_dereference_check() usage!
[   19.497643]
[   19.497652] other info that might help us debug this:
[   19.497661]
[   19.497669]
[   19.497679] rcu_scheduler_active = 2, debug_locks = 1
[   19.497689] RCU used illegally from extended quiescent state!
[   19.497698] 1 lock held by swapper/0/0:
[   19.497712]  #0: 0000000001252750 (logbuf_lock){-...}-{2:2}, at: vprintk_emit+0x70/0x368
[   19.497779]
[   19.497788] stack backtrace:
[   19.497797] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 5.9.0-rc3 #1
[   19.497807] Hardware name: QEMU 2964 QEMU (KVM/Linux)
[   19.497816] Call Trace:
[   19.497825]  [<00000000001164f2>] show_stack+0x9a/0x100
[   19.497835]  [<0000000000982b94>] dump_stack+0x9c/0xd0
[   19.497844]  [<00000000001d9914>] lock_release+0x334/0x350
[   19.497854]  [<0000000000e04354>] _raw_spin_unlock+0x2c/0x50
[   19.497863]  [<00000000001e6d5a>] vprintk_emit+0xb2/0x368
[   19.497873]  [<00000000001e704a>] vprintk_default+0x3a/0x48
[   19.497882]  [<00000000001e7b8c>] printk+0x4c/0x58
[   19.497892]  [<00000000001db3c2>] lockdep_rcu_suspicious+0x32/0x110
[   19.497902]  [<00000000001d5de2>] lock_acquire+0x41a/0x498
[   19.497911]  [<0000000000103b72>] enabled_wait+0xca/0x198
[   19.497921]  [<0000000000103f80>] arch_cpu_idle+0x20/0x38
[   19.497932]  [<0000000000e03c30>] default_idle_call+0x98/0x300
[   19.497943]  [<000000000019958c>] do_idle+0xe4/0x190
[   19.497954]  [<00000000001998f4>] cpu_startup_entry+0x34/0x38
[   19.497964]  [<00000000013a297a>] arch_call_rest_init+0x92/0x98
[   19.497974] 1 lock held by swapper/0/0:
[   19.497982]  #0: 0000000001252750 (logbuf_lock){-...}-{2:2}, at: vprintk_emit+0x70/0x368

Bisect log (for arm):

# 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
# good: [044d0d6de9f50192f9697583504a382347ee95ca] lockdep: Only trace IRQ edges
git bisect good 044d0d6de9f50192f9697583504a382347ee95ca
# good: [3edd8db2d53fe6c96ad66248bb1479ae62807268] Merge tag '5.9-rc2-smb-fix' of git://git.samba.org/sfrench/cifs-2.6
git bisect good 3edd8db2d53fe6c96ad66248bb1479ae62807268
# bad: [eb1f00237aca2e368b93db79303f8433d1976d10] lockdep,trace: Expose tracepoints
git bisect bad eb1f00237aca2e368b93db79303f8433d1976d10
# first bad commit: [eb1f00237aca2e368b93db79303f8433d1976d10] lockdep,trace: Expose tracepoints

Powered by blists - more mailing lists