From: Joel Fernandes <joel@joelfernandes.org>
To: "Paul E. McKenney" <paulmck@kernel.org>
Cc: rcu@vger.kernel.org, linux-kernel@vger.kernel.org,
rushikesh.s.kadam@intel.com, urezki@gmail.com,
neeraj.iitr10@gmail.com, frederic@kernel.org,
rostedt@goodmis.org, youssefesmat@google.com, surenb@google.com
Subject: Re: [PATCH v7 10/11] scsi/scsi_error: Use call_rcu_flush() instead of call_rcu()
Date: Fri, 7 Oct 2022 19:29:14 +0000 [thread overview]
Message-ID: <Y0B+CqZVP3bqQyn5@google.com> (raw)
In-Reply-To: <20221007175208.GI4196@paulmck-ThinkPad-P17-Gen-1>
On Fri, Oct 07, 2022 at 10:52:08AM -0700, Paul E. McKenney wrote:
> On Fri, Oct 07, 2022 at 01:31:23PM -0400, Joel Fernandes wrote:
> >
> >
> > > On Oct 7, 2022, at 1:19 PM, Joel Fernandes <joel@joelfernandes.org> wrote:
> > >
> > > On Fri, Oct 07, 2022 at 03:18:26AM +0000, Joel Fernandes wrote:
> > >>> On Tue, Oct 04, 2022 at 02:41:56AM +0000, Joel Fernandes (Google) wrote:
> > >>> From: Uladzislau Rezki <urezki@gmail.com>
> > >>>
> > >>> Slow boot time is seen on KVM running typical Linux distributions due to
> > >>> SCSI layer calling call_rcu(). Recent changes to save power may be
> > >>> causing this slowness. Using call_rcu_flush() fixes the issue and brings
> > >>> the boot time back to what it originally was. Convert it.
> > >>>
> > >>> Signed-off-by: Uladzislau Rezki <urezki@gmail.com>
> > >>> Signed-off-by: Joel Fernandes (Google) <joel@joelfernandes.org>
> > >>
> > >> And I successfully setup Debian on KVM and verified that this fixes it, so
> > >> now I have a nice reproducible rig for my
> > >> 'lazy-callback-doing-a-wakeup-detector' (I wrote half the detector thanks to
> > >> ideas from Steve, and will finish the other half tomorrow or so).
> > >>
> > >> Tested-by: Joel Fernandes (Google) <joel@joelfernandes.org>
> > >
> > > Looks like I can catch Vlad's issue with the below patch. Thoughts? Does this
> > > look reasonable for mainline? (I think so as it is self-contained and the
> > > debug option is default off, and could be useful down the line).
>
> Excellent as a debug patch!!! Let's see how it goes -- if it proves
> sufficiently useful, some form should go into mainline. Or at least
> be feature prominently somewhere public.
Ok that sounds good.
> > > [ 6.887033 ] rcu: *****************************************************
> > > [ 6.891242 ] rcu: RCU: A wake up has been detected from a lazy callback!
> > > [ 6.895377 ] rcu: The callback name is: scsi_eh_inc_host_failed
> > > [ 6.899084 ] rcu: The task it woke up is: scsi_eh_1 (61)
> > > [ 6.902405 ] rcu: This could cause performance issues! Check the stack.
> > > [ 6.906532 ] rcu: *****************************************************
> > >
> > >
> > > [ 17.127128 ] rcu: *****************************************************
> > > [ 17.131397 ] rcu: RCU: A wake up has been detected from a lazy callback!
> > > [ 17.135703 ] rcu: The callback name is: scsi_eh_inc_host_failed
> > > [ 17.139485 ] rcu: The task it woke up is: scsi_eh_1 (61)
> > > [ 17.142828 ] rcu: This could cause performance issues! Check the stack.
> > > [ 17.146962 ] rcu: *****************************************************
> > >
> > > And thanks to Steve for the binary search code.
> > >
> > > One thing I found is I have to ignore kworkers because there are times when a
> > > work item is queued from a callback and those callbacks don't seem to
> > > contribute to performance issues. So I am filtering these:
> > >
> > > [ 38.631724 ] rcu: The callback name is: thread_stack_free_rcu
> > > [ 38.635317 ] rcu: The task it woke up is: kworker/3:2 (143)
> > >
> > > [ 39.649332 ] rcu: The callback name is: delayed_put_task_struct
> > > [ 39.653037 ] rcu: The task it woke up is: kworker/0:1 (40)
> > >
> > > ---8<-----------------------
> > >
> > > From: "Joel Fernandes (Google)" <joel@joelfernandes.org>
> > > Subject: [PATCH] lazy wake debug
> > >
> > > Signed-off-by: Joel Fernandes (Google) <joel@joelfernandes.org>
> > > ---
> > > kernel/rcu/Kconfig | 7 ++
> > > kernel/rcu/lazy-debug.h | 149 ++++++++++++++++++++++++++++++++++++++++
> > > kernel/rcu/tree.c | 9 +++
> > > 3 files changed, 165 insertions(+)
> > > create mode 100644 kernel/rcu/lazy-debug.h
> > >
> > > diff --git a/kernel/rcu/Kconfig b/kernel/rcu/Kconfig
> > > index edd632e68497..08c06f739187 100644
> > > --- a/kernel/rcu/Kconfig
> > > +++ b/kernel/rcu/Kconfig
> > > @@ -322,4 +322,11 @@ config RCU_LAZY
> > > To save power, batch RCU callbacks and flush after delay, memory
> > > pressure or callback list growing too big.
> > >
> > > +config RCU_LAZY_DEBUG
> > > + bool "RCU callback lazy invocation debugging"
> > > + depends on RCU_LAZY
> > > + default n
> > > + help
> > > + Debugging to catch issues caused by delayed RCU callbacks.
> > > +
> > > endmenu # "RCU Subsystem"
> > > diff --git a/kernel/rcu/lazy-debug.h b/kernel/rcu/lazy-debug.h
> > > new file mode 100644
> > > index 000000000000..fc1cc1cb89f0
> > > --- /dev/null
> > > +++ b/kernel/rcu/lazy-debug.h
> > > @@ -0,0 +1,149 @@
> > > +#include <linux/string.h>
> > > +#include <linux/spinlock.h>
> > > +
> > > +#ifdef CONFIG_RCU_LAZY_DEBUG
> > > +#include <linux/preempt.h>
> > > +#include <trace/events/sched.h>
> > > +
> > > +static DEFINE_PER_CPU(bool, rcu_lazy_cb_exec) = false;
> > > +static DEFINE_PER_CPU(void *, rcu_lazy_ip) = NULL;
> > > +
> > > +static DEFINE_RAW_SPINLOCK(lazy_funcs_lock);
> > > +
> > > +#define FUNC_SIZE 1024
> >
> > And I know this array can overflow in the future so I will add checks for that in the code if we are going with this patch.
>
> I believe that there are fewer than 300 RCU callback functions, but yes,
> there would need to at least be a check at some point.
>
> I still strongly suggest the static search in addition to this. Yes, this
> is a cool patch, but it should be mostly used for the difficult-to-find
> instances.
I wrote some scripts shared below (could be improves) which search for "wake"
in code following an RCU callback's reference. This catches SCSI too but I
did find one more:
(1)
rxrpc_destroy_connection()
which does:
wake_up_var(&conn->params.local->rxnet->nr_conns);
I think I'll change this to call_rcu_flush() to be safe.
========
All others are harmless / false-positives which I inspected and didn't have
anything concerning.
---8<-----------------------
From: "Joel Fernandes (Google)" <joel@joelfernandes.org>
Subject: [PATCH] debug: look for wake references after rcu callback body
First run search-call-rcu.sh which generates some files, then run
search-wakers.sh to see the references to wake.
Signed-off-by: Joel Fernandes (Google) <joel@joelfernandes.org>
---
search-call-rcu.sh | 19 +++++++++++++++++++
search-wakers.sh | 15 +++++++++++++++
2 files changed, 34 insertions(+)
create mode 100755 search-call-rcu.sh
create mode 100755 search-wakers.sh
diff --git a/search-call-rcu.sh b/search-call-rcu.sh
new file mode 100755
index 000000000000..21406355888c
--- /dev/null
+++ b/search-call-rcu.sh
@@ -0,0 +1,19 @@
+#!/bin/bash
+
+rm func-list
+touch func-list
+
+for f in $(find . \( -name "*.c" -o -name "*.h" \) | grep -v rcu); do
+
+ funcs=$(perl -0777 -ne 'while(m/call_rcu\([&]?.+,\s?(.+)\).*;/g){print "$1\n";}' $f)
+
+ if [ "x$funcs" != "x" ]; then
+ for func in $funcs; do
+ echo "$f $func" >> func-list
+ echo "$f $func"
+ done
+ fi
+
+done
+
+cat func-list | sort | uniq | tee func-list-sorted
diff --git a/search-wakers.sh b/search-wakers.sh
new file mode 100755
index 000000000000..a96d60a7e16b
--- /dev/null
+++ b/search-wakers.sh
@@ -0,0 +1,15 @@
+#!/bin/bash
+
+while read fl; do
+ file=$(echo $fl | cut -d " " -f1)
+ func=$(echo $fl | cut -d " " -f2)
+
+ grep -A 30 $func $file | grep wake > /dev/null
+
+ if [ $? -eq 0 ]; then
+ echo "keyword wake found after function reference $func in $file"
+ echo "Output:"
+ grep -A 30 $func $file
+ echo "==========================================================="
+ fi
+done < func-list-sorted
--
2.38.0.rc1.362.ged0d419d3c-goog
next prev parent reply other threads:[~2022-10-07 19:29 UTC|newest]
Thread overview: 45+ messages / expand[flat|nested] mbox.gz Atom feed top
2022-10-04 2:41 [PATCH v7 00/11] rcu: call_rcu() power improvements Joel Fernandes (Google)
2022-10-04 2:41 ` [PATCH v7 01/11] rcu: Wake up nocb gp thread on rcu_barrier_entrain() Joel Fernandes (Google)
2022-10-04 22:28 ` Frederic Weisbecker
2022-10-04 22:57 ` Joel Fernandes
2022-10-05 10:39 ` Frederic Weisbecker
2022-10-07 2:47 ` Joel Fernandes
2022-10-07 11:26 ` Frederic Weisbecker
2022-10-07 12:46 ` Joel Fernandes
2022-10-04 2:41 ` [PATCH v7 02/11] rcu: Make call_rcu() lazy to save power Joel Fernandes (Google)
2022-10-04 11:41 ` Uladzislau Rezki
2022-10-04 13:30 ` Paul E. McKenney
2022-10-04 14:53 ` Uladzislau Rezki
2022-10-04 15:58 ` Paul E. McKenney
2022-10-04 16:20 ` Uladzislau Rezki
2022-10-04 18:27 ` Paul E. McKenney
2022-10-05 11:28 ` Uladzislau Rezki
2022-10-04 16:22 ` Joel Fernandes
2022-10-04 18:05 ` Joel Fernandes
2022-10-05 11:21 ` Uladzislau Rezki
2022-10-05 11:44 ` Uladzislau Rezki
2022-10-06 19:11 ` Paul E. McKenney
2022-10-11 17:44 ` Joel Fernandes
2022-10-04 2:41 ` [PATCH v7 03/11] rcu: Refactor code a bit in rcu_nocb_do_flush_bypass() Joel Fernandes (Google)
2022-10-06 19:12 ` Paul E. McKenney
2022-10-04 2:41 ` [PATCH v7 04/11] rcu: shrinker for lazy rcu Joel Fernandes (Google)
2022-10-04 2:41 ` [PATCH v7 05/11] rcuscale: Add laziness and kfree tests Joel Fernandes (Google)
2022-10-06 19:15 ` Paul E. McKenney
2022-10-04 2:41 ` [PATCH v7 06/11] percpu-refcount: Use call_rcu_flush() for atomic switch Joel Fernandes (Google)
2022-10-04 2:41 ` [PATCH v7 07/11] rcu/sync: Use call_rcu_flush() instead of call_rcu Joel Fernandes (Google)
2022-10-04 2:41 ` [PATCH v7 08/11] rcu/rcuscale: Use call_rcu_flush() for async reader test Joel Fernandes (Google)
2022-10-04 2:41 ` [PATCH v7 09/11] rcu/rcutorture: Use call_rcu_flush() where needed Joel Fernandes (Google)
2022-10-04 2:41 ` [PATCH v7 10/11] scsi/scsi_error: Use call_rcu_flush() instead of call_rcu() Joel Fernandes (Google)
2022-10-07 3:18 ` Joel Fernandes
2022-10-07 17:19 ` Joel Fernandes
2022-10-07 17:31 ` Joel Fernandes
2022-10-07 17:52 ` Paul E. McKenney
2022-10-07 19:29 ` Joel Fernandes [this message]
2022-10-07 19:56 ` Paul E. McKenney
2022-10-07 20:24 ` Joel Fernandes
2022-10-04 2:41 ` [PATCH v7 11/11] workqueue: Make queue_rcu_work() use call_rcu_flush() Joel Fernandes (Google)
2022-10-06 18:55 ` [PATCH v7 00/11] rcu: call_rcu() power improvements Paul E. McKenney
2022-10-07 14:40 ` Uladzislau Rezki
2022-10-07 14:54 ` Paul E. McKenney
2022-10-07 15:09 ` Joel Fernandes
2022-10-07 18:30 ` Paul E. McKenney
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=Y0B+CqZVP3bqQyn5@google.com \
--to=joel@joelfernandes.org \
--cc=frederic@kernel.org \
--cc=linux-kernel@vger.kernel.org \
--cc=neeraj.iitr10@gmail.com \
--cc=paulmck@kernel.org \
--cc=rcu@vger.kernel.org \
--cc=rostedt@goodmis.org \
--cc=rushikesh.s.kadam@intel.com \
--cc=surenb@google.com \
--cc=urezki@gmail.com \
--cc=youssefesmat@google.com \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).