Re: [PATCH v3 resend 4/6] fs: Move call_rcu() to call_rcu_lazy() in some paths

[Paul E. McKenney]

On Fri, Aug 19, 2022 at 12:30:49PM -0400, Joel Fernandes wrote:
> On 8/18/2022 10:45 PM, Joel Fernandes wrote:
> > On 8/18/2022 10:35 PM, Paul E. McKenney wrote:
> >> On Thu, Aug 18, 2022 at 09:21:56PM -0400, Joel Fernandes wrote:
> >>> On Thu, Aug 18, 2022 at 7:05 PM Joel Fernandes <joel@xxxxxxxxxxxxxxxxx> wrote:
> >>>>
> >>>> On Thu, Aug 18, 2022 at 1:23 PM Joel Fernandes <joel@xxxxxxxxxxxxxxxxx> wrote:
> >>>>>
> >>>>> [Sorry, adding back the CC list]
> >>>>>
> >>>>> On Mon, Aug 8, 2022 at 11:45 PM Joel Fernandes (Google)
> >>>>> <joel@xxxxxxxxxxxxxxxxx> wrote:
> >>>>>>
> >>>>>> This is required to prevent callbacks triggering RCU machinery too
> >>>>>> quickly and too often, which adds more power to the system.
> >>>>>>
> >>>>>> When testing, we found that these paths were invoked often when the
> >>>>>> system is not doing anything (screen is ON but otherwise idle).
> >>>>>
> >>>>> Unfortunately, I am seeing a slow down in ChromeOS boot performance
> >>>>> after applying this particular patch. It is the first time I could
> >>>>> test ChromeOS boot times with the series since it was hard to find a
> >>>>> ChromeOS device that runs the upstream kernel.
> >>>>>
> >>>>> Anyway, Vlad, Neeraj, do you guys also see slower boot times with this
> >>>>> patch? I wonder if the issue is with wake up interaction with the nocb
> >>>>> GP threads.
> >>>>>
> >>>>> We ought to disable lazy RCU during boot since it would have little
> >>>>> benefit anyway. But I am also concerned about some deeper problem I
> >>>>> did not catch before.
> >>>>>
> >>>>> I'll look into tracing the fs paths to see if I can narrow down what's
> >>>>> causing it. Will also try a newer kernel, I am currently testing on
> >>>>> 5.19-rc4.
> >>>>
> >>>> I got somewhere with this. It looks like queuing CBs as lazy CBs
> >>>> instead of normal CBs, are triggering expedited stalls during the boot
> >>>> process:
> >>>>
> >>>>   39.949198] rcu: INFO: rcu_preempt detected expedited stalls on
> >>>> CPUs/tasks: { } 28 jiffies s: 69 root: 0x0/.
> >>>>
> >>>> No idea how/why lazy RCU CBs would be related to expedited GP issues,
> >>>> but maybe something hangs and causes that side-effect.
> >>>>
> >>>> initcall_debug did not help, as it seems initcalls all work fine, and
> >>>> then 8 seconds after the boot, it starts slowing down a lot, followed
> >>>> by the RCU stall messages. As a next step I'll enable ftrace during
> >>>> the boot to see if I can get more insight. But I believe, its not the
> >>>> FS layer, the FS layer just triggers lazy CBs, but there is something
> >>>> wrong with the core lazy-RCU work itself.
> >>>>
> >>>> This kernel is 5.19-rc4. I'll also try to rebase ChromeOS on more
> >>>> recent kernels and debug.
> >>>
> >>> More digging, thanks to trace_event= boot option , I find that the
> >>> boot process does have some synchronous waits, and though these are
> >>> "non-lazy", for some reason the lazy CBs that were previously queued
> >>> are making them wait for the *full* lazy duration. Which points to a
> >>> likely bug in the lazy RCU logic. These synchronous CBs should never
> >>> be waiting like the lazy ones:
> >>>
> >>> [   17.715904]  => trace_dump_stack
> >>> [   17.715904]  => __wait_rcu_gp
> >>> [   17.715904]  => synchronize_rcu
> >>> [   17.715904]  => selinux_netcache_avc_callback
> >>> [   17.715904]  => avc_ss_reset
> >>> [   17.715904]  => sel_write_enforce
> >>> [   17.715904]  => vfs_write
> >>> [   17.715904]  => ksys_write
> >>> [   17.715904]  => do_syscall_64
> >>> [   17.715904]  => entry_SYSCALL_64_after_hwframe
> >>>
> >>> I'm tired so I'll resume the debug later.
> >>
> >> At times like this, I often pull the suspect code into userspace and
> >> run it through its paces.  In this case, a bunch of call_rcu_lazy()
> >> invocations into an empty bypass list, followed by a call_rcu()
> >> invocation, then a check to make sure that the bypass list is no longer
> >> lazy.
> > 
> > Thanks a lot for this great debug idea, I will look into it.
> 
> It seems to be a subtle issue when a large number of callbacks are
> queued trigging the lock-contention code, which happens at boot. It
> appears the non-lazy ones and lazy ones collide, so you have the lazy
> timer which wins, and then the regular bypass lock-contention timer is
> not allowed to do its thing. Due to this, the rcuog thread wakes up much
> later than a jiffie.

Good show, and glad you found it!

> Things are much better with the following change. However, this brings
> me to a question about lock-contention based or any deferring and boot time.
> 
> If you have a path like selinux doing a synchronize_rcu(), shouldn't we
> skip the jiffie waiting for the bypass timer? Otherwise things
> synchronously waiting will slow down more than usual. Maybe bypassing
> should not be done for any case until boot up is done. I'm curious to
> see if that improves boot time.

Why not simply disable laziness at boot time and enable it only after
booting is complete?  The exiting rcupdate.rcu_normal_after_boot kernel
boot parameter uses a similar scheme.

> @@ -580,7 +585,11 @@ static void __call_rcu_nocb_wake(struct rcu_data
> *rdp, bool was_alldone,
>         len = rcu_segcblist_n_cbs(&rdp->cblist);
>         bypass_len = rcu_cblist_n_cbs(&rdp->nocb_bypass);
>         lazy_len = rcu_cblist_n_lazy_cbs(&rdp->nocb_bypass);
> -       if (was_alldone) {
> +
> +       // If we are in lazy-mode, we still need to do a wake up even if
> +       // all CBs were previously done. Otherwise the GP thread will
> +       // wait for the full lazy duration.
> +       if (was_alldone || (READ_ONCE(rdp->nocb_defer_wakeup) ==
> RCU_NOCB_WAKE_LAZY)) {
>                 rdp->qlen_last_fqs_check = len;
>                 // Only lazy CBs in bypass list
>                 if (lazy_len && bypass_len == lazy_len) {

And this change looks plausible, though as always, the system's opinion
carries much more weight than does mine.

							Thanx, Paul