Re: [PATCH tip/core/rcu 5/7] torture: Trace long read-side delays

[Paul E. McKenney]

On Mon, Nov 14, 2016 at 09:21:10AM -0800, Josh Triplett wrote:
> On Mon, Nov 14, 2016 at 08:57:11AM -0800, Paul E. McKenney wrote:
> > Although rcutorture will occasionally do a 50-millisecond grace-period
> > delay, these delays are quite rare.  And rightly so, because otherwise
> > the read rate would be quite low.  Thie means that it can be important
> > to identify whether or not a given run contained a long-delay read.
> > This commit therefore inserts a trace_rcu_torture_read() event to flag
> > runs containing long delays.
> > 
> > Signed-off-by: Paul E. McKenney <paulmck@xxxxxxxxxxxxxxxxxx>
> 
> A couple of apparent typos below.  With those fixed:
> Reviewed-by: Josh Triplett <josh@xxxxxxxxxxxxxxxx>
> 
> >  include/trace/events/rcu.h |  5 ++++-
> >  kernel/rcu/rcutorture.c    | 11 ++++++++++-
> >  2 files changed, 14 insertions(+), 2 deletions(-)
> > 
> > diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h
> > index d3e756539d44..b31e05bc8e26 100644
> > --- a/include/trace/events/rcu.h
> > +++ b/include/trace/events/rcu.h
> > @@ -698,7 +698,10 @@ TRACE_EVENT(rcu_batch_end,
> >  /*
> >   * Tracepoint for rcutorture readers.  The first argument is the name
> >   * of the RCU flavor from rcutorture's viewpoint and the second argument
> > - * is the callback address.
> > + * is the callback address.  The third callback is the start time in
> > + * seconds, and the last two arguments are the grace period numbers
> > + * and the beginning and end of the read, respectively.  Note that the
> > + * callback address can be NULL.
> 
> s/third callback/third argument/?

Good catch, fixed!

> Also, s/and the beginning/of the beginning/?

Let's see...  "the last two arguments are the grace period numbers and
the beginning and end of the read, respectively."  -ENONSENSE for sure.

I believe that the "and" needs to become "at" as follows:

"the last two arguments are the grace period numbers at the beginning
and end of the read, respectively."

Does that help?

							Thanx, Paul

> >  TRACE_EVENT(rcu_torture_read,
> >  
> > diff --git a/kernel/rcu/rcutorture.c b/kernel/rcu/rcutorture.c
> > index bf08fee53dc7..87c51225ceec 100644
> > --- a/kernel/rcu/rcutorture.c
> > +++ b/kernel/rcu/rcutorture.c
> > @@ -289,15 +289,24 @@ static int rcu_torture_read_lock(void) __acquires(RCU)
> >  
> >  static void rcu_read_delay(struct torture_random_state *rrsp)
> >  {
> > +	unsigned long started;
> > +	unsigned long completed;
> >  	const unsigned long shortdelay_us = 200;
> >  	const unsigned long longdelay_ms = 50;
> > +	unsigned long long ts;
> >  
> >  	/* We want a short delay sometimes to make a reader delay the grace
> >  	 * period, and we want a long delay occasionally to trigger
> >  	 * force_quiescent_state. */
> >  
> > -	if (!(torture_random(rrsp) % (nrealreaders * 2000 * longdelay_ms)))
> > +	if (!(torture_random(rrsp) % (nrealreaders * 2000 * longdelay_ms))) {
> > +		started = cur_ops->completed();
> > +		ts = rcu_trace_clock_local();
> >  		mdelay(longdelay_ms);
> > +		completed = cur_ops->completed();
> > +		do_trace_rcu_torture_read(cur_ops->name, NULL, ts,
> > +					  started, completed);
> > +	}
> >  	if (!(torture_random(rrsp) % (nrealreaders * 2 * shortdelay_us)))
> >  		udelay(shortdelay_us);
> >  #ifdef CONFIG_PREEMPT
> > -- 
> > 2.5.2
> > 
>