[PATCH v2 00/12] nfsd: observability improvements

[PATCH v2 00/12] nfsd: observability improvements

[Jeff Layton]

While troubleshooting a performance problem internally, it became
evident that we needed tracepoints in nfsd_commit. The first patch adds
that. While discussing that, Sargun pointed out some tracepoints he
added using kprobes. Those are converted to static tracepoints here, and
the legacy dprintk's removed.

Lastly, I've updated the svc_xprt_dequeue tracepoint to show how long
the xprt sat on the queue before being serviced.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
Changes in v2:
- Break tracepoints out into multiple patches
- Flesh out the tracepoints in these locations to display the same info
  as legacy dprintks.
- have all the tracepoints SVC_XPRT_ENDPOINT_* info
- update svc_xprt_dequeue tracepoint to show how long xprt was on queue
- Link to v1: https://lore.kernel.org/r/20250306-nfsd-tracepoints-v1-0-4405bf41b95f@kernel.org

---
Jeff Layton (12):
      nfsd: add commit start/done tracepoints around nfsd_commit()
      sunrpc: add info about xprt queue times to svc_xprt_dequeue tracepoint
      sunrpc: move the SVC_RQST_EVENT_*() macros to common header
      nfsd: add a tracepoint for nfsd_setattr
      nfsd: add a tracepoint to nfsd_lookup_dentry
      nfsd: add tracepoints around nfsd_create events
      nfsd: add tracepoints for symlink events
      nfsd: add tracepoints for hardlink events
      nfsd: add tracepoints for unlink events
      nfsd: add tracepoints to rename events
      nfsd: add tracepoints for readdir events
      nfsd: add tracepoint for getattr events

 fs/nfsd/nfs3proc.c              |  67 +++------
 fs/nfsd/nfs4proc.c              |  45 ++++++
 fs/nfsd/nfsproc.c               |  39 ++----
 fs/nfsd/trace.h                 | 298 ++++++++++++++++++++++++++++++++++++++++
 fs/nfsd/vfs.c                   |  10 +-
 include/linux/sunrpc/svc_xprt.h |   1 +
 include/trace/events/sunrpc.h   |  36 +----
 include/trace/misc/fs.h         |  21 +++
 include/trace/misc/sunrpc.h     |  23 ++++
 net/sunrpc/svc_xprt.c           |   1 +
 10 files changed, 433 insertions(+), 108 deletions(-)
---
base-commit: 71238ba71a67aab408cfe14b6a5ae3c9b83082f9
change-id: 20250303-nfsd-tracepoints-c82add9155a6

Best regards,
-- 
Jeff Layton <jlayton@kernel.org>

[PATCH v2 01/12] nfsd: add commit start/done tracepoints around nfsd_commit()

[Jeff Layton]

Very useful for gauging how long the vfs_fsync_range() takes.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/trace.h | 2 ++
 fs/nfsd/vfs.c   | 3 +++
 2 files changed, 5 insertions(+)

diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index a7630e9f657776a9335ba68ad223641e3ed9121a..0d49fc064f7273f32c93732a993fd77bc0783f5d 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -451,6 +451,8 @@ DEFINE_NFSD_IO_EVENT(write_start);
 DEFINE_NFSD_IO_EVENT(write_opened);
 DEFINE_NFSD_IO_EVENT(write_io_done);
 DEFINE_NFSD_IO_EVENT(write_done);
+DEFINE_NFSD_IO_EVENT(commit_start);
+DEFINE_NFSD_IO_EVENT(commit_done);
 
 DECLARE_EVENT_CLASS(nfsd_err_class,
 	TP_PROTO(struct svc_rqst *rqstp,
diff --git a/fs/nfsd/vfs.c b/fs/nfsd/vfs.c
index 86e199a758f6c69c508151fb14886f4b5da9c080..d1156a18a79579bf427fe5809dc93d06e241201e 100644
--- a/fs/nfsd/vfs.c
+++ b/fs/nfsd/vfs.c
@@ -1366,6 +1366,8 @@ nfsd_commit(struct svc_rqst *rqstp, struct svc_fh *fhp, struct nfsd_file *nf,
 	loff_t			start, end;
 	struct nfsd_net		*nn;
 
+	trace_nfsd_commit_start(rqstp, fhp, offset, count);
+
 	/*
 	 * Convert the client-provided (offset, count) range to a
 	 * (start, end) range. If the client-provided range falls
@@ -1404,6 +1406,7 @@ nfsd_commit(struct svc_rqst *rqstp, struct svc_fh *fhp, struct nfsd_file *nf,
 	} else
 		nfsd_copy_write_verifier(verf, nn);
 
+	trace_nfsd_commit_done(rqstp, fhp, offset, count);
 	return err;
 }
 

-- 
2.49.0

[PATCH v2 02/12] sunrpc: add info about xprt queue times to svc_xprt_dequeue tracepoint

[Jeff Layton]

Currently, this tracepoint displays "wakeup-us", which is the time that
the woken thread spent sleeping, before dequeueing the next xprt. Add a
new statistic that shows how long the xprt sat on the queue before being
serviced.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 include/linux/sunrpc/svc_xprt.h |  1 +
 include/trace/events/sunrpc.h   | 13 +++++++------
 net/sunrpc/svc_xprt.c           |  1 +
 3 files changed, 9 insertions(+), 6 deletions(-)

diff --git a/include/linux/sunrpc/svc_xprt.h b/include/linux/sunrpc/svc_xprt.h
index 72be609525796792274d5b8cb5ff37f73723fc23..369a89aea18618748607ee943247c327bf62c8d5 100644
--- a/include/linux/sunrpc/svc_xprt.h
+++ b/include/linux/sunrpc/svc_xprt.h
@@ -53,6 +53,7 @@ struct svc_xprt {
 	struct svc_xprt_class	*xpt_class;
 	const struct svc_xprt_ops *xpt_ops;
 	struct kref		xpt_ref;
+	ktime_t			xpt_qtime;
 	struct list_head	xpt_list;
 	struct lwq_node		xpt_ready;
 	unsigned long		xpt_flags;
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 5d331383047b79b9f6dcd699c87287453c1a5f49..b5a0f0bc1a3b7cfd90ce0181a8a419db810988bb 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -2040,19 +2040,20 @@ TRACE_EVENT(svc_xprt_dequeue,
 
 	TP_STRUCT__entry(
 		SVC_XPRT_ENDPOINT_FIELDS(rqst->rq_xprt)
-
 		__field(unsigned long, wakeup)
+		__field(unsigned long, qtime)
 	),
 
 	TP_fast_assign(
-		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
+		ktime_t ktime = ktime_get();
 
-		__entry->wakeup = ktime_to_us(ktime_sub(ktime_get(),
-							rqst->rq_qtime));
+		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
+		__entry->wakeup = ktime_to_us(ktime_sub(ktime, rqst->rq_qtime));
+		__entry->qtime = ktime_to_us(ktime_sub(ktime, rqst->rq_xprt->xpt_qtime));
 	),
 
-	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu",
-		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup)
+	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu qtime=%lu",
+		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup, __entry->qtime)
 );
 
 DECLARE_EVENT_CLASS(svc_xprt_event,
diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
index ae25405d8bd22672a361d1fd3adfdcebb403f90f..32018557797b1f683d8b7259f5fccd029aebcd71 100644
--- a/net/sunrpc/svc_xprt.c
+++ b/net/sunrpc/svc_xprt.c
@@ -488,6 +488,7 @@ void svc_xprt_enqueue(struct svc_xprt *xprt)
 	pool = svc_pool_for_cpu(xprt->xpt_server);
 
 	percpu_counter_inc(&pool->sp_sockets_queued);
+	xprt->xpt_qtime = ktime_get();
 	lwq_enqueue(&xprt->xpt_ready, &pool->sp_xprts);
 
 	svc_pool_wake_idle_thread(pool);

-- 
2.49.0

[PATCH v2 03/12] sunrpc: move the SVC_RQST_EVENT_*() macros to common header

[Jeff Layton]

We need this for some of the nfsd tracepoints, so move them to the
common misc/sunrpc.h infrastructure.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 include/trace/events/sunrpc.h | 23 -----------------------
 include/trace/misc/sunrpc.h   | 23 +++++++++++++++++++++++
 2 files changed, 23 insertions(+), 23 deletions(-)

diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index b5a0f0bc1a3b7cfd90ce0181a8a419db810988bb..bd6a1e3631c291c55bde37cb73d2086d9b15c5de 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -1716,29 +1716,6 @@ TRACE_DEFINE_ENUM(SVC_COMPLETE);
 		{ SVC_PENDING,	"SVC_PENDING" },	\
 		{ SVC_COMPLETE,	"SVC_COMPLETE" })
 
-#define SVC_RQST_ENDPOINT_FIELDS(r) \
-		__sockaddr(server, (r)->rq_xprt->xpt_locallen) \
-		__sockaddr(client, (r)->rq_xprt->xpt_remotelen) \
-		__field(unsigned int, netns_ino) \
-		__field(u32, xid)
-
-#define SVC_RQST_ENDPOINT_ASSIGNMENTS(r) \
-		do { \
-			struct svc_xprt *xprt = (r)->rq_xprt; \
-			__assign_sockaddr(server, &xprt->xpt_local, \
-					  xprt->xpt_locallen); \
-			__assign_sockaddr(client, &xprt->xpt_remote, \
-					  xprt->xpt_remotelen); \
-			__entry->netns_ino = xprt->xpt_net->ns.inum; \
-			__entry->xid = be32_to_cpu((r)->rq_xid); \
-		} while (0)
-
-#define SVC_RQST_ENDPOINT_FORMAT \
-		"xid=0x%08x server=%pISpc client=%pISpc"
-
-#define SVC_RQST_ENDPOINT_VARARGS \
-		__entry->xid, __get_sockaddr(server), __get_sockaddr(client)
-
 TRACE_EVENT_CONDITION(svc_authenticate,
 	TP_PROTO(
 		const struct svc_rqst *rqst,
diff --git a/include/trace/misc/sunrpc.h b/include/trace/misc/sunrpc.h
index 588557d07ea820116219cf8ac7b049976a7d89b1..c3c8feede26087bad9b4c8dd0019606ee9982259 100644
--- a/include/trace/misc/sunrpc.h
+++ b/include/trace/misc/sunrpc.h
@@ -15,4 +15,27 @@
 #define SUNRPC_TRACE_TASK_SPECIFIER \
 	"task:" SUNRPC_TRACE_PID_SPECIFIER "@" SUNRPC_TRACE_CLID_SPECIFIER
 
+#define SVC_RQST_ENDPOINT_FIELDS(r) \
+		__sockaddr(server, (r)->rq_xprt->xpt_locallen) \
+		__sockaddr(client, (r)->rq_xprt->xpt_remotelen) \
+		__field(unsigned int, netns_ino) \
+		__field(u32, xid)
+
+#define SVC_RQST_ENDPOINT_ASSIGNMENTS(r) \
+		do { \
+			struct svc_xprt *xprt = (r)->rq_xprt; \
+			__assign_sockaddr(server, &xprt->xpt_local, \
+					  xprt->xpt_locallen); \
+			__assign_sockaddr(client, &xprt->xpt_remote, \
+					  xprt->xpt_remotelen); \
+			__entry->netns_ino = xprt->xpt_net->ns.inum; \
+			__entry->xid = be32_to_cpu((r)->rq_xid); \
+		} while (0)
+
+#define SVC_RQST_ENDPOINT_FORMAT \
+		"xid=0x%08x server=%pISpc client=%pISpc"
+
+#define SVC_RQST_ENDPOINT_VARARGS \
+		__entry->xid, __get_sockaddr(server), __get_sockaddr(client)
+
 #endif /* _TRACE_SUNRPC_BASE_H */

-- 
2.49.0

[PATCH v2 04/12] nfsd: add a tracepoint for nfsd_setattr

[Jeff Layton]

Turn Sargun's internal kprobe based implementation of this into a normal
static tracepoint. Also, remove the dprintk's that got added recently
with the fix for zero-length ACLs.

Cc: Sargun Dillon <sargun@sargun.me>
Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/trace.h         | 35 +++++++++++++++++++++++++++++++++++
 fs/nfsd/vfs.c           |  5 ++---
 include/trace/misc/fs.h | 21 +++++++++++++++++++++
 3 files changed, 58 insertions(+), 3 deletions(-)

diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 0d49fc064f7273f32c93732a993fd77bc0783f5d..c496fed58e2eed15458f35a158fbfef39a972c55 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -11,6 +11,7 @@
 #include <linux/tracepoint.h>
 #include <linux/sunrpc/clnt.h>
 #include <linux/sunrpc/xprt.h>
+#include <trace/misc/fs.h>
 #include <trace/misc/nfs.h>
 #include <trace/misc/sunrpc.h>
 
@@ -2337,6 +2338,40 @@ DEFINE_EVENT(nfsd_copy_async_done_class,		\
 DEFINE_COPY_ASYNC_DONE_EVENT(done);
 DEFINE_COPY_ASYNC_DONE_EVENT(cancel);
 
+TRACE_EVENT(nfsd_setattr,
+	TP_PROTO(const struct svc_rqst *rqstp, const struct svc_fh *fhp,
+		 const struct iattr *iap, const struct timespec64 *guardtime),
+	TP_ARGS(rqstp, fhp, iap, guardtime),
+	TP_STRUCT__entry(
+		SVC_RQST_ENDPOINT_FIELDS(rqstp)
+		__field(u32, fh_hash)
+		__field(s64, gtime_tv_sec)
+		__field(u32, gtime_tv_nsec)
+		__field(unsigned int, ia_valid)
+		__field(loff_t, ia_size)
+		__field(uid_t, ia_uid)
+		__field(gid_t, ia_gid)
+		__field(umode_t, ia_mode)
+	),
+	TP_fast_assign(__entry->xid = be32_to_cpu(rqstp->rq_xid);
+		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
+		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
+		__entry->gtime_tv_sec = guardtime ? guardtime->tv_sec : 0;
+		__entry->gtime_tv_nsec = guardtime ? guardtime->tv_nsec : 0;
+		__entry->ia_valid = iap->ia_valid;
+		__entry->ia_size = iap->ia_size;
+		__entry->ia_uid = __kuid_val(iap->ia_uid);
+		__entry->ia_gid = __kgid_val(iap->ia_gid);
+		__entry->ia_mode = iap->ia_mode;
+	),
+	TP_printk(
+		"xid=0x%08x fh_hash=0x%08x ia_valid=%s ia_size=%llu ia_mode=0%o ia_uid=%u ia_gid=%u guard_time=%lld.%u",
+		__entry->xid, __entry->fh_hash, show_ia_valid_flags(__entry->ia_valid),
+		__entry->ia_size, __entry->ia_mode, __entry->ia_uid, __entry->ia_gid,
+		__entry->gtime_tv_sec, __entry->gtime_tv_nsec
+	)
+)
+
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH
diff --git a/fs/nfsd/vfs.c b/fs/nfsd/vfs.c
index d1156a18a79579bf427fe5809dc93d06e241201e..77ae22abc1a21ec587cf089b2a5f750464b5e985 100644
--- a/fs/nfsd/vfs.c
+++ b/fs/nfsd/vfs.c
@@ -501,7 +501,8 @@ nfsd_setattr(struct svc_rqst *rqstp, struct svc_fh *fhp,
 	bool		size_change = (iap->ia_valid & ATTR_SIZE);
 	int		retries;
 
-dprintk("nfsd_setattr pacl=%p valid=0x%x\n", attr->na_pacl, iap->ia_valid);
+	trace_nfsd_setattr(rqstp, fhp, iap, guardtime);
+
 	if (iap->ia_valid & ATTR_SIZE) {
 		accmode |= NFSD_MAY_WRITE|NFSD_MAY_OWNER_OVERRIDE;
 		ftype = S_IFREG;
@@ -597,7 +598,6 @@ dprintk("nfsd_setattr pacl=%p valid=0x%x\n", attr->na_pacl, iap->ia_valid);
 						NULL);
 	}
 	if (IS_ENABLED(CONFIG_FS_POSIX_ACL) && attr->na_pacl) {
-dprintk("at set_posix_acl\n");
 		/*
 		 * For any file system that is not ACL_SCOPE_FILE_OBJECT,
 		 * a_count == 0 MUST reply nfserr_inval.
@@ -612,7 +612,6 @@ dprintk("at set_posix_acl\n");
 							attr->na_pacl);
 		else
 			attr->na_paclerr = -EINVAL;
-dprintk("set_posix_acl=%d\n", attr->na_paclerr);
 	}
 out_fill_attrs:
 	/*
diff --git a/include/trace/misc/fs.h b/include/trace/misc/fs.h
index 738b97f22f3651f2370830037a8f4bfdf9a42ad4..0406ebe2a80a499dfcadb7e63db4d9e4a84d4d64 100644
--- a/include/trace/misc/fs.h
+++ b/include/trace/misc/fs.h
@@ -120,3 +120,24 @@
 		{ LOOKUP_BENEATH,	"BENEATH" }, \
 		{ LOOKUP_IN_ROOT,	"IN_ROOT" }, \
 		{ LOOKUP_CACHED,	"CACHED" })
+
+#define show_ia_valid_flags(flags)			\
+	__print_flags(flags, "|",			\
+		{ ATTR_MODE,		"MODE" },	\
+		{ ATTR_UID,		"UID" },	\
+		{ ATTR_GID,		"GID" },	\
+		{ ATTR_SIZE,		"SIZE" },	\
+		{ ATTR_ATIME,		"ATIME" },	\
+		{ ATTR_MTIME,		"MTIME" },	\
+		{ ATTR_CTIME,		"CTIME" },	\
+		{ ATTR_ATIME_SET,	"ATIME_SET" },	\
+		{ ATTR_MTIME_SET,	"MTIME_SET" },	\
+		{ ATTR_FORCE,		"FORCE" },	\
+		{ ATTR_KILL_SUID,	"KILL_SUID" },	\
+		{ ATTR_KILL_SGID,	"KILL_SGID" },	\
+		{ ATTR_FILE,		"FILE" },	\
+		{ ATTR_KILL_PRIV,	"KILL_PRIV" },	\
+		{ ATTR_OPEN,		"OPEN" },	\
+		{ ATTR_TIMES_SET,	"TIMES_SET" },	\
+		{ ATTR_TOUCH,		"TOUCH"},	\
+		{ ATTR_DELEG,		"DELEG"})

-- 
2.49.0

[PATCH v2 05/12] nfsd: add a tracepoint to nfsd_lookup_dentry

[Jeff Layton]

...and drop the dprintk.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/trace.h | 19 +++++++++++++++++++
 fs/nfsd/vfs.c   |  2 +-
 2 files changed, 20 insertions(+), 1 deletion(-)

diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index c496fed58e2eed15458f35a158fbfef39a972c55..382849d7c321d6ded8213890c2e7075770aa716c 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -2372,6 +2372,25 @@ TRACE_EVENT(nfsd_setattr,
 	)
 )
 
+TRACE_EVENT(nfsd_lookup_dentry,
+	TP_PROTO(struct svc_rqst *rqstp,
+		 struct svc_fh *fhp,
+		 const char *name,
+		 unsigned int len),
+	TP_ARGS(rqstp, fhp, name, len),
+	TP_STRUCT__entry(
+		SVC_RQST_ENDPOINT_FIELDS(rqstp)
+		__field(u32, fh_hash)
+		__string_len(name, name, len)
+	),
+	TP_fast_assign(
+		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
+		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
+		__assign_str(name);
+	),
+	TP_printk("xid=0x%08x fh_hash=0x%08x name=%s",
+		  __entry->xid, __entry->fh_hash, __get_str(name))
+);
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH
diff --git a/fs/nfsd/vfs.c b/fs/nfsd/vfs.c
index 77ae22abc1a21ec587cf089b2a5f750464b5e985..2b96806111d6a45b351707db6a93219cb91d45f5 100644
--- a/fs/nfsd/vfs.c
+++ b/fs/nfsd/vfs.c
@@ -246,7 +246,7 @@ nfsd_lookup_dentry(struct svc_rqst *rqstp, struct svc_fh *fhp,
 	struct dentry		*dentry;
 	int			host_err;
 
-	dprintk("nfsd: nfsd_lookup(fh %s, %.*s)\n", SVCFH_fmt(fhp), len,name);
+	trace_nfsd_lookup_dentry(rqstp, fhp, name, len);
 
 	dparent = fhp->fh_dentry;
 	exp = exp_get(fhp->fh_export);

-- 
2.49.0

[PATCH v2 06/12] nfsd: add tracepoints around nfsd_create events

[Jeff Layton]

...and remove the legacy dprintks.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/nfs3proc.c | 18 +++++-------------
 fs/nfsd/nfs4proc.c | 29 +++++++++++++++++++++++++++++
 fs/nfsd/nfsproc.c  |  6 +++---
 fs/nfsd/trace.h    | 39 +++++++++++++++++++++++++++++++++++++++
 4 files changed, 76 insertions(+), 16 deletions(-)

diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
index 372bdcf5e07a5c835da240ecebb02e3576eb2ca6..ea1280970ea11b2a82f0de88ad0422eef7063d6d 100644
--- a/fs/nfsd/nfs3proc.c
+++ b/fs/nfsd/nfs3proc.c
@@ -14,6 +14,7 @@
 #include "xdr3.h"
 #include "vfs.h"
 #include "filecache.h"
+#include "trace.h"
 
 #define NFSDDBG_FACILITY		NFSDDBG_PROC
 
@@ -380,10 +381,7 @@ nfsd3_proc_create(struct svc_rqst *rqstp)
 	struct nfsd3_diropres *resp = rqstp->rq_resp;
 	svc_fh *dirfhp, *newfhp;
 
-	dprintk("nfsd: CREATE(3)   %s %.*s\n",
-				SVCFH_fmt(&argp->fh),
-				argp->len,
-				argp->name);
+	trace_nfsd3_proc_create(rqstp, &argp->fh, S_IFREG, argp->name, argp->len);
 
 	dirfhp = fh_copy(&resp->dirfh, &argp->fh);
 	newfhp = fh_init(&resp->fh, NFS3_FHSIZE);
@@ -405,10 +403,7 @@ nfsd3_proc_mkdir(struct svc_rqst *rqstp)
 		.na_iattr	= &argp->attrs,
 	};
 
-	dprintk("nfsd: MKDIR(3)    %s %.*s\n",
-				SVCFH_fmt(&argp->fh),
-				argp->len,
-				argp->name);
+	trace_nfsd3_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
 
 	argp->attrs.ia_valid &= ~ATTR_SIZE;
 	fh_copy(&resp->dirfh, &argp->fh);
@@ -471,13 +466,10 @@ nfsd3_proc_mknod(struct svc_rqst *rqstp)
 	struct nfsd_attrs attrs = {
 		.na_iattr	= &argp->attrs,
 	};
-	int type;
+	int type = nfs3_ftypes[argp->ftype];
 	dev_t	rdev = 0;
 
-	dprintk("nfsd: MKNOD(3)    %s %.*s\n",
-				SVCFH_fmt(&argp->fh),
-				argp->len,
-				argp->name);
+	trace_nfsd3_proc_mknod(rqstp, &argp->fh, type, argp->name, argp->len);
 
 	fh_copy(&resp->dirfh, &argp->fh);
 	fh_init(&resp->fh, NFS3_FHSIZE);
diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
index 6e23d6103010197c0316b07c189fe12ec3033812..2c795103deaa4044596bd07d90db788169a32a0c 100644
--- a/fs/nfsd/nfs4proc.c
+++ b/fs/nfsd/nfs4proc.c
@@ -250,6 +250,8 @@ nfsd4_create_file(struct svc_rqst *rqstp, struct svc_fh *fhp,
 	__be32 status;
 	int host_err;
 
+	trace_nfsd4_create_file(rqstp, fhp, S_IFREG, open->op_fname, open->op_fnamelen);
+
 	if (isdotent(open->op_fname, open->op_fnamelen))
 		return nfserr_exist;
 	if (!(iap->ia_valid & ATTR_MODE))
@@ -807,6 +809,29 @@ nfsd4_commit(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	return status;
 }
 
+static umode_t nfs_type_to_vfs_type(enum nfs_ftype4 nfstype)
+{
+	switch (nfstype) {
+	case NF4REG:
+		return S_IFREG;
+	case NF4DIR:
+		return S_IFDIR;
+	case NF4BLK:
+		return S_IFBLK;
+	case NF4CHR:
+		return S_IFCHR;
+	case NF4LNK:
+		return S_IFLNK;
+	case NF4SOCK:
+		return S_IFSOCK;
+	case NF4FIFO:
+		return S_IFIFO;
+	default:
+		break;
+	}
+	return 0;
+}
+
 static __be32
 nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	     union nfsd4_op_u *u)
@@ -822,6 +847,10 @@ nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	__be32 status;
 	dev_t rdev;
 
+	trace_nfsd4_create(rqstp, &cstate->current_fh,
+			   nfs_type_to_vfs_type(create->cr_type),
+			   create->cr_name, create->cr_namelen);
+
 	fh_init(&resfh, NFS4_FHSIZE);
 
 	status = fh_verify(rqstp, &cstate->current_fh, S_IFDIR, NFSD_MAY_NOP);
diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
index 6dda081eb24c00b834ab0965c3a35a12115bceb7..33d8cbf8785588d38d4ec5efd769c1d1d06c6a91 100644
--- a/fs/nfsd/nfsproc.c
+++ b/fs/nfsd/nfsproc.c
@@ -10,6 +10,7 @@
 #include "cache.h"
 #include "xdr.h"
 #include "vfs.h"
+#include "trace.h"
 
 #define NFSDDBG_FACILITY		NFSDDBG_PROC
 
@@ -292,8 +293,7 @@ nfsd_proc_create(struct svc_rqst *rqstp)
 	int		hosterr;
 	dev_t		rdev = 0, wanted = new_decode_dev(attr->ia_size);
 
-	dprintk("nfsd: CREATE   %s %.*s\n",
-		SVCFH_fmt(dirfhp), argp->len, argp->name);
+	trace_nfsd_proc_create(rqstp, dirfhp, S_IFREG, argp->name, argp->len);
 
 	/* First verify the parent file handle */
 	resp->status = fh_verify(rqstp, dirfhp, S_IFDIR, NFSD_MAY_EXEC);
@@ -548,7 +548,7 @@ nfsd_proc_mkdir(struct svc_rqst *rqstp)
 		.na_iattr	= &argp->attrs,
 	};
 
-	dprintk("nfsd: MKDIR    %s %.*s\n", SVCFH_fmt(&argp->fh), argp->len, argp->name);
+	trace_nfsd_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
 
 	if (resp->fh.fh_dentry) {
 		printk(KERN_WARNING
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 382849d7c321d6ded8213890c2e7075770aa716c..c6aff23a845f06c87e701d57ec577c2c5c5a743c 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -2391,6 +2391,45 @@ TRACE_EVENT(nfsd_lookup_dentry,
 	TP_printk("xid=0x%08x fh_hash=0x%08x name=%s",
 		  __entry->xid, __entry->fh_hash, __get_str(name))
 );
+
+DECLARE_EVENT_CLASS(nfsd_vfs_create_class,
+	TP_PROTO(struct svc_rqst *rqstp,
+		 struct svc_fh *fhp,
+		 umode_t type,
+		 const char *name,
+		 unsigned int len),
+	TP_ARGS(rqstp, fhp, type, name, len),
+	TP_STRUCT__entry(
+		SVC_RQST_ENDPOINT_FIELDS(rqstp)
+		__field(u32, fh_hash)
+		__field(umode_t, type)
+		__string_len(name, name, len)
+	),
+	TP_fast_assign(
+		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
+		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
+		__entry->type = type;
+		__assign_str(name);
+	),
+	TP_printk("xid=0x%08x fh_hash=0x%08x type=%s name=%s",
+		  __entry->xid, __entry->fh_hash,
+		  show_fs_file_type(__entry->type), __get_str(name))
+);
+
+#define DEFINE_NFSD_VFS_CREATE_EVENT(__name)						\
+	DEFINE_EVENT(nfsd_vfs_create_class, __name,					\
+		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp,		\
+			      umode_t type, const char *name, unsigned int len),	\
+		     TP_ARGS(rqstp, fhp, type, name, len))
+
+DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_create);
+DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_mkdir);
+DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_create);
+DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mkdir);
+DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mknod);
+DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create);
+DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create_file);
+
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH

