Re: Normal RCU grace period can be stalled for long because need-resched flags not set?

["Paul E. McKenney" <paulmck@linux.ibm.com>]

On Thu, Jul 04, 2019 at 02:50:55PM -0400, Joel Fernandes wrote:
> On Thu, Jul 04, 2019 at 10:13:15AM -0700, Paul E. McKenney wrote:
> > On Wed, Jul 03, 2019 at 11:24:54PM -0400, Joel Fernandes wrote:
> > > On Wed, Jul 03, 2019 at 05:50:09PM -0700, Paul E. McKenney wrote:
> > > > On Wed, Jul 03, 2019 at 08:32:13PM -0400, Joel Fernandes wrote:
> > 
> > [ . . . ]
> > 
> > > > > If I add an rcu_perf_wait_shutdown() to the end of the loop, the outliers go away.
> > > > > 
> > > > > Still can't explain that :)
> > > > > 
> > > > > 	do {
> > > > > 		...
> > > > > 		...
> > > > > +               rcu_perf_wait_shutdown();
> > > > >         } while (!torture_must_stop());
> > > > 
> > > > Might it be the cond_resched_tasks_rcu_qs() invoked from within
> > > > rcu_perf_wait_shutdown()?  So I have to ask...  What happens if you
> > > > use cond_resched_tasks_rcu_qs() at the end of that loop instead of
> > > > rcu_perf_wait_shutdown()?
> > > 
> > > I don't think it is, if I call cond_resched_tasks_rcu_qs(), it still doesn't
> > > help. Only calling rcu_perf_wait_shutdown() cures it.
> > 
> > My eyes seem to be working better today.
> > 
> > Here is rcu_perf_wait_shutdown():
> > 
> > 	static void rcu_perf_wait_shutdown(void)
> > 	{
> > 		cond_resched_tasks_rcu_qs();
> > 		if (atomic_read(&n_rcu_perf_writer_finished) < nrealwriters)
> > 			return;
> > 		while (!torture_must_stop())
> > 			schedule_timeout_uninterruptible(1);
> > 	}
> > 
> > Take a close look at the "while" loop.  It is effectively ending your
> > test prematurely and thus rendering the code no longer CPU-bound.  ;-)
> 
> That makes a lot of sense. I also found that I can drop
> 'rcu_perf_wait_shutdown' in my preempt-disable loop as long as I don't do an
> ftrace trace. I suspect the trace dump happening at the end is messing with
> the last iteration of the writer loops. My preempt disable loop probably
> disables preemption for a long time without rescheduling during this ftrace
> dump.

Agreed, although rcutorture does have special handling for ftrace dumps,
they still kick out the occasional RCU CPU stall warning and the like.

> Anyway, having the rcu_perf_wait_shutdown without doing the ftrace dump seems
> to solve it.

Did you mean "leaving out both the rcu_perf_wait_shutdown() and the
ftrace dump"?

Another approach would be to set a global variable prior to the call
to ftrace_dump() -- and there might already be such a variable -- and
making a load of that variable be part of the termination condition for
your loop.  With appropriate ordering added, of course.

> So actually the point of all my testing was (other than learning) was to
> compare how RCU pre-consolidated vs post-consolidated does. As predicted,
> with post-consolidated RCU, the preempt-disable / enable does manage to slow
> down the grace periods. This is not an issue per-se as you said that even
> 100s of ms of grace period delay is within acceptable RCU latencies. The
> results are as below:

And thank you for checking this out!

And the 1.2-second outliers were due to the ftrace dump?  If not, it would
be good to understand what was happening in that case.

> I am happy to try out any other test scenarios as well if you would like me
> to. I am open to any other suggestions you may have to improve the rcuperf
> tests in this (deferred/consolidated RCU) or other regards.
> 
> I did have a request, could you help me understand why is the grace period
> duration double that of my busy wait time? You mentioned this has something
> to do with the thread not waking up before another GP is started. But I did
> not follow this. Thanks a lot!!

Let's look at a normal grace period, and assume the ->gp_seq grace-period
sequence counter is initially 0x1, so that a grace period is already
in progress (keep in mind that the low-order two bits of ->gp_seq are
the phase within the grace period and the rest of the bits are the
grace-period number, so we are in phase 1 of the grace period following
grace period #0).  This grace period was started via synchronize_rcu()
by Task A.

Then we have the following sequence of events:

o	Task B does call_rcu(), but is too late to use the already-started
	grace period, so it needs another one.	The ->gp_seq_needed
	counter thus becomes 0x8.

o	The current grace period completes, so that the ->gp_seq
	counter becomes 0x4.  Callback invocation commences.

o	The grace-period kthread notices that ->gp_seq_needed is greater
	than ->gp_seq, so it starts a new grace period.  The ->gp_seq
	counter therefore becomes 0x5.

o	The callback for Task A's synchronize_rcu() is invoked, awakening
	Task A.  This happens almost immediately after the new grace
	period starts, but does definitely happen -after- that grace
	period starts.

o	Task A, being part of rcuperf, almost immediately does another
	synchronize_rcu().  So ->gp_seq_needed becomes 0xc.

If you play out the rest of this sequence, you should see how Task A
waits for almost two full grace periods.

> Performance changes in consolidated vs regular
> -------------------------------------------
> I ran a thread on a reserved CPU doing preempt disable + busy wait + preempt enable
> in a loop and measured the difference in rcuperf between conslidated and regular.
> nreaders = nwriters = 10.
> 
> 		(preempt disable duration)
> 		5ms	10ms	20ms	50ms
> v4.19
> median (usecs)	12000.3	12001	11000	12000
> 
> v5.1 (deferred)
> median (usecs)	13000	19999   40000   100000
> 
> All of this is still within spec of RCU.
> 
> Note as discussed:
> These results are independent of the value of jiffies_to_sched_qs. However,
> in my preempt-disable + enable loop, if I don't do a
> set_preempt_need_resched() in my loop, then I need to lower
> jiffies_to_sched_qs to bring down the grace period durations. This is
> understandable because the tick may not know sooner that it needs to resched
> the preempt disable busy loop.

Good stuff!  Again, thank you for doing this!!!

							Thanx, Paul