Re: RCU qsmask !=0 warnings on large-SMP...

[Steffen Persvold <sp@numascale.com>]

On 1/25/2012 19:14, Paul E. McKenney wrote:
[]
>> CONFIG_NO_HZ is not set, so it should not happen. We see that the behavior is the same with CONFIG_NO_HZ=y though, but it takes longer to reproduce usually.
>
> OK, the CONFIG_NO_HZ=n has the least code involved, so it would be best
> for debugging.

Good, that was my thought also when looking at the code. I'm reducing 
NR_CPUS to 512 now to get two levels just for simpler debugging (the 
issue is still present).

[]
>> Because the RCU tree is 3 levels, the printout function we added in the patch gets called 3 times each time with the same RDP but with different RNPs (in rcu_start_gp()).
>
> Ah, good point.  Hmmm...
>
> Looking back at Daniel's original email, we have the root rcu_node
> structure with ->qsmask=0x1 (indicating first descendent), the next
> level having ->qsmask=0x8 (indicating fourth descendent) and the last
> level having ->qsmask=0x1, again indicating first descendent.  So,
> zero, 16, 32, 48.  Which agrees with the CPU number below that has not
> yet caught up to the current grace period.
>
> Another really odd thing...  If we are starting the new grace period,
> we should have incremented rsp->gpnum.  And in fact, we do have
> rsp->gpnum being one larger than rsp->completed, as expected.  But
> if we have only initialized the root rcu_node structures, how can
> the per-CPU rcudata structures know about the new grace period yet?
>
> There was a time when the CPUs could find out early, but I think that
> was a long time ago.  Yes, check_for_new_grace_period() does compare
> rdp->gpnum against rsp->gpnum, but it calls note_new_gpnum() which
> acquires the rnp->lock(), and nothing happens unless __note_new_gpnum()
> sees that rnp->gpnum is different rdp->gpnum.
>
> So, it would be very interesting to add the values rdp->mynode->gpnum
> and rdp->mynode->completed to your list, perhaps labeling them something
> like "rng" and "rnc" respectively.

I will add this to the printout.

>
> Of course, CPU 48 should not have decided that it was done with the
> old grace period before clearing its bit.  For that matter, some
> CPU somewhere decided that the grace period was done despite the
> root rcu_node's ->qsmask being non-zero, which should be prevented
> by the:
>
> 	if (rnp->qsmask != 0 || rcu_preempt_blocked_readers_cgp(rnp)) {
>
> line in rcu_report_qs_rnp().
>
> 3.2 has some event tracing that would be extremely helpful in tracking
> this down.  Are you able to run 3.2?

Yes, 3.2.1 is our debug target right now.

[]
>>> Same here, but most of the ql= values are larger.  Later printout?
>>
>> The loop in rcu_start_gp() releases the node lock between each time it gets a new level in the RCU tree (it has to) :
>>
>> 	rcu_for_each_node_breadth_first(rsp, rnp) {
>> 		raw_spin_lock(&rnp->lock);	/* irqs already disabled. */
>> 		rcu_debug_print(rsp, rnp);
>>
>> so I guess this allows ql= values to increase maybe, no ?
>
> The ql= levels can increase anyway -- those queues are only accessed by
> the corresponding CPU or from stop_machine context.  The small increases
> are entirely consistent with your having bits set at all levels of the
> rcu_node tree.  The reason I was surprised is that my earlier bugs (as
> in before the code hit mainline) only ever resulted in a single level
> having a stray bit.

Ok.

[]
>>
>> Thanks for looking into this Paul, we'd be more than happy to test out theories and patches.
>
> The event tracing, particularly the "rcu_grace_period" set, would be
> very helpful.

Are you talking about the data from /sys/kernel/debug/rcu/ ? I have 
CONFIG_RCU_TRACE (and consequently CONFIG_TREE_RCU_TRACE) set, is this 
enough to get the event data you want ?

Cheers,
-- 
Steffen Persvold, Chief Architect NumaChip
Numascale AS - www.numascale.com
Tel: +47 92 49 25 54 Skype: spersvold