-- 
2.49.0

[PATCH v2 07/12] nfsd: add tracepoints for symlink events

[Jeff Layton]

...and remove the legacy dprintks.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/nfs3proc.c |  8 +++-----
 fs/nfsd/nfs4proc.c |  3 +++
 fs/nfsd/nfsproc.c  |  7 +++----
 fs/nfsd/trace.h    | 35 +++++++++++++++++++++++++++++++++++
 4 files changed, 44 insertions(+), 9 deletions(-)

diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
index ea1280970ea11b2a82f0de88ad0422eef7063d6d..587fc92597e7c77d078e871b8d12684c6b5efa2d 100644
--- a/fs/nfsd/nfs3proc.c
+++ b/fs/nfsd/nfs3proc.c
@@ -423,6 +423,9 @@ nfsd3_proc_symlink(struct svc_rqst *rqstp)
 		.na_iattr	= &argp->attrs,
 	};
 
+	trace_nfsd3_proc_symlink(rqstp, &argp->ffh, argp->fname, argp->flen,
+				 argp->tname, argp->tlen);
+
 	if (argp->tlen == 0) {
 		resp->status = nfserr_inval;
 		goto out;
@@ -440,11 +443,6 @@ nfsd3_proc_symlink(struct svc_rqst *rqstp)
 		goto out;
 	}
 
-	dprintk("nfsd: SYMLINK(3)  %s %.*s -> %.*s\n",
-				SVCFH_fmt(&argp->ffh),
-				argp->flen, argp->fname,
-				argp->tlen, argp->tname);
-
 	fh_copy(&resp->dirfh, &argp->ffh);
 	fh_init(&resp->fh, NFS3_FHSIZE);
 	resp->status = nfsd_symlink(rqstp, &resp->dirfh, argp->fname,
diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
index 2c795103deaa4044596bd07d90db788169a32a0c..e22596a2e311861be1e4f595d77547be04634ce7 100644
--- a/fs/nfsd/nfs4proc.c
+++ b/fs/nfsd/nfs4proc.c
@@ -873,6 +873,9 @@ nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	current->fs->umask = create->cr_umask;
 	switch (create->cr_type) {
 	case NF4LNK:
+		trace_nfsd4_symlink(rqstp, &cstate->current_fh,
+				    create->cr_name, create->cr_namelen,
+				    create->cr_data, create->cr_datalen);
 		status = nfsd_symlink(rqstp, &cstate->current_fh,
 				      create->cr_name, create->cr_namelen,
 				      create->cr_data, &attrs, &resfh);
diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
index 33d8cbf8785588d38d4ec5efd769c1d1d06c6a91..0674ed6b978f6caa1325a9271f2fde9b3ef60945 100644
--- a/fs/nfsd/nfsproc.c
+++ b/fs/nfsd/nfsproc.c
@@ -506,6 +506,9 @@ nfsd_proc_symlink(struct svc_rqst *rqstp)
 	};
 	struct svc_fh	newfh;
 
+	trace_nfsd_proc_symlink(rqstp, &argp->ffh, argp->fname, argp->flen,
+				argp->tname, argp->tlen);
+
 	if (argp->tlen > NFS_MAXPATHLEN) {
 		resp->status = nfserr_nametoolong;
 		goto out;
@@ -519,10 +522,6 @@ nfsd_proc_symlink(struct svc_rqst *rqstp)
 		goto out;
 	}
 
-	dprintk("nfsd: SYMLINK  %s %.*s -> %.*s\n",
-		SVCFH_fmt(&argp->ffh), argp->flen, argp->fname,
-		argp->tlen, argp->tname);
-
 	fh_init(&newfh, NFS_FHSIZE);
 	resp->status = nfsd_symlink(rqstp, &argp->ffh, argp->fname, argp->flen,
 				    argp->tname, &attrs, &newfh);
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index c6aff23a845f06c87e701d57ec577c2c5c5a743c..850dbf1240b234b67dd7d75d6903c0f49dc01261 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -2430,6 +2430,41 @@ DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mknod);
 DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create);
 DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create_file);
 
+DECLARE_EVENT_CLASS(nfsd_vfs_symlink_class,
+	TP_PROTO(struct svc_rqst *rqstp,
+		 struct svc_fh *fhp,
+		 const char *name,
+		 unsigned int namelen,
+		 const char *tgt,
+		 unsigned int tgtlen),
+	TP_ARGS(rqstp, fhp, name, namelen, tgt, tgtlen),
+	TP_STRUCT__entry(
+		SVC_RQST_ENDPOINT_FIELDS(rqstp)
+		__field(u32, fh_hash)
+		__string_len(name, name, namelen)
+		__string_len(tgt, tgt, tgtlen)
+	),
+	TP_fast_assign(
+		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
+		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
+		__assign_str(name);
+		__assign_str(tgt);
+	),
+	TP_printk("xid=0x%08x fh_hash=0x%08x name=%s target=%s",
+		  __entry->xid, __entry->fh_hash,
+		  __get_str(name), __get_str(tgt))
+);
+
+#define DEFINE_NFSD_VFS_SYMLINK_EVENT(__name)					\
+	DEFINE_EVENT(nfsd_vfs_symlink_class, __name,				\
+		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp,	\
+			      const char *name, unsigned int namelen,		\
+			      const char *tgt, unsigned int tgtlen),		\
+		     TP_ARGS(rqstp, fhp, name, namelen, tgt, tgtlen))
+
+DEFINE_NFSD_VFS_SYMLINK_EVENT(nfsd_proc_symlink);
+DEFINE_NFSD_VFS_SYMLINK_EVENT(nfsd3_proc_symlink);
+DEFINE_NFSD_VFS_SYMLINK_EVENT(nfsd4_symlink);
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH

-- 
2.49.0

[PATCH v2 08/12] nfsd: add tracepoints for hardlink events

[Jeff Layton]

...and remove the legacy dprintks.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/nfs3proc.c |  7 +------
 fs/nfsd/nfs4proc.c |  3 +++
 fs/nfsd/nfsproc.c  |  7 +------
 fs/nfsd/trace.h    | 35 +++++++++++++++++++++++++++++++++++
 4 files changed, 40 insertions(+), 12 deletions(-)

diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
index 587fc92597e7c77d078e871b8d12684c6b5efa2d..97aaf98d0af7dc565b21937ecca4852dd9253221 100644
--- a/fs/nfsd/nfs3proc.c
+++ b/fs/nfsd/nfs3proc.c
@@ -564,12 +564,7 @@ nfsd3_proc_link(struct svc_rqst *rqstp)
 	struct nfsd3_linkargs *argp = rqstp->rq_argp;
 	struct nfsd3_linkres  *resp = rqstp->rq_resp;
 
-	dprintk("nfsd: LINK(3)     %s ->\n",
-				SVCFH_fmt(&argp->ffh));
-	dprintk("nfsd:   -> %s %.*s\n",
-				SVCFH_fmt(&argp->tfh),
-				argp->tlen,
-				argp->tname);
+	trace_nfsd_proc_link(rqstp, &argp->ffh, &argp->tfh, argp->tname, argp->tlen);
 
 	fh_copy(&resp->fh,  &argp->ffh);
 	fh_copy(&resp->tfh, &argp->tfh);
diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
index e22596a2e311861be1e4f595d77547be04634ce7..7dffae2f16d9fa8dea043b7bf300eaca52c0aa7c 100644
--- a/fs/nfsd/nfs4proc.c
+++ b/fs/nfsd/nfs4proc.c
@@ -977,6 +977,9 @@ nfsd4_link(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	struct nfsd4_link *link = &u->link;
 	__be32 status;
 
+	trace_nfsd4_link(rqstp, &cstate->save_fh, &cstate->current_fh,
+			 link->li_name, link->li_namelen);
+
 	status = nfsd_link(rqstp, &cstate->current_fh,
 			   link->li_name, link->li_namelen, &cstate->save_fh);
 	if (!status)
diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
index 0674ed6b978f6caa1325a9271f2fde9b3ef60945..b40b5ab1d3b17dd8974fcaeda3ac7c26baee67cf 100644
--- a/fs/nfsd/nfsproc.c
+++ b/fs/nfsd/nfsproc.c
@@ -481,12 +481,7 @@ nfsd_proc_link(struct svc_rqst *rqstp)
 	struct nfsd_linkargs *argp = rqstp->rq_argp;
 	struct nfsd_stat *resp = rqstp->rq_resp;
 
-	dprintk("nfsd: LINK     %s ->\n",
-		SVCFH_fmt(&argp->ffh));
-	dprintk("nfsd:    %s %.*s\n",
-		SVCFH_fmt(&argp->tfh),
-		argp->tlen,
-		argp->tname);
+	trace_nfsd_proc_link(rqstp, &argp->ffh, &argp->tfh, argp->tname, argp->tlen);
 
 	resp->status = nfsd_link(rqstp, &argp->tfh, argp->tname, argp->tlen,
 				 &argp->ffh);
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 850dbf1240b234b67dd7d75d6903c0f49dc01261..9ff919a08f424bfe023cf91244fe08effbdf993e 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -2465,6 +2465,41 @@ DECLARE_EVENT_CLASS(nfsd_vfs_symlink_class,
 DEFINE_NFSD_VFS_SYMLINK_EVENT(nfsd_proc_symlink);
 DEFINE_NFSD_VFS_SYMLINK_EVENT(nfsd3_proc_symlink);
 DEFINE_NFSD_VFS_SYMLINK_EVENT(nfsd4_symlink);
+
+DECLARE_EVENT_CLASS(nfsd_vfs_link_class,
+	TP_PROTO(struct svc_rqst *rqstp,
+		 struct svc_fh *sfhp,
+		 struct svc_fh *tfhp,
+		 const char *name,
+		 unsigned int namelen),
+	TP_ARGS(rqstp, sfhp, tfhp, name, namelen),
+	TP_STRUCT__entry(
+		SVC_RQST_ENDPOINT_FIELDS(rqstp)
+		__field(u32, sfh_hash)
+		__field(u32, tfh_hash)
+		__string_len(name, name, namelen)
+	),
+	TP_fast_assign(
+		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
+		__entry->sfh_hash = knfsd_fh_hash(&sfhp->fh_handle);
+		__entry->tfh_hash = knfsd_fh_hash(&tfhp->fh_handle);
+		__assign_str(name);
+	),
+	TP_printk("xid=0x%08x src_fh=0x%08x tgt_fh=0x%08x name=%s",
+		  __entry->xid, __entry->sfh_hash, __entry->tfh_hash,
+		  __get_str(name))
+);
+
+#define DEFINE_NFSD_VFS_LINK_EVENT(__name)					\
+	DEFINE_EVENT(nfsd_vfs_link_class, __name,				\
+		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *sfhp,	\
+			      struct svc_fh *tfhp, const char *name,		\
+			      unsigned int namelen),				\
+		     TP_ARGS(rqstp, sfhp, tfhp, name, namelen))
+
+DEFINE_NFSD_VFS_LINK_EVENT(nfsd_proc_link);
+DEFINE_NFSD_VFS_LINK_EVENT(nfsd3_proc_link);
+DEFINE_NFSD_VFS_LINK_EVENT(nfsd4_link);
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH

-- 
2.49.0

[PATCH v2 09/12] nfsd: add tracepoints for unlink events

[Jeff Layton]

...and remove the legacy dprintks.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/nfs3proc.c | 10 ++--------
 fs/nfsd/nfs4proc.c |  2 ++
 fs/nfsd/nfsproc.c  |  5 ++---
 fs/nfsd/trace.h    | 34 ++++++++++++++++++++++++++++++++++
 4 files changed, 40 insertions(+), 11 deletions(-)

diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
index 97aaf98d0af7dc565b21937ecca4852dd9253221..8893bf5e0b1d15b24e9c2c71fa1a8a09586a03d3 100644
--- a/fs/nfsd/nfs3proc.c
+++ b/fs/nfsd/nfs3proc.c
@@ -501,10 +501,7 @@ nfsd3_proc_remove(struct svc_rqst *rqstp)
 	struct nfsd3_diropargs *argp = rqstp->rq_argp;
 	struct nfsd3_attrstat *resp = rqstp->rq_resp;
 
-	dprintk("nfsd: REMOVE(3)   %s %.*s\n",
-				SVCFH_fmt(&argp->fh),
-				argp->len,
-				argp->name);
+	trace_nfsd3_proc_remove(rqstp, &argp->fh, argp->name, argp->len);
 
 	/* Unlink. -S_IFDIR means file must not be a directory */
 	fh_copy(&resp->fh, &argp->fh);
@@ -523,10 +520,7 @@ nfsd3_proc_rmdir(struct svc_rqst *rqstp)
 	struct nfsd3_diropargs *argp = rqstp->rq_argp;
 	struct nfsd3_attrstat *resp = rqstp->rq_resp;
 
-	dprintk("nfsd: RMDIR(3)    %s %.*s\n",
-				SVCFH_fmt(&argp->fh),
-				argp->len,
-				argp->name);
+	trace_nfsd3_proc_rmdir(rqstp, &argp->fh, argp->name, argp->len);
 
 	fh_copy(&resp->fh, &argp->fh);
 	resp->status = nfsd_unlink(rqstp, &resp->fh, S_IFDIR,
diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
index 7dffae2f16d9fa8dea043b7bf300eaca52c0aa7c..8524e78201e22984517e93cd9a2834190266c633 100644
--- a/fs/nfsd/nfs4proc.c
+++ b/fs/nfsd/nfs4proc.c
@@ -1114,6 +1114,8 @@ nfsd4_remove(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	struct nfsd4_remove *remove = &u->remove;
 	__be32 status;
 
+	trace_nfsd4_remove(rqstp, &cstate->current_fh, remove->rm_name, remove->rm_namelen);
+
 	if (opens_in_grace(SVC_NET(rqstp)))
 		return nfserr_grace;
 	status = nfsd_unlink(rqstp, &cstate->current_fh, 0,
diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
index b40b5ab1d3b17dd8974fcaeda3ac7c26baee67cf..55656bb0264c31c10419ed41240c91ba66493106 100644
--- a/fs/nfsd/nfsproc.c
+++ b/fs/nfsd/nfsproc.c
@@ -445,8 +445,7 @@ nfsd_proc_remove(struct svc_rqst *rqstp)
 	struct nfsd_diropargs *argp = rqstp->rq_argp;
 	struct nfsd_stat *resp = rqstp->rq_resp;
 
-	dprintk("nfsd: REMOVE   %s %.*s\n", SVCFH_fmt(&argp->fh),
-		argp->len, argp->name);
+	trace_nfsd_proc_remove(rqstp, &argp->fh, argp->name, argp->len);
 
 	/* Unlink. -SIFDIR means file must not be a directory */
 	resp->status = nfsd_unlink(rqstp, &argp->fh, -S_IFDIR,
@@ -572,7 +571,7 @@ nfsd_proc_rmdir(struct svc_rqst *rqstp)
 	struct nfsd_diropargs *argp = rqstp->rq_argp;
 	struct nfsd_stat *resp = rqstp->rq_resp;
 
-	dprintk("nfsd: RMDIR    %s %.*s\n", SVCFH_fmt(&argp->fh), argp->len, argp->name);
+	trace_nfsd_proc_rmdir(rqstp, &argp->fh, argp->name, argp->len);
 
 	resp->status = nfsd_unlink(rqstp, &argp->fh, S_IFDIR,
 				   argp->name, argp->len);
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 9ff919a08f424bfe023cf91244fe08effbdf993e..dd984917bd0a741ac545c06631ab2a7de8af5158 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -2500,6 +2500,40 @@ DECLARE_EVENT_CLASS(nfsd_vfs_link_class,
 DEFINE_NFSD_VFS_LINK_EVENT(nfsd_proc_link);
 DEFINE_NFSD_VFS_LINK_EVENT(nfsd3_proc_link);
 DEFINE_NFSD_VFS_LINK_EVENT(nfsd4_link);
+
+DECLARE_EVENT_CLASS(nfsd_vfs_unlink_class,
+	TP_PROTO(struct svc_rqst *rqstp,
+		 struct svc_fh *fhp,
+		 const char *name,
+		 unsigned int len),
+	TP_ARGS(rqstp, fhp, name, len),
+	TP_STRUCT__entry(
+		SVC_RQST_ENDPOINT_FIELDS(rqstp)
+		__field(u32, fh_hash)
+		__string_len(name, name, len)
+	),
+	TP_fast_assign(
+		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
+		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
+		__assign_str(name);
+	),
+	TP_printk("xid=0x%08x fh_hash=0x%08x name=%s",
+		  __entry->xid, __entry->fh_hash,
+		  __get_str(name))
+);
+
+#define DEFINE_NFSD_VFS_UNLINK_EVENT(__name)						\
+	DEFINE_EVENT(nfsd_vfs_unlink_class, __name,					\
+		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp,		\
+			      const char *name, unsigned int len),			\
+		     TP_ARGS(rqstp, fhp, name, len))
+
+DEFINE_NFSD_VFS_UNLINK_EVENT(nfsd_proc_remove);
+DEFINE_NFSD_VFS_UNLINK_EVENT(nfsd_proc_rmdir);
+DEFINE_NFSD_VFS_UNLINK_EVENT(nfsd3_proc_remove);
+DEFINE_NFSD_VFS_UNLINK_EVENT(nfsd3_proc_rmdir);
+DEFINE_NFSD_VFS_UNLINK_EVENT(nfsd4_remove);
+
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH

-- 
2.49.0

[PATCH v2 10/12] nfsd: add tracepoints to rename events

[Jeff Layton]

...and remove the legacy dprintks.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/nfs3proc.c | 10 ++--------
 fs/nfsd/nfs4proc.c |  4 ++++
 fs/nfsd/nfsproc.c  |  6 ++----
 fs/nfsd/trace.h    | 40 ++++++++++++++++++++++++++++++++++++++++
 4 files changed, 48 insertions(+), 12 deletions(-)

diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
index 8893bf5e0b1d15b24e9c2c71fa1a8a09586a03d3..4fd3c2284eb96c1d712639675140412b84eadb2f 100644
--- a/fs/nfsd/nfs3proc.c
+++ b/fs/nfsd/nfs3proc.c
@@ -535,14 +535,8 @@ nfsd3_proc_rename(struct svc_rqst *rqstp)
 	struct nfsd3_renameargs *argp = rqstp->rq_argp;
 	struct nfsd3_renameres *resp = rqstp->rq_resp;
 
-	dprintk("nfsd: RENAME(3)   %s %.*s ->\n",
-				SVCFH_fmt(&argp->ffh),
-				argp->flen,
-				argp->fname);
-	dprintk("nfsd: -> %s %.*s\n",
-				SVCFH_fmt(&argp->tfh),
-				argp->tlen,
-				argp->tname);
+	trace_nfsd3_proc_rename(rqstp, &argp->ffh, &argp->tfh, argp->fname,
+				argp->flen, argp->tname, argp->tlen);
 
 	fh_copy(&resp->ffh, &argp->ffh);
 	fh_copy(&resp->tfh, &argp->tfh);
diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
index 8524e78201e22984517e93cd9a2834190266c633..7e6c80e0482a997d4085c87dae88d10c2f06b77b 100644
--- a/fs/nfsd/nfs4proc.c
+++ b/fs/nfsd/nfs4proc.c
@@ -1132,6 +1132,10 @@ nfsd4_rename(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	struct nfsd4_rename *rename = &u->rename;
 	__be32 status;
 
+	trace_nfsd4_rename(rqstp, &cstate->save_fh, &cstate->current_fh,
+			   rename->rn_sname, rename->rn_snamelen,
+			   rename->rn_tname, rename->rn_tnamelen);
+
 	if (opens_in_grace(SVC_NET(rqstp)))
 		return nfserr_grace;
 	status = nfsd_rename(rqstp, &cstate->save_fh, rename->rn_sname,
diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
index 55656bb0264c31c10419ed41240c91ba66493106..d99e1bff2f8a99e477e3cf21eb7058cfe40a7cb4 100644
--- a/fs/nfsd/nfsproc.c
+++ b/fs/nfsd/nfsproc.c
@@ -461,10 +461,8 @@ nfsd_proc_rename(struct svc_rqst *rqstp)
 	struct nfsd_renameargs *argp = rqstp->rq_argp;
 	struct nfsd_stat *resp = rqstp->rq_resp;
 
-	dprintk("nfsd: RENAME   %s %.*s -> \n",
-		SVCFH_fmt(&argp->ffh), argp->flen, argp->fname);
-	dprintk("nfsd:        ->  %s %.*s\n",
-		SVCFH_fmt(&argp->tfh), argp->tlen, argp->tname);
+	trace_nfsd_proc_rename(rqstp, &argp->ffh, &argp->tfh, argp->fname,
+			       argp->flen, argp->tname, argp->tlen);
 
 	resp->status = nfsd_rename(rqstp, &argp->ffh, argp->fname, argp->flen,
 				   &argp->tfh, argp->tname, argp->tlen);
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index dd984917bd0a741ac545c06631ab2a7de8af5158..7bf3ee4acd9862171cae5caefced3507f4897e90 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -2534,6 +2534,46 @@ DEFINE_NFSD_VFS_UNLINK_EVENT(nfsd3_proc_remove);
 DEFINE_NFSD_VFS_UNLINK_EVENT(nfsd3_proc_rmdir);
 DEFINE_NFSD_VFS_UNLINK_EVENT(nfsd4_remove);
 
+DECLARE_EVENT_CLASS(nfsd_vfs_rename_class,
+	TP_PROTO(struct svc_rqst *rqstp,
+		 struct svc_fh *sfhp,
+		 struct svc_fh *tfhp,
+		 const char *name,
+		 unsigned int namelen,
+		 const char *tgt,
+		 unsigned int tgtlen),
+	TP_ARGS(rqstp, sfhp, tfhp, name, namelen, tgt, tgtlen),
+	TP_STRUCT__entry(
+		SVC_RQST_ENDPOINT_FIELDS(rqstp)
+		__field(u32, sfh_hash)
+		__field(u32, tfh_hash)
+		__string_len(name, name, namelen)
+		__string_len(tgt, tgt, tgtlen)
+	),
+	TP_fast_assign(
+		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
+		__entry->sfh_hash = knfsd_fh_hash(&sfhp->fh_handle);
+		__entry->tfh_hash = knfsd_fh_hash(&tfhp->fh_handle);
+		__assign_str(name);
+		__assign_str(tgt);
+	),
+	TP_printk("xid=0x%08x sfh_hash=0x%08x tfh_hash=0x%08x name=%s target=%s",
+		  __entry->xid, __entry->sfh_hash, __entry->tfh_hash,
+		  __get_str(name), __get_str(tgt))
+);
+
+#define DEFINE_NFSD_VFS_RENAME_EVENT(__name)					\
+	DEFINE_EVENT(nfsd_vfs_rename_class, __name,				\
+		     TP_PROTO(struct svc_rqst *rqstp,				\
+			      struct svc_fh *sfhp, struct svc_fh *tfhp,		\
+			      const char *name, unsigned int namelen,		\
+			      const char *tgt, unsigned int tgtlen),		\
+		     TP_ARGS(rqstp, sfhp, tfhp, name, namelen, tgt, tgtlen))
+
+DEFINE_NFSD_VFS_RENAME_EVENT(nfsd_proc_rename);
+DEFINE_NFSD_VFS_RENAME_EVENT(nfsd3_proc_rename);
+DEFINE_NFSD_VFS_RENAME_EVENT(nfsd4_rename);
+
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH

-- 
2.49.0

[PATCH v2 11/12] nfsd: add tracepoints for readdir events

[Jeff Layton]

...and remove the legacy dprintks.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/nfs3proc.c |  8 ++------
 fs/nfsd/nfs4proc.c |  2 ++
 fs/nfsd/nfsproc.c  |  4 +---
 fs/nfsd/trace.h    | 32 ++++++++++++++++++++++++++++++++
 4 files changed, 37 insertions(+), 9 deletions(-)

diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
index 4fd3c2284eb96c1d712639675140412b84eadb2f..b9ed55a4cdd740bc0aa84b7cbc0e37906d55d666 100644
--- a/fs/nfsd/nfs3proc.c
+++ b/fs/nfsd/nfs3proc.c
@@ -592,9 +592,7 @@ nfsd3_proc_readdir(struct svc_rqst *rqstp)
 	struct nfsd3_readdirres  *resp = rqstp->rq_resp;
 	loff_t		offset;
 
-	dprintk("nfsd: READDIR(3)  %s %d bytes at %d\n",
-				SVCFH_fmt(&argp->fh),
-				argp->count, (u32) argp->cookie);
+	trace_nfsd3_proc_readdir(rqstp, &argp->fh, argp->cookie, argp->count);
 
 	nfsd3_init_dirlist_pages(rqstp, resp, argp->count);
 
@@ -626,9 +624,7 @@ nfsd3_proc_readdirplus(struct svc_rqst *rqstp)
 	struct nfsd3_readdirres  *resp = rqstp->rq_resp;
 	loff_t	offset;
 
-	dprintk("nfsd: READDIR+(3) %s %d bytes at %d\n",
-				SVCFH_fmt(&argp->fh),
-				argp->count, (u32) argp->cookie);
+	trace_nfsd3_proc_readdirplus(rqstp, &argp->fh, argp->cookie, argp->count);
 
 	nfsd3_init_dirlist_pages(rqstp, resp, argp->count);
 
diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
index 7e6c80e0482a997d4085c87dae88d10c2f06b77b..8dd1233693dc82febe300f6f2714059c718909bc 100644
--- a/fs/nfsd/nfs4proc.c
+++ b/fs/nfsd/nfs4proc.c
@@ -1080,6 +1080,8 @@ nfsd4_readdir(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	u64 cookie = readdir->rd_cookie;
 	static const nfs4_verifier zeroverf;
 
+	trace_nfsd4_readdir(rqstp, &cstate->current_fh, cookie, readdir->rd_dircount);
+
 	/* no need to check permission - this will be done in nfsd_readdir() */
 
 	if (readdir->rd_bmval[1] & NFSD_WRITEONLY_ATTRS_WORD1)
diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
index d99e1bff2f8a99e477e3cf21eb7058cfe40a7cb4..ce3f1ca636f79687e65077effcc0588639d9366d 100644
--- a/fs/nfsd/nfsproc.c
+++ b/fs/nfsd/nfsproc.c
@@ -606,9 +606,7 @@ nfsd_proc_readdir(struct svc_rqst *rqstp)
 	struct nfsd_readdirres *resp = rqstp->rq_resp;
 	loff_t		offset;
 
-	dprintk("nfsd: READDIR  %s %d bytes at %d\n",
-		SVCFH_fmt(&argp->fh),		
-		argp->count, argp->cookie);
+	trace_nfsd_proc_readdir(rqstp, &argp->fh, argp->cookie, argp->count);
 
 	nfsd_init_dirlist_pages(rqstp, resp, argp->count);
 
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 7bf3ee4acd9862171cae5caefced3507f4897e90..1d48a37dd33fb4c6e338534d576bcc8fd1a8f54d 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -2574,6 +2574,38 @@ DEFINE_NFSD_VFS_RENAME_EVENT(nfsd_proc_rename);
 DEFINE_NFSD_VFS_RENAME_EVENT(nfsd3_proc_rename);
 DEFINE_NFSD_VFS_RENAME_EVENT(nfsd4_rename);
 
+DECLARE_EVENT_CLASS(nfsd_vfs_readdir_class,
+	TP_PROTO(struct svc_rqst *rqstp,
+		 struct svc_fh *fhp,
+		 u64 cookie, u32 count),
+	TP_ARGS(rqstp, fhp, cookie, count),
+	TP_STRUCT__entry(
+		SVC_RQST_ENDPOINT_FIELDS(rqstp)
+		__field(u32, fh_hash)
+		__field(u64, cookie)
+		__field(u32, count)
+	),
+	TP_fast_assign(
+		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
+		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
+		__entry->cookie = cookie;
+		__entry->count = count;
+	),
+	TP_printk("xid=0x%08x fh_hash=0x%08x cookie=0x%llx count=%u",
+		  __entry->xid, __entry->fh_hash, __entry->cookie, __entry->count)
+);
+
+#define DEFINE_NFSD_VFS_READDIR_EVENT(__name)					\
+	DEFINE_EVENT(nfsd_vfs_readdir_class, __name,				\
+		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp,	\
+			      u64 cookie, u32 count),				\
+		     TP_ARGS(rqstp, fhp, cookie, count))
+
+DEFINE_NFSD_VFS_READDIR_EVENT(nfsd_proc_readdir);
+DEFINE_NFSD_VFS_READDIR_EVENT(nfsd3_proc_readdir);
+DEFINE_NFSD_VFS_READDIR_EVENT(nfsd3_proc_readdirplus);
+DEFINE_NFSD_VFS_READDIR_EVENT(nfsd4_readdir);
+
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH

-- 
2.49.0

[PATCH v2 12/12] nfsd: add tracepoint for getattr events

[Jeff Layton]

...including STATFS on v2 and FSSTAT on v3. Also, remove the dprintks.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/nfs3proc.c |  6 ++----
 fs/nfsd/nfs4proc.c |  2 ++
 fs/nfsd/nfsproc.c  |  4 ++--
 fs/nfsd/trace.h    | 27 +++++++++++++++++++++++++++
 4 files changed, 33 insertions(+), 6 deletions(-)

diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
index b9ed55a4cdd740bc0aa84b7cbc0e37906d55d666..d2c6902ca9e2496d90ddf13e96b119e415c23cfc 100644
--- a/fs/nfsd/nfs3proc.c
+++ b/fs/nfsd/nfs3proc.c
@@ -70,8 +70,7 @@ nfsd3_proc_getattr(struct svc_rqst *rqstp)
 	struct nfsd_fhandle *argp = rqstp->rq_argp;
 	struct nfsd3_attrstat *resp = rqstp->rq_resp;
 
-	dprintk("nfsd: GETATTR(3)  %s\n",
-		SVCFH_fmt(&argp->fh));
+	trace_nfsd3_proc_getattr(rqstp, &argp->fh);
 
 	fh_copy(&resp->fh, &argp->fh);
 	resp->status = fh_verify(rqstp, &resp->fh, 0,
@@ -665,8 +664,7 @@ nfsd3_proc_fsstat(struct svc_rqst *rqstp)
 	struct nfsd_fhandle *argp = rqstp->rq_argp;
 	struct nfsd3_fsstatres *resp = rqstp->rq_resp;
 
-	dprintk("nfsd: FSSTAT(3)   %s\n",
-				SVCFH_fmt(&argp->fh));
+	trace_nfsd3_proc_fsstat(rqstp, &argp->fh);
 
 	resp->status = nfsd_statfs(rqstp, &argp->fh, &resp->stats, 0);
 	fh_put(&argp->fh);
diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
index 8dd1233693dc82febe300f6f2714059c718909bc..1b2cf5a2d8265659edaa7177bc778f74c1a532a3 100644
--- a/fs/nfsd/nfs4proc.c
+++ b/fs/nfsd/nfs4proc.c
@@ -955,6 +955,8 @@ nfsd4_getattr(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	struct nfsd4_getattr *getattr = &u->getattr;
 	__be32 status;
 
+	trace_nfsd4_getattr(rqstp, &cstate->current_fh);
+
 	status = fh_verify(rqstp, &cstate->current_fh, 0, NFSD_MAY_NOP);
 	if (status)
 		return status;
diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
index ce3f1ca636f79687e65077effcc0588639d9366d..35b9f79f077adce4499c7f52244d69da8f5090c4 100644
--- a/fs/nfsd/nfsproc.c
+++ b/fs/nfsd/nfsproc.c
@@ -55,7 +55,7 @@ nfsd_proc_getattr(struct svc_rqst *rqstp)
 	struct nfsd_fhandle *argp = rqstp->rq_argp;
 	struct nfsd_attrstat *resp = rqstp->rq_resp;
 
-	dprintk("nfsd: GETATTR  %s\n", SVCFH_fmt(&argp->fh));
+	trace_nfsd_proc_getattr(rqstp, &argp->fh);
 
 	fh_copy(&resp->fh, &argp->fh);
 	resp->status = fh_verify(rqstp, &resp->fh, 0,
@@ -631,7 +631,7 @@ nfsd_proc_statfs(struct svc_rqst *rqstp)
 	struct nfsd_fhandle *argp = rqstp->rq_argp;
 	struct nfsd_statfsres *resp = rqstp->rq_resp;
 
-	dprintk("nfsd: STATFS   %s\n", SVCFH_fmt(&argp->fh));
+	trace_nfsd_proc_statfs(rqstp, &argp->fh);
 
 	resp->status = nfsd_statfs(rqstp, &argp->fh, &resp->stats,
 				   NFSD_MAY_BYPASS_GSS_ON_ROOT);
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 1d48a37dd33fb4c6e338534d576bcc8fd1a8f54d..ffe16a7ab1f24db999763bcc220e31cf8035d412 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -2606,6 +2606,33 @@ DEFINE_NFSD_VFS_READDIR_EVENT(nfsd3_proc_readdir);
 DEFINE_NFSD_VFS_READDIR_EVENT(nfsd3_proc_readdirplus);
 DEFINE_NFSD_VFS_READDIR_EVENT(nfsd4_readdir);
 
+DECLARE_EVENT_CLASS(nfsd_vfs_getattr_class,
+	TP_PROTO(struct svc_rqst *rqstp,
+		 struct svc_fh *fhp),
+	TP_ARGS(rqstp, fhp),
+	TP_STRUCT__entry(
+		SVC_RQST_ENDPOINT_FIELDS(rqstp)
+		__field(u32, fh_hash)
+	),
+	TP_fast_assign(
+		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
+		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
+	),
+	TP_printk("xid=0x%08x fh_hash=0x%08x",
+		  __entry->xid, __entry->fh_hash)
+);
+
+#define DEFINE_NFSD_VFS_GETATTR_EVENT(__name)					\
+	DEFINE_EVENT(nfsd_vfs_getattr_class, __name,				\
+		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp),	\
+		     TP_ARGS(rqstp, fhp))
+
+DEFINE_NFSD_VFS_GETATTR_EVENT(nfsd_proc_getattr);
+DEFINE_NFSD_VFS_GETATTR_EVENT(nfsd_proc_statfs);
+DEFINE_NFSD_VFS_GETATTR_EVENT(nfsd3_proc_getattr);
+DEFINE_NFSD_VFS_GETATTR_EVENT(nfsd3_proc_fsstat);
+DEFINE_NFSD_VFS_GETATTR_EVENT(nfsd4_getattr);
+
 #endif /* _NFSD_TRACE_H */
 
 #undef TRACE_INCLUDE_PATH

-- 
2.49.0

Re: [PATCH v2 02/12] sunrpc: add info about xprt queue times to svc_xprt_dequeue tracepoint

[Chuck Lever]

On 4/9/25 10:32 AM, Jeff Layton wrote:
> Currently, this tracepoint displays "wakeup-us", which is the time that
> the woken thread spent sleeping, before dequeueing the next xprt. Add a
> new statistic that shows how long the xprt sat on the queue before being
> serviced.

I don't understand the difference between "waiting on queue" and
"sleeping". When are those two latency measurements not the same?


> Signed-off-by: Jeff Layton <jlayton@kernel.org>
> ---
>  include/linux/sunrpc/svc_xprt.h |  1 +
>  include/trace/events/sunrpc.h   | 13 +++++++------
>  net/sunrpc/svc_xprt.c           |  1 +
>  3 files changed, 9 insertions(+), 6 deletions(-)
> 
> diff --git a/include/linux/sunrpc/svc_xprt.h b/include/linux/sunrpc/svc_xprt.h
> index 72be609525796792274d5b8cb5ff37f73723fc23..369a89aea18618748607ee943247c327bf62c8d5 100644
> --- a/include/linux/sunrpc/svc_xprt.h
> +++ b/include/linux/sunrpc/svc_xprt.h
> @@ -53,6 +53,7 @@ struct svc_xprt {
>  	struct svc_xprt_class	*xpt_class;
>  	const struct svc_xprt_ops *xpt_ops;
>  	struct kref		xpt_ref;
> +	ktime_t			xpt_qtime;
>  	struct list_head	xpt_list;
>  	struct lwq_node		xpt_ready;
>  	unsigned long		xpt_flags;
> diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> index 5d331383047b79b9f6dcd699c87287453c1a5f49..b5a0f0bc1a3b7cfd90ce0181a8a419db810988bb 100644
> --- a/include/trace/events/sunrpc.h
> +++ b/include/trace/events/sunrpc.h
> @@ -2040,19 +2040,20 @@ TRACE_EVENT(svc_xprt_dequeue,
>  
>  	TP_STRUCT__entry(
>  		SVC_XPRT_ENDPOINT_FIELDS(rqst->rq_xprt)
> -
>  		__field(unsigned long, wakeup)
> +		__field(unsigned long, qtime)
>  	),
>  
>  	TP_fast_assign(
> -		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
> +		ktime_t ktime = ktime_get();
>  
> -		__entry->wakeup = ktime_to_us(ktime_sub(ktime_get(),
> -							rqst->rq_qtime));
> +		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
> +		__entry->wakeup = ktime_to_us(ktime_sub(ktime, rqst->rq_qtime));
> +		__entry->qtime = ktime_to_us(ktime_sub(ktime, rqst->rq_xprt->xpt_qtime));
>  	),
>  
> -	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu",
> -		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup)
> +	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu qtime=%lu",
> +		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup, __entry->qtime)
>  );
>  
>  DECLARE_EVENT_CLASS(svc_xprt_event,
> diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
> index ae25405d8bd22672a361d1fd3adfdcebb403f90f..32018557797b1f683d8b7259f5fccd029aebcd71 100644
> --- a/net/sunrpc/svc_xprt.c
> +++ b/net/sunrpc/svc_xprt.c
> @@ -488,6 +488,7 @@ void svc_xprt_enqueue(struct svc_xprt *xprt)
>  	pool = svc_pool_for_cpu(xprt->xpt_server);
>  
>  	percpu_counter_inc(&pool->sp_sockets_queued);
> +	xprt->xpt_qtime = ktime_get();
>  	lwq_enqueue(&xprt->xpt_ready, &pool->sp_xprts);
>  
>  	svc_pool_wake_idle_thread(pool);
> 


-- 
Chuck Lever

Re: [PATCH v2 04/12] nfsd: add a tracepoint for nfsd_setattr

[Chuck Lever]

On 4/9/25 10:32 AM, Jeff Layton wrote:
> Turn Sargun's internal kprobe based implementation of this into a normal
> static tracepoint. Also, remove the dprintk's that got added recently
> with the fix for zero-length ACLs.
> 
> Cc: Sargun Dillon <sargun@sargun.me>
> Signed-off-by: Jeff Layton <jlayton@kernel.org>
> ---
>  fs/nfsd/trace.h         | 35 +++++++++++++++++++++++++++++++++++
>  fs/nfsd/vfs.c           |  5 ++---
>  include/trace/misc/fs.h | 21 +++++++++++++++++++++
>  3 files changed, 58 insertions(+), 3 deletions(-)
> 
> diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
> index 0d49fc064f7273f32c93732a993fd77bc0783f5d..c496fed58e2eed15458f35a158fbfef39a972c55 100644
> --- a/fs/nfsd/trace.h
> +++ b/fs/nfsd/trace.h
> @@ -11,6 +11,7 @@
>  #include <linux/tracepoint.h>
>  #include <linux/sunrpc/clnt.h>
>  #include <linux/sunrpc/xprt.h>
> +#include <trace/misc/fs.h>
>  #include <trace/misc/nfs.h>
>  #include <trace/misc/sunrpc.h>
>  
> @@ -2337,6 +2338,40 @@ DEFINE_EVENT(nfsd_copy_async_done_class,		\
>  DEFINE_COPY_ASYNC_DONE_EVENT(done);
>  DEFINE_COPY_ASYNC_DONE_EVENT(cancel);
>  
> +TRACE_EVENT(nfsd_setattr,
> +	TP_PROTO(const struct svc_rqst *rqstp, const struct svc_fh *fhp,
> +		 const struct iattr *iap, const struct timespec64 *guardtime),
> +	TP_ARGS(rqstp, fhp, iap, guardtime),
> +	TP_STRUCT__entry(
> +		SVC_RQST_ENDPOINT_FIELDS(rqstp)
> +		__field(u32, fh_hash)
> +		__field(s64, gtime_tv_sec)
> +		__field(u32, gtime_tv_nsec)
> +		__field(unsigned int, ia_valid)
> +		__field(loff_t, ia_size)
> +		__field(uid_t, ia_uid)
> +		__field(gid_t, ia_gid)
> +		__field(umode_t, ia_mode)
> +	),
> +	TP_fast_assign(__entry->xid = be32_to_cpu(rqstp->rq_xid);
> +		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
> +		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
> +		__entry->gtime_tv_sec = guardtime ? guardtime->tv_sec : 0;
> +		__entry->gtime_tv_nsec = guardtime ? guardtime->tv_nsec : 0;
> +		__entry->ia_valid = iap->ia_valid;
> +		__entry->ia_size = iap->ia_size;
> +		__entry->ia_uid = __kuid_val(iap->ia_uid);
> +		__entry->ia_gid = __kgid_val(iap->ia_gid);
> +		__entry->ia_mode = iap->ia_mode;
> +	),
> +	TP_printk(
> +		"xid=0x%08x fh_hash=0x%08x ia_valid=%s ia_size=%llu ia_mode=0%o ia_uid=%u ia_gid=%u guard_time=%lld.%u",
> +		__entry->xid, __entry->fh_hash, show_ia_valid_flags(__entry->ia_valid),
> +		__entry->ia_size, __entry->ia_mode, __entry->ia_uid, __entry->ia_gid,
> +		__entry->gtime_tv_sec, __entry->gtime_tv_nsec
> +	)
> +)
> +
>  #endif /* _NFSD_TRACE_H */
>  
>  #undef TRACE_INCLUDE_PATH
> diff --git a/fs/nfsd/vfs.c b/fs/nfsd/vfs.c
> index d1156a18a79579bf427fe5809dc93d06e241201e..77ae22abc1a21ec587cf089b2a5f750464b5e985 100644
> --- a/fs/nfsd/vfs.c
> +++ b/fs/nfsd/vfs.c
> @@ -501,7 +501,8 @@ nfsd_setattr(struct svc_rqst *rqstp, struct svc_fh *fhp,
>  	bool		size_change = (iap->ia_valid & ATTR_SIZE);
>  	int		retries;
>  
> -dprintk("nfsd_setattr pacl=%p valid=0x%x\n", attr->na_pacl, iap->ia_valid);

Nit:

These unindented dprintk call sites were introduced by Rick's POSIX
ACL patch series, which is experimental. He's promised to remove them
before he sends a final version of that series.

Your patch can leave them in place, as they will be gone soon by other
means.


> +	trace_nfsd_setattr(rqstp, fhp, iap, guardtime);
> +
>  	if (iap->ia_valid & ATTR_SIZE) {
>  		accmode |= NFSD_MAY_WRITE|NFSD_MAY_OWNER_OVERRIDE;
>  		ftype = S_IFREG;
> @@ -597,7 +598,6 @@ dprintk("nfsd_setattr pacl=%p valid=0x%x\n", attr->na_pacl, iap->ia_valid);
>  						NULL);
>  	}
>  	if (IS_ENABLED(CONFIG_FS_POSIX_ACL) && attr->na_pacl) {
> -dprintk("at set_posix_acl\n");
>  		/*
>  		 * For any file system that is not ACL_SCOPE_FILE_OBJECT,
>  		 * a_count == 0 MUST reply nfserr_inval.
> @@ -612,7 +612,6 @@ dprintk("at set_posix_acl\n");
>  							attr->na_pacl);
>  		else
>  			attr->na_paclerr = -EINVAL;
> -dprintk("set_posix_acl=%d\n", attr->na_paclerr);
>  	}
>  out_fill_attrs:
>  	/*
> diff --git a/include/trace/misc/fs.h b/include/trace/misc/fs.h
> index 738b97f22f3651f2370830037a8f4bfdf9a42ad4..0406ebe2a80a499dfcadb7e63db4d9e4a84d4d64 100644
> --- a/include/trace/misc/fs.h
> +++ b/include/trace/misc/fs.h
> @@ -120,3 +120,24 @@
>  		{ LOOKUP_BENEATH,	"BENEATH" }, \
>  		{ LOOKUP_IN_ROOT,	"IN_ROOT" }, \
>  		{ LOOKUP_CACHED,	"CACHED" })
> +
> +#define show_ia_valid_flags(flags)			\
> +	__print_flags(flags, "|",			\
> +		{ ATTR_MODE,		"MODE" },	\
> +		{ ATTR_UID,		"UID" },	\
> +		{ ATTR_GID,		"GID" },	\
> +		{ ATTR_SIZE,		"SIZE" },	\
> +		{ ATTR_ATIME,		"ATIME" },	\
> +		{ ATTR_MTIME,		"MTIME" },	\
> +		{ ATTR_CTIME,		"CTIME" },	\
> +		{ ATTR_ATIME_SET,	"ATIME_SET" },	\
> +		{ ATTR_MTIME_SET,	"MTIME_SET" },	\
> +		{ ATTR_FORCE,		"FORCE" },	\
> +		{ ATTR_KILL_SUID,	"KILL_SUID" },	\
> +		{ ATTR_KILL_SGID,	"KILL_SGID" },	\
> +		{ ATTR_FILE,		"FILE" },	\
> +		{ ATTR_KILL_PRIV,	"KILL_PRIV" },	\
> +		{ ATTR_OPEN,		"OPEN" },	\
> +		{ ATTR_TIMES_SET,	"TIMES_SET" },	\
> +		{ ATTR_TOUCH,		"TOUCH"},	\
> +		{ ATTR_DELEG,		"DELEG"})
> 


-- 
Chuck Lever

Re: [PATCH v2 06/12] nfsd: add tracepoints around nfsd_create events

[Chuck Lever]

On 4/9/25 10:32 AM, Jeff Layton wrote:
> ...and remove the legacy dprintks.
> 
> Signed-off-by: Jeff Layton <jlayton@kernel.org>
> ---
>  fs/nfsd/nfs3proc.c | 18 +++++-------------
>  fs/nfsd/nfs4proc.c | 29 +++++++++++++++++++++++++++++
>  fs/nfsd/nfsproc.c  |  6 +++---
>  fs/nfsd/trace.h    | 39 +++++++++++++++++++++++++++++++++++++++
>  4 files changed, 76 insertions(+), 16 deletions(-)
> 
> diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
> index 372bdcf5e07a5c835da240ecebb02e3576eb2ca6..ea1280970ea11b2a82f0de88ad0422eef7063d6d 100644
> --- a/fs/nfsd/nfs3proc.c
> +++ b/fs/nfsd/nfs3proc.c
> @@ -14,6 +14,7 @@
>  #include "xdr3.h"
>  #include "vfs.h"
>  #include "filecache.h"
> +#include "trace.h"
>  
>  #define NFSDDBG_FACILITY		NFSDDBG_PROC
>  
> @@ -380,10 +381,7 @@ nfsd3_proc_create(struct svc_rqst *rqstp)
>  	struct nfsd3_diropres *resp = rqstp->rq_resp;
>  	svc_fh *dirfhp, *newfhp;
>  
> -	dprintk("nfsd: CREATE(3)   %s %.*s\n",
> -				SVCFH_fmt(&argp->fh),
> -				argp->len,
> -				argp->name);
> +	trace_nfsd3_proc_create(rqstp, &argp->fh, S_IFREG, argp->name, argp->len);
>  
>  	dirfhp = fh_copy(&resp->dirfh, &argp->fh);
>  	newfhp = fh_init(&resp->fh, NFS3_FHSIZE);
> @@ -405,10 +403,7 @@ nfsd3_proc_mkdir(struct svc_rqst *rqstp)
>  		.na_iattr	= &argp->attrs,
>  	};
>  
> -	dprintk("nfsd: MKDIR(3)    %s %.*s\n",
> -				SVCFH_fmt(&argp->fh),
> -				argp->len,
> -				argp->name);
> +	trace_nfsd3_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
>  
>  	argp->attrs.ia_valid &= ~ATTR_SIZE;
>  	fh_copy(&resp->dirfh, &argp->fh);
> @@ -471,13 +466,10 @@ nfsd3_proc_mknod(struct svc_rqst *rqstp)
>  	struct nfsd_attrs attrs = {
>  		.na_iattr	= &argp->attrs,
>  	};
> -	int type;
> +	int type = nfs3_ftypes[argp->ftype];
>  	dev_t	rdev = 0;
>  
> -	dprintk("nfsd: MKNOD(3)    %s %.*s\n",
> -				SVCFH_fmt(&argp->fh),
> -				argp->len,
> -				argp->name);
> +	trace_nfsd3_proc_mknod(rqstp, &argp->fh, type, argp->name, argp->len);
>  
>  	fh_copy(&resp->dirfh, &argp->fh);
>  	fh_init(&resp->fh, NFS3_FHSIZE);
> diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
> index 6e23d6103010197c0316b07c189fe12ec3033812..2c795103deaa4044596bd07d90db788169a32a0c 100644
> --- a/fs/nfsd/nfs4proc.c
> +++ b/fs/nfsd/nfs4proc.c
> @@ -250,6 +250,8 @@ nfsd4_create_file(struct svc_rqst *rqstp, struct svc_fh *fhp,
>  	__be32 status;
>  	int host_err;
>  
> +	trace_nfsd4_create_file(rqstp, fhp, S_IFREG, open->op_fname, open->op_fnamelen);
> +
>  	if (isdotent(open->op_fname, open->op_fnamelen))
>  		return nfserr_exist;
>  	if (!(iap->ia_valid & ATTR_MODE))
> @@ -807,6 +809,29 @@ nfsd4_commit(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>  	return status;
>  }
>  
> +static umode_t nfs_type_to_vfs_type(enum nfs_ftype4 nfstype)
> +{
> +	switch (nfstype) {
> +	case NF4REG:
> +		return S_IFREG;
> +	case NF4DIR:
> +		return S_IFDIR;
> +	case NF4BLK:
> +		return S_IFBLK;
> +	case NF4CHR:
> +		return S_IFCHR;
> +	case NF4LNK:
> +		return S_IFLNK;
> +	case NF4SOCK:
> +		return S_IFSOCK;
> +	case NF4FIFO:
> +		return S_IFIFO;
> +	default:
> +		break;
> +	}
> +	return 0;
> +}
> +

Wondering what happens when trace points are disabled in the kernel
build. Maybe this helper belongs in fs/nfsd/trace.h instead as a
macro wrapper for __print_symbolic(). But see below.


>  static __be32
>  nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>  	     union nfsd4_op_u *u)
> @@ -822,6 +847,10 @@ nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>  	__be32 status;
>  	dev_t rdev;
>  
> +	trace_nfsd4_create(rqstp, &cstate->current_fh,
> +			   nfs_type_to_vfs_type(create->cr_type),
> +			   create->cr_name, create->cr_namelen);
> +
>  	fh_init(&resfh, NFS4_FHSIZE);
>  
>  	status = fh_verify(rqstp, &cstate->current_fh, S_IFDIR, NFSD_MAY_NOP);
> diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
> index 6dda081eb24c00b834ab0965c3a35a12115bceb7..33d8cbf8785588d38d4ec5efd769c1d1d06c6a91 100644
> --- a/fs/nfsd/nfsproc.c
> +++ b/fs/nfsd/nfsproc.c
> @@ -10,6 +10,7 @@
>  #include "cache.h"
>  #include "xdr.h"
>  #include "vfs.h"
> +#include "trace.h"
>  
>  #define NFSDDBG_FACILITY		NFSDDBG_PROC
>  
> @@ -292,8 +293,7 @@ nfsd_proc_create(struct svc_rqst *rqstp)
>  	int		hosterr;
>  	dev_t		rdev = 0, wanted = new_decode_dev(attr->ia_size);
>  
> -	dprintk("nfsd: CREATE   %s %.*s\n",
> -		SVCFH_fmt(dirfhp), argp->len, argp->name);
> +	trace_nfsd_proc_create(rqstp, dirfhp, S_IFREG, argp->name, argp->len);
>  
>  	/* First verify the parent file handle */
>  	resp->status = fh_verify(rqstp, dirfhp, S_IFDIR, NFSD_MAY_EXEC);
> @@ -548,7 +548,7 @@ nfsd_proc_mkdir(struct svc_rqst *rqstp)
>  		.na_iattr	= &argp->attrs,
>  	};
>  
> -	dprintk("nfsd: MKDIR    %s %.*s\n", SVCFH_fmt(&argp->fh), argp->len, argp->name);
> +	trace_nfsd_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
>  
>  	if (resp->fh.fh_dentry) {
>  		printk(KERN_WARNING
> diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
> index 382849d7c321d6ded8213890c2e7075770aa716c..c6aff23a845f06c87e701d57ec577c2c5c5a743c 100644
> --- a/fs/nfsd/trace.h
> +++ b/fs/nfsd/trace.h
> @@ -2391,6 +2391,45 @@ TRACE_EVENT(nfsd_lookup_dentry,
>  	TP_printk("xid=0x%08x fh_hash=0x%08x name=%s",
>  		  __entry->xid, __entry->fh_hash, __get_str(name))
>  );
> +
> +DECLARE_EVENT_CLASS(nfsd_vfs_create_class,
> +	TP_PROTO(struct svc_rqst *rqstp,
> +		 struct svc_fh *fhp,
> +		 umode_t type,
> +		 const char *name,
> +		 unsigned int len),
> +	TP_ARGS(rqstp, fhp, type, name, len),
> +	TP_STRUCT__entry(
> +		SVC_RQST_ENDPOINT_FIELDS(rqstp)
> +		__field(u32, fh_hash)
> +		__field(umode_t, type)
> +		__string_len(name, name, len)
> +	),
> +	TP_fast_assign(
> +		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
> +		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
> +		__entry->type = type;
> +		__assign_str(name);
> +	),
> +	TP_printk("xid=0x%08x fh_hash=0x%08x type=%s name=%s",
> +		  __entry->xid, __entry->fh_hash,
> +		  show_fs_file_type(__entry->type), __get_str(name))
> +);
> +
> +#define DEFINE_NFSD_VFS_CREATE_EVENT(__name)						\
> +	DEFINE_EVENT(nfsd_vfs_create_class, __name,					\
> +		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp,		\
> +			      umode_t type, const char *name, unsigned int len),	\
> +		     TP_ARGS(rqstp, fhp, type, name, len))
> +
> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_create);
> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_mkdir);
> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_create);
> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mkdir);
> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mknod);
> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create);
> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create_file);

I think we would be better off with one or two new trace points in
nfsd_create() and nfsd_create_setattr() instead of all of these...

Unless I've missed what you are trying to observe...?


> +
>  #endif /* _NFSD_TRACE_H */
>  
>  #undef TRACE_INCLUDE_PATH
> 


-- 
Chuck Lever

Re: [PATCH v2 07/12] nfsd: add tracepoints for symlink events

[Chuck Lever]

On 4/9/25 10:32 AM, Jeff Layton wrote:
> ...and remove the legacy dprintks.
> 
> Signed-off-by: Jeff Layton <jlayton@kernel.org>
> ---
>  fs/nfsd/nfs3proc.c |  8 +++-----
>  fs/nfsd/nfs4proc.c |  3 +++
>  fs/nfsd/nfsproc.c  |  7 +++----
>  fs/nfsd/trace.h    | 35 +++++++++++++++++++++++++++++++++++
>  4 files changed, 44 insertions(+), 9 deletions(-)
> 
> diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
> index ea1280970ea11b2a82f0de88ad0422eef7063d6d..587fc92597e7c77d078e871b8d12684c6b5efa2d 100644
> --- a/fs/nfsd/nfs3proc.c
> +++ b/fs/nfsd/nfs3proc.c
> @@ -423,6 +423,9 @@ nfsd3_proc_symlink(struct svc_rqst *rqstp)
>  		.na_iattr	= &argp->attrs,
>  	};
>  
> +	trace_nfsd3_proc_symlink(rqstp, &argp->ffh, argp->fname, argp->flen,
> +				 argp->tname, argp->tlen);
> +
>  	if (argp->tlen == 0) {
>  		resp->status = nfserr_inval;
>  		goto out;
> @@ -440,11 +443,6 @@ nfsd3_proc_symlink(struct svc_rqst *rqstp)
>  		goto out;
>  	}
>  
> -	dprintk("nfsd: SYMLINK(3)  %s %.*s -> %.*s\n",
> -				SVCFH_fmt(&argp->ffh),
> -				argp->flen, argp->fname,
> -				argp->tlen, argp->tname);
> -
>  	fh_copy(&resp->dirfh, &argp->ffh);
>  	fh_init(&resp->fh, NFS3_FHSIZE);
>  	resp->status = nfsd_symlink(rqstp, &resp->dirfh, argp->fname,
> diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
> index 2c795103deaa4044596bd07d90db788169a32a0c..e22596a2e311861be1e4f595d77547be04634ce7 100644
> --- a/fs/nfsd/nfs4proc.c
> +++ b/fs/nfsd/nfs4proc.c
> @@ -873,6 +873,9 @@ nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>  	current->fs->umask = create->cr_umask;
>  	switch (create->cr_type) {
>  	case NF4LNK:
> +		trace_nfsd4_symlink(rqstp, &cstate->current_fh,
> +				    create->cr_name, create->cr_namelen,
> +				    create->cr_data, create->cr_datalen);
>  		status = nfsd_symlink(rqstp, &cstate->current_fh,
>  				      create->cr_name, create->cr_namelen,
>  				      create->cr_data, &attrs, &resfh);
> diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
> index 33d8cbf8785588d38d4ec5efd769c1d1d06c6a91..0674ed6b978f6caa1325a9271f2fde9b3ef60945 100644
> --- a/fs/nfsd/nfsproc.c
> +++ b/fs/nfsd/nfsproc.c
> @@ -506,6 +506,9 @@ nfsd_proc_symlink(struct svc_rqst *rqstp)
>  	};
>  	struct svc_fh	newfh;
>  
> +	trace_nfsd_proc_symlink(rqstp, &argp->ffh, argp->fname, argp->flen,
> +				argp->tname, argp->tlen);
> +
>  	if (argp->tlen > NFS_MAXPATHLEN) {
>  		resp->status = nfserr_nametoolong;
>  		goto out;
> @@ -519,10 +522,6 @@ nfsd_proc_symlink(struct svc_rqst *rqstp)
>  		goto out;
>  	}
>  
> -	dprintk("nfsd: SYMLINK  %s %.*s -> %.*s\n",
> -		SVCFH_fmt(&argp->ffh), argp->flen, argp->fname,
> -		argp->tlen, argp->tname);
> -
>  	fh_init(&newfh, NFS_FHSIZE);
>  	resp->status = nfsd_symlink(rqstp, &argp->ffh, argp->fname, argp->flen,
>  				    argp->tname, &attrs, &newfh);
> diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
> index c6aff23a845f06c87e701d57ec577c2c5c5a743c..850dbf1240b234b67dd7d75d6903c0f49dc01261 100644
> --- a/fs/nfsd/trace.h
> +++ b/fs/nfsd/trace.h
> @@ -2430,6 +2430,41 @@ DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mknod);
>  DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create);
>  DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create_file);
>  
> +DECLARE_EVENT_CLASS(nfsd_vfs_symlink_class,
> +	TP_PROTO(struct svc_rqst *rqstp,
> +		 struct svc_fh *fhp,
> +		 const char *name,
> +		 unsigned int namelen,
> +		 const char *tgt,
> +		 unsigned int tgtlen),
> +	TP_ARGS(rqstp, fhp, name, namelen, tgt, tgtlen),
> +	TP_STRUCT__entry(
> +		SVC_RQST_ENDPOINT_FIELDS(rqstp)
> +		__field(u32, fh_hash)
> +		__string_len(name, name, namelen)
> +		__string_len(tgt, tgt, tgtlen)
> +	),
> +	TP_fast_assign(
> +		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
> +		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
> +		__assign_str(name);
> +		__assign_str(tgt);
> +	),
> +	TP_printk("xid=0x%08x fh_hash=0x%08x name=%s target=%s",
> +		  __entry->xid, __entry->fh_hash,
> +		  __get_str(name), __get_str(tgt))
> +);
> +
> +#define DEFINE_NFSD_VFS_SYMLINK_EVENT(__name)					\
> +	DEFINE_EVENT(nfsd_vfs_symlink_class, __name,				\
> +		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp,	\
> +			      const char *name, unsigned int namelen,		\
> +			      const char *tgt, unsigned int tgtlen),		\
> +		     TP_ARGS(rqstp, fhp, name, namelen, tgt, tgtlen))
> +
> +DEFINE_NFSD_VFS_SYMLINK_EVENT(nfsd_proc_symlink);
> +DEFINE_NFSD_VFS_SYMLINK_EVENT(nfsd3_proc_symlink);
> +DEFINE_NFSD_VFS_SYMLINK_EVENT(nfsd4_symlink);

