Re: [PATCH -rcu dev 2/2] rcu/dyntick-idle: Add better tracing

From: "Paul E. McKenney" <paulmck@kernel.org>
To: "Joel Fernandes (Google)" <joel@joelfernandes.org>
Cc: linux-kernel@vger.kernel.org, Bjorn Helgaas <bhelgaas@google.com>,
	Ingo Molnar <mingo@redhat.com>,
	Josh Triplett <josh@joshtriplett.org>,
	Lai Jiangshan <jiangshanlai@gmail.com>,
	Mathieu Desnoyers <mathieu.desnoyers@efficios.com>,
	Petr Mladek <pmladek@suse.com>,
	"Rafael J. Wysocki" <rafael.j.wysocki@intel.com>,
	rcu@vger.kernel.org, Steven Rostedt <rostedt@goodmis.org>,
	Yafang Shao <laoar.shao@gmail.com>
Subject: Re: [PATCH -rcu dev 2/2] rcu/dyntick-idle: Add better tracing
Date: Tue, 3 Sep 2019 13:04:46 -0700	[thread overview]
Message-ID: <20190903200446.GE4125@linux.ibm.com> (raw)
In-Reply-To: <20190830162348.192303-2-joel@joelfernandes.org>

On Fri, Aug 30, 2019 at 12:23:48PM -0400, Joel Fernandes (Google) wrote:
> The dyntick-idle traces are a bit confusing. This patch makes it simpler
> and adds some missing cases such as EQS-enter due to user vs idle mode.
> 
> Following are the changes:
> (1) Add a new context field to trace_rcu_dyntick tracepoint. This
>     context field can be "USER", "IDLE" or "IRQ".
> 
> (2) Remove the "++=" and "--=" strings and replace them with
>    "StillNonIdle". This is much easier on the eyes, and the -- and ++
>    are easily apparent in the dynticks_nesting counters we are printing
>    anyway.
> 
> This patch is based on the previous patches to simplify rcu_dyntick
> counters [1] and with these traces, I have verified the counters are
> working properly.
> 
> [1]
> Link: https://lore.kernel.org/patchwork/patch/1120021/
> Link: https://lore.kernel.org/patchwork/patch/1120022/
> 
> Signed-off-by: Joel Fernandes (Google) <joel@joelfernandes.org>

This looks fine, but depends on the earlier patch.

							Thanx, Paul

