Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]
Groups > linux.kernel > #1732829 > unrolled thread
| Started by | Neeraj Upadhyay <neeraju@codeaurora.org> |
|---|---|
| First post | 2017-09-15 13:20 +0200 |
| Last post | 2017-09-21 17:50 +0200 |
| Articles | 20 on this page of 35 — 7 participants |
Back to article view | Back to linux.kernel
Query regarding synchronize_sched_expedited and resched_cpu Neeraj Upadhyay <neeraju@codeaurora.org> - 2017-09-15 13:20 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-17 03:10 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Neeraj Upadhyay <neeraju@codeaurora.org> - 2017-09-17 08:10 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Steven Rostedt <rostedt@goodmis.org> - 2017-09-18 17:20 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-18 18:10 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Steven Rostedt <rostedt@goodmis.org> - 2017-09-18 18:20 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Steven Rostedt <rostedt@goodmis.org> - 2017-09-18 18:30 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-18 19:00 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-19 02:00 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Steven Rostedt <rostedt@goodmis.org> - 2017-09-19 03:30 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-19 04:30 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Byungchul Park <byungchul.park@lge.com> - 2017-09-19 04:00 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Byungchul Park <byungchul.park@lge.com> - 2017-09-19 04:10 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-19 04:40 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Byungchul Park <byungchul.park@lge.com> - 2017-09-19 04:50 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-19 06:10 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Boqun Feng <boqun.feng@gmail.com> - 2017-09-19 07:40 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Mike Galbraith <efault@gmx.de> - 2017-09-19 08:20 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Byungchul Park <byungchul.park@lge.com> - 2017-09-19 09:00 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-19 15:50 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Peter Zijlstra <peterz@infradead.org> - 2017-09-21 16:00 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-21 17:40 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Byungchul Park <byungchul.park@lge.com> - 2017-09-19 04:00 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-18 18:30 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-19 17:40 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Steven Rostedt <rostedt@goodmis.org> - 2017-09-19 18:00 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-19 18:20 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Peter Zijlstra <peterz@infradead.org> - 2017-09-21 16:10 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-21 18:10 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Peter Zijlstra <peterz@infradead.org> - 2017-09-21 18:40 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-21 18:50 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Peter Zijlstra <peterz@infradead.org> - 2017-09-21 16:00 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> - 2017-09-21 17:40 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Peter Zijlstra <peterz@infradead.org> - 2017-09-21 18:20 +0200
Re: Query regarding synchronize_sched_expedited and resched_cpu Steven Rostedt <rostedt@goodmis.org> - 2017-09-21 17:50 +0200
Page 1 of 2 [1] 2 Next page →
| From | Neeraj Upadhyay <neeraju@codeaurora.org> |
|---|---|
| Date | 2017-09-15 13:20 +0200 |
| Subject | Query regarding synchronize_sched_expedited and resched_cpu |
| Message-ID | <upWP8-22A-9@gated-at.bofh.it> |
Hi,
We have one query regarding the behavior of RCU expedited grace period,
for scenario where resched_cpu() in sync_sched_exp_handler() fails to
acquire the rq lock and returns w/o setting the need_resched. In this
case, how do we ensure that the CPU notify rcu about the
end of sched grace period (schedule() -> __schedule() ->
rcu_note_context_switch(cpu) -> rcu_sched_qs()) , for cases where tick
is stopped on that CPU. Is it implied from the rq lock acquisition
failure, that the owner of the rq lock will enforce context switch?
For which scenarios in RCU paths (as the function is used only in RCU
code), we need trylock check in resched_cpu()?
void resched_cpu(int cpu)
{
struct rq *rq = cpu_rq(cpu);
unsigned long flags;
if (!raw_spin_trylock_irqsave(&rq->lock, flags))
return;
resched_curr(rq);
raw_spin_unlock_irqrestore(&rq->lock, flags);
}
This issue was observed in below scenario, where one of the CPUs (CPU1)
started synchronize_sched_expedited and sent IPI to CPU5, which is in
the idle path but handled sync_sched_exp_handler() IPI before
rcu_idle_enter().
As resched_cpu() failed to acquire the rq lock, need_resched was not set,
and CPU went to idle; resulting in expedited stall getting reported by
CPU1.
Below is the scenario:
• CPU1 is waiting for expedited wait to complete:
sync_rcu_exp_select_cpus
rdp->exp_dynticks_snap & 0x1 // returns 1 for CPU5
IPI sent to CPU5
synchronize_sched_expedited_wait
ret = swait_event_timeout(
rsp->expedited_wq,
sync_rcu_preempt_exp_done(rnp_root),
jiffies_stall);
expmask = 0x20 , and CPU 5 is in idle path (in cpuidle_enter())
• CPU5 handles IPI and fails to acquire rq lock.
Handles IPI
sync_sched_exp_handler
resched_cpu
returns while failing to try lock acquire rq->lock
need_resched is not set
• CPU5 calls rcu_idle_enter() and as need_resched is not set, goes to
idle (schedule() is not called).
• CPU 1 reports RCU stall.
--
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a
member of the Code Aurora Forum, hosted by The Linux Foundation
[toc] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2017-09-17 03:10 +0200 |
| Message-ID | <uqwfT-Yw-3@gated-at.bofh.it> |
| In reply to | #1732829 |
On Fri, Sep 15, 2017 at 04:44:38PM +0530, Neeraj Upadhyay wrote:
> Hi,
>
> We have one query regarding the behavior of RCU expedited grace period,
> for scenario where resched_cpu() in sync_sched_exp_handler() fails to
> acquire the rq lock and returns w/o setting the need_resched. In this
> case, how do we ensure that the CPU notify rcu about the
> end of sched grace period (schedule() -> __schedule() ->
> rcu_note_context_switch(cpu) -> rcu_sched_qs()) , for cases where tick
> is stopped on that CPU. Is it implied from the rq lock acquisition
> failure, that the owner of the rq lock will enforce context switch?
> For which scenarios in RCU paths (as the function is used only in RCU
> code), we need trylock check in resched_cpu()?
>
> void resched_cpu(int cpu)
> {
> struct rq *rq = cpu_rq(cpu);
> unsigned long flags;
>
> if (!raw_spin_trylock_irqsave(&rq->lock, flags))
> return;
> resched_curr(rq);
> raw_spin_unlock_irqrestore(&rq->lock, flags);
> }
>
>
> This issue was observed in below scenario, where one of the CPUs (CPU1)
> started synchronize_sched_expedited and sent IPI to CPU5, which is in
> the idle path but handled sync_sched_exp_handler() IPI before
> rcu_idle_enter().
> As resched_cpu() failed to acquire the rq lock, need_resched was not set,
> and CPU went to idle; resulting in expedited stall getting reported
> by CPU1.
>
> Below is the scenario:
>
> • CPU1 is waiting for expedited wait to complete:
> sync_rcu_exp_select_cpus
> rdp->exp_dynticks_snap & 0x1 // returns 1 for CPU5
> IPI sent to CPU5
>
> synchronize_sched_expedited_wait
> ret = swait_event_timeout(
> rsp->expedited_wq,
> sync_rcu_preempt_exp_done(rnp_root),
> jiffies_stall);
>
> expmask = 0x20 , and CPU 5 is in idle path (in cpuidle_enter())
>
>
>
> • CPU5 handles IPI and fails to acquire rq lock.
>
> Handles IPI
> sync_sched_exp_handler
> resched_cpu
> returns while failing to try lock acquire rq->lock
> need_resched is not set
>
> • CPU5 calls rcu_idle_enter() and as need_resched is not set, goes to
> idle (schedule() is not called).
>
> • CPU 1 reports RCU stall.
Good catch and good detective work!!!
I will be working on a fix this week, hopefully involving resched_cpu()
getting a return value so that I can track who needs a later retry.
Thanx, Paul
[toc] | [prev] | [next] | [standalone]
| From | Neeraj Upadhyay <neeraju@codeaurora.org> |
|---|---|
| Date | 2017-09-17 08:10 +0200 |
| Message-ID | <uqAWd-432-1@gated-at.bofh.it> |
| In reply to | #1733360 |
On 09/17/2017 06:30 AM, Paul E. McKenney wrote:
> On Fri, Sep 15, 2017 at 04:44:38PM +0530, Neeraj Upadhyay wrote:
>> Hi,
>>
>> We have one query regarding the behavior of RCU expedited grace period,
>> for scenario where resched_cpu() in sync_sched_exp_handler() fails to
>> acquire the rq lock and returns w/o setting the need_resched. In this
>> case, how do we ensure that the CPU notify rcu about the
>> end of sched grace period (schedule() -> __schedule() ->
>> rcu_note_context_switch(cpu) -> rcu_sched_qs()) , for cases where tick
>> is stopped on that CPU. Is it implied from the rq lock acquisition
>> failure, that the owner of the rq lock will enforce context switch?
>> For which scenarios in RCU paths (as the function is used only in RCU
>> code), we need trylock check in resched_cpu()?
>>
>> void resched_cpu(int cpu)
>> {
>> struct rq *rq = cpu_rq(cpu);
>> unsigned long flags;
>>
>> if (!raw_spin_trylock_irqsave(&rq->lock, flags))
>> return;
>> resched_curr(rq);
>> raw_spin_unlock_irqrestore(&rq->lock, flags);
>> }
>>
>>
>> This issue was observed in below scenario, where one of the CPUs (CPU1)
>> started synchronize_sched_expedited and sent IPI to CPU5, which is in
>> the idle path but handled sync_sched_exp_handler() IPI before
>> rcu_idle_enter().
>> As resched_cpu() failed to acquire the rq lock, need_resched was not set,
>> and CPU went to idle; resulting in expedited stall getting reported
>> by CPU1.
>>
>> Below is the scenario:
>>
>> • CPU1 is waiting for expedited wait to complete:
>> sync_rcu_exp_select_cpus
>> rdp->exp_dynticks_snap & 0x1 // returns 1 for CPU5
>> IPI sent to CPU5
>>
>> synchronize_sched_expedited_wait
>> ret = swait_event_timeout(
>> rsp->expedited_wq,
>> sync_rcu_preempt_exp_done(rnp_root),
>> jiffies_stall);
>>
>> expmask = 0x20 , and CPU 5 is in idle path (in cpuidle_enter())
>>
>>
>>
>> • CPU5 handles IPI and fails to acquire rq lock.
>>
>> Handles IPI
>> sync_sched_exp_handler
>> resched_cpu
>> returns while failing to try lock acquire rq->lock
>> need_resched is not set
>>
>> • CPU5 calls rcu_idle_enter() and as need_resched is not set, goes to
>> idle (schedule() is not called).
>>
>> • CPU 1 reports RCU stall.
> Good catch and good detective work!!!
>
> I will be working on a fix this week, hopefully involving resched_cpu()
> getting a return value so that I can track who needs a later retry.
>
> Thanx, Paul
>
Hi Paul, how about replacing raw_spin_trylock_irqsave with
raw_spin_lock_irqsave in resched_cpu()? Are there any paths
in RCU code, which depend on trylock check/spinlock recursion?
Thanks
Neeraj
--
QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a
member of the Code Aurora Forum, hosted by The Linux Foundation
[toc] | [prev] | [next] | [standalone]
| From | Steven Rostedt <rostedt@goodmis.org> |
|---|---|
| Date | 2017-09-18 17:20 +0200 |
| Message-ID | <ur603-7Z6-49@gated-at.bofh.it> |
| In reply to | #1733393 |
On Sun, 17 Sep 2017 11:37:06 +0530 Neeraj Upadhyay <neeraju@codeaurora.org> wrote: > Hi Paul, how about replacing raw_spin_trylock_irqsave with > raw_spin_lock_irqsave in resched_cpu()? Are there any paths > in RCU code, which depend on trylock check/spinlock recursion? It looks to me that resched_cpu() was added for nohz full sched balancing, but is not longer used by that. The only user is currently RCU. Perhaps we should change that from a trylock to a lock. -- Steve
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2017-09-18 18:10 +0200 |
| Message-ID | <ur6Mr-8un-51@gated-at.bofh.it> |
| In reply to | #1734223 |
On Mon, Sep 18, 2017 at 11:11:05AM -0400, Steven Rostedt wrote:
> On Sun, 17 Sep 2017 11:37:06 +0530
> Neeraj Upadhyay <neeraju@codeaurora.org> wrote:
>
> > Hi Paul, how about replacing raw_spin_trylock_irqsave with
> > raw_spin_lock_irqsave in resched_cpu()? Are there any paths
> > in RCU code, which depend on trylock check/spinlock recursion?
>
> It looks to me that resched_cpu() was added for nohz full sched
> balancing, but is not longer used by that. The only user is currently
> RCU. Perhaps we should change that from a trylock to a lock.
That certainly is a much simpler fix than the one I was thinking of!
So how about the following patch?
Thanx, Paul
------------------------------------------------------------------------
commit bc43e2e7e08134e6f403ac845edcf4f85668d803
Author: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Date: Mon Sep 18 08:54:40 2017 -0700
sched: Make resched_cpu() unconditional
The current implementation of synchronize_sched_expedited() incorrectly
assumes that resched_cpu() is unconditional, which it is not. This means
that synchronize_sched_expedited() can hang when resched_cpu()'s trylock
fails as follows (analysis by Neeraj Upadhyay):
o CPU1 is waiting for expedited wait to complete:
sync_rcu_exp_select_cpus
rdp->exp_dynticks_snap & 0x1 // returns 1 for CPU5
IPI sent to CPU5
synchronize_sched_expedited_wait
ret = swait_event_timeout(
rsp->expedited_wq,
sync_rcu_preempt_exp_done(rnp_root),
jiffies_stall);
expmask = 0x20 , and CPU 5 is in idle path (in cpuidle_enter())
o CPU5 handles IPI and fails to acquire rq lock.
Handles IPI
sync_sched_exp_handler
resched_cpu
returns while failing to try lock acquire rq->lock
need_resched is not set
o CPU5 calls rcu_idle_enter() and as need_resched is not set, goes to
idle (schedule() is not called).
o CPU 1 reports RCU stall.
Given that resched_cpu() is used only by RCU, this commit fixes the
assumption by making resched_cpu() unconditional.
Reported-by: Neeraj Upadhyay <neeraju@codeaurora.org>
Suggested-by: Neeraj Upadhyay <neeraju@codeaurora.org>
Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
Cc: Peter Zijlstra <peterz@infradead.org>
Cc: Steven Rostedt <rostedt@goodmis.org>
diff --git a/kernel/sched/core.c b/kernel/sched/core.c
index cab8c5ec128e..b2281971894c 100644
--- a/kernel/sched/core.c
+++ b/kernel/sched/core.c
@@ -505,8 +505,7 @@ void resched_cpu(int cpu)
struct rq *rq = cpu_rq(cpu);
unsigned long flags;
- if (!raw_spin_trylock_irqsave(&rq->lock, flags))
- return;
+ raw_spin_lock_irqsave(&rq->lock, flags);
resched_curr(rq);
raw_spin_unlock_irqrestore(&rq->lock, flags);
}
[toc] | [prev] | [next] | [standalone]
| From | Steven Rostedt <rostedt@goodmis.org> |
|---|---|
| Date | 2017-09-18 18:20 +0200 |
| Message-ID | <ur6W7-7F-27@gated-at.bofh.it> |
| In reply to | #1734268 |
On Mon, 18 Sep 2017 09:01:25 -0700 "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote: > sched: Make resched_cpu() unconditional > > The current implementation of synchronize_sched_expedited() incorrectly > assumes that resched_cpu() is unconditional, which it is not. This means > that synchronize_sched_expedited() can hang when resched_cpu()'s trylock > fails as follows (analysis by Neeraj Upadhyay): > > o CPU1 is waiting for expedited wait to complete: > sync_rcu_exp_select_cpus > rdp->exp_dynticks_snap & 0x1 // returns 1 for CPU5 > IPI sent to CPU5 > > synchronize_sched_expedited_wait > ret = swait_event_timeout( > rsp->expedited_wq, > sync_rcu_preempt_exp_done(rnp_root), > jiffies_stall); > > expmask = 0x20 , and CPU 5 is in idle path (in cpuidle_enter()) > > o CPU5 handles IPI and fails to acquire rq lock. > > Handles IPI > sync_sched_exp_handler > resched_cpu > returns while failing to try lock acquire rq->lock > need_resched is not set > > o CPU5 calls rcu_idle_enter() and as need_resched is not set, goes to > idle (schedule() is not called). > > o CPU 1 reports RCU stall. > > Given that resched_cpu() is used only by RCU, this commit fixes the > assumption by making resched_cpu() unconditional. Probably want to run this with several workloads with lockdep enabled first. -- Steve > > Reported-by: Neeraj Upadhyay <neeraju@codeaurora.org> > Suggested-by: Neeraj Upadhyay <neeraju@codeaurora.org> > Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com> > Cc: Peter Zijlstra <peterz@infradead.org> > Cc: Steven Rostedt <rostedt@goodmis.org> > > diff --git a/kernel/sched/core.c b/kernel/sched/core.c > index cab8c5ec128e..b2281971894c 100644 > --- a/kernel/sched/core.c > +++ b/kernel/sched/core.c > @@ -505,8 +505,7 @@ void resched_cpu(int cpu) > struct rq *rq = cpu_rq(cpu); > unsigned long flags; > > - if (!raw_spin_trylock_irqsave(&rq->lock, flags)) > - return; > + raw_spin_lock_irqsave(&rq->lock, flags); > resched_curr(rq); > raw_spin_unlock_irqrestore(&rq->lock, flags); > }
[toc] | [prev] | [next] | [standalone]
| From | Steven Rostedt <rostedt@goodmis.org> |
|---|---|
| Date | 2017-09-18 18:30 +0200 |
| Message-ID | <ur75M-b2-39@gated-at.bofh.it> |
| In reply to | #1734274 |
On Mon, 18 Sep 2017 09:24:12 -0700
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> As soon as I work through the backlog of lockdep complaints that
> appeared in the last merge window... :-(
>
> sparse_irq_lock, I am looking at you!!! ;-)
I just hit one too, and decided to write a patch to show a chain of 3
when applicable.
For example:
Chain exists of:
cpu_hotplug_lock.rw_sem --> smpboot_threads_lock --> (complete)&self->parked
Possible unsafe locking scenario by crosslock:
CPU0 CPU1 CPU2
---- ---- ----
lock(smpboot_threads_lock);
lock((complete)&self->parked);
lock(cpu_hotplug_lock.rw_sem);
lock(smpboot_threads_lock);
lock(cpu_hotplug_lock.rw_sem);
unlock((complete)&self->parked);
*** DEADLOCK ***
:-)
-- Steve
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2017-09-18 19:00 +0200 |
| Message-ID | <ur7yO-mI-9@gated-at.bofh.it> |
| In reply to | #1734283 |
On Mon, Sep 18, 2017 at 12:29:31PM -0400, Steven Rostedt wrote:
> On Mon, 18 Sep 2017 09:24:12 -0700
> "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
>
>
> > As soon as I work through the backlog of lockdep complaints that
> > appeared in the last merge window... :-(
> >
> > sparse_irq_lock, I am looking at you!!! ;-)
>
> I just hit one too, and decided to write a patch to show a chain of 3
> when applicable.
>
> For example:
>
> Chain exists of:
> cpu_hotplug_lock.rw_sem --> smpboot_threads_lock --> (complete)&self->parked
>
> Possible unsafe locking scenario by crosslock:
>
> CPU0 CPU1 CPU2
> ---- ---- ----
> lock(smpboot_threads_lock);
> lock((complete)&self->parked);
> lock(cpu_hotplug_lock.rw_sem);
> lock(smpboot_threads_lock);
> lock(cpu_hotplug_lock.rw_sem);
> unlock((complete)&self->parked);
>
> *** DEADLOCK ***
>
> :-)
Nice!!!
My next step is reverting 12ac1d0f6c3e ("genirq: Make sparse_irq_lock
protect what it should protect") to see if that helps.
Thanx, Paul
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2017-09-19 02:00 +0200 |
| Message-ID | <ure7g-4Xi-1@gated-at.bofh.it> |
| In reply to | #1734303 |
On Mon, Sep 18, 2017 at 09:55:27AM -0700, Paul E. McKenney wrote:
> On Mon, Sep 18, 2017 at 12:29:31PM -0400, Steven Rostedt wrote:
> > On Mon, 18 Sep 2017 09:24:12 -0700
> > "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> >
> >
> > > As soon as I work through the backlog of lockdep complaints that
> > > appeared in the last merge window... :-(
> > >
> > > sparse_irq_lock, I am looking at you!!! ;-)
> >
> > I just hit one too, and decided to write a patch to show a chain of 3
> > when applicable.
> >
> > For example:
> >
> > Chain exists of:
> > cpu_hotplug_lock.rw_sem --> smpboot_threads_lock --> (complete)&self->parked
> >
> > Possible unsafe locking scenario by crosslock:
> >
> > CPU0 CPU1 CPU2
> > ---- ---- ----
> > lock(smpboot_threads_lock);
> > lock((complete)&self->parked);
> > lock(cpu_hotplug_lock.rw_sem);
> > lock(smpboot_threads_lock);
> > lock(cpu_hotplug_lock.rw_sem);
> > unlock((complete)&self->parked);
> >
> > *** DEADLOCK ***
> >
> > :-)
>
> Nice!!!
>
> My next step is reverting 12ac1d0f6c3e ("genirq: Make sparse_irq_lock
> protect what it should protect") to see if that helps.
No joy, but it is amazing how much nicer "git bisect" is when your
failure happens deterministically within 35 seconds. ;-)
The bisection converged to the range starting with 7a46ec0e2f48
("locking/refcounts, x86/asm: Implement fast refcount overflow
protection") and ending with 0c2364791343 ("Merge branch 'x86/asm'
into locking/core"). All of these failed with an unrelated build
error, but there was a fix that could be merged. This flagged
d0541b0fa64b ("locking/lockdep: Make CONFIG_LOCKDEP_CROSSRELEASE part
of CONFIG_PROVE_LOCKING"), which unfortunately does not revert cleanly.
However, the effect of a reversion can be obtained by removing the
selects of LOCKDEP_CROSSRELEASE and LOCKDEP_COMPLETE from
PROVE_LOCKING, which allows recent commits to complete a short
rcutorture test successfully.
So, Byungchul, any enlightenment? Please see lockdep splat below.
Thanx, Paul
------------------------------------------------------------------------
[ 35.310179] ======================================================
[ 35.310749] WARNING: possible circular locking dependency detected
[ 35.310749] 4.13.0-rc4+ #1 Not tainted
[ 35.310749] ------------------------------------------------------
[ 35.310749] torture_onoff/766 is trying to acquire lock:
[ 35.313943] ((complete)&st->done){+.+.}, at: [<ffffffffb905f5a6>] takedown_cpu+0x86/0xf0
[ 35.313943]
[ 35.313943] but task is already holding lock:
[ 35.313943] (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
[ 35.313943]
[ 35.313943] which lock already depends on the new lock.
[ 35.313943]
[ 35.313943]
[ 35.313943] the existing dependency chain (in reverse order) is:
[ 35.313943]
[ 35.313943] -> #1 (sparse_irq_lock){+.+.}:
[ 35.313943] __mutex_lock+0x65/0x960
[ 35.313943] mutex_lock_nested+0x16/0x20
[ 35.313943] irq_lock_sparse+0x12/0x20
[ 35.313943] irq_affinity_online_cpu+0x13/0xd0
[ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
[ 35.313943]
[ 35.313943] -> #0 ((complete)&st->done){+.+.}:
[ 35.313943] check_prev_add+0x401/0x800
[ 35.313943] __lock_acquire+0x1100/0x11a0
[ 35.313943] lock_acquire+0x9e/0x1e0
[ 35.313943] wait_for_completion+0x36/0x130
[ 35.313943] takedown_cpu+0x86/0xf0
[ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
[ 35.313943] cpuhp_down_callbacks+0x3d/0x80
[ 35.313943] _cpu_down+0xbb/0xf0
[ 35.313943] do_cpu_down+0x39/0x50
[ 35.313943] cpu_down+0xb/0x10
[ 35.313943] torture_offline+0x75/0x140
[ 35.313943] torture_onoff+0x102/0x1e0
[ 35.313943] kthread+0x142/0x180
[ 35.313943] ret_from_fork+0x27/0x40
[ 35.313943]
[ 35.313943] other info that might help us debug this:
[ 35.313943]
[ 35.313943] Possible unsafe locking scenario:
[ 35.313943]
[ 35.313943] CPU0 CPU1
[ 35.313943] ---- ----
[ 35.313943] lock(sparse_irq_lock);
[ 35.313943] lock((complete)&st->done);
[ 35.313943] lock(sparse_irq_lock);
[ 35.313943] lock((complete)&st->done);
[ 35.313943]
[ 35.313943] *** DEADLOCK ***
[ 35.313943]
[ 35.313943] 3 locks held by torture_onoff/766:
[ 35.313943] #0: (cpu_add_remove_lock){+.+.}, at: [<ffffffffb9060be2>] do_cpu_down+0x22/0x50
[ 35.313943] #1: (cpu_hotplug_lock.rw_sem){++++}, at: [<ffffffffb90acc41>] percpu_down_write+0x21/0xf0
[ 35.313943] #2: (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
[ 35.313943]
[ 35.313943] stack backtrace:
[ 35.313943] CPU: 7 PID: 766 Comm: torture_onoff Not tainted 4.13.0-rc4+ #1
[ 35.313943] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
[ 35.313943] Call Trace:
[ 35.313943] dump_stack+0x67/0x97
[ 35.313943] print_circular_bug+0x21d/0x330
[ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
[ 35.313943] check_prev_add+0x401/0x800
[ 35.313943] ? wake_up_q+0x70/0x70
[ 35.313943] __lock_acquire+0x1100/0x11a0
[ 35.313943] ? __lock_acquire+0x1100/0x11a0
[ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
[ 35.313943] lock_acquire+0x9e/0x1e0
[ 35.313943] ? takedown_cpu+0x86/0xf0
[ 35.313943] wait_for_completion+0x36/0x130
[ 35.313943] ? takedown_cpu+0x86/0xf0
[ 35.313943] ? stop_machine_cpuslocked+0xb9/0xd0
[ 35.313943] ? cpuhp_invoke_callback+0x8b0/0x8b0
[ 35.313943] ? cpuhp_complete_idle_dead+0x10/0x10
[ 35.313943] takedown_cpu+0x86/0xf0
[ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
[ 35.313943] cpuhp_down_callbacks+0x3d/0x80
[ 35.313943] _cpu_down+0xbb/0xf0
[ 35.313943] do_cpu_down+0x39/0x50
[ 35.313943] cpu_down+0xb/0x10
[ 35.313943] torture_offline+0x75/0x140
[ 35.313943] torture_onoff+0x102/0x1e0
[ 35.313943] kthread+0x142/0x180
[ 35.313943] ? torture_kthread_stopping+0x70/0x70
[ 35.313943] ? kthread_create_on_node+0x40/0x40
[ 35.313943] ret_from_fork+0x27/0x40
[toc] | [prev] | [next] | [standalone]
| From | Steven Rostedt <rostedt@goodmis.org> |
|---|---|
| Date | 2017-09-19 03:30 +0200 |
| Message-ID | <urfwl-5VI-5@gated-at.bofh.it> |
| In reply to | #1734547 |
On Mon, 18 Sep 2017 16:53:11 -0700
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> On Mon, Sep 18, 2017 at 09:55:27AM -0700, Paul E. McKenney wrote:
> > On Mon, Sep 18, 2017 at 12:29:31PM -0400, Steven Rostedt wrote:
> > > On Mon, 18 Sep 2017 09:24:12 -0700
> > > "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> > >
> > >
> > > > As soon as I work through the backlog of lockdep complaints that
> > > > appeared in the last merge window... :-(
> > > >
> > > > sparse_irq_lock, I am looking at you!!! ;-)
> > >
> > > I just hit one too, and decided to write a patch to show a chain of 3
> > > when applicable.
> > >
> > > For example:
> > >
> > > Chain exists of:
> > > cpu_hotplug_lock.rw_sem --> smpboot_threads_lock --> (complete)&self->parked
> > >
> > > Possible unsafe locking scenario by crosslock:
> > >
> > > CPU0 CPU1 CPU2
> > > ---- ---- ----
> > > lock(smpboot_threads_lock);
> > > lock((complete)&self->parked);
> > > lock(cpu_hotplug_lock.rw_sem);
> > > lock(smpboot_threads_lock);
> > > lock(cpu_hotplug_lock.rw_sem);
> > > unlock((complete)&self->parked);
> > >
> > > *** DEADLOCK ***
> > >
> > > :-)
> >
> > Nice!!!
> >
Note, the above lockdep splat does discover a bug.
> > My next step is reverting 12ac1d0f6c3e ("genirq: Make sparse_irq_lock
> > protect what it should protect") to see if that helps.
>
> No joy, but it is amazing how much nicer "git bisect" is when your
> failure happens deterministically within 35 seconds. ;-)
>
> The bisection converged to the range starting with 7a46ec0e2f48
> ("locking/refcounts, x86/asm: Implement fast refcount overflow
> protection") and ending with 0c2364791343 ("Merge branch 'x86/asm'
> into locking/core"). All of these failed with an unrelated build
> error, but there was a fix that could be merged. This flagged
> d0541b0fa64b ("locking/lockdep: Make CONFIG_LOCKDEP_CROSSRELEASE part
> of CONFIG_PROVE_LOCKING"), which unfortunately does not revert cleanly.
> However, the effect of a reversion can be obtained by removing the
> selects of LOCKDEP_CROSSRELEASE and LOCKDEP_COMPLETE from
> PROVE_LOCKING, which allows recent commits to complete a short
> rcutorture test successfully.
I don't think you want to remove those. It appears that lockdep now
covers completions, and it is uncovering a lot of bugs.
>
> So, Byungchul, any enlightenment? Please see lockdep splat below.
Did you discover the below by reverting lockdep patches? It doesn't
really make sense. It looks to me to be about completions but not
fully covering it.
-- Steve
> Thanx, Paul
>
> ------------------------------------------------------------------------
>
> [ 35.310179] ======================================================
> [ 35.310749] WARNING: possible circular locking dependency detected
> [ 35.310749] 4.13.0-rc4+ #1 Not tainted
> [ 35.310749] ------------------------------------------------------
> [ 35.310749] torture_onoff/766 is trying to acquire lock:
> [ 35.313943] ((complete)&st->done){+.+.}, at: [<ffffffffb905f5a6>] takedown_cpu+0x86/0xf0
> [ 35.313943]
> [ 35.313943] but task is already holding lock:
> [ 35.313943] (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
> [ 35.313943]
> [ 35.313943] which lock already depends on the new lock.
> [ 35.313943]
> [ 35.313943]
> [ 35.313943] the existing dependency chain (in reverse order) is:
> [ 35.313943]
> [ 35.313943] -> #1 (sparse_irq_lock){+.+.}:
> [ 35.313943] __mutex_lock+0x65/0x960
> [ 35.313943] mutex_lock_nested+0x16/0x20
> [ 35.313943] irq_lock_sparse+0x12/0x20
> [ 35.313943] irq_affinity_online_cpu+0x13/0xd0
> [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> [ 35.313943]
> [ 35.313943] -> #0 ((complete)&st->done){+.+.}:
> [ 35.313943] check_prev_add+0x401/0x800
> [ 35.313943] __lock_acquire+0x1100/0x11a0
> [ 35.313943] lock_acquire+0x9e/0x1e0
> [ 35.313943] wait_for_completion+0x36/0x130
> [ 35.313943] takedown_cpu+0x86/0xf0
> [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> [ 35.313943] cpuhp_down_callbacks+0x3d/0x80
> [ 35.313943] _cpu_down+0xbb/0xf0
> [ 35.313943] do_cpu_down+0x39/0x50
> [ 35.313943] cpu_down+0xb/0x10
> [ 35.313943] torture_offline+0x75/0x140
> [ 35.313943] torture_onoff+0x102/0x1e0
> [ 35.313943] kthread+0x142/0x180
> [ 35.313943] ret_from_fork+0x27/0x40
> [ 35.313943]
> [ 35.313943] other info that might help us debug this:
> [ 35.313943]
> [ 35.313943] Possible unsafe locking scenario:
> [ 35.313943]
> [ 35.313943] CPU0 CPU1
> [ 35.313943] ---- ----
> [ 35.313943] lock(sparse_irq_lock);
> [ 35.313943] lock((complete)&st->done);
> [ 35.313943] lock(sparse_irq_lock);
> [ 35.313943] lock((complete)&st->done);
> [ 35.313943]
> [ 35.313943] *** DEADLOCK ***
> [ 35.313943]
> [ 35.313943] 3 locks held by torture_onoff/766:
> [ 35.313943] #0: (cpu_add_remove_lock){+.+.}, at: [<ffffffffb9060be2>] do_cpu_down+0x22/0x50
> [ 35.313943] #1: (cpu_hotplug_lock.rw_sem){++++}, at: [<ffffffffb90acc41>] percpu_down_write+0x21/0xf0
> [ 35.313943] #2: (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
> [ 35.313943]
> [ 35.313943] stack backtrace:
> [ 35.313943] CPU: 7 PID: 766 Comm: torture_onoff Not tainted 4.13.0-rc4+ #1
> [ 35.313943] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
> [ 35.313943] Call Trace:
> [ 35.313943] dump_stack+0x67/0x97
> [ 35.313943] print_circular_bug+0x21d/0x330
> [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> [ 35.313943] check_prev_add+0x401/0x800
> [ 35.313943] ? wake_up_q+0x70/0x70
> [ 35.313943] __lock_acquire+0x1100/0x11a0
> [ 35.313943] ? __lock_acquire+0x1100/0x11a0
> [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> [ 35.313943] lock_acquire+0x9e/0x1e0
> [ 35.313943] ? takedown_cpu+0x86/0xf0
> [ 35.313943] wait_for_completion+0x36/0x130
> [ 35.313943] ? takedown_cpu+0x86/0xf0
> [ 35.313943] ? stop_machine_cpuslocked+0xb9/0xd0
> [ 35.313943] ? cpuhp_invoke_callback+0x8b0/0x8b0
> [ 35.313943] ? cpuhp_complete_idle_dead+0x10/0x10
> [ 35.313943] takedown_cpu+0x86/0xf0
> [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> [ 35.313943] cpuhp_down_callbacks+0x3d/0x80
> [ 35.313943] _cpu_down+0xbb/0xf0
> [ 35.313943] do_cpu_down+0x39/0x50
> [ 35.313943] cpu_down+0xb/0x10
> [ 35.313943] torture_offline+0x75/0x140
> [ 35.313943] torture_onoff+0x102/0x1e0
> [ 35.313943] kthread+0x142/0x180
> [ 35.313943] ? torture_kthread_stopping+0x70/0x70
> [ 35.313943] ? kthread_create_on_node+0x40/0x40
> [ 35.313943] ret_from_fork+0x27/0x40
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2017-09-19 04:30 +0200 |
| Message-ID | <urgsp-6BP-5@gated-at.bofh.it> |
| In reply to | #1734590 |
On Mon, Sep 18, 2017 at 09:23:01PM -0400, Steven Rostedt wrote:
> On Mon, 18 Sep 2017 16:53:11 -0700
> "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
>
> > On Mon, Sep 18, 2017 at 09:55:27AM -0700, Paul E. McKenney wrote:
> > > On Mon, Sep 18, 2017 at 12:29:31PM -0400, Steven Rostedt wrote:
> > > > On Mon, 18 Sep 2017 09:24:12 -0700
> > > > "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> > > >
> > > >
> > > > > As soon as I work through the backlog of lockdep complaints that
> > > > > appeared in the last merge window... :-(
> > > > >
> > > > > sparse_irq_lock, I am looking at you!!! ;-)
> > > >
> > > > I just hit one too, and decided to write a patch to show a chain of 3
> > > > when applicable.
> > > >
> > > > For example:
> > > >
> > > > Chain exists of:
> > > > cpu_hotplug_lock.rw_sem --> smpboot_threads_lock --> (complete)&self->parked
> > > >
> > > > Possible unsafe locking scenario by crosslock:
> > > >
> > > > CPU0 CPU1 CPU2
> > > > ---- ---- ----
> > > > lock(smpboot_threads_lock);
> > > > lock((complete)&self->parked);
> > > > lock(cpu_hotplug_lock.rw_sem);
> > > > lock(smpboot_threads_lock);
> > > > lock(cpu_hotplug_lock.rw_sem);
> > > > unlock((complete)&self->parked);
> > > >
> > > > *** DEADLOCK ***
> > > >
> > > > :-)
> > >
> > > Nice!!!
>
> Note, the above lockdep splat does discover a bug.
Fair enough, but I unfortunately have several other much more bizarre
bugs stacked up and so I am not volunteering to fix this one.
> > > My next step is reverting 12ac1d0f6c3e ("genirq: Make sparse_irq_lock
> > > protect what it should protect") to see if that helps.
> >
> > No joy, but it is amazing how much nicer "git bisect" is when your
> > failure happens deterministically within 35 seconds. ;-)
> >
> > The bisection converged to the range starting with 7a46ec0e2f48
> > ("locking/refcounts, x86/asm: Implement fast refcount overflow
> > protection") and ending with 0c2364791343 ("Merge branch 'x86/asm'
> > into locking/core"). All of these failed with an unrelated build
> > error, but there was a fix that could be merged. This flagged
> > d0541b0fa64b ("locking/lockdep: Make CONFIG_LOCKDEP_CROSSRELEASE part
> > of CONFIG_PROVE_LOCKING"), which unfortunately does not revert cleanly.
> > However, the effect of a reversion can be obtained by removing the
> > selects of LOCKDEP_CROSSRELEASE and LOCKDEP_COMPLETE from
> > PROVE_LOCKING, which allows recent commits to complete a short
> > rcutorture test successfully.
>
> I don't think you want to remove those. It appears that lockdep now
> covers completions, and it is uncovering a lot of bugs.
Actually, I do, at least in the short term. This splat is getting in the
way of my diagnostics for the other bugs. Please note that I am -not-
arguing that mainline should change, at least not yet.
> > So, Byungchul, any enlightenment? Please see lockdep splat below.
>
> Did you discover the below by reverting lockdep patches? It doesn't
> really make sense. It looks to me to be about completions but not
> fully covering it.
No, the splat below is what I get from stock v4.14-rc1 on these
rcutorture scenarios: SRCU-P, TASKS01, TREE03, and TREE05. If you
would like to try it yourself, TASKS01 requires only two CPUs and
the others require eight.
When I suppress LOCKDEP_CROSSRELEASE and LOCKDEP_COMPLETE, I don't
see anything that looks like that deadlock, but it is of course quite
possible that the deadlock is very low probability -- and I did short
30-minute runs.
Thanx, Paul
> -- Steve
>
> > Thanx, Paul
> >
> > ------------------------------------------------------------------------
> >
> > [ 35.310179] ======================================================
> > [ 35.310749] WARNING: possible circular locking dependency detected
> > [ 35.310749] 4.13.0-rc4+ #1 Not tainted
> > [ 35.310749] ------------------------------------------------------
> > [ 35.310749] torture_onoff/766 is trying to acquire lock:
> > [ 35.313943] ((complete)&st->done){+.+.}, at: [<ffffffffb905f5a6>] takedown_cpu+0x86/0xf0
> > [ 35.313943]
> > [ 35.313943] but task is already holding lock:
> > [ 35.313943] (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
> > [ 35.313943]
> > [ 35.313943] which lock already depends on the new lock.
> > [ 35.313943]
> > [ 35.313943]
> > [ 35.313943] the existing dependency chain (in reverse order) is:
> > [ 35.313943]
> > [ 35.313943] -> #1 (sparse_irq_lock){+.+.}:
> > [ 35.313943] __mutex_lock+0x65/0x960
> > [ 35.313943] mutex_lock_nested+0x16/0x20
> > [ 35.313943] irq_lock_sparse+0x12/0x20
> > [ 35.313943] irq_affinity_online_cpu+0x13/0xd0
> > [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> > [ 35.313943]
> > [ 35.313943] -> #0 ((complete)&st->done){+.+.}:
> > [ 35.313943] check_prev_add+0x401/0x800
> > [ 35.313943] __lock_acquire+0x1100/0x11a0
> > [ 35.313943] lock_acquire+0x9e/0x1e0
> > [ 35.313943] wait_for_completion+0x36/0x130
> > [ 35.313943] takedown_cpu+0x86/0xf0
> > [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> > [ 35.313943] cpuhp_down_callbacks+0x3d/0x80
> > [ 35.313943] _cpu_down+0xbb/0xf0
> > [ 35.313943] do_cpu_down+0x39/0x50
> > [ 35.313943] cpu_down+0xb/0x10
> > [ 35.313943] torture_offline+0x75/0x140
> > [ 35.313943] torture_onoff+0x102/0x1e0
> > [ 35.313943] kthread+0x142/0x180
> > [ 35.313943] ret_from_fork+0x27/0x40
> > [ 35.313943]
> > [ 35.313943] other info that might help us debug this:
> > [ 35.313943]
> > [ 35.313943] Possible unsafe locking scenario:
> > [ 35.313943]
> > [ 35.313943] CPU0 CPU1
> > [ 35.313943] ---- ----
> > [ 35.313943] lock(sparse_irq_lock);
> > [ 35.313943] lock((complete)&st->done);
> > [ 35.313943] lock(sparse_irq_lock);
> > [ 35.313943] lock((complete)&st->done);
> > [ 35.313943]
> > [ 35.313943] *** DEADLOCK ***
> > [ 35.313943]
> > [ 35.313943] 3 locks held by torture_onoff/766:
> > [ 35.313943] #0: (cpu_add_remove_lock){+.+.}, at: [<ffffffffb9060be2>] do_cpu_down+0x22/0x50
> > [ 35.313943] #1: (cpu_hotplug_lock.rw_sem){++++}, at: [<ffffffffb90acc41>] percpu_down_write+0x21/0xf0
> > [ 35.313943] #2: (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
> > [ 35.313943]
> > [ 35.313943] stack backtrace:
> > [ 35.313943] CPU: 7 PID: 766 Comm: torture_onoff Not tainted 4.13.0-rc4+ #1
> > [ 35.313943] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
> > [ 35.313943] Call Trace:
> > [ 35.313943] dump_stack+0x67/0x97
> > [ 35.313943] print_circular_bug+0x21d/0x330
> > [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> > [ 35.313943] check_prev_add+0x401/0x800
> > [ 35.313943] ? wake_up_q+0x70/0x70
> > [ 35.313943] __lock_acquire+0x1100/0x11a0
> > [ 35.313943] ? __lock_acquire+0x1100/0x11a0
> > [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> > [ 35.313943] lock_acquire+0x9e/0x1e0
> > [ 35.313943] ? takedown_cpu+0x86/0xf0
> > [ 35.313943] wait_for_completion+0x36/0x130
> > [ 35.313943] ? takedown_cpu+0x86/0xf0
> > [ 35.313943] ? stop_machine_cpuslocked+0xb9/0xd0
> > [ 35.313943] ? cpuhp_invoke_callback+0x8b0/0x8b0
> > [ 35.313943] ? cpuhp_complete_idle_dead+0x10/0x10
> > [ 35.313943] takedown_cpu+0x86/0xf0
> > [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> > [ 35.313943] cpuhp_down_callbacks+0x3d/0x80
> > [ 35.313943] _cpu_down+0xbb/0xf0
> > [ 35.313943] do_cpu_down+0x39/0x50
> > [ 35.313943] cpu_down+0xb/0x10
> > [ 35.313943] torture_offline+0x75/0x140
> > [ 35.313943] torture_onoff+0x102/0x1e0
> > [ 35.313943] kthread+0x142/0x180
> > [ 35.313943] ? torture_kthread_stopping+0x70/0x70
> > [ 35.313943] ? kthread_create_on_node+0x40/0x40
> > [ 35.313943] ret_from_fork+0x27/0x40
>
[toc] | [prev] | [next] | [standalone]
| From | Byungchul Park <byungchul.park@lge.com> |
|---|---|
| Date | 2017-09-19 04:00 +0200 |
| Message-ID | <urfZn-66X-1@gated-at.bofh.it> |
| In reply to | #1734547 |
On Mon, Sep 18, 2017 at 04:53:11PM -0700, Paul E. McKenney wrote:
> So, Byungchul, any enlightenment? Please see lockdep splat below.
>
> Thanx, Paul
>
> ------------------------------------------------------------------------
>
> [ 35.310179] ======================================================
> [ 35.310749] WARNING: possible circular locking dependency detected
> [ 35.310749] 4.13.0-rc4+ #1 Not tainted
> [ 35.310749] ------------------------------------------------------
> [ 35.310749] torture_onoff/766 is trying to acquire lock:
> [ 35.313943] ((complete)&st->done){+.+.}, at: [<ffffffffb905f5a6>] takedown_cpu+0x86/0xf0
> [ 35.313943]
> [ 35.313943] but task is already holding lock:
> [ 35.313943] (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
> [ 35.313943]
> [ 35.313943] which lock already depends on the new lock.
> [ 35.313943]
> [ 35.313943]
> [ 35.313943] the existing dependency chain (in reverse order) is:
> [ 35.313943]
> [ 35.313943] -> #1 (sparse_irq_lock){+.+.}:
> [ 35.313943] __mutex_lock+0x65/0x960
> [ 35.313943] mutex_lock_nested+0x16/0x20
> [ 35.313943] irq_lock_sparse+0x12/0x20
> [ 35.313943] irq_affinity_online_cpu+0x13/0xd0
> [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> [ 35.313943]
> [ 35.313943] -> #0 ((complete)&st->done){+.+.}:
> [ 35.313943] check_prev_add+0x401/0x800
> [ 35.313943] __lock_acquire+0x1100/0x11a0
> [ 35.313943] lock_acquire+0x9e/0x1e0
> [ 35.313943] wait_for_completion+0x36/0x130
> [ 35.313943] takedown_cpu+0x86/0xf0
> [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> [ 35.313943] cpuhp_down_callbacks+0x3d/0x80
> [ 35.313943] _cpu_down+0xbb/0xf0
> [ 35.313943] do_cpu_down+0x39/0x50
> [ 35.313943] cpu_down+0xb/0x10
> [ 35.313943] torture_offline+0x75/0x140
> [ 35.313943] torture_onoff+0x102/0x1e0
> [ 35.313943] kthread+0x142/0x180
> [ 35.313943] ret_from_fork+0x27/0x40
> [ 35.313943]
> [ 35.313943] other info that might help us debug this:
> [ 35.313943]
> [ 35.313943] Possible unsafe locking scenario:
> [ 35.313943]
> [ 35.313943] CPU0 CPU1
> [ 35.313943] ---- ----
> [ 35.313943] lock(sparse_irq_lock);
> [ 35.313943] lock((complete)&st->done);
> [ 35.313943] lock(sparse_irq_lock);
> [ 35.313943] lock((complete)&st->done);
> [ 35.313943]
> [ 35.313943] *** DEADLOCK ***
Hello Paul and Steven,
This is saying:
Thread A
--------
takedown_cpu()
irq_lock_sparse()
wait_for_completion(&st->done) // Wait for completion of B
irq_unlock_sparse()
Thread B
--------
cpuhp_invoke_callback()
irq_lock_sparse() // Wait for A to irq_unlock_sparse()
(on the way going to complete(&st->done))
So, lockdep consider this as a deadlock.
Is it possible to happen?
Thanks,
Byungchul
> [ 35.313943]
> [ 35.313943] 3 locks held by torture_onoff/766:
> [ 35.313943] #0: (cpu_add_remove_lock){+.+.}, at: [<ffffffffb9060be2>] do_cpu_down+0x22/0x50
> [ 35.313943] #1: (cpu_hotplug_lock.rw_sem){++++}, at: [<ffffffffb90acc41>] percpu_down_write+0x21/0xf0
> [ 35.313943] #2: (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
> [ 35.313943]
> [ 35.313943] stack backtrace:
> [ 35.313943] CPU: 7 PID: 766 Comm: torture_onoff Not tainted 4.13.0-rc4+ #1
> [ 35.313943] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
> [ 35.313943] Call Trace:
> [ 35.313943] dump_stack+0x67/0x97
> [ 35.313943] print_circular_bug+0x21d/0x330
> [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> [ 35.313943] check_prev_add+0x401/0x800
> [ 35.313943] ? wake_up_q+0x70/0x70
> [ 35.313943] __lock_acquire+0x1100/0x11a0
> [ 35.313943] ? __lock_acquire+0x1100/0x11a0
> [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> [ 35.313943] lock_acquire+0x9e/0x1e0
> [ 35.313943] ? takedown_cpu+0x86/0xf0
> [ 35.313943] wait_for_completion+0x36/0x130
> [ 35.313943] ? takedown_cpu+0x86/0xf0
> [ 35.313943] ? stop_machine_cpuslocked+0xb9/0xd0
> [ 35.313943] ? cpuhp_invoke_callback+0x8b0/0x8b0
> [ 35.313943] ? cpuhp_complete_idle_dead+0x10/0x10
> [ 35.313943] takedown_cpu+0x86/0xf0
> [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> [ 35.313943] cpuhp_down_callbacks+0x3d/0x80
> [ 35.313943] _cpu_down+0xbb/0xf0
> [ 35.313943] do_cpu_down+0x39/0x50
> [ 35.313943] cpu_down+0xb/0x10
> [ 35.313943] torture_offline+0x75/0x140
> [ 35.313943] torture_onoff+0x102/0x1e0
> [ 35.313943] kthread+0x142/0x180
> [ 35.313943] ? torture_kthread_stopping+0x70/0x70
> [ 35.313943] ? kthread_create_on_node+0x40/0x40
> [ 35.313943] ret_from_fork+0x27/0x40
[toc] | [prev] | [next] | [standalone]
| From | Byungchul Park <byungchul.park@lge.com> |
|---|---|
| Date | 2017-09-19 04:10 +0200 |
| Message-ID | <urg94-6pO-3@gated-at.bofh.it> |
| In reply to | #1734592 |
On Tue, Sep 19, 2017 at 10:50:27AM +0900, Byungchul Park wrote:
> On Mon, Sep 18, 2017 at 04:53:11PM -0700, Paul E. McKenney wrote:
> > So, Byungchul, any enlightenment? Please see lockdep splat below.
> >
> > Thanx, Paul
> >
> > ------------------------------------------------------------------------
> >
> > [ 35.310179] ======================================================
> > [ 35.310749] WARNING: possible circular locking dependency detected
> > [ 35.310749] 4.13.0-rc4+ #1 Not tainted
> > [ 35.310749] ------------------------------------------------------
> > [ 35.310749] torture_onoff/766 is trying to acquire lock:
> > [ 35.313943] ((complete)&st->done){+.+.}, at: [<ffffffffb905f5a6>] takedown_cpu+0x86/0xf0
> > [ 35.313943]
> > [ 35.313943] but task is already holding lock:
> > [ 35.313943] (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
> > [ 35.313943]
> > [ 35.313943] which lock already depends on the new lock.
> > [ 35.313943]
> > [ 35.313943]
> > [ 35.313943] the existing dependency chain (in reverse order) is:
> > [ 35.313943]
> > [ 35.313943] -> #1 (sparse_irq_lock){+.+.}:
> > [ 35.313943] __mutex_lock+0x65/0x960
> > [ 35.313943] mutex_lock_nested+0x16/0x20
> > [ 35.313943] irq_lock_sparse+0x12/0x20
> > [ 35.313943] irq_affinity_online_cpu+0x13/0xd0
> > [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> > [ 35.313943]
> > [ 35.313943] -> #0 ((complete)&st->done){+.+.}:
> > [ 35.313943] check_prev_add+0x401/0x800
> > [ 35.313943] __lock_acquire+0x1100/0x11a0
> > [ 35.313943] lock_acquire+0x9e/0x1e0
> > [ 35.313943] wait_for_completion+0x36/0x130
> > [ 35.313943] takedown_cpu+0x86/0xf0
> > [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> > [ 35.313943] cpuhp_down_callbacks+0x3d/0x80
> > [ 35.313943] _cpu_down+0xbb/0xf0
> > [ 35.313943] do_cpu_down+0x39/0x50
> > [ 35.313943] cpu_down+0xb/0x10
> > [ 35.313943] torture_offline+0x75/0x140
> > [ 35.313943] torture_onoff+0x102/0x1e0
> > [ 35.313943] kthread+0x142/0x180
> > [ 35.313943] ret_from_fork+0x27/0x40
> > [ 35.313943]
> > [ 35.313943] other info that might help us debug this:
> > [ 35.313943]
> > [ 35.313943] Possible unsafe locking scenario:
> > [ 35.313943]
> > [ 35.313943] CPU0 CPU1
> > [ 35.313943] ---- ----
> > [ 35.313943] lock(sparse_irq_lock);
> > [ 35.313943] lock((complete)&st->done);
> > [ 35.313943] lock(sparse_irq_lock);
> > [ 35.313943] lock((complete)&st->done);
> > [ 35.313943]
> > [ 35.313943] *** DEADLOCK ***
>
> Hello Paul and Steven,
>
> This is saying:
>
> Thread A
> --------
> takedown_cpu()
> irq_lock_sparse()
> wait_for_completion(&st->done) // Wait for completion of B
> irq_unlock_sparse()
>
> Thread B
> --------
> cpuhp_invoke_callback()
> irq_lock_sparse() // Wait for A to irq_unlock_sparse()
> (on the way going to complete(&st->done))
>
> So, lockdep consider this as a deadlock.
> Is it possible to happen?
In addition, if it's impossible, then we should fix lock class
assignments so that the locks actually have different classes.
> Thanks,
> Byungchul
>
> > [ 35.313943]
> > [ 35.313943] 3 locks held by torture_onoff/766:
> > [ 35.313943] #0: (cpu_add_remove_lock){+.+.}, at: [<ffffffffb9060be2>] do_cpu_down+0x22/0x50
> > [ 35.313943] #1: (cpu_hotplug_lock.rw_sem){++++}, at: [<ffffffffb90acc41>] percpu_down_write+0x21/0xf0
> > [ 35.313943] #2: (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
> > [ 35.313943]
> > [ 35.313943] stack backtrace:
> > [ 35.313943] CPU: 7 PID: 766 Comm: torture_onoff Not tainted 4.13.0-rc4+ #1
> > [ 35.313943] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
> > [ 35.313943] Call Trace:
> > [ 35.313943] dump_stack+0x67/0x97
> > [ 35.313943] print_circular_bug+0x21d/0x330
> > [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> > [ 35.313943] check_prev_add+0x401/0x800
> > [ 35.313943] ? wake_up_q+0x70/0x70
> > [ 35.313943] __lock_acquire+0x1100/0x11a0
> > [ 35.313943] ? __lock_acquire+0x1100/0x11a0
> > [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> > [ 35.313943] lock_acquire+0x9e/0x1e0
> > [ 35.313943] ? takedown_cpu+0x86/0xf0
> > [ 35.313943] wait_for_completion+0x36/0x130
> > [ 35.313943] ? takedown_cpu+0x86/0xf0
> > [ 35.313943] ? stop_machine_cpuslocked+0xb9/0xd0
> > [ 35.313943] ? cpuhp_invoke_callback+0x8b0/0x8b0
> > [ 35.313943] ? cpuhp_complete_idle_dead+0x10/0x10
> > [ 35.313943] takedown_cpu+0x86/0xf0
> > [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> > [ 35.313943] cpuhp_down_callbacks+0x3d/0x80
> > [ 35.313943] _cpu_down+0xbb/0xf0
> > [ 35.313943] do_cpu_down+0x39/0x50
> > [ 35.313943] cpu_down+0xb/0x10
> > [ 35.313943] torture_offline+0x75/0x140
> > [ 35.313943] torture_onoff+0x102/0x1e0
> > [ 35.313943] kthread+0x142/0x180
> > [ 35.313943] ? torture_kthread_stopping+0x70/0x70
> > [ 35.313943] ? kthread_create_on_node+0x40/0x40
> > [ 35.313943] ret_from_fork+0x27/0x40
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2017-09-19 04:40 +0200 |
| Message-ID | <urgC5-6EL-9@gated-at.bofh.it> |
| In reply to | #1734595 |
On Tue, Sep 19, 2017 at 11:06:10AM +0900, Byungchul Park wrote:
> On Tue, Sep 19, 2017 at 10:50:27AM +0900, Byungchul Park wrote:
> > On Mon, Sep 18, 2017 at 04:53:11PM -0700, Paul E. McKenney wrote:
> > > So, Byungchul, any enlightenment? Please see lockdep splat below.
> > >
> > > Thanx, Paul
> > >
> > > ------------------------------------------------------------------------
> > >
> > > [ 35.310179] ======================================================
> > > [ 35.310749] WARNING: possible circular locking dependency detected
> > > [ 35.310749] 4.13.0-rc4+ #1 Not tainted
> > > [ 35.310749] ------------------------------------------------------
> > > [ 35.310749] torture_onoff/766 is trying to acquire lock:
> > > [ 35.313943] ((complete)&st->done){+.+.}, at: [<ffffffffb905f5a6>] takedown_cpu+0x86/0xf0
> > > [ 35.313943]
> > > [ 35.313943] but task is already holding lock:
> > > [ 35.313943] (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
> > > [ 35.313943]
> > > [ 35.313943] which lock already depends on the new lock.
> > > [ 35.313943]
> > > [ 35.313943]
> > > [ 35.313943] the existing dependency chain (in reverse order) is:
> > > [ 35.313943]
> > > [ 35.313943] -> #1 (sparse_irq_lock){+.+.}:
> > > [ 35.313943] __mutex_lock+0x65/0x960
> > > [ 35.313943] mutex_lock_nested+0x16/0x20
> > > [ 35.313943] irq_lock_sparse+0x12/0x20
> > > [ 35.313943] irq_affinity_online_cpu+0x13/0xd0
> > > [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> > > [ 35.313943]
> > > [ 35.313943] -> #0 ((complete)&st->done){+.+.}:
> > > [ 35.313943] check_prev_add+0x401/0x800
> > > [ 35.313943] __lock_acquire+0x1100/0x11a0
> > > [ 35.313943] lock_acquire+0x9e/0x1e0
> > > [ 35.313943] wait_for_completion+0x36/0x130
> > > [ 35.313943] takedown_cpu+0x86/0xf0
> > > [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> > > [ 35.313943] cpuhp_down_callbacks+0x3d/0x80
> > > [ 35.313943] _cpu_down+0xbb/0xf0
> > > [ 35.313943] do_cpu_down+0x39/0x50
> > > [ 35.313943] cpu_down+0xb/0x10
> > > [ 35.313943] torture_offline+0x75/0x140
> > > [ 35.313943] torture_onoff+0x102/0x1e0
> > > [ 35.313943] kthread+0x142/0x180
> > > [ 35.313943] ret_from_fork+0x27/0x40
> > > [ 35.313943]
> > > [ 35.313943] other info that might help us debug this:
> > > [ 35.313943]
> > > [ 35.313943] Possible unsafe locking scenario:
> > > [ 35.313943]
> > > [ 35.313943] CPU0 CPU1
> > > [ 35.313943] ---- ----
> > > [ 35.313943] lock(sparse_irq_lock);
> > > [ 35.313943] lock((complete)&st->done);
> > > [ 35.313943] lock(sparse_irq_lock);
> > > [ 35.313943] lock((complete)&st->done);
> > > [ 35.313943]
> > > [ 35.313943] *** DEADLOCK ***
> >
> > Hello Paul and Steven,
> >
> > This is saying:
> >
> > Thread A
> > --------
> > takedown_cpu()
> > irq_lock_sparse()
> > wait_for_completion(&st->done) // Wait for completion of B
> > irq_unlock_sparse()
> >
> > Thread B
> > --------
> > cpuhp_invoke_callback()
> > irq_lock_sparse() // Wait for A to irq_unlock_sparse()
> > (on the way going to complete(&st->done))
> >
> > So, lockdep consider this as a deadlock.
> > Is it possible to happen?
>
> In addition, if it's impossible, then we should fix lock class
> assignments so that the locks actually have different classes.
Interesting, and thank you for the analysis!
The strange thing is that the way you describe it, this would be a
deterministic deadlock. Yet CPU hotplug operations complete just fine
in my tests. What am I missing here?
Thanx, Paul
> > Thanks,
> > Byungchul
> >
> > > [ 35.313943]
> > > [ 35.313943] 3 locks held by torture_onoff/766:
> > > [ 35.313943] #0: (cpu_add_remove_lock){+.+.}, at: [<ffffffffb9060be2>] do_cpu_down+0x22/0x50
> > > [ 35.313943] #1: (cpu_hotplug_lock.rw_sem){++++}, at: [<ffffffffb90acc41>] percpu_down_write+0x21/0xf0
> > > [ 35.313943] #2: (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
> > > [ 35.313943]
> > > [ 35.313943] stack backtrace:
> > > [ 35.313943] CPU: 7 PID: 766 Comm: torture_onoff Not tainted 4.13.0-rc4+ #1
> > > [ 35.313943] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
> > > [ 35.313943] Call Trace:
> > > [ 35.313943] dump_stack+0x67/0x97
> > > [ 35.313943] print_circular_bug+0x21d/0x330
> > > [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> > > [ 35.313943] check_prev_add+0x401/0x800
> > > [ 35.313943] ? wake_up_q+0x70/0x70
> > > [ 35.313943] __lock_acquire+0x1100/0x11a0
> > > [ 35.313943] ? __lock_acquire+0x1100/0x11a0
> > > [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> > > [ 35.313943] lock_acquire+0x9e/0x1e0
> > > [ 35.313943] ? takedown_cpu+0x86/0xf0
> > > [ 35.313943] wait_for_completion+0x36/0x130
> > > [ 35.313943] ? takedown_cpu+0x86/0xf0
> > > [ 35.313943] ? stop_machine_cpuslocked+0xb9/0xd0
> > > [ 35.313943] ? cpuhp_invoke_callback+0x8b0/0x8b0
> > > [ 35.313943] ? cpuhp_complete_idle_dead+0x10/0x10
> > > [ 35.313943] takedown_cpu+0x86/0xf0
> > > [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> > > [ 35.313943] cpuhp_down_callbacks+0x3d/0x80
> > > [ 35.313943] _cpu_down+0xbb/0xf0
> > > [ 35.313943] do_cpu_down+0x39/0x50
> > > [ 35.313943] cpu_down+0xb/0x10
> > > [ 35.313943] torture_offline+0x75/0x140
> > > [ 35.313943] torture_onoff+0x102/0x1e0
> > > [ 35.313943] kthread+0x142/0x180
> > > [ 35.313943] ? torture_kthread_stopping+0x70/0x70
> > > [ 35.313943] ? kthread_create_on_node+0x40/0x40
> > > [ 35.313943] ret_from_fork+0x27/0x40
>
[toc] | [prev] | [next] | [standalone]
| From | Byungchul Park <byungchul.park@lge.com> |
|---|---|
| Date | 2017-09-19 04:50 +0200 |
| Message-ID | <urgLM-6I2-21@gated-at.bofh.it> |
| In reply to | #1734607 |
On Mon, Sep 18, 2017 at 07:33:29PM -0700, Paul E. McKenney wrote:
> > > Hello Paul and Steven,
> > >
> > > This is saying:
> > >
> > > Thread A
> > > --------
> > > takedown_cpu()
> > > irq_lock_sparse()
> > > wait_for_completion(&st->done) // Wait for completion of B
> > > irq_unlock_sparse()
> > >
> > > Thread B
> > > --------
> > > cpuhp_invoke_callback()
> > > irq_lock_sparse() // Wait for A to irq_unlock_sparse()
> > > (on the way going to complete(&st->done))
> > >
> > > So, lockdep consider this as a deadlock.
> > > Is it possible to happen?
> >
> > In addition, if it's impossible, then we should fix lock class
> > assignments so that the locks actually have different classes.
>
> Interesting, and thank you for the analysis!
>
> The strange thing is that the way you describe it, this would be a
> deterministic deadlock. Yet CPU hotplug operations complete just fine
> in my tests. What am I missing here?
Hi, :)
Lockdep basically reports either (1) an actual deadlock happened at the
time or (2) a deadlock possibility, even w/o LOCKDEP_CROSSRELEASE.
Both are useful. But LOCKDEP_CROSSRELEASE can only do the latter. IOW,
the deadlock would actually happen _only_ when the two threads(A and B)
run simultaniously.
In your case, those two threads might run at different timings. So it's
not an actual deadlock, but still has a possibility for the problem to
happen later.
> Thanx, Paul
>
> > > Thanks,
> > > Byungchul
> > >
> > > > [ 35.313943]
> > > > [ 35.313943] 3 locks held by torture_onoff/766:
> > > > [ 35.313943] #0: (cpu_add_remove_lock){+.+.}, at: [<ffffffffb9060be2>] do_cpu_down+0x22/0x50
> > > > [ 35.313943] #1: (cpu_hotplug_lock.rw_sem){++++}, at: [<ffffffffb90acc41>] percpu_down_write+0x21/0xf0
> > > > [ 35.313943] #2: (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
> > > > [ 35.313943]
> > > > [ 35.313943] stack backtrace:
> > > > [ 35.313943] CPU: 7 PID: 766 Comm: torture_onoff Not tainted 4.13.0-rc4+ #1
> > > > [ 35.313943] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
> > > > [ 35.313943] Call Trace:
> > > > [ 35.313943] dump_stack+0x67/0x97
> > > > [ 35.313943] print_circular_bug+0x21d/0x330
> > > > [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> > > > [ 35.313943] check_prev_add+0x401/0x800
> > > > [ 35.313943] ? wake_up_q+0x70/0x70
> > > > [ 35.313943] __lock_acquire+0x1100/0x11a0
> > > > [ 35.313943] ? __lock_acquire+0x1100/0x11a0
> > > > [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> > > > [ 35.313943] lock_acquire+0x9e/0x1e0
> > > > [ 35.313943] ? takedown_cpu+0x86/0xf0
> > > > [ 35.313943] wait_for_completion+0x36/0x130
> > > > [ 35.313943] ? takedown_cpu+0x86/0xf0
> > > > [ 35.313943] ? stop_machine_cpuslocked+0xb9/0xd0
> > > > [ 35.313943] ? cpuhp_invoke_callback+0x8b0/0x8b0
> > > > [ 35.313943] ? cpuhp_complete_idle_dead+0x10/0x10
> > > > [ 35.313943] takedown_cpu+0x86/0xf0
> > > > [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> > > > [ 35.313943] cpuhp_down_callbacks+0x3d/0x80
> > > > [ 35.313943] _cpu_down+0xbb/0xf0
> > > > [ 35.313943] do_cpu_down+0x39/0x50
> > > > [ 35.313943] cpu_down+0xb/0x10
> > > > [ 35.313943] torture_offline+0x75/0x140
> > > > [ 35.313943] torture_onoff+0x102/0x1e0
> > > > [ 35.313943] kthread+0x142/0x180
> > > > [ 35.313943] ? torture_kthread_stopping+0x70/0x70
> > > > [ 35.313943] ? kthread_create_on_node+0x40/0x40
> > > > [ 35.313943] ret_from_fork+0x27/0x40
> >
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2017-09-19 06:10 +0200 |
| Message-ID | <uri1d-7Do-25@gated-at.bofh.it> |
| In reply to | #1734618 |
On Tue, Sep 19, 2017 at 11:48:22AM +0900, Byungchul Park wrote:
> On Mon, Sep 18, 2017 at 07:33:29PM -0700, Paul E. McKenney wrote:
> > > > Hello Paul and Steven,
> > > >
> > > > This is saying:
> > > >
> > > > Thread A
> > > > --------
> > > > takedown_cpu()
> > > > irq_lock_sparse()
> > > > wait_for_completion(&st->done) // Wait for completion of B
> > > > irq_unlock_sparse()
> > > >
> > > > Thread B
> > > > --------
> > > > cpuhp_invoke_callback()
> > > > irq_lock_sparse() // Wait for A to irq_unlock_sparse()
> > > > (on the way going to complete(&st->done))
> > > >
> > > > So, lockdep consider this as a deadlock.
> > > > Is it possible to happen?
> > >
> > > In addition, if it's impossible, then we should fix lock class
> > > assignments so that the locks actually have different classes.
> >
> > Interesting, and thank you for the analysis!
> >
> > The strange thing is that the way you describe it, this would be a
> > deterministic deadlock. Yet CPU hotplug operations complete just fine
> > in my tests. What am I missing here?
>
> Hi, :)
>
> Lockdep basically reports either (1) an actual deadlock happened at the
> time or (2) a deadlock possibility, even w/o LOCKDEP_CROSSRELEASE.
>
> Both are useful. But LOCKDEP_CROSSRELEASE can only do the latter. IOW,
> the deadlock would actually happen _only_ when the two threads(A and B)
> run simultaniously.
>
> In your case, those two threads might run at different timings. So it's
> not an actual deadlock, but still has a possibility for the problem to
> happen later.
Fair enough, if the wakeup always happened first, deadlock might well
be avoided. If the sleep happened first, I suspect deadlock would
be deterministic in this case.
Thanx, Paul
> > > > Thanks,
> > > > Byungchul
> > > >
> > > > > [ 35.313943]
> > > > > [ 35.313943] 3 locks held by torture_onoff/766:
> > > > > [ 35.313943] #0: (cpu_add_remove_lock){+.+.}, at: [<ffffffffb9060be2>] do_cpu_down+0x22/0x50
> > > > > [ 35.313943] #1: (cpu_hotplug_lock.rw_sem){++++}, at: [<ffffffffb90acc41>] percpu_down_write+0x21/0xf0
> > > > > [ 35.313943] #2: (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
> > > > > [ 35.313943]
> > > > > [ 35.313943] stack backtrace:
> > > > > [ 35.313943] CPU: 7 PID: 766 Comm: torture_onoff Not tainted 4.13.0-rc4+ #1
> > > > > [ 35.313943] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
> > > > > [ 35.313943] Call Trace:
> > > > > [ 35.313943] dump_stack+0x67/0x97
> > > > > [ 35.313943] print_circular_bug+0x21d/0x330
> > > > > [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> > > > > [ 35.313943] check_prev_add+0x401/0x800
> > > > > [ 35.313943] ? wake_up_q+0x70/0x70
> > > > > [ 35.313943] __lock_acquire+0x1100/0x11a0
> > > > > [ 35.313943] ? __lock_acquire+0x1100/0x11a0
> > > > > [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> > > > > [ 35.313943] lock_acquire+0x9e/0x1e0
> > > > > [ 35.313943] ? takedown_cpu+0x86/0xf0
> > > > > [ 35.313943] wait_for_completion+0x36/0x130
> > > > > [ 35.313943] ? takedown_cpu+0x86/0xf0
> > > > > [ 35.313943] ? stop_machine_cpuslocked+0xb9/0xd0
> > > > > [ 35.313943] ? cpuhp_invoke_callback+0x8b0/0x8b0
> > > > > [ 35.313943] ? cpuhp_complete_idle_dead+0x10/0x10
> > > > > [ 35.313943] takedown_cpu+0x86/0xf0
> > > > > [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> > > > > [ 35.313943] cpuhp_down_callbacks+0x3d/0x80
> > > > > [ 35.313943] _cpu_down+0xbb/0xf0
> > > > > [ 35.313943] do_cpu_down+0x39/0x50
> > > > > [ 35.313943] cpu_down+0xb/0x10
> > > > > [ 35.313943] torture_offline+0x75/0x140
> > > > > [ 35.313943] torture_onoff+0x102/0x1e0
> > > > > [ 35.313943] kthread+0x142/0x180
> > > > > [ 35.313943] ? torture_kthread_stopping+0x70/0x70
> > > > > [ 35.313943] ? kthread_create_on_node+0x40/0x40
> > > > > [ 35.313943] ret_from_fork+0x27/0x40
> > >
>
[toc] | [prev] | [next] | [standalone]
| From | Boqun Feng <boqun.feng@gmail.com> |
|---|---|
| Date | 2017-09-19 07:40 +0200 |
| Message-ID | <urjqi-8ru-11@gated-at.bofh.it> |
| In reply to | #1734646 |
[Multipart message — attachments visible in raw view] — view raw
On Mon, Sep 18, 2017 at 09:04:56PM -0700, Paul E. McKenney wrote:
> On Tue, Sep 19, 2017 at 11:48:22AM +0900, Byungchul Park wrote:
> > On Mon, Sep 18, 2017 at 07:33:29PM -0700, Paul E. McKenney wrote:
> > > > > Hello Paul and Steven,
> > > > >
So I think this is another false positive, and the reason is we use
st->done for multiple purposes.
> > > > > This is saying:
> > > > >
> > > > > Thread A
> > > > > --------
> > > > > takedown_cpu()
> > > > > irq_lock_sparse()
> > > > > wait_for_completion(&st->done) // Wait for completion of B
Thread A wait for the idle task on the outgoing to set the st->state to
CPUHP_AP_IDLE_DEAD(i.e. the corresponding complete() is the one in
cpuhp_complete_idle_dead()), and it happens when we try to _offline_ a
cpu.
> > > > > irq_unlock_sparse()
> > > > >
> > > > > Thread B
> > > > > --------
> > > > > cpuhp_invoke_callback()
> > > > > irq_lock_sparse() // Wait for A to irq_unlock_sparse()
irq_affinity_online_cpu() is called here, so it happens when we try to
_online_ a cpu.
> > > > > (on the way going to complete(&st->done))
and we are going to complete(&st->done) in a hotplug thread context to
indicate the hotplug thread has finished its job(i.e. this complete() is
the one in cpuhp_thread_fun()).
So even though the &st->done are the same instance, the deadlock could
not happen, I think, as we could not up/down a same cpu at the same
time?
If I'm not missing something subtle. To fix this we can either
1) have dedicated completion instances for different wait purposes
in cpuhp_cpu_state.
or
2) extend crossrelease to have the "subclass" concept, so that
callsite of complete() and wait_for_completion() for the same
completion instance but with different purposes could be
differed by lockdep.
Thoughts?
Regards,
Boqun
> > > > >
> > > > > So, lockdep consider this as a deadlock.
> > > > > Is it possible to happen?
> > > >
> > > > In addition, if it's impossible, then we should fix lock class
> > > > assignments so that the locks actually have different classes.
> > >
> > > Interesting, and thank you for the analysis!
> > >
> > > The strange thing is that the way you describe it, this would be a
> > > deterministic deadlock. Yet CPU hotplug operations complete just fine
> > > in my tests. What am I missing here?
> >
> > Hi, :)
> >
> > Lockdep basically reports either (1) an actual deadlock happened at the
> > time or (2) a deadlock possibility, even w/o LOCKDEP_CROSSRELEASE.
> >
> > Both are useful. But LOCKDEP_CROSSRELEASE can only do the latter. IOW,
> > the deadlock would actually happen _only_ when the two threads(A and B)
> > run simultaniously.
> >
> > In your case, those two threads might run at different timings. So it's
> > not an actual deadlock, but still has a possibility for the problem to
> > happen later.
>
> Fair enough, if the wakeup always happened first, deadlock might well
> be avoided. If the sleep happened first, I suspect deadlock would
> be deterministic in this case.
>
> Thanx, Paul
>
> > > > > Thanks,
> > > > > Byungchul
> > > > >
> > > > > > [ 35.313943]
> > > > > > [ 35.313943] 3 locks held by torture_onoff/766:
> > > > > > [ 35.313943] #0: (cpu_add_remove_lock){+.+.}, at: [<ffffffffb9060be2>] do_cpu_down+0x22/0x50
> > > > > > [ 35.313943] #1: (cpu_hotplug_lock.rw_sem){++++}, at: [<ffffffffb90acc41>] percpu_down_write+0x21/0xf0
> > > > > > [ 35.313943] #2: (sparse_irq_lock){+.+.}, at: [<ffffffffb90c5e42>] irq_lock_sparse+0x12/0x20
> > > > > > [ 35.313943]
> > > > > > [ 35.313943] stack backtrace:
> > > > > > [ 35.313943] CPU: 7 PID: 766 Comm: torture_onoff Not tainted 4.13.0-rc4+ #1
> > > > > > [ 35.313943] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Ubuntu-1.8.2-1ubuntu1 04/01/2014
> > > > > > [ 35.313943] Call Trace:
> > > > > > [ 35.313943] dump_stack+0x67/0x97
> > > > > > [ 35.313943] print_circular_bug+0x21d/0x330
> > > > > > [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> > > > > > [ 35.313943] check_prev_add+0x401/0x800
> > > > > > [ 35.313943] ? wake_up_q+0x70/0x70
> > > > > > [ 35.313943] __lock_acquire+0x1100/0x11a0
> > > > > > [ 35.313943] ? __lock_acquire+0x1100/0x11a0
> > > > > > [ 35.313943] ? add_lock_to_list.isra.31+0xc0/0xc0
> > > > > > [ 35.313943] lock_acquire+0x9e/0x1e0
> > > > > > [ 35.313943] ? takedown_cpu+0x86/0xf0
> > > > > > [ 35.313943] wait_for_completion+0x36/0x130
> > > > > > [ 35.313943] ? takedown_cpu+0x86/0xf0
> > > > > > [ 35.313943] ? stop_machine_cpuslocked+0xb9/0xd0
> > > > > > [ 35.313943] ? cpuhp_invoke_callback+0x8b0/0x8b0
> > > > > > [ 35.313943] ? cpuhp_complete_idle_dead+0x10/0x10
> > > > > > [ 35.313943] takedown_cpu+0x86/0xf0
> > > > > > [ 35.313943] cpuhp_invoke_callback+0xa7/0x8b0
> > > > > > [ 35.313943] cpuhp_down_callbacks+0x3d/0x80
> > > > > > [ 35.313943] _cpu_down+0xbb/0xf0
> > > > > > [ 35.313943] do_cpu_down+0x39/0x50
> > > > > > [ 35.313943] cpu_down+0xb/0x10
> > > > > > [ 35.313943] torture_offline+0x75/0x140
> > > > > > [ 35.313943] torture_onoff+0x102/0x1e0
> > > > > > [ 35.313943] kthread+0x142/0x180
> > > > > > [ 35.313943] ? torture_kthread_stopping+0x70/0x70
> > > > > > [ 35.313943] ? kthread_create_on_node+0x40/0x40
> > > > > > [ 35.313943] ret_from_fork+0x27/0x40
> > > >
> >
>
[toc] | [prev] | [next] | [standalone]
| From | Mike Galbraith <efault@gmx.de> |
|---|---|
| Date | 2017-09-19 08:20 +0200 |
| Message-ID | <urk30-rX-15@gated-at.bofh.it> |
| In reply to | #1734664 |
On Tue, 2017-09-19 at 13:37 +0800, Boqun Feng wrote: > On Mon, Sep 18, 2017 at 09:04:56PM -0700, Paul E. McKenney wrote: > > On Tue, Sep 19, 2017 at 11:48:22AM +0900, Byungchul Park wrote: > > > On Mon, Sep 18, 2017 at 07:33:29PM -0700, Paul E. McKenney wrote: > > > > > > Hello Paul and Steven, > > > > > > > > So I think this is another false positive, and the reason is we use > st->done for multiple purposes. > > > > > > > This is saying: > > > > > > > > > > > > Thread A > > > > > > -------- > > > > > > takedown_cpu() > > > > > > irq_lock_sparse() > > > > > > wait_for_completion(&st->done) // Wait for completion of B > > Thread A wait for the idle task on the outgoing to set the st->state to > CPUHP_AP_IDLE_DEAD(i.e. the corresponding complete() is the one in > cpuhp_complete_idle_dead()), and it happens when we try to _offline_ a > cpu. > > > > > > > irq_unlock_sparse() > > > > > > > > > > > > Thread B > > > > > > -------- > > > > > > cpuhp_invoke_callback() > > > > > > irq_lock_sparse() // Wait for A to irq_unlock_sparse() > > irq_affinity_online_cpu() is called here, so it happens when we try to > _online_ a cpu. > > > > > > > (on the way going to complete(&st->done)) > > and we are going to complete(&st->done) in a hotplug thread context to > indicate the hotplug thread has finished its job(i.e. this complete() is > the one in cpuhp_thread_fun()). > > > So even though the &st->done are the same instance, the deadlock could > not happen, I think, as we could not up/down a same cpu at the same > time? > > If I'm not missing something subtle. To fix this we can either > > 1) have dedicated completion instances for different wait purposes > in cpuhp_cpu_state. > > or > > 2) extend crossrelease to have the "subclass" concept, so that > callsite of complete() and wait_for_completion() for the same > completion instance but with different purposes could be > differed by lockdep. > > Thoughts? https://lkml.org/lkml/2017/9/5/184 Peter's patches worked for me, but per tglx, additional (non- grasshopper level) hotplug-fu is required. -Mike
[toc] | [prev] | [next] | [standalone]
| From | Byungchul Park <byungchul.park@lge.com> |
|---|---|
| Date | 2017-09-19 09:00 +0200 |
| Message-ID | <urkFH-Lc-5@gated-at.bofh.it> |
| In reply to | #1734672 |
On Tue, Sep 19, 2017 at 08:11:53AM +0200, Mike Galbraith wrote: > https://lkml.org/lkml/2017/9/5/184 Now, I checked the patches above. It looks to be a good approach to me. Thanks, Byungchul > Peter's patches worked for me, but per tglx, additional (non- > grasshopper level) hotplug-fu is required. > > -Mike
[toc] | [prev] | [next] | [standalone]
| From | "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> |
|---|---|
| Date | 2017-09-19 15:50 +0200 |
| Message-ID | <urr4u-66a-17@gated-at.bofh.it> |
| In reply to | #1734672 |
On Tue, Sep 19, 2017 at 08:11:53AM +0200, Mike Galbraith wrote: > On Tue, 2017-09-19 at 13:37 +0800, Boqun Feng wrote: > > On Mon, Sep 18, 2017 at 09:04:56PM -0700, Paul E. McKenney wrote: > > > On Tue, Sep 19, 2017 at 11:48:22AM +0900, Byungchul Park wrote: > > > > On Mon, Sep 18, 2017 at 07:33:29PM -0700, Paul E. McKenney wrote: > > > > > > > Hello Paul and Steven, > > > > > > > > > > > So I think this is another false positive, and the reason is we use > > st->done for multiple purposes. > > > > > > > > > This is saying: > > > > > > > > > > > > > > Thread A > > > > > > > -------- > > > > > > > takedown_cpu() > > > > > > > irq_lock_sparse() > > > > > > > wait_for_completion(&st->done) // Wait for completion of B > > > > Thread A wait for the idle task on the outgoing to set the st->state to > > CPUHP_AP_IDLE_DEAD(i.e. the corresponding complete() is the one in > > cpuhp_complete_idle_dead()), and it happens when we try to _offline_ a > > cpu. > > > > > > > > > irq_unlock_sparse() > > > > > > > > > > > > > > Thread B > > > > > > > -------- > > > > > > > cpuhp_invoke_callback() > > > > > > > irq_lock_sparse() // Wait for A to irq_unlock_sparse() > > > > irq_affinity_online_cpu() is called here, so it happens when we try to > > _online_ a cpu. > > > > > > > > > (on the way going to complete(&st->done)) > > > > and we are going to complete(&st->done) in a hotplug thread context to > > indicate the hotplug thread has finished its job(i.e. this complete() is > > the one in cpuhp_thread_fun()). > > > > > > So even though the &st->done are the same instance, the deadlock could > > not happen, I think, as we could not up/down a same cpu at the same > > time? > > > > If I'm not missing something subtle. To fix this we can either > > > > 1) have dedicated completion instances for different wait purposes > > in cpuhp_cpu_state. > > > > or > > > > 2) extend crossrelease to have the "subclass" concept, so that > > callsite of complete() and wait_for_completion() for the same > > completion instance but with different purposes could be > > differed by lockdep. > > > > Thoughts? > > https://lkml.org/lkml/2017/9/5/184 > > Peter's patches worked for me, but per tglx, additional (non- > grasshopper level) hotplug-fu is required. Thank you, I will give these a go! Thanx, Paul
[toc] | [prev] | [next] | [standalone]
Page 1 of 2 [1] 2 Next page →
Back to top | Article view | linux.kernel
csiph-web