Likewise, maybe one tracepoint in nfsd_symlink() would be better? This
comment also applies to the remaining patches in this series.

If you're trying to capture the NFS version too, perhaps
SVC_RQST_ENDPOINT can be expanded to record the RPC program and version.

Also, name these new tracepoints "nfsd_vfs_yada" and then you can use a
glob to enable the VFS tracepoints in one go, like so:

  # trace-cmd record -e nfsd:nfsd_vfs_\*


>  #endif /* _NFSD_TRACE_H */
>  
>  #undef TRACE_INCLUDE_PATH
> 


-- 
Chuck Lever

Re: [PATCH v2 02/12] sunrpc: add info about xprt queue times to svc_xprt_dequeue tracepoint

[Jeff Layton]

On Wed, 2025-04-09 at 11:00 -0400, Chuck Lever wrote:
> On 4/9/25 10:32 AM, Jeff Layton wrote:
> > Currently, this tracepoint displays "wakeup-us", which is the time that
> > the woken thread spent sleeping, before dequeueing the next xprt. Add a
> > new statistic that shows how long the xprt sat on the queue before being
> > serviced.
> 
> I don't understand the difference between "waiting on queue" and
> "sleeping". When are those two latency measurements not the same?
> 

These are measuring two different things:

svc_rqst->rq_qtime represents the time between when thread on the
sp_idle_threads list was woken. This patch adds svc_xprt->xpt_qtime,
which represents the time that the svc_xprt was added to the lwq.

