Linux-NFS Archive on lore.kernel.org
 help / color / Atom feed
From: Chuck Lever <chuck.lever@oracle.com>
To: bfields@fieldses.org
Cc: linux-nfs@vger.kernel.org, linux-rdma@vger.kernel.org
Subject: [PATCH v3 27/32] NFSD: Add tracepoints to NFSD's duplicate reply cache
Date: Thu, 21 May 2020 10:36:05 -0400
Message-ID: <20200521143605.3557.32136.stgit@klimt.1015granger.net> (raw)
In-Reply-To: <20200521141100.3557.17098.stgit@klimt.1015granger.net>

Try to capture DRC failures.

Two additional clean-ups:
- Introduce Doxygen-style comments for the main entry points
- Remove a dprintk that fires for an allocation failure. This was
  the only dprintk in the REPCACHE class.

Reported-by: kbuild test robot <lkp@intel.com>
[ cel: force typecast for display of checksum values ]
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfscache.c |   57 +++++++++++++++++++++++++++++++-------------------
 fs/nfsd/trace.h    |   59 ++++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 94 insertions(+), 22 deletions(-)

diff --git a/fs/nfsd/nfscache.c b/fs/nfsd/nfscache.c
index 96352ab7bd81..945d2f5e760e 100644
--- a/fs/nfsd/nfscache.c
+++ b/fs/nfsd/nfscache.c
@@ -20,8 +20,7 @@
 
 #include "nfsd.h"
 #include "cache.h"
-
-#define NFSDDBG_FACILITY	NFSDDBG_REPCACHE
+#include "trace.h"
 
 /*
  * We use this value to determine the number of hash buckets from the max
@@ -323,8 +322,10 @@ nfsd_cache_key_cmp(const struct svc_cacherep *key,
 			const struct svc_cacherep *rp, struct nfsd_net *nn)
 {
 	if (key->c_key.k_xid == rp->c_key.k_xid &&
-	    key->c_key.k_csum != rp->c_key.k_csum)
+	    key->c_key.k_csum != rp->c_key.k_csum) {
 		++nn->payload_misses;
+		trace_nfsd_drc_mismatch(nn, key, rp);
+	}
 
 	return memcmp(&key->c_key, &rp->c_key, sizeof(key->c_key));
 }
@@ -377,15 +378,22 @@ nfsd_cache_insert(struct nfsd_drc_bucket *b, struct svc_cacherep *key,
 	return ret;
 }
 
-/*
+/**
+ * nfsd_cache_lookup - Find an entry in the duplicate reply cache
+ * @rqstp: Incoming Call to find
+ *
  * Try to find an entry matching the current call in the cache. When none
  * is found, we try to grab the oldest expired entry off the LRU list. If
  * a suitable one isn't there, then drop the cache_lock and allocate a
  * new one, then search again in case one got inserted while this thread
  * didn't hold the lock.
+ *
+ * Return values:
+ *   %RC_DOIT: Process the request normally
+ *   %RC_REPLY: Reply from cache
+ *   %RC_DROPIT: Do not process the request further
  */
-int
-nfsd_cache_lookup(struct svc_rqst *rqstp)
+int nfsd_cache_lookup(struct svc_rqst *rqstp)
 {
 	struct nfsd_net *nn = net_generic(SVC_NET(rqstp), nfsd_net_id);
 	struct svc_cacherep	*rp, *found;
@@ -399,7 +407,7 @@ nfsd_cache_lookup(struct svc_rqst *rqstp)
 	rqstp->rq_cacherep = NULL;
 	if (type == RC_NOCACHE) {
 		nfsdstats.rcnocache++;
-		return rtn;
+		goto out;
 	}
 
 	csum = nfsd_cache_csum(rqstp);
@@ -409,10 +417,8 @@ nfsd_cache_lookup(struct svc_rqst *rqstp)
 	 * preallocate an entry.
 	 */
 	rp = nfsd_reply_cache_alloc(rqstp, csum, nn);
-	if (!rp) {
-		dprintk("nfsd: unable to allocate DRC entry!\n");
-		return rtn;
-	}
+	if (!rp)
+		goto out;
 
 	spin_lock(&b->cache_lock);
 	found = nfsd_cache_insert(b, rp, nn);
@@ -431,8 +437,10 @@ nfsd_cache_lookup(struct svc_rqst *rqstp)
 
 	/* go ahead and prune the cache */
 	prune_bucket(b, nn);
- out:
+
+out_unlock:
 	spin_unlock(&b->cache_lock);
+out:
 	return rtn;
 
 found_entry:
@@ -442,13 +450,13 @@ nfsd_cache_lookup(struct svc_rqst *rqstp)
 
 	/* Request being processed */
 	if (rp->c_state == RC_INPROG)
-		goto out;
+		goto out_trace;
 
 	/* From the hall of fame of impractical attacks:
 	 * Is this a user who tries to snoop on the cache? */
 	rtn = RC_DOIT;
 	if (!test_bit(RQ_SECURE, &rqstp->rq_flags) && rp->c_secure)
-		goto out;
+		goto out_trace;
 
 	/* Compose RPC reply header */
 	switch (rp->c_type) {
@@ -460,7 +468,7 @@ nfsd_cache_lookup(struct svc_rqst *rqstp)
 		break;
 	case RC_REPLBUFF:
 		if (!nfsd_cache_append(rqstp, &rp->c_replvec))
-			goto out;	/* should not happen */
+			goto out_unlock; /* should not happen */
 		rtn = RC_REPLY;
 		break;
 	default:
@@ -468,13 +476,19 @@ nfsd_cache_lookup(struct svc_rqst *rqstp)
 		nfsd_reply_cache_free_locked(b, rp, nn);
 	}
 
-	goto out;
+out_trace:
+	trace_nfsd_drc_found(nn, rqstp, rtn);
+	goto out_unlock;
 }
 
-/*
- * Update a cache entry. This is called from nfsd_dispatch when
- * the procedure has been executed and the complete reply is in
- * rqstp->rq_res.
+/**
+ * nfsd_cache_update - Update an entry in the duplicate reply cache.
+ * @rqstp: svc_rqst with a finished Reply
+ * @cachetype: which cache to update
+ * @statp: Reply's status code
+ *
+ * This is called from nfsd_dispatch when the procedure has been
+ * executed and the complete reply is in rqstp->rq_res.
  *
  * We're copying around data here rather than swapping buffers because
  * the toplevel loop requires max-sized buffers, which would be a waste
@@ -487,8 +501,7 @@ nfsd_cache_lookup(struct svc_rqst *rqstp)
  * nfsd failed to encode a reply that otherwise would have been cached.
  * In this case, nfsd_cache_update is called with statp == NULL.
  */
-void
-nfsd_cache_update(struct svc_rqst *rqstp, int cachetype, __be32 *statp)
+void nfsd_cache_update(struct svc_rqst *rqstp, int cachetype, __be32 *statp)
 {
 	struct nfsd_net *nn = net_generic(SVC_NET(rqstp), nfsd_net_id);
 	struct svc_cacherep *rp = rqstp->rq_cacherep;
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 78c574251c60..371dc198d28e 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -432,6 +432,65 @@ TRACE_EVENT(nfsd_file_fsnotify_handle_event,
 			__entry->nlink, __entry->mode, __entry->mask)
 );
 
+#include "cache.h"
+
+TRACE_DEFINE_ENUM(RC_DROPIT);
+TRACE_DEFINE_ENUM(RC_REPLY);
+TRACE_DEFINE_ENUM(RC_DOIT);
+
+#define show_drc_retval(x)						\
+	__print_symbolic(x,						\
+		{ RC_DROPIT, "DROPIT" },				\
+		{ RC_REPLY, "REPLY" },					\
+		{ RC_DOIT, "DOIT" })
+
+TRACE_EVENT(nfsd_drc_found,
+	TP_PROTO(
+		const struct nfsd_net *nn,
+		const struct svc_rqst *rqstp,
+		int result
+	),
+	TP_ARGS(nn, rqstp, result),
+	TP_STRUCT__entry(
+		__field(unsigned long long, boot_time)
+		__field(unsigned long, result)
+		__field(u32, xid)
+	),
+	TP_fast_assign(
+		__entry->boot_time = nn->boot_time;
+		__entry->result = result;
+		__entry->xid = be32_to_cpu(rqstp->rq_xid);
+	),
+	TP_printk("boot_time=%16llx xid=0x%08x result=%s",
+		__entry->boot_time, __entry->xid,
+		show_drc_retval(__entry->result))
+
+);
+
+TRACE_EVENT(nfsd_drc_mismatch,
+	TP_PROTO(
+		const struct nfsd_net *nn,
+		const struct svc_cacherep *key,
+		const struct svc_cacherep *rp
+	),
+	TP_ARGS(nn, key, rp),
+	TP_STRUCT__entry(
+		__field(unsigned long long, boot_time)
+		__field(u32, xid)
+		__field(u32, cached)
+		__field(u32, ingress)
+	),
+	TP_fast_assign(
+		__entry->boot_time = nn->boot_time;
+		__entry->xid = be32_to_cpu(key->c_key.k_xid);
+		__entry->cached = (__force u32)key->c_key.k_csum;
+		__entry->ingress = (__force u32)rp->c_key.k_csum;
+	),
+	TP_printk("boot_time=%16llx xid=0x%08x cached-csum=0x%08x ingress-csum=0x%08x",
+		__entry->boot_time, __entry->xid, __entry->cached,
+		__entry->ingress)
+);
+
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH


  parent reply index

Thread overview: 33+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2020-05-21 14:33 [PATCH v3 00/32] Possible NFSD patches for v5.8 Chuck Lever
2020-05-21 14:33 ` [PATCH v3 01/32] SUNRPC: Move xpt_mutex into socket xpo_sendto methods Chuck Lever
2020-05-21 14:33 ` [PATCH v3 02/32] svcrdma: Clean up the tracing for rw_ctx_init errors Chuck Lever
2020-05-21 14:33 ` [PATCH v3 03/32] svcrdma: Clean up handling of get_rw_ctx errors Chuck Lever
2020-05-21 14:34 ` [PATCH v3 04/32] svcrdma: Trace page overruns when constructing RDMA Reads Chuck Lever
2020-05-21 14:34 ` [PATCH v3 05/32] svcrdma: trace undersized Write chunks Chuck Lever
2020-05-21 14:34 ` [PATCH v3 06/32] svcrdma: Fix backchannel return code Chuck Lever
2020-05-21 14:34 ` [PATCH v3 07/32] svcrdma: Remove backchannel dprintk call sites Chuck Lever
2020-05-21 14:34 ` [PATCH v3 08/32] svcrdma: Rename tracepoints that record header decoding errors Chuck Lever
2020-05-21 14:34 ` [PATCH v3 09/32] svcrdma: Remove the SVCRDMA_DEBUG macro Chuck Lever
2020-05-21 14:34 ` [PATCH v3 10/32] svcrdma: Displayed remote IP address should match stored address Chuck Lever
2020-05-21 14:34 ` [PATCH v3 11/32] svcrdma: Add tracepoints to report ->xpo_accept failures Chuck Lever
2020-05-21 14:34 ` [PATCH v3 12/32] SUNRPC: Remove kernel memory address from svc_xprt tracepoints Chuck Lever
2020-05-21 14:34 ` [PATCH v3 13/32] SUNRPC: Tracepoint to record errors in svc_xpo_create() Chuck Lever
2020-05-21 14:34 ` [PATCH v3 14/32] SUNRPC: Trace a few more generic svc_xprt events Chuck Lever
2020-05-21 14:35 ` [PATCH v3 15/32] SUNRPC: Remove "#include <trace/events/skb.h>" Chuck Lever
2020-05-21 14:35 ` [PATCH v3 16/32] SUNRPC: Add more svcsock tracepoints Chuck Lever
2020-05-21 14:35 ` [PATCH v3 17/32] SUNRPC: Replace dprintk call sites in TCP state change callouts Chuck Lever
2020-05-21 14:35 ` [PATCH v3 18/32] SUNRPC: Trace server-side rpcbind registration events Chuck Lever
2020-05-21 14:35 ` [PATCH v3 19/32] SUNRPC: Rename svc_sock::sk_reclen Chuck Lever
2020-05-21 14:35 ` [PATCH v3 20/32] SUNRPC: Restructure svc_tcp_recv_record() Chuck Lever
2020-05-21 14:35 ` [PATCH v3 21/32] SUNRPC: Replace dprintk() call sites in TCP receive path Chuck Lever
2020-05-21 14:35 ` [PATCH v3 22/32] SUNRPC: Refactor recvfrom path dealing with incomplete TCP receives Chuck Lever
2020-05-21 14:35 ` [PATCH v3 23/32] SUNRPC: Clean up svc_release_skb() functions Chuck Lever
2020-05-21 14:35 ` [PATCH v3 24/32] SUNRPC: Refactor svc_recvfrom() Chuck Lever
2020-05-21 14:35 ` [PATCH v3 25/32] SUNRPC: Restructure svc_udp_recvfrom() Chuck Lever
2020-05-21 14:36 ` [PATCH v3 26/32] SUNRPC: svc_show_status() macro should have enum definitions Chuck Lever
2020-05-21 14:36 ` Chuck Lever [this message]
2020-05-21 14:36 ` [PATCH v3 28/32] NFSD: Add tracepoints to the NFSD state management code Chuck Lever
2020-05-21 14:36 ` [PATCH v3 29/32] NFSD: Add tracepoints for monitoring NFSD callbacks Chuck Lever
2020-05-21 14:36 ` [PATCH v3 30/32] SUNRPC: Clean up request deferral tracepoints Chuck Lever
2020-05-21 14:36 ` [PATCH v3 31/32] NFSD: Squash an annoying compiler warning Chuck Lever
2020-05-21 14:36 ` [PATCH v3 32/32] NFSD: Fix improperly-formatted Doxygen comments Chuck Lever

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20200521143605.3557.32136.stgit@klimt.1015granger.net \
    --to=chuck.lever@oracle.com \
    --cc=bfields@fieldses.org \
    --cc=linux-nfs@vger.kernel.org \
    --cc=linux-rdma@vger.kernel.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link

Linux-NFS Archive on lore.kernel.org

Archives are clonable:
	git clone --mirror https://lore.kernel.org/linux-nfs/0 linux-nfs/git/0.git

	# If you have public-inbox 1.1+ installed, you may
	# initialize and index your mirror using the following commands:
	public-inbox-init -V2 linux-nfs linux-nfs/ https://lore.kernel.org/linux-nfs \
		linux-nfs@vger.kernel.org
	public-inbox-index linux-nfs

Example config snippet for mirrors

Newsgroup available over NNTP:
	nntp://nntp.lore.kernel.org/org.kernel.vger.linux-nfs


AGPL code for this site: git clone https://public-inbox.org/public-inbox.git