Re: rcu, sched: WARNING: CPU: 30 PID: 23771 at kernel/rcu/tree_plugin.h:337 rcu_read_unlock_special+0x369/0x550()
From: Paul E. McKenney
Date: Fri Jan 23 2015 - 04:48:32 EST
On Fri, Jan 23, 2015 at 05:16:46PM +0800, Lai Jiangshan wrote:
> On 01/23/2015 02:55 PM, Paul E. McKenney wrote:
> > On Thu, Jan 22, 2015 at 11:05:45PM -0500, Sasha Levin wrote:
> >> On 01/22/2015 11:02 PM, Sasha Levin wrote:
> >>> On 01/22/2015 10:51 PM, Paul E. McKenney wrote:
> >>>> On Thu, Jan 22, 2015 at 10:29:01PM -0500, Sasha Levin wrote:
> >>>>>> On 01/21/2015 07:43 PM, Paul E. McKenney wrote:
> >>>>>>>> On Wed, Jan 21, 2015 at 10:44:57AM -0500, Sasha Levin wrote:
> >>>>>>>>>> On 01/20/2015 09:57 PM, Paul E. McKenney wrote:
> >>>>>>>>>>>>>>>> So RCU believes that an RCU read-side critical section that ended within
> >>>>>>>>>>>>>>>>>>>> an interrupt handler (in this case, an hrtimer) somehow got preempted.
> >>>>>>>>>>>>>>>>>>>> Which is not supposed to happen.
> >>>>>>>>>>>>>>>>>>>>
> >>>>>>>>>>>>>>>>>>>> Do you have CONFIG_PROVE_RCU enabled? If not, could you please enable it
> >>>>>>>>>>>>>>>>>>>> and retry?
> >>>>>>>>>>>>>>>>
> >>>>>>>>>>>>>>>> I did have CONFIG_PROVE_RCU, and didn't see anything else besides what I pasted here.
> >>>>>>>>>>>> OK, fair enough. I do have a stack of RCU CPU stall-warning changes on
> >>>>>>>>>>>> their way in, please see v3.19-rc1..630181c4a915 in -rcu, which is at:
> >>>>>>>>>>>>
> >>>>>>>>>>>> git://git.kernel.org/pub/scm/linux/kernel/git/paulmck/linux-rcu.git
> >>>>>>>>>>>>
> >>>>>>>>>>>> These handle the problems that Dave Jones, yourself, and a few others
> >>>>>>>>>>>> located this past December. Could you please give them a spin?
> >>>>>>>>>>
> >>>>>>>>>> They seem to be a part of -next already, so this testing already includes them.
> >>>>>>>>>>
> >>>>>>>>>> I seem to be getting them about once a day, anything I can add to debug it?
> >>>>>>>>
> >>>>>>>> Could you please try reproducing with the following patch?
> >>>>>>
> >>>>>> Yes, and I've got mixed results. It reproduced, and all I got was:
> >>>>>>
> >>>>>> [ 717.645572] ===============================
> >>>>>> [ 717.645572] [ INFO: suspicious RCU usage. ]
> >>>>>> [ 717.645572] 3.19.0-rc5-next-20150121-sasha-00064-g3c37e35-dirty #1809 Tainted: G W
> >>>>>> [ 717.645572] -------------------------------
> >>>>>> [ 717.645572] kernel/rcu/tree_plugin.h:337 rcu_read_unlock() from irq or softirq with blocking in critical section!!!
> >>>>>> [ 717.645572] !
> >>>>>> [ 717.645572]
> >>>>>> [ 717.645572] other info that might help us debug this:
> >>>>>> [ 717.645572]
> >>>>>> [ 717.645572]
> >>>>>> [ 717.645572] rcu_scheduler_active = 1, debug_locks = 1
> >>>>>> [ 717.645572] 3 locks held by trinity-c29/16497:
> >>>>>> [ 717.645572] #0: (&sb->s_type->i_mutex_key){+.+.+.}, at: [<ffffffff81bec373>] lookup_slow+0xd3/0x420
> >>>>>> [ 717.645572] #1:
> >>>>>> [hang]
> >>>>>>
> >>>>>> So the rest of the locks/stack trace didn't get printed, nor the pr_alert() which
> >>>>>> should follow that.
> >>>>>>
> >>>>>> I've removed the lockdep call and will re-run it.
> >>>> Thank you! You are keeping the pr_alert(), correct?
> >>>
> >>> Yup, just the lockdep call goes away.
> >>
> >> Okay, this reproduced faster than I anticipated:
> >>
> >> [ 786.160131] ->rcu_read_unlock_special: 0x100 (b: 0, nq: 1)
> >> [ 786.239513] ->rcu_read_unlock_special: 0x100 (b: 0, nq: 1)
> >> [ 786.240503] ->rcu_read_unlock_special: 0x100 (b: 0, nq: 1)
> >> [ 786.242575] ->rcu_read_unlock_special: 0x100 (b: 0, nq: 1)
> >> [ 786.243565] ->rcu_read_unlock_special: 0x100 (b: 0, nq: 1)
> >> [ 786.243565] ->rcu_read_unlock_special: 0x100 (b: 0, nq: 1)
> >> [ 786.243565] ->rcu_read_unlock_special: 0x100 (b: 0, nq: 1)
> >> [ 786.243565] ->rcu_read_unlock_special: 0x100 (b: 0, nq: 1)
> >> [ 786.243565] ->rcu_read_unlock_special: 0x100 (b: 0, nq: 1)
> >>
> >> It seems like the WARN_ON_ONCE was hiding the fact it actually got hit couple
> >> of times in a very short interval. Maybe that would also explain lockdep crapping
> >> itself.
> >
> > OK, that was what I thought was the situation. I have not yet fully
> > worked out how RCU gets into that state, but in the meantime, here
> > is a patch that should prevent the splats. (It requires a subtle
> > interaction of quiescent-state detection and the scheduling-clock
> > interrupt.)
> >
> > Thanx, Paul
> >
> > ------------------------------------------------------------------------
> >
> > rcu: Clear need_qs flag to prevent splat
> >
> > If the scheduling-clock interrupt sets the current tasks need_qs flag,
> > but if the current CPU passes through a quiescent state in the meantime,
> > then rcu_preempt_qs() will fail to clear the need_qs flag, which can fool
> > RCU into thinking that additional rcu_read_unlock_special() processing
> > is needed. This commit therefore clears the need_qs flag before checking
> > for additional processing.
> >
> > Reported-by: Sasha Levin <sasha.levin@xxxxxxxxxx>
> > Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxxxxxxxxxx>
> >
> > diff --git a/kernel/rcu/tree_plugin.h b/kernel/rcu/tree_plugin.h
> > index 8669de884445..ec99dc16aa38 100644
> > --- a/kernel/rcu/tree_plugin.h
> > +++ b/kernel/rcu/tree_plugin.h
> > @@ -322,6 +322,7 @@ void rcu_read_unlock_special(struct task_struct *t)
> > special = t->rcu_read_unlock_special;
> > if (special.b.need_qs) {
> > rcu_preempt_qs();
> > + t->rcu_read_unlock_special.need_qs = false;
> > if (!t->rcu_read_unlock_special.s) {
> > local_irq_restore(flags);
> > return;
> >
> > .
>
>
> rcu_preempt_qs() can be called from rcu_preempt_note_context_switch()
> without irq-disabled. I think it is dangerous, since it touches need_qs and
> passed_quiesce directly and touches rcu_read_unlock_special.b.blocked and
> qs_pending indirectly. At least it addes burden for me to understand them all.
Yep, disabling interrupts across the call to rcu_preempt_qs() in
rcu_preempt_note_context_switch() would be another way to fix this.
And in fact the code used to disable interrupts across this call.
But I was informed that interrupt disabling in the scheduler fastpath
was socially irresponsible, so I removed it, obviously failing to think
it through. So the fix above should cover things without re-introducing
the overhead on the scheduler fastpath.
Make sense, or is there some other problem with this?
Here are some that I considered and dismissed as non-problems:
1. We could take an interrupt just before recording the quiescent
state, do RCU_SOFTIRQ on return from that interrupt, notice a new
grace period, and upon return from interrupt to rcu_preempt_qs()
record a quiescent state.
But that is OK, because we are in rcu_preempt_qs(), and thus
are in a quiescent state both before and after the interrupt,
regardless of what the grace period number might be.
2. As #1 above, but we get interrupted just after recording
the quiescent state instead of just before.
This is also OK. When the new grace period is noticed, the
quiescent-state information is cleared. The current quiescent
state is ignored, but there will be another quiescent state
along at some point in the near future.
3. As #1 above, but after clearing need_qs. Same result as #2.
Any that I missed?
Thanx, Paul
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/