SUNRPC: Trace calls to .rpc_call_done

Introduce a single tracepoint that can replace simple dprintk call
sites in upper layer "rpc_call_done" callbacks. Example:

   kworker/u24:2-1254  [001]   771.026677: rpc_stats_latency:    task:00000001@00000002 xid=0x16a6f3c0 rpcbindv2 GETPORT backlog=446 rtt=101 execute=555
   kworker/u24:2-1254  [001]   771.026677: rpc_task_call_done:   task:00000001@00000002 flags=ASYNC|DYNAMIC|SOFT|SOFTCONN|SENT runstate=RUNNING|ACTIVE status=0 action=rpcb_getport_done
   kworker/u24:2-1254  [001]   771.026678: rpcb_setport:         task:00000001@00000002 status=0 port=20048

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Signed-off-by: Trond Myklebust <trond.myklebust@hammerspace.com>

diff --git a/fs/lockd/clntproc.c b/fs/lockd/clntproc.c
index b11f2afa84f1f453b7d441bd52171552c6b6cbf6..99fffc9cb9585cdad7ae80336cac42674e818d5d 100644 (file)
--- a/fs/lockd/clntproc.c
+++ b/fs/lockd/clntproc.c
@@ -794,9 +794,6 @@ static void nlmclnt_cancel_callback(struct rpc_task *task, void *data)
                goto retry_cancel;
        }
 
