Message-ID: <fa8b7857-b9fd-72ad-36a7-8b09e4472816@joelfernandes.org>
Date:   Fri, 19 Aug 2022 14:14:46 -0400
From:   Joel Fernandes <joel@...lfernandes.org>
To:     paulmck@...nel.org
Cc:     LKML <linux-kernel@...r.kernel.org>,
        Rushikesh S Kadam <rushikesh.s.kadam@...el.com>,
        "Uladzislau Rezki (Sony)" <urezki@...il.com>,
        Neeraj upadhyay <neeraj.iitr10@...il.com>,
        Frederic Weisbecker <frederic@...nel.org>,
        Steven Rostedt <rostedt@...dmis.org>, rcu <rcu@...r.kernel.org>
Subject: Re: [PATCH v3 resend 4/6] fs: Move call_rcu() to call_rcu_lazy() in
 some paths



On 8/19/2022 1:12 PM, Paul E. McKenney wrote:
> 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@...lfernandes.org> wrote:
>>>>>>
>>>>>> On Thu, Aug 18, 2022 at 1:23 PM Joel Fernandes <joel@...lfernandes.org> wrote:
>>>>>>>
>>>>>>> [Sorry, adding back the CC list]
>>>>>>>
>>>>>>> On Mon, Aug 8, 2022 at 11:45 PM Joel Fernandes (Google)
>>>>>>> <joel@...lfernandes.org> 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!

Thanks!

>> 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.

That sounds like the right thing to good, but unfortunately it wont help
this problem. The boot time issue happens after init has started. So the
OS is still "booting" even though the kernel has.

Also the problem can happen after boot as well, like if RCU
lazy/non-lazy callbacks come back to back quickly, or so.

But yes nonetheless, I can see the value of disabling it till the
in-kernel boot completets.

>> @@ -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.

Sounds good, thanks, I am testing it more. Will update it for v4.

Thanks,

 - Joel

Powered by blists - more mailing lists