Re: WARNING: at kernel/rcutree.c:388 rcu_eqs_enter

["Paul E. McKenney" <paulmck@linux.vnet.ibm.com>]

On Thu, May 23, 2013 at 11:51:52AM -0400, Dave Jones wrote:
> On Wed, May 22, 2013 at 02:51:29AM -0700, Paul E. McKenney wrote:
> 
>  > trace: Allow idle-safe tracepoints to be called from irq
>  > 
>  > __DECLARE_TRACE_RCU() currently creates an _rcuidle() tracepoint which
>  > may safely be invoked from what RCU considers to be an idle CPU.
>  > However, these _rcuidle() tracepoints may -not- be invoked from the
>  > handler of an irq taken from idle, because rcu_idle_enter() zeroes
>  > RCU's nesting-level counter, so that the rcu_irq_exit() returning to
>  > idle will trigger a WARN_ON_ONCE().
>  > 
>  > This commit therefore substitutes rcu_irq_enter() for rcu_idle_exit()
>  > and rcu_irq_exit() for rcu_idle_enter() in order to make the _rcuidle()
>  > tracepoints usable from irq handlers as well as from process context.
>  > 
>  > Reported-by: Dave Jones <davej@redhat.com>
>  > Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
>  > Cc: Steven Rostedt <rostedt@goodmis.org>
>  > 
>  > diff --git a/include/linux/tracepoint.h b/include/linux/tracepoint.h
>  > index 2f322c3..f8e084d 100644
>  > --- a/include/linux/tracepoint.h
>  > +++ b/include/linux/tracepoint.h
>  > @@ -145,8 +145,8 @@ static inline void tracepoint_synchronize_unregister(void)
>  >  				TP_PROTO(data_proto),			\
>  >  				TP_ARGS(data_args),			\
>  >  				TP_CONDITION(cond),			\
>  > -				rcu_idle_exit(),			\
>  > -				rcu_idle_enter());			\
>  > +				rcu_irq_enter(),			\
>  > +				rcu_irq_exit());			\
>  >  	}
>  >  #else
>  >  #define __DECLARE_TRACE_RCU(name, proto, args, cond, data_proto, data_args)
> 
> This stops the "WARNING: at kernel/context_tracking.c:55 user_enter+0xb5/0xd0()"
> but I still see..

Thank you for testing this!

This is the same one that you and Steven Rostedt are discussing, correct?

							Thanx, Paul

> [  363.399348] ===============================
> [  363.400617] [ INFO: suspicious RCU usage. ]
> [  363.401880] 3.10.0-rc2+ #31 Not tainted
> [  363.403210] -------------------------------
> [  363.403787] include/linux/rcupdate.h:771 rcu_read_lock() used illegally while idle!
> [  363.403831] 
> other info that might help us debug this:
> 
> [  363.403880] 
> RCU used illegally from idle CPU!
> rcu_scheduler_active = 1, debug_locks = 0
> [  363.403942] RCU used illegally from extended quiescent state!
> [  363.403976] 2 locks held by trinity-child0/27319:
> [  363.404006]  #0:  (&rq->lock){-.-.-.}, at: [<ffffffff816e91bf>] __schedule+0xef/0x9c0
> [  363.404076]  #1:  (rcu_read_lock){.+.+..}, at: [<ffffffff810a5605>] cpuacct_charge+0x5/0x1f0
> [  363.404146] 
> stack backtrace:
> [  363.404176] CPU: 1 PID: 27319 Comm: trinity-child0 Not tainted 3.10.0-rc2+ #31 
> [  363.405536]  0000000000000000 ffff880208ddfcf8 ffffffff816e2a5b ffff880208ddfd28
> [  363.406835]  ffffffff810b5917 ffff880243362568 00000000003c3c18 ffff880243362520
> [  363.408140]  0000000000000001 ffff880208ddfd60 ffffffff810a5785 ffffffff810a5605
> [  363.409451] Call Trace:
> [  363.410726]  [<ffffffff816e2a5b>] dump_stack+0x19/0x1b
> [  363.412005]  [<ffffffff810b5917>] lockdep_rcu_suspicious+0xe7/0x120
> [  363.413281]  [<ffffffff810a5785>] cpuacct_charge+0x185/0x1f0
> [  363.414543]  [<ffffffff810a5605>] ? cpuacct_charge+0x5/0x1f0
> [  363.415793]  [<ffffffff8109607c>] update_curr+0xec/0x250
> [  363.417035]  [<ffffffff810975a8>] put_prev_task_fair+0x228/0x480
> [  363.418273]  [<ffffffff816e9236>] __schedule+0x166/0x9c0
> [  363.419497]  [<ffffffff816e9ee4>] preempt_schedule+0x44/0x60
> [  363.420717]  [<ffffffff816e9fb0>] ? __cond_resched_softirq+0x60/0x60
> [  363.421940]  [<ffffffff816ebfa4>] ? retint_careful+0x12/0x2e
> [  363.423155]  [<ffffffff8110e2b3>] ftrace_ops_control_func+0x1d3/0x210
> [  363.424373]  [<ffffffff816f3a40>] ftrace_call+0x5/0x2f
> [  363.425577]  [<ffffffff816ebf9d>] ? retint_careful+0xb/0x2e
> [  363.426784]  [<ffffffff816e9fb5>] ? schedule_user+0x5/0x70
> [  363.427988]  [<ffffffff816e9fb5>] ? schedule_user+0x5/0x70
> [  363.429184]  [<ffffffff816ebfa4>] ? retint_careful+0x12/0x2e
> 
> I'll try Steve's patch on top next.
> 
> 	Dave
>