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