The first tells us how long the interval was between the thread being
woken and the xprt being dequeued. The new statistic tells us how long
between the xprt being enqueued and dequeued.

They could easily diverge if there were not enough threads available to
service all of the queued xprts.

> 
> > Signed-off-by: Jeff Layton <jlayton@kernel.org>
> > ---
> >  include/linux/sunrpc/svc_xprt.h |  1 +
> >  include/trace/events/sunrpc.h   | 13 +++++++------
> >  net/sunrpc/svc_xprt.c           |  1 +
> >  3 files changed, 9 insertions(+), 6 deletions(-)
> > 
> > diff --git a/include/linux/sunrpc/svc_xprt.h b/include/linux/sunrpc/svc_xprt.h
> > index 72be609525796792274d5b8cb5ff37f73723fc23..369a89aea18618748607ee943247c327bf62c8d5 100644
> > --- a/include/linux/sunrpc/svc_xprt.h
> > +++ b/include/linux/sunrpc/svc_xprt.h
> > @@ -53,6 +53,7 @@ struct svc_xprt {
> >  	struct svc_xprt_class	*xpt_class;
> >  	const struct svc_xprt_ops *xpt_ops;
> >  	struct kref		xpt_ref;
> > +	ktime_t			xpt_qtime;
> >  	struct list_head	xpt_list;
> >  	struct lwq_node		xpt_ready;
> >  	unsigned long		xpt_flags;
> > diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> > index 5d331383047b79b9f6dcd699c87287453c1a5f49..b5a0f0bc1a3b7cfd90ce0181a8a419db810988bb 100644
> > --- a/include/trace/events/sunrpc.h
> > +++ b/include/trace/events/sunrpc.h
> > @@ -2040,19 +2040,20 @@ TRACE_EVENT(svc_xprt_dequeue,
> >  
> >  	TP_STRUCT__entry(
> >  		SVC_XPRT_ENDPOINT_FIELDS(rqst->rq_xprt)
> > -
> >  		__field(unsigned long, wakeup)
> > +		__field(unsigned long, qtime)
> >  	),
> >  
> >  	TP_fast_assign(
> > -		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
> > +		ktime_t ktime = ktime_get();
> >  
> > -		__entry->wakeup = ktime_to_us(ktime_sub(ktime_get(),
> > -							rqst->rq_qtime));
> > +		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
> > +		__entry->wakeup = ktime_to_us(ktime_sub(ktime, rqst->rq_qtime));
> > +		__entry->qtime = ktime_to_us(ktime_sub(ktime, rqst->rq_xprt->xpt_qtime));
> >  	),
> >  
> > -	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu",
> > -		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup)
> > +	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu qtime=%lu",
> > +		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup, __entry->qtime)
> >  );
> >  
> >  DECLARE_EVENT_CLASS(svc_xprt_event,
> > diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
> > index ae25405d8bd22672a361d1fd3adfdcebb403f90f..32018557797b1f683d8b7259f5fccd029aebcd71 100644
> > --- a/net/sunrpc/svc_xprt.c
> > +++ b/net/sunrpc/svc_xprt.c
> > @@ -488,6 +488,7 @@ void svc_xprt_enqueue(struct svc_xprt *xprt)
> >  	pool = svc_pool_for_cpu(xprt->xpt_server);
> >  
> >  	percpu_counter_inc(&pool->sp_sockets_queued);
> > +	xprt->xpt_qtime = ktime_get();
> >  	lwq_enqueue(&xprt->xpt_ready, &pool->sp_xprts);
> >  
> >  	svc_pool_wake_idle_thread(pool);
> > 
> 
> 

-- 
Jeff Layton <jlayton@kernel.org>

Re: [PATCH v2 06/12] nfsd: add tracepoints around nfsd_create events

[Jeff Layton]

On Wed, 2025-04-09 at 11:09 -0400, Chuck Lever wrote:
> On 4/9/25 10:32 AM, Jeff Layton wrote:
> > ...and remove the legacy dprintks.
> > 
> > Signed-off-by: Jeff Layton <jlayton@kernel.org>
> > ---
> >  fs/nfsd/nfs3proc.c | 18 +++++-------------
> >  fs/nfsd/nfs4proc.c | 29 +++++++++++++++++++++++++++++
> >  fs/nfsd/nfsproc.c  |  6 +++---
> >  fs/nfsd/trace.h    | 39 +++++++++++++++++++++++++++++++++++++++
> >  4 files changed, 76 insertions(+), 16 deletions(-)
> > 
> > diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
> > index 372bdcf5e07a5c835da240ecebb02e3576eb2ca6..ea1280970ea11b2a82f0de88ad0422eef7063d6d 100644
> > --- a/fs/nfsd/nfs3proc.c
> > +++ b/fs/nfsd/nfs3proc.c
> > @@ -14,6 +14,7 @@
> >  #include "xdr3.h"
> >  #include "vfs.h"
> >  #include "filecache.h"
> > +#include "trace.h"
> >  
> >  #define NFSDDBG_FACILITY		NFSDDBG_PROC
> >  
> > @@ -380,10 +381,7 @@ nfsd3_proc_create(struct svc_rqst *rqstp)
> >  	struct nfsd3_diropres *resp = rqstp->rq_resp;
> >  	svc_fh *dirfhp, *newfhp;
> >  
> > -	dprintk("nfsd: CREATE(3)   %s %.*s\n",
> > -				SVCFH_fmt(&argp->fh),
> > -				argp->len,
> > -				argp->name);
> > +	trace_nfsd3_proc_create(rqstp, &argp->fh, S_IFREG, argp->name, argp->len);
> >  
> >  	dirfhp = fh_copy(&resp->dirfh, &argp->fh);
> >  	newfhp = fh_init(&resp->fh, NFS3_FHSIZE);
> > @@ -405,10 +403,7 @@ nfsd3_proc_mkdir(struct svc_rqst *rqstp)
> >  		.na_iattr	= &argp->attrs,
> >  	};
> >  
> > -	dprintk("nfsd: MKDIR(3)    %s %.*s\n",
> > -				SVCFH_fmt(&argp->fh),
> > -				argp->len,
> > -				argp->name);
> > +	trace_nfsd3_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
> >  
> >  	argp->attrs.ia_valid &= ~ATTR_SIZE;
> >  	fh_copy(&resp->dirfh, &argp->fh);
> > @@ -471,13 +466,10 @@ nfsd3_proc_mknod(struct svc_rqst *rqstp)
> >  	struct nfsd_attrs attrs = {
> >  		.na_iattr	= &argp->attrs,
> >  	};
> > -	int type;
> > +	int type = nfs3_ftypes[argp->ftype];
> >  	dev_t	rdev = 0;
> >  
> > -	dprintk("nfsd: MKNOD(3)    %s %.*s\n",
> > -				SVCFH_fmt(&argp->fh),
> > -				argp->len,
> > -				argp->name);
> > +	trace_nfsd3_proc_mknod(rqstp, &argp->fh, type, argp->name, argp->len);
> >  
> >  	fh_copy(&resp->dirfh, &argp->fh);
> >  	fh_init(&resp->fh, NFS3_FHSIZE);
> > diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
> > index 6e23d6103010197c0316b07c189fe12ec3033812..2c795103deaa4044596bd07d90db788169a32a0c 100644
> > --- a/fs/nfsd/nfs4proc.c
> > +++ b/fs/nfsd/nfs4proc.c
> > @@ -250,6 +250,8 @@ nfsd4_create_file(struct svc_rqst *rqstp, struct svc_fh *fhp,
> >  	__be32 status;
> >  	int host_err;
> >  
> > +	trace_nfsd4_create_file(rqstp, fhp, S_IFREG, open->op_fname, open->op_fnamelen);
> > +
> >  	if (isdotent(open->op_fname, open->op_fnamelen))
> >  		return nfserr_exist;
> >  	if (!(iap->ia_valid & ATTR_MODE))
> > @@ -807,6 +809,29 @@ nfsd4_commit(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
> >  	return status;
> >  }
> >  
> > +static umode_t nfs_type_to_vfs_type(enum nfs_ftype4 nfstype)
> > +{
> > +	switch (nfstype) {
> > +	case NF4REG:
> > +		return S_IFREG;
> > +	case NF4DIR:
> > +		return S_IFDIR;
> > +	case NF4BLK:
> > +		return S_IFBLK;
> > +	case NF4CHR:
> > +		return S_IFCHR;
> > +	case NF4LNK:
> > +		return S_IFLNK;
> > +	case NF4SOCK:
> > +		return S_IFSOCK;
> > +	case NF4FIFO:
> > +		return S_IFIFO;
> > +	default:
> > +		break;
> > +	}
> > +	return 0;
> > +}
> > +
> 
> Wondering what happens when trace points are disabled in the kernel
> build. Maybe this helper belongs in fs/nfsd/trace.h instead as a
> macro wrapper for __print_symbolic(). But see below.
> 

If tracepoints are disabled, then the only caller of this static
function would go away, so it should get optimized out. I don't see how
you'd make this a wrapper around __print_symbolic(), since the point is
to pass in a NFS version-independent constant that the tracepoint class
can use as a type.

> 
> >  static __be32
> >  nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
> >  	     union nfsd4_op_u *u)
> > @@ -822,6 +847,10 @@ nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
> >  	__be32 status;
> >  	dev_t rdev;
> >  
> > +	trace_nfsd4_create(rqstp, &cstate->current_fh,
> > +			   nfs_type_to_vfs_type(create->cr_type),
> > +			   create->cr_name, create->cr_namelen);
> > +
> >  	fh_init(&resfh, NFS4_FHSIZE);
> >  
> >  	status = fh_verify(rqstp, &cstate->current_fh, S_IFDIR, NFSD_MAY_NOP);
> > diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
> > index 6dda081eb24c00b834ab0965c3a35a12115bceb7..33d8cbf8785588d38d4ec5efd769c1d1d06c6a91 100644
> > --- a/fs/nfsd/nfsproc.c
> > +++ b/fs/nfsd/nfsproc.c
> > @@ -10,6 +10,7 @@
> >  #include "cache.h"
> >  #include "xdr.h"
> >  #include "vfs.h"
> > +#include "trace.h"
> >  
> >  #define NFSDDBG_FACILITY		NFSDDBG_PROC
> >  
> > @@ -292,8 +293,7 @@ nfsd_proc_create(struct svc_rqst *rqstp)
> >  	int		hosterr;
> >  	dev_t		rdev = 0, wanted = new_decode_dev(attr->ia_size);
> >  
> > -	dprintk("nfsd: CREATE   %s %.*s\n",
> > -		SVCFH_fmt(dirfhp), argp->len, argp->name);
> > +	trace_nfsd_proc_create(rqstp, dirfhp, S_IFREG, argp->name, argp->len);
> >  
> >  	/* First verify the parent file handle */
> >  	resp->status = fh_verify(rqstp, dirfhp, S_IFDIR, NFSD_MAY_EXEC);
> > @@ -548,7 +548,7 @@ nfsd_proc_mkdir(struct svc_rqst *rqstp)
> >  		.na_iattr	= &argp->attrs,
> >  	};
> >  
> > -	dprintk("nfsd: MKDIR    %s %.*s\n", SVCFH_fmt(&argp->fh), argp->len, argp->name);
> > +	trace_nfsd_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
> >  
> >  	if (resp->fh.fh_dentry) {
> >  		printk(KERN_WARNING
> > diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
> > index 382849d7c321d6ded8213890c2e7075770aa716c..c6aff23a845f06c87e701d57ec577c2c5c5a743c 100644
> > --- a/fs/nfsd/trace.h
> > +++ b/fs/nfsd/trace.h
> > @@ -2391,6 +2391,45 @@ TRACE_EVENT(nfsd_lookup_dentry,
> >  	TP_printk("xid=0x%08x fh_hash=0x%08x name=%s",
> >  		  __entry->xid, __entry->fh_hash, __get_str(name))
> >  );
> > +
> > +DECLARE_EVENT_CLASS(nfsd_vfs_create_class,
> > +	TP_PROTO(struct svc_rqst *rqstp,
> > +		 struct svc_fh *fhp,
> > +		 umode_t type,
> > +		 const char *name,
> > +		 unsigned int len),
> > +	TP_ARGS(rqstp, fhp, type, name, len),
> > +	TP_STRUCT__entry(
> > +		SVC_RQST_ENDPOINT_FIELDS(rqstp)
> > +		__field(u32, fh_hash)
> > +		__field(umode_t, type)
> > +		__string_len(name, name, len)
> > +	),
> > +	TP_fast_assign(
> > +		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
> > +		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
> > +		__entry->type = type;
> > +		__assign_str(name);
> > +	),
> > +	TP_printk("xid=0x%08x fh_hash=0x%08x type=%s name=%s",
> > +		  __entry->xid, __entry->fh_hash,
> > +		  show_fs_file_type(__entry->type), __get_str(name))
> > +);
> > +
> > +#define DEFINE_NFSD_VFS_CREATE_EVENT(__name)						\
> > +	DEFINE_EVENT(nfsd_vfs_create_class, __name,					\
> > +		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp,		\
> > +			      umode_t type, const char *name, unsigned int len),	\
> > +		     TP_ARGS(rqstp, fhp, type, name, len))
> > +
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_create);
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_mkdir);
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_create);
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mkdir);
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mknod);
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create);
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create_file);
> 
> I think we would be better off with one or two new trace points in
> nfsd_create() and nfsd_create_setattr() instead of all of these...
> 
> Unless I've missed what you are trying to observe...?
>

