Re: [PATCH 3/7] rcu/trace: Add name of the source for gp_seq

2020-06-18 Thread Joel Fernandes
On Thu, Jun 18, 2020 at 05:12:01PM -0700, Paul E. McKenney wrote:
> On Thu, Jun 18, 2020 at 07:51:17PM -0400, Joel Fernandes wrote:
> > On Thu, Jun 18, 2020 at 03:19:01PM -0700, Paul E. McKenney wrote:
> > > On Thu, Jun 18, 2020 at 04:29:51PM -0400, Joel Fernandes (Google) wrote:
> > > > The gp_seq value can come from either of rdp, rsp or rnp.
> > > > 
> > > > Only the rsp is the global source of truth (most accurate GP info). The
> > > > rnp can be off by ~1 and the rdp can be off by way more. Add some more
> > > > context to traces to clarify where it comes from.
> > > 
> > > This would be better done in scripting that processes the trace messages.
> > > I must pass on this one.
> > 
> > I don't think so. I think people reading traces would get confused.  
> > Recently
> > I had to talk with someone about this as well when going over traces. I
> > myself struggle with it.
> > 
> > > For future reference, the TPS() around strings is not optional.  Without
> > > it, trace messages from crash dumps are garbled, if I remember correctly.
> > 
> > Ok. I will fix that.
> 
> Then please sort this patch after the others.  I am quite unconvinced
> about this one, but some of the others looked quite valuable.

To summarize what's left for me to do right now:

1 and 7 were pulled.
2 - requires the per-cblist counter I'll work on in the near future.
3 - have to add TPS()
4 - The negative number fixes which I'll resend.
5 - changing to gp_seq_req in this tracepoint.
6 - dropping for now and pushing it to a git tag.

So on top of rcu/dev I'll rework 3 and 5, and resend 4.

Please do consider again if we can find a place to 6 :) thanks!

thanks,

 - Joel


