NFSD: Add tracepoints to NFSD's duplicate reply cache

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>

diff --git a/fs/nfsd/nfscache.c b/fs/nfsd/nfscache.c
index 96352ab7bd8100af89f2fadfa50825e31221dd7b..945d2f5e760e82819081d88e396a26c4e7b57307 100644 (file)
--- 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 @@ out:
        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 @@ found_entry:
 
        /* 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 @@ found_entry:
                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 @@ found_entry:
                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 @@ found_entry:
  * 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 78c574251c608bf56c841e0cd80a47bb22a47834..371dc198d28ee9cc1430923a7a22212f31bce61d 100644 (file)
--- 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