Re: [PATCH 15/15] nfsd: Trace NFSv4 COMPOUND execution

["J. Bruce Fields" <bfields@fieldses.org>]

On Tue, Mar 13, 2018 at 11:44:59AM -0400, Chuck Lever wrote:
> This helps record the identity and timing of the ops in each NFSv4
> COMPOUND, replacing dprintk calls that did much the same thing.

Would it be better to leave it to userspace to translate an operation
number to a name?

--b.

> 
> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> ---
>  fs/nfsd/nfs4proc.c |    9 +++------
>  fs/nfsd/trace.h    |   39 +++++++++++++++++++++++++++++++++++++++
>  2 files changed, 42 insertions(+), 6 deletions(-)
> 
> diff --git a/fs/nfsd/nfs4proc.c b/fs/nfsd/nfs4proc.c
> index 39016b6..0df37e0 100644
> --- a/fs/nfsd/nfs4proc.c
> +++ b/fs/nfsd/nfs4proc.c
> @@ -1722,12 +1722,10 @@ static void svcxdr_init_encode(struct svc_rqst *rqstp,
>  		goto encode_op;
>  	}
>  
> +	trace_nfsd_compound(rqstp, args->opcnt);
>  	while (!status && resp->opcnt < args->opcnt) {
>  		op = &args->ops[resp->opcnt++];
>  
> -		dprintk("nfsv4 compound op #%d/%d: %d (%s)\n",
> -			resp->opcnt, args->opcnt, op->opnum,
> -			nfsd4_op_name(op->opnum));
>  		/*
>  		 * The XDR decode routines may have pre-set op->status;
>  		 * for example, if there is a miscellaneous XDR error
> @@ -1801,9 +1799,8 @@ static void svcxdr_init_encode(struct svc_rqst *rqstp,
>  			status = op->status;
>  		}
>  
> -		dprintk("nfsv4 compound op %p opcnt %d #%d: %d: status %d\n",
> -			args->ops, args->opcnt, resp->opcnt, op->opnum,
> -			be32_to_cpu(status));
> +		trace_nfsd_compound_status(args->opcnt, resp->opcnt, status,
> +					   nfsd4_op_name(op->opnum));
>  
>  		nfsd4_cstate_clear_replay(cstate);
>  		nfsd4_increment_op_stats(op->opnum);
> diff --git a/fs/nfsd/trace.h b/fs/nfsd/trace.h
> index a8bbd9d..80933e4 100644
> --- a/fs/nfsd/trace.h
> +++ b/fs/nfsd/trace.h
> @@ -11,6 +11,45 @@
>  #include <linux/tracepoint.h>
>  #include "nfsfh.h"
>  
> +TRACE_EVENT(nfsd_compound,
> +	TP_PROTO(const struct svc_rqst *rqst,
> +		 u32 args_opcnt),
> +	TP_ARGS(rqst, args_opcnt),
> +	TP_STRUCT__entry(
> +		__field(u32, xid)
> +		__field(u32, args_opcnt)
> +	),
> +	TP_fast_assign(
> +		__entry->xid = be32_to_cpu(rqst->rq_xid);
> +		__entry->args_opcnt = args_opcnt;
> +	),
> +	TP_printk("xid=0x%08x opcnt=%u",
> +		__entry->xid, __entry->args_opcnt)
> +)
> +
> +TRACE_EVENT(nfsd_compound_status,
> +	TP_PROTO(u32 args_opcnt,
> +		 u32 resp_opcnt,
> +		 __be32 status,
> +		 const char *name),
> +	TP_ARGS(args_opcnt, resp_opcnt, status, name),
> +	TP_STRUCT__entry(
> +		__field(u32, args_opcnt)
> +		__field(u32, resp_opcnt)
> +		__field(int, status)
> +		__string(name, name)
> +	),
> +	TP_fast_assign(
> +		__entry->args_opcnt = args_opcnt;
> +		__entry->resp_opcnt = resp_opcnt;
> +		__entry->status = be32_to_cpu(status);
> +		__assign_str(name, name);
> +	),
> +	TP_printk("op=%u/%u %s status=%d",
> +		__entry->resp_opcnt, __entry->args_opcnt,
> +		__get_str(name), __entry->status)
> +)
> +
>  DECLARE_EVENT_CLASS(nfsd_io_class,
>  	TP_PROTO(struct svc_rqst *rqstp,
>  		 struct svc_fh	*fhp,