NFSD: Add tracepoints to report NFSv4 callback completions
authorChuck Lever <chuck.lever@oracle.com>
Thu, 8 Sep 2022 22:13:54 +0000 (18:13 -0400)
committerChuck Lever <chuck.lever@oracle.com>
Mon, 26 Sep 2022 18:02:32 +0000 (14:02 -0400)
Wireshark has always been lousy about dissecting NFSv4 callbacks,
especially NFSv4.0 backchannel requests. Add tracepoints so we
can surgically capture these events in the trace log.

Tracepoints are time-stamped and ordered so that we can now observe
the timing relationship between a CB_RECALL Reply and the client's
DELEGRETURN Call. Example:

            nfsd-1153  [002]   211.986391: nfsd_cb_recall:       addr=192.168.1.67:45767 client 62ea82e4:fee7492a stateid 00000003:00000001

            nfsd-1153  [002]   212.095634: nfsd_compound:        xid=0x0000002c opcnt=2
            nfsd-1153  [002]   212.095647: nfsd_compound_status: op=1/2 OP_PUTFH status=0
            nfsd-1153  [002]   212.095658: nfsd_file_put:        hash=0xf72 inode=0xffff9291148c7410 ref=3 flags=HASHED|REFERENCED may=READ file=0xffff929103b3ea00
            nfsd-1153  [002]   212.095661: nfsd_compound_status: op=2/2 OP_DELEGRETURN status=0
   kworker/u25:8-148   [002]   212.096713: nfsd_cb_recall_done:  client 62ea82e4:fee7492a stateid 00000003:00000001 status=0

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Reviewed-by: Jeff Layton <jlayton@kernel.org>
fs/nfsd/nfs4layouts.c
fs/nfsd/nfs4proc.c
fs/nfsd/nfs4state.c
fs/nfsd/trace.h

index 2c05692a9abf1a45944bbe94da635317be24dadb..3564d1c6f61042a71c7200e6f073da1acf7535d1 100644 (file)
@@ -658,7 +658,7 @@ nfsd4_cb_layout_done(struct nfsd4_callback *cb, struct rpc_task *task)
        ktime_t now, cutoff;
        const struct nfsd4_layout_ops *ops;
 
-
+       trace_nfsd_cb_layout_done(&ls->ls_stid.sc_stateid, task);
        switch (task->tk_status) {
        case 0:
        case -NFS4ERR_DELAY:
index f14b015022ed575f4a08f0b29902fd0429970120..1918c9ec347836f3e11349bc0595cb6b0cb1a44a 100644 (file)
@@ -1613,6 +1613,10 @@ static void nfsd4_cb_offload_release(struct nfsd4_callback *cb)
 static int nfsd4_cb_offload_done(struct nfsd4_callback *cb,
                                 struct rpc_task *task)
 {
+       struct nfsd4_cb_offload *cbo =
+               container_of(cb, struct nfsd4_cb_offload, co_cb);
+
+       trace_nfsd_cb_offload_done(&cbo->co_res.cb_stateid, task);
        return 1;
 }
 
index c5d199d7e6b4e2ec8624deab8a8d9ab24519bbeb..561f3556b1d22ec5dffa5a1cae1c88f602fe1bc4 100644 (file)
@@ -357,6 +357,8 @@ nfsd4_cb_notify_lock_prepare(struct nfsd4_callback *cb)
 static int
 nfsd4_cb_notify_lock_done(struct nfsd4_callback *cb, struct rpc_task *task)
 {
+       trace_nfsd_cb_notify_lock_done(&zero_stateid, task);
+
        /*
         * Since this is just an optimization, we don't try very hard if it
         * turns out not to succeed. We'll requeue it on NFS4ERR_DELAY, and
@@ -4743,6 +4745,8 @@ static int nfsd4_cb_recall_done(struct nfsd4_callback *cb,
 {
        struct nfs4_delegation *dp = cb_to_delegation(cb);
 
+       trace_nfsd_cb_recall_done(&dp->dl_stid.sc_stateid, task);
+
        if (dp->dl_stid.sc_type == NFS4_CLOSED_DELEG_STID ||
            dp->dl_stid.sc_type == NFS4_REVOKED_DELEG_STID)
                return 1;
index 0c35a1a844e6c5017fc44d538ee971edd634d5bc..ec8e08315779a8753c8adda194aa27dda59f84cd 100644 (file)
@@ -1448,6 +1448,45 @@ TRACE_EVENT(nfsd_cb_offload,
                __entry->fh_hash, __entry->count, __entry->status)
 );
 
+DECLARE_EVENT_CLASS(nfsd_cb_done_class,
+       TP_PROTO(
+               const stateid_t *stp,
+               const struct rpc_task *task
+       ),
+       TP_ARGS(stp, task),
+       TP_STRUCT__entry(
+               __field(u32, cl_boot)
+               __field(u32, cl_id)
+               __field(u32, si_id)
+               __field(u32, si_generation)
+               __field(int, status)
+       ),
+       TP_fast_assign(
+               __entry->cl_boot = stp->si_opaque.so_clid.cl_boot;
+               __entry->cl_id = stp->si_opaque.so_clid.cl_id;
+               __entry->si_id = stp->si_opaque.so_id;
+               __entry->si_generation = stp->si_generation;
+               __entry->status = task->tk_status;
+       ),
+       TP_printk("client %08x:%08x stateid %08x:%08x status=%d",
+               __entry->cl_boot, __entry->cl_id, __entry->si_id,
+               __entry->si_generation, __entry->status
+       )
+);
+
+#define DEFINE_NFSD_CB_DONE_EVENT(name)                        \
+DEFINE_EVENT(nfsd_cb_done_class, name,                 \
+       TP_PROTO(                                       \
+               const stateid_t *stp,                   \
+               const struct rpc_task *task             \
+       ),                                              \
+       TP_ARGS(stp, task))
+
+DEFINE_NFSD_CB_DONE_EVENT(nfsd_cb_recall_done);
+DEFINE_NFSD_CB_DONE_EVENT(nfsd_cb_notify_lock_done);
+DEFINE_NFSD_CB_DONE_EVENT(nfsd_cb_layout_done);
+DEFINE_NFSD_CB_DONE_EVENT(nfsd_cb_offload_done);
+
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH