History

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

Chuck Lever committed 5 years ago

Commit b40887e1 parent d9f87749 files · +2 −17Browse files

Unified · Split

9 files
  1. fs/lockd/clntproc.c +0 −3
  2. fs/lockd/svc4proc.c +0 −2
  3. fs/lockd/svcproc.c +0 −2
  4. fs/nfs/filelayout/filelayout.c +0 −2
  5. fs/nfs/flexfilelayout/flexfilelayout.c +0 −2
  6. fs/nfs/pagelist.c +0 −3
  7. fs/nfs/write.c +0 −3
  8. include/trace/events/sunrpc.h +1 −0
  9. net/sunrpc/sched.c +1 −0
fs/lockd/clntproc.c+0−3
@@ -794,9 +794,6 @@ static void nlmclnt_cancel_callback(struct rpc_task *task, void *data) · 793 unmodified lines
794794 goto retry_cancel;
795795 }
796796
797− dprintk("lockd: cancel status %u (task %u)\n",
798− status, task->tk_pid);
799−
800797 switch (status) {
801798 case NLM_LCK_GRANTED:
802799 case NLM_LCK_DENIED_GRACE_PERIOD:
fs/lockd/svc4proc.c+0−2
@@ -269,8 +269,6 @@ nlm4svc_proc_granted(struct svc_rqst *rqstp) · 268 unmodified lines
269269 */
270270 static void nlm4svc_callback_exit(struct rpc_task *task, void *data)
271271 {
272− dprintk("lockd: %5u callback returned %d\n", task->tk_pid,
273− -task->tk_status);
274272 }
275273
276274 static void nlm4svc_callback_release(void *data)
fs/lockd/svcproc.c+0−2
@@ -301,8 +301,6 @@ nlmsvc_proc_granted(struct svc_rqst *rqstp) · 300 unmodified lines
301301 */
302302 static void nlmsvc_callback_exit(struct rpc_task *task, void *data)
303303 {
304− dprintk("lockd: %5u callback returned %d\n", task->tk_pid,
305− -task->tk_status);
306304 }
307305
308306 void nlmsvc_release_call(struct nlm_rqst *call)
fs/nfs/filelayout/filelayout.c+0−2
@@ -293,8 +293,6 @@ static void filelayout_read_call_done(struct rpc_task *task, void *data) · 292 unmodified lines
293293 {
294294 struct nfs_pgio_header *hdr = data;
295295
296− dprintk("--> %s task->tk_status %d\n", __func__, task->tk_status);
297−
298296 if (test_bit(NFS_IOHDR_REDO, &hdr->flags) &&
299297 task->tk_status == 0) {
300298 nfs41_sequence_done(task, &hdr->res.seq_res);
fs/nfs/flexfilelayout/flexfilelayout.c+0−2
@@ -1414,8 +1414,6 @@ static void ff_layout_read_call_done(struct rpc_task *task, void *data) · 1413 unmodified lines
14141414 {
14151415 struct nfs_pgio_header *hdr = data;
14161416
1417− dprintk("--> %s task->tk_status %d\n", __func__, task->tk_status);
1418−
14191417 if (test_bit(NFS_IOHDR_REDO, &hdr->flags) &&
14201418 task->tk_status == 0) {
14211419 nfs4_sequence_done(task, &hdr->res.seq_res);
fs/nfs/pagelist.c+0−3
@@ -864,9 +864,6 @@ static void nfs_pgio_result(struct rpc_task *task, void *calldata) · 863 unmodified lines
864864 struct nfs_pgio_header *hdr = calldata;
865865 struct inode *inode = hdr->inode;
866866
867− dprintk("NFS: %s: %5u, (status %d)\n", __func__,
868− task->tk_pid, task->tk_status);
869−
870867 if (hdr->rw_ops->rw_done(task, hdr, inode) != 0)
871868 return;
872869 if (task->tk_status < 0)
fs/nfs/write.c+0−3
@@ -1840,9 +1840,6 @@ static void nfs_commit_done(struct rpc_task *task, void *calldata) · 1839 unmodified lines
18401840 {
18411841 struct nfs_commit_data *data = calldata;
18421842
1843− dprintk("NFS: %5u nfs_commit_done (status %d)\n",
1844− task->tk_pid, task->tk_status);
1845−
18461843 /* Call the NFS version-specific code */
18471844 NFS_PROTO(data->inode)->commit_done(task, data);
18481845 trace_nfs_commit_done(task, data);
include/trace/events/sunrpc.h+1−0
@@ -378,6 +378,7 @@ DEFINE_RPC_RUNNING_EVENT(complete); · 377 unmodified lines
378378 DEFINE_RPC_RUNNING_EVENT(timeout);
379379 DEFINE_RPC_RUNNING_EVENT(signalled);
380380 DEFINE_RPC_RUNNING_EVENT(end);
381+DEFINE_RPC_RUNNING_EVENT(call_done);
381382
382383 DECLARE_EVENT_CLASS(rpc_task_queued,
383384
net/sunrpc/sched.c+1−0
@@ -837,6 +837,7 @@ void rpc_exit_task(struct rpc_task *task) · 836 unmodified lines
837837 else if (task->tk_client)
838838 rpc_count_iostats(task, task->tk_client->cl_metrics);
839839 if (task->tk_ops->rpc_call_done != NULL) {
840+ trace_rpc_task_call_done(task, task->tk_ops->rpc_call_done);
840841 task->tk_ops->rpc_call_done(task, task->tk_calldata);
841842 if (task->tk_action != NULL) {
842843 /* Always release the RPC slot and buffer memory */