Received-SPF: pass (google.com: domain of linux-nfs-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
Sender: Chuck Lever <chucklever@gmail.com>
Subject: [PATCH v2 14/27] NFSD: nfsd_compound_status tracepoint should record
 XID
From:   Chuck Lever <chuck.lever@oracle.com>
To:     bfields@fieldses.org, Bill.Baker@oracle.com
Cc:     linux-nfs@vger.kernel.org
Date:   Mon, 21 Sep 2020 14:12:03 -0400
Message-ID: <160071192365.1468.5120570739589347009.stgit@klimt.1015granger.net>
In-Reply-To: <160071167664.1468.1365570508917640511.stgit@klimt.1015granger.net>
References: <160071167664.1468.1365570508917640511.stgit@klimt.1015granger.net>
User-Agent: StGit/0.23
MIME-Version: 1.0
Content-Type: text/plain; charset="utf-8"
Content-Transfer-Encoding: 7bit
Precedence: bulk

The two tracepoints, nfsd_compound and nfsd_compound_status, should
provide matching information, to enable the records to be bracketed
correctly. So, for example:

nfsd-1034  [000]   165.191371: nfsd4_compound:       xid=0xe62d9610 opcnt=4
nfsd-1034  [000]   165.191516: nfsd4_compound_status: xid=0xe62d9610 op=1/4 OP_PUTFH status=OK
nfsd-1034  [000]   165.191637: nfsd4_compound_status: xid=0xe62d9610 op=2/4 OP_CREATE status=OK
nfsd-1034  [000]   165.191639: nfsd4_compound_status: xid=0xe62d9610 op=3/4 OP_GETFH status=OK
nfsd-1034  [000]   165.191680: nfsd4_compound_status: xid=0xe62d9610 op=4/4 OP_GETATTR status=OK

Also, report the status code symbolically instead of numerically for
faster readability.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
 fs/nfsd/nfs4proc.c |    6 ++--
 fs/nfsd/trace.h    |   86 ++++++++++++++++++++++++++++------------------------
 2 files changed, 50 insertions(+), 42 deletions(-)

diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
index e89a51ed2bbf..17a627f97766 100644
--- a/fs/nfsd/nfs4proc.c
+++ b/fs/nfsd/nfs4proc.c
@@ -2371,7 +2371,7 @@ nfsd4_proc_compound(struct svc_rqst *rqstp)
 
 	rqstp->rq_lease_breaker = (void **)&cstate->clp;
 
-	trace_nfsd_compound(rqstp, args->opcnt);
+	trace_nfsd4_compound(rqstp, args->opcnt);
 	while (!status && resp->opcnt < args->opcnt) {
 		op = &args->ops[resp->opcnt++];
 
@@ -2450,8 +2450,8 @@ nfsd4_proc_compound(struct svc_rqst *rqstp)
 			status = op->status;
 		}
 
-		trace_nfsd_compound_status(args->opcnt, resp->opcnt, status,
-					   nfsd4_op_name(op->opnum));
+		trace_nfsd4_compoundstatus(rqstp, args->opcnt, resp->opcnt,
+					   status, nfsd4_op_name(op->opnum));
 
 		nfsd4_cstate_clear_replay(cstate);
 		nfsd4_increment_op_stats(op->opnum);
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 15b97275b3b4..afcb3bcf13f2 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -98,45 +98,6 @@ TRACE_EVENT(nfsd_setattr_args,
 	)
 );
 
-TRACE_EVENT(nfsd_compound,
-	TP_PROTO(const struct svc_rqst *rqst,
-		 u32 args_opcnt),
-	TP_ARGS(rqst, args_opcnt),
-	TP_STRUCT__entry(
-		__field(u32, xid)
-		__field(u32, args_opcnt)
-	),
-	TP_fast_assign(
-		__entry->xid = be32_to_cpu(rqst->rq_xid);
-		__entry->args_opcnt = args_opcnt;
-	),
-	TP_printk("xid=0x%08x opcnt=%u",
-		__entry->xid, __entry->args_opcnt)
-)
-
-TRACE_EVENT(nfsd_compound_status,
-	TP_PROTO(u32 args_opcnt,
-		 u32 resp_opcnt,
-		 __be32 status,
-		 const char *name),
-	TP_ARGS(args_opcnt, resp_opcnt, status, name),
-	TP_STRUCT__entry(
-		__field(u32, args_opcnt)
-		__field(u32, resp_opcnt)
-		__field(int, status)
-		__string(name, name)
-	),
-	TP_fast_assign(
-		__entry->args_opcnt = args_opcnt;
-		__entry->resp_opcnt = resp_opcnt;
-		__entry->status = be32_to_cpu(status);
-		__assign_str(name, name);
-	),
-	TP_printk("op=%u/%u %s status=%d",
-		__entry->resp_opcnt, __entry->args_opcnt,
-		__get_str(name), __entry->status)
-)
-
 DECLARE_EVENT_CLASS(nfsd_fh_err_class,
 	TP_PROTO(struct svc_rqst *rqstp,
 		 struct svc_fh	*fhp,
@@ -333,6 +294,53 @@ DEFINE_EVENT(nfsd_err_class, nfsd_##name,	\
 DEFINE_NFSD_ERR_EVENT(read_err);
 DEFINE_NFSD_ERR_EVENT(write_err);
 
+TRACE_EVENT(nfsd4_compound,
+	TP_PROTO(
+		const struct svc_rqst *rqstp,
+		 u32 args_opcnt
+	),
+	TP_ARGS(rqstp, args_opcnt),
+	TP_STRUCT__entry(
+		__field(u32, xid)
+		__field(u32, args_opcnt)
+	),
+	TP_fast_assign(
+		__entry->xid = be32_to_cpu(rqstp->rq_xid);
+		__entry->args_opcnt = args_opcnt;
+	),
+	TP_printk("xid=0x%08x opcnt=%u",
+		__entry->xid, __entry->args_opcnt)
+)
+
+TRACE_EVENT(nfsd4_compoundstatus,
+	TP_PROTO(
+		 const struct svc_rqst *rqstp,
+		 u32 args_opcnt,
+		 u32 resp_opcnt,
+		 __be32 status,
+		 const char *name
+	),
+	TP_ARGS(rqstp, args_opcnt, resp_opcnt, status, name),
+	TP_STRUCT__entry(
+		__field(u32, xid)
+		__field(u32, args_opcnt)
+		__field(u32, resp_opcnt)
+		__field(int, status)
+		__string(name, name)
+	),
+	TP_fast_assign(
+		__entry->xid = be32_to_cpu(rqstp->rq_xid);
+		__entry->args_opcnt = args_opcnt;
+		__entry->resp_opcnt = resp_opcnt;
+		__entry->status = be32_to_cpu(status);
+		__assign_str(name, name);
+	),
+	TP_printk("xid=0x%08x op=%u/%u %s status=%s",
+		__entry->xid, __entry->resp_opcnt, __entry->args_opcnt,
+		__get_str(name), show_nfs4_status(__entry->status)
+	)
+)
+
 #include "state.h"
 #include "filecache.h"
 #include "vfs.h"