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 an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.