From: Guenter Roeck <linux@roeck-us.net>
To: Peter Zijlstra <peterz@infradead.org>
Cc: linux-kernel@vger.kernel.org, mingo@kernel.org, will@kernel.org,
npiggin@gmail.com, elver@google.com, jgross@suse.com,
paulmck@kernel.org, rostedt@goodmis.org, rjw@rjwysocki.net,
joel@joelfernandes.org, svens@linux.ibm.com, tglx@linutronix.de
Subject: Re: [PATCH v2 11/11] lockdep,trace: Expose tracepoints
Date: Tue, 1 Sep 2020 20:51:46 -0700 [thread overview]
Message-ID: <20200902035146.GA45826@roeck-us.net> (raw)
In-Reply-To: <20200821085348.782688941@infradead.org>
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
next prev parent reply other threads:[~2020-09-02 3:51 UTC|newest]
Thread overview: 53+ messages / expand[flat|nested] mbox.gz Atom feed top
2020-08-21 8:47 [PATCH v2 00/11] TRACE_IRQFLAGS wreckage Peter Zijlstra
2020-08-21 8:47 ` [PATCH v2 01/11] lockdep: Use raw_cpu_*() for per-cpu variables Peter Zijlstra
2020-08-27 1:05 ` Joel Fernandes
2020-08-27 7:54 ` [tip: locking/core] " tip-bot2 for Peter Zijlstra
2020-08-21 8:47 ` [PATCH v2 02/11] cpuidle: Fixup IRQ state Peter Zijlstra
2020-08-21 17:36 ` Rafael J. Wysocki
2020-08-27 1:06 ` Joel Fernandes
2020-08-27 7:54 ` [tip: locking/core] " tip-bot2 for Peter Zijlstra
2020-08-21 8:47 ` [PATCH v2 03/11] sched,idle,rcu: Push rcu_idle deeper into the idle path Peter Zijlstra
2020-08-27 1:18 ` Joel Fernandes
2020-08-27 1:24 ` Joel Fernandes
2020-08-27 7:47 ` peterz
2020-08-27 7:53 ` Thomas Gleixner
2020-08-27 22:30 ` Joel Fernandes
2020-09-02 7:08 ` peterz
2020-08-27 7:54 ` [tip: locking/core] " tip-bot2 for Peter Zijlstra
2020-08-21 8:47 ` [PATCH v2 04/11] cpuidle: Make CPUIDLE_FLAG_TLB_FLUSHED generic Peter Zijlstra
2020-08-27 7:54 ` [tip: locking/core] " tip-bot2 for Peter Zijlstra
2020-08-21 8:47 ` [PATCH v2 05/11] cpuidle: Move trace_cpu_idle() into generic code Peter Zijlstra
2020-08-27 7:54 ` [tip: locking/core] " tip-bot2 for Peter Zijlstra
2020-08-21 8:47 ` [PATCH v2 06/11] x86/entry: Remove unused THUNKs Peter Zijlstra
2020-08-27 7:54 ` [tip: locking/core] " tip-bot2 for Peter Zijlstra
2020-08-21 8:47 ` [PATCH v2 07/11] locking/lockdep: Cleanup Peter Zijlstra
2020-08-27 7:54 ` [tip: locking/core] " tip-bot2 for Peter Zijlstra
2020-08-21 8:47 ` [PATCH v2 08/11] nds32: Implement arch_irqs_disabled() Peter Zijlstra
2020-08-27 7:54 ` [tip: locking/core] " tip-bot2 for Peter Zijlstra
2020-08-21 8:47 ` [PATCH v2 09/11] arm64: " Peter Zijlstra
2020-08-27 7:54 ` [tip: locking/core] " tip-bot2 for Peter Zijlstra
2020-08-21 8:47 ` [PATCH v2 10/11] lockdep: Only trace IRQ edges Peter Zijlstra
2020-08-26 0:47 ` Thomas Gleixner
2020-09-02 4:21 ` Guenter Roeck
2020-09-02 9:09 ` peterz
2020-09-02 9:12 ` peterz
2020-09-02 13:48 ` Guenter Roeck
2020-09-08 14:22 ` peterz
2020-09-08 14:40 ` Guenter Roeck
2020-09-08 15:41 ` [PATCH] sparc64: Fix irqtrace warnings on Ultra-S peterz
2020-08-21 8:47 ` [PATCH v2 11/11] lockdep,trace: Expose tracepoints Peter Zijlstra
2020-08-27 7:54 ` [tip: locking/core] " tip-bot2 for Peter Zijlstra
2020-09-02 3:51 ` Guenter Roeck [this message]
2020-09-02 7:24 ` [PATCH v2 11/11] " peterz
2020-09-02 13:21 ` Guenter Roeck
2020-09-02 8:56 ` peterz
2020-09-02 13:57 ` Guenter Roeck
2020-09-03 14:00 ` peterz
2020-09-03 14:13 ` peterz
2020-09-03 15:19 ` Guenter Roeck
2020-09-03 15:36 ` peterz
2020-09-03 15:54 ` Paul E. McKenney
2020-09-03 18:11 ` Guenter Roeck
2020-08-21 12:58 ` [PATCH v2 00/11] TRACE_IRQFLAGS wreckage peterz
2020-08-26 10:16 ` [PATCH v2 12/11] mips: Implement arch_irqs_disabled() peterz
2020-08-27 7:54 ` [tip: locking/core] " tip-bot2 for Peter Zijlstra
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20200902035146.GA45826@roeck-us.net \
--to=linux@roeck-us.net \
--cc=elver@google.com \
--cc=jgross@suse.com \
--cc=joel@joelfernandes.org \
--cc=linux-kernel@vger.kernel.org \
--cc=mingo@kernel.org \
--cc=npiggin@gmail.com \
--cc=paulmck@kernel.org \
--cc=peterz@infradead.org \
--cc=rjw@rjwysocki.net \
--cc=rostedt@goodmis.org \
--cc=svens@linux.ibm.com \
--cc=tglx@linutronix.de \
--cc=will@kernel.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox