NFSD: Add callback operation lifetime trace points

Help observe the flow of callback operations.

bc_shutdown() records exactly when the backchannel RPC client is
destroyed and cl_cb_client is replaced with NULL.

Examples include:

         nfsd-955   [004]   650.013997: nfsd_cb_queue:        addr=192.168.122.6:0 client 65b3c5b8:f541f749 cb=0xffff8881134b02f8 (first try)
kworker/u21:4-497   [004]   650.014050: nfsd_cb_seq_status:   task:00000001@00000001 sessionid=65b3c5b8:f541f749:00000001:00000000 tk_status=-107 seq_status=1
kworker/u21:4-497   [004]   650.014051: nfsd_cb_restart:      addr=192.168.122.6:0 client 65b3c5b8:f541f749 cb=0xffff88810e39f400 (first try)
kworker/u21:4-497   [004]   650.014066: nfsd_cb_queue:        addr=192.168.122.6:0 client 65b3c5b8:f541f749 cb=0xffff88810e39f400 (need restart)

kworker/u16:0-10    [006]   650.065750: nfsd_cb_start:        addr=192.168.122.6:0 client 65b3c5b8:f541f749 state=UNKNOWN
kworker/u16:0-10    [006]   650.065752: nfsd_cb_bc_update:    addr=192.168.122.6:0 client 65b3c5b8:f541f749 cb=0xffff8881134b02f8 (first try)
kworker/u16:0-10    [006]   650.065754: nfsd_cb_bc_shutdown:  addr=192.168.122.6:0 client 65b3c5b8:f541f749 cb=0xffff8881134b02f8 (first try)
kworker/u16:0-10    [006]   650.065810: nfsd_cb_new_state:    addr=192.168.122.6:0 client 65b3c5b8:f541f749 state=DOWN

Reviewed-by: Jeff Layton <jlayton@kernel.org>
Reviewed-by: Benjamin Coddington <bcodding@redhat.com>
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>

diff --git a/fs/nfsd/nfs4callback.c b/fs/nfsd/nfs4callback.c
index a63171ccfc2b8877ce9be5d3124411bc0e55ecd0..b50ce54aa1bfab61540d94e50cd10f2b7b48bdfd 100644 (file)
--- a/fs/nfsd/nfs4callback.c
+++ b/fs/nfsd/nfs4callback.c
@@ -887,12 +887,14 @@ static struct workqueue_struct *callback_wq;
 
 static bool nfsd4_queue_cb(struct nfsd4_callback *cb)
 {
+       trace_nfsd_cb_queue(cb->cb_clp, cb);
        return queue_delayed_work(callback_wq, &cb->cb_work, 0);
 }
 
 static void nfsd4_queue_cb_delayed(struct nfsd4_callback *cb,
                                   unsigned long msecs)
 {
+       trace_nfsd_cb_queue(cb->cb_clp, cb);
        queue_delayed_work(callback_wq, &cb->cb_work,
                           msecs_to_jiffies(msecs));
 }
