Re: [PATCH 2/3] nfsd: new tracepoint for check_slot_seqid

[Jeff Layton]

On Fri, 2024-04-05 at 15:03 -0400, Chuck Lever wrote:
> On Fri, Apr 05, 2024 at 02:40:50PM -0400, Jeff Layton wrote:
> > Replace a dprintk in check_slot_seqid with a new tracepoint.  Add a
> > nfs4_client argument to check_slot_seqid so that we can pass the
> > appropriate info to the tracepoint.
> > 
> > Signed-off-by: Jeffrey Layton <jlayton@xxxxxxxxxx>
> > ---
> >  fs/nfsd/nfs4state.c | 12 ++++++------
> >  fs/nfsd/trace.h     | 34 ++++++++++++++++++++++++++++++++++
> >  2 files changed, 40 insertions(+), 6 deletions(-)
> > 
> > diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
> > index 3cef81e196c6..5891bc3e2b0b 100644
> > --- a/fs/nfsd/nfs4state.c
> > +++ b/fs/nfsd/nfs4state.c
> > @@ -3642,10 +3642,9 @@ nfsd4_exchange_id(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
> >  }
> >  
> >  static __be32
> > -check_slot_seqid(u32 seqid, u32 slot_seqid, int slot_inuse)
> > +check_slot_seqid(struct nfs4_client *clp, u32 seqid, u32 slot_seqid, bool slot_inuse)
> >  {
> > -	dprintk("%s enter. seqid %d slot_seqid %d\n", __func__, seqid,
> > -		slot_seqid);
> > +	trace_check_slot_seqid(clp, seqid, slot_seqid, slot_inuse);
> 
> Getting rid of the dprintk: +1
> 
> Tracing slot seqid checks: +1
> 
> But I'd like something a little different for the tracepoint
> itself. I can make these changes if you like to just hand this off.
> 
> Let's make this trace point into three separate trace events, one
> at the nfsd4_sequence check_slot_seqid() call site, and two in
> nfsd4_create_session(), like below.
> 
> Two reasons for this change:
> 
> 1. Separate tracepoints in nfsd4_create_session will show whether
>    the client is confirmed or not
> 
> 2. The tracepoint in nfsd4_sequence will normally be noisy, so
>    having a separate tracepoint for that case makes it easy to
>    disable that one while leaving the create_session tracepoints
>    enabled.
> 
> And, bonus: you won't have to change the synopsis of
> check_slot_seqid().
> 
> 
> >  	/* The slot is in use, and no response has been sent. */
> >  	if (slot_inuse) {
> > @@ -3827,7 +3826,8 @@ nfsd4_create_session(struct svc_rqst *rqstp,
> >  		cs_slot = &conf->cl_cs_slot;
> 		trace_nfsd_slot_seqid_confirmed
> >  	else
> >  		cs_slot = &unconf->cl_cs_slot;
> 		trace_nfsd_slot_seqid_unconfirmed
> > -	status = check_slot_seqid(cr_ses->seqid, cs_slot->sl_seqid, 0);
> > +	status = check_slot_seqid(conf ? conf : unconf, cr_ses->seqid,
> > +				  cs_slot->sl_seqid, false);
> >  	switch (status) {
> >  	case nfs_ok:
> >  		cs_slot->sl_seqid++;
> > @@ -4221,8 +4221,8 @@ nfsd4_sequence(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
> >  	 * sr_highest_slotid and the sr_target_slot id to maxslots */
> >  	seq->maxslots = session->se_fchannel.maxreqs;
> >  
> 	trace_nfsd_slot_seqid_sequence
> > -	status = check_slot_seqid(seq->seqid, slot->sl_seqid,
> > -					slot->sl_flags & NFSD4_SLOT_INUSE);
> > +	status = check_slot_seqid(clp, seq->seqid, slot->sl_seqid,
> > +				  slot->sl_flags & NFSD4_SLOT_INUSE);
> >  	if (status == nfserr_replay_cache) {
> >  		status = nfserr_seq_misordered;
> >  		if (!(slot->sl_flags & NFSD4_SLOT_INITIALIZED))
> > diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
> > index 7f1a6d568bdb..ec00ca7ecfc8 100644
> > --- a/fs/nfsd/trace.h
> > +++ b/fs/nfsd/trace.h
> > @@ -1542,6 +1542,40 @@ TRACE_EVENT(nfsd_cb_seq_status,
> >  	)
> >  );
> >  
> > +TRACE_EVENT(check_slot_seqid,
> 
> Nit: NFSD tracepoint names should start with "nfsd_".
> 
> 
> > +	TP_PROTO(
> > +		const struct nfs4_client *clp,
> > +		u32 seqid,
> > +		u32 slot_seqid,
> > +		bool inuse
> > +	),
> > +	TP_ARGS(clp, seqid, slot_seqid, inuse),
> > +	TP_STRUCT__entry(
> > +		__field(u32, seqid)
> > +		__field(u32, slot_seqid)
> > +		__field(u32, cl_boot)
> > +		__field(u32, cl_id)
> > +		__sockaddr(addr, clp->cl_cb_conn.cb_addrlen)
> > +		__field(bool, conf)
> > +		__field(bool, inuse)
> > +	),
> > +	TP_fast_assign(
> > +		__entry->cl_boot = clp->cl_clientid.cl_boot;
> > +		__entry->cl_id = clp->cl_clientid.cl_id;
> > +		__assign_sockaddr(addr, &clp->cl_cb_conn.cb_addr,
> > +				  clp->cl_cb_conn.cb_addrlen);
> > +		__entry->seqid = seqid;
> > +		__entry->slot_seqid = slot_seqid;
> > +		__entry->conf = test_bit(NFSD4_CLIENT_CONFIRMED, &clp->cl_flags);
> > +		__entry->inuse = inuse;
> > +	),
> > +	TP_printk("addr=%pISpc %s client %08x:%08x seqid=%u slot_seqid=%u inuse=%d",
> > +		__get_sockaddr(addr), __entry->conf ? "conf" : "unconf",
> > +		__entry->cl_boot, __entry->cl_id,
> > +		__entry->seqid, __entry->slot_seqid, __entry->inuse
> 
> Nit: How about: __entry->in_use ? "(in use)" : "(not in use)"
> 
> Since TP_printk is for human readers.
> 
> 
> > +	)
> > +);
> > +
> >  TRACE_EVENT(nfsd_cb_free_slot,
> >  	TP_PROTO(
> >  		const struct rpc_task *task,
> > 
> > -- 
> > 2.44.0
> > 
> 

Sure, those all sound like fine changes. If you're fine making them,
thats good with me too. I mostly posted these since I used these to help
track down the CB_RECALL_ANY issue.
-- 
Jeff Layton <jlayton@xxxxxxxxxx>