diff mbox series

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

Message ID 20250306-nfsd-tracepoints-v1-3-4405bf41b95f@kernel.org (mailing list archive)
State Not Applicable
Headers show
Series nfsd: observability improvements | expand

Checks

Context Check Description
netdev/series_format success Posting correctly formatted
netdev/tree_selection success Guessed tree name to be net-next
netdev/ynl success Generated files up to date; no warnings/errors; no diff in generated;
netdev/fixes_present success Fixes tag not required for -next series
netdev/header_inline success No static functions without inline keyword in header files
netdev/build_32bit fail Errors and warnings before: 0 this patch: 7
netdev/build_tools success No tools touched, skip
netdev/cc_maintainers success CCed 7 of 7 maintainers
netdev/build_clang fail Errors and warnings before: 0 this patch: 8
netdev/verify_signedoff success Signed-off-by tag matches author and committer
netdev/deprecated_api success None detected
netdev/check_selftest success No net selftest shell script
netdev/verify_fixes success No Fixes tag
netdev/build_allmodconfig_warn fail Errors and warnings before: 4 this patch: 11
netdev/checkpatch warning CHECK: Alignment should match open parenthesis CHECK: Lines should not end with a '('
netdev/build_clang_rust success No Rust files in patch. Skipping build
netdev/kdoc success Errors and warnings before: 17 this patch: 17
netdev/source_inline success Was 0 now: 0

Commit Message

Jeff Layton March 6, 2025, 12:38 p.m. UTC 
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(+)

Comments

Chuck Lever March 6, 2025, 2:29 p.m. UTC | #1 
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 = {
>
Jeff Layton March 6, 2025, 4:28 p.m. UTC | #2 
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 = {
> > 
> 
>
Chuck Lever March 6, 2025, 5:40 p.m. UTC | #3 
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
diff mbox series

Patch

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 = {