@@ -1113,6 +1115,7 @@ static void nfsd41_destroy_cb(struct nfsd4_callback *cb)
 {
        struct nfs4_client *clp = cb->cb_clp;
 
+       trace_nfsd_cb_destroy(clp, cb);
        nfsd41_cb_release_slot(cb);
        if (cb->cb_ops && cb->cb_ops->release)
                cb->cb_ops->release(cb);
@@ -1227,6 +1230,7 @@ retry_nowait:
        goto out;
 need_restart:
        if (!test_bit(NFSD4_CLIENT_CB_KILL, &clp->cl_flags)) {
+               trace_nfsd_cb_restart(clp, cb);
                task->tk_status = 0;
                cb->cb_need_restart = true;
        }
@@ -1340,11 +1344,14 @@ static void nfsd4_process_cb_update(struct nfsd4_callback *cb)
        struct nfsd4_conn *c;
        int err;
 
+       trace_nfsd_cb_bc_update(clp, cb);
+
        /*
         * This is either an update, or the client dying; in either case,
         * kill the old client:
         */
        if (clp->cl_cb_client) {
+               trace_nfsd_cb_bc_shutdown(clp, cb);
                rpc_shutdown_client(clp->cl_cb_client);
                clp->cl_cb_client = NULL;
                put_cred(clp->cl_cb_cred);
@@ -1356,6 +1363,7 @@ static void nfsd4_process_cb_update(struct nfsd4_callback *cb)
        }
        if (test_bit(NFSD4_CLIENT_CB_KILL, &clp->cl_flags))
                return;
+
        spin_lock(&clp->cl_lock);
        /*
         * Only serialized callback code is allowed to clear these

diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 6003af2bee33cb7943208cf76622c71368294b5c..9f9e58debc26112598ca55a4be02b9d3d2a49912 100644 (file)
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -1443,6 +1443,48 @@ TRACE_EVENT(nfsd_cb_setup_err,
                __entry->error)
 );
 
+DECLARE_EVENT_CLASS(nfsd_cb_lifetime_class,
+       TP_PROTO(
+               const struct nfs4_client *clp,
+               const struct nfsd4_callback *cb
+       ),
+       TP_ARGS(clp, cb),
+       TP_STRUCT__entry(
+               __field(u32, cl_boot)
+               __field(u32, cl_id)
+               __field(const void *, cb)
+               __field(bool, need_restart)
+               __sockaddr(addr, clp->cl_cb_conn.cb_addrlen)
+       ),
+       TP_fast_assign(
+               __entry->cl_boot = clp->cl_clientid.cl_boot;
+               __entry->cl_id = clp->cl_clientid.cl_id;
+               __entry->cb = cb;
+               __entry->need_restart = cb->cb_need_restart;
+               __assign_sockaddr(addr, &clp->cl_cb_conn.cb_addr,
+                                 clp->cl_cb_conn.cb_addrlen)
+       ),
+       TP_printk("addr=%pISpc client %08x:%08x cb=%p%s",
+               __get_sockaddr(addr), __entry->cl_boot, __entry->cl_id,
+               __entry->cb, __entry->need_restart ?
+                       " (need restart)" : " (first try)"
+       )
+);
+
+#define DEFINE_NFSD_CB_LIFETIME_EVENT(name)            \
+DEFINE_EVENT(nfsd_cb_lifetime_class, nfsd_cb_##name,   \
+       TP_PROTO(                                       \
+               const struct nfs4_client *clp,          \
+               const struct nfsd4_callback *cb         \
+       ),                                              \
+       TP_ARGS(clp, cb))
+
+DEFINE_NFSD_CB_LIFETIME_EVENT(queue);
+DEFINE_NFSD_CB_LIFETIME_EVENT(destroy);
+DEFINE_NFSD_CB_LIFETIME_EVENT(restart);
+DEFINE_NFSD_CB_LIFETIME_EVENT(bc_update);
+DEFINE_NFSD_CB_LIFETIME_EVENT(bc_shutdown);
+
 TRACE_EVENT(nfsd_cb_seq_status,
        TP_PROTO(
                const struct rpc_task *task,

diff --git a/include/trace/misc/nfs.h b/include/trace/misc/nfs.h
index 0d9d48dca38a8949047a72d472700ffcd2bebc20..64ab5dac59ce0c7ea6834e308b307e17e649dc4b 100644 (file)
--- a/include/trace/misc/nfs.h
+++ b/include/trace/misc/nfs.h
@@ -385,3 +385,37 @@ TRACE_DEFINE_ENUM(IOMODE_ANY);
                { SEQ4_STATUS_RESTART_RECLAIM_NEEDED,   "RESTART_RECLAIM_NEEDED" }, \
                { SEQ4_STATUS_CB_PATH_DOWN_SESSION,     "CB_PATH_DOWN_SESSION" }, \
                { SEQ4_STATUS_BACKCHANNEL_FAULT,        "BACKCHANNEL_FAULT" })
+
+TRACE_DEFINE_ENUM(OP_CB_GETATTR);
+TRACE_DEFINE_ENUM(OP_CB_RECALL);
+TRACE_DEFINE_ENUM(OP_CB_LAYOUTRECALL);
+TRACE_DEFINE_ENUM(OP_CB_NOTIFY);
+TRACE_DEFINE_ENUM(OP_CB_PUSH_DELEG);
+TRACE_DEFINE_ENUM(OP_CB_RECALL_ANY);
+TRACE_DEFINE_ENUM(OP_CB_RECALLABLE_OBJ_AVAIL);
+TRACE_DEFINE_ENUM(OP_CB_RECALL_SLOT);
+TRACE_DEFINE_ENUM(OP_CB_SEQUENCE);
+TRACE_DEFINE_ENUM(OP_CB_WANTS_CANCELLED);
+TRACE_DEFINE_ENUM(OP_CB_NOTIFY_LOCK);
+TRACE_DEFINE_ENUM(OP_CB_NOTIFY_DEVICEID);
+TRACE_DEFINE_ENUM(OP_CB_OFFLOAD);
+TRACE_DEFINE_ENUM(OP_CB_ILLEGAL);
+
+#define show_nfs4_cb_op(x) \
+       __print_symbolic(x, \
+               { 0,                            "CB_NULL" }, \
+               { 1,                            "CB_COMPOUND" }, \
+               { OP_CB_GETATTR,                "CB_GETATTR" }, \
+               { OP_CB_RECALL,                 "CB_RECALL" }, \
+               { OP_CB_LAYOUTRECALL,           "CB_LAYOUTRECALL" }, \
+               { OP_CB_NOTIFY,                 "CB_NOTIFY" }, \
+               { OP_CB_PUSH_DELEG,             "CB_PUSH_DELEG" }, \
+               { OP_CB_RECALL_ANY,             "CB_RECALL_ANY" }, \
+               { OP_CB_RECALLABLE_OBJ_AVAIL,   "CB_RECALLABLE_OBJ_AVAIL" }, \
+               { OP_CB_RECALL_SLOT,            "CB_RECALL_SLOT" }, \
+               { OP_CB_SEQUENCE,               "CB_SEQUENCE" }, \
+               { OP_CB_WANTS_CANCELLED,        "CB_WANTS_CANCELLED" }, \
+               { OP_CB_NOTIFY_LOCK,            "CB_NOTIFY_LOCK" }, \
+               { OP_CB_NOTIFY_DEVICEID,        "CB_NOTIFY_DEVICEID" }, \
+               { OP_CB_OFFLOAD,                "CB_OFFLOAD" }, \
+               { OP_CB_ILLEGAL,                "CB_ILLEGAL" })