[PATCH 0/4] nfsd: observability improvements

[PATCH 0/4] 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.

Lastly, this adds a new counter to the pool_stats for counting the number
of times that the kernel tried to wake a svc thread, but there were none
available. I think this may be useful info for determining whether we're
bumping up against the size of the thread pool.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
Jeff Layton (4):
      nfsd: add commit start/done tracepoints around nfsd_commit()
      nfsd: add a tracepoint for nfsd_setattr
      nfsd: add some stub tracepoints around key vfs functions
      sunrpc: keep a count of when there are no threads available

 fs/nfsd/nfs3proc.c         |  3 ++
 fs/nfsd/nfs4proc.c         |  2 +
 fs/nfsd/nfsproc.c          |  2 +
 fs/nfsd/trace.h            | 91 ++++++++++++++++++++++++++++++++++++++++++++++
 fs/nfsd/vfs.c              | 31 ++++++++++++++++
 include/linux/sunrpc/svc.h |  1 +
 net/sunrpc/svc.c           |  4 +-
 net/sunrpc/svc_xprt.c      |  7 ++--
 8 files changed, 137 insertions(+), 4 deletions(-)
---
base-commit: 7dc86d35a5f8a7ac24b53792c704b101e5041842
change-id: 20250303-nfsd-tracepoints-c82add9155a6

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

[PATCH 1/4] 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 4021b047eb1804f0058f6fb511d3fdfc03a42bf3..390ddfb169083535faa3a2413389e247bdbf4a73 100644
--- a/fs/nfsd/vfs.c
+++ b/fs/nfsd/vfs.c
@@ -1339,6 +1339,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
@@ -1377,6 +1379,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.48.1

[PATCH 2/4] nfsd: add a tracepoint for nfsd_setattr

[Jeff Layton]

Turn Sargun's internal kprobe based implementation of this into a normal
static tracepoint.

Cc: Sargun Dillon <sargun@meta.com>
Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/trace.h | 54 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
 fs/nfsd/vfs.c   |  2 ++
 2 files changed, 56 insertions(+)

diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 0d49fc064f7273f32c93732a993fd77bc0783f5d..117f7e1fd66a4838a048cc44bd5bf4dd8c6db958 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -2337,6 +2337,60 @@ DEFINE_EVENT(nfsd_copy_async_done_class,		\
 DEFINE_COPY_ASYNC_DONE_EVENT(done);
 DEFINE_COPY_ASYNC_DONE_EVENT(cancel);
 
+#define show_ia_valid_flags(x)					\
+	__print_flags(x, "|",					\
+			{ 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"})
+
+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(
+		__field(u32, xid)
+		__field(u32, fh_hash)
+		__field(s64, gtime_tv_sec)
+		__field(u32, gtime_tv_nsec)
+		__field(unsigned int, ia_valid)
+		__field(umode_t, ia_mode)
+		__field(uid_t, ia_uid)
+		__field(gid_t, ia_gid)
+		__field(loff_t, ia_size)
+	),
+	TP_fast_assign(__entry->xid = be32_to_cpu(rqstp->rq_xid);
+	       __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_mode = iap->ia_mode;
+	       __entry->ia_uid = __kuid_val(iap->ia_uid);
+	       __entry->ia_gid = __kgid_val(iap->ia_gid);
+	       __entry->ia_size = iap->ia_size;
+
+	),
+	TP_printk(
+		"xid=0x%08x fh_hash=0x%08x ia_valid=%s ia_mode=%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_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 390ddfb169083535faa3a2413389e247bdbf4a73..d755cc87a8670c491e55194de266d999ba1b337d 100644
--- a/fs/nfsd/vfs.c
+++ b/fs/nfsd/vfs.c
@@ -499,6 +499,8 @@ nfsd_setattr(struct svc_rqst *rqstp, struct svc_fh *fhp,
 	bool		size_change = (iap->ia_valid & ATTR_SIZE);
 	int		retries;
 
+	trace_nfsd_setattr(rqstp, fhp, iap, guardtime);
+
 	if (iap->ia_valid & ATTR_SIZE) {
 		accmode |= NFSD_MAY_WRITE|NFSD_MAY_OWNER_OVERRIDE;
 		ftype = S_IFREG;

-- 
2.48.1

Re: [PATCH 2/4] nfsd: add a tracepoint for nfsd_setattr

[Chuck Lever]

On 3/6/25 7:38 AM, Jeff Layton wrote:
> Turn Sargun's internal kprobe based implementation of this into a normal
> static tracepoint.
> 
> Cc: Sargun Dillon <sargun@meta.com>
> Signed-off-by: Jeff Layton <jlayton@kernel.org>
> ---
>  fs/nfsd/trace.h | 54 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
>  fs/nfsd/vfs.c   |  2 ++
>  2 files changed, 56 insertions(+)
> 
> diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
> index 0d49fc064f7273f32c93732a993fd77bc0783f5d..117f7e1fd66a4838a048cc44bd5bf4dd8c6db958 100644
> --- a/fs/nfsd/trace.h
> +++ b/fs/nfsd/trace.h
> @@ -2337,6 +2337,60 @@ DEFINE_EVENT(nfsd_copy_async_done_class,		\
>  DEFINE_COPY_ASYNC_DONE_EVENT(done);
>  DEFINE_COPY_ASYNC_DONE_EVENT(cancel);
>  
> +#define show_ia_valid_flags(x)					\
> +	__print_flags(x, "|",					\
> +			{ 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"})

Let's add the above helper in include/trace/misc/fs.h instead.


> +
> +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(
> +		__field(u32, xid)
> +		__field(u32, fh_hash)
> +		__field(s64, gtime_tv_sec)
> +		__field(u32, gtime_tv_nsec)
> +		__field(unsigned int, ia_valid)
> +		__field(umode_t, ia_mode)
> +		__field(uid_t, ia_uid)
> +		__field(gid_t, ia_gid)
> +		__field(loff_t, ia_size)
> +	),
> +	TP_fast_assign(__entry->xid = be32_to_cpu(rqstp->rq_xid);
> +	       __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_mode = iap->ia_mode;
> +	       __entry->ia_uid = __kuid_val(iap->ia_uid);
> +	       __entry->ia_gid = __kgid_val(iap->ia_gid);
> +	       __entry->ia_size = iap->ia_size;
> +
> +	),
> +	TP_printk(
> +		"xid=0x%08x fh_hash=0x%08x ia_valid=%s ia_mode=%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_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 390ddfb169083535faa3a2413389e247bdbf4a73..d755cc87a8670c491e55194de266d999ba1b337d 100644
> --- a/fs/nfsd/vfs.c
> +++ b/fs/nfsd/vfs.c
> @@ -499,6 +499,8 @@ nfsd_setattr(struct svc_rqst *rqstp, struct svc_fh *fhp,
>  	bool		size_change = (iap->ia_valid & ATTR_SIZE);
>  	int		retries;
>  
> +	trace_nfsd_setattr(rqstp, fhp, iap, guardtime);
> +
>  	if (iap->ia_valid & ATTR_SIZE) {
>  		accmode |= NFSD_MAY_WRITE|NFSD_MAY_OWNER_OVERRIDE;
>  		ftype = S_IFREG;
> 


-- 
Chuck Lever

[PATCH 3/4] nfsd: add some stub tracepoints around key vfs functions

[Jeff Layton]

Sargun set up kprobes to add some of these tracepoints. Convert them to
simple static tracepoints. These are pretty sparse for now, but they
could be expanded in the future as needed.

Cc: Sargun Dillon <sargun@meta.com>
Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 fs/nfsd/nfs3proc.c |  3 +++
 fs/nfsd/nfs4proc.c |  2 ++
 fs/nfsd/nfsproc.c  |  2 ++
 fs/nfsd/trace.h    | 35 +++++++++++++++++++++++++++++++++++
 fs/nfsd/vfs.c      | 26 ++++++++++++++++++++++++++
 5 files changed, 68 insertions(+)

diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
index 372bdcf5e07a5c835da240ecebb02e3576eb2ca6..2a56cae4c78a7ca66d569637e9f0e7c0fdcfb826 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
 
@@ -69,6 +70,8 @@ nfsd3_proc_getattr(struct svc_rqst *rqstp)
 	struct nfsd_fhandle *argp = rqstp->rq_argp;
 	struct nfsd3_attrstat *resp = rqstp->rq_resp;
 
+	trace_nfsd_getattr(rqstp, &argp->fh);
+
 	dprintk("nfsd: GETATTR(3)  %s\n",
 		SVCFH_fmt(&argp->fh));
 
diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
index c20f1abcb94f131b1ec898860ba2c394b22e61e1..87d241ff91920317e0122a58bf0cf71c5b28d264 100644
--- a/fs/nfsd/nfs4proc.c
+++ b/fs/nfsd/nfs4proc.c
@@ -876,6 +876,8 @@ nfsd4_getattr(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
 	struct nfsd4_getattr *getattr = &u->getattr;
 	__be32 status;
 
+	trace_nfsd_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 6dda081eb24c00b834ab0965c3a35a12115bceb7..9563372f0826b9580299144069f57664dbd2a079 100644
--- a/fs/nfsd/nfsproc.c
+++ b/fs/nfsd/nfsproc.c
@@ -54,6 +54,8 @@ nfsd_proc_getattr(struct svc_rqst *rqstp)
 	struct nfsd_fhandle *argp = rqstp->rq_argp;
 	struct nfsd_attrstat *resp = rqstp->rq_resp;
 
+	trace_nfsd_getattr(rqstp, &argp->fh);
+
 	dprintk("nfsd: GETATTR  %s\n", SVCFH_fmt(&argp->fh));
 
 	fh_copy(&resp->fh, &argp->fh);
diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
index 117f7e1fd66a4838a048cc44bd5bf4dd8c6db958..d4a78fe1bab24b594b96cca8611c439da9ed6926 100644
--- a/fs/nfsd/trace.h
+++ b/fs/nfsd/trace.h
@@ -2337,6 +2337,41 @@ DEFINE_EVENT(nfsd_copy_async_done_class,		\
 DEFINE_COPY_ASYNC_DONE_EVENT(done);
 DEFINE_COPY_ASYNC_DONE_EVENT(cancel);
 
+DECLARE_EVENT_CLASS(nfsd_vfs_class,
+	TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp),
+	TP_ARGS(rqstp, fhp),
+	TP_STRUCT__entry(
+		__field(u32, xid)
+		__field(u32, fh_hash)
+	),
+	TP_fast_assign(
+		__entry->xid = be32_to_cpu(rqstp->rq_xid);
+		__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_EVENT(name)                                        \
+	DEFINE_EVENT(nfsd_vfs_class, nfsd_##name,                           \
+		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp), \
+		     TP_ARGS(rqstp, fhp))
+
+DEFINE_NFSD_VFS_EVENT(lookup);
+DEFINE_NFSD_VFS_EVENT(lookup_dentry);
+DEFINE_NFSD_VFS_EVENT(create_locked);
+DEFINE_NFSD_VFS_EVENT(create);
+DEFINE_NFSD_VFS_EVENT(access);
+DEFINE_NFSD_VFS_EVENT(create_setattr);
+DEFINE_NFSD_VFS_EVENT(readlink);
+DEFINE_NFSD_VFS_EVENT(symlink);
+DEFINE_NFSD_VFS_EVENT(link);
+DEFINE_NFSD_VFS_EVENT(rename);
+DEFINE_NFSD_VFS_EVENT(unlink);
+DEFINE_NFSD_VFS_EVENT(readdir);
+DEFINE_NFSD_VFS_EVENT(statfs);
+DEFINE_NFSD_VFS_EVENT(getattr);
+
 #define show_ia_valid_flags(x)					\
 	__print_flags(x, "|",					\
 			{ ATTR_MODE, "MODE" },			\
diff --git a/fs/nfsd/vfs.c b/fs/nfsd/vfs.c
index d755cc87a8670c491e55194de266d999ba1b337d..772a4d32b09a4bd217a9258ec803c06618cf13c8 100644
--- a/fs/nfsd/vfs.c
+++ b/fs/nfsd/vfs.c
@@ -244,6 +244,8 @@ nfsd_lookup_dentry(struct svc_rqst *rqstp, struct svc_fh *fhp,
 	struct dentry		*dentry;
 	int			host_err;
 
+	trace_nfsd_lookup(rqstp, fhp);
+
 	dprintk("nfsd: nfsd_lookup(fh %s, %.*s)\n", SVCFH_fmt(fhp), len,name);
 
 	dparent = fhp->fh_dentry;
@@ -313,6 +315,8 @@ nfsd_lookup(struct svc_rqst *rqstp, struct svc_fh *fhp, const char *name,
 	struct dentry		*dentry;
 	__be32 err;
 
+	trace_nfsd_lookup(rqstp, fhp);
+
 	err = fh_verify(rqstp, fhp, S_IFDIR, NFSD_MAY_EXEC);
 	if (err)
 		return err;
@@ -794,6 +798,8 @@ nfsd_access(struct svc_rqst *rqstp, struct svc_fh *fhp, u32 *access, u32 *suppor
 	u32			query, result = 0, sresult = 0;
 	__be32			error;
 
+	trace_nfsd_create(rqstp, fhp);
+
 	error = fh_verify(rqstp, fhp, 0, NFSD_MAY_NOP);
 	if (error)
 		goto out;
@@ -1401,6 +1407,8 @@ nfsd_create_setattr(struct svc_rqst *rqstp, struct svc_fh *fhp,
 	struct iattr *iap = attrs->na_iattr;
 	__be32 status;
 
+	trace_nfsd_create_setattr(rqstp, fhp);
+
 	/*
 	 * Mode has already been set by file creation.
 	 */
@@ -1467,6 +1475,8 @@ nfsd_create_locked(struct svc_rqst *rqstp, struct svc_fh *fhp,
 	__be32		err;
 	int		host_err;
 
+	trace_nfsd_create_locked(rqstp, fhp);
+
 	dentry = fhp->fh_dentry;
 	dirp = d_inode(dentry);
 
@@ -1557,6 +1567,8 @@ nfsd_create(struct svc_rqst *rqstp, struct svc_fh *fhp,
 	__be32		err;
 	int		host_err;
 
+	trace_nfsd_create(rqstp, fhp);
+
 	if (isdotent(fname, flen))
 		return nfserr_exist;
 
@@ -1609,6 +1621,8 @@ nfsd_readlink(struct svc_rqst *rqstp, struct svc_fh *fhp, char *buf, int *lenp)
 	DEFINE_DELAYED_CALL(done);
 	int len;
 
+	trace_nfsd_readlink(rqstp, fhp);
+
 	err = fh_verify(rqstp, fhp, S_IFLNK, NFSD_MAY_NOP);
 	if (unlikely(err))
 		return err;
@@ -1657,6 +1671,8 @@ nfsd_symlink(struct svc_rqst *rqstp, struct svc_fh *fhp,
 	__be32		err, cerr;
 	int		host_err;
 
+	trace_nfsd_symlink(rqstp, fhp);
+
 	err = nfserr_noent;
 	if (!flen || path[0] == '\0')
 		goto out;
@@ -1725,6 +1741,8 @@ nfsd_link(struct svc_rqst *rqstp, struct svc_fh *ffhp,
 	__be32		err;
 	int		host_err;
 
+	trace_nfsd_link(rqstp, ffhp);
+
 	err = fh_verify(rqstp, ffhp, S_IFDIR, NFSD_MAY_CREATE);
 	if (err)
 		goto out;
@@ -1842,6 +1860,8 @@ nfsd_rename(struct svc_rqst *rqstp, struct svc_fh *ffhp, char *fname, int flen,
 	int		host_err;
 	bool		close_cached = false;
 
+	trace_nfsd_rename(rqstp, ffhp);
+
 	err = fh_verify(rqstp, ffhp, S_IFDIR, NFSD_MAY_REMOVE);
 	if (err)
 		goto out;
@@ -2000,6 +2020,8 @@ nfsd_unlink(struct svc_rqst *rqstp, struct svc_fh *fhp, int type,
 	__be32		err;
 	int		host_err;
 
+	trace_nfsd_unlink(rqstp, fhp);
+
 	err = nfserr_acces;
 	if (!flen || isdotent(fname, flen))
 		goto out;
@@ -2222,6 +2244,8 @@ nfsd_readdir(struct svc_rqst *rqstp, struct svc_fh *fhp, loff_t *offsetp,
 	loff_t		offset = *offsetp;
 	int             may_flags = NFSD_MAY_READ;
 
+	trace_nfsd_readdir(rqstp, fhp);
+
 	err = nfsd_open(rqstp, fhp, S_IFDIR, may_flags, &file);
 	if (err)
 		goto out;
@@ -2288,6 +2312,8 @@ nfsd_statfs(struct svc_rqst *rqstp, struct svc_fh *fhp, struct kstatfs *stat, in
 {
 	__be32 err;
 
+	trace_nfsd_statfs(rqstp, fhp);
+
 	err = fh_verify(rqstp, fhp, 0, NFSD_MAY_NOP | access);
 	if (!err) {
 		struct path path = {

-- 
2.48.1

Re: [PATCH 3/4] nfsd: add some stub tracepoints around key vfs functions

[Chuck Lever]

On 3/6/25 7:38 AM, Jeff Layton wrote:
> Sargun set up kprobes to add some of these tracepoints. Convert them to
> simple static tracepoints. These are pretty sparse for now, but they
> could be expanded in the future as needed.

I have mixed feelings about this.

- Probably tracepoints should replace the existing dprintk call sites.
  dprintk is kind of useless for heavy traffic.

- Seems like other existing tracepoints could report most of the same
  information. fh_verify, for example, has a tracepoint that reports
  the file handle. There's an svc proc tracepoint, and an NFSv4 COMPOUND
  tracepoint that can report XID and procedure.

- If the tracepoint is passed an @rqstp, it should also record the
  nfsd namespace number.

I'd like to know more about what exactly you were hoping to extract,
and which tracepoint(s) were most helpful for you.


> Cc: Sargun Dillon <sargun@meta.com>
> Signed-off-by: Jeff Layton <jlayton@kernel.org>
> ---
>  fs/nfsd/nfs3proc.c |  3 +++
>  fs/nfsd/nfs4proc.c |  2 ++
>  fs/nfsd/nfsproc.c  |  2 ++
>  fs/nfsd/trace.h    | 35 +++++++++++++++++++++++++++++++++++
>  fs/nfsd/vfs.c      | 26 ++++++++++++++++++++++++++
>  5 files changed, 68 insertions(+)
> 
> diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
> index 372bdcf5e07a5c835da240ecebb02e3576eb2ca6..2a56cae4c78a7ca66d569637e9f0e7c0fdcfb826 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
>  
> @@ -69,6 +70,8 @@ nfsd3_proc_getattr(struct svc_rqst *rqstp)
>  	struct nfsd_fhandle *argp = rqstp->rq_argp;
>  	struct nfsd3_attrstat *resp = rqstp->rq_resp;
>  
> +	trace_nfsd_getattr(rqstp, &argp->fh);
> +
>  	dprintk("nfsd: GETATTR(3)  %s\n",
>  		SVCFH_fmt(&argp->fh));
>  
> diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
> index c20f1abcb94f131b1ec898860ba2c394b22e61e1..87d241ff91920317e0122a58bf0cf71c5b28d264 100644
> --- a/fs/nfsd/nfs4proc.c
> +++ b/fs/nfsd/nfs4proc.c
> @@ -876,6 +876,8 @@ nfsd4_getattr(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
>  	struct nfsd4_getattr *getattr = &u->getattr;
>  	__be32 status;
>  
> +	trace_nfsd_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 6dda081eb24c00b834ab0965c3a35a12115bceb7..9563372f0826b9580299144069f57664dbd2a079 100644
> --- a/fs/nfsd/nfsproc.c
> +++ b/fs/nfsd/nfsproc.c
> @@ -54,6 +54,8 @@ nfsd_proc_getattr(struct svc_rqst *rqstp)
>  	struct nfsd_fhandle *argp = rqstp->rq_argp;
>  	struct nfsd_attrstat *resp = rqstp->rq_resp;
>  
> +	trace_nfsd_getattr(rqstp, &argp->fh);
> +
>  	dprintk("nfsd: GETATTR  %s\n", SVCFH_fmt(&argp->fh));
>  
>  	fh_copy(&resp->fh, &argp->fh);
> diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
> index 117f7e1fd66a4838a048cc44bd5bf4dd8c6db958..d4a78fe1bab24b594b96cca8611c439da9ed6926 100644
> --- a/fs/nfsd/trace.h
> +++ b/fs/nfsd/trace.h
> @@ -2337,6 +2337,41 @@ DEFINE_EVENT(nfsd_copy_async_done_class,		\
>  DEFINE_COPY_ASYNC_DONE_EVENT(done);
>  DEFINE_COPY_ASYNC_DONE_EVENT(cancel);
>  
> +DECLARE_EVENT_CLASS(nfsd_vfs_class,
> +	TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp),
> +	TP_ARGS(rqstp, fhp),
> +	TP_STRUCT__entry(
> +		__field(u32, xid)
> +		__field(u32, fh_hash)
> +	),
> +	TP_fast_assign(
> +		__entry->xid = be32_to_cpu(rqstp->rq_xid);
> +		__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_EVENT(name)                                        \
> +	DEFINE_EVENT(nfsd_vfs_class, nfsd_##name,                           \
> +		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp), \
> +		     TP_ARGS(rqstp, fhp))
> +
> +DEFINE_NFSD_VFS_EVENT(lookup);
> +DEFINE_NFSD_VFS_EVENT(lookup_dentry);
> +DEFINE_NFSD_VFS_EVENT(create_locked);
> +DEFINE_NFSD_VFS_EVENT(create);
> +DEFINE_NFSD_VFS_EVENT(access);
> +DEFINE_NFSD_VFS_EVENT(create_setattr);
> +DEFINE_NFSD_VFS_EVENT(readlink);
> +DEFINE_NFSD_VFS_EVENT(symlink);
> +DEFINE_NFSD_VFS_EVENT(link);
> +DEFINE_NFSD_VFS_EVENT(rename);
> +DEFINE_NFSD_VFS_EVENT(unlink);
> +DEFINE_NFSD_VFS_EVENT(readdir);
> +DEFINE_NFSD_VFS_EVENT(statfs);
> +DEFINE_NFSD_VFS_EVENT(getattr);
> +
>  #define show_ia_valid_flags(x)					\
>  	__print_flags(x, "|",					\
>  			{ ATTR_MODE, "MODE" },			\
> diff --git a/fs/nfsd/vfs.c b/fs/nfsd/vfs.c
> index d755cc87a8670c491e55194de266d999ba1b337d..772a4d32b09a4bd217a9258ec803c06618cf13c8 100644
> --- a/fs/nfsd/vfs.c
> +++ b/fs/nfsd/vfs.c
> @@ -244,6 +244,8 @@ nfsd_lookup_dentry(struct svc_rqst *rqstp, struct svc_fh *fhp,
>  	struct dentry		*dentry;
>  	int			host_err;
>  
> +	trace_nfsd_lookup(rqstp, fhp);
> +
>  	dprintk("nfsd: nfsd_lookup(fh %s, %.*s)\n", SVCFH_fmt(fhp), len,name);
>  
>  	dparent = fhp->fh_dentry;
> @@ -313,6 +315,8 @@ nfsd_lookup(struct svc_rqst *rqstp, struct svc_fh *fhp, const char *name,
>  	struct dentry		*dentry;
>  	__be32 err;
>  
> +	trace_nfsd_lookup(rqstp, fhp);
> +
>  	err = fh_verify(rqstp, fhp, S_IFDIR, NFSD_MAY_EXEC);
>  	if (err)
>  		return err;
> @@ -794,6 +798,8 @@ nfsd_access(struct svc_rqst *rqstp, struct svc_fh *fhp, u32 *access, u32 *suppor
>  	u32			query, result = 0, sresult = 0;
>  	__be32			error;
>  
> +	trace_nfsd_create(rqstp, fhp);
> +
>  	error = fh_verify(rqstp, fhp, 0, NFSD_MAY_NOP);
>  	if (error)
>  		goto out;
> @@ -1401,6 +1407,8 @@ nfsd_create_setattr(struct svc_rqst *rqstp, struct svc_fh *fhp,
>  	struct iattr *iap = attrs->na_iattr;
>  	__be32 status;
>  
> +	trace_nfsd_create_setattr(rqstp, fhp);
> +
>  	/*
>  	 * Mode has already been set by file creation.
>  	 */
> @@ -1467,6 +1475,8 @@ nfsd_create_locked(struct svc_rqst *rqstp, struct svc_fh *fhp,
>  	__be32		err;
>  	int		host_err;
>  
> +	trace_nfsd_create_locked(rqstp, fhp);
> +
>  	dentry = fhp->fh_dentry;
>  	dirp = d_inode(dentry);
>  
> @@ -1557,6 +1567,8 @@ nfsd_create(struct svc_rqst *rqstp, struct svc_fh *fhp,
>  	__be32		err;
>  	int		host_err;
>  
> +	trace_nfsd_create(rqstp, fhp);
> +
>  	if (isdotent(fname, flen))
>  		return nfserr_exist;
>  
> @@ -1609,6 +1621,8 @@ nfsd_readlink(struct svc_rqst *rqstp, struct svc_fh *fhp, char *buf, int *lenp)
>  	DEFINE_DELAYED_CALL(done);
>  	int len;
>  
> +	trace_nfsd_readlink(rqstp, fhp);
> +
>  	err = fh_verify(rqstp, fhp, S_IFLNK, NFSD_MAY_NOP);
>  	if (unlikely(err))
>  		return err;
> @@ -1657,6 +1671,8 @@ nfsd_symlink(struct svc_rqst *rqstp, struct svc_fh *fhp,
>  	__be32		err, cerr;
>  	int		host_err;
>  
> +	trace_nfsd_symlink(rqstp, fhp);
> +
>  	err = nfserr_noent;
>  	if (!flen || path[0] == '\0')
>  		goto out;
> @@ -1725,6 +1741,8 @@ nfsd_link(struct svc_rqst *rqstp, struct svc_fh *ffhp,
>  	__be32		err;
>  	int		host_err;
>  
> +	trace_nfsd_link(rqstp, ffhp);
> +
>  	err = fh_verify(rqstp, ffhp, S_IFDIR, NFSD_MAY_CREATE);
>  	if (err)
>  		goto out;
> @@ -1842,6 +1860,8 @@ nfsd_rename(struct svc_rqst *rqstp, struct svc_fh *ffhp, char *fname, int flen,
>  	int		host_err;
>  	bool		close_cached = false;
>  
> +	trace_nfsd_rename(rqstp, ffhp);
> +
>  	err = fh_verify(rqstp, ffhp, S_IFDIR, NFSD_MAY_REMOVE);
>  	if (err)
>  		goto out;
> @@ -2000,6 +2020,8 @@ nfsd_unlink(struct svc_rqst *rqstp, struct svc_fh *fhp, int type,
>  	__be32		err;
>  	int		host_err;
>  
> +	trace_nfsd_unlink(rqstp, fhp);
> +
>  	err = nfserr_acces;
>  	if (!flen || isdotent(fname, flen))
>  		goto out;
> @@ -2222,6 +2244,8 @@ nfsd_readdir(struct svc_rqst *rqstp, struct svc_fh *fhp, loff_t *offsetp,
>  	loff_t		offset = *offsetp;
>  	int             may_flags = NFSD_MAY_READ;
>  
> +	trace_nfsd_readdir(rqstp, fhp);
> +
>  	err = nfsd_open(rqstp, fhp, S_IFDIR, may_flags, &file);
>  	if (err)
>  		goto out;
> @@ -2288,6 +2312,8 @@ nfsd_statfs(struct svc_rqst *rqstp, struct svc_fh *fhp, struct kstatfs *stat, in
>  {
>  	__be32 err;
>  
> +	trace_nfsd_statfs(rqstp, fhp);
> +
>  	err = fh_verify(rqstp, fhp, 0, NFSD_MAY_NOP | access);
>  	if (!err) {
>  		struct path path = {
> 


-- 
Chuck Lever

Re: [PATCH 3/4] nfsd: add some stub tracepoints around key vfs functions

[Jeff Layton]

On Thu, 2025-03-06 at 09:29 -0500, Chuck Lever wrote:
> On 3/6/25 7:38 AM, Jeff Layton wrote:
> > Sargun set up kprobes to add some of these tracepoints. Convert them to
> > simple static tracepoints. These are pretty sparse for now, but they
> > could be expanded in the future as needed.
> 
> I have mixed feelings about this.
> 
> - Probably tracepoints should replace the existing dprintk call sites.
>   dprintk is kind of useless for heavy traffic.
> 

I'm fine with removing dprintks as we go.

> - Seems like other existing tracepoints could report most of the same
>   information. fh_verify, for example, has a tracepoint that reports
>   the file handle. There's an svc proc tracepoint, and an NFSv4 COMPOUND
>   tracepoint that can report XID and procedure.
> 

The problem there is the lack of context. Yes, I can see that
fh_verify() got called, but on a busy server it can be hard to tell why
it got called. I see things like the fh_verify() tracepoint working in
conjunction with these new tracepoints. IOW, you could match up the
xids and see which fh_verify() was called for which operation.


If you like, I could drop the fh hash from these tracepoints, and just
print xid and net namespace?
 
> - If the tracepoint is passed an @rqstp, it should also record the
>   nfsd namespace number.
> 

Thanks, I'll plan to add that.

> I'd like to know more about what exactly you were hoping to extract,
> and which tracepoint(s) were most helpful for you.
> 

Sargun, you're probably best equipped to answer this question. What's
most useful to you in these tracepoints?

> 
> > Cc: Sargun Dillon <sargun@meta.com>
> > Signed-off-by: Jeff Layton <jlayton@kernel.org>
> > ---
> >  fs/nfsd/nfs3proc.c |  3 +++
> >  fs/nfsd/nfs4proc.c |  2 ++
> >  fs/nfsd/nfsproc.c  |  2 ++
> >  fs/nfsd/trace.h    | 35 +++++++++++++++++++++++++++++++++++
> >  fs/nfsd/vfs.c      | 26 ++++++++++++++++++++++++++
> >  5 files changed, 68 insertions(+)
> > 
> > diff --git a/fs/nfsd/nfs3proc.c b/fs/nfsd/nfs3proc.c
> > index 372bdcf5e07a5c835da240ecebb02e3576eb2ca6..2a56cae4c78a7ca66d569637e9f0e7c0fdcfb826 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
> >  
> > @@ -69,6 +70,8 @@ nfsd3_proc_getattr(struct svc_rqst *rqstp)
> >  	struct nfsd_fhandle *argp = rqstp->rq_argp;
> >  	struct nfsd3_attrstat *resp = rqstp->rq_resp;
> >  
> > +	trace_nfsd_getattr(rqstp, &argp->fh);
> > +
> >  	dprintk("nfsd: GETATTR(3)  %s\n",
> >  		SVCFH_fmt(&argp->fh));
> >  
> > diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
> > index c20f1abcb94f131b1ec898860ba2c394b22e61e1..87d241ff91920317e0122a58bf0cf71c5b28d264 100644
> > --- a/fs/nfsd/nfs4proc.c
> > +++ b/fs/nfsd/nfs4proc.c
> > @@ -876,6 +876,8 @@ nfsd4_getattr(struct svc_rqst *rqstp, struct nfsd4_compound_state *cstate,
> >  	struct nfsd4_getattr *getattr = &u->getattr;
> >  	__be32 status;
> >  
> > +	trace_nfsd_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 6dda081eb24c00b834ab0965c3a35a12115bceb7..9563372f0826b9580299144069f57664dbd2a079 100644
> > --- a/fs/nfsd/nfsproc.c
> > +++ b/fs/nfsd/nfsproc.c
> > @@ -54,6 +54,8 @@ nfsd_proc_getattr(struct svc_rqst *rqstp)
> >  	struct nfsd_fhandle *argp = rqstp->rq_argp;
> >  	struct nfsd_attrstat *resp = rqstp->rq_resp;
> >  
> > +	trace_nfsd_getattr(rqstp, &argp->fh);
> > +
> >  	dprintk("nfsd: GETATTR  %s\n", SVCFH_fmt(&argp->fh));
> >  
> >  	fh_copy(&resp->fh, &argp->fh);
> > diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
> > index 117f7e1fd66a4838a048cc44bd5bf4dd8c6db958..d4a78fe1bab24b594b96cca8611c439da9ed6926 100644
> > --- a/fs/nfsd/trace.h
> > +++ b/fs/nfsd/trace.h
> > @@ -2337,6 +2337,41 @@ DEFINE_EVENT(nfsd_copy_async_done_class,		\
> >  DEFINE_COPY_ASYNC_DONE_EVENT(done);
> >  DEFINE_COPY_ASYNC_DONE_EVENT(cancel);
> >  
> > +DECLARE_EVENT_CLASS(nfsd_vfs_class,
> > +	TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp),
> > +	TP_ARGS(rqstp, fhp),
> > +	TP_STRUCT__entry(
> > +		__field(u32, xid)
> > +		__field(u32, fh_hash)
> > +	),
> > +	TP_fast_assign(
> > +		__entry->xid = be32_to_cpu(rqstp->rq_xid);
> > +		__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_EVENT(name)                                        \
> > +	DEFINE_EVENT(nfsd_vfs_class, nfsd_##name,                           \
> > +		     TP_PROTO(struct svc_rqst *rqstp, struct svc_fh *fhp), \
> > +		     TP_ARGS(rqstp, fhp))
> > +
> > +DEFINE_NFSD_VFS_EVENT(lookup);
> > +DEFINE_NFSD_VFS_EVENT(lookup_dentry);
> > +DEFINE_NFSD_VFS_EVENT(create_locked);
> > +DEFINE_NFSD_VFS_EVENT(create);
> > +DEFINE_NFSD_VFS_EVENT(access);
> > +DEFINE_NFSD_VFS_EVENT(create_setattr);
> > +DEFINE_NFSD_VFS_EVENT(readlink);
> > +DEFINE_NFSD_VFS_EVENT(symlink);
> > +DEFINE_NFSD_VFS_EVENT(link);
> > +DEFINE_NFSD_VFS_EVENT(rename);
> > +DEFINE_NFSD_VFS_EVENT(unlink);
> > +DEFINE_NFSD_VFS_EVENT(readdir);
> > +DEFINE_NFSD_VFS_EVENT(statfs);
> > +DEFINE_NFSD_VFS_EVENT(getattr);
> > +
> >  #define show_ia_valid_flags(x)					\
> >  	__print_flags(x, "|",					\
> >  			{ ATTR_MODE, "MODE" },			\
> > diff --git a/fs/nfsd/vfs.c b/fs/nfsd/vfs.c
> > index d755cc87a8670c491e55194de266d999ba1b337d..772a4d32b09a4bd217a9258ec803c06618cf13c8 100644
> > --- a/fs/nfsd/vfs.c
> > +++ b/fs/nfsd/vfs.c
> > @@ -244,6 +244,8 @@ nfsd_lookup_dentry(struct svc_rqst *rqstp, struct svc_fh *fhp,
> >  	struct dentry		*dentry;
> >  	int			host_err;
> >  
> > +	trace_nfsd_lookup(rqstp, fhp);
> > +
> >  	dprintk("nfsd: nfsd_lookup(fh %s, %.*s)\n", SVCFH_fmt(fhp), len,name);
> >  
> >  	dparent = fhp->fh_dentry;
> > @@ -313,6 +315,8 @@ nfsd_lookup(struct svc_rqst *rqstp, struct svc_fh *fhp, const char *name,
> >  	struct dentry		*dentry;
> >  	__be32 err;
> >  
> > +	trace_nfsd_lookup(rqstp, fhp);
> > +
> >  	err = fh_verify(rqstp, fhp, S_IFDIR, NFSD_MAY_EXEC);
> >  	if (err)
> >  		return err;
> > @@ -794,6 +798,8 @@ nfsd_access(struct svc_rqst *rqstp, struct svc_fh *fhp, u32 *access, u32 *suppor
> >  	u32			query, result = 0, sresult = 0;
> >  	__be32			error;
> >  
> > +	trace_nfsd_create(rqstp, fhp);
> > +
> >  	error = fh_verify(rqstp, fhp, 0, NFSD_MAY_NOP);
> >  	if (error)
> >  		goto out;
> > @@ -1401,6 +1407,8 @@ nfsd_create_setattr(struct svc_rqst *rqstp, struct svc_fh *fhp,
> >  	struct iattr *iap = attrs->na_iattr;
> >  	__be32 status;
> >  
> > +	trace_nfsd_create_setattr(rqstp, fhp);
> > +
> >  	/*
> >  	 * Mode has already been set by file creation.
> >  	 */
> > @@ -1467,6 +1475,8 @@ nfsd_create_locked(struct svc_rqst *rqstp, struct svc_fh *fhp,
> >  	__be32		err;
> >  	int		host_err;
> >  
> > +	trace_nfsd_create_locked(rqstp, fhp);
> > +
> >  	dentry = fhp->fh_dentry;
> >  	dirp = d_inode(dentry);
> >  
> > @@ -1557,6 +1567,8 @@ nfsd_create(struct svc_rqst *rqstp, struct svc_fh *fhp,
> >  	__be32		err;
> >  	int		host_err;
> >  
> > +	trace_nfsd_create(rqstp, fhp);
> > +
> >  	if (isdotent(fname, flen))
> >  		return nfserr_exist;
> >  
> > @@ -1609,6 +1621,8 @@ nfsd_readlink(struct svc_rqst *rqstp, struct svc_fh *fhp, char *buf, int *lenp)
> >  	DEFINE_DELAYED_CALL(done);
> >  	int len;
> >  
> > +	trace_nfsd_readlink(rqstp, fhp);
> > +
> >  	err = fh_verify(rqstp, fhp, S_IFLNK, NFSD_MAY_NOP);
> >  	if (unlikely(err))
> >  		return err;
> > @@ -1657,6 +1671,8 @@ nfsd_symlink(struct svc_rqst *rqstp, struct svc_fh *fhp,
> >  	__be32		err, cerr;
> >  	int		host_err;
> >  
> > +	trace_nfsd_symlink(rqstp, fhp);
> > +
> >  	err = nfserr_noent;
> >  	if (!flen || path[0] == '\0')
> >  		goto out;
> > @@ -1725,6 +1741,8 @@ nfsd_link(struct svc_rqst *rqstp, struct svc_fh *ffhp,
> >  	__be32		err;
> >  	int		host_err;
> >  
> > +	trace_nfsd_link(rqstp, ffhp);
> > +
> >  	err = fh_verify(rqstp, ffhp, S_IFDIR, NFSD_MAY_CREATE);
> >  	if (err)
> >  		goto out;
> > @@ -1842,6 +1860,8 @@ nfsd_rename(struct svc_rqst *rqstp, struct svc_fh *ffhp, char *fname, int flen,
> >  	int		host_err;
> >  	bool		close_cached = false;
> >  
> > +	trace_nfsd_rename(rqstp, ffhp);
> > +
> >  	err = fh_verify(rqstp, ffhp, S_IFDIR, NFSD_MAY_REMOVE);
> >  	if (err)
> >  		goto out;
> > @@ -2000,6 +2020,8 @@ nfsd_unlink(struct svc_rqst *rqstp, struct svc_fh *fhp, int type,
> >  	__be32		err;
> >  	int		host_err;
> >  
> > +	trace_nfsd_unlink(rqstp, fhp);
> > +
> >  	err = nfserr_acces;
> >  	if (!flen || isdotent(fname, flen))
> >  		goto out;
> > @@ -2222,6 +2244,8 @@ nfsd_readdir(struct svc_rqst *rqstp, struct svc_fh *fhp, loff_t *offsetp,
> >  	loff_t		offset = *offsetp;
> >  	int             may_flags = NFSD_MAY_READ;
> >  
> > +	trace_nfsd_readdir(rqstp, fhp);
> > +
> >  	err = nfsd_open(rqstp, fhp, S_IFDIR, may_flags, &file);
> >  	if (err)
> >  		goto out;
> > @@ -2288,6 +2312,8 @@ nfsd_statfs(struct svc_rqst *rqstp, struct svc_fh *fhp, struct kstatfs *stat, in
> >  {
> >  	__be32 err;
> >  
> > +	trace_nfsd_statfs(rqstp, fhp);
> > +
> >  	err = fh_verify(rqstp, fhp, 0, NFSD_MAY_NOP | access);
> >  	if (!err) {
> >  		struct path path = {
> > 
> 
> 

-- 
Jeff Layton <jlayton@kernel.org>

Re: [PATCH 3/4] nfsd: add some stub tracepoints around key vfs functions

[Chuck Lever]

On 3/6/25 11:28 AM, Jeff Layton wrote:
> On Thu, 2025-03-06 at 09:29 -0500, Chuck Lever wrote:
>> On 3/6/25 7:38 AM, Jeff Layton wrote:
>>> Sargun set up kprobes to add some of these tracepoints. Convert them to
>>> simple static tracepoints. These are pretty sparse for now, but they
>>> could be expanded in the future as needed.
>>
>> I have mixed feelings about this.

To be very clear: I'm always up for better observability! The details of
this patch are where I start to have some hesitation.


>> - Probably tracepoints should replace the existing dprintk call sites.
>>   dprintk is kind of useless for heavy traffic.
>>
> 
> I'm fine with removing dprintks as we go.

Removing them was controversial a few years ago when I first brought
this up... I would very much like to see these call sites gone, even if
we don't have immediate replacements in the form of trace points.


>> - Seems like other existing tracepoints could report most of the same
>>   information. fh_verify, for example, has a tracepoint that reports
>>   the file handle. There's an svc proc tracepoint, and an NFSv4 COMPOUND
>>   tracepoint that can report XID and procedure.
>>
> 
> The problem there is the lack of context. Yes, I can see that
> fh_verify() got called, but on a busy server it can be hard to tell why
> it got called. I see things like the fh_verify() tracepoint working in
> conjunction with these new tracepoints. IOW, you could match up the
> xids and see which fh_verify() was called for which operation.

If we're talking about NFSv3 only, sunrpc:svc_process records the XID,
nfsd thread, NFSv3 procedure name, and NFSD namespace of each incoming
RPC call. You also get the NFS client's IP address.

You can also enable nfsd:nfsd_fh_verify to capture several of those
items, plus the NFS file handle.

The kernel process information will be identical for both the svc_proc
and nfsd_fh_verify trace points -- that will tie the two records
together so you can match an XID to an NFS procedure and its file handle
argument.

If you want to see a little more you can enable the function_graph
plug-in for nfsd_dispatch().

Another approach is adding trace points in the XDR layer to capture
all of the arguments of incoming RPC calls:

https://web.git.kernel.org/pub/scm/linux/kernel/git/cel/linux.git/log/?h=topic-xdr-tracepoints


-- 
Chuck Lever

Re: [PATCH 3/4] nfsd: add some stub tracepoints around key vfs functions

[kernel test robot]

Hi Jeff,

kernel test robot noticed the following build errors:

[auto build test ERROR on 7dc86d35a5f8a7ac24b53792c704b101e5041842]

url:    https://github.com/intel-lab-lkp/linux/commits/Jeff-Layton/nfsd-add-commit-start-done-tracepoints-around-nfsd_commit/20250306-204120
base:   7dc86d35a5f8a7ac24b53792c704b101e5041842
patch link:    https://lore.kernel.org/r/20250306-nfsd-tracepoints-v1-3-4405bf41b95f%40kernel.org
patch subject: [PATCH 3/4] nfsd: add some stub tracepoints around key vfs functions
config: arm-randconfig-003-20250307 (https://download.01.org/0day-ci/archive/20250307/202503071828.4eKhNhUb-lkp@intel.com/config)
compiler: clang version 19.1.7 (https://github.com/llvm/llvm-project cd708029e0b2869e80abe31ddb175f7c35361f90)
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20250307/202503071828.4eKhNhUb-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202503071828.4eKhNhUb-lkp@intel.com/

All errors (new ones prefixed by >>):

>> fs/nfsd/nfsproc.c:57:2: error: call to undeclared function 'trace_nfsd_getattr'; ISO C99 and later do not support implicit function declarations [-Wimplicit-function-declaration]
      57 |         trace_nfsd_getattr(rqstp, &argp->fh);
         |         ^
   1 error generated.


vim +/trace_nfsd_getattr +57 fs/nfsd/nfsproc.c

    46	
    47	/*
    48	 * Get a file's attributes
    49	 * N.B. After this call resp->fh needs an fh_put
    50	 */
    51	static __be32
    52	nfsd_proc_getattr(struct svc_rqst *rqstp)
    53	{
    54		struct nfsd_fhandle *argp = rqstp->rq_argp;
    55		struct nfsd_attrstat *resp = rqstp->rq_resp;
    56	
  > 57		trace_nfsd_getattr(rqstp, &argp->fh);
    58	
    59		dprintk("nfsd: GETATTR  %s\n", SVCFH_fmt(&argp->fh));
    60	
    61		fh_copy(&resp->fh, &argp->fh);
    62		resp->status = fh_verify(rqstp, &resp->fh, 0,
    63					 NFSD_MAY_NOP | NFSD_MAY_BYPASS_GSS_ON_ROOT);
    64		if (resp->status != nfs_ok)
    65			goto out;
    66		resp->status = fh_getattr(&resp->fh, &resp->stat);
    67	out:
    68		resp->status = nfsd_map_status(resp->status);
    69		return rpc_success;
    70	}
    71	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

Re: [PATCH 3/4] nfsd: add some stub tracepoints around key vfs functions

[kernel test robot]

Hi Jeff,

kernel test robot noticed the following build errors:

[auto build test ERROR on 7dc86d35a5f8a7ac24b53792c704b101e5041842]

url:    https://github.com/intel-lab-lkp/linux/commits/Jeff-Layton/nfsd-add-commit-start-done-tracepoints-around-nfsd_commit/20250306-204120
base:   7dc86d35a5f8a7ac24b53792c704b101e5041842
patch link:    https://lore.kernel.org/r/20250306-nfsd-tracepoints-v1-3-4405bf41b95f%40kernel.org
patch subject: [PATCH 3/4] nfsd: add some stub tracepoints around key vfs functions
config: csky-randconfig-001-20250307 (https://download.01.org/0day-ci/archive/20250307/202503071834.Qj8kjbdh-lkp@intel.com/config)
compiler: csky-linux-gcc (GCC) 14.2.0
reproduce (this is a W=1 build): (https://download.01.org/0day-ci/archive/20250307/202503071834.Qj8kjbdh-lkp@intel.com/reproduce)

If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <lkp@intel.com>
| Closes: https://lore.kernel.org/oe-kbuild-all/202503071834.Qj8kjbdh-lkp@intel.com/

All errors (new ones prefixed by >>):

   fs/nfsd/nfsproc.c: In function 'nfsd_proc_getattr':
>> fs/nfsd/nfsproc.c:57:9: error: implicit declaration of function 'trace_nfsd_getattr' [-Wimplicit-function-declaration]
      57 |         trace_nfsd_getattr(rqstp, &argp->fh);
         |         ^~~~~~~~~~~~~~~~~~


vim +/trace_nfsd_getattr +57 fs/nfsd/nfsproc.c

    46	
    47	/*
    48	 * Get a file's attributes
    49	 * N.B. After this call resp->fh needs an fh_put
    50	 */
    51	static __be32
    52	nfsd_proc_getattr(struct svc_rqst *rqstp)
    53	{
    54		struct nfsd_fhandle *argp = rqstp->rq_argp;
    55		struct nfsd_attrstat *resp = rqstp->rq_resp;
    56	
  > 57		trace_nfsd_getattr(rqstp, &argp->fh);
    58	
    59		dprintk("nfsd: GETATTR  %s\n", SVCFH_fmt(&argp->fh));
    60	
    61		fh_copy(&resp->fh, &argp->fh);
    62		resp->status = fh_verify(rqstp, &resp->fh, 0,
    63					 NFSD_MAY_NOP | NFSD_MAY_BYPASS_GSS_ON_ROOT);
    64		if (resp->status != nfs_ok)
    65			goto out;
    66		resp->status = fh_getattr(&resp->fh, &resp->stat);
    67	out:
    68		resp->status = nfsd_map_status(resp->status);
    69		return rpc_success;
    70	}
    71	

-- 
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki

[PATCH 4/4] sunrpc: keep a count of when there are no threads available

[Jeff Layton]

Add a new percpu counter and pool_stat that can track how often the
kernel went to wake up a thread, but they all were busy.

Signed-off-by: Jeff Layton <jlayton@kernel.org>
---
 include/linux/sunrpc/svc.h | 1 +
 net/sunrpc/svc.c           | 4 +++-
 net/sunrpc/svc_xprt.c      | 7 ++++---
 3 files changed, 8 insertions(+), 4 deletions(-)

diff --git a/include/linux/sunrpc/svc.h b/include/linux/sunrpc/svc.h
index 74658cca0f38f21e2673c84c7bcae948ff7feea6..179dbfc86887374e1a0a2b669c5839cb622dd3f5 100644
--- a/include/linux/sunrpc/svc.h
+++ b/include/linux/sunrpc/svc.h
@@ -44,6 +44,7 @@ struct svc_pool {
 	struct percpu_counter	sp_messages_arrived;
 	struct percpu_counter	sp_sockets_queued;
 	struct percpu_counter	sp_threads_woken;
+	struct percpu_counter	sp_no_threads_avail;
 
 	unsigned long		sp_flags;
 } ____cacheline_aligned_in_smp;
diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c
index e7f9c295d13c03bf28a5eeec839fd85e24f5525f..789f08022aec210b6df08036997ef801d3c73ac8 100644
--- a/net/sunrpc/svc.c
+++ b/net/sunrpc/svc.c
@@ -545,6 +545,7 @@ __svc_create(struct svc_program *prog, int nprogs, struct svc_stat *stats,
 		percpu_counter_init(&pool->sp_messages_arrived, 0, GFP_KERNEL);
 		percpu_counter_init(&pool->sp_sockets_queued, 0, GFP_KERNEL);
 		percpu_counter_init(&pool->sp_threads_woken, 0, GFP_KERNEL);
+		percpu_counter_init(&pool->sp_no_threads_avail, 0, GFP_KERNEL);
 	}
 
 	return serv;
@@ -629,6 +630,7 @@ svc_destroy(struct svc_serv **servp)
 		percpu_counter_destroy(&pool->sp_messages_arrived);
 		percpu_counter_destroy(&pool->sp_sockets_queued);
 		percpu_counter_destroy(&pool->sp_threads_woken);
+		percpu_counter_destroy(&pool->sp_no_threads_avail);
 	}
 	kfree(serv->sv_pools);
 	kfree(serv);
@@ -756,7 +758,7 @@ void svc_pool_wake_idle_thread(struct svc_pool *pool)
 		return;
 	}
 	rcu_read_unlock();
-
+	percpu_counter_inc(&pool->sp_no_threads_avail);
 }
 EXPORT_SYMBOL_GPL(svc_pool_wake_idle_thread);
 
diff --git a/net/sunrpc/svc_xprt.c b/net/sunrpc/svc_xprt.c
index ae25405d8bd22672a361d1fd3adfdcebb403f90f..b2c5a74e4609e8f4a3f5f4637dd9b46b40b79324 100644
--- a/net/sunrpc/svc_xprt.c
+++ b/net/sunrpc/svc_xprt.c
@@ -1451,15 +1451,16 @@ static int svc_pool_stats_show(struct seq_file *m, void *p)
 	struct svc_pool *pool = p;
 
 	if (p == SEQ_START_TOKEN) {
-		seq_puts(m, "# pool packets-arrived sockets-enqueued threads-woken threads-timedout\n");
+		seq_puts(m, "# pool packets-arrived sockets-enqueued threads-woken threads-timedout no-threads-avail\n");
 		return 0;
 	}
 
-	seq_printf(m, "%u %llu %llu %llu 0\n",
+	seq_printf(m, "%u %llu %llu %llu 0 %llu\n",
 		   pool->sp_id,
 		   percpu_counter_sum_positive(&pool->sp_messages_arrived),
 		   percpu_counter_sum_positive(&pool->sp_sockets_queued),
-		   percpu_counter_sum_positive(&pool->sp_threads_woken));
+		   percpu_counter_sum_positive(&pool->sp_threads_woken),
+		   percpu_counter_sum_positive(&pool->sp_no_threads_avail));
 
 	return 0;
 }

-- 
2.48.1