-       dprintk("lockd: cancel status %u (task %u)\n",
-                       status, task->tk_pid);
-
        switch (status) {
        case NLM_LCK_GRANTED:
        case NLM_LCK_DENIED_GRACE_PERIOD:

diff --git a/fs/lockd/svc4proc.c b/fs/lockd/svc4proc.c
index e10ae2c41279e46ef9de58fb04c7b4206afefc28..176b468a61c757ba3ac5801fcb173f9cd31c9bae 100644 (file)
--- a/fs/lockd/svc4proc.c
+++ b/fs/lockd/svc4proc.c
@@ -269,8 +269,6 @@ nlm4svc_proc_granted(struct svc_rqst *rqstp)
  */
 static void nlm4svc_callback_exit(struct rpc_task *task, void *data)
 {
-       dprintk("lockd: %5u callback returned %d\n", task->tk_pid,
-                       -task->tk_status);
 }
 
 static void nlm4svc_callback_release(void *data)

diff --git a/fs/lockd/svcproc.c b/fs/lockd/svcproc.c
index 99696d3f6dd66566491759d0f2db1d12a5e15ff3..4dc1b40a489a2ab49139ba3fe11750047204aa33 100644 (file)
--- a/fs/lockd/svcproc.c
+++ b/fs/lockd/svcproc.c
@@ -301,8 +301,6 @@ nlmsvc_proc_granted(struct svc_rqst *rqstp)
  */
 static void nlmsvc_callback_exit(struct rpc_task *task, void *data)
 {
-       dprintk("lockd: %5u callback returned %d\n", task->tk_pid,
-                       -task->tk_status);
 }
 
 void nlmsvc_release_call(struct nlm_rqst *call)

diff --git a/fs/nfs/filelayout/filelayout.c b/fs/nfs/filelayout/filelayout.c
index d2103852475fa0f82cbf09fbefea870e46a8474d..9c96e3e5ed3524b2bf5a400b24c5650349fd17d2 100644 (file)
--- a/fs/nfs/filelayout/filelayout.c
+++ b/fs/nfs/filelayout/filelayout.c
@@ -293,8 +293,6 @@ static void filelayout_read_call_done(struct rpc_task *task, void *data)
 {
        struct nfs_pgio_header *hdr = data;
 
-       dprintk("--> %s task->tk_status %d\n", __func__, task->tk_status);
-
        if (test_bit(NFS_IOHDR_REDO, &hdr->flags) &&
            task->tk_status == 0) {
                nfs41_sequence_done(task, &hdr->res.seq_res);

diff --git a/fs/nfs/flexfilelayout/flexfilelayout.c b/fs/nfs/flexfilelayout/flexfilelayout.c
index d383de00d4868fc569c7a9435868d8a7a26d6a7e..a553d59afa8b8a00e81516f76c47ec5cd2baba45 100644 (file)
--- a/fs/nfs/flexfilelayout/flexfilelayout.c
+++ b/fs/nfs/flexfilelayout/flexfilelayout.c
@@ -1414,8 +1414,6 @@ static void ff_layout_read_call_done(struct rpc_task *task, void *data)
 {
        struct nfs_pgio_header *hdr = data;
 
-       dprintk("--> %s task->tk_status %d\n", __func__, task->tk_status);
-
        if (test_bit(NFS_IOHDR_REDO, &hdr->flags) &&
            task->tk_status == 0) {
                nfs4_sequence_done(task, &hdr->res.seq_res);

diff --git a/fs/nfs/pagelist.c b/fs/nfs/pagelist.c
index 72333bcaa4c432712dfc2bdb5af20d486fe42908..ad7f83dc9a2dfe71b78cf408b05bc3f72f6b8b35 100644 (file)
--- a/fs/nfs/pagelist.c
+++ b/fs/nfs/pagelist.c
@@ -864,9 +864,6 @@ static void nfs_pgio_result(struct rpc_task *task, void *calldata)
        struct nfs_pgio_header *hdr = calldata;
        struct inode *inode = hdr->inode;
 
-       dprintk("NFS: %s: %5u, (status %d)\n", __func__,
-               task->tk_pid, task->tk_status);
-
        if (hdr->rw_ops->rw_done(task, hdr, inode) != 0)
                return;
        if (task->tk_status < 0)

diff --git a/fs/nfs/write.c b/fs/nfs/write.c
index 465220f47142cef8725895dc73c9c4013d3d29b2..82c5b89395f674b97bf1eaf410ec86593a1a40d0 100644 (file)
--- a/fs/nfs/write.c
+++ b/fs/nfs/write.c
@@ -1840,9 +1840,6 @@ static void nfs_commit_done(struct rpc_task *task, void *calldata)
 {
        struct nfs_commit_data  *data = calldata;
 
-        dprintk("NFS: %5u nfs_commit_done (status %d)\n",
-                                task->tk_pid, task->tk_status);
-
        /* Call the NFS version-specific code */
        NFS_PROTO(data->inode)->commit_done(task, data);
        trace_nfs_commit_done(task, data);

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index f8b12eb0769332c8c2a90e872ca47d53ec1752c6..dc922e6648204c4affc883ee7e7384f39700414a 100644 (file)
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -378,6 +378,7 @@ DEFINE_RPC_RUNNING_EVENT(complete);
 DEFINE_RPC_RUNNING_EVENT(timeout);
 DEFINE_RPC_RUNNING_EVENT(signalled);
 DEFINE_RPC_RUNNING_EVENT(end);
+DEFINE_RPC_RUNNING_EVENT(call_done);
 
 DECLARE_EVENT_CLASS(rpc_task_queued,
 

diff --git a/net/sunrpc/sched.c b/net/sunrpc/sched.c
index f4f311ea7a66c6c1d1e03ac88ac6cbbfaf811f81..e2c835482791e3c31cb639ee5999f5a03e1b90f6 100644 (file)
--- a/net/sunrpc/sched.c
+++ b/net/sunrpc/sched.c
@@ -837,6 +837,7 @@ void rpc_exit_task(struct rpc_task *task)
        else if (task->tk_client)
                rpc_count_iostats(task, task->tk_client->cl_metrics);
        if (task->tk_ops->rpc_call_done != NULL) {
+               trace_rpc_task_call_done(task, task->tk_ops->rpc_call_done);
                task->tk_ops->rpc_call_done(task, task->tk_calldata);
                if (task->tk_action != NULL) {
                        /* Always release the RPC slot and buffer memory */