Skip to content
This repository has been archived by the owner on Sep 24, 2020. It is now read-only.

Commit

Permalink
svcrdma: Trace key RPC/RDMA protocol events
Browse files Browse the repository at this point in the history 
This includes:
  * Transport accept and tear-down
  * Decisions about using Write and Reply chunks
  * Each RDMA segment that is handled
  * Whenever an RDMA_ERR is sent

As a clean-up, I've standardized the order of the includes, and
removed some now redundant dprintk call sites.

Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
Signed-off-by: J. Bruce Fields <bfields@redhat.com>
  • Loading branch information
@chucklever
chucklever authored and J. Bruce Fields committed May 11, 2018
1 parent b6e717c commit 98895ed
Show file tree
Hide file tree
Showing 5 changed files with 311 additions and 48 deletions.
262 changes: 261 additions & 1 deletion include/trace/events/rpcrdma.h
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,8 @@
/* SPDX-License-Identifier: GPL-2.0 */
/*
* Copyright (c) 2017 Oracle. All rights reserved.
* Copyright (c) 2017, 2018 Oracle. All rights reserved.
*
* Trace point definitions for the "rpcrdma" subsystem.
*/
#undef TRACE_SYSTEM
#define TRACE_SYSTEM rpcrdma
Expand Down Expand Up @@ -885,6 +887,264 @@ TRACE_EVENT(xprtrdma_cb_setup,
DEFINE_CB_EVENT(xprtrdma_cb_call);
DEFINE_CB_EVENT(xprtrdma_cb_reply);

/**
** Server-side RPC/RDMA events
**/

DECLARE_EVENT_CLASS(svcrdma_xprt_event,
TP_PROTO(
const struct svc_xprt *xprt
),

TP_ARGS(xprt),

TP_STRUCT__entry(
__field(const void *, xprt)
__string(addr, xprt->xpt_remotebuf)
),

TP_fast_assign(
__entry->xprt = xprt;
__assign_str(addr, xprt->xpt_remotebuf);
),

TP_printk("xprt=%p addr=%s",
__entry->xprt, __get_str(addr)
)
);

#define DEFINE_XPRT_EVENT(name) \
DEFINE_EVENT(svcrdma_xprt_event, svcrdma_xprt_##name, \
TP_PROTO( \
const struct svc_xprt *xprt \
), \
TP_ARGS(xprt))

DEFINE_XPRT_EVENT(accept);
DEFINE_XPRT_EVENT(fail);
DEFINE_XPRT_EVENT(free);

TRACE_DEFINE_ENUM(RDMA_MSG);
TRACE_DEFINE_ENUM(RDMA_NOMSG);
TRACE_DEFINE_ENUM(RDMA_MSGP);
TRACE_DEFINE_ENUM(RDMA_DONE);
TRACE_DEFINE_ENUM(RDMA_ERROR);

#define show_rpcrdma_proc(x) \
__print_symbolic(x, \
{ RDMA_MSG, "RDMA_MSG" }, \
{ RDMA_NOMSG, "RDMA_NOMSG" }, \
{ RDMA_MSGP, "RDMA_MSGP" }, \
{ RDMA_DONE, "RDMA_DONE" }, \
{ RDMA_ERROR, "RDMA_ERROR" })

TRACE_EVENT(svcrdma_decode_rqst,
TP_PROTO(
__be32 *p,
unsigned int hdrlen
),

TP_ARGS(p, hdrlen),

TP_STRUCT__entry(
__field(u32, xid)
__field(u32, vers)
__field(u32, proc)
__field(u32, credits)
__field(unsigned int, hdrlen)
),

TP_fast_assign(
__entry->xid = be32_to_cpup(p++);
__entry->vers = be32_to_cpup(p++);
__entry->credits = be32_to_cpup(p++);
__entry->proc = be32_to_cpup(p);
__entry->hdrlen = hdrlen;
),

TP_printk("xid=0x%08x vers=%u credits=%u proc=%s hdrlen=%u",
__entry->xid, __entry->vers, __entry->credits,
show_rpcrdma_proc(__entry->proc), __entry->hdrlen)
);

TRACE_EVENT(svcrdma_decode_short,
TP_PROTO(
unsigned int hdrlen
),

TP_ARGS(hdrlen),

TP_STRUCT__entry(
__field(unsigned int, hdrlen)
),

TP_fast_assign(
__entry->hdrlen = hdrlen;
),

TP_printk("hdrlen=%u", __entry->hdrlen)
);

DECLARE_EVENT_CLASS(svcrdma_badreq_event,
TP_PROTO(
__be32 *p
),

TP_ARGS(p),

TP_STRUCT__entry(
__field(u32, xid)
__field(u32, vers)
__field(u32, proc)
__field(u32, credits)
),

TP_fast_assign(
__entry->xid = be32_to_cpup(p++);
__entry->vers = be32_to_cpup(p++);
__entry->credits = be32_to_cpup(p++);
__entry->proc = be32_to_cpup(p);
),

TP_printk("xid=0x%08x vers=%u credits=%u proc=%u",
__entry->xid, __entry->vers, __entry->credits, __entry->proc)
);

#define DEFINE_BADREQ_EVENT(name) \
DEFINE_EVENT(svcrdma_badreq_event, svcrdma_decode_##name,\
TP_PROTO( \
__be32 *p \
), \
TP_ARGS(p))

DEFINE_BADREQ_EVENT(badvers);
DEFINE_BADREQ_EVENT(drop);
DEFINE_BADREQ_EVENT(badproc);
DEFINE_BADREQ_EVENT(parse);

DECLARE_EVENT_CLASS(svcrdma_segment_event,
TP_PROTO(
u32 handle,
u32 length,
u64 offset
),

TP_ARGS(handle, length, offset),

TP_STRUCT__entry(
__field(u32, handle)
__field(u32, length)
__field(u64, offset)
),

TP_fast_assign(
__entry->handle = handle;
__entry->length = length;
__entry->offset = offset;
),

TP_printk("%u@0x%016llx:0x%08x",
__entry->length, (unsigned long long)__entry->offset,
__entry->handle
)
);

#define DEFINE_SEGMENT_EVENT(name) \
DEFINE_EVENT(svcrdma_segment_event, svcrdma_encode_##name,\
TP_PROTO( \
u32 handle, \
u32 length, \
u64 offset \
), \
TP_ARGS(handle, length, offset))

DEFINE_SEGMENT_EVENT(rseg);
DEFINE_SEGMENT_EVENT(wseg);

DECLARE_EVENT_CLASS(svcrdma_chunk_event,
TP_PROTO(
u32 length
),

TP_ARGS(length),

TP_STRUCT__entry(
__field(u32, length)
),

TP_fast_assign(
__entry->length = length;
),

TP_printk("length=%u",
__entry->length
)
);

#define DEFINE_CHUNK_EVENT(name) \
DEFINE_EVENT(svcrdma_chunk_event, svcrdma_encode_##name,\
TP_PROTO( \
u32 length \
), \
TP_ARGS(length))

DEFINE_CHUNK_EVENT(pzr);
DEFINE_CHUNK_EVENT(write);
DEFINE_CHUNK_EVENT(reply);

TRACE_EVENT(svcrdma_encode_read,
TP_PROTO(
u32 length,
u32 position
),

TP_ARGS(length, position),

TP_STRUCT__entry(
__field(u32, length)
__field(u32, position)
),

TP_fast_assign(
__entry->length = length;
__entry->position = position;
),

TP_printk("length=%u position=%u",
__entry->length, __entry->position
)
);

DECLARE_EVENT_CLASS(svcrdma_error_event,
TP_PROTO(
__be32 xid
),

TP_ARGS(xid),

TP_STRUCT__entry(
__field(u32, xid)
),

TP_fast_assign(
__entry->xid = be32_to_cpu(xid);
),

TP_printk("xid=0x%08x",
__entry->xid
)
);

#define DEFINE_ERROR_EVENT(name) \
DEFINE_EVENT(svcrdma_error_event, svcrdma_err_##name, \
TP_PROTO( \
__be32 xid \
), \
TP_ARGS(xid))

DEFINE_ERROR_EVENT(vers);
DEFINE_ERROR_EVENT(chunk);

#endif /* _TRACE_RPCRDMA_H */

#include <trace/define_trace.h>
36 changes: 16 additions & 20 deletions net/sunrpc/xprtrdma/svc_rdma_recvfrom.c
View file
Original file line number Diff line number Diff line change
Expand Up @@ -93,17 +93,19 @@
* (see rdma_read_complete() below).
*/

#include <linux/spinlock.h>
#include <asm/unaligned.h>
#include <rdma/ib_verbs.h>
#include <rdma/rdma_cm.h>

#include <linux/spinlock.h>

#include <linux/sunrpc/xdr.h>
#include <linux/sunrpc/debug.h>
#include <linux/sunrpc/rpc_rdma.h>
#include <linux/sunrpc/svc_rdma.h>

#include "xprt_rdma.h"
#include <trace/events/rpcrdma.h>

#define RPCDBG_FACILITY RPCDBG_SVCXPRT

/*
Expand Down Expand Up @@ -295,7 +297,6 @@ static int svc_rdma_xdr_decode_req(struct xdr_buf *rq_arg)
{
__be32 *p, *end, *rdma_argp;
unsigned int hdr_len;
char *proc;

/* Verify that there's enough bytes for header + something */
if (rq_arg->len <= RPCRDMA_HDRLEN_ERR)
Expand All @@ -307,10 +308,8 @@ static int svc_rdma_xdr_decode_req(struct xdr_buf *rq_arg)

switch (*(rdma_argp + 3)) {
case rdma_msg:
proc = "RDMA_MSG";
break;
case rdma_nomsg:
proc = "RDMA_NOMSG";
break;

case rdma_done:
Expand Down Expand Up @@ -340,30 +339,27 @@ static int svc_rdma_xdr_decode_req(struct xdr_buf *rq_arg)
hdr_len = (unsigned long)p - (unsigned long)rdma_argp;
rq_arg->head[0].iov_len -= hdr_len;
rq_arg->len -= hdr_len;
dprintk("svcrdma: received %s request for XID 0x%08x, hdr_len=%u\n",
proc, be32_to_cpup(rdma_argp), hdr_len);
trace_svcrdma_decode_rqst(rdma_argp, hdr_len);
return hdr_len;

out_short:
dprintk("svcrdma: header too short = %d\n", rq_arg->len);
trace_svcrdma_decode_short(rq_arg->len);
return -EINVAL;

out_version:
dprintk("svcrdma: bad xprt version: %u\n",
be32_to_cpup(rdma_argp + 1));
trace_svcrdma_decode_badvers(rdma_argp);
return -EPROTONOSUPPORT;

out_drop:
dprintk("svcrdma: dropping RDMA_DONE/ERROR message\n");
trace_svcrdma_decode_drop(rdma_argp);
return 0;

out_proc:
dprintk("svcrdma: bad rdma procedure (%u)\n",
be32_to_cpup(rdma_argp + 3));
trace_svcrdma_decode_badproc(rdma_argp);
return -EINVAL;

out_inval:
dprintk("svcrdma: failed to parse transport header\n");
trace_svcrdma_decode_parse(rdma_argp);
return -EINVAL;
}

Expand Down Expand Up @@ -412,12 +408,16 @@ static void svc_rdma_send_error(struct svcxprt_rdma *xprt,
*p++ = *(rdma_argp + 1);
*p++ = xprt->sc_fc_credits;
*p++ = rdma_error;
if (status == -EPROTONOSUPPORT) {
switch (status) {
case -EPROTONOSUPPORT:
*p++ = err_vers;
*p++ = rpcrdma_version;
*p++ = rpcrdma_version;
} else {
trace_svcrdma_err_vers(*rdma_argp);
break;
default:
*p++ = err_chunk;
trace_svcrdma_err_chunk(*rdma_argp);
}
length = (unsigned long)p - (unsigned long)err_msgp;

Expand Down Expand Up @@ -532,8 +532,6 @@ int svc_rdma_recvfrom(struct svc_rqst *rqstp)
}
spin_unlock(&rdma_xprt->sc_rq_dto_lock);

dprintk("svcrdma: recvfrom: ctxt=%p on xprt=%p, rqstp=%p\n",
ctxt, rdma_xprt, rqstp);
atomic_inc(&rdma_stat_recv);

svc_rdma_build_arg_xdr(rqstp, ctxt);
Expand All @@ -559,8 +557,6 @@ int svc_rdma_recvfrom(struct svc_rqst *rqstp)

complete:
svc_rdma_put_context(ctxt, 0);
dprintk("svcrdma: recvfrom: xprt=%p, rqstp=%p, rq_arg.len=%u\n",
rdma_xprt, rqstp, rqstp->rq_arg.len);
rqstp->rq_prot = IPPROTO_MAX;
svc_xprt_copy_addrs(rqstp, xprt);
return rqstp->rq_arg.len;
Expand Down
Loading

0 comments on commit 98895ed

Please sign in to comment.