I'll look into doing it that way.

> 
> > +
> >  #endif /* _NFSD_TRACE_H */
> >  
> >  #undef TRACE_INCLUDE_PATH
> > 
> 
> 

-- 
Jeff Layton <jlayton@kernel.org>

Re: [PATCH v2 06/12] nfsd: add tracepoints around nfsd_create events

[Chuck Lever]

On 4/9/25 11:36 AM, Jeff Layton wrote:
> On Wed, 2025-04-09 at 11:09 -0400, Chuck Lever wrote:
>> On 4/9/25 10:32 AM, Jeff Layton wrote:
>>> ...and remove the legacy dprintks.
>>>
>>> Signed-off-by: Jeff Layton <jlayton@kernel.org>
>>> ---
>>>  fs/nfsd/nfs3proc.c | 18 +++++-------------
>>>  fs/nfsd/nfs4proc.c | 29 +++++++++++++++++++++++++++++
>>>  fs/nfsd/nfsproc.c  |  6 +++---
>>>  fs/nfsd/trace.h    | 39 +++++++++++++++++++++++++++++++++++++++
>>>  4 files changed, 76 insertions(+), 16 deletions(-)
>>>
>>> diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
>>> index 372bdcf5e07a5c835da240ecebb02e3576eb2ca6..ea1280970ea11b2a82f0de88ad0422eef7063d6d 100644
>>> --- a/fs/nfsd/nfs3proc.c
>>> +++ b/fs/nfsd/nfs3proc.c
>>> @@ -14,6 +14,7 @@
>>>  #include "xdr3.h"
>>>  #include "vfs.h"
>>>  #include "filecache.h"
>>> +#include "trace.h"
>>>  
>>>  #define NFSDDBG_FACILITY		NFSDDBG_PROC
>>>  
>>> @@ -380,10 +381,7 @@ nfsd3_proc_create(struct svc_rqst *rqstp)
>>>  	struct nfsd3_diropres *resp = rqstp->rq_resp;
>>>  	svc_fh *dirfhp, *newfhp;
>>>  
>>> -	dprintk("nfsd: CREATE(3)   %s %.*s\n",
>>> -				SVCFH_fmt(&argp->fh),
>>> -				argp->len,
>>> -				argp->name);
>>> +	trace_nfsd3_proc_create(rqstp, &argp->fh, S_IFREG, argp->name, argp->len);
>>>  
>>>  	dirfhp = fh_copy(&resp->dirfh, &argp->fh);
>>>  	newfhp = fh_init(&resp->fh, NFS3_FHSIZE);
>>> @@ -405,10 +403,7 @@ nfsd3_proc_mkdir(struct svc_rqst *rqstp)
>>>  		.na_iattr	= &argp->attrs,
>>>  	};
>>>  
>>> -	dprintk("nfsd: MKDIR(3)    %s %.*s\n",
>>> -				SVCFH_fmt(&argp->fh),
>>> -				argp->len,
>>> -				argp->name);
>>> +	trace_nfsd3_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
>>>  
>>>  	argp->attrs.ia_valid &= ~ATTR_SIZE;
>>>  	fh_copy(&resp->dirfh, &argp->fh);
>>> @@ -471,13 +466,10 @@ nfsd3_proc_mknod(struct svc_rqst *rqstp)
>>>  	struct nfsd_attrs attrs = {
>>>  		.na_iattr	= &argp->attrs,
>>>  	};
>>> -	int type;
>>> +	int type = nfs3_ftypes[argp->ftype];
>>>  	dev_t	rdev = 0;
>>>  
>>> -	dprintk("nfsd: MKNOD(3)    %s %.*s\n",
>>> -				SVCFH_fmt(&argp->fh),
>>> -				argp->len,
>>> -				argp->name);
>>> +	trace_nfsd3_proc_mknod(rqstp, &argp->fh, type, argp->name, argp->len);
>>>  
>>>  	fh_copy(&resp->dirfh, &argp->fh);
>>>  	fh_init(&resp->fh, NFS3_FHSIZE);
>>> diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
>>> index 6e23d6103010197c0316b07c189fe12ec3033812..2c795103deaa4044596bd07d90db788169a32a0c 100644
>>> --- a/fs/nfsd/nfs4proc.c
>>> +++ b/fs/nfsd/nfs4proc.c
>>> @@ -250,6 +250,8 @@ nfsd4_create_file(struct svc_rqst *rqstp, struct svc_fh *fhp,
>>>  	__be32 status;
>>>  	int host_err;
>>>  
>>> +	trace_nfsd4_create_file(rqstp, fhp, S_IFREG, open->op_fname, open->op_fnamelen);
>>> +
>>>  	if (isdotent(open->op_fname, open->op_fnamelen))
>>>  		return nfserr_exist;
>>>  	if (!(iap->ia_valid & ATTR_MODE))
>>> @@ -807,6 +809,29 @@ nfsd4_commit(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>>>  	return status;
>>>  }
>>>  
>>> +static umode_t nfs_type_to_vfs_type(enum nfs_ftype4 nfstype)
>>> +{
>>> +	switch (nfstype) {
>>> +	case NF4REG:
>>> +		return S_IFREG;
>>> +	case NF4DIR:
>>> +		return S_IFDIR;
>>> +	case NF4BLK:
>>> +		return S_IFBLK;
>>> +	case NF4CHR:
>>> +		return S_IFCHR;
>>> +	case NF4LNK:
>>> +		return S_IFLNK;
>>> +	case NF4SOCK:
>>> +		return S_IFSOCK;
>>> +	case NF4FIFO:
>>> +		return S_IFIFO;
>>> +	default:
>>> +		break;
>>> +	}
>>> +	return 0;
>>> +}
>>> +
>>
>> Wondering what happens when trace points are disabled in the kernel
>> build. Maybe this helper belongs in fs/nfsd/trace.h instead as a
>> macro wrapper for __print_symbolic(). But see below.
>>
> 
> If tracepoints are disabled, then the only caller of this static
> function would go away, so it should get optimized out.

AIUI, the compiler will complain in that case. If we need to keep this
function here, then this is a legitimate use for "inline".


> I don't see how
> you'd make this a wrapper around __print_symbolic(), since the point is
> to pass in a NFS version-independent constant that the tracepoint class
> can use as a type.
> 
>>
>>>  static __be32
>>>  nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>>>  	     union nfsd4_op_u *u)
>>> @@ -822,6 +847,10 @@ nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>>>  	__be32 status;
>>>  	dev_t rdev;
>>>  
>>> +	trace_nfsd4_create(rqstp, &cstate->current_fh,
>>> +			   nfs_type_to_vfs_type(create->cr_type),
>>> +			   create->cr_name, create->cr_namelen);
>>> +
>>>  	fh_init(&resfh, NFS4_FHSIZE);
>>>  
>>>  	status = fh_verify(rqstp, &cstate->current_fh, S_IFDIR, NFSD_MAY_NOP);
>>> diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
>>> index 6dda081eb24c00b834ab0965c3a35a12115bceb7..33d8cbf8785588d38d4ec5efd769c1d1d06c6a91 100644
>>> --- a/fs/nfsd/nfsproc.c
>>> +++ b/fs/nfsd/nfsproc.c
>>> @@ -10,6 +10,7 @@
>>>  #include "cache.h"
>>>  #include "xdr.h"
>>>  #include "vfs.h"
>>> +#include "trace.h"
>>>  
>>>  #define NFSDDBG_FACILITY		NFSDDBG_PROC
>>>  
>>> @@ -292,8 +293,7 @@ nfsd_proc_create(struct svc_rqst *rqstp)
>>>  	int		hosterr;
>>>  	dev_t		rdev = 0, wanted = new_decode_dev(attr->ia_size);
>>>  
>>> -	dprintk("nfsd: CREATE   %s %.*s\n",
>>> -		SVCFH_fmt(dirfhp), argp->len, argp->name);
>>> +	trace_nfsd_proc_create(rqstp, dirfhp, S_IFREG, argp->name, argp->len);
>>>  
>>>  	/* First verify the parent file handle */
>>>  	resp->status = fh_verify(rqstp, dirfhp, S_IFDIR, NFSD_MAY_EXEC);
>>> @@ -548,7 +548,7 @@ nfsd_proc_mkdir(struct svc_rqst *rqstp)
>>>  		.na_iattr	= &argp->attrs,
>>>  	};
>>>  
>>> -	dprintk("nfsd: MKDIR    %s %.*s\n", SVCFH_fmt(&argp->fh), argp->len, argp->name);
>>> +	trace_nfsd_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
>>>  
>>>  	if (resp->fh.fh_dentry) {
>>>  		printk(KERN_WARNING
>>> diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
>>> index 382849d7c321d6ded8213890c2e7075770aa716c..c6aff23a845f06c87e701d57ec577c2c5c5a743c 100644
>>> --- a/fs/nfsd/trace.h
>>> +++ b/fs/nfsd/trace.h
>>> @@ -2391,6 +2391,45 @@ TRACE_EVENT(nfsd_lookup_dentry,
>>>  	TP_printk("xid=0x%08x fh_hash=0x%08x name=%s",
>>>  		  __entry->xid, __entry->fh_hash, __get_str(name))
>>>  );
>>> +
>>> +DECLARE_EVENT_CLASS(nfsd_vfs_create_class,
>>> +	TP_PROTO(struct svc_rqst *rqstp,
>>> +		 struct svc_fh *fhp,
>>> +		 umode_t type,
>>> +		 const char *name,
>>> +		 unsigned int len),
>>> +	TP_ARGS(rqstp, fhp, type, name, len),
>>> +	TP_STRUCT__entry(
>>> +		SVC_RQST_ENDPOINT_FIELDS(rqstp)
>>> +		__field(u32, fh_hash)
>>> +		__field(umode_t, type)
>>> +		__string_len(name, name, len)
>>> +	),
>>> +	TP_fast_assign(
>>> +		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
>>> +		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
>>> +		__entry->type = type;
>>> +		__assign_str(name);
>>> +	),
>>> +	TP_printk("xid=0x%08x fh_hash=0x%08x type=%s name=%s",
>>> +		  __entry->xid, __entry->fh_hash,
>>> +		  show_fs_file_type(__entry->type), __get_str(name))
>>> +);
>>> +
>>> +#define DEFINE_NFSD_VFS_CREATE_EVENT(__name)						\
>>> +	DEFINE_EVENT(nfsd_vfs_create_class, __name,					\
>>> +		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp,		\
>>> +			      umode_t type, const char *name, unsigned int len),	\
>>> +		     TP_ARGS(rqstp, fhp, type, name, len))
>>> +
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_create);
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_mkdir);
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_create);
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mkdir);
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mknod);
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create);
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create_file);
>>
>> I think we would be better off with one or two new trace points in
>> nfsd_create() and nfsd_create_setattr() instead of all of these...
>>
>> Unless I've missed what you are trying to observe...?
>>
> 
> I'll look into doing it that way.
> 
>>
>>> +
>>>  #endif /* _NFSD_TRACE_H */
>>>  
>>>  #undef TRACE_INCLUDE_PATH
>>>
>>
>>
> 


-- 
Chuck Lever

Re: [PATCH v2 06/12] nfsd: add tracepoints around nfsd_create events

[Chuck Lever]

On 4/9/25 11:38 AM, Chuck Lever wrote:
> On 4/9/25 11:36 AM, Jeff Layton wrote:
>> On Wed, 2025-04-09 at 11:09 -0400, Chuck Lever wrote:
>>> On 4/9/25 10:32 AM, Jeff Layton wrote:
>>>> ...and remove the legacy dprintks.
>>>>
>>>> Signed-off-by: Jeff Layton <jlayton@kernel.org>
>>>> ---
>>>>  fs/nfsd/nfs3proc.c | 18 +++++-------------
>>>>  fs/nfsd/nfs4proc.c | 29 +++++++++++++++++++++++++++++
>>>>  fs/nfsd/nfsproc.c  |  6 +++---
>>>>  fs/nfsd/trace.h    | 39 +++++++++++++++++++++++++++++++++++++++
>>>>  4 files changed, 76 insertions(+), 16 deletions(-)
>>>>
>>>> diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
>>>> index 372bdcf5e07a5c835da240ecebb02e3576eb2ca6..ea1280970ea11b2a82f0de88ad0422eef7063d6d 100644
>>>> --- a/fs/nfsd/nfs3proc.c
>>>> +++ b/fs/nfsd/nfs3proc.c
>>>> @@ -14,6 +14,7 @@
>>>>  #include "xdr3.h"
>>>>  #include "vfs.h"
>>>>  #include "filecache.h"
>>>> +#include "trace.h"
>>>>  
>>>>  #define NFSDDBG_FACILITY		NFSDDBG_PROC
>>>>  
>>>> @@ -380,10 +381,7 @@ nfsd3_proc_create(struct svc_rqst *rqstp)
>>>>  	struct nfsd3_diropres *resp = rqstp->rq_resp;
>>>>  	svc_fh *dirfhp, *newfhp;
>>>>  
>>>> -	dprintk("nfsd: CREATE(3)   %s %.*s\n",
>>>> -				SVCFH_fmt(&argp->fh),
>>>> -				argp->len,
>>>> -				argp->name);
>>>> +	trace_nfsd3_proc_create(rqstp, &argp->fh, S_IFREG, argp->name, argp->len);
>>>>  
>>>>  	dirfhp = fh_copy(&resp->dirfh, &argp->fh);
>>>>  	newfhp = fh_init(&resp->fh, NFS3_FHSIZE);
>>>> @@ -405,10 +403,7 @@ nfsd3_proc_mkdir(struct svc_rqst *rqstp)
>>>>  		.na_iattr	= &argp->attrs,
>>>>  	};
>>>>  
>>>> -	dprintk("nfsd: MKDIR(3)    %s %.*s\n",
>>>> -				SVCFH_fmt(&argp->fh),
>>>> -				argp->len,
>>>> -				argp->name);
>>>> +	trace_nfsd3_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
>>>>  
>>>>  	argp->attrs.ia_valid &= ~ATTR_SIZE;
>>>>  	fh_copy(&resp->dirfh, &argp->fh);
>>>> @@ -471,13 +466,10 @@ nfsd3_proc_mknod(struct svc_rqst *rqstp)
>>>>  	struct nfsd_attrs attrs = {
>>>>  		.na_iattr	= &argp->attrs,
>>>>  	};
>>>> -	int type;
>>>> +	int type = nfs3_ftypes[argp->ftype];
>>>>  	dev_t	rdev = 0;
>>>>  
>>>> -	dprintk("nfsd: MKNOD(3)    %s %.*s\n",
>>>> -				SVCFH_fmt(&argp->fh),
>>>> -				argp->len,
>>>> -				argp->name);
>>>> +	trace_nfsd3_proc_mknod(rqstp, &argp->fh, type, argp->name, argp->len);
>>>>  
>>>>  	fh_copy(&resp->dirfh, &argp->fh);
>>>>  	fh_init(&resp->fh, NFS3_FHSIZE);
>>>> diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
>>>> index 6e23d6103010197c0316b07c189fe12ec3033812..2c795103deaa4044596bd07d90db788169a32a0c 100644
>>>> --- a/fs/nfsd/nfs4proc.c
>>>> +++ b/fs/nfsd/nfs4proc.c
>>>> @@ -250,6 +250,8 @@ nfsd4_create_file(struct svc_rqst *rqstp, struct svc_fh *fhp,
>>>>  	__be32 status;
>>>>  	int host_err;
>>>>  
>>>> +	trace_nfsd4_create_file(rqstp, fhp, S_IFREG, open->op_fname, open->op_fnamelen);
>>>> +
>>>>  	if (isdotent(open->op_fname, open->op_fnamelen))
>>>>  		return nfserr_exist;
>>>>  	if (!(iap->ia_valid & ATTR_MODE))
>>>> @@ -807,6 +809,29 @@ nfsd4_commit(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>>>>  	return status;
>>>>  }
>>>>  
>>>> +static umode_t nfs_type_to_vfs_type(enum nfs_ftype4 nfstype)
>>>> +{
>>>> +	switch (nfstype) {
>>>> +	case NF4REG:
>>>> +		return S_IFREG;
>>>> +	case NF4DIR:
>>>> +		return S_IFDIR;
>>>> +	case NF4BLK:
>>>> +		return S_IFBLK;
>>>> +	case NF4CHR:
>>>> +		return S_IFCHR;
>>>> +	case NF4LNK:
>>>> +		return S_IFLNK;
>>>> +	case NF4SOCK:
>>>> +		return S_IFSOCK;
>>>> +	case NF4FIFO:
>>>> +		return S_IFIFO;
>>>> +	default:
>>>> +		break;
>>>> +	}
>>>> +	return 0;
>>>> +}
>>>> +
>>>
>>> Wondering what happens when trace points are disabled in the kernel
>>> build. Maybe this helper belongs in fs/nfsd/trace.h instead as a
>>> macro wrapper for __print_symbolic(). But see below.
>>>
>>
>> If tracepoints are disabled, then the only caller of this static
>> function would go away, so it should get optimized out.
> 
> AIUI, the compiler will complain in that case. If we need to keep this
> function here, then this is a legitimate use for "inline".

or maybe_unused.


>> I don't see how
>> you'd make this a wrapper around __print_symbolic(), since the point is
>> to pass in a NFS version-independent constant that the tracepoint class
>> can use as a type.
>>
>>>
>>>>  static __be32
>>>>  nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>>>>  	     union nfsd4_op_u *u)
>>>> @@ -822,6 +847,10 @@ nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>>>>  	__be32 status;
>>>>  	dev_t rdev;
>>>>  
>>>> +	trace_nfsd4_create(rqstp, &cstate->current_fh,
>>>> +			   nfs_type_to_vfs_type(create->cr_type),
>>>> +			   create->cr_name, create->cr_namelen);
>>>> +
>>>>  	fh_init(&resfh, NFS4_FHSIZE);
>>>>  
>>>>  	status = fh_verify(rqstp, &cstate->current_fh, S_IFDIR, NFSD_MAY_NOP);
>>>> diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
>>>> index 6dda081eb24c00b834ab0965c3a35a12115bceb7..33d8cbf8785588d38d4ec5efd769c1d1d06c6a91 100644
>>>> --- a/fs/nfsd/nfsproc.c
>>>> +++ b/fs/nfsd/nfsproc.c
>>>> @@ -10,6 +10,7 @@
>>>>  #include "cache.h"
>>>>  #include "xdr.h"
>>>>  #include "vfs.h"
>>>> +#include "trace.h"
>>>>  
>>>>  #define NFSDDBG_FACILITY		NFSDDBG_PROC
>>>>  
>>>> @@ -292,8 +293,7 @@ nfsd_proc_create(struct svc_rqst *rqstp)
>>>>  	int		hosterr;
>>>>  	dev_t		rdev = 0, wanted = new_decode_dev(attr->ia_size);
>>>>  
>>>> -	dprintk("nfsd: CREATE   %s %.*s\n",
>>>> -		SVCFH_fmt(dirfhp), argp->len, argp->name);
>>>> +	trace_nfsd_proc_create(rqstp, dirfhp, S_IFREG, argp->name, argp->len);
>>>>  
>>>>  	/* First verify the parent file handle */
>>>>  	resp->status = fh_verify(rqstp, dirfhp, S_IFDIR, NFSD_MAY_EXEC);
>>>> @@ -548,7 +548,7 @@ nfsd_proc_mkdir(struct svc_rqst *rqstp)
>>>>  		.na_iattr	= &argp->attrs,
>>>>  	};
>>>>  
>>>> -	dprintk("nfsd: MKDIR    %s %.*s\n", SVCFH_fmt(&argp->fh), argp->len, argp->name);
>>>> +	trace_nfsd_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
>>>>  
>>>>  	if (resp->fh.fh_dentry) {
>>>>  		printk(KERN_WARNING
>>>> diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
>>>> index 382849d7c321d6ded8213890c2e7075770aa716c..c6aff23a845f06c87e701d57ec577c2c5c5a743c 100644
>>>> --- a/fs/nfsd/trace.h
>>>> +++ b/fs/nfsd/trace.h
>>>> @@ -2391,6 +2391,45 @@ TRACE_EVENT(nfsd_lookup_dentry,
>>>>  	TP_printk("xid=0x%08x fh_hash=0x%08x name=%s",
>>>>  		  __entry->xid, __entry->fh_hash, __get_str(name))
>>>>  );
>>>> +
>>>> +DECLARE_EVENT_CLASS(nfsd_vfs_create_class,
>>>> +	TP_PROTO(struct svc_rqst *rqstp,
>>>> +		 struct svc_fh *fhp,
>>>> +		 umode_t type,
>>>> +		 const char *name,
>>>> +		 unsigned int len),
>>>> +	TP_ARGS(rqstp, fhp, type, name, len),
>>>> +	TP_STRUCT__entry(
>>>> +		SVC_RQST_ENDPOINT_FIELDS(rqstp)
>>>> +		__field(u32, fh_hash)
>>>> +		__field(umode_t, type)
>>>> +		__string_len(name, name, len)
>>>> +	),
>>>> +	TP_fast_assign(
>>>> +		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
>>>> +		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
>>>> +		__entry->type = type;
>>>> +		__assign_str(name);
>>>> +	),
>>>> +	TP_printk("xid=0x%08x fh_hash=0x%08x type=%s name=%s",
>>>> +		  __entry->xid, __entry->fh_hash,
>>>> +		  show_fs_file_type(__entry->type), __get_str(name))
>>>> +);
>>>> +
>>>> +#define DEFINE_NFSD_VFS_CREATE_EVENT(__name)						\
>>>> +	DEFINE_EVENT(nfsd_vfs_create_class, __name,					\
>>>> +		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp,		\
>>>> +			      umode_t type, const char *name, unsigned int len),	\
>>>> +		     TP_ARGS(rqstp, fhp, type, name, len))
>>>> +
>>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_create);
>>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_mkdir);
>>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_create);
>>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mkdir);
>>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mknod);
>>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create);
>>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create_file);
>>>
>>> I think we would be better off with one or two new trace points in
>>> nfsd_create() and nfsd_create_setattr() instead of all of these...
>>>
>>> Unless I've missed what you are trying to observe...?
>>>
>>
>> I'll look into doing it that way.
>>
>>>
>>>> +
>>>>  #endif /* _NFSD_TRACE_H */
>>>>  
>>>>  #undef TRACE_INCLUDE_PATH
>>>>
>>>
>>>
>>
> 
> 


