> On Mar 14, 2018, at 4:55 PM, J. Bruce Fields <bfields@xxxxxxxxxxxx> wrote:
>
> 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?
The tools that are used to look at these records are very generic,
like trace-cmd, which doesn't know from NFS. It's just so much nicer
to use that tool and see operation names that match wireshark displays
rather than op numbers.
However, if you'd like to additionally preserve the operation number
in the trace record, that is possible to add very easily.
Here is the difficulty with the latency event I add earlier in the
series: If we simply record the RPC procedure number there, for NFSv4
we'd see just a bunch of "proc=1". I added this here trace event
partially to record the latency of processing each operation in a
COMPOUND, and partially to see which operations are associated with
the latency of the whole RPC (ah, it's SEQUENCE, PUTFH, READ, GETATTR,
so this must be a READ request).
> --b.
>
>>
>> Signed-off-by: Chuck Lever <chuck.lever@xxxxxxxxxx>
>> ---
>> 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));
Instead of "op=%u/%u" here, maybe the XID might be more useful for
the event that reports each operation in the COMPOUND. On the other
hand, it's pretty obvious which nfsd_compound event these go with:
they will all come from the same nfsd process.
>> 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,
> --
> To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
> the body of a message to majordomo@xxxxxxxxxxxxxxx
> More majordomo info at http://vger.kernel.org/majordomo-info.html
--
Chuck Lever
--
To unsubscribe from this list: send the line "unsubscribe linux-nfs" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
