From db2acd6e8ab1606c47bcea3e269ac7cff897eb8d Mon Sep 17 00:00:00 2001 From: Jeff Layton Date: Fri, 5 Apr 2024 14:40:49 -0400 Subject: nfsd: drop extraneous newline from nfsd tracepoints We never want a newline in tracepoint output. Signed-off-by: Jeff Layton Tested-by: Vladimir Benes Signed-off-by: Chuck Lever --- fs/nfsd/trace.h | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) (limited to 'fs/nfsd/trace.h') diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h index 1cd2076210b1..c0cc345a576e 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(name, name); ), - TP_printk("file=%s time=%d\n", + TP_printk("file=%s time=%d", __get_str(name), __entry->time ) ); -- cgit v1.2.3 From 2d49901150ecf82f9a3d3d2dc30e38b17fef71a0 Mon Sep 17 00:00:00 2001 From: Chuck Lever Date: Fri, 5 Apr 2024 14:40:50 -0400 Subject: nfsd: new tracepoint for check_slot_seqid Replace a dprintk in check_slot_seqid with tracepoints. These new tracepoints track slot sequence numbers during operation. Suggested-by: Jeffrey Layton Signed-off-by: Chuck Lever --- fs/nfsd/nfs4state.c | 14 +++++------ fs/nfsd/trace.h | 70 +++++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 77 insertions(+), 7 deletions(-) (limited to 'fs/nfsd/trace.h') diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c index 5ae70fb1d3a2..bd81217ada7f 100644 --- a/fs/nfsd/nfs4state.c +++ b/fs/nfsd/nfs4state.c @@ -3636,12 +3636,8 @@ out_nolock: return status; } -static __be32 -check_slot_seqid(u32 seqid, u32 slot_seqid, int slot_inuse) +static __be32 check_slot_seqid(u32 seqid, u32 slot_seqid, bool slot_inuse) { - dprintk("%s enter. seqid %d slot_seqid %d\n", __func__, seqid, - slot_seqid); - /* The slot is in use, and no response has been sent. */ if (slot_inuse) { if (seqid == slot_seqid) @@ -3818,10 +3814,13 @@ nfsd4_create_session(struct svc_rqst *rqstp, } /* RFC 8881 Section 18.36.4 Phase 2: Sequence ID processing. */ - if (conf) + if (conf) { cs_slot = &conf->cl_cs_slot; - else + trace_nfsd_slot_seqid_conf(conf, cr_ses); + } else { cs_slot = &unconf->cl_cs_slot; + trace_nfsd_slot_seqid_unconf(unconf, cr_ses); + } status = check_slot_seqid(cr_ses->seqid, cs_slot->sl_seqid, 0); switch (status) { case nfs_ok: @@ -4216,6 +4215,7 @@ 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(clp, seq, slot); status = check_slot_seqid(seq->seqid, slot->sl_seqid, slot->sl_flags & NFSD4_SLOT_INUSE); if (status == nfserr_replay_cache) { diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h index c0cc345a576e..ac2124461a08 100644 --- a/fs/nfsd/trace.h +++ b/fs/nfsd/trace.h @@ -749,6 +749,76 @@ TRACE_EVENT_CONDITION(nfsd_seq4_status, ) ); +DECLARE_EVENT_CLASS(nfsd_cs_slot_class, + TP_PROTO( + const struct nfs4_client *clp, + const struct nfsd4_create_session *cs + ), + TP_ARGS(clp, cs), + 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) + ), + TP_fast_assign( + const struct nfsd4_clid_slot *slot = &clp->cl_cs_slot; + + __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 = cs->seqid; + __entry->slot_seqid = slot->sl_seqid; + ), + TP_printk("addr=%pISpc client %08x:%08x seqid=%u slot_seqid=%u", + __get_sockaddr(addr), __entry->cl_boot, __entry->cl_id, + __entry->seqid, __entry->slot_seqid + ) +); + +#define DEFINE_CS_SLOT_EVENT(name) \ +DEFINE_EVENT(nfsd_cs_slot_class, nfsd_##name, \ + TP_PROTO( \ + const struct nfs4_client *clp, \ + const struct nfsd4_create_session *cs \ + ), \ + TP_ARGS(clp, cs)) + +DEFINE_CS_SLOT_EVENT(slot_seqid_conf); +DEFINE_CS_SLOT_EVENT(slot_seqid_unconf); + +TRACE_EVENT(nfsd_slot_seqid_sequence, + TP_PROTO( + const struct nfs4_client *clp, + const struct nfsd4_sequence *seq, + const struct nfsd4_slot *slot + ), + TP_ARGS(clp, seq, slot), + 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, in_use) + ), + 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 = seq->seqid; + __entry->slot_seqid = slot->sl_seqid; + ), + TP_printk("addr=%pISpc client %08x:%08x seqid=%u slot_seqid=%u (%sin use)", + __get_sockaddr(addr), __entry->cl_boot, __entry->cl_id, + __entry->seqid, __entry->slot_seqid, + __entry->in_use ? "" : "not " + ) +); + DECLARE_EVENT_CLASS(nfsd_clientid_class, TP_PROTO(const clientid_t *clid), TP_ARGS(clid), -- cgit v1.2.3 From 9320f27fda5498c80f9e0c7d8c80d50e8297d89e Mon Sep 17 00:00:00 2001 From: Jeff Layton Date: Fri, 5 Apr 2024 14:40:51 -0400 Subject: nfsd: add tracepoint in mark_client_expired_locked Show client info alongside the number of cl_rpc_users. If that's elevated, then we can infer that this function returned nfserr_jukebox. [ cel: For additional debugging of RPC user refcounting ] Signed-off-by: Jeff Layton Tested-by: Vladimir Benes Signed-off-by: Chuck Lever --- fs/nfsd/nfs4state.c | 6 +++++- fs/nfsd/trace.h | 24 ++++++++++++++++++++++++ 2 files changed, 29 insertions(+), 1 deletion(-) (limited to 'fs/nfsd/trace.h') diff --git a/fs/nfsd/nfs4state.c b/fs/nfsd/nfs4state.c index bd81217ada7f..66f9a4f031a4 100644 --- a/fs/nfsd/nfs4state.c +++ b/fs/nfsd/nfs4state.c @@ -2347,7 +2347,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_nfsd_mark_client_expired(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 ac2124461a08..b5e48d504062 100644 --- a/fs/nfsd/trace.h +++ b/fs/nfsd/trace.h @@ -848,6 +848,30 @@ DEFINE_CLIENTID_EVENT(purged); DEFINE_CLIENTID_EVENT(renew); DEFINE_CLIENTID_EVENT(stale); +TRACE_EVENT(nfsd_mark_client_expired, + 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) +); + DECLARE_EVENT_CLASS(nfsd_net_class, TP_PROTO(const struct nfsd_net *nn), TP_ARGS(nn), -- cgit v1.2.3