Re: [PATCH 5/5 v2] rcu: Fix dyntick-idle tracing

[Paul E. McKenney]

On Fri, Apr 07, 2017 at 10:53:16AM -0400, Steven Rostedt wrote:
> On Fri, 7 Apr 2017 07:40:11 -0700
> "Paul E. McKenney" <paulmck@xxxxxxxxxxxxxxxxxx> wrote:
> 
> > On Fri, Apr 07, 2017 at 10:01:11AM -0400, Steven Rostedt wrote:
> > > From: "Paul E. McKenney" <paulmck@xxxxxxxxxxxxxxxxxx>
> > > 
> > > The tracing subsystem started using rcu_irq_entry() and rcu_irq_exit()
> > > (with my blessing) to allow the current _rcuidle alternative tracepoint
> > > name to be dispensed with while still maintaining good performance.
> > > Unfortunately, this causes RCU's dyntick-idle entry code's tracing to
> > > appear to RCU like an interrupt that occurs where RCU is not designed
> > > to handle interrupts.
> > > 
> > > This commit fixes this problem by moving the zeroing of ->dynticks_nesting
> > > after the offending trace_rcu_dyntick() statement, which narrows the
> > > window of vulnerability to a pair of adjacent statements that are now
> > > marked with comments to that effect.
> > > 
> > > Link: http://lkml.kernel.org/r/20170405193928.GM1600@xxxxxxxxxxxxxxxxxx
> > > 
> > > Reported-by: Steven Rostedt <rostedt@xxxxxxxxxxx>
> > > Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxxxxxxxxxx>
> > > Signed-off-by: Steven Rostedt (VMware) <rostedt@xxxxxxxxxxx>
> > > ---
> > >  kernel/rcu/tree.c | 48 +++++++++++++++++++++++-------------------------
> > >  1 file changed, 23 insertions(+), 25 deletions(-)
> > > 
> > > diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> > > index 50fee7689e71..8b4d273331e4 100644
> > > --- a/kernel/rcu/tree.c
> > > +++ b/kernel/rcu/tree.c
> > > @@ -57,6 +57,7 @@
> > >  #include <linux/random.h>
> > >  #include <linux/trace_events.h>
> > >  #include <linux/suspend.h>
> > > +#include <linux/ftrace.h>
> > > 
> > >  #include "tree.h"
> > >  #include "rcu.h"
> > > @@ -771,25 +772,24 @@ cpu_needs_another_gp(struct rcu_state *rsp, struct rcu_data *rdp)
> > >  }
> > > 
> > >  /*
> > > - * rcu_eqs_enter_common - current CPU is moving towards extended quiescent state
> > > + * rcu_eqs_enter_common - current CPU is entering an extended quiescent state
> > >   *
> > > - * If the new value of the ->dynticks_nesting counter now is zero,
> > > - * we really have entered idle, and must do the appropriate accounting.
> > > - * The caller must have disabled interrupts.
> > > + * Enter idle, doing appropriate accounting.  The caller must have
> > > + * disabled interrupts.
> > >   */
> > > -static void rcu_eqs_enter_common(long long oldval, bool user)
> > > +static void rcu_eqs_enter_common(bool user)
> > >  {
> > >  	struct rcu_state *rsp;
> > >  	struct rcu_data *rdp;
> > > -	RCU_TRACE(struct rcu_dynticks *rdtp = this_cpu_ptr(&rcu_dynticks);)
> > > +	struct rcu_dynticks *rdtp = this_cpu_ptr(&rcu_dynticks);
> > > 
> > > -	trace_rcu_dyntick(TPS("Start"), oldval, rdtp->dynticks_nesting);
> > > +	trace_rcu_dyntick(TPS("Start"), rdtp->dynticks_nesting, 0);
> > >  	if (IS_ENABLED(CONFIG_RCU_EQS_DEBUG) &&
> > >  	    !user && !is_idle_task(current)) {
> > >  		struct task_struct *idle __maybe_unused =
> > >  			idle_task(smp_processor_id());
> > > 
> > > -		trace_rcu_dyntick(TPS("Error on entry: not idle task"), oldval, 0);
> > > +		trace_rcu_dyntick(TPS("Error on entry: not idle task"), rdtp->dynticks_nesting, 0);
> > >  		rcu_ftrace_dump(DUMP_ORIG);
> > >  		WARN_ONCE(1, "Current pid: %d comm: %s / Idle pid: %d comm: %s",
> > >  			  current->pid, current->comm,
> > > @@ -800,7 +800,10 @@ static void rcu_eqs_enter_common(long long oldval, bool user)
> > >  		do_nocb_deferred_wakeup(rdp);
> > >  	}
> > >  	rcu_prepare_for_idle();
> > > -	rcu_dynticks_eqs_enter();
> > > +	stack_tracer_disable();
> > > +	rdtp->dynticks_nesting = 0; /* Breaks tracing momentarily. */
> > > +	rcu_dynticks_eqs_enter(); /* After this, tracing works again. */
> > > +	stack_tracer_enable();  
> > 
> > Hmmm...  There is not supposed to be any tracing in this interval,
> 
> Why not? function tracing happens without an issue. But then again,
> function tracing doesn't depend on RCU.
> 
> > and interrupts are disabled.  Wouldn't it be better to have something
> > that made tracing illegal during this interval?
> 
> I don't see an issue here. Function tracing is fine. There should be no
> trace_events() as those are static events and shouldn't dynamically
> appear in this interval.
> 
> The problem I hit is that stack tracing uses function tracing to check
> the stack of all functions. It doesn't need RCU either, unless it hits
> a new "max stack", which it then calls save_stack_trace(), which does a
> lot, and it does perform an rcu_read_lock(), which is what broke.
> 
> I'm fine with tracing, as that works. What doesn't work is tracing a
> new max stack.
> 
> > 
> > Yeah, I am a bit concerned about idle-entry latency...
> > 
> 
> Which should now be fine because of the inlined this_cpu_inc/dec()
> which is very efficient and made for fast paths like this.

OK, I am willing to let people complain if they can measure the
difference.  If they can measure the difference, there are some things
we can do.

						Thanx, Paul