* __local_bh_enable_ip() vs lockdep @ 2020-12-15 19:01 Heiko Carstens 2020-12-15 19:47 ` Steven Rostedt 0 siblings, 1 reply; 8+ messages in thread From: Heiko Carstens @ 2020-12-15 19:01 UTC (permalink / raw) To: Peter Zijlstra, Steven Rostedt, Thomas Gleixner Cc: linux-kernel, Sven Schnelle Hello, the ftrace stack tracer kernel selftest is able to trigger the warning below from time to time. This looks like there is an ordering problem in __local_bh_enable_ip(): first there is a call to lockdep_softirqs_on() and afterwards preempt_count_sub() is ftraced before it was able to modify preempt_count: [ 1016.245418] ------------[ cut here ]------------ [ 1016.245428] DEBUG_LOCKS_WARN_ON(current->softirqs_enabled) [ 1016.245441] WARNING: CPU: 8 PID: 8300 at kernel/locking/lockdep.c:5298 check_flags.part.0+0x196/0x208 [ 1016.245580] CPU: 8 PID: 8300 Comm: sshd Not tainted 5.11.0-20201215.rc0.git0.d33ce49dca6c.300.fc33.s390x+debug #1 ... [ 1016.245691] Call Trace: [ 1016.245698] [<000000004c1537fa>] check_flags.part.0+0x19a/0x208 [ 1016.245705] ([<000000004c1537f6>] check_flags.part.0+0x196/0x208) [ 1016.245711] [<000000004cced786>] lock_is_held_type+0x8e/0x1b8 [ 1016.245716] [<000000004c172924>] rcu_read_lock_sched_held+0x64/0xb8 [ 1016.245724] [<000000004c1b151c>] module_assert_mutex_or_preempt+0x34/0x68 [ 1016.245730] [<000000004c1b2e04>] __module_address.part.0+0x2c/0x118 [ 1016.245735] [<000000004c1b9dca>] __module_text_address+0x3a/0x90 [ 1016.245741] [<000000004c1b9ed4>] is_module_text_address+0x34/0x78 [ 1016.245748] [<000000004c0f9a1a>] kernel_text_address+0x5a/0x130 [ 1016.245752] [<000000004c0f9b16>] __kernel_text_address+0x26/0x70 [ 1016.245757] [<000000004c094038>] unwind_get_return_address+0x40/0x68 [ 1016.245763] [<000000004c099dac>] arch_stack_walk+0xac/0xd0 [ 1016.245768] [<000000004c18be10>] stack_trace_save+0x50/0x68 [ 1016.245774] [<000000004c22d80c>] check_stack+0xc4/0x348 [ 1016.245780] [<000000004c22db46>] stack_trace_call+0xb6/0xd0 [ 1016.245785] [<000000004cd00082>] ftrace_caller+0x7a/0x7e [ 1016.245791] [<000000004c1081d6>] preempt_count_sub+0x6/0x138 <--- [ 1016.245795] [<000000004c0d3d46>] __local_bh_enable_ip+0x13e/0x190 <--- [ 1016.245811] [<000003ff8023c34c>] nft_update_chain_stats+0xdc/0x168 [nf_tables] [ 1016.245820] [<000003ff8023c916>] nft_do_chain+0x53e/0x550 [nf_tables] [ 1016.245827] [<000003ff80251974>] nft_do_chain_ipv4+0x6c/0x78 [nf_tables] [ 1016.245833] [<000000004cb0ab00>] nf_hook_slow+0x58/0xf8 [ 1016.245839] [<000000004cb1dc24>] nf_hook.constprop.0+0xfc/0x1d0 [ 1016.245844] [<000000004cb207b2>] __ip_local_out+0x92/0xe8 [ 1016.245848] [<000000004cb20d00>] __ip_queue_xmit+0x1d8/0x640 [ 1016.245854] [<000000004cb4578c>] __tcp_transmit_skb+0x3dc/0x770 [ 1016.245858] [<000000004cb46e86>] tcp_write_xmit+0x38e/0x758 [ 1016.245863] [<000000004cb47298>] __tcp_push_pending_frames+0x48/0x118 [ 1016.245868] [<000000004cb2f604>] tcp_sendmsg_locked+0x95c/0xb78 [ 1016.245872] [<000000004cb2f864>] tcp_sendmsg+0x44/0x68 [ 1016.245878] [<000000004ca30c3c>] sock_sendmsg+0x64/0x78 [ 1016.245882] [<000000004ca30cc2>] sock_write_iter+0x72/0x98 [ 1016.245887] [<000000004c3dcfda>] new_sync_write+0x10a/0x198 [ 1016.245891] [<000000004c3dd6a6>] vfs_write.part.0+0x196/0x290 [ 1016.245896] [<000000004c3e0220>] ksys_write+0xb8/0xf8 [ 1016.245900] [<000000004ccfd326>] system_call+0xe2/0x29c [ 1016.245904] INFO: lockdep is turned off. ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: __local_bh_enable_ip() vs lockdep 2020-12-15 19:01 __local_bh_enable_ip() vs lockdep Heiko Carstens @ 2020-12-15 19:47 ` Steven Rostedt 2020-12-16 17:52 ` Peter Zijlstra 0 siblings, 1 reply; 8+ messages in thread From: Steven Rostedt @ 2020-12-15 19:47 UTC (permalink / raw) To: Heiko Carstens Cc: Peter Zijlstra, Thomas Gleixner, linux-kernel, Sven Schnelle On Tue, 15 Dec 2020 20:01:52 +0100 Heiko Carstens <hca@linux.ibm.com> wrote: > Hello, > > the ftrace stack tracer kernel selftest is able to trigger the warning > below from time to time. This looks like there is an ordering problem > in __local_bh_enable_ip(): > first there is a call to lockdep_softirqs_on() and afterwards > preempt_count_sub() is ftraced before it was able to modify > preempt_count: Don't run ftrace stack tracer when debugging lockdep. ;-) /me runs! -- Steve > > [ 1016.245418] ------------[ cut here ]------------ > [ 1016.245428] DEBUG_LOCKS_WARN_ON(current->softirqs_enabled) > [ 1016.245441] WARNING: CPU: 8 PID: 8300 at kernel/locking/lockdep.c:5298 check_flags.part.0+0x196/0x208 > [ 1016.245580] CPU: 8 PID: 8300 Comm: sshd Not tainted 5.11.0-20201215.rc0.git0.d33ce49dca6c.300.fc33.s390x+debug #1 > ... > [ 1016.245691] Call Trace: > [ 1016.245698] [<000000004c1537fa>] check_flags.part.0+0x19a/0x208 > [ 1016.245705] ([<000000004c1537f6>] check_flags.part.0+0x196/0x208) > [ 1016.245711] [<000000004cced786>] lock_is_held_type+0x8e/0x1b8 > [ 1016.245716] [<000000004c172924>] rcu_read_lock_sched_held+0x64/0xb8 > [ 1016.245724] [<000000004c1b151c>] module_assert_mutex_or_preempt+0x34/0x68 > [ 1016.245730] [<000000004c1b2e04>] __module_address.part.0+0x2c/0x118 > [ 1016.245735] [<000000004c1b9dca>] __module_text_address+0x3a/0x90 > [ 1016.245741] [<000000004c1b9ed4>] is_module_text_address+0x34/0x78 > [ 1016.245748] [<000000004c0f9a1a>] kernel_text_address+0x5a/0x130 > [ 1016.245752] [<000000004c0f9b16>] __kernel_text_address+0x26/0x70 > [ 1016.245757] [<000000004c094038>] unwind_get_return_address+0x40/0x68 > [ 1016.245763] [<000000004c099dac>] arch_stack_walk+0xac/0xd0 > [ 1016.245768] [<000000004c18be10>] stack_trace_save+0x50/0x68 > [ 1016.245774] [<000000004c22d80c>] check_stack+0xc4/0x348 > [ 1016.245780] [<000000004c22db46>] stack_trace_call+0xb6/0xd0 > [ 1016.245785] [<000000004cd00082>] ftrace_caller+0x7a/0x7e > [ 1016.245791] [<000000004c1081d6>] preempt_count_sub+0x6/0x138 <--- > [ 1016.245795] [<000000004c0d3d46>] __local_bh_enable_ip+0x13e/0x190 <--- > [ 1016.245811] [<000003ff8023c34c>] nft_update_chain_stats+0xdc/0x168 [nf_tables] > [ 1016.245820] [<000003ff8023c916>] nft_do_chain+0x53e/0x550 [nf_tables] > [ 1016.245827] [<000003ff80251974>] nft_do_chain_ipv4+0x6c/0x78 [nf_tables] > [ 1016.245833] [<000000004cb0ab00>] nf_hook_slow+0x58/0xf8 > [ 1016.245839] [<000000004cb1dc24>] nf_hook.constprop.0+0xfc/0x1d0 > [ 1016.245844] [<000000004cb207b2>] __ip_local_out+0x92/0xe8 > [ 1016.245848] [<000000004cb20d00>] __ip_queue_xmit+0x1d8/0x640 > [ 1016.245854] [<000000004cb4578c>] __tcp_transmit_skb+0x3dc/0x770 > [ 1016.245858] [<000000004cb46e86>] tcp_write_xmit+0x38e/0x758 > [ 1016.245863] [<000000004cb47298>] __tcp_push_pending_frames+0x48/0x118 > [ 1016.245868] [<000000004cb2f604>] tcp_sendmsg_locked+0x95c/0xb78 > [ 1016.245872] [<000000004cb2f864>] tcp_sendmsg+0x44/0x68 > [ 1016.245878] [<000000004ca30c3c>] sock_sendmsg+0x64/0x78 > [ 1016.245882] [<000000004ca30cc2>] sock_write_iter+0x72/0x98 > [ 1016.245887] [<000000004c3dcfda>] new_sync_write+0x10a/0x198 > [ 1016.245891] [<000000004c3dd6a6>] vfs_write.part.0+0x196/0x290 > [ 1016.245896] [<000000004c3e0220>] ksys_write+0xb8/0xf8 > [ 1016.245900] [<000000004ccfd326>] system_call+0xe2/0x29c > [ 1016.245904] INFO: lockdep is turned off. ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: __local_bh_enable_ip() vs lockdep 2020-12-15 19:47 ` Steven Rostedt @ 2020-12-16 17:52 ` Peter Zijlstra 2020-12-16 18:35 ` Heiko Carstens 2020-12-18 15:33 ` Heiko Carstens 0 siblings, 2 replies; 8+ messages in thread From: Peter Zijlstra @ 2020-12-16 17:52 UTC (permalink / raw) To: Steven Rostedt Cc: Heiko Carstens, Thomas Gleixner, linux-kernel, Sven Schnelle On Tue, Dec 15, 2020 at 02:47:24PM -0500, Steven Rostedt wrote: > On Tue, 15 Dec 2020 20:01:52 +0100 > Heiko Carstens <hca@linux.ibm.com> wrote: > > > Hello, > > > > the ftrace stack tracer kernel selftest is able to trigger the warning > > below from time to time. This looks like there is an ordering problem > > in __local_bh_enable_ip(): > > first there is a call to lockdep_softirqs_on() and afterwards > > preempt_count_sub() is ftraced before it was able to modify > > preempt_count: > > Don't run ftrace stack tracer when debugging lockdep. ;-) > > /me runs! Ha!, seriously though; that seems like something we've encountered before, but my google-fu is failing me. Do you remember what, if anything, was the problem with this? --- diff --git a/kernel/softirq.c b/kernel/softirq.c index d5bfd5e661fc..9d71046ea247 100644 --- a/kernel/softirq.c +++ b/kernel/softirq.c @@ -186,7 +186,7 @@ void __local_bh_enable_ip(unsigned long ip, unsigned int cnt) * Keep preemption disabled until we are done with * softirq processing: */ - preempt_count_sub(cnt - 1); + __preempt_count_sub(cnt - 1); if (unlikely(!in_interrupt() && local_softirq_pending())) { /* ^ permalink raw reply related [flat|nested] 8+ messages in thread
* Re: __local_bh_enable_ip() vs lockdep 2020-12-16 17:52 ` Peter Zijlstra @ 2020-12-16 18:35 ` Heiko Carstens 2020-12-18 15:33 ` Heiko Carstens 1 sibling, 0 replies; 8+ messages in thread From: Heiko Carstens @ 2020-12-16 18:35 UTC (permalink / raw) To: Peter Zijlstra Cc: Steven Rostedt, Thomas Gleixner, linux-kernel, Sven Schnelle On Wed, Dec 16, 2020 at 06:52:59PM +0100, Peter Zijlstra wrote: > On Tue, Dec 15, 2020 at 02:47:24PM -0500, Steven Rostedt wrote: > > On Tue, 15 Dec 2020 20:01:52 +0100 > > Heiko Carstens <hca@linux.ibm.com> wrote: > > > > > Hello, > > > > > > the ftrace stack tracer kernel selftest is able to trigger the warning > > > below from time to time. This looks like there is an ordering problem > > > in __local_bh_enable_ip(): > > > first there is a call to lockdep_softirqs_on() and afterwards > > > preempt_count_sub() is ftraced before it was able to modify > > > preempt_count: > > > > Don't run ftrace stack tracer when debugging lockdep. ;-) > > > > /me runs! > > Ha!, seriously though; that seems like something we've encountered > before, but my google-fu is failing me. > > Do you remember what, if anything, was the problem with this? Actually this looks like: 1a63dcd8765b ("softirq: Reorder trace_softirqs_on to prevent lockdep splat") I can give it a test, but it looks quite obvious that your patch will make the problem go away. > diff --git a/kernel/softirq.c b/kernel/softirq.c > index d5bfd5e661fc..9d71046ea247 100644 > --- a/kernel/softirq.c > +++ b/kernel/softirq.c > @@ -186,7 +186,7 @@ void __local_bh_enable_ip(unsigned long ip, unsigned int cnt) > * Keep preemption disabled until we are done with > * softirq processing: > */ > - preempt_count_sub(cnt - 1); > + __preempt_count_sub(cnt - 1); > > if (unlikely(!in_interrupt() && local_softirq_pending())) { > /* > ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: __local_bh_enable_ip() vs lockdep 2020-12-16 17:52 ` Peter Zijlstra 2020-12-16 18:35 ` Heiko Carstens @ 2020-12-18 15:33 ` Heiko Carstens 2020-12-18 15:37 ` Peter Zijlstra 1 sibling, 1 reply; 8+ messages in thread From: Heiko Carstens @ 2020-12-18 15:33 UTC (permalink / raw) To: Peter Zijlstra Cc: Steven Rostedt, Thomas Gleixner, linux-kernel, Sven Schnelle On Wed, Dec 16, 2020 at 06:52:59PM +0100, Peter Zijlstra wrote: > On Tue, Dec 15, 2020 at 02:47:24PM -0500, Steven Rostedt wrote: > > On Tue, 15 Dec 2020 20:01:52 +0100 > > Heiko Carstens <hca@linux.ibm.com> wrote: > > > > > Hello, > > > > > > the ftrace stack tracer kernel selftest is able to trigger the warning > > > below from time to time. This looks like there is an ordering problem > > > in __local_bh_enable_ip(): > > > first there is a call to lockdep_softirqs_on() and afterwards > > > preempt_count_sub() is ftraced before it was able to modify > > > preempt_count: > > > > Don't run ftrace stack tracer when debugging lockdep. ;-) > > > > /me runs! > > Ha!, seriously though; that seems like something we've encountered > before, but my google-fu is failing me. > > Do you remember what, if anything, was the problem with this? > > --- > diff --git a/kernel/softirq.c b/kernel/softirq.c > index d5bfd5e661fc..9d71046ea247 100644 > --- a/kernel/softirq.c > +++ b/kernel/softirq.c > @@ -186,7 +186,7 @@ void __local_bh_enable_ip(unsigned long ip, unsigned int cnt) > * Keep preemption disabled until we are done with > * softirq processing: > */ > - preempt_count_sub(cnt - 1); > + __preempt_count_sub(cnt - 1); > > if (unlikely(!in_interrupt() && local_softirq_pending())) { > /* FWIW, Tested-by: Heiko Carstens <hca@linux.ibm.com> Peter, will you make proper patch out of this? ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: __local_bh_enable_ip() vs lockdep 2020-12-18 15:33 ` Heiko Carstens @ 2020-12-18 15:37 ` Peter Zijlstra 2020-12-18 15:45 ` Peter Zijlstra 0 siblings, 1 reply; 8+ messages in thread From: Peter Zijlstra @ 2020-12-18 15:37 UTC (permalink / raw) To: Heiko Carstens Cc: Steven Rostedt, Thomas Gleixner, linux-kernel, Sven Schnelle On Fri, Dec 18, 2020 at 04:33:56PM +0100, Heiko Carstens wrote: > Peter, will you make proper patch out of this? Yes, let me go do that now, and stick it in the quilt series before I go off and don't think for 2 weeks. ^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: __local_bh_enable_ip() vs lockdep 2020-12-18 15:37 ` Peter Zijlstra @ 2020-12-18 15:45 ` Peter Zijlstra 2020-12-18 16:02 ` [tip: locking/urgent] softirq: Avoid bad tracing / lockdep interaction tip-bot2 for Peter Zijlstra 0 siblings, 1 reply; 8+ messages in thread From: Peter Zijlstra @ 2020-12-18 15:45 UTC (permalink / raw) To: Heiko Carstens Cc: Steven Rostedt, Thomas Gleixner, linux-kernel, Sven Schnelle On Fri, Dec 18, 2020 at 04:37:16PM +0100, Peter Zijlstra wrote: > On Fri, Dec 18, 2020 at 04:33:56PM +0100, Heiko Carstens wrote: > > > Peter, will you make proper patch out of this? > > Yes, let me go do that now, and stick it in the quilt series before I go > off and don't think for 2 weeks. As below, I'll try and push it out to tip/locking/urgent before I really dissapear. --- Subject: softirq: Avoid bad tracing / lockdep interaction From: Peter Zijlstra <peterz@infradead.org> Date: Fri Dec 18 16:39:14 CET 2020 Similar to commit: 1a63dcd8765b ("softirq: Reorder trace_softirqs_on to prevent lockdep splat") __local_bh_enable_ip() can also call into tracing with inconsistent state. Unlike that commit we don't need to bother about the tracepoint because 'cnt-1' never matches preempt_count() (by construction). Reported-by: Heiko Carstens <hca@linux.ibm.com> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org> Tested-by: Heiko Carstens <hca@linux.ibm.com> --- kernel/softirq.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) --- a/kernel/softirq.c +++ b/kernel/softirq.c @@ -186,7 +186,7 @@ void __local_bh_enable_ip(unsigned long * Keep preemption disabled until we are done with * softirq processing: */ - preempt_count_sub(cnt - 1); + __preempt_count_sub(cnt - 1); if (unlikely(!in_interrupt() && local_softirq_pending())) { /* ^ permalink raw reply [flat|nested] 8+ messages in thread
* [tip: locking/urgent] softirq: Avoid bad tracing / lockdep interaction 2020-12-18 15:45 ` Peter Zijlstra @ 2020-12-18 16:02 ` tip-bot2 for Peter Zijlstra 0 siblings, 0 replies; 8+ messages in thread From: tip-bot2 for Peter Zijlstra @ 2020-12-18 16:02 UTC (permalink / raw) To: linux-tip-commits Cc: Heiko Carstens, Peter Zijlstra (Intel), x86, linux-kernel The following commit has been merged into the locking/urgent branch of tip: Commit-ID: 91ea62d58bd661827c328a2c6c02a87fa4aae88b Gitweb: https://git.kernel.org/tip/91ea62d58bd661827c328a2c6c02a87fa4aae88b Author: Peter Zijlstra <peterz@infradead.org> AuthorDate: Fri, 18 Dec 2020 16:39:14 +01:00 Committer: Peter Zijlstra <peterz@infradead.org> CommitterDate: Fri, 18 Dec 2020 16:53:13 +01:00 softirq: Avoid bad tracing / lockdep interaction Similar to commit: 1a63dcd8765b ("softirq: Reorder trace_softirqs_on to prevent lockdep splat") __local_bh_enable_ip() can also call into tracing with inconsistent state. Unlike that commit we don't need to bother about the tracepoint because 'cnt-1' never matches preempt_count() (by construction). Reported-by: Heiko Carstens <hca@linux.ibm.com> Signed-off-by: Peter Zijlstra (Intel) <peterz@infradead.org> Tested-by: Heiko Carstens <hca@linux.ibm.com> Link: https://lkml.kernel.org/r/20201218154519.GW3092@hirez.programming.kicks-ass.net --- kernel/softirq.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/kernel/softirq.c b/kernel/softirq.c index 09229ad..0f1d3a3 100644 --- a/kernel/softirq.c +++ b/kernel/softirq.c @@ -185,7 +185,7 @@ void __local_bh_enable_ip(unsigned long ip, unsigned int cnt) * Keep preemption disabled until we are done with * softirq processing: */ - preempt_count_sub(cnt - 1); + __preempt_count_sub(cnt - 1); if (unlikely(!in_interrupt() && local_softirq_pending())) { /* ^ permalink raw reply related [flat|nested] 8+ messages in thread
end of thread, other threads:[~2020-12-18 16:03 UTC | newest] Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2020-12-15 19:01 __local_bh_enable_ip() vs lockdep Heiko Carstens 2020-12-15 19:47 ` Steven Rostedt 2020-12-16 17:52 ` Peter Zijlstra 2020-12-16 18:35 ` Heiko Carstens 2020-12-18 15:33 ` Heiko Carstens 2020-12-18 15:37 ` Peter Zijlstra 2020-12-18 15:45 ` Peter Zijlstra 2020-12-18 16:02 ` [tip: locking/urgent] softirq: Avoid bad tracing / lockdep interaction tip-bot2 for Peter Zijlstra
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).