Re: [PATCH v2] rcu: Fix missed wakeup of exp_wq waiters

From: Paul E. McKenney
Date: Thu Nov 21 2019 - 10:01:14 EST

Next message: Yang Weijiang: "Re: [PATCH v7 6/9] vmx: spp: Set up SPP paging table at vmentry/vmexit"
Previous message: syzbot: "Re: KASAN: use-after-free Read in ccid_hc_tx_delete"
In reply to: Neeraj Upadhyay: "Re: [PATCH v2] rcu: Fix missed wakeup of exp_wq waiters"
Next in thread: Neeraj Upadhyay: "Re: [PATCH v2] rcu: Fix missed wakeup of exp_wq waiters"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Thu, Nov 21, 2019 at 09:48:05AM +0530, Neeraj Upadhyay wrote:
> On 11/21/2019 9:37 AM, Paul E. McKenney wrote:
> > On Wed, Nov 20, 2019 at 10:28:38AM +0530, Neeraj Upadhyay wrote:
> > >
> > > On 11/20/2019 1:08 AM, Paul E. McKenney wrote:
> > > > On Tue, Nov 19, 2019 at 03:17:07AM +0000, Neeraj Upadhyay wrote:
> > > > > For the tasks waiting in exp_wq inside exp_funnel_lock(),
> > > > > there is a chance that they might be indefinitely blocked
> > > > > in below scenario:
> > > > >
> > > > > 1. There is a task waiting on exp sequence 0b'100' inside
> > > > > exp_funnel_lock(). This task blocks at wq index 1.
> > > > >
> > > > > synchronize_rcu_expedited()
> > > > > s = 0b'100'
> > > > > exp_funnel_lock()
> > > > > wait_event(rnp->exp_wq[rcu_seq_ctr(s) & 0x3]
> > > > >
> > > > > 2. The expedited grace period (which above task blocks for)
> > > > > completes and task (task1) holding exp_mutex queues
> > > > > worker and schedules out.
> > > > >
> > > > > synchronize_rcu_expedited()
> > > > > s = 0b'100'
> > > > > queue_work(rcu_gp_wq, &rew.rew_work)
> > > > > wake_up_worker()
> > > > > schedule()
> > > > >
> > > > > 3. kworker A picks up the queued work and completes the exp gp
> > > > > sequence and then blocks on exp_wake_mutex, which is held
> > > > > by another kworker, which is doing wakeups for expedited_sequence
> > > > > 0.
> > > > >
> > > > > rcu_exp_wait_wake()
> > > > > rcu_exp_wait_wake()
> > > > > rcu_exp_gp_seq_end(rsp) // rsp->expedited_sequence is incremented
> > > > > // to 0b'100'
> > > > > mutex_lock(&rcu_state.exp_wake_mutex)
> > > > >
> > > > > 4. task1 does not enter wait queue, as sync_exp_work_done() returns true,
> > > > > and releases exp_mutex.
> > > > >
> > > > > wait_event(rnp->exp_wq[rcu_seq_ctr(s) & 0x3],
> > > > > sync_exp_work_done(rsp, s));
> > > > > mutex_unlock(&rsp->exp_mutex);
> > > > >
> > > > > 5. Next exp GP completes, and sequence number is incremented:
> > > > >
> > > > > rcu_exp_wait_wake()
> > > > > rcu_exp_wait_wake()
> > > > > rcu_exp_gp_seq_end(rsp) // rsp->expedited_sequence = 0b'200'
> > > > >
> > > > > 6. kworker A acquires exp_wake_mutex. As it uses current
> > > > > expedited_sequence, it wakes up workers from wrong wait queue
> > > > > index - it should have worken wait queue corresponding to
> > > > > 0b'100' sequence, but wakes up the ones for 0b'200' sequence.
> > > > > This results in task at step 1 indefinitely blocked.
> > > > >
> > > > > rcu_exp_wait_wake()
> > > > > wake_up_all(&rnp->exp_wq[rcu_seq_ctr(rsp->expedited_sequence) & 0x3]);
> > > > >
> > > > > This issue manifested as DPM device timeout during suspend, as scsi
> > > > > device was stuck in _synchronize_rcu_expedited().
> > > > >
> > > > > schedule()
> > > > > synchronize_rcu_expedited()
> > > > > synchronize_rcu()
> > > > > scsi_device_quiesce()
> > > > > scsi_bus_suspend()
> > > > > dpm_run_callback()
> > > > > __device_suspend()
> > > > >
> > > > > Fix this by using the correct exp sequence number, the one which
> > > > > owner of the exp_mutex initiated and passed to kworker,
> > > > > to index the wait queue, inside rcu_exp_wait_wake().
> > > > >
> > > > > Signed-off-by: Neeraj Upadhyay <neeraju@xxxxxxxxxxxxxx>
> > > >
> > > > Queued, thank you!
> > > >
> > > > I reworked the commit message to make it easier to follow the sequence
> > > > of events. Please see below and let me know if I messed anything up.
> > > >
> > > > Thanx, Paul
> > > >
> > > > ------------------------------------------------------------------------
> > > >
> > > > commit d887fd2a66861f51ed93b5dde894b9646a5569dd
> > > > Author: Neeraj Upadhyay <neeraju@xxxxxxxxxxxxxx>
> > > > Date: Tue Nov 19 03:17:07 2019 +0000
> > > >
> > > > rcu: Fix missed wakeup of exp_wq waiters
> > > > Tasks waiting within exp_funnel_lock() for an expedited grace period to
> > > > elapse can be starved due to the following sequence of events:
> > > > 1. Tasks A and B both attempt to start an expedited grace
> > > > period at about the same time. This grace period will have
> > > > completed when the lower four bits of the rcu_state structure's
> > > > ->expedited_sequence field are 0b'0100', for example, when the
> > > > initial value of this counter is zero. Task A wins, and thus
> > > > does the actual work of starting the grace period, including
> > > > acquiring the rcu_state structure's .exp_mutex and sets the
> > > > counter to 0b'0001'.
> > > > 2. Because task B lost the race to start the grace period, it
> > > > waits on ->expedited_sequence to reach 0b'0100' inside of
> > > > exp_funnel_lock(). This task therefore blocks on the rcu_node
> > > > structure's ->exp_wq[1] field, keeping in mind that the
> > > > end-of-grace-period value of ->expedited_sequence (0b'0100')
> > > > is shifted down two bits before indexing the ->exp_wq[] field.
> > > > 3. Task C attempts to start another expedited grace period,
> > > > but blocks on ->exp_mutex, which is still held by Task A.
> > > > 4. The aforementioned expedited grace period completes, so that
> > > > ->expedited_sequence now has the value 0b'0100'. A kworker task
> > > > therefore acquires the rcu_state structure's ->exp_wake_mutex
> > > > and starts awakening any tasks waiting for this grace period.
> > > > 5. One of the first tasks awakened happens to be Task A. Task A
> > > > therefore releases the rcu_state structure's ->exp_mutex,
> > > > which allows Task C to start the next expedited grace period,
> > > > which causes the lower four bits of the rcu_state structure's
> > > > ->expedited_sequence field to become 0b'0101'.
> > > > 6. Task C's expedited grace period completes, so that the lower four
> > > > bits of the rcu_state structure's ->expedited_sequence field now
> > > > become 0b'1000'.
> > > > 7. The kworker task from step 4 above continues its wakeups.
> > > > Unfortunately, the wake_up_all() refetches the rcu_state
> > > > structure's .expedited_sequence field:
> > >
> > > This might not be true. I think wake_up_all(), which internally calls
> > > __wake_up(), will use a single wq_head for doing all wakeups. So, a single
> > > .expedited_sequence value would be used to get wq_head.
> > >
> > > void __wake_up(struct wait_queue_head *wq_head, ...)
> >
> > The wake_up_all() really is selecting among four different ->exp_wq[]
> > array entries:
> >
> > wake_up_all(&rnp->exp_wq[rcu_seq_ctr(rcu_state.expedited_sequence) & 0x3]);
> >
> > So I lost you here. Are you saying that the wake_up_all() will somehow
> > be operating on ->exp_wq[1], which is where Task B is blocked? Or that
> > Task B would instead be blocked on ->exp_wq[2]? Or that failing to wake
> > up Task B is OK for some reason? Or something else entirely?
>
> My bad; I was thinking only of the case where there is only one
> rnp node (which is also the root) in RCU tree. In case of only
> one rnp node also, issue can be seen. Please ignore my
> comment. The commit description looks good to me.

Thank you for checking!

And the sequence of events below looks greatly improved over your
original. I suspect that there are more similar bugs to find in
Linux-kernel RCU, so please use a carefully labeled style like that
below when reporting the next one.

Thanx, Paul

> Thanks
> Neeraj
> >
> > Thanx, Paul
> >
> > > However, below sequence of events would result in problem:
> > >
> > > 1. Tasks A starts an expedited grace period at about the same time.
> > > This grace period will have completed when the lower four bits
> > > of the rcu_state structure's ->expedited_sequence field are 0b'0100',
> > > for example, when the initial value of this counter is zero.
> > > Task A wins, acquires the rcu_state structure's .exp_mutex and
> > > sets the counter to 0b'0001'.
> > >
> > > 2. The aforementioned expedited grace period completes, so that
> > > ->expedited_sequence now has the value 0b'0100'. A kworker task
> > > therefore acquires the rcu_state structure's ->exp_wake_mutex
> > > and starts awakening any tasks waiting for this grace period.
> > > This kworker gets preempted while unlocking wq_head lock
> > >
> > > wake_up_all()
> > > __wake_up()
> > > __wake_up_common_lock()
> > > spin_unlock_irqrestore()
> > > __raw_spin_unlock_irqrestore()
> > > preempt_enable()
> > > __preempt_schedule()
> > >
> > > 3. One of the first tasks awakened happens to be Task A. Task A
> > > therefore releases the rcu_state structure's ->exp_mutex,
> > >
> > > 4. Tasks B and C both attempt to start an expedited grace
> > > period at about the same time. This grace period will have
> > > completed when the lower four bits of the rcu_state structure's
> > > ->expedited_sequence field are 0b'1000'. Task B wins, and thus
> > > does the actual work of starting the grace period, including
> > > acquiring the rcu_state structure's .exp_mutex and sets the
> > > counter to 0b'0101'.
> > >
> > > 5. Because task C lost the race to start the grace period, it
> > > waits on ->expedited_sequence to reach 0b'1000' inside of
> > > exp_funnel_lock(). This task therefore blocks on the rcu_node
> > > structure's ->exp_wq[2] field, keeping in mind that the
> > > end-of-grace-period value of ->expedited_sequence (0b'1000')
> > > is shifted down two bits before indexing the ->exp_wq[] field.
> > >
> > > 6. Task B queues work to complete expedited grace period. This
> > > task is preempted just before wait_event call. Kworker task picks
> > > up the work queued by task B and and completes grace period, so
> > > that the lower four bits of the rcu_state structure's
> > > ->expedited_sequence field now become 0b'1000'. This kworker starts
> > > waiting on the exp_wake_mutex, which is owned by kworker doing
> > > wakeups for expedited sequence initiated by task A.
> > >
> > > 7. Task B schedules in and finds its expedited sequence snapshot has
> > > completed; so, it does not enter waitq and releases exp_mutex. This
> > > allows Task D to start the next expedited grace period,
> > > which causes the lower four bits of the rcu_state structure's
> > > ->expedited_sequence field to become 0b'1001'.
> > >
> > > 8. Task D's expedited grace period completes, so that the lower four
> > > bits of the rcu_state structure's ->expedited_sequence field now
> > > become 0b'1100'.
> > >
> > > 9. kworker from step 2 is scheduled in and releases exp_wake_mutex;
> > > kworker correspnding to Task B's expedited grace period acquires
> > > exp_wake_mutex and starts wakeups. Unfortunately, it used the
> > > rcu_state structure's .expedited_sequence field for determining
> > > the waitq index.
> > >
> > >
> > > wake_up_all(&rnp->exp_wq[rcu_seq_ctr(rcu_state.expedited_sequence) & 0x3]);
> > >
> > > This results in the wakeup being applied to the rcu_node
> > > structure's ->exp_wq[3] field, which is unfortunate given that
> > > Task C is instead waiting on ->exp_wq[2].
> > >
> > >
> > > > wake_up_all(&rnp->exp_wq[rcu_seq_ctr(rcu_state.expedited_sequence) & 0x3]);
> > > > This results in the wakeup being applied to the rcu_node
> > > > structure's ->exp_wq[2] field, which is unfortunate given that
> > > > Task B is instead waiting on ->exp_wq[1].
> > > > On a busy system, no harm is done (or at least no permanent harm is done).
> > > > Some later expedited grace period will redo the wakeup. But on a quiet
> > > > system, such as many embedded systems, it might be a good long time before
> > > > there was another expedited grace period. On such embedded systems,
> > > > this situation could therefore result in a system hang.
> > > > This issue manifested as DPM device timeout during suspend (which
> > > > usually qualifies as a quiet time) due to a SCSI device being stuck in
> > > > _synchronize_rcu_expedited(), with the following stack trace:
> > > > schedule()
> > > > synchronize_rcu_expedited()
> > > > synchronize_rcu()
> > > > scsi_device_quiesce()
> > > > scsi_bus_suspend()
> > > > dpm_run_callback()
> > > > __device_suspend()
> > > > This commit therefore prevents such delays, timeouts, and hangs by
> > > > making rcu_exp_wait_wake() use its "s" argument consistently instead of
> > > > refetching from rcu_state.expedited_sequence.
> > >
> > > Do we need a "fixes" tag here?
> > >
> > > > Signed-off-by: Neeraj Upadhyay <neeraju@xxxxxxxxxxxxxx>
> > > > Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxx
> > > >
> > > > diff --git a/kernel/rcu/tree_exp.h b/kernel/rcu/tree_exp.h
> > > > index 6ce598d..4433d00a 100644
> > > > --- a/kernel/rcu/tree_exp.h
> > > > +++ b/kernel/rcu/tree_exp.h
> > > > @@ -557,7 +557,7 @@ static void rcu_exp_wait_wake(unsigned long s)
> > > > spin_unlock(&rnp->exp_lock);
> > > > }
> > > > smp_mb(); /* All above changes before wakeup. */
> > > > - wake_up_all(&rnp->exp_wq[rcu_seq_ctr(rcu_state.expedited_sequence) & 0x3]);
> > > > + wake_up_all(&rnp->exp_wq[rcu_seq_ctr(s) & 0x3]);
> > > > }
> > > > trace_rcu_exp_grace_period(rcu_state.name, s, TPS("endwake"));
> > > > mutex_unlock(&rcu_state.exp_wake_mutex);
> > > >
> > >
> > > --
> > > QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member of
> > > the Code Aurora Forum, hosted by The Linux Foundation
>
> --
> QUALCOMM INDIA, on behalf of Qualcomm Innovation Center, Inc. is a member of
> the Code Aurora Forum, hosted by The Linux Foundation

Next message: Yang Weijiang: "Re: [PATCH v7 6/9] vmx: spp: Set up SPP paging table at vmentry/vmexit"
Previous message: syzbot: "Re: KASAN: use-after-free Read in ccid_hc_tx_delete"
In reply to: Neeraj Upadhyay: "Re: [PATCH v2] rcu: Fix missed wakeup of exp_wq waiters"
Next in thread: Neeraj Upadhyay: "Re: [PATCH v2] rcu: Fix missed wakeup of exp_wq waiters"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]