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

[Jeff Layton <jlayton@kernel.org>]

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>