> 
>   Thanx, Paul
> 
> > thanks,
> > 
> >  - Joel
> > 
> > > 
> > >   Thanx, Paul
> > > 
> > > > Signed-off-by: Joel Fernandes (Google) 
> > > > ---
> > > >  include/trace/events/rcu.h | 12 
> > > >  kernel/rcu/tree.c  | 32 
> > > >  kernel/rcu/tree_plugin.h   |  2 +-
> > > >  3 files changed, 25 insertions(+), 21 deletions(-)
> > > > 
> > > > diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h
> > > > index a6d49864dcc27..cb5363564f7ed 100644
> > > > --- a/include/trace/events/rcu.h
> > > > +++ b/include/trace/events/rcu.h
> > > > @@ -68,24 +68,28 @@ TRACE_EVENT(rcu_utilization,
> > > >   */
> > > >  TRACE_EVENT_RCU(rcu_grace_period,
> > > >  
> > > > -   TP_PROTO(const char *rcuname, unsigned long gp_seq, const char 
> > > > *gpevent),
> > > > +   TP_PROTO(const char *rcuname, const char *gp_seq_src,
> > > > +   unsigned long gp_seq, const char *gpevent),
> > > >  
> > > > -   TP_ARGS(rcuname, gp_seq, gpevent),
> > > > +   TP_ARGS(rcuname, gp_seq_src, gp_seq, gpevent),
> > > >  
> > > > TP_STRUCT__entry(
> > > > __field(const char *, rcuname)
> > > > +   __field(const char *, gp_seq_src)
> > > > __field(unsigned long, gp_seq)
> > > > __field(const char *, gpevent)
> > > > ),
> > > >  
> > > > TP_fast_assign(
> > > > __entry->rcuname = rcuname;
> > > > +   __entry->gp_seq_src = gp_seq_src;
> > > > __entry->gp_seq = gp_seq;
> > > > __entry->gpevent = gpevent;
> > > > ),
> > > >  
> > > > -   TP_printk("%s %lu %s",
> > > > - __entry->rcuname, __entry->gp_seq, __entry->gpevent)
> > > > +   TP_printk("%s %s_gp_seq=%lu %s",
> > > > + __entry->rcuname, __entry->gp_seq_src,
> > > > + __entry->gp_seq, __entry->gpevent)
> > > >  );
> > > >  
> > > >  /*
> > > > diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> > > > index c61af6a33fbfd..81df1b837dd9d 100644
> > > > --- a/kernel/rcu/tree.c
> > > > +++ b/kernel/rcu/tree.c
> > > > @@ -1334,7 +1334,7 @@ static bool rcu_start_this_gp(struct rcu_node 
> > > > *rnp_start, struct rcu_data *rdp,
> > > > trace_rcu_this_gp(rnp, rdp, gp_seq_req, 
> > > > TPS("NoGPkthread"));
> > > > goto unlock_out;
> > > > }
> > > > -   trace_rcu_grace_period(rcu_state.name, 
> > > > data_race(rcu_state.gp_seq), TPS("newreq"));
> > > > +   trace_rcu_grace_period(rcu_state.name, "rsp", 
> > > > data_race(rcu_state.gp_seq), TPS("newreq"));
> > > > ret = true;  /* Caller must wake GP kthread. */
> > > >  unlock_out:
> > > > /* Push furthest requested GP to leaf node and rcu_data 
> > > > structure. */
> > > > @@ -1437,9 +1437,9 @@ static bool rcu_accelerate_cbs(struct rcu_node 
> > > > *rnp, struct rcu_data *rdp)
> > > >  
> > > > /* Trace depending on how much we were able to accelerate. */
> > > > if (rcu_segcblist_restempty(&rdp->cblist, RCU_WAIT_TAIL))
> > > > -   trace_rcu_grace_period(rcu_state.name, rdp->gp_seq, 
> > > > TPS("AccWaitCB"));
> > > > +

Re: [PATCH 3/7] rcu/trace: Add name of the source for gp_seq

2020-06-18 Thread Joel Fernandes
On Thu, Jun 18, 2020 at 08:01:38PM -0400, Steven Rostedt wrote:
> On Thu, 18 Jun 2020 15:19:01 -0700
> "Paul E. McKenney"  wrote:
> 
> > For future reference, the TPS() around strings is not optional.  Without
> > it, trace messages from crash dumps are garbled, if I remember correctly.
> 
> When you pass in a string like this, only the pointer to the string is
> saved in the ring buffer. User space tools have no idea what those
> pointers are. The TPS() around strings maps those pointers to the
> string and shows them in the /sys/kernel/tracing/printk_formats file,
> such that perf and trace-cmd know how to make sense of those strings.

Makes sense. Quite a valuable feature!

thanks,

 - Joel



Re: [PATCH 3/7] rcu/trace: Add name of the source for gp_seq

2020-06-18 Thread Joel Fernandes
On Thu, Jun 18, 2020 at 05:12:01PM -0700, Paul E. McKenney wrote:
> On Thu, Jun 18, 2020 at 07:51:17PM -0400, Joel Fernandes wrote:
> > On Thu, Jun 18, 2020 at 03:19:01PM -0700, Paul E. McKenney wrote:
> > > On Thu, Jun 18, 2020 at 04:29:51PM -0400, Joel Fernandes (Google) wrote:
> > > > The gp_seq value can come from either of rdp, rsp or rnp.
> > > > 
> > > > Only the rsp is the global source of truth (most accurate GP info). The
> > > > rnp can be off by ~1 and the rdp can be off by way more. Add some more
> > > > context to traces to clarify where it comes from.
> > > 
> > > This would be better done in scripting that processes the trace messages.
> > > I must pass on this one.
> > 
> > I don't think so. I think people reading traces would get confused.  
> > Recently
> > I had to talk with someone about this as well when going over traces. I
> > myself struggle with it.
> > 
> > > For future reference, the TPS() around strings is not optional.  Without
> > > it, trace messages from crash dumps are garbled, if I remember correctly.
> > 
> > Ok. I will fix that.
> 
> Then please sort this patch after the others.  I am quite unconvinced
> about this one, but some of the others looked quite valuable.

Sure sounds good :) will do :) thanks!

 - Joel

