On Fri, Oct 7, 2022 at 3:56 PM Paul E. McKenney <paulmck@xxxxxxxxxx> wrote:
[..]
> > > > > [ 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)
> > > > >
[..]
> > > > > + 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.
>
> Very good, and thank you for doing this!
Thanks.
> Maybe include the script in the cover letter of the next version?
Good idea, thanks, I will do so.
- Joel
>
> Thanx, Paul
>
> > ---8<-----------------------
> >
> > From: "Joel Fernandes (Google)" <joel@xxxxxxxxxxxxxxxxx>
> > 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@xxxxxxxxxxxxxxxxx>
> > ---
> > 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
> >
