Re: 4.19-rc1: ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!

[Steven Rostedt <rostedt@goodmis.org>]

On Sat, 1 Sep 2018 21:16:39 -0700
"Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:

> On Sat, Sep 01, 2018 at 06:45:31PM -0400, Steven Rostedt wrote:
> > On Sat, 1 Sep 2018 10:54:42 -0700
> > "Paul E. McKenney" <paulmck@linux.vnet.ibm.com> wrote:
> >   
> > > On Sat, Sep 01, 2018 at 07:35:59PM +0200, Borislav Petkov wrote:  
> > > > This is a huge splat! It haz some perf* and sched* in it, I guess for
> > > > peterz to stare at. And lemme add Paul for good measure too :)
> > > > 
> > > > Kernel is -rc1 + 3 microcode loader patches ontop which should not be
> > > > related.    
> > > 
> > > It really is tracing from the idle loop.  But I thought that the event
> > > tracing took care of that.  Adding Steve and Joel for their thoughts.
> > > 
> > > 							Thanx, Paul
> > >   
> > > > Thx.
> > > > 
> > > > ---
> > > > [   62.409125] =============================
> > > > [   62.409129] WARNING: suspicious RCU usage
> > > > [   62.409133] 4.19.0-rc1+ #1 Not tainted
> > > > [   62.409136] -----------------------------
> > > > [   62.409140] ./include/linux/rcupdate.h:631 rcu_read_lock() used illegally while idle!
> > > > [   62.409143] 
> > > >                other info that might help us debug this:
> > > > 
> > > > [   62.409147] 
> > > >                RCU used illegally from idle CPU!
> > > >                rcu_scheduler_active = 2, debug_locks = 1
> > > > [   62.409151] RCU used illegally from extended quiescent state!
> > > > [   62.409155] 1 lock held by swapper/0/0:
> > > > [   62.409158]  #0: 000000004557ee0e (rcu_read_lock){....}, at: perf_event_output_forward+0x0/0x130
> > > > [   62.409175] 
> > > >                stack backtrace:
> > > > [   62.409180] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.0-rc1+ #1
> > > > [   62.409183] Hardware name: LENOVO 2320CTO/2320CTO, BIOS G2ET86WW (2.06 ) 11/13/2012
> > > > [   62.409187] Call Trace:
> > > > [   62.409196]  dump_stack+0x85/0xcb
> > > > [   62.409203]  perf_event_output_forward+0xf6/0x130  
> > 
> > I think this is because we switched the trace point code to be
> > protected by srcu instead of rcu_lock_sched() and a song and dance to
> > "make RCU watch again" if it is not, but perf is using normal
> > rcu_read_lock() internally even though it is hooked into the
> > tracepoint code. Should perf switch to SRCU, or perhaps it can do the
> > song and dance to make RCU watch again?  
> 
> Well, this is a regression, so in theory we could push my three SRCU
> patches into the current merge window, which would allow perf going
> to SRCU, thus fixing the above splat.  I am OK either way.  What would
> you prefer?
> 
>

I wonder if this partial revert will fix things?

-- Steve


diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
index 7f2e16e76ac4..041f7e56a289 100644
--- a/include/linux/tracepoint.h
+++ b/include/linux/tracepoint.h
@@ -158,8 +158,10 @@ extern void syscall_unregfunc(void);
 		 * For rcuidle callers, use srcu since sched-rcu	\
 		 * doesn't work from the idle path.			\
 		 */							\
-		if (rcuidle)						\
+		if (rcuidle) {						\
 			idx = srcu_read_lock_notrace(&tracepoint_srcu);	\
+			rcu_irq_enter_irqson();				\
+		}							\
 									\
 		it_func_ptr = rcu_dereference_raw((tp)->funcs);		\
 									\
@@ -171,8 +173,10 @@ extern void syscall_unregfunc(void);
 			} while ((++it_func_ptr)->func);		\
 		}							\
 									\
-		if (rcuidle)						\
+		if (rcuidle) {						\
+			rcu_irq_exit_irqson();				\
 			srcu_read_unlock_notrace(&tracepoint_srcu, idx);\
+		}							\
 									\
 		preempt_enable_notrace();				\
 	} while (0)