-- 
Chuck Lever

Re: [PATCH v2 06/12] nfsd: add tracepoints around nfsd_create events

[Jeff Layton]

On Wed, 2025-04-09 at 11:09 -0400, Chuck Lever wrote:
> On 4/9/25 10:32 AM, Jeff Layton wrote:
> > ...and remove the legacy dprintks.
> > 
> > Signed-off-by: Jeff Layton <jlayton@kernel.org>
> > ---
> >  fs/nfsd/nfs3proc.c | 18 +++++-------------
> >  fs/nfsd/nfs4proc.c | 29 +++++++++++++++++++++++++++++
> >  fs/nfsd/nfsproc.c  |  6 +++---
> >  fs/nfsd/trace.h    | 39 +++++++++++++++++++++++++++++++++++++++
> >  4 files changed, 76 insertions(+), 16 deletions(-)
> > 
> > diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
> > index 372bdcf5e07a5c835da240ecebb02e3576eb2ca6..ea1280970ea11b2a82f0de88ad0422eef7063d6d 100644
> > --- a/fs/nfsd/nfs3proc.c
> > +++ b/fs/nfsd/nfs3proc.c
> > @@ -14,6 +14,7 @@
> >  #include "xdr3.h"
> >  #include "vfs.h"
> >  #include "filecache.h"
> > +#include "trace.h"
> >  
> >  #define NFSDDBG_FACILITY		NFSDDBG_PROC
> >  
> > @@ -380,10 +381,7 @@ nfsd3_proc_create(struct svc_rqst *rqstp)
> >  	struct nfsd3_diropres *resp = rqstp->rq_resp;
> >  	svc_fh *dirfhp, *newfhp;
> >  
> > -	dprintk("nfsd: CREATE(3)   %s %.*s\n",
> > -				SVCFH_fmt(&argp->fh),
> > -				argp->len,
> > -				argp->name);
> > +	trace_nfsd3_proc_create(rqstp, &argp->fh, S_IFREG, argp->name, argp->len);
> >  
> >  	dirfhp = fh_copy(&resp->dirfh, &argp->fh);
> >  	newfhp = fh_init(&resp->fh, NFS3_FHSIZE);
> > @@ -405,10 +403,7 @@ nfsd3_proc_mkdir(struct svc_rqst *rqstp)
> >  		.na_iattr	= &argp->attrs,
> >  	};
> >  
> > -	dprintk("nfsd: MKDIR(3)    %s %.*s\n",
> > -				SVCFH_fmt(&argp->fh),
> > -				argp->len,
> > -				argp->name);
> > +	trace_nfsd3_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
> >  
> >  	argp->attrs.ia_valid &= ~ATTR_SIZE;
> >  	fh_copy(&resp->dirfh, &argp->fh);
> > @@ -471,13 +466,10 @@ nfsd3_proc_mknod(struct svc_rqst *rqstp)
> >  	struct nfsd_attrs attrs = {
> >  		.na_iattr	= &argp->attrs,
> >  	};
> > -	int type;
> > +	int type = nfs3_ftypes[argp->ftype];
> >  	dev_t	rdev = 0;
> >  
> > -	dprintk("nfsd: MKNOD(3)    %s %.*s\n",
> > -				SVCFH_fmt(&argp->fh),
> > -				argp->len,
> > -				argp->name);
> > +	trace_nfsd3_proc_mknod(rqstp, &argp->fh, type, argp->name, argp->len);
> >  
> >  	fh_copy(&resp->dirfh, &argp->fh);
> >  	fh_init(&resp->fh, NFS3_FHSIZE);
> > diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
> > index 6e23d6103010197c0316b07c189fe12ec3033812..2c795103deaa4044596bd07d90db788169a32a0c 100644
> > --- a/fs/nfsd/nfs4proc.c
> > +++ b/fs/nfsd/nfs4proc.c
> > @@ -250,6 +250,8 @@ nfsd4_create_file(struct svc_rqst *rqstp, struct svc_fh *fhp,
> >  	__be32 status;
> >  	int host_err;
> >  
> > +	trace_nfsd4_create_file(rqstp, fhp, S_IFREG, open->op_fname, open->op_fnamelen);
> > +
> >  	if (isdotent(open->op_fname, open->op_fnamelen))
> >  		return nfserr_exist;
> >  	if (!(iap->ia_valid & ATTR_MODE))
> > @@ -807,6 +809,29 @@ nfsd4_commit(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
> >  	return status;
> >  }
> >  
> > +static umode_t nfs_type_to_vfs_type(enum nfs_ftype4 nfstype)
> > +{
> > +	switch (nfstype) {
> > +	case NF4REG:
> > +		return S_IFREG;
> > +	case NF4DIR:
> > +		return S_IFDIR;
> > +	case NF4BLK:
> > +		return S_IFBLK;
> > +	case NF4CHR:
> > +		return S_IFCHR;
> > +	case NF4LNK:
> > +		return S_IFLNK;
> > +	case NF4SOCK:
> > +		return S_IFSOCK;
> > +	case NF4FIFO:
> > +		return S_IFIFO;
> > +	default:
> > +		break;
> > +	}
> > +	return 0;
> > +}
> > +
> 
> Wondering what happens when trace points are disabled in the kernel
> build. Maybe this helper belongs in fs/nfsd/trace.h instead as a
> macro wrapper for __print_symbolic(). But see below.
> 
> 
> >  static __be32
> >  nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
> >  	     union nfsd4_op_u *u)
> > @@ -822,6 +847,10 @@ nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
> >  	__be32 status;
> >  	dev_t rdev;
> >  
> > +	trace_nfsd4_create(rqstp, &cstate->current_fh,
> > +			   nfs_type_to_vfs_type(create->cr_type),
> > +			   create->cr_name, create->cr_namelen);
> > +
> >  	fh_init(&resfh, NFS4_FHSIZE);
> >  
> >  	status = fh_verify(rqstp, &cstate->current_fh, S_IFDIR, NFSD_MAY_NOP);
> > diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
> > index 6dda081eb24c00b834ab0965c3a35a12115bceb7..33d8cbf8785588d38d4ec5efd769c1d1d06c6a91 100644
> > --- a/fs/nfsd/nfsproc.c
> > +++ b/fs/nfsd/nfsproc.c
> > @@ -10,6 +10,7 @@
> >  #include "cache.h"
> >  #include "xdr.h"
> >  #include "vfs.h"
> > +#include "trace.h"
> >  
> >  #define NFSDDBG_FACILITY		NFSDDBG_PROC
> >  
> > @@ -292,8 +293,7 @@ nfsd_proc_create(struct svc_rqst *rqstp)
> >  	int		hosterr;
> >  	dev_t		rdev = 0, wanted = new_decode_dev(attr->ia_size);
> >  
> > -	dprintk("nfsd: CREATE   %s %.*s\n",
> > -		SVCFH_fmt(dirfhp), argp->len, argp->name);
> > +	trace_nfsd_proc_create(rqstp, dirfhp, S_IFREG, argp->name, argp->len);
> >  
> >  	/* First verify the parent file handle */
> >  	resp->status = fh_verify(rqstp, dirfhp, S_IFDIR, NFSD_MAY_EXEC);
> > @@ -548,7 +548,7 @@ nfsd_proc_mkdir(struct svc_rqst *rqstp)
> >  		.na_iattr	= &argp->attrs,
> >  	};
> >  
> > -	dprintk("nfsd: MKDIR    %s %.*s\n", SVCFH_fmt(&argp->fh), argp->len, argp->name);
> > +	trace_nfsd_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
> >  
> >  	if (resp->fh.fh_dentry) {
> >  		printk(KERN_WARNING
> > diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
> > index 382849d7c321d6ded8213890c2e7075770aa716c..c6aff23a845f06c87e701d57ec577c2c5c5a743c 100644
> > --- a/fs/nfsd/trace.h
> > +++ b/fs/nfsd/trace.h
> > @@ -2391,6 +2391,45 @@ TRACE_EVENT(nfsd_lookup_dentry,
> >  	TP_printk("xid=0x%08x fh_hash=0x%08x name=%s",
> >  		  __entry->xid, __entry->fh_hash, __get_str(name))
> >  );
> > +
> > +DECLARE_EVENT_CLASS(nfsd_vfs_create_class,
> > +	TP_PROTO(struct svc_rqst *rqstp,
> > +		 struct svc_fh *fhp,
> > +		 umode_t type,
> > +		 const char *name,
> > +		 unsigned int len),
> > +	TP_ARGS(rqstp, fhp, type, name, len),
> > +	TP_STRUCT__entry(
> > +		SVC_RQST_ENDPOINT_FIELDS(rqstp)
> > +		__field(u32, fh_hash)
> > +		__field(umode_t, type)
> > +		__string_len(name, name, len)
> > +	),
> > +	TP_fast_assign(
> > +		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
> > +		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
> > +		__entry->type = type;
> > +		__assign_str(name);
> > +	),
> > +	TP_printk("xid=0x%08x fh_hash=0x%08x type=%s name=%s",
> > +		  __entry->xid, __entry->fh_hash,
> > +		  show_fs_file_type(__entry->type), __get_str(name))
> > +);
> > +
> > +#define DEFINE_NFSD_VFS_CREATE_EVENT(__name)						\
> > +	DEFINE_EVENT(nfsd_vfs_create_class, __name,					\
> > +		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp,		\
> > +			      umode_t type, const char *name, unsigned int len),	\
> > +		     TP_ARGS(rqstp, fhp, type, name, len))
> > +
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_create);
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_mkdir);
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_create);
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mkdir);
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mknod);
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create);
> > +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create_file);
> 
> I think we would be better off with one or two new trace points in
> nfsd_create() and nfsd_create_setattr() instead of all of these...
> 
> Unless I've missed what you are trying to observe...?
> 

Now I remember why I did it this way. Doing it the way you suggest
makes this all a bit messy:

Most of the callers create files via nfsd_create(), but
nfsd3_create_file calls vfs_create() directly. It does call
nfsd_create_setattr(), but that's really not the right place for this
either, since it's doing a setattr and not the create itself. Notably,
it isn't passed the filename.

Note too that burying this tracepoint down in nfs_create() also means
that error conditions can happen before the tracepoint that may mean
that it won't fire. So, if you're watching the traces to see when
CREATE or MKDIR calls occur, you may miss some of them.

How do you want to proceed? 
-- 
Jeff Layton <jlayton@kernel.org>

Re: [PATCH v2 06/12] nfsd: add tracepoints around nfsd_create events

[Chuck Lever]

On 4/9/25 12:50 PM, Jeff Layton wrote:
> On Wed, 2025-04-09 at 11:09 -0400, Chuck Lever wrote:
>> On 4/9/25 10:32 AM, Jeff Layton wrote:
>>> ...and remove the legacy dprintks.
>>>
>>> Signed-off-by: Jeff Layton <jlayton@kernel.org>
>>> ---
>>>  fs/nfsd/nfs3proc.c | 18 +++++-------------
>>>  fs/nfsd/nfs4proc.c | 29 +++++++++++++++++++++++++++++
>>>  fs/nfsd/nfsproc.c  |  6 +++---
>>>  fs/nfsd/trace.h    | 39 +++++++++++++++++++++++++++++++++++++++
>>>  4 files changed, 76 insertions(+), 16 deletions(-)
>>>
>>> diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
>>> index 372bdcf5e07a5c835da240ecebb02e3576eb2ca6..ea1280970ea11b2a82f0de88ad0422eef7063d6d 100644
>>> --- a/fs/nfsd/nfs3proc.c
>>> +++ b/fs/nfsd/nfs3proc.c
>>> @@ -14,6 +14,7 @@
>>>  #include "xdr3.h"
>>>  #include "vfs.h"
>>>  #include "filecache.h"
>>> +#include "trace.h"
>>>  
>>>  #define NFSDDBG_FACILITY		NFSDDBG_PROC
>>>  
>>> @@ -380,10 +381,7 @@ nfsd3_proc_create(struct svc_rqst *rqstp)
>>>  	struct nfsd3_diropres *resp = rqstp->rq_resp;
>>>  	svc_fh *dirfhp, *newfhp;
>>>  
>>> -	dprintk("nfsd: CREATE(3)   %s %.*s\n",
>>> -				SVCFH_fmt(&argp->fh),
>>> -				argp->len,
>>> -				argp->name);
>>> +	trace_nfsd3_proc_create(rqstp, &argp->fh, S_IFREG, argp->name, argp->len);
>>>  
>>>  	dirfhp = fh_copy(&resp->dirfh, &argp->fh);
>>>  	newfhp = fh_init(&resp->fh, NFS3_FHSIZE);
>>> @@ -405,10 +403,7 @@ nfsd3_proc_mkdir(struct svc_rqst *rqstp)
>>>  		.na_iattr	= &argp->attrs,
>>>  	};
>>>  
>>> -	dprintk("nfsd: MKDIR(3)    %s %.*s\n",
>>> -				SVCFH_fmt(&argp->fh),
>>> -				argp->len,
>>> -				argp->name);
>>> +	trace_nfsd3_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
>>>  
>>>  	argp->attrs.ia_valid &= ~ATTR_SIZE;
>>>  	fh_copy(&resp->dirfh, &argp->fh);
>>> @@ -471,13 +466,10 @@ nfsd3_proc_mknod(struct svc_rqst *rqstp)
>>>  	struct nfsd_attrs attrs = {
>>>  		.na_iattr	= &argp->attrs,
>>>  	};
>>> -	int type;
>>> +	int type = nfs3_ftypes[argp->ftype];
>>>  	dev_t	rdev = 0;
>>>  
>>> -	dprintk("nfsd: MKNOD(3)    %s %.*s\n",
>>> -				SVCFH_fmt(&argp->fh),
>>> -				argp->len,
>>> -				argp->name);
>>> +	trace_nfsd3_proc_mknod(rqstp, &argp->fh, type, argp->name, argp->len);
>>>  
>>>  	fh_copy(&resp->dirfh, &argp->fh);
>>>  	fh_init(&resp->fh, NFS3_FHSIZE);
>>> diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
>>> index 6e23d6103010197c0316b07c189fe12ec3033812..2c795103deaa4044596bd07d90db788169a32a0c 100644
>>> --- a/fs/nfsd/nfs4proc.c
>>> +++ b/fs/nfsd/nfs4proc.c
>>> @@ -250,6 +250,8 @@ nfsd4_create_file(struct svc_rqst *rqstp, struct svc_fh *fhp,
>>>  	__be32 status;
>>>  	int host_err;
>>>  
>>> +	trace_nfsd4_create_file(rqstp, fhp, S_IFREG, open->op_fname, open->op_fnamelen);
>>> +
>>>  	if (isdotent(open->op_fname, open->op_fnamelen))
>>>  		return nfserr_exist;
>>>  	if (!(iap->ia_valid & ATTR_MODE))
>>> @@ -807,6 +809,29 @@ nfsd4_commit(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>>>  	return status;
>>>  }
>>>  
>>> +static umode_t nfs_type_to_vfs_type(enum nfs_ftype4 nfstype)
>>> +{
>>> +	switch (nfstype) {
>>> +	case NF4REG:
>>> +		return S_IFREG;
>>> +	case NF4DIR:
>>> +		return S_IFDIR;
>>> +	case NF4BLK:
>>> +		return S_IFBLK;
>>> +	case NF4CHR:
>>> +		return S_IFCHR;
>>> +	case NF4LNK:
>>> +		return S_IFLNK;
>>> +	case NF4SOCK:
>>> +		return S_IFSOCK;
>>> +	case NF4FIFO:
>>> +		return S_IFIFO;
>>> +	default:
>>> +		break;
>>> +	}
>>> +	return 0;
>>> +}
>>> +
>>
>> Wondering what happens when trace points are disabled in the kernel
>> build. Maybe this helper belongs in fs/nfsd/trace.h instead as a
>> macro wrapper for __print_symbolic(). But see below.
>>
>>
>>>  static __be32
>>>  nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>>>  	     union nfsd4_op_u *u)
>>> @@ -822,6 +847,10 @@ nfsd4_create(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>>>  	__be32 status;
>>>  	dev_t rdev;
>>>  
>>> +	trace_nfsd4_create(rqstp, &cstate->current_fh,
>>> +			   nfs_type_to_vfs_type(create->cr_type),
>>> +			   create->cr_name, create->cr_namelen);
>>> +
>>>  	fh_init(&resfh, NFS4_FHSIZE);
>>>  
>>>  	status = fh_verify(rqstp, &cstate->current_fh, S_IFDIR, NFSD_MAY_NOP);
>>> diff --git a/fs/nfsd/nfsproc.c b/fs/nfsd/nfsproc.c
>>> index 6dda081eb24c00b834ab0965c3a35a12115bceb7..33d8cbf8785588d38d4ec5efd769c1d1d06c6a91 100644
>>> --- a/fs/nfsd/nfsproc.c
>>> +++ b/fs/nfsd/nfsproc.c
>>> @@ -10,6 +10,7 @@
>>>  #include "cache.h"
>>>  #include "xdr.h"
>>>  #include "vfs.h"
>>> +#include "trace.h"
>>>  
>>>  #define NFSDDBG_FACILITY		NFSDDBG_PROC
>>>  
>>> @@ -292,8 +293,7 @@ nfsd_proc_create(struct svc_rqst *rqstp)
>>>  	int		hosterr;
>>>  	dev_t		rdev = 0, wanted = new_decode_dev(attr->ia_size);
>>>  
>>> -	dprintk("nfsd: CREATE   %s %.*s\n",
>>> -		SVCFH_fmt(dirfhp), argp->len, argp->name);
>>> +	trace_nfsd_proc_create(rqstp, dirfhp, S_IFREG, argp->name, argp->len);
>>>  
>>>  	/* First verify the parent file handle */
>>>  	resp->status = fh_verify(rqstp, dirfhp, S_IFDIR, NFSD_MAY_EXEC);
>>> @@ -548,7 +548,7 @@ nfsd_proc_mkdir(struct svc_rqst *rqstp)
>>>  		.na_iattr	= &argp->attrs,
>>>  	};
>>>  
>>> -	dprintk("nfsd: MKDIR    %s %.*s\n", SVCFH_fmt(&argp->fh), argp->len, argp->name);
>>> +	trace_nfsd_proc_mkdir(rqstp, &argp->fh, S_IFDIR, argp->name, argp->len);
>>>  
>>>  	if (resp->fh.fh_dentry) {
>>>  		printk(KERN_WARNING
>>> diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
>>> index 382849d7c321d6ded8213890c2e7075770aa716c..c6aff23a845f06c87e701d57ec577c2c5c5a743c 100644
>>> --- a/fs/nfsd/trace.h
>>> +++ b/fs/nfsd/trace.h
>>> @@ -2391,6 +2391,45 @@ TRACE_EVENT(nfsd_lookup_dentry,
>>>  	TP_printk("xid=0x%08x fh_hash=0x%08x name=%s",
>>>  		  __entry->xid, __entry->fh_hash, __get_str(name))
>>>  );
>>> +
>>> +DECLARE_EVENT_CLASS(nfsd_vfs_create_class,
>>> +	TP_PROTO(struct svc_rqst *rqstp,
>>> +		 struct svc_fh *fhp,
>>> +		 umode_t type,
>>> +		 const char *name,
>>> +		 unsigned int len),
>>> +	TP_ARGS(rqstp, fhp, type, name, len),
>>> +	TP_STRUCT__entry(
>>> +		SVC_RQST_ENDPOINT_FIELDS(rqstp)
>>> +		__field(u32, fh_hash)
>>> +		__field(umode_t, type)
>>> +		__string_len(name, name, len)
>>> +	),
>>> +	TP_fast_assign(
>>> +		SVC_RQST_ENDPOINT_ASSIGNMENTS(rqstp);
>>> +		__entry->fh_hash = knfsd_fh_hash(&fhp->fh_handle);
>>> +		__entry->type = type;
>>> +		__assign_str(name);
>>> +	),
>>> +	TP_printk("xid=0x%08x fh_hash=0x%08x type=%s name=%s",
>>> +		  __entry->xid, __entry->fh_hash,
>>> +		  show_fs_file_type(__entry->type), __get_str(name))
>>> +);
>>> +
>>> +#define DEFINE_NFSD_VFS_CREATE_EVENT(__name)						\
>>> +	DEFINE_EVENT(nfsd_vfs_create_class, __name,					\
>>> +		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp,		\
>>> +			      umode_t type, const char *name, unsigned int len),	\
>>> +		     TP_ARGS(rqstp, fhp, type, name, len))
>>> +
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_create);
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd_proc_mkdir);
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_create);
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mkdir);
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd3_proc_mknod);
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create);
>>> +DEFINE_NFSD_VFS_CREATE_EVENT(nfsd4_create_file);
>>
>> I think we would be better off with one or two new trace points in
>> nfsd_create() and nfsd_create_setattr() instead of all of these...
>>
>> Unless I've missed what you are trying to observe...?
>>
> 
> Now I remember why I did it this way. Doing it the way you suggest
> makes this all a bit messy:
> 
> Most of the callers create files via nfsd_create(), but
> nfsd3_create_file calls vfs_create() directly. It does call
> nfsd_create_setattr(), but that's really not the right place for this
> either, since it's doing a setattr and not the create itself. Notably,
> it isn't passed the filename.
> 
> Note too that burying this tracepoint down in nfs_create() also means
> that error conditions can happen before the tracepoint that may mean
> that it won't fire. So, if you're watching the traces to see when
> CREATE or MKDIR calls occur, you may miss some of them.
> 
> How do you want to proceed? 

