[PATCH 0/3] nfsd: tracepoint cleanups and additions

[PATCH 0/3] nfsd: tracepoint cleanups and additions

[Jeff Layton]

First a patch to remove a few newlines from existing tracepoint string
formats, and then a couple of new tracepoints to instrument some of the
activity around CREATE_SESSION and client expiry. Probably reasonable
for v6.10.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
Jeff Layton (3):
      nfsd: drop extraneous newline from nfsd tracepoints
      nfsd: new tracepoint for check_slot_seqid
      nfsd: add tracepoint in mark_client_expired_locked

 fs/nfsd/nfs4state.c | 18 +++++++++------
 fs/nfsd/trace.h     | 64 ++++++++++++++++++++++++++++++++++++++++++++++++++---
 2 files changed, 72 insertions(+), 10 deletions(-)
---
base-commit: 10396f4df8b75ff6ab0aa2cd74296565466f2c8d
change-id: 20240405-nfsd-fixes-adc4524ae2bf

Best regards,
-- 
Jeff Layton <jlayton@kernel.org>

[PATCH 1/3] nfsd: drop extraneous newline from nfsd tracepoints

[Jeff Layton]

We never want a newline in tracepoint output.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/trace.h | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index e545e92c4408..7f1a6d568bdb 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -1534,7 +1534,7 @@ TRACE_EVENT(nfsd_cb_seq_status,
 		__entry->seq_status = cb->cb_seq_status;
 	),
 	TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
-		" sessionid=%08x:%08x:%08x:%08x tk_status=%d seq_status=%d\n",
+		" sessionid=%08x:%08x:%08x:%08x tk_status=%d seq_status=%d",
 		__entry->task_id, __entry->client_id,
 		__entry->cl_boot, __entry->cl_id,
 		__entry->seqno, __entry->reserved,
@@ -1573,7 +1573,7 @@ TRACE_EVENT(nfsd_cb_free_slot,
 		__entry->slot_seqno = session->se_cb_seq_nr;
 	),
 	TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
-		" sessionid=%08x:%08x:%08x:%08x new slot seqno=%u\n",
+		" sessionid=%08x:%08x:%08x:%08x new slot seqno=%u",
 		__entry->task_id, __entry->client_id,
 		__entry->cl_boot, __entry->cl_id,
 		__entry->seqno, __entry->reserved,
@@ -1978,7 +1978,7 @@ TRACE_EVENT(nfsd_ctl_time,
 		__entry->time = time;
 		__assign_str_len(name, name, namelen);
 	),
-	TP_printk("file=%s time=%d\n",
+	TP_printk("file=%s time=%d",
 		__get_str(name), __entry->time
 	)
 );

-- 
2.44.0

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

[Jeff Layton]

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@redhat.com>
---
 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);
 
 	/* 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;
 	else
 		cs_slot = &unconf->cl_cs_slot;
-	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;
 
-	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,
+	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
+	)
+);
+
 TRACE_EVENT(nfsd_cb_free_slot,
 	TP_PROTO(
 		const struct rpc_task *task,

-- 
2.44.0

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

[Chuck Lever]

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@redhat.com>
> ---
>  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
> 

-- 
Chuck Lever

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@redhat.com>
> > ---
> >  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@kernel.org>

[PATCH 3/3] nfsd: add tracepoint in mark_client_expired_locked

[Jeff Layton]

Show client info alongside the number of cl_rpc_users. If that's
elevated, then we can infer that this function returned nfserr_jukebox.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/nfs4state.c |  6 +++++-
 fs/nfsd/trace.h     | 24 ++++++++++++++++++++++++
 2 files changed, 29 insertions(+), 1 deletion(-)

diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c
index 5891bc3e2b0b..2b5dadeed8c9 100644
--- a/fs/nfsd/nfs4state.c
+++ b/fs/nfsd/nfs4state.c
@@ -2352,7 +2352,11 @@ unhash_client(struct nfs4_client *clp)
 
 static __be32 mark_client_expired_locked(struct nfs4_client *clp)
 {
-	if (atomic_read(&clp->cl_rpc_users))
+	int users = atomic_read(&clp->cl_rpc_users);
+
+	trace_mark_client_expired_locked(clp, users);
+
+	if (users)
 		return nfserr_jukebox;
 	unhash_client_locked(clp);
 	return nfs_ok;
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index ec00ca7ecfc8..b50d6a71c7d9 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -1576,6 +1576,30 @@ TRACE_EVENT(check_slot_seqid,
 	)
 );
 
+TRACE_EVENT(mark_client_expired_locked,
+	TP_PROTO(
+		const struct nfs4_client *clp,
+		int cl_rpc_users
+	),
+	TP_ARGS(clp, cl_rpc_users),
+	TP_STRUCT__entry(
+		__field(int, cl_rpc_users)
+		__field(u32, cl_boot)
+		__field(u32, cl_id)
+		__sockaddr(addr, clp->cl_cb_conn.cb_addrlen)
+	),
+	TP_fast_assign(
+		__entry->cl_rpc_users = cl_rpc_users;
+		__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)
+	),
+	TP_printk("addr=%pISpc client %08x:%08x cl_rpc_users=%d",
+		__get_sockaddr(addr), __entry->cl_boot, __entry->cl_id,
+		__entry->cl_rpc_users)
+);
+
 TRACE_EVENT(nfsd_cb_free_slot,
 	TP_PROTO(
 		const struct rpc_task *task,

-- 
2.44.0