> ---
>  include/trace/events/rcu.h | 13 ++++++++-----
>  kernel/rcu/tree.c          | 19 +++++++++++++------
>  2 files changed, 21 insertions(+), 11 deletions(-)
> 
> diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h
> index 66122602bd08..474c1f7e7104 100644
> --- a/include/trace/events/rcu.h
> +++ b/include/trace/events/rcu.h
> @@ -449,12 +449,14 @@ TRACE_EVENT_RCU(rcu_fqs,
>   */
>  TRACE_EVENT_RCU(rcu_dyntick,
>  
> -	TP_PROTO(const char *polarity, long oldnesting, long newnesting, atomic_t dynticks),
> +	TP_PROTO(const char *polarity, const char *context, long oldnesting,
> +		 long newnesting, atomic_t dynticks),
>  
> -	TP_ARGS(polarity, oldnesting, newnesting, dynticks),
> +	TP_ARGS(polarity, context, oldnesting, newnesting, dynticks),
>  
>  	TP_STRUCT__entry(
>  		__field(const char *, polarity)
> +		__field(const char *, context)
>  		__field(long, oldnesting)
>  		__field(long, newnesting)
>  		__field(int, dynticks)
> @@ -462,14 +464,15 @@ TRACE_EVENT_RCU(rcu_dyntick,
>  
>  	TP_fast_assign(
>  		__entry->polarity = polarity;
> +		__entry->context = context;
>  		__entry->oldnesting = oldnesting;
>  		__entry->newnesting = newnesting;
>  		__entry->dynticks = atomic_read(&dynticks);
>  	),
>  
> -	TP_printk("%s %lx %lx %#3x", __entry->polarity,
> -		  __entry->oldnesting, __entry->newnesting,
> -		  __entry->dynticks & 0xfff)
> +	TP_printk("%s %s %lx %lx %#3x", __entry->polarity,
> +		__entry->context, __entry->oldnesting, __entry->newnesting,
> +		__entry->dynticks & 0xfff)
>  );
>  
>  /*
> diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> index 417dd00b9e87..463407762b5a 100644
> --- a/kernel/rcu/tree.c
> +++ b/kernel/rcu/tree.c
> @@ -533,7 +533,8 @@ static void rcu_eqs_enter(bool user)
>  	}
>  
>  	lockdep_assert_irqs_disabled();
> -	trace_rcu_dyntick(TPS("Start"), rdp->dynticks_nesting, 0, rdp->dynticks);
> +	trace_rcu_dyntick(TPS("Start"), (user ? TPS("USER") : TPS("IDLE")),
> +			  rdp->dynticks_nesting, 0, rdp->dynticks);
>  	WARN_ON_ONCE(IS_ENABLED(CONFIG_RCU_EQS_DEBUG) && !user && !is_idle_task(current));
>  	rdp = this_cpu_ptr(&rcu_data);
>  	do_nocb_deferred_wakeup(rdp);
> @@ -606,14 +607,17 @@ static __always_inline void rcu_nmi_exit_common(bool irq)
>  	 * leave it in non-RCU-idle state.
>  	 */
>  	if (rdp->dynticks_nmi_nesting != 1) {
> -		trace_rcu_dyntick(TPS("--="), rdp->dynticks_nmi_nesting, rdp->dynticks_nmi_nesting - 2, rdp->dynticks);
> +		trace_rcu_dyntick(TPS("StillNonIdle"), TPS("IRQ"),
> +				  rdp->dynticks_nmi_nesting,
> +				  rdp->dynticks_nmi_nesting - 2, rdp->dynticks);
>  		WRITE_ONCE(rdp->dynticks_nmi_nesting, /* No store tearing. */
>  			   rdp->dynticks_nmi_nesting - 2);
>  		return;
>  	}
>  
>  	/* This NMI interrupted an RCU-idle CPU, restore RCU-idleness. */
> -	trace_rcu_dyntick(TPS("Startirq"), rdp->dynticks_nmi_nesting, 0, rdp->dynticks);
> +	trace_rcu_dyntick(TPS("Start"), TPS("IRQ"), rdp->dynticks_nmi_nesting,
> +			  0, rdp->dynticks);
>  	WRITE_ONCE(rdp->dynticks_nmi_nesting, 0); /* Avoid store tearing. */
>  
>  	if (irq)
> @@ -700,7 +704,8 @@ static void rcu_eqs_exit(bool user)
>  	rcu_dynticks_task_exit();
>  	rcu_dynticks_eqs_exit();
>  	rcu_cleanup_after_idle();
> -	trace_rcu_dyntick(TPS("End"), rdp->dynticks_nesting, 1, rdp->dynticks);
> +	trace_rcu_dyntick(TPS("End"), (user ? TPS("USER") : TPS("IDLE")),
> +			  rdp->dynticks_nesting, 1, rdp->dynticks);
>  	WARN_ON_ONCE(IS_ENABLED(CONFIG_RCU_EQS_DEBUG) && !user && !is_idle_task(current));
>  	WRITE_ONCE(rdp->dynticks_nesting, 1);
>  	WARN_ON_ONCE(rdp->dynticks_nmi_nesting);
> @@ -787,9 +792,11 @@ static __always_inline void rcu_nmi_enter_common(bool irq)
>  		rdp->rcu_forced_tick = true;
>  		tick_dep_set_cpu(rdp->cpu, TICK_DEP_BIT_RCU);
>  	}
> -	trace_rcu_dyntick(incby == 1 ? TPS("Endirq") : TPS("++="),
> -			  rdp->dynticks_nmi_nesting,
> +
> +	trace_rcu_dyntick(incby == 1 ? TPS("End") : TPS("StillNonIdle"),
> +			  TPS("IRQ"), rdp->dynticks_nmi_nesting,
>  			  rdp->dynticks_nmi_nesting + incby, rdp->dynticks);
> +
>  	WRITE_ONCE(rdp->dynticks_nmi_nesting, /* Prevent store tearing. */
>  		   rdp->dynticks_nmi_nesting + incby);
>  	barrier();
> -- 
> 2.23.0.187.g17f5b7556c-goog
> 