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@xxxxxxxxxx>
> > ---
> >  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@xxxxxxxxxx>