| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <54C300DD.9070608@cn.fujitsu.com>
Date: Sat, 24 Jan 2015 10:18:05 +0800
From: Lai Jiangshan <laijs@...fujitsu.com>
To: <paulmck@...ux.vnet.ibm.com>, Sasha Levin <sasha.levin@...cle.com>
CC: Ingo Molnar <mingo@...nel.org>,
Peter Zijlstra <peterz@...radead.org>,
LKML <linux-kernel@...r.kernel.org>,
"davej@...emonkey.org.uk >> Dave Jones" <davej@...emonkey.org.uk>
Subject: Re: rcu, sched: WARNING: CPU: 30 PID: 23771 at kernel/rcu/tree_plugin.h:337
rcu_read_unlock_special+0x369/0x550()
On 01/23/2015 05:36 PM, Paul E. McKenney wrote:
> On Thu, Jan 22, 2015 at 10:55:42PM -0800, 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.)
>
> And I did finally figure out how this can happen. Please see below
> for an updated patch with this information recorded in the commit log.
> Sasha, I am impressed -- your testing not only located a true RCU bug,
> but an RCU bug that can happen on a uniprocessor! ;-)
>
> As far as I know, the bug is harmless apart from the splat, but still...
>
> 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.
>
> For this problem to occur, we need rcu_preempt_data.passed_quiesce equal
> to true and current->rcu_read_unlock_special.b.need_qs also equal to true.
> This condition can occur as follows:
Hi, Paul
I still can't draw the sequence map.
>
> 1. CPU 0 is aware of the current preemptible RCU grace period,
> but has not yet passed through a quiescent state. Among other
> things, this means that rcu_preempt_data.passed_quiesce is false.
>
> 2. Task A running on CPU 0 enters a preemptible RCU read-side
> critical section.
>
> 3. CPU 0 takes a scheduling-clock interrupt, which notices the
> RCU read-side critical section and the need for a quiescent state,
> and thus sets current->rcu_read_unlock_special.b.need_qs to true.
So, Task A is still in the preemptible RCU read-side critical section here.
>
> 4. Task A is preempted, enters the scheduler, eventually invoking
> rcu_preempt_note_context_switch() which in turn invokes
> rcu_preempt_qs().
>
> Because rcu_preempt_data.passed_quiesce is false,
> control enters the body of the "if" statement, which sets
> rcu_preempt_data.passed_quiesce to true.
>
> 5. At this point, CPU 0 takes an interrupt. The interrupt
> handler contains an RCU read-side critical section, and
> the rcu_read_unlock() notes that current->rcu_read_unlock_special
> is nonzero, and thus invokes rcu_read_unlock_special().
If the previous critical section is not ended, this new critical section
is nested, and this new critical section will not call rcu_read_unlock_special().
If the previous critical section is ended, the conditions were changed between
step#3,#4,#5, and the following #6... can't happen.
Thanks,
Lai
>
> 6. Once in rcu_read_unlock_special(), the fact that
> current->rcu_read_unlock_special.b.need_qs is true becomes
> apparent, so rcu_read_unlock_special() invokes rcu_preempt_qs().
> Recursively, given that we interrupted out of that same
> function in the preceding step.
>
> 7. Because rcu_preempt_data.passed_quiesce is now true,
> rcu_preempt_qs() does nothing, and simply returns.
>
> 8. Upon return to rcu_read_unlock_special(), it is noted that
> current->rcu_read_unlock_special is still nonzero (because
> the interrupted rcu_preempt_qs() had not yet gotten around
> to clearing current->rcu_read_unlock_special.b.need_qs).
>
> 9. Execution proceeds to the WARN_ON_ONCE(), which notes that
> we are in an interrupt handler and thus duly splats.
>
> The solution, as noted above, is to make rcu_read_unlock_special()
> clear out current->rcu_read_unlock_special.b.need_qs after calling
> rcu_preempt_qs(). The interrupted rcu_preempt_qs() will clear it again,
> but this is harmless. The worst that happens is that we clobber another
> attempt to set this field, but this is not a problem because we just
> got done reporting a quiescent state.
>
> Reported-by: Sasha Levin <sasha.levin@...cle.com>
> Signed-off-by: Paul E. McKenney <paulmck@...ux.vnet.ibm.com>
>
> 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;
>
> .
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
Powered by blists - more mailing lists