You can see incoming RPC messages via the svc_process trace point.
If you want to see the arguments for the operations too, you enable
the nfsd_vfs_ tracepoints. It is reasonable to add trace points in
the error flows if you believe those are important to surface.

For CREATE, add the new nfsd_vfs_create trace point in nfsd_create()
and also in nfsd3_create_file().

How does that sound?

-- 
Chuck Lever

Re: [PATCH v2 02/12] sunrpc: add info about xprt queue times to svc_xprt_dequeue tracepoint

[Jeff Layton]

On Wed, 2025-04-09 at 11:26 -0400, Jeff Layton wrote:
> On Wed, 2025-04-09 at 11:00 -0400, Chuck Lever wrote:
> > On 4/9/25 10:32 AM, Jeff Layton wrote:
> > > Currently, this tracepoint displays "wakeup-us", which is the time that
> > > the woken thread spent sleeping, before dequeueing the next xprt. Add a
> > > new statistic that shows how long the xprt sat on the queue before being
> > > serviced.
> > 
> > I don't understand the difference between "waiting on queue" and
> > "sleeping". When are those two latency measurements not the same?
> > 
> 
> These are measuring two different things:
> 
> svc_rqst->rq_qtime represents the time between when thread on the
> sp_idle_threads list was woken. This patch adds svc_xprt->xpt_qtime,
> which represents the time that the svc_xprt was added to the lwq.
> 
> The first tells us how long the interval was between the thread being
> woken and the xprt being dequeued. The new statistic tells us how long
> between the xprt being enqueued and dequeued.
> 
> They could easily diverge if there were not enough threads available to
> service all of the queued xprts.
> 

Hi Chuck! If you're OK with my rationale above, I'd like to expedite
merging this patch in particular.

The reason is that we have clients with the nfs_layout_flexfiles
dataserver_timeo module parameter set for 6s. This helps them switch to
an alternate mirror when a DS goes down, but we see a lot of RPC
timeouts when this is set.

My theory is that the xprts are getting queued and it's taking a long
time for a thread to pick it up. That should show up as a large value
in the qtime field in this tracepoint if I'm correct.

Would you be amenable to that?

> > 
> > > Signed-off-by: Jeff Layton <jlayton@kernel.org>
> > > ---
> > >  include/linux/sunrpc/svc_xprt.h |  1 +
> > >  include/trace/events/sunrpc.h   | 13 +++++++------
> > >  net/sunrpc/svc_xprt.c           |  1 +
> > >  3 files changed, 9 insertions(+), 6 deletions(-)
> > > 
> > > diff --git a/include/linux/sunrpc/svc_xprt.h b/include/linux/sunrpc/svc_xprt.h
> > > index 72be609525796792274d5b8cb5ff37f73723fc23..369a89aea18618748607ee943247c327bf62c8d5 100644
> > > --- a/include/linux/sunrpc/svc_xprt.h
> > > +++ b/include/linux/sunrpc/svc_xprt.h
> > > @@ -53,6 +53,7 @@ struct svc_xprt {
> > >  	struct svc_xprt_class	*xpt_class;
> > >  	const struct svc_xprt_ops *xpt_ops;
> > >  	struct kref		xpt_ref;
> > > +	ktime_t			xpt_qtime;
> > >  	struct list_head	xpt_list;
> > >  	struct lwq_node		xpt_ready;
> > >  	unsigned long		xpt_flags;
> > > diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> > > index 5d331383047b79b9f6dcd699c87287453c1a5f49..b5a0f0bc1a3b7cfd90ce0181a8a419db810988bb 100644
> > > --- a/include/trace/events/sunrpc.h
> > > +++ b/include/trace/events/sunrpc.h
> > > @@ -2040,19 +2040,20 @@ TRACE_EVENT(svc_xprt_dequeue,
> > >  
> > >  	TP_STRUCT__entry(
> > >  		SVC_XPRT_ENDPOINT_FIELDS(rqst->rq_xprt)
> > > -
> > >  		__field(unsigned long, wakeup)
> > > +		__field(unsigned long, qtime)
> > >  	),
> > >  
> > >  	TP_fast_assign(
> > > -		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
> > > +		ktime_t ktime = ktime_get();
> > >  
> > > -		__entry->wakeup = ktime_to_us(ktime_sub(ktime_get(),
> > > -							rqst->rq_qtime));
> > > +		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
> > > +		__entry->wakeup = ktime_to_us(ktime_sub(ktime, rqst->rq_qtime));
> > > +		__entry->qtime = ktime_to_us(ktime_sub(ktime, rqst->rq_xprt->xpt_qtime));
> > >  	),
> > >  
> > > -	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu",
> > > -		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup)
> > > +	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu qtime=%lu",
> > > +		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup, __entry->qtime)
> > >  );
> > >  
> > >  DECLARE_EVENT_CLASS(svc_xprt_event,
> > > diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
> > > index ae25405d8bd22672a361d1fd3adfdcebb403f90f..32018557797b1f683d8b7259f5fccd029aebcd71 100644
> > > --- a/net/sunrpc/svc_xprt.c
> > > +++ b/net/sunrpc/svc_xprt.c
> > > @@ -488,6 +488,7 @@ void svc_xprt_enqueue(struct svc_xprt *xprt)
> > >  	pool = svc_pool_for_cpu(xprt->xpt_server);
> > >  
> > >  	percpu_counter_inc(&pool->sp_sockets_queued);
> > > +	xprt->xpt_qtime = ktime_get();
> > >  	lwq_enqueue(&xprt->xpt_ready, &pool->sp_xprts);
> > >  
> > >  	svc_pool_wake_idle_thread(pool);
> > > 
> > 
> > 
> 

-- 
Jeff Layton <jlayton@kernel.org>

Re: [PATCH v2 02/12] sunrpc: add info about xprt queue times to svc_xprt_dequeue tracepoint

[Chuck Lever]

On 4/11/25 9:10 AM, Jeff Layton wrote:
> On Wed, 2025-04-09 at 11:26 -0400, Jeff Layton wrote:
>> On Wed, 2025-04-09 at 11:00 -0400, Chuck Lever wrote:
>>> On 4/9/25 10:32 AM, Jeff Layton wrote:
>>>> Currently, this tracepoint displays "wakeup-us", which is the time that
>>>> the woken thread spent sleeping, before dequeueing the next xprt. Add a
>>>> new statistic that shows how long the xprt sat on the queue before being
>>>> serviced.
>>>
>>> I don't understand the difference between "waiting on queue" and
>>> "sleeping". When are those two latency measurements not the same?
>>>
>>
>> These are measuring two different things:
>>
>> svc_rqst->rq_qtime represents the time between when thread on the
>> sp_idle_threads list was woken. This patch adds svc_xprt->xpt_qtime,
>> which represents the time that the svc_xprt was added to the lwq.
>>
>> The first tells us how long the interval was between the thread being
>> woken and the xprt being dequeued. The new statistic tells us how long
>> between the xprt being enqueued and dequeued.
>>
>> They could easily diverge if there were not enough threads available to
>> service all of the queued xprts.
>>
> 
> Hi Chuck! If you're OK with my rationale above, I'd like to expedite
> merging this patch in particular.
> 
> The reason is that we have clients with the nfs_layout_flexfiles
> dataserver_timeo module parameter set for 6s. This helps them switch to
> an alternate mirror when a DS goes down, but we see a lot of RPC
> timeouts when this is set.
> 
> My theory is that the xprts are getting queued and it's taking a long
> time for a thread to pick it up. That should show up as a large value
> in the qtime field in this tracepoint if I'm correct.
> 
> Would you be amenable to that?

No objection, repost this one with the beefier rationale.

But it depends on what you mean by "expedite" -- v6.16 would be the
next "normal" opportunity, since this change doesn't qualify as a
bug fix.


>>>> Signed-off-by: Jeff Layton <jlayton@kernel.org>
>>>> ---
>>>>  include/linux/sunrpc/svc_xprt.h |  1 +
>>>>  include/trace/events/sunrpc.h   | 13 +++++++------
>>>>  net/sunrpc/svc_xprt.c           |  1 +
>>>>  3 files changed, 9 insertions(+), 6 deletions(-)
>>>>
>>>> diff --git a/include/linux/sunrpc/svc_xprt.h b/include/linux/sunrpc/svc_xprt.h
>>>> index 72be609525796792274d5b8cb5ff37f73723fc23..369a89aea18618748607ee943247c327bf62c8d5 100644
>>>> --- a/include/linux/sunrpc/svc_xprt.h
>>>> +++ b/include/linux/sunrpc/svc_xprt.h
>>>> @@ -53,6 +53,7 @@ struct svc_xprt {
>>>>  	struct svc_xprt_class	*xpt_class;
>>>>  	const struct svc_xprt_ops *xpt_ops;
>>>>  	struct kref		xpt_ref;
>>>> +	ktime_t			xpt_qtime;
>>>>  	struct list_head	xpt_list;
>>>>  	struct lwq_node		xpt_ready;
>>>>  	unsigned long		xpt_flags;
>>>> diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
>>>> index 5d331383047b79b9f6dcd699c87287453c1a5f49..b5a0f0bc1a3b7cfd90ce0181a8a419db810988bb 100644
>>>> --- a/include/trace/events/sunrpc.h
>>>> +++ b/include/trace/events/sunrpc.h
>>>> @@ -2040,19 +2040,20 @@ TRACE_EVENT(svc_xprt_dequeue,
>>>>  
>>>>  	TP_STRUCT__entry(
>>>>  		SVC_XPRT_ENDPOINT_FIELDS(rqst->rq_xprt)
>>>> -
>>>>  		__field(unsigned long, wakeup)
>>>> +		__field(unsigned long, qtime)
>>>>  	),
>>>>  
>>>>  	TP_fast_assign(
>>>> -		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
>>>> +		ktime_t ktime = ktime_get();
>>>>  
>>>> -		__entry->wakeup = ktime_to_us(ktime_sub(ktime_get(),
>>>> -							rqst->rq_qtime));
>>>> +		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
>>>> +		__entry->wakeup = ktime_to_us(ktime_sub(ktime, rqst->rq_qtime));
>>>> +		__entry->qtime = ktime_to_us(ktime_sub(ktime, rqst->rq_xprt->xpt_qtime));
>>>>  	),
>>>>  
>>>> -	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu",
>>>> -		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup)
>>>> +	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu qtime=%lu",
>>>> +		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup, __entry->qtime)
>>>>  );
>>>>  
>>>>  DECLARE_EVENT_CLASS(svc_xprt_event,
>>>> diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
>>>> index ae25405d8bd22672a361d1fd3adfdcebb403f90f..32018557797b1f683d8b7259f5fccd029aebcd71 100644
>>>> --- a/net/sunrpc/svc_xprt.c
>>>> +++ b/net/sunrpc/svc_xprt.c
>>>> @@ -488,6 +488,7 @@ void svc_xprt_enqueue(struct svc_xprt *xprt)
>>>>  	pool = svc_pool_for_cpu(xprt->xpt_server);
>>>>  
>>>>  	percpu_counter_inc(&pool->sp_sockets_queued);
>>>> +	xprt->xpt_qtime = ktime_get();
>>>>  	lwq_enqueue(&xprt->xpt_ready, &pool->sp_xprts);
>>>>  
>>>>  	svc_pool_wake_idle_thread(pool);
>>>>
>>>
>>>
>>
> 


-- 
Chuck Lever

Re: [PATCH v2 02/12] sunrpc: add info about xprt queue times to svc_xprt_dequeue tracepoint

[Jeff Layton]

On Fri, 2025-04-11 at 09:24 -0400, Chuck Lever wrote:
> On 4/11/25 9:10 AM, Jeff Layton wrote:
> > On Wed, 2025-04-09 at 11:26 -0400, Jeff Layton wrote:
> > > On Wed, 2025-04-09 at 11:00 -0400, Chuck Lever wrote:
> > > > On 4/9/25 10:32 AM, Jeff Layton wrote:
> > > > > Currently, this tracepoint displays "wakeup-us", which is the time that
> > > > > the woken thread spent sleeping, before dequeueing the next xprt. Add a
> > > > > new statistic that shows how long the xprt sat on the queue before being
> > > > > serviced.
> > > > 
> > > > I don't understand the difference between "waiting on queue" and
> > > > "sleeping". When are those two latency measurements not the same?
> > > > 
> > > 
> > > These are measuring two different things:
> > > 
> > > svc_rqst->rq_qtime represents the time between when thread on the
> > > sp_idle_threads list was woken. This patch adds svc_xprt->xpt_qtime,
> > > which represents the time that the svc_xprt was added to the lwq.
> > > 
> > > The first tells us how long the interval was between the thread being
> > > woken and the xprt being dequeued. The new statistic tells us how long
> > > between the xprt being enqueued and dequeued.
> > > 
> > > They could easily diverge if there were not enough threads available to
> > > service all of the queued xprts.
> > > 
> > 
> > Hi Chuck! If you're OK with my rationale above, I'd like to expedite
> > merging this patch in particular.
> > 
> > The reason is that we have clients with the nfs_layout_flexfiles
> > dataserver_timeo module parameter set for 6s. This helps them switch to
> > an alternate mirror when a DS goes down, but we see a lot of RPC
> > timeouts when this is set.
> > 
> > My theory is that the xprts are getting queued and it's taking a long
> > time for a thread to pick it up. That should show up as a large value
> > in the qtime field in this tracepoint if I'm correct.
> > 
> > Would you be amenable to that?
> 
> No objection, repost this one with the beefier rationale.
> 

Will do.

> But it depends on what you mean by "expedite" -- v6.16 would be the
> next "normal" opportunity, since this change doesn't qualify as a
> bug fix.
> 

I was hoping for v6.15, as I don't want to wait months to figure this
out. Eventually, I need this in a particular downstream distribution
that is reticent to take patches that aren't already merged.

> 
> > > > > Signed-off-by: Jeff Layton <jlayton@kernel.org>
> > > > > ---
> > > > >  include/linux/sunrpc/svc_xprt.h |  1 +
> > > > >  include/trace/events/sunrpc.h   | 13 +++++++------
> > > > >  net/sunrpc/svc_xprt.c           |  1 +
> > > > >  3 files changed, 9 insertions(+), 6 deletions(-)
> > > > > 
> > > > > diff --git a/include/linux/sunrpc/svc_xprt.h b/include/linux/sunrpc/svc_xprt.h
> > > > > index 72be609525796792274d5b8cb5ff37f73723fc23..369a89aea18618748607ee943247c327bf62c8d5 100644
> > > > > --- a/include/linux/sunrpc/svc_xprt.h
> > > > > +++ b/include/linux/sunrpc/svc_xprt.h
> > > > > @@ -53,6 +53,7 @@ struct svc_xprt {
> > > > >  	struct svc_xprt_class	*xpt_class;
> > > > >  	const struct svc_xprt_ops *xpt_ops;
> > > > >  	struct kref		xpt_ref;
> > > > > +	ktime_t			xpt_qtime;
> > > > >  	struct list_head	xpt_list;
> > > > >  	struct lwq_node		xpt_ready;
> > > > >  	unsigned long		xpt_flags;
> > > > > diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
> > > > > index 5d331383047b79b9f6dcd699c87287453c1a5f49..b5a0f0bc1a3b7cfd90ce0181a8a419db810988bb 100644
> > > > > --- a/include/trace/events/sunrpc.h
> > > > > +++ b/include/trace/events/sunrpc.h
> > > > > @@ -2040,19 +2040,20 @@ TRACE_EVENT(svc_xprt_dequeue,
> > > > >  
> > > > >  	TP_STRUCT__entry(
> > > > >  		SVC_XPRT_ENDPOINT_FIELDS(rqst->rq_xprt)
> > > > > -
> > > > >  		__field(unsigned long, wakeup)
> > > > > +		__field(unsigned long, qtime)
> > > > >  	),
> > > > >  
> > > > >  	TP_fast_assign(
> > > > > -		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
> > > > > +		ktime_t ktime = ktime_get();
> > > > >  
> > > > > -		__entry->wakeup = ktime_to_us(ktime_sub(ktime_get(),
> > > > > -							rqst->rq_qtime));
> > > > > +		SVC_XPRT_ENDPOINT_ASSIGNMENTS(rqst->rq_xprt);
> > > > > +		__entry->wakeup = ktime_to_us(ktime_sub(ktime, rqst->rq_qtime));
> > > > > +		__entry->qtime = ktime_to_us(ktime_sub(ktime, rqst->rq_xprt->xpt_qtime));
> > > > >  	),
> > > > >  
> > > > > -	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu",
> > > > > -		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup)
> > > > > +	TP_printk(SVC_XPRT_ENDPOINT_FORMAT " wakeup-us=%lu qtime=%lu",
> > > > > +		SVC_XPRT_ENDPOINT_VARARGS, __entry->wakeup, __entry->qtime)
> > > > >  );
> > > > >  
> > > > >  DECLARE_EVENT_CLASS(svc_xprt_event,
> > > > > diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
> > > > > index ae25405d8bd22672a361d1fd3adfdcebb403f90f..32018557797b1f683d8b7259f5fccd029aebcd71 100644
> > > > > --- a/net/sunrpc/svc_xprt.c
> > > > > +++ b/net/sunrpc/svc_xprt.c
> > > > > @@ -488,6 +488,7 @@ void svc_xprt_enqueue(struct svc_xprt *xprt)
> > > > >  	pool = svc_pool_for_cpu(xprt->xpt_server);
> > > > >  
> > > > >  	percpu_counter_inc(&pool->sp_sockets_queued);
> > > > > +	xprt->xpt_qtime = ktime_get();
> > > > >  	lwq_enqueue(&xprt->xpt_ready, &pool->sp_xprts);
> > > > >  
> > > > >  	svc_pool_wake_idle_thread(pool);
> > > > > 
> > > > 
> > > > 
> > > 
> > 
> 
> 

-- 
Jeff Layton <jlayton@kernel.org>

Re: (subset) [PATCH v2 00/12] nfsd: observability improvements

[cel]

From: Chuck Lever <chuck.lever@oracle.com>

On Wed, 09 Apr 2025 10:32:22 -0400, Jeff Layton wrote:
> While troubleshooting a performance problem internally, it became
> evident that we needed tracepoints in nfsd_commit. The first patch adds
> that. While discussing that, Sargun pointed out some tracepoints he
> added using kprobes. Those are converted to static tracepoints here, and
> the legacy dprintk's removed.
> 
> Lastly, I've updated the svc_xprt_dequeue tracepoint to show how long
> the xprt sat on the queue before being serviced.
> 
> [...]

Applied to nfsd-testing, thanks!

[01/12] nfsd: add commit start/done tracepoints around nfsd_commit()
        commit: f2a3825118e6177f4de5ee9996248ced2918b08b

--
Chuck Lever