>   Thanx, Paul
> 
> > thanks,
> > 
> >  - Joel
> > 
> > > 
> > >   Thanx, Paul
> > > 
> > > > Signed-off-by: Joel Fernandes (Google) 
> > > > ---
> > > >  include/trace/events/rcu.h | 12 
> > > >  kernel/rcu/tree.c  | 32 
> > > >  kernel/rcu/tree_plugin.h   |  2 +-
> > > >  3 files changed, 25 insertions(+), 21 deletions(-)
> > > > 
> > > > diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h
> > > > index a6d49864dcc27..cb5363564f7ed 100644
> > > > --- a/include/trace/events/rcu.h
> > > > +++ b/include/trace/events/rcu.h
> > > > @@ -68,24 +68,28 @@ TRACE_EVENT(rcu_utilization,
> > > >   */
> > > >  TRACE_EVENT_RCU(rcu_grace_period,
> > > >  
> > > > -   TP_PROTO(const char *rcuname, unsigned long gp_seq, const char 
> > > > *gpevent),
> > > > +   TP_PROTO(const char *rcuname, const char *gp_seq_src,
> > > > +   unsigned long gp_seq, const char *gpevent),
> > > >  
> > > > -   TP_ARGS(rcuname, gp_seq, gpevent),
> > > > +   TP_ARGS(rcuname, gp_seq_src, gp_seq, gpevent),
> > > >  
> > > > TP_STRUCT__entry(
> > > > __field(const char *, rcuname)
> > > > +   __field(const char *, gp_seq_src)
> > > > __field(unsigned long, gp_seq)
> > > > __field(const char *, gpevent)
> > > > ),
> > > >  
> > > > TP_fast_assign(
> > > > __entry->rcuname = rcuname;
> > > > +   __entry->gp_seq_src = gp_seq_src;
> > > > __entry->gp_seq = gp_seq;
> > > > __entry->gpevent = gpevent;
> > > > ),
> > > >  
> > > > -   TP_printk("%s %lu %s",
> > > > - __entry->rcuname, __entry->gp_seq, __entry->gpevent)
> > > > +   TP_printk("%s %s_gp_seq=%lu %s",
> > > > + __entry->rcuname, __entry->gp_seq_src,
> > > > + __entry->gp_seq, __entry->gpevent)
> > > >  );
> > > >  
> > > >  /*
> > > > diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> > > > index c61af6a33fbfd..81df1b837dd9d 100644
> > > > --- a/kernel/rcu/tree.c
> > > > +++ b/kernel/rcu/tree.c
> > > > @@ -1334,7 +1334,7 @@ static bool rcu_start_this_gp(struct rcu_node 
> > > > *rnp_start, struct rcu_data *rdp,
> > > > trace_rcu_this_gp(rnp, rdp, gp_seq_req, 
> > > > TPS("NoGPkthread"));
> > > > goto unlock_out;
> > > > }
> > > > -   trace_rcu_grace_period(rcu_state.name, 
> > > > data_race(rcu_state.gp_seq), TPS("newreq"));
> > > > +   trace_rcu_grace_period(rcu_state.name, "rsp", 
> > > > data_race(rcu_state.gp_seq), TPS("newreq"));
> > > > ret = true;  /* Caller must wake GP kthread. */
> > > >  unlock_out:
> > > > /* Push furthest requested GP to leaf node and rcu_data 
> > > > structure. */
> > > > @@ -1437,9 +1437,9 @@ static bool rcu_accelerate_cbs(struct rcu_node 
> > > > *rnp, struct rcu_data *rdp)
> > > >  
> > > > /* Trace depending on how much we were able to accelerate. */
> > > > if (rcu_segcblist_restempty(&rdp->cblist, RCU_WAIT_TAIL))
> > > > -   trace_rcu_grace_period(rcu_state.name, rdp->gp_seq, 
> > > > TPS("AccWaitCB"));
> > > > +   trace_rcu_grace_period(rcu_state.name, "rdp", 
> > > > rdp->gp_seq, TPS("AccWaitCB"));
> > > > else
> > > > -   trace_rcu_grace_period(rcu_state.name, rdp->gp_seq, 
> > > > TPS("AccReadyCB"));
> > > > +   trace_rcu_grace_period(rcu_state.name, "rdp", 
> > > > rdp->gp_seq, TPS("AccReadyCB"));
> > > >  
> > > > /* Count CBs for tracing. */
> > > > r

Re: [PATCH 3/7] rcu/trace: Add name of the source for gp_seq

2020-06-18 Thread Paul E. McKenney
On Thu, Jun 18, 2020 at 07:51:17PM -0400, Joel Fernandes wrote:
> On Thu, Jun 18, 2020 at 03:19:01PM -0700, Paul E. McKenney wrote:
> > On Thu, Jun 18, 2020 at 04:29:51PM -0400, Joel Fernandes (Google) wrote:
> > > The gp_seq value can come from either of rdp, rsp or rnp.
> > > 
> > > Only the rsp is the global source of truth (most accurate GP info). The
> > > rnp can be off by ~1 and the rdp can be off by way more. Add some more
> > > context to traces to clarify where it comes from.
> > 
> > This would be better done in scripting that processes the trace messages.
> > I must pass on this one.
> 
> I don't think so. I think people reading traces would get confused.  Recently
> I had to talk with someone about this as well when going over traces. I
> myself struggle with it.
> 
> > For future reference, the TPS() around strings is not optional.  Without
> > it, trace messages from crash dumps are garbled, if I remember correctly.
> 
> Ok. I will fix that.

Then please sort this patch after the others.  I am quite unconvinced
about this one, but some of the others looked quite valuable.

Thanx, Paul

> thanks,
> 
>  - Joel
> 
> > 
> > Thanx, Paul
> > 
> > > Signed-off-by: Joel Fernandes (Google) 
> > > ---
> > >  include/trace/events/rcu.h | 12 
> > >  kernel/rcu/tree.c  | 32 
> > >  kernel/rcu/tree_plugin.h   |  2 +-
> > >  3 files changed, 25 insertions(+), 21 deletions(-)
> > > 
> > > diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h
> > > index a6d49864dcc27..cb5363564f7ed 100644
> > > --- a/include/trace/events/rcu.h
> > > +++ b/include/trace/events/rcu.h
> > > @@ -68,24 +68,28 @@ TRACE_EVENT(rcu_utilization,
> > >   */
> > >  TRACE_EVENT_RCU(rcu_grace_period,
> > >  
> > > - TP_PROTO(const char *rcuname, unsigned long gp_seq, const char 
> > > *gpevent),
> > > + TP_PROTO(const char *rcuname, const char *gp_seq_src,
> > > + unsigned long gp_seq, const char *gpevent),
> > >  
> > > - TP_ARGS(rcuname, gp_seq, gpevent),
> > > + TP_ARGS(rcuname, gp_seq_src, gp_seq, gpevent),
> > >  
> > >   TP_STRUCT__entry(
> > >   __field(const char *, rcuname)
> > > + __field(const char *, gp_seq_src)
> > >   __field(unsigned long, gp_seq)
> > >   __field(const char *, gpevent)
> > >   ),
> > >  
> > >   TP_fast_assign(
> > >   __entry->rcuname = rcuname;
> > > + __entry->gp_seq_src = gp_seq_src;
> > >   __entry->gp_seq = gp_seq;
> > >   __entry->gpevent = gpevent;
> > >   ),
> > >  
> > > - TP_printk("%s %lu %s",
> > > -   __entry->rcuname, __entry->gp_seq, __entry->gpevent)
> > > + TP_printk("%s %s_gp_seq=%lu %s",
> > > +   __entry->rcuname, __entry->gp_seq_src,
> > > +   __entry->gp_seq, __entry->gpevent)
> > >  );
> > >  
> > >  /*
> > > diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> > > index c61af6a33fbfd..81df1b837dd9d 100644
> > > --- a/kernel/rcu/tree.c
> > > +++ b/kernel/rcu/tree.c
> > > @@ -1334,7 +1334,7 @@ static bool rcu_start_this_gp(struct rcu_node 
> > > *rnp_start, struct rcu_data *rdp,
> > >   trace_rcu_this_gp(rnp, rdp, gp_seq_req, TPS("NoGPkthread"));
> > >   goto unlock_out;
> > >   }
> > > - trace_rcu_grace_period(rcu_state.name, data_race(rcu_state.gp_seq), 
> > > TPS("newreq"));
> > > + trace_rcu_grace_period(rcu_state.name, "rsp", 
> > > data_race(rcu_state.gp_seq), TPS("newreq"));
> > >   ret = true;  /* Caller must wake GP kthread. */
> > >  unlock_out:
> > >   /* Push furthest requested GP to leaf node and rcu_data structure. */
> > > @@ -1437,9 +1437,9 @@ static bool rcu_accelerate_cbs(struct rcu_node 
> > > *rnp, struct rcu_data *rdp)
> > >  
> > >   /* Trace depending on how much we were able to accelerate. */
> > >   if (rcu_segcblist_restempty(&rdp->cblist, RCU_WAIT_TAIL))
> > > - trace_rcu_grace_period(rcu_state.name, rdp->gp_seq, 
> > > TPS("AccWaitCB"));
> > > + trace_rcu_grace_period(rcu_state.name, "rdp", rdp->gp_seq, 
> > > TPS("AccWaitCB"));
> > >   else
> > > - trace_rcu_grace_period(rcu_state.name, rdp->gp_seq, 
> > > TPS("AccReadyCB"));
> > > + trace_rcu_grace_period(rcu_state.name, "rdp", rdp->gp_seq, 
> > > TPS("AccReadyCB"));
> > >  
> > >   /* Count CBs for tracing. */
> > >   rcu_segcblist_countseq(&rdp->cblist, cbs, gps);
> > > @@ -1543,7 +1543,7 @@ static bool __note_gp_changes(struct rcu_node *rnp, 
> > > struct rcu_data *rdp)
> > >   if (!offloaded)
> > >   ret = rcu_advance_cbs(rnp, rdp); /* Advance CBs. */
> > >   rdp->core_needs_qs = false;
> > > - trace_rcu_grace_period(rcu_state.name, rdp->gp_seq, 
> > > TPS("cpuend"));
> > > + trace_rcu_grace_period(rcu_state.name, "rdp", rdp->gp_seq, 
> > > TPS("cpuend"));
> > >   } else {
> > >   if (!offloaded)
> > >   ret = rcu_ac

Re: [PATCH 3/7] rcu/trace: Add name of the source for gp_seq

2020-06-18 Thread Steven Rostedt
On Thu, 18 Jun 2020 15:19:01 -0700
"Paul E. McKenney"  wrote:

> For future reference, the TPS() around strings is not optional.  Without
> it, trace messages from crash dumps are garbled, if I remember correctly.

When you pass in a string like this, only the pointer to the string is
saved in the ring buffer. User space tools have no idea what those
pointers are. The TPS() around strings maps those pointers to the
string and shows them in the /sys/kernel/tracing/printk_formats file,
such that perf and trace-cmd know how to make sense of those strings.

-- Steve


Re: [PATCH 3/7] rcu/trace: Add name of the source for gp_seq

2020-06-18 Thread Joel Fernandes
On Thu, Jun 18, 2020 at 03:19:01PM -0700, Paul E. McKenney wrote:
> On Thu, Jun 18, 2020 at 04:29:51PM -0400, Joel Fernandes (Google) wrote:
> > The gp_seq value can come from either of rdp, rsp or rnp.
> > 
> > Only the rsp is the global source of truth (most accurate GP info). The
> > rnp can be off by ~1 and the rdp can be off by way more. Add some more
> > context to traces to clarify where it comes from.
> 
> This would be better done in scripting that processes the trace messages.
> I must pass on this one.

I don't think so. I think people reading traces would get confused.  Recently
I had to talk with someone about this as well when going over traces. I
myself struggle with it.

> For future reference, the TPS() around strings is not optional.  Without
> it, trace messages from crash dumps are garbled, if I remember correctly.

Ok. I will fix that.

thanks,

 - Joel

> 
>   Thanx, Paul
> 
> > Signed-off-by: Joel Fernandes (Google) 
> > ---
> >  include/trace/events/rcu.h | 12 
> >  kernel/rcu/tree.c  | 32 
> >  kernel/rcu/tree_plugin.h   |  2 +-
> >  3 files changed, 25 insertions(+), 21 deletions(-)
> > 
> > diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h
> > index a6d49864dcc27..cb5363564f7ed 100644
> > --- a/include/trace/events/rcu.h
> > +++ b/include/trace/events/rcu.h
> > @@ -68,24 +68,28 @@ TRACE_EVENT(rcu_utilization,
> >   */
> >  TRACE_EVENT_RCU(rcu_grace_period,
> >  
> > -   TP_PROTO(const char *rcuname, unsigned long gp_seq, const char 
> > *gpevent),
> > +   TP_PROTO(const char *rcuname, const char *gp_seq_src,
> > +   unsigned long gp_seq, const char *gpevent),
> >  
> > -   TP_ARGS(rcuname, gp_seq, gpevent),
> > +   TP_ARGS(rcuname, gp_seq_src, gp_seq, gpevent),
> >  
> > TP_STRUCT__entry(
> > __field(const char *, rcuname)
> > +   __field(const char *, gp_seq_src)
> > __field(unsigned long, gp_seq)
> > __field(const char *, gpevent)
> > ),
> >  
> > TP_fast_assign(
> > __entry->rcuname = rcuname;
> > +   __entry->gp_seq_src = gp_seq_src;
> > __entry->gp_seq = gp_seq;
> > __entry->gpevent = gpevent;
> > ),
> >  
> > -   TP_printk("%s %lu %s",
> > - __entry->rcuname, __entry->gp_seq, __entry->gpevent)
> > +   TP_printk("%s %s_gp_seq=%lu %s",
> > + __entry->rcuname, __entry->gp_seq_src,
> > + __entry->gp_seq, __entry->gpevent)
> >  );
> >  
> >  /*
> > diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> > index c61af6a33fbfd..81df1b837dd9d 100644
> > --- a/kernel/rcu/tree.c
> > +++ b/kernel/rcu/tree.c
> > @@ -1334,7 +1334,7 @@ static bool rcu_start_this_gp(struct rcu_node 
> > *rnp_start, struct rcu_data *rdp,
> > trace_rcu_this_gp(rnp, rdp, gp_seq_req, TPS("NoGPkthread"));
> > goto unlock_out;
> > }
> > -   trace_rcu_grace_period(rcu_state.name, data_race(rcu_state.gp_seq), 
> > TPS("newreq"));
> > +   trace_rcu_grace_period(rcu_state.name, "rsp", 
> > data_race(rcu_state.gp_seq), TPS("newreq"));
> > ret = true;  /* Caller must wake GP kthread. */
> >  unlock_out:
> > /* Push furthest requested GP to leaf node and rcu_data structure. */
> > @@ -1437,9 +1437,9 @@ static bool rcu_accelerate_cbs(struct rcu_node *rnp, 
> > struct rcu_data *rdp)
> >  
> > /* Trace depending on how much we were able to accelerate. */
> > if (rcu_segcblist_restempty(&rdp->cblist, RCU_WAIT_TAIL))
> > -   trace_rcu_grace_period(rcu_state.name, rdp->gp_seq, 
> > TPS("AccWaitCB"));
> > +   trace_rcu_grace_period(rcu_state.name, "rdp", rdp->gp_seq, 
> > TPS("AccWaitCB"));
> > else
> > -   trace_rcu_grace_period(rcu_state.name, rdp->gp_seq, 
> > TPS("AccReadyCB"));
> > +   trace_rcu_grace_period(rcu_state.name, "rdp", rdp->gp_seq, 
> > TPS("AccReadyCB"));
> >  
> > /* Count CBs for tracing. */
> > rcu_segcblist_countseq(&rdp->cblist, cbs, gps);
> > @@ -1543,7 +1543,7 @@ static bool __note_gp_changes(struct rcu_node *rnp, 
> > struct rcu_data *rdp)
> > if (!offloaded)
> > ret = rcu_advance_cbs(rnp, rdp); /* Advance CBs. */
> > rdp->core_needs_qs = false;
> > -   trace_rcu_grace_period(rcu_state.name, rdp->gp_seq, 
> > TPS("cpuend"));
> > +   trace_rcu_grace_period(rcu_state.name, "rdp", rdp->gp_seq, 
> > TPS("cpuend"));
> > } else {
> > if (!offloaded)
> > ret = rcu_accelerate_cbs(rnp, rdp); /* Recent CBs. */
> > @@ -1559,7 +1559,7 @@ static bool __note_gp_changes(struct rcu_node *rnp, 
> > struct rcu_data *rdp)
> >  * set up to detect a quiescent state, otherwise don't
> >  * go looking for one.
> >  */
> > -   trace_rcu_grace_period(rcu_state.name, rnp->gp_seq, 
> > TPS("cpustart"));
> > +   trace_rcu_grace_peri

Re: [PATCH 3/7] rcu/trace: Add name of the source for gp_seq

2020-06-18 Thread Paul E. McKenney
On Thu, Jun 18, 2020 at 04:29:51PM -0400, Joel Fernandes (Google) wrote:
> The gp_seq value can come from either of rdp, rsp or rnp.
> 
> Only the rsp is the global source of truth (most accurate GP info). The
> rnp can be off by ~1 and the rdp can be off by way more. Add some more
> context to traces to clarify where it comes from.

This would be better done in scripting that processes the trace messages.
I must pass on this one.

For future reference, the TPS() around strings is not optional.  Without
it, trace messages from crash dumps are garbled, if I remember correctly.

Thanx, Paul

> Signed-off-by: Joel Fernandes (Google) 
> ---
>  include/trace/events/rcu.h | 12 
>  kernel/rcu/tree.c  | 32 
>  kernel/rcu/tree_plugin.h   |  2 +-
>  3 files changed, 25 insertions(+), 21 deletions(-)
> 
> diff --git a/include/trace/events/rcu.h b/include/trace/events/rcu.h
> index a6d49864dcc27..cb5363564f7ed 100644
> --- a/include/trace/events/rcu.h
> +++ b/include/trace/events/rcu.h
> @@ -68,24 +68,28 @@ TRACE_EVENT(rcu_utilization,
>   */
>  TRACE_EVENT_RCU(rcu_grace_period,
>  
> - TP_PROTO(const char *rcuname, unsigned long gp_seq, const char 
> *gpevent),
> + TP_PROTO(const char *rcuname, const char *gp_seq_src,
> + unsigned long gp_seq, const char *gpevent),
>  
> - TP_ARGS(rcuname, gp_seq, gpevent),
> + TP_ARGS(rcuname, gp_seq_src, gp_seq, gpevent),
>  
>   TP_STRUCT__entry(
>   __field(const char *, rcuname)
> + __field(const char *, gp_seq_src)
>   __field(unsigned long, gp_seq)
>   __field(const char *, gpevent)
>   ),
>  
>   TP_fast_assign(
>   __entry->rcuname = rcuname;
> + __entry->gp_seq_src = gp_seq_src;
>   __entry->gp_seq = gp_seq;
>   __entry->gpevent = gpevent;
>   ),
>  
> - TP_printk("%s %lu %s",
> -   __entry->rcuname, __entry->gp_seq, __entry->gpevent)
> + TP_printk("%s %s_gp_seq=%lu %s",
> +   __entry->rcuname, __entry->gp_seq_src,
> +   __entry->gp_seq, __entry->gpevent)
>  );
>  
>  /*
> diff --git a/kernel/rcu/tree.c b/kernel/rcu/tree.c
> index c61af6a33fbfd..81df1b837dd9d 100644
> --- a/kernel/rcu/tree.c
> +++ b/kernel/rcu/tree.c
> @@ -1334,7 +1334,7 @@ static bool rcu_start_this_gp(struct rcu_node 
> *rnp_start, struct rcu_data *rdp,
>   trace_rcu_this_gp(rnp, rdp, gp_seq_req, TPS("NoGPkthread"));
>   goto unlock_out;
>   }
> - trace_rcu_grace_period(rcu_state.name, data_race(rcu_state.gp_seq), 
> TPS("newreq"));
> + trace_rcu_grace_period(rcu_state.name, "rsp", 
> data_race(rcu_state.gp_seq), TPS("newreq"));
>   ret = true;  /* Caller must wake GP kthread. */
>  unlock_out:
>   /* Push furthest requested GP to leaf node and rcu_data structure. */
> @@ -1437,9 +1437,9 @@ static bool rcu_accelerate_cbs(struct rcu_node *rnp, 
> struct rcu_data *rdp)
>  
>   /* Trace depending on how much we were able to accelerate. */
>   if (rcu_segcblist_restempty(&rdp->cblist, RCU_WAIT_TAIL))
> - trace_rcu_grace_period(rcu_state.name, rdp->gp_seq, 
> TPS("AccWaitCB"));
> + trace_rcu_grace_period(rcu_state.name, "rdp", rdp->gp_seq, 
> TPS("AccWaitCB"));
>   else
> - trace_rcu_grace_period(rcu_state.name, rdp->gp_seq, 
> TPS("AccReadyCB"));
> + trace_rcu_grace_period(rcu_state.name, "rdp", rdp->gp_seq, 
> TPS("AccReadyCB"));
>  
>   /* Count CBs for tracing. */
>   rcu_segcblist_countseq(&rdp->cblist, cbs, gps);
> @@ -1543,7 +1543,7 @@ static bool __note_gp_changes(struct rcu_node *rnp, 
> struct rcu_data *rdp)
>   if (!offloaded)
>   ret = rcu_advance_cbs(rnp, rdp); /* Advance CBs. */
>   rdp->core_needs_qs = false;
> - trace_rcu_grace_period(rcu_state.name, rdp->gp_seq, 
> TPS("cpuend"));
> + trace_rcu_grace_period(rcu_state.name, "rdp", rdp->gp_seq, 
> TPS("cpuend"));
>   } else {
>   if (!offloaded)
>   ret = rcu_accelerate_cbs(rnp, rdp); /* Recent CBs. */
> @@ -1559,7 +1559,7 @@ static bool __note_gp_changes(struct rcu_node *rnp, 
> struct rcu_data *rdp)
>* set up to detect a quiescent state, otherwise don't
>* go looking for one.
>*/
> - trace_rcu_grace_period(rcu_state.name, rnp->gp_seq, 
> TPS("cpustart"));
> + trace_rcu_grace_period(rcu_state.name, "rnp", rnp->gp_seq, 
> TPS("cpustart"));
>   need_qs = !!(rnp->qsmask & rdp->grpmask);
>   rdp->cpu_no_qs.b.norm = need_qs;
>   rdp->core_needs_qs = need_qs;
> @@ -1660,7 +1660,7 @@ static bool rcu_gp_init(void)
>   /* Record GP times before starting GP, hence rcu_seq_start(). */
>   rcu_seq_start(&rcu_state.gp_seq);
>   ASSERT_EXCLUS