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

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