* [PATCH v4 0/7] Update RPC task pid as displayed by tracepoints
@ 2021-10-16 22:02 Chuck Lever
2021-10-16 22:02 ` [PATCH v4 1/7] SUNRPC: Tracepoints should display tk_pid and cl_clid as a fixed-size field Chuck Lever
` (6 more replies)
0 siblings, 7 replies; 13+ messages in thread
From: Chuck Lever @ 2021-10-16 22:02 UTC (permalink / raw)
To: trondmy; +Cc: linux-nfs
Reposting this series:
https://lore.kernel.org/linux-nfs/163345354511.524558.1980332041837428746.stgit@morisot.1015granger.net/
with the final patch in that series was updated as it was here:
https://lore.kernel.org/linux-nfs/163370502469.515303.12254136133220397877.stgit@morisot.1015granger.net/
Changes since v3:
- Repost entire series with updated 5/5
- Include two more tracepoint-related clean up patches
---
Chuck Lever (7):
SUNRPC: Tracepoints should display tk_pid and cl_clid as a fixed-size field
SUNRPC: Avoid NULL pointer dereferences in tracepoints
SUNRPC: Use BIT() macro in rpc_show_xprt_state()
SUNRPC: Don't dereference xprt->snd_task if it's a cookie
NFS: Replace dprintk callsites in nfs_readpage(s)
SUNRPC: Trace calls to .rpc_call_done
NFS: Remove --> and <-- dprintk call sites
fs/lockd/clntproc.c | 3 -
fs/lockd/svc4proc.c | 2 -
fs/lockd/svcproc.c | 2 -
fs/nfs/filelayout/filelayout.c | 2 -
fs/nfs/flexfilelayout/flexfilelayout.c | 2 -
fs/nfs/nfs4proc.c | 54 +-------
fs/nfs/nfs4trace.h | 17 +--
fs/nfs/nfstrace.h | 155 ++++++++++++++++++++-
fs/nfs/pagelist.c | 3 -
fs/nfs/read.c | 11 +-
fs/nfs/write.c | 3 -
include/trace/events/rpcgss.h | 36 ++---
include/trace/events/rpcrdma.h | 104 ++++++--------
include/trace/events/sunrpc.h | 183 +++++++++++--------------
include/trace/events/sunrpc_base.h | 42 ++++++
net/sunrpc/sched.c | 1 +
16 files changed, 351 insertions(+), 269 deletions(-)
create mode 100644 include/trace/events/sunrpc_base.h
--
Chuck Lever
^ permalink raw reply [flat|nested] 13+ messages in thread
* [PATCH v4 1/7] SUNRPC: Tracepoints should display tk_pid and cl_clid as a fixed-size field
2021-10-16 22:02 [PATCH v4 0/7] Update RPC task pid as displayed by tracepoints Chuck Lever
@ 2021-10-16 22:02 ` Chuck Lever
2021-10-16 22:02 ` [PATCH v4 2/7] SUNRPC: Avoid NULL pointer dereferences in tracepoints Chuck Lever
` (5 subsequent siblings)
6 siblings, 0 replies; 13+ messages in thread
From: Chuck Lever @ 2021-10-16 22:02 UTC (permalink / raw)
To: trondmy; +Cc: linux-nfs
For certain special cases, RPC-related tracepoints record a -1 as
the task ID or the client ID. It's ugly for a trace event to display
4 billion in these cases.
To help keep SUNRPC tracepoints consistent, create a macro that
defines the print format specifiers for tk_pid and cl_clid. At some
point in the future we might try tk_pid with a wider range of values
than 0..64K so this makes it easier to make that change.
RPC tracepoints now look like this:
<...>-1276 [009] 149.720358: rpc_clnt_new: client=00000005 peer=[192.168.2.55]:20049 program=nfs server=klimt.ib
<...>-1342 [004] 149.921234: rpc_xdr_recvfrom: task:0000001a@00000005 head=[0xff1242d9ab6dc01c,144] page=0 tail=[(nil),0] len=144
<...>-1342 [004] 149.921235: xprt_release_cong: task:0000001a@00000005 snd_task:ffffffff cong=256 cwnd=16384
<...>-1342 [004] 149.921235: xprt_put_cong: task:0000001a@00000005 snd_task:ffffffff cong=0 cwnd=16384
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
fs/nfs/nfs4trace.h | 9 ++--
fs/nfs/nfstrace.h | 6 ++-
include/trace/events/rpcgss.h | 18 ++++++---
include/trace/events/rpcrdma.h | 42 ++++++++++++--------
include/trace/events/sunrpc.h | 74 ++++++++++++++++++++++--------------
include/trace/events/sunrpc_base.h | 18 +++++++++
6 files changed, 108 insertions(+), 59 deletions(-)
create mode 100644 include/trace/events/sunrpc_base.h
diff --git a/fs/nfs/nfs4trace.h b/fs/nfs/nfs4trace.h
index 7a2567aa2b86..d4f061046c09 100644
--- a/fs/nfs/nfs4trace.h
+++ b/fs/nfs/nfs4trace.h
@@ -9,6 +9,7 @@
#define _TRACE_NFS4_H
#include <linux/tracepoint.h>
+#include <trace/events/sunrpc_base.h>
TRACE_DEFINE_ENUM(EPERM);
TRACE_DEFINE_ENUM(ENOENT);
@@ -694,8 +695,8 @@ TRACE_EVENT(nfs4_xdr_bad_operation,
__entry->expected = expected;
),
- TP_printk(
- "task:%u@%d xid=0x%08x operation=%u, expected=%u",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " xid=0x%08x operation=%u, expected=%u",
__entry->task_id, __entry->client_id, __entry->xid,
__entry->op, __entry->expected
)
@@ -729,8 +730,8 @@ DECLARE_EVENT_CLASS(nfs4_xdr_event,
__entry->error = error;
),
- TP_printk(
- "task:%u@%d xid=0x%08x error=%ld (%s) operation=%u",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " xid=0x%08x error=%ld (%s) operation=%u",
__entry->task_id, __entry->client_id, __entry->xid,
-__entry->error, show_nfsv4_errors(__entry->error),
__entry->op
diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
index 44fd016a8e65..82b51120450f 100644
--- a/fs/nfs/nfstrace.h
+++ b/fs/nfs/nfstrace.h
@@ -11,6 +11,8 @@
#include <linux/tracepoint.h>
#include <linux/iversion.h>
+#include <trace/events/sunrpc_base.h>
+
#define nfs_show_file_type(ftype) \
__print_symbolic(ftype, \
{ DT_UNKNOWN, "UNKNOWN" }, \
@@ -1409,8 +1411,8 @@ DECLARE_EVENT_CLASS(nfs_xdr_event,
__assign_str(procedure, task->tk_msg.rpc_proc->p_name);
),
- TP_printk(
- "task:%u@%d xid=0x%08x %sv%d %s error=%ld (%s)",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " xid=0x%08x %sv%d %s error=%ld (%s)",
__entry->task_id, __entry->client_id, __entry->xid,
__get_str(program), __entry->version,
__get_str(procedure), -__entry->error,
diff --git a/include/trace/events/rpcgss.h b/include/trace/events/rpcgss.h
index b2a2672e6632..3ba63319af3c 100644
--- a/include/trace/events/rpcgss.h
+++ b/include/trace/events/rpcgss.h
@@ -13,6 +13,8 @@
#include <linux/tracepoint.h>
+#include <trace/events/sunrpc_base.h>
+
/**
** GSS-API related trace events
**/
@@ -99,7 +101,7 @@ DECLARE_EVENT_CLASS(rpcgss_gssapi_event,
__entry->maj_stat = maj_stat;
),
- TP_printk("task:%u@%u maj_stat=%s",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " maj_stat=%s",
__entry->task_id, __entry->client_id,
__entry->maj_stat == 0 ?
"GSS_S_COMPLETE" : show_gss_status(__entry->maj_stat))
@@ -332,7 +334,8 @@ TRACE_EVENT(rpcgss_unwrap_failed,
__entry->client_id = task->tk_client->cl_clid;
),
- TP_printk("task:%u@%u", __entry->task_id, __entry->client_id)
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
+ __entry->task_id, __entry->client_id)
);
TRACE_EVENT(rpcgss_bad_seqno,
@@ -358,7 +361,8 @@ TRACE_EVENT(rpcgss_bad_seqno,
__entry->received = received;
),
- TP_printk("task:%u@%u expected seqno %u, received seqno %u",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " expected seqno %u, received seqno %u",
__entry->task_id, __entry->client_id,
__entry->expected, __entry->received)
);
@@ -386,7 +390,7 @@ TRACE_EVENT(rpcgss_seqno,
__entry->seqno = rqst->rq_seqno;
),
- TP_printk("task:%u@%u xid=0x%08x seqno=%u",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " xid=0x%08x seqno=%u",
__entry->task_id, __entry->client_id,
__entry->xid, __entry->seqno)
);
@@ -418,7 +422,8 @@ TRACE_EVENT(rpcgss_need_reencode,
__entry->ret = ret;
),
- TP_printk("task:%u@%u xid=0x%08x rq_seqno=%u seq_xmit=%u reencode %sneeded",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " xid=0x%08x rq_seqno=%u seq_xmit=%u reencode %sneeded",
__entry->task_id, __entry->client_id,
__entry->xid, __entry->seqno, __entry->seq_xmit,
__entry->ret ? "" : "un")
@@ -452,7 +457,8 @@ TRACE_EVENT(rpcgss_update_slack,
__entry->verfsize = auth->au_verfsize;
),
- TP_printk("task:%u@%u xid=0x%08x auth=%p rslack=%u ralign=%u verfsize=%u\n",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " xid=0x%08x auth=%p rslack=%u ralign=%u verfsize=%u\n",
__entry->task_id, __entry->client_id, __entry->xid,
__entry->auth, __entry->rslack, __entry->ralign,
__entry->verfsize)
diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index afb2e394797c..7f46ef621c95 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -14,7 +14,9 @@
#include <linux/sunrpc/rpc_rdma_cid.h>
#include <linux/tracepoint.h>
#include <rdma/ib_cm.h>
+
#include <trace/events/rdma.h>
+#include <trace/events/sunrpc_base.h>
/**
** Event classes
@@ -279,7 +281,8 @@ DECLARE_EVENT_CLASS(xprtrdma_rdch_event,
__entry->nsegs = nsegs;
),
- TP_printk("task:%u@%u pos=%u %u@0x%016llx:0x%08x (%s)",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " pos=%u %u@0x%016llx:0x%08x (%s)",
__entry->task_id, __entry->client_id,
__entry->pos, __entry->length,
(unsigned long long)__entry->offset, __entry->handle,
@@ -326,7 +329,8 @@ DECLARE_EVENT_CLASS(xprtrdma_wrch_event,
__entry->nsegs = nsegs;
),
- TP_printk("task:%u@%u %u@0x%016llx:0x%08x (%s)",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " %u@0x%016llx:0x%08x (%s)",
__entry->task_id, __entry->client_id,
__entry->length, (unsigned long long)__entry->offset,
__entry->handle,
@@ -393,7 +397,8 @@ DECLARE_EVENT_CLASS(xprtrdma_mr_class,
__entry->dir = mr->mr_dir;
),
- TP_printk("task:%u@%u mr.id=%u nents=%d %u@0x%016llx:0x%08x (%s)",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " mr.id=%u nents=%d %u@0x%016llx:0x%08x (%s)",
__entry->task_id, __entry->client_id,
__entry->mr_id, __entry->nents, __entry->length,
(unsigned long long)__entry->offset, __entry->handle,
@@ -636,9 +641,9 @@ TRACE_EVENT(xprtrdma_nomrs_err,
__assign_str(port, rpcrdma_portstr(r_xprt));
),
- TP_printk("peer=[%s]:%s task:%u@%u",
- __get_str(addr), __get_str(port),
- __entry->task_id, __entry->client_id
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " peer=[%s]:%s",
+ __entry->task_id, __entry->client_id,
+ __get_str(addr), __get_str(port)
)
);
@@ -700,7 +705,8 @@ TRACE_EVENT(xprtrdma_marshal,
__entry->wtype = wtype;
),
- TP_printk("task:%u@%u xid=0x%08x: hdr=%u xdr=%u/%u/%u %s/%s",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " xid=0x%08x hdr=%u xdr=%u/%u/%u %s/%s",
__entry->task_id, __entry->client_id, __entry->xid,
__entry->hdrlen,
__entry->headlen, __entry->pagelen, __entry->taillen,
@@ -730,7 +736,7 @@ TRACE_EVENT(xprtrdma_marshal_failed,
__entry->ret = ret;
),
- TP_printk("task:%u@%u xid=0x%08x: ret=%d",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " xid=0x%08x ret=%d",
__entry->task_id, __entry->client_id, __entry->xid,
__entry->ret
)
@@ -757,7 +763,7 @@ TRACE_EVENT(xprtrdma_prepsend_failed,
__entry->ret = ret;
),
- TP_printk("task:%u@%u xid=0x%08x: ret=%d",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " xid=0x%08x ret=%d",
__entry->task_id, __entry->client_id, __entry->xid,
__entry->ret
)
@@ -792,7 +798,7 @@ TRACE_EVENT(xprtrdma_post_send,
__entry->signaled = req->rl_wr.send_flags & IB_SEND_SIGNALED;
),
- TP_printk("task:%u@%u cq.id=%u cid=%d (%d SGE%s) %s",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " cq.id=%u cid=%d (%d SGE%s) %s",
__entry->task_id, __entry->client_id,
__entry->cq_id, __entry->completion_id,
__entry->num_sge, (__entry->num_sge == 1 ? "" : "s"),
@@ -827,7 +833,7 @@ TRACE_EVENT(xprtrdma_post_send_err,
__entry->rc = rc;
),
- TP_printk("task:%u@%u cq.id=%u rc=%d",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " cq.id=%u rc=%d",
__entry->task_id, __entry->client_id,
__entry->cq_id, __entry->rc
)
@@ -939,7 +945,7 @@ TRACE_EVENT(xprtrdma_post_linv_err,
__entry->status = status;
),
- TP_printk("task:%u@%u status=%d",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " status=%d",
__entry->task_id, __entry->client_id, __entry->status
)
);
@@ -1127,7 +1133,7 @@ TRACE_EVENT(xprtrdma_reply,
__entry->credits = credits;
),
- TP_printk("task:%u@%u xid=0x%08x credits=%u",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " xid=0x%08x credits=%u",
__entry->task_id, __entry->client_id, __entry->xid,
__entry->credits
)
@@ -1163,7 +1169,7 @@ TRACE_EVENT(xprtrdma_err_vers,
__entry->max = be32_to_cpup(max);
),
- TP_printk("task:%u@%u xid=0x%08x versions=[%u, %u]",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " xid=0x%08x versions=[%u, %u]",
__entry->task_id, __entry->client_id, __entry->xid,
__entry->min, __entry->max
)
@@ -1188,7 +1194,7 @@ TRACE_EVENT(xprtrdma_err_chunk,
__entry->xid = be32_to_cpu(rqst->rq_xid);
),
- TP_printk("task:%u@%u xid=0x%08x",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " xid=0x%08x",
__entry->task_id, __entry->client_id, __entry->xid
)
);
@@ -1214,7 +1220,7 @@ TRACE_EVENT(xprtrdma_err_unrecognized,
__entry->procedure = be32_to_cpup(procedure);
),
- TP_printk("task:%u@%u xid=0x%08x procedure=%u",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " xid=0x%08x procedure=%u",
__entry->task_id, __entry->client_id, __entry->xid,
__entry->procedure
)
@@ -1246,7 +1252,7 @@ TRACE_EVENT(xprtrdma_fixup,
__entry->taillen = rqst->rq_rcv_buf.tail[0].iov_len;
),
- TP_printk("task:%u@%u fixup=%lu xdr=%zu/%u/%zu",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " fixup=%lu xdr=%zu/%u/%zu",
__entry->task_id, __entry->client_id, __entry->fixup,
__entry->headlen, __entry->pagelen, __entry->taillen
)
@@ -1296,7 +1302,7 @@ TRACE_EVENT(xprtrdma_mrs_zap,
__entry->client_id = task->tk_client->cl_clid;
),
- TP_printk("task:%u@%u",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
__entry->task_id, __entry->client_id
)
);
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 2d04eb96d418..92def7d6663e 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -14,6 +14,8 @@
#include <linux/net.h>
#include <linux/tracepoint.h>
+#include <trace/events/sunrpc_base.h>
+
TRACE_DEFINE_ENUM(SOCK_STREAM);
TRACE_DEFINE_ENUM(SOCK_DGRAM);
TRACE_DEFINE_ENUM(SOCK_RAW);
@@ -78,7 +80,8 @@ DECLARE_EVENT_CLASS(rpc_xdr_buf_class,
__entry->msg_len = xdr->len;
),
- TP_printk("task:%u@%u head=[%p,%zu] page=%u tail=[%p,%zu] len=%u",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " head=[%p,%zu] page=%u tail=[%p,%zu] len=%u",
__entry->task_id, __entry->client_id,
__entry->head_base, __entry->head_len, __entry->page_len,
__entry->tail_base, __entry->tail_len, __entry->msg_len
@@ -114,7 +117,7 @@ DECLARE_EVENT_CLASS(rpc_clnt_class,
__entry->client_id = clnt->cl_clid;
),
- TP_printk("clid=%u", __entry->client_id)
+ TP_printk("client=" SUNRPC_TRACE_CLID_SPECIFIER, __entry->client_id)
);
#define DEFINE_RPC_CLNT_EVENT(name) \
@@ -158,7 +161,8 @@ TRACE_EVENT(rpc_clnt_new,
__assign_str(server, server);
),
- TP_printk("client=%u peer=[%s]:%s program=%s server=%s",
+ TP_printk("client=" SUNRPC_TRACE_CLID_SPECIFIER
+ " peer=[%s]:%s program=%s server=%s",
__entry->client_id, __get_str(addr), __get_str(port),
__get_str(program), __get_str(server))
);
@@ -206,7 +210,8 @@ TRACE_EVENT(rpc_clnt_clone_err,
__entry->error = error;
),
- TP_printk("client=%u error=%d", __entry->client_id, __entry->error)
+ TP_printk("client=" SUNRPC_TRACE_CLID_SPECIFIER " error=%d",
+ __entry->client_id, __entry->error)
);
@@ -248,7 +253,7 @@ DECLARE_EVENT_CLASS(rpc_task_status,
__entry->status = task->tk_status;
),
- TP_printk("task:%u@%u status=%d",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " status=%d",
__entry->task_id, __entry->client_id,
__entry->status)
);
@@ -288,7 +293,7 @@ TRACE_EVENT(rpc_request,
__assign_str(procname, rpc_proc_name(task));
),
- TP_printk("task:%u@%u %sv%d %s (%ssync)",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " %sv%d %s (%ssync)",
__entry->task_id, __entry->client_id,
__get_str(progname), __entry->version,
__get_str(procname), __entry->async ? "a": ""
@@ -348,7 +353,8 @@ DECLARE_EVENT_CLASS(rpc_task_running,
__entry->flags = task->tk_flags;
),
- TP_printk("task:%u@%d flags=%s runstate=%s status=%d action=%ps",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " flags=%s runstate=%s status=%d action=%ps",
__entry->task_id, __entry->client_id,
rpc_show_task_flags(__entry->flags),
rpc_show_runstate(__entry->runstate),
@@ -400,7 +406,8 @@ DECLARE_EVENT_CLASS(rpc_task_queued,
__assign_str(q_name, rpc_qname(q));
),
- TP_printk("task:%u@%d flags=%s runstate=%s status=%d timeout=%lu queue=%s",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " flags=%s runstate=%s status=%d timeout=%lu queue=%s",
__entry->task_id, __entry->client_id,
rpc_show_task_flags(__entry->flags),
rpc_show_runstate(__entry->runstate),
@@ -436,7 +443,7 @@ DECLARE_EVENT_CLASS(rpc_failure,
__entry->client_id = task->tk_client->cl_clid;
),
- TP_printk("task:%u@%u",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
__entry->task_id, __entry->client_id)
);
@@ -478,7 +485,8 @@ DECLARE_EVENT_CLASS(rpc_reply_event,
__assign_str(servername, task->tk_xprt->servername);
),
- TP_printk("task:%u@%d server=%s xid=0x%08x %sv%d %s",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " server=%s xid=0x%08x %sv%d %s",
__entry->task_id, __entry->client_id, __get_str(servername),
__entry->xid, __get_str(progname), __entry->version,
__get_str(procname))
@@ -538,7 +546,8 @@ TRACE_EVENT(rpc_buf_alloc,
__entry->status = status;
),
- TP_printk("task:%u@%u callsize=%zu recvsize=%zu status=%d",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " callsize=%zu recvsize=%zu status=%d",
__entry->task_id, __entry->client_id,
__entry->callsize, __entry->recvsize, __entry->status
)
@@ -567,7 +576,8 @@ TRACE_EVENT(rpc_call_rpcerror,
__entry->rpc_status = rpc_status;
),
- TP_printk("task:%u@%u tk_status=%d rpc_status=%d",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " tk_status=%d rpc_status=%d",
__entry->task_id, __entry->client_id,
__entry->tk_status, __entry->rpc_status)
);
@@ -607,7 +617,8 @@ TRACE_EVENT(rpc_stats_latency,
__entry->execute = ktime_to_us(execute);
),
- TP_printk("task:%u@%d xid=0x%08x %sv%d %s backlog=%lu rtt=%lu execute=%lu",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " xid=0x%08x %sv%d %s backlog=%lu rtt=%lu execute=%lu",
__entry->task_id, __entry->client_id, __entry->xid,
__get_str(progname), __entry->version, __get_str(procname),
__entry->backlog, __entry->rtt, __entry->execute)
@@ -651,8 +662,8 @@ TRACE_EVENT(rpc_xdr_overflow,
__entry->version = task->tk_client->cl_vers;
__assign_str(procedure, task->tk_msg.rpc_proc->p_name);
} else {
- __entry->task_id = 0;
- __entry->client_id = 0;
+ __entry->task_id = -1;
+ __entry->client_id = -1;
__assign_str(progname, "unknown");
__entry->version = 0;
__assign_str(procedure, "unknown");
@@ -668,8 +679,8 @@ TRACE_EVENT(rpc_xdr_overflow,
__entry->len = xdr->buf->len;
),
- TP_printk(
- "task:%u@%u %sv%d %s requested=%zu p=%p end=%p xdr=[%p,%zu]/%u/[%p,%zu]/%u\n",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " %sv%d %s requested=%zu p=%p end=%p xdr=[%p,%zu]/%u/[%p,%zu]/%u\n",
__entry->task_id, __entry->client_id,
__get_str(progname), __entry->version, __get_str(procedure),
__entry->requested, __entry->p, __entry->end,
@@ -727,8 +738,8 @@ TRACE_EVENT(rpc_xdr_alignment,
__entry->len = xdr->buf->len;
),
- TP_printk(
- "task:%u@%u %sv%d %s offset=%zu copied=%u xdr=[%p,%zu]/%u/[%p,%zu]/%u\n",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " %sv%d %s offset=%zu copied=%u xdr=[%p,%zu]/%u/[%p,%zu]/%u\n",
__entry->task_id, __entry->client_id,
__get_str(progname), __entry->version, __get_str(procedure),
__entry->offset, __entry->copied,
@@ -917,7 +928,8 @@ TRACE_EVENT(rpc_socket_nospace,
__entry->remaining = rqst->rq_slen - transport->xmit.offset;
),
- TP_printk("task:%u@%u total=%u remaining=%u",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " total=%u remaining=%u",
__entry->task_id, __entry->client_id,
__entry->total, __entry->remaining
)
@@ -1042,8 +1054,8 @@ TRACE_EVENT(xprt_transmit,
__entry->status = status;
),
- TP_printk(
- "task:%u@%u xid=0x%08x seqno=%u status=%d",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " xid=0x%08x seqno=%u status=%d",
__entry->task_id, __entry->client_id, __entry->xid,
__entry->seqno, __entry->status)
);
@@ -1082,8 +1094,8 @@ TRACE_EVENT(xprt_retransmit,
__assign_str(procname, rpc_proc_name(task));
),
- TP_printk(
- "task:%u@%u xid=0x%08x %sv%d %s ntrans=%d timeout=%lu",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " xid=0x%08x %sv%d %s ntrans=%d timeout=%lu",
__entry->task_id, __entry->client_id, __entry->xid,
__get_str(progname), __entry->version, __get_str(procname),
__entry->ntrans, __entry->timeout
@@ -1137,7 +1149,8 @@ DECLARE_EVENT_CLASS(xprt_writelock_event,
xprt->snd_task->tk_pid : -1;
),
- TP_printk("task:%u@%u snd_task:%u",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " snd_task:" SUNRPC_TRACE_PID_SPECIFIER,
__entry->task_id, __entry->client_id,
__entry->snd_task_id)
);
@@ -1185,7 +1198,9 @@ DECLARE_EVENT_CLASS(xprt_cong_event,
__entry->wait = test_bit(XPRT_CWND_WAIT, &xprt->state);
),
- TP_printk("task:%u@%u snd_task:%u cong=%lu cwnd=%lu%s",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " snd_task:" SUNRPC_TRACE_PID_SPECIFIER
+ " cong=%lu cwnd=%lu%s",
__entry->task_id, __entry->client_id,
__entry->snd_task_id, __entry->cong, __entry->cwnd,
__entry->wait ? " (wait)" : "")
@@ -1223,7 +1238,7 @@ TRACE_EVENT(xprt_reserve,
__entry->xid = be32_to_cpu(rqst->rq_xid);
),
- TP_printk("task:%u@%u xid=0x%08x",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " xid=0x%08x",
__entry->task_id, __entry->client_id, __entry->xid
)
);
@@ -1312,7 +1327,8 @@ TRACE_EVENT(rpcb_getport,
__assign_str(servername, task->tk_xprt->servername);
),
- TP_printk("task:%u@%u server=%s program=%u version=%u protocol=%d bind_version=%u",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
+ " server=%s program=%u version=%u protocol=%d bind_version=%u",
__entry->task_id, __entry->client_id, __get_str(servername),
__entry->program, __entry->version, __entry->protocol,
__entry->bind_version
@@ -1342,7 +1358,7 @@ TRACE_EVENT(rpcb_setport,
__entry->port = port;
),
- TP_printk("task:%u@%u status=%d port=%u",
+ TP_printk(SUNRPC_TRACE_TASK_SPECIFIER " status=%d port=%u",
__entry->task_id, __entry->client_id,
__entry->status, __entry->port
)
diff --git a/include/trace/events/sunrpc_base.h b/include/trace/events/sunrpc_base.h
new file mode 100644
index 000000000000..588557d07ea8
--- /dev/null
+++ b/include/trace/events/sunrpc_base.h
@@ -0,0 +1,18 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+/*
+ * Copyright (c) 2021 Oracle and/or its affiliates.
+ *
+ * Common types and format specifiers for sunrpc.
+ */
+
+#if !defined(_TRACE_SUNRPC_BASE_H)
+#define _TRACE_SUNRPC_BASE_H
+
+#include <linux/tracepoint.h>
+
+#define SUNRPC_TRACE_PID_SPECIFIER "%08x"
+#define SUNRPC_TRACE_CLID_SPECIFIER "%08x"
+#define SUNRPC_TRACE_TASK_SPECIFIER \
+ "task:" SUNRPC_TRACE_PID_SPECIFIER "@" SUNRPC_TRACE_CLID_SPECIFIER
+
+#endif /* _TRACE_SUNRPC_BASE_H */
^ permalink raw reply related [flat|nested] 13+ messages in thread
* [PATCH v4 2/7] SUNRPC: Avoid NULL pointer dereferences in tracepoints
2021-10-16 22:02 [PATCH v4 0/7] Update RPC task pid as displayed by tracepoints Chuck Lever
2021-10-16 22:02 ` [PATCH v4 1/7] SUNRPC: Tracepoints should display tk_pid and cl_clid as a fixed-size field Chuck Lever
@ 2021-10-16 22:02 ` Chuck Lever
2021-10-20 18:43 ` Trond Myklebust
2021-10-16 22:02 ` [PATCH v4 3/7] SUNRPC: Use BIT() macro in rpc_show_xprt_state() Chuck Lever
` (4 subsequent siblings)
6 siblings, 1 reply; 13+ messages in thread
From: Chuck Lever @ 2021-10-16 22:02 UTC (permalink / raw)
To: trondmy; +Cc: linux-nfs
On occasion, a NULL rpc_task pointer is passed into tracepoints.
We've open-coded a few places where this is expected, but let's
be defensive and protect every place that wants to dereference
a task to assign the tk_pid and cl_clid.
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
fs/nfs/nfs4trace.h | 8 +---
fs/nfs/nfstrace.h | 3 -
include/trace/events/rpcgss.h | 18 +++-----
include/trace/events/rpcrdma.h | 62 ++++++++---------------------
include/trace/events/sunrpc.h | 77 +++++++++---------------------------
include/trace/events/sunrpc_base.h | 15 +++++++
6 files changed, 61 insertions(+), 122 deletions(-)
diff --git a/fs/nfs/nfs4trace.h b/fs/nfs/nfs4trace.h
index d4f061046c09..66fbd3c33c15 100644
--- a/fs/nfs/nfs4trace.h
+++ b/fs/nfs/nfs4trace.h
@@ -686,10 +686,8 @@ TRACE_EVENT(nfs4_xdr_bad_operation,
TP_fast_assign(
const struct rpc_rqst *rqstp = xdr->rqst;
- const struct rpc_task *task = rqstp->rq_task;
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(rqstp->rq_task);
__entry->xid = be32_to_cpu(rqstp->rq_xid);
__entry->op = op;
__entry->expected = expected;
@@ -721,10 +719,8 @@ DECLARE_EVENT_CLASS(nfs4_xdr_event,
TP_fast_assign(
const struct rpc_rqst *rqstp = xdr->rqst;
- const struct rpc_task *task = rqstp->rq_task;
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(rqstp->rq_task);
__entry->xid = be32_to_cpu(rqstp->rq_xid);
__entry->op = op;
__entry->error = error;
diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
index 82b51120450f..e9be65b52bfe 100644
--- a/fs/nfs/nfstrace.h
+++ b/fs/nfs/nfstrace.h
@@ -1401,8 +1401,7 @@ DECLARE_EVENT_CLASS(nfs_xdr_event,
const struct rpc_rqst *rqstp = xdr->rqst;
const struct rpc_task *task = rqstp->rq_task;
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->xid = be32_to_cpu(rqstp->rq_xid);
__entry->version = task->tk_client->cl_vers;
__entry->error = error;
diff --git a/include/trace/events/rpcgss.h b/include/trace/events/rpcgss.h
index 3ba63319af3c..87b17ebd09c3 100644
--- a/include/trace/events/rpcgss.h
+++ b/include/trace/events/rpcgss.h
@@ -96,8 +96,7 @@ DECLARE_EVENT_CLASS(rpcgss_gssapi_event,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->maj_stat = maj_stat;
),
@@ -330,8 +329,7 @@ TRACE_EVENT(rpcgss_unwrap_failed,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
),
TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
@@ -355,8 +353,7 @@ TRACE_EVENT(rpcgss_bad_seqno,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->expected = expected;
__entry->received = received;
),
@@ -384,8 +381,7 @@ TRACE_EVENT(rpcgss_seqno,
TP_fast_assign(
const struct rpc_rqst *rqst = task->tk_rqstp;
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->xid = be32_to_cpu(rqst->rq_xid);
__entry->seqno = rqst->rq_seqno;
),
@@ -414,8 +410,7 @@ TRACE_EVENT(rpcgss_need_reencode,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
__entry->seq_xmit = seq_xmit;
__entry->seqno = task->tk_rqstp->rq_seqno;
@@ -448,8 +443,7 @@ TRACE_EVENT(rpcgss_update_slack,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
__entry->auth = auth;
__entry->rslack = auth->au_rslack;
diff --git a/include/trace/events/rpcrdma.h b/include/trace/events/rpcrdma.h
index 7f46ef621c95..c2ab9e5d775b 100644
--- a/include/trace/events/rpcrdma.h
+++ b/include/trace/events/rpcrdma.h
@@ -271,8 +271,7 @@ DECLARE_EVENT_CLASS(xprtrdma_rdch_event,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->pos = pos;
__entry->nents = mr->mr_nents;
__entry->handle = mr->mr_handle;
@@ -320,8 +319,7 @@ DECLARE_EVENT_CLASS(xprtrdma_wrch_event,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->nents = mr->mr_nents;
__entry->handle = mr->mr_handle;
__entry->length = mr->mr_length;
@@ -380,15 +378,8 @@ DECLARE_EVENT_CLASS(xprtrdma_mr_class,
TP_fast_assign(
const struct rpcrdma_req *req = mr->mr_req;
- if (req) {
- const struct rpc_task *task = req->rl_slot.rq_task;
-
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
- } else {
- __entry->task_id = 0;
- __entry->client_id = -1;
- }
+ if (req)
+ SUNRPC_TRACE_TASK_ASSIGN(req->rl_slot.rq_task);
__entry->mr_id = mr->mr_ibmr->res.id;
__entry->nents = mr->mr_nents;
__entry->handle = mr->mr_handle;
@@ -633,10 +624,7 @@ TRACE_EVENT(xprtrdma_nomrs_err,
),
TP_fast_assign(
- const struct rpc_rqst *rqst = &req->rl_slot;
-
- __entry->task_id = rqst->rq_task->tk_pid;
- __entry->client_id = rqst->rq_task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(req->rl_slot.rq_task);
__assign_str(addr, rpcrdma_addrstr(r_xprt));
__assign_str(port, rpcrdma_portstr(r_xprt));
),
@@ -694,8 +682,7 @@ TRACE_EVENT(xprtrdma_marshal,
TP_fast_assign(
const struct rpc_rqst *rqst = &req->rl_slot;
- __entry->task_id = rqst->rq_task->tk_pid;
- __entry->client_id = rqst->rq_task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
__entry->xid = be32_to_cpu(rqst->rq_xid);
__entry->hdrlen = req->rl_hdrbuf.len;
__entry->headlen = rqst->rq_snd_buf.head[0].iov_len;
@@ -730,8 +717,7 @@ TRACE_EVENT(xprtrdma_marshal_failed,
),
TP_fast_assign(
- __entry->task_id = rqst->rq_task->tk_pid;
- __entry->client_id = rqst->rq_task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
__entry->xid = be32_to_cpu(rqst->rq_xid);
__entry->ret = ret;
),
@@ -757,8 +743,7 @@ TRACE_EVENT(xprtrdma_prepsend_failed,
),
TP_fast_assign(
- __entry->task_id = rqst->rq_task->tk_pid;
- __entry->client_id = rqst->rq_task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
__entry->xid = be32_to_cpu(rqst->rq_xid);
__entry->ret = ret;
),
@@ -791,9 +776,7 @@ TRACE_EVENT(xprtrdma_post_send,
__entry->cq_id = sc->sc_cid.ci_queue_id;
__entry->completion_id = sc->sc_cid.ci_completion_id;
- __entry->task_id = rqst->rq_task->tk_pid;
- __entry->client_id = rqst->rq_task->tk_client ?
- rqst->rq_task->tk_client->cl_clid : -1;
+ SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
__entry->num_sge = req->rl_wr.num_sge;
__entry->signaled = req->rl_wr.send_flags & IB_SEND_SIGNALED;
),
@@ -827,9 +810,7 @@ TRACE_EVENT(xprtrdma_post_send_err,
const struct rpcrdma_ep *ep = r_xprt->rx_ep;
__entry->cq_id = ep ? ep->re_attr.recv_cq->res.id : 0;
- __entry->task_id = rqst->rq_task->tk_pid;
- __entry->client_id = rqst->rq_task->tk_client ?
- rqst->rq_task->tk_client->cl_clid : -1;
+ SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
__entry->rc = rc;
),
@@ -938,10 +919,7 @@ TRACE_EVENT(xprtrdma_post_linv_err,
),
TP_fast_assign(
- const struct rpc_task *task = req->rl_slot.rq_task;
-
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(req->rl_slot.rq_task);
__entry->status = status;
),
@@ -1127,8 +1105,7 @@ TRACE_EVENT(xprtrdma_reply,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->xid = be32_to_cpu(rep->rr_xid);
__entry->credits = credits;
),
@@ -1162,8 +1139,7 @@ TRACE_EVENT(xprtrdma_err_vers,
),
TP_fast_assign(
- __entry->task_id = rqst->rq_task->tk_pid;
- __entry->client_id = rqst->rq_task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
__entry->xid = be32_to_cpu(rqst->rq_xid);
__entry->min = be32_to_cpup(min);
__entry->max = be32_to_cpup(max);
@@ -1189,8 +1165,7 @@ TRACE_EVENT(xprtrdma_err_chunk,
),
TP_fast_assign(
- __entry->task_id = rqst->rq_task->tk_pid;
- __entry->client_id = rqst->rq_task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
__entry->xid = be32_to_cpu(rqst->rq_xid);
),
@@ -1215,8 +1190,7 @@ TRACE_EVENT(xprtrdma_err_unrecognized,
),
TP_fast_assign(
- __entry->task_id = rqst->rq_task->tk_pid;
- __entry->client_id = rqst->rq_task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
__entry->procedure = be32_to_cpup(procedure);
),
@@ -1244,8 +1218,7 @@ TRACE_EVENT(xprtrdma_fixup,
),
TP_fast_assign(
- __entry->task_id = rqst->rq_task->tk_pid;
- __entry->client_id = rqst->rq_task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
__entry->fixup = fixup;
__entry->headlen = rqst->rq_rcv_buf.head[0].iov_len;
__entry->pagelen = rqst->rq_rcv_buf.page_len;
@@ -1298,8 +1271,7 @@ TRACE_EVENT(xprtrdma_mrs_zap,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
),
TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 92def7d6663e..4fd6299bc907 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -69,9 +69,7 @@ DECLARE_EVENT_CLASS(rpc_xdr_buf_class,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client ?
- task->tk_client->cl_clid : -1;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->head_base = xdr->head[0].iov_base;
__entry->head_len = xdr->head[0].iov_len;
__entry->tail_base = xdr->tail[0].iov_base;
@@ -248,8 +246,7 @@ DECLARE_EVENT_CLASS(rpc_task_status,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->status = task->tk_status;
),
@@ -285,8 +282,7 @@ TRACE_EVENT(rpc_request,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->version = task->tk_client->cl_vers;
__entry->async = RPC_IS_ASYNC(task);
__assign_str(progname, task->tk_client->cl_program->name);
@@ -344,9 +340,7 @@ DECLARE_EVENT_CLASS(rpc_task_running,
),
TP_fast_assign(
- __entry->client_id = task->tk_client ?
- task->tk_client->cl_clid : -1;
- __entry->task_id = task->tk_pid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->action = action;
__entry->runstate = task->tk_runstate;
__entry->status = task->tk_status;
@@ -396,9 +390,7 @@ DECLARE_EVENT_CLASS(rpc_task_queued,
),
TP_fast_assign(
- __entry->client_id = task->tk_client ?
- task->tk_client->cl_clid : -1;
- __entry->task_id = task->tk_pid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->timeout = rpc_task_timeout(task);
__entry->runstate = task->tk_runstate;
__entry->status = task->tk_status;
@@ -439,8 +431,7 @@ DECLARE_EVENT_CLASS(rpc_failure,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
),
TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
@@ -476,8 +467,7 @@ DECLARE_EVENT_CLASS(rpc_reply_event,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
__assign_str(progname, task->tk_client->cl_program->name);
__entry->version = task->tk_client->cl_vers;
@@ -539,8 +529,7 @@ TRACE_EVENT(rpc_buf_alloc,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->callsize = task->tk_rqstp->rq_callsize;
__entry->recvsize = task->tk_rqstp->rq_rcvsize;
__entry->status = status;
@@ -570,8 +559,7 @@ TRACE_EVENT(rpc_call_rpcerror,
),
TP_fast_assign(
- __entry->client_id = task->tk_client->cl_clid;
- __entry->task_id = task->tk_pid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->tk_status = tk_status;
__entry->rpc_status = rpc_status;
),
@@ -606,8 +594,7 @@ TRACE_EVENT(rpc_stats_latency,
),
TP_fast_assign(
- __entry->client_id = task->tk_client->cl_clid;
- __entry->task_id = task->tk_pid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
__entry->version = task->tk_client->cl_vers;
__assign_str(progname, task->tk_client->cl_program->name);
@@ -655,8 +642,7 @@ TRACE_EVENT(rpc_xdr_overflow,
if (xdr->rqst) {
const struct rpc_task *task = xdr->rqst->rq_task;
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__assign_str(progname,
task->tk_client->cl_program->name);
__entry->version = task->tk_client->cl_vers;
@@ -721,8 +707,7 @@ TRACE_EVENT(rpc_xdr_alignment,
TP_fast_assign(
const struct rpc_task *task = xdr->rqst->rq_task;
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__assign_str(progname,
task->tk_client->cl_program->name);
__entry->version = task->tk_client->cl_vers;
@@ -922,8 +907,7 @@ TRACE_EVENT(rpc_socket_nospace,
),
TP_fast_assign(
- __entry->task_id = rqst->rq_task->tk_pid;
- __entry->client_id = rqst->rq_task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
__entry->total = rqst->rq_slen;
__entry->remaining = rqst->rq_slen - transport->xmit.offset;
),
@@ -1046,9 +1030,7 @@ TRACE_EVENT(xprt_transmit,
),
TP_fast_assign(
- __entry->task_id = rqst->rq_task->tk_pid;
- __entry->client_id = rqst->rq_task->tk_client ?
- rqst->rq_task->tk_client->cl_clid : -1;
+ SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
__entry->xid = be32_to_cpu(rqst->rq_xid);
__entry->seqno = rqst->rq_seqno;
__entry->status = status;
@@ -1082,9 +1064,7 @@ TRACE_EVENT(xprt_retransmit,
TP_fast_assign(
struct rpc_task *task = rqst->rq_task;
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client ?
- task->tk_client->cl_clid : -1;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->xid = be32_to_cpu(rqst->rq_xid);
__entry->ntrans = rqst->rq_ntrans;
__entry->timeout = task->tk_timeout;
@@ -1137,14 +1117,7 @@ DECLARE_EVENT_CLASS(xprt_writelock_event,
),
TP_fast_assign(
- if (task) {
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client ?
- task->tk_client->cl_clid : -1;
- } else {
- __entry->task_id = -1;
- __entry->client_id = -1;
- }
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->snd_task_id = xprt->snd_task ?
xprt->snd_task->tk_pid : -1;
),
@@ -1183,14 +1156,7 @@ DECLARE_EVENT_CLASS(xprt_cong_event,
),
TP_fast_assign(
- if (task) {
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client ?
- task->tk_client->cl_clid : -1;
- } else {
- __entry->task_id = -1;
- __entry->client_id = -1;
- }
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->snd_task_id = xprt->snd_task ?
xprt->snd_task->tk_pid : -1;
__entry->cong = xprt->cong;
@@ -1233,8 +1199,7 @@ TRACE_EVENT(xprt_reserve,
),
TP_fast_assign(
- __entry->task_id = rqst->rq_task->tk_pid;
- __entry->client_id = rqst->rq_task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
__entry->xid = be32_to_cpu(rqst->rq_xid);
),
@@ -1318,8 +1283,7 @@ TRACE_EVENT(rpcb_getport,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = clnt->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->program = clnt->cl_prog;
__entry->version = clnt->cl_vers;
__entry->protocol = task->tk_xprt->prot;
@@ -1352,8 +1316,7 @@ TRACE_EVENT(rpcb_setport,
),
TP_fast_assign(
- __entry->task_id = task->tk_pid;
- __entry->client_id = task->tk_client->cl_clid;
+ SUNRPC_TRACE_TASK_ASSIGN(task);
__entry->status = status;
__entry->port = port;
),
diff --git a/include/trace/events/sunrpc_base.h b/include/trace/events/sunrpc_base.h
index 588557d07ea8..2cbed4a9a63a 100644
--- a/include/trace/events/sunrpc_base.h
+++ b/include/trace/events/sunrpc_base.h
@@ -10,6 +10,21 @@
#include <linux/tracepoint.h>
+#define SUNRPC_TRACE_PID_SPECIAL (-1)
+
+#define SUNRPC_TRACE_TASK_ASSIGN(t) \
+ do { \
+ if ((t) != NULL) { \
+ __entry->task_id = (t)->tk_pid; \
+ __entry->client_id = (t)->tk_client ? \
+ (t)->tk_client->cl_clid : \
+ SUNRPC_TRACE_PID_SPECIAL; \
+ } else { \
+ __entry->task_id = SUNRPC_TRACE_PID_SPECIAL; \
+ __entry->client_id = SUNRPC_TRACE_PID_SPECIAL; \
+ } \
+ } while (0);
+
#define SUNRPC_TRACE_PID_SPECIFIER "%08x"
#define SUNRPC_TRACE_CLID_SPECIFIER "%08x"
#define SUNRPC_TRACE_TASK_SPECIFIER \
^ permalink raw reply related [flat|nested] 13+ messages in thread
* [PATCH v4 3/7] SUNRPC: Use BIT() macro in rpc_show_xprt_state()
2021-10-16 22:02 [PATCH v4 0/7] Update RPC task pid as displayed by tracepoints Chuck Lever
2021-10-16 22:02 ` [PATCH v4 1/7] SUNRPC: Tracepoints should display tk_pid and cl_clid as a fixed-size field Chuck Lever
2021-10-16 22:02 ` [PATCH v4 2/7] SUNRPC: Avoid NULL pointer dereferences in tracepoints Chuck Lever
@ 2021-10-16 22:02 ` Chuck Lever
2021-10-16 22:02 ` [PATCH v4 4/7] SUNRPC: Don't dereference xprt->snd_task if it's a cookie Chuck Lever
` (3 subsequent siblings)
6 siblings, 0 replies; 13+ messages in thread
From: Chuck Lever @ 2021-10-16 22:02 UTC (permalink / raw)
To: trondmy; +Cc: linux-nfs
Clean up: BIT() is preferred over open-coding the shift.
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
include/trace/events/sunrpc.h | 24 ++++++++++++------------
1 file changed, 12 insertions(+), 12 deletions(-)
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 4fd6299bc907..9caf4533366e 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -921,18 +921,18 @@ TRACE_EVENT(rpc_socket_nospace,
#define rpc_show_xprt_state(x) \
__print_flags(x, "|", \
- { (1UL << XPRT_LOCKED), "LOCKED"}, \
- { (1UL << XPRT_CONNECTED), "CONNECTED"}, \
- { (1UL << XPRT_CONNECTING), "CONNECTING"}, \
- { (1UL << XPRT_CLOSE_WAIT), "CLOSE_WAIT"}, \
- { (1UL << XPRT_BOUND), "BOUND"}, \
- { (1UL << XPRT_BINDING), "BINDING"}, \
- { (1UL << XPRT_CLOSING), "CLOSING"}, \
- { (1UL << XPRT_OFFLINE), "OFFLINE"}, \
- { (1UL << XPRT_REMOVE), "REMOVE"}, \
- { (1UL << XPRT_CONGESTED), "CONGESTED"}, \
- { (1UL << XPRT_CWND_WAIT), "CWND_WAIT"}, \
- { (1UL << XPRT_WRITE_SPACE), "WRITE_SPACE"})
+ { BIT(XPRT_LOCKED), "LOCKED" }, \
+ { BIT(XPRT_CONNECTED), "CONNECTED" }, \
+ { BIT(XPRT_CONNECTING), "CONNECTING" }, \
+ { BIT(XPRT_CLOSE_WAIT), "CLOSE_WAIT" }, \
+ { BIT(XPRT_BOUND), "BOUND" }, \
+ { BIT(XPRT_BINDING), "BINDING" }, \
+ { BIT(XPRT_CLOSING), "CLOSING" }, \
+ { BIT(XPRT_OFFLINE), "OFFLINE" }, \
+ { BIT(XPRT_REMOVE), "REMOVE" }, \
+ { BIT(XPRT_CONGESTED), "CONGESTED" }, \
+ { BIT(XPRT_CWND_WAIT), "CWND_WAIT" }, \
+ { BIT(XPRT_WRITE_SPACE), "WRITE_SPACE" })
DECLARE_EVENT_CLASS(rpc_xprt_lifetime_class,
TP_PROTO(
^ permalink raw reply related [flat|nested] 13+ messages in thread
* [PATCH v4 4/7] SUNRPC: Don't dereference xprt->snd_task if it's a cookie
2021-10-16 22:02 [PATCH v4 0/7] Update RPC task pid as displayed by tracepoints Chuck Lever
` (2 preceding siblings ...)
2021-10-16 22:02 ` [PATCH v4 3/7] SUNRPC: Use BIT() macro in rpc_show_xprt_state() Chuck Lever
@ 2021-10-16 22:02 ` Chuck Lever
2021-10-16 22:02 ` [PATCH v4 5/7] NFS: Replace dprintk callsites in nfs_readpage(s) Chuck Lever
` (2 subsequent siblings)
6 siblings, 0 replies; 13+ messages in thread
From: Chuck Lever @ 2021-10-16 22:02 UTC (permalink / raw)
To: trondmy; +Cc: linux-nfs
Fixes: e26d9972720e ("SUNRPC: Clean up scheduling of autoclose")
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
include/trace/events/sunrpc.h | 9 ++++-----
include/trace/events/sunrpc_base.h | 9 +++++++++
2 files changed, 13 insertions(+), 5 deletions(-)
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 9caf4533366e..83c2a1cb2e3a 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -932,7 +932,8 @@ TRACE_EVENT(rpc_socket_nospace,
{ BIT(XPRT_REMOVE), "REMOVE" }, \
{ BIT(XPRT_CONGESTED), "CONGESTED" }, \
{ BIT(XPRT_CWND_WAIT), "CWND_WAIT" }, \
- { BIT(XPRT_WRITE_SPACE), "WRITE_SPACE" })
+ { BIT(XPRT_WRITE_SPACE), "WRITE_SPACE" }, \
+ { BIT(XPRT_SND_IS_COOKIE), "SND_IS_COOKIE" })
DECLARE_EVENT_CLASS(rpc_xprt_lifetime_class,
TP_PROTO(
@@ -1118,8 +1119,7 @@ DECLARE_EVENT_CLASS(xprt_writelock_event,
TP_fast_assign(
SUNRPC_TRACE_TASK_ASSIGN(task);
- __entry->snd_task_id = xprt->snd_task ?
- xprt->snd_task->tk_pid : -1;
+ SUNRPC_TRACE_SNDTASK_ASSIGN(xprt);
),
TP_printk(SUNRPC_TRACE_TASK_SPECIFIER
@@ -1157,8 +1157,7 @@ DECLARE_EVENT_CLASS(xprt_cong_event,
TP_fast_assign(
SUNRPC_TRACE_TASK_ASSIGN(task);
- __entry->snd_task_id = xprt->snd_task ?
- xprt->snd_task->tk_pid : -1;
+ SUNRPC_TRACE_SNDTASK_ASSIGN(xprt);
__entry->cong = xprt->cong;
__entry->cwnd = xprt->cwnd;
__entry->wait = test_bit(XPRT_CWND_WAIT, &xprt->state);
diff --git a/include/trace/events/sunrpc_base.h b/include/trace/events/sunrpc_base.h
index 2cbed4a9a63a..abdffe4f53d6 100644
--- a/include/trace/events/sunrpc_base.h
+++ b/include/trace/events/sunrpc_base.h
@@ -25,6 +25,15 @@
} \
} while (0);
+#define SUNRPC_TRACE_SNDTASK_ASSIGN(x) \
+ do { \
+ if ((x)->snd_task && \
+ !test_bit(XPRT_SND_IS_COOKIE, &(x)->state)) \
+ __entry->snd_task_id = (x)->snd_task->tk_pid; \
+ else \
+ __entry->snd_task_id = SUNRPC_TRACE_PID_SPECIAL; \
+ } while(0);
+
#define SUNRPC_TRACE_PID_SPECIFIER "%08x"
#define SUNRPC_TRACE_CLID_SPECIFIER "%08x"
#define SUNRPC_TRACE_TASK_SPECIFIER \
^ permalink raw reply related [flat|nested] 13+ messages in thread
* [PATCH v4 5/7] NFS: Replace dprintk callsites in nfs_readpage(s)
2021-10-16 22:02 [PATCH v4 0/7] Update RPC task pid as displayed by tracepoints Chuck Lever
` (3 preceding siblings ...)
2021-10-16 22:02 ` [PATCH v4 4/7] SUNRPC: Don't dereference xprt->snd_task if it's a cookie Chuck Lever
@ 2021-10-16 22:02 ` Chuck Lever
2021-11-02 19:36 ` David Wysochanski
2021-10-16 22:02 ` [PATCH v4 6/7] SUNRPC: Trace calls to .rpc_call_done Chuck Lever
2021-10-16 22:03 ` [PATCH v4 7/7] NFS: Remove --> and <-- dprintk call sites Chuck Lever
6 siblings, 1 reply; 13+ messages in thread
From: Chuck Lever @ 2021-10-16 22:02 UTC (permalink / raw)
To: trondmy; +Cc: linux-nfs
These new events report slightly different information for readpage
and readpages/readahead.
For readpage:
fsx-1387 [006] 380.761896: nfs_aop_readpage: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355910932437 offset=131072
fsx-1387 [006] 380.761900: nfs_aop_readpage_done: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355910932437 offset=131072 ret=0
The index of a synchronous single-page read is reported.
For readpages:
fsx-1387 [006] 380.760847: nfs_aop_readahead: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355909932456 nr_pages=3
fsx-1387 [006] 380.760853: nfs_aop_readahead_done: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355909932456 nr_pages=3 ret=0
The count of pages requested is reported. nfs_readpages does not
wait for the READ requests to complete.
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
fs/nfs/nfstrace.h | 146 +++++++++++++++++++++++++++++++++++++++++++++++++++++
fs/nfs/read.c | 11 ++--
2 files changed, 151 insertions(+), 6 deletions(-)
diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
index e9be65b52bfe..898308780df8 100644
--- a/fs/nfs/nfstrace.h
+++ b/fs/nfs/nfstrace.h
@@ -862,6 +862,152 @@ TRACE_EVENT(nfs_sillyrename_unlink,
)
);
+TRACE_EVENT(nfs_aop_readpage,
+ TP_PROTO(
+ const struct inode *inode,
+ struct page *page
+ ),
+
+ TP_ARGS(inode, page),
+
+ TP_STRUCT__entry(
+ __field(dev_t, dev)
+ __field(u32, fhandle)
+ __field(u64, fileid)
+ __field(u64, version)
+ __field(loff_t, offset)
+ ),
+
+ TP_fast_assign(
+ const struct nfs_inode *nfsi = NFS_I(inode);
+
+ __entry->dev = inode->i_sb->s_dev;
+ __entry->fileid = nfsi->fileid;
+ __entry->fhandle = nfs_fhandle_hash(&nfsi->fh);
+ __entry->version = inode_peek_iversion_raw(inode);
+ __entry->offset = page_index(page) << PAGE_SHIFT;
+ ),
+
+ TP_printk(
+ "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu offset=%lld",
+ MAJOR(__entry->dev), MINOR(__entry->dev),
+ (unsigned long long)__entry->fileid,
+ __entry->fhandle, __entry->version,
+ __entry->offset
+ )
+);
+
+TRACE_EVENT(nfs_aop_readpage_done,
+ TP_PROTO(
+ const struct inode *inode,
+ struct page *page,
+ int ret
+ ),
+
+ TP_ARGS(inode, page, ret),
+
+ TP_STRUCT__entry(
+ __field(dev_t, dev)
+ __field(u32, fhandle)
+ __field(int, ret)
+ __field(u64, fileid)
+ __field(u64, version)
+ __field(loff_t, offset)
+ ),
+
+ TP_fast_assign(
+ const struct nfs_inode *nfsi = NFS_I(inode);
+
+ __entry->dev = inode->i_sb->s_dev;
+ __entry->fileid = nfsi->fileid;
+ __entry->fhandle = nfs_fhandle_hash(&nfsi->fh);
+ __entry->version = inode_peek_iversion_raw(inode);
+ __entry->offset = page_index(page) << PAGE_SHIFT;
+ __entry->ret = ret;
+ ),
+
+ TP_printk(
+ "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu offset=%lld ret=%d",
+ MAJOR(__entry->dev), MINOR(__entry->dev),
+ (unsigned long long)__entry->fileid,
+ __entry->fhandle, __entry->version,
+ __entry->offset, __entry->ret
+ )
+);
+
+TRACE_EVENT(nfs_aop_readahead,
+ TP_PROTO(
+ const struct inode *inode,
+ unsigned int nr_pages
+ ),
+
+ TP_ARGS(inode, nr_pages),
+
+ TP_STRUCT__entry(
+ __field(dev_t, dev)
+ __field(u32, fhandle)
+ __field(u64, fileid)
+ __field(u64, version)
+ __field(unsigned int, nr_pages)
+ ),
+
+ TP_fast_assign(
+ const struct nfs_inode *nfsi = NFS_I(inode);
+
+ __entry->dev = inode->i_sb->s_dev;
+ __entry->fileid = nfsi->fileid;
+ __entry->fhandle = nfs_fhandle_hash(&nfsi->fh);
+ __entry->version = inode_peek_iversion_raw(inode);
+ __entry->nr_pages = nr_pages;
+ ),
+
+ TP_printk(
+ "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu nr_pages=%u",
+ MAJOR(__entry->dev), MINOR(__entry->dev),
+ (unsigned long long)__entry->fileid,
+ __entry->fhandle, __entry->version,
+ __entry->nr_pages
+ )
+);
+
+TRACE_EVENT(nfs_aop_readahead_done,
+ TP_PROTO(
+ const struct inode *inode,
+ unsigned int nr_pages,
+ int ret
+ ),
+
+ TP_ARGS(inode, nr_pages, ret),
+
+ TP_STRUCT__entry(
+ __field(dev_t, dev)
+ __field(u32, fhandle)
+ __field(int, ret)
+ __field(u64, fileid)
+ __field(u64, version)
+ __field(unsigned int, nr_pages)
+ ),
+
+ TP_fast_assign(
+ const struct nfs_inode *nfsi = NFS_I(inode);
+
+ __entry->dev = inode->i_sb->s_dev;
+ __entry->fileid = nfsi->fileid;
+ __entry->fhandle = nfs_fhandle_hash(&nfsi->fh);
+ __entry->version = inode_peek_iversion_raw(inode);
+ __entry->nr_pages = nr_pages;
+ __entry->ret = ret;
+ ),
+
+ TP_printk(
+ "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu nr_pages=%u ret=%d",
+ MAJOR(__entry->dev), MINOR(__entry->dev),
+ (unsigned long long)__entry->fileid,
+ __entry->fhandle, __entry->version,
+ __entry->nr_pages, __entry->ret
+ )
+);
+
TRACE_EVENT(nfs_initiate_read,
TP_PROTO(
const struct nfs_pgio_header *hdr
diff --git a/fs/nfs/read.c b/fs/nfs/read.c
index 08d6cc57cbc3..c8273d4b12ad 100644
--- a/fs/nfs/read.c
+++ b/fs/nfs/read.c
@@ -337,8 +337,7 @@ int nfs_readpage(struct file *file, struct page *page)
struct inode *inode = page_file_mapping(page)->host;
int ret;
- dprintk("NFS: nfs_readpage (%p %ld@%lu)\n",
- page, PAGE_SIZE, page_index(page));
+ trace_nfs_aop_readpage(inode, page);
nfs_inc_stats(inode, NFSIOS_VFSREADPAGE);
/*
@@ -390,9 +389,11 @@ int nfs_readpage(struct file *file, struct page *page)
}
out:
put_nfs_open_context(desc.ctx);
+ trace_nfs_aop_readpage_done(inode, page, ret);
return ret;
out_unlock:
unlock_page(page);
+ trace_nfs_aop_readpage_done(inode, page, ret);
return ret;
}
@@ -403,10 +404,7 @@ int nfs_readpages(struct file *file, struct address_space *mapping,
struct inode *inode = mapping->host;
int ret;
- dprintk("NFS: nfs_readpages (%s/%Lu %d)\n",
- inode->i_sb->s_id,
- (unsigned long long)NFS_FILEID(inode),
- nr_pages);
+ trace_nfs_aop_readahead(inode, nr_pages);
nfs_inc_stats(inode, NFSIOS_VFSREADPAGES);
ret = -ESTALE;
@@ -439,6 +437,7 @@ int nfs_readpages(struct file *file, struct address_space *mapping,
read_complete:
put_nfs_open_context(desc.ctx);
out:
+ trace_nfs_aop_readahead_done(inode, nr_pages, ret);
return ret;
}
^ permalink raw reply related [flat|nested] 13+ messages in thread
* [PATCH v4 6/7] SUNRPC: Trace calls to .rpc_call_done
2021-10-16 22:02 [PATCH v4 0/7] Update RPC task pid as displayed by tracepoints Chuck Lever
` (4 preceding siblings ...)
2021-10-16 22:02 ` [PATCH v4 5/7] NFS: Replace dprintk callsites in nfs_readpage(s) Chuck Lever
@ 2021-10-16 22:02 ` Chuck Lever
2021-10-16 22:03 ` [PATCH v4 7/7] NFS: Remove --> and <-- dprintk call sites Chuck Lever
6 siblings, 0 replies; 13+ messages in thread
From: Chuck Lever @ 2021-10-16 22:02 UTC (permalink / raw)
To: trondmy; +Cc: linux-nfs
Introduce a single tracepoint that can replace simple dprintk call
sites in upper layer "rpc_call_done" callbacks. Example:
kworker/u24:2-1254 [001] 771.026677: rpc_stats_latency: task:00000001@00000002 xid=0x16a6f3c0 rpcbindv2 GETPORT backlog=446 rtt=101 execute=555
kworker/u24:2-1254 [001] 771.026677: rpc_task_call_done: task:00000001@00000002 flags=ASYNC|DYNAMIC|SOFT|SOFTCONN|SENT runstate=RUNNING|ACTIVE status=0 action=rpcb_getport_done
kworker/u24:2-1254 [001] 771.026678: rpcb_setport: task:00000001@00000002 status=0 port=20048
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
fs/lockd/clntproc.c | 3 ---
fs/lockd/svc4proc.c | 2 --
fs/lockd/svcproc.c | 2 --
fs/nfs/filelayout/filelayout.c | 2 --
fs/nfs/flexfilelayout/flexfilelayout.c | 2 --
fs/nfs/pagelist.c | 3 ---
fs/nfs/write.c | 3 ---
include/trace/events/sunrpc.h | 1 +
net/sunrpc/sched.c | 1 +
9 files changed, 2 insertions(+), 17 deletions(-)
diff --git a/fs/lockd/clntproc.c b/fs/lockd/clntproc.c
index b11f2afa84f1..99fffc9cb958 100644
--- a/fs/lockd/clntproc.c
+++ b/fs/lockd/clntproc.c
@@ -794,9 +794,6 @@ static void nlmclnt_cancel_callback(struct rpc_task *task, void *data)
goto retry_cancel;
}
- dprintk("lockd: cancel status %u (task %u)\n",
- status, task->tk_pid);
-
switch (status) {
case NLM_LCK_GRANTED:
case NLM_LCK_DENIED_GRACE_PERIOD:
diff --git a/fs/lockd/svc4proc.c b/fs/lockd/svc4proc.c
index e10ae2c41279..176b468a61c7 100644
--- a/fs/lockd/svc4proc.c
+++ b/fs/lockd/svc4proc.c
@@ -269,8 +269,6 @@ nlm4svc_proc_granted(struct svc_rqst *rqstp)
*/
static void nlm4svc_callback_exit(struct rpc_task *task, void *data)
{
- dprintk("lockd: %5u callback returned %d\n", task->tk_pid,
- -task->tk_status);
}
static void nlm4svc_callback_release(void *data)
diff --git a/fs/lockd/svcproc.c b/fs/lockd/svcproc.c
index 99696d3f6dd6..4dc1b40a489a 100644
--- a/fs/lockd/svcproc.c
+++ b/fs/lockd/svcproc.c
@@ -301,8 +301,6 @@ nlmsvc_proc_granted(struct svc_rqst *rqstp)
*/
static void nlmsvc_callback_exit(struct rpc_task *task, void *data)
{
- dprintk("lockd: %5u callback returned %d\n", task->tk_pid,
- -task->tk_status);
}
void nlmsvc_release_call(struct nlm_rqst *call)
diff --git a/fs/nfs/filelayout/filelayout.c b/fs/nfs/filelayout/filelayout.c
index d2103852475f..9c96e3e5ed35 100644
--- a/fs/nfs/filelayout/filelayout.c
+++ b/fs/nfs/filelayout/filelayout.c
@@ -293,8 +293,6 @@ static void filelayout_read_call_done(struct rpc_task *task, void *data)
{
struct nfs_pgio_header *hdr = data;
- dprintk("--> %s task->tk_status %d\n", __func__, task->tk_status);
-
if (test_bit(NFS_IOHDR_REDO, &hdr->flags) &&
task->tk_status == 0) {
nfs41_sequence_done(task, &hdr->res.seq_res);
diff --git a/fs/nfs/flexfilelayout/flexfilelayout.c b/fs/nfs/flexfilelayout/flexfilelayout.c
index d383de00d486..a553d59afa8b 100644
--- a/fs/nfs/flexfilelayout/flexfilelayout.c
+++ b/fs/nfs/flexfilelayout/flexfilelayout.c
@@ -1414,8 +1414,6 @@ static void ff_layout_read_call_done(struct rpc_task *task, void *data)
{
struct nfs_pgio_header *hdr = data;
- dprintk("--> %s task->tk_status %d\n", __func__, task->tk_status);
-
if (test_bit(NFS_IOHDR_REDO, &hdr->flags) &&
task->tk_status == 0) {
nfs4_sequence_done(task, &hdr->res.seq_res);
diff --git a/fs/nfs/pagelist.c b/fs/nfs/pagelist.c
index cc232d1f16f2..9cc057d40ef3 100644
--- a/fs/nfs/pagelist.c
+++ b/fs/nfs/pagelist.c
@@ -870,9 +870,6 @@ static void nfs_pgio_result(struct rpc_task *task, void *calldata)
struct nfs_pgio_header *hdr = calldata;
struct inode *inode = hdr->inode;
- dprintk("NFS: %s: %5u, (status %d)\n", __func__,
- task->tk_pid, task->tk_status);
-
if (hdr->rw_ops->rw_done(task, hdr, inode) != 0)
return;
if (task->tk_status < 0)
diff --git a/fs/nfs/write.c b/fs/nfs/write.c
index 1ded0d232ece..dedfdf7ad2ec 100644
--- a/fs/nfs/write.c
+++ b/fs/nfs/write.c
@@ -1836,9 +1836,6 @@ static void nfs_commit_done(struct rpc_task *task, void *calldata)
{
struct nfs_commit_data *data = calldata;
- dprintk("NFS: %5u nfs_commit_done (status %d)\n",
- task->tk_pid, task->tk_status);
-
/* Call the NFS version-specific code */
NFS_PROTO(data->inode)->commit_done(task, data);
trace_nfs_commit_done(task, data);
diff --git a/include/trace/events/sunrpc.h b/include/trace/events/sunrpc.h
index 83c2a1cb2e3a..2345bdfb30b0 100644
--- a/include/trace/events/sunrpc.h
+++ b/include/trace/events/sunrpc.h
@@ -372,6 +372,7 @@ DEFINE_RPC_RUNNING_EVENT(complete);
DEFINE_RPC_RUNNING_EVENT(timeout);
DEFINE_RPC_RUNNING_EVENT(signalled);
DEFINE_RPC_RUNNING_EVENT(end);
+DEFINE_RPC_RUNNING_EVENT(call_done);
DECLARE_EVENT_CLASS(rpc_task_queued,
diff --git a/net/sunrpc/sched.c b/net/sunrpc/sched.c
index b3402aeb8f30..34c71fa95c41 100644
--- a/net/sunrpc/sched.c
+++ b/net/sunrpc/sched.c
@@ -837,6 +837,7 @@ void rpc_exit_task(struct rpc_task *task)
else if (task->tk_client)
rpc_count_iostats(task, task->tk_client->cl_metrics);
if (task->tk_ops->rpc_call_done != NULL) {
+ trace_rpc_task_call_done(task, task->tk_ops->rpc_call_done);
task->tk_ops->rpc_call_done(task, task->tk_calldata);
if (task->tk_action != NULL) {
/* Always release the RPC slot and buffer memory */
^ permalink raw reply related [flat|nested] 13+ messages in thread
* [PATCH v4 7/7] NFS: Remove --> and <-- dprintk call sites
2021-10-16 22:02 [PATCH v4 0/7] Update RPC task pid as displayed by tracepoints Chuck Lever
` (5 preceding siblings ...)
2021-10-16 22:02 ` [PATCH v4 6/7] SUNRPC: Trace calls to .rpc_call_done Chuck Lever
@ 2021-10-16 22:03 ` Chuck Lever
6 siblings, 0 replies; 13+ messages in thread
From: Chuck Lever @ 2021-10-16 22:03 UTC (permalink / raw)
To: trondmy; +Cc: linux-nfs
dprintk call sites that display no other information than the
function name can be replaced with use of the trace "function" or
"function_graph" plug-ins.
Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
---
fs/nfs/nfs4proc.c | 54 +++++------------------------------------------------
1 file changed, 5 insertions(+), 49 deletions(-)
diff --git a/fs/nfs/nfs4proc.c b/fs/nfs/nfs4proc.c
index e1214bb6b7ee..1e51ed1167c8 100644
--- a/fs/nfs/nfs4proc.c
+++ b/fs/nfs/nfs4proc.c
@@ -3561,7 +3561,6 @@ static void nfs4_close_done(struct rpc_task *task, void *data)
.stateid = &calldata->arg.stateid,
};
- dprintk("%s: begin!\n", __func__);
if (!nfs4_sequence_done(task, &calldata->res.seq_res))
return;
trace_nfs4_close(state, &calldata->arg, &calldata->res, task->tk_status);
@@ -3616,7 +3615,7 @@ static void nfs4_close_done(struct rpc_task *task, void *data)
task->tk_status = 0;
nfs_release_seqid(calldata->arg.seqid);
nfs_refresh_inode(calldata->inode, &calldata->fattr);
- dprintk("%s: done, ret = %d!\n", __func__, task->tk_status);
+ dprintk("%s: ret = %d\n", __func__, task->tk_status);
return;
out_restart:
task->tk_status = 0;
@@ -3634,7 +3633,6 @@ static void nfs4_close_prepare(struct rpc_task *task, void *data)
bool is_rdonly, is_wronly, is_rdwr;
int call_close = 0;
- dprintk("%s: begin!\n", __func__);
if (nfs_wait_on_sequence(calldata->arg.seqid, task) != 0)
goto out_wait;
@@ -3708,7 +3706,6 @@ static void nfs4_close_prepare(struct rpc_task *task, void *data)
&calldata->res.seq_res,
task) != 0)
nfs_release_seqid(calldata->arg.seqid);
- dprintk("%s: done!\n", __func__);
return;
out_no_action:
task->tk_action = NULL;
@@ -5347,8 +5344,6 @@ static bool nfs4_read_plus_not_supported(struct rpc_task *task,
static int nfs4_read_done(struct rpc_task *task, struct nfs_pgio_header *hdr)
{
- dprintk("--> %s\n", __func__);
-
if (!nfs4_sequence_done(task, &hdr->res.seq_res))
return -EAGAIN;
if (nfs4_read_stateid_changed(task, &hdr->args))
@@ -7003,7 +6998,6 @@ static void nfs4_lock_prepare(struct rpc_task *task, void *calldata)
struct nfs4_lockdata *data = calldata;
struct nfs4_state *state = data->lsp->ls_state;
- dprintk("%s: begin!\n", __func__);
if (nfs_wait_on_sequence(data->arg.lock_seqid, task) != 0)
goto out_wait;
/* Do we need to do an open_to_lock_owner? */
@@ -7037,7 +7031,7 @@ static void nfs4_lock_prepare(struct rpc_task *task, void *calldata)
nfs_release_seqid(data->arg.lock_seqid);
out_wait:
nfs4_sequence_done(task, &data->res.seq_res);
- dprintk("%s: done!, ret = %d\n", __func__, data->rpc_status);
+ dprintk("%s: ret = %d\n", __func__, data->rpc_status);
}
static void nfs4_lock_done(struct rpc_task *task, void *calldata)
@@ -7045,8 +7039,6 @@ static void nfs4_lock_done(struct rpc_task *task, void *calldata)
struct nfs4_lockdata *data = calldata;
struct nfs4_lock_state *lsp = data->lsp;
- dprintk("%s: begin!\n", __func__);
-
if (!nfs4_sequence_done(task, &data->res.seq_res))
return;
@@ -7080,7 +7072,7 @@ static void nfs4_lock_done(struct rpc_task *task, void *calldata)
goto out_restart;
}
out_done:
- dprintk("%s: done, ret = %d!\n", __func__, data->rpc_status);
+ dprintk("%s: ret = %d!\n", __func__, data->rpc_status);
return;
out_restart:
if (!data->cancelled)
@@ -7092,7 +7084,6 @@ static void nfs4_lock_release(void *calldata)
{
struct nfs4_lockdata *data = calldata;
- dprintk("%s: begin!\n", __func__);
nfs_free_seqid(data->arg.open_seqid);
if (data->cancelled && data->rpc_status == 0) {
struct rpc_task *task;
@@ -7106,7 +7097,6 @@ static void nfs4_lock_release(void *calldata)
nfs4_put_lock_state(data->lsp);
put_nfs_open_context(data->ctx);
kfree(data);
- dprintk("%s: done!\n", __func__);
}
static const struct rpc_call_ops nfs4_lock_ops = {
@@ -7153,7 +7143,6 @@ static int _nfs4_do_setlk(struct nfs4_state *state, int cmd, struct file_lock *f
if (client->cl_minorversion)
task_setup_data.flags |= RPC_TASK_MOVEABLE;
- dprintk("%s: begin!\n", __func__);
data = nfs4_alloc_lockdata(fl, nfs_file_open_context(fl->fl_file),
fl->fl_u.nfs4_fl.owner,
recovery_type == NFS_LOCK_NEW ? GFP_KERNEL : GFP_NOFS);
@@ -7184,7 +7173,7 @@ static int _nfs4_do_setlk(struct nfs4_state *state, int cmd, struct file_lock *f
data->cancelled = true;
trace_nfs4_set_lock(fl, state, &data->res.stateid, cmd, ret);
rpc_put_task(task);
- dprintk("%s: done, ret = %d!\n", __func__, ret);
+ dprintk("%s: ret = %d\n", __func__, ret);
return ret;
}
@@ -8855,14 +8844,12 @@ static void nfs4_get_lease_time_prepare(struct rpc_task *task,
struct nfs4_get_lease_time_data *data =
(struct nfs4_get_lease_time_data *)calldata;
- dprintk("--> %s\n", __func__);
/* just setup sequence, do not trigger session recovery
since we're invoked within one */
nfs4_setup_sequence(data->clp,
&data->args->la_seq_args,
&data->res->lr_seq_res,
task);
- dprintk("<-- %s\n", __func__);
}
/*
@@ -8874,13 +8861,11 @@ static void nfs4_get_lease_time_done(struct rpc_task *task, void *calldata)
struct nfs4_get_lease_time_data *data =
(struct nfs4_get_lease_time_data *)calldata;
- dprintk("--> %s\n", __func__);
if (!nfs4_sequence_done(task, &data->res->lr_seq_res))
return;
switch (task->tk_status) {
case -NFS4ERR_DELAY:
case -NFS4ERR_GRACE:
- dprintk("%s Retry: tk_status %d\n", __func__, task->tk_status);
rpc_delay(task, NFS4_POLL_RETRY_MIN);
task->tk_status = 0;
fallthrough;
@@ -8888,7 +8873,6 @@ static void nfs4_get_lease_time_done(struct rpc_task *task, void *calldata)
rpc_restart_call_prepare(task);
return;
}
- dprintk("<-- %s\n", __func__);
}
static const struct rpc_call_ops nfs4_get_lease_time_ops = {
@@ -9120,7 +9104,6 @@ int nfs4_proc_create_session(struct nfs_client *clp, const struct cred *cred)
dprintk("%s client>seqid %d sessionid %u:%u:%u:%u\n", __func__,
clp->cl_seqid, ptr[0], ptr[1], ptr[2], ptr[3]);
out:
- dprintk("<-- %s\n", __func__);
return status;
}
@@ -9138,8 +9121,6 @@ int nfs4_proc_destroy_session(struct nfs4_session *session,
};
int status = 0;
- dprintk("--> nfs4_proc_destroy_session\n");
-
/* session is still being setup */
if (!test_and_clear_bit(NFS4_SESSION_ESTABLISHED, &session->session_state))
return 0;
@@ -9151,8 +9132,6 @@ int nfs4_proc_destroy_session(struct nfs4_session *session,
if (status)
dprintk("NFS: Got error %d from the server on DESTROY_SESSION. "
"Session has been destroyed regardless...\n", status);
-
- dprintk("<-- nfs4_proc_destroy_session\n");
return status;
}
@@ -9200,7 +9179,7 @@ static void nfs41_sequence_call_done(struct rpc_task *task, void *data)
if (task->tk_status < 0) {
dprintk("%s ERROR %d\n", __func__, task->tk_status);
if (refcount_read(&clp->cl_count) == 1)
- goto out;
+ return;
if (nfs41_sequence_handle_errors(task, clp) == -EAGAIN) {
rpc_restart_call_prepare(task);
@@ -9208,8 +9187,6 @@ static void nfs41_sequence_call_done(struct rpc_task *task, void *data)
}
}
dprintk("%s rpc_cred %p\n", __func__, task->tk_msg.rpc_cred);
-out:
- dprintk("<-- %s\n", __func__);
}
static void nfs41_sequence_prepare(struct rpc_task *task, void *data)
@@ -9356,7 +9333,6 @@ static void nfs4_reclaim_complete_done(struct rpc_task *task, void *data)
struct nfs_client *clp = calldata->clp;
struct nfs4_sequence_res *res = &calldata->res.seq_res;
- dprintk("--> %s\n", __func__);
if (!nfs41_sequence_done(task, res))
return;
@@ -9365,7 +9341,6 @@ static void nfs4_reclaim_complete_done(struct rpc_task *task, void *data)
rpc_restart_call_prepare(task);
return;
}
- dprintk("<-- %s\n", __func__);
}
static void nfs4_free_reclaim_complete_data(void *data)
@@ -9400,7 +9375,6 @@ static int nfs41_proc_reclaim_complete(struct nfs_client *clp,
};
int status = -ENOMEM;
- dprintk("--> %s\n", __func__);
calldata = kzalloc(sizeof(*calldata), GFP_NOFS);
if (calldata == NULL)
goto out;
@@ -9423,19 +9397,15 @@ nfs4_layoutget_prepare(struct rpc_task *task, void *calldata)
struct nfs4_layoutget *lgp = calldata;
struct nfs_server *server = NFS_SERVER(lgp->args.inode);
- dprintk("--> %s\n", __func__);
nfs4_setup_sequence(server->nfs_client, &lgp->args.seq_args,
&lgp->res.seq_res, task);
- dprintk("<-- %s\n", __func__);
}
static void nfs4_layoutget_done(struct rpc_task *task, void *calldata)
{
struct nfs4_layoutget *lgp = calldata;
- dprintk("--> %s\n", __func__);
nfs41_sequence_process(task, &lgp->res.seq_res);
- dprintk("<-- %s\n", __func__);
}
static int
@@ -9524,7 +9494,6 @@ nfs4_layoutget_handle_exception(struct rpc_task *task,
status = err;
}
out:
- dprintk("<-- %s\n", __func__);
return status;
}
@@ -9538,10 +9507,8 @@ static void nfs4_layoutget_release(void *calldata)
{
struct nfs4_layoutget *lgp = calldata;
- dprintk("--> %s\n", __func__);
nfs4_sequence_free_slot(&lgp->res.seq_res);
pnfs_layoutget_free(lgp);
- dprintk("<-- %s\n", __func__);
}
static const struct rpc_call_ops nfs4_layoutget_call_ops = {
@@ -9577,8 +9544,6 @@ nfs4_proc_layoutget(struct nfs4_layoutget *lgp, long *timeout)
};
int status = 0;
- dprintk("--> %s\n", __func__);
-
nfs4_init_sequence(&lgp->args.seq_args, &lgp->res.seq_res, 0, 0);
task = rpc_run_task(&task_setup_data);
@@ -9614,7 +9579,6 @@ nfs4_layoutreturn_prepare(struct rpc_task *task, void *calldata)
{
struct nfs4_layoutreturn *lrp = calldata;
- dprintk("--> %s\n", __func__);
nfs4_setup_sequence(lrp->clp,
&lrp->args.seq_args,
&lrp->res.seq_res,
@@ -9628,8 +9592,6 @@ static void nfs4_layoutreturn_done(struct rpc_task *task, void *calldata)
struct nfs4_layoutreturn *lrp = calldata;
struct nfs_server *server;
- dprintk("--> %s\n", __func__);
-
if (!nfs41_sequence_process(task, &lrp->res.seq_res))
return;
@@ -9660,7 +9622,6 @@ static void nfs4_layoutreturn_done(struct rpc_task *task, void *calldata)
break;
goto out_restart;
}
- dprintk("<-- %s\n", __func__);
return;
out_restart:
task->tk_status = 0;
@@ -9673,7 +9634,6 @@ static void nfs4_layoutreturn_release(void *calldata)
struct nfs4_layoutreturn *lrp = calldata;
struct pnfs_layout_hdr *lo = lrp->args.layout;
- dprintk("--> %s\n", __func__);
pnfs_layoutreturn_free_lsegs(lo, &lrp->args.stateid, &lrp->args.range,
lrp->res.lrs_present ? &lrp->res.stateid : NULL);
nfs4_sequence_free_slot(&lrp->res.seq_res);
@@ -9683,7 +9643,6 @@ static void nfs4_layoutreturn_release(void *calldata)
nfs_iput_and_deactive(lrp->inode);
put_cred(lrp->cred);
kfree(calldata);
- dprintk("<-- %s\n", __func__);
}
static const struct rpc_call_ops nfs4_layoutreturn_call_ops = {
@@ -9714,7 +9673,6 @@ int nfs4_proc_layoutreturn(struct nfs4_layoutreturn *lrp, bool sync)
NFS_SP4_MACH_CRED_PNFS_CLEANUP,
&task_setup_data.rpc_client, &msg);
- dprintk("--> %s\n", __func__);
lrp->inode = nfs_igrab_and_active(lrp->args.inode);
if (!sync) {
if (!lrp->inode) {
@@ -9761,7 +9719,6 @@ _nfs4_proc_getdeviceinfo(struct nfs_server *server,
};
int status;
- dprintk("--> %s\n", __func__);
status = nfs4_call_sync(server->client, server, &msg, &args.seq_args, &res.seq_res, 0);
if (res.notification & ~args.notify_types)
dprintk("%s: unsupported notification\n", __func__);
@@ -9933,7 +9890,6 @@ _nfs41_proc_secinfo_no_name(struct nfs_server *server, struct nfs_fh *fhandle,
msg.rpc_cred = cred;
}
- dprintk("--> %s\n", __func__);
nfs4_init_sequence(&args.seq_args, &res.seq_res, 0, 0);
status = nfs4_call_sync_custom(&task_setup);
dprintk("<-- %s status=%d\n", __func__, status);
^ permalink raw reply related [flat|nested] 13+ messages in thread
* Re: [PATCH v4 2/7] SUNRPC: Avoid NULL pointer dereferences in tracepoints
2021-10-16 22:02 ` [PATCH v4 2/7] SUNRPC: Avoid NULL pointer dereferences in tracepoints Chuck Lever
@ 2021-10-20 18:43 ` Trond Myklebust
2021-10-20 19:39 ` Chuck Lever III
0 siblings, 1 reply; 13+ messages in thread
From: Trond Myklebust @ 2021-10-20 18:43 UTC (permalink / raw)
To: chuck.lever; +Cc: linux-nfs
On Sat, 2021-10-16 at 18:02 -0400, Chuck Lever wrote:
> On occasion, a NULL rpc_task pointer is passed into tracepoints.
> We've open-coded a few places where this is expected, but let's
> be defensive and protect every place that wants to dereference
> a task to assign the tk_pid and cl_clid.
>
No, I won't apply this.
This patch is going to lead to a bunch of static checkers complaining
that we're checking 'task' for NULL after we've already dereferenced it
in the same function, and/or complaining that we're dereferencing a
value that might be null because we just had a check for it.
Even within the macros touched by this patch, we have instances of the
latter occurring, where we read task->tk_client->cl_vers (and other
fields) immediately after we just declared that we had to check both
task and task->tk_client for NULL.
> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> ---
> fs/nfs/nfs4trace.h | 8 +---
> fs/nfs/nfstrace.h | 3 -
> include/trace/events/rpcgss.h | 18 +++-----
> include/trace/events/rpcrdma.h | 62 ++++++++------------------
> ---
> include/trace/events/sunrpc.h | 77 +++++++++-----------------
> ----------
> include/trace/events/sunrpc_base.h | 15 +++++++
> 6 files changed, 61 insertions(+), 122 deletions(-)
>
> diff --git a/fs/nfs/nfs4trace.h b/fs/nfs/nfs4trace.h
> index d4f061046c09..66fbd3c33c15 100644
> --- a/fs/nfs/nfs4trace.h
> +++ b/fs/nfs/nfs4trace.h
> @@ -686,10 +686,8 @@ TRACE_EVENT(nfs4_xdr_bad_operation,
>
> TP_fast_assign(
> const struct rpc_rqst *rqstp = xdr->rqst;
> - const struct rpc_task *task = rqstp->rq_task;
>
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(rqstp->rq_task);
> __entry->xid = be32_to_cpu(rqstp->rq_xid);
> __entry->op = op;
> __entry->expected = expected;
> @@ -721,10 +719,8 @@ DECLARE_EVENT_CLASS(nfs4_xdr_event,
>
> TP_fast_assign(
> const struct rpc_rqst *rqstp = xdr->rqst;
> - const struct rpc_task *task = rqstp->rq_task;
>
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(rqstp->rq_task);
> __entry->xid = be32_to_cpu(rqstp->rq_xid);
> __entry->op = op;
> __entry->error = error;
> diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
> index 82b51120450f..e9be65b52bfe 100644
> --- a/fs/nfs/nfstrace.h
> +++ b/fs/nfs/nfstrace.h
> @@ -1401,8 +1401,7 @@ DECLARE_EVENT_CLASS(nfs_xdr_event,
> const struct rpc_rqst *rqstp = xdr->rqst;
> const struct rpc_task *task = rqstp->rq_task;
>
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->xid = be32_to_cpu(rqstp->rq_xid);
> __entry->version = task->tk_client->cl_vers;
> __entry->error = error;
> diff --git a/include/trace/events/rpcgss.h
> b/include/trace/events/rpcgss.h
> index 3ba63319af3c..87b17ebd09c3 100644
> --- a/include/trace/events/rpcgss.h
> +++ b/include/trace/events/rpcgss.h
> @@ -96,8 +96,7 @@ DECLARE_EVENT_CLASS(rpcgss_gssapi_event,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->maj_stat = maj_stat;
> ),
>
> @@ -330,8 +329,7 @@ TRACE_EVENT(rpcgss_unwrap_failed,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> ),
>
> TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
> @@ -355,8 +353,7 @@ TRACE_EVENT(rpcgss_bad_seqno,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->expected = expected;
> __entry->received = received;
> ),
> @@ -384,8 +381,7 @@ TRACE_EVENT(rpcgss_seqno,
> TP_fast_assign(
> const struct rpc_rqst *rqst = task->tk_rqstp;
>
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->xid = be32_to_cpu(rqst->rq_xid);
> __entry->seqno = rqst->rq_seqno;
> ),
> @@ -414,8 +410,7 @@ TRACE_EVENT(rpcgss_need_reencode,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
> __entry->seq_xmit = seq_xmit;
> __entry->seqno = task->tk_rqstp->rq_seqno;
> @@ -448,8 +443,7 @@ TRACE_EVENT(rpcgss_update_slack,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
> __entry->auth = auth;
> __entry->rslack = auth->au_rslack;
> diff --git a/include/trace/events/rpcrdma.h
> b/include/trace/events/rpcrdma.h
> index 7f46ef621c95..c2ab9e5d775b 100644
> --- a/include/trace/events/rpcrdma.h
> +++ b/include/trace/events/rpcrdma.h
> @@ -271,8 +271,7 @@ DECLARE_EVENT_CLASS(xprtrdma_rdch_event,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->pos = pos;
> __entry->nents = mr->mr_nents;
> __entry->handle = mr->mr_handle;
> @@ -320,8 +319,7 @@ DECLARE_EVENT_CLASS(xprtrdma_wrch_event,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->nents = mr->mr_nents;
> __entry->handle = mr->mr_handle;
> __entry->length = mr->mr_length;
> @@ -380,15 +378,8 @@ DECLARE_EVENT_CLASS(xprtrdma_mr_class,
> TP_fast_assign(
> const struct rpcrdma_req *req = mr->mr_req;
>
> - if (req) {
> - const struct rpc_task *task = req-
> >rl_slot.rq_task;
> -
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client-
> >cl_clid;
> - } else {
> - __entry->task_id = 0;
> - __entry->client_id = -1;
> - }
> + if (req)
> + SUNRPC_TRACE_TASK_ASSIGN(req-
> >rl_slot.rq_task);
> __entry->mr_id = mr->mr_ibmr->res.id;
> __entry->nents = mr->mr_nents;
> __entry->handle = mr->mr_handle;
> @@ -633,10 +624,7 @@ TRACE_EVENT(xprtrdma_nomrs_err,
> ),
>
> TP_fast_assign(
> - const struct rpc_rqst *rqst = &req->rl_slot;
> -
> - __entry->task_id = rqst->rq_task->tk_pid;
> - __entry->client_id = rqst->rq_task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(req->rl_slot.rq_task);
> __assign_str(addr, rpcrdma_addrstr(r_xprt));
> __assign_str(port, rpcrdma_portstr(r_xprt));
> ),
> @@ -694,8 +682,7 @@ TRACE_EVENT(xprtrdma_marshal,
> TP_fast_assign(
> const struct rpc_rqst *rqst = &req->rl_slot;
>
> - __entry->task_id = rqst->rq_task->tk_pid;
> - __entry->client_id = rqst->rq_task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> __entry->xid = be32_to_cpu(rqst->rq_xid);
> __entry->hdrlen = req->rl_hdrbuf.len;
> __entry->headlen = rqst->rq_snd_buf.head[0].iov_len;
> @@ -730,8 +717,7 @@ TRACE_EVENT(xprtrdma_marshal_failed,
> ),
>
> TP_fast_assign(
> - __entry->task_id = rqst->rq_task->tk_pid;
> - __entry->client_id = rqst->rq_task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> __entry->xid = be32_to_cpu(rqst->rq_xid);
> __entry->ret = ret;
> ),
> @@ -757,8 +743,7 @@ TRACE_EVENT(xprtrdma_prepsend_failed,
> ),
>
> TP_fast_assign(
> - __entry->task_id = rqst->rq_task->tk_pid;
> - __entry->client_id = rqst->rq_task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> __entry->xid = be32_to_cpu(rqst->rq_xid);
> __entry->ret = ret;
> ),
> @@ -791,9 +776,7 @@ TRACE_EVENT(xprtrdma_post_send,
>
> __entry->cq_id = sc->sc_cid.ci_queue_id;
> __entry->completion_id = sc->sc_cid.ci_completion_id;
> - __entry->task_id = rqst->rq_task->tk_pid;
> - __entry->client_id = rqst->rq_task->tk_client ?
> - rqst->rq_task->tk_client-
> >cl_clid : -1;
> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> __entry->num_sge = req->rl_wr.num_sge;
> __entry->signaled = req->rl_wr.send_flags &
> IB_SEND_SIGNALED;
> ),
> @@ -827,9 +810,7 @@ TRACE_EVENT(xprtrdma_post_send_err,
> const struct rpcrdma_ep *ep = r_xprt->rx_ep;
>
> __entry->cq_id = ep ? ep->re_attr.recv_cq->res.id :
> 0;
> - __entry->task_id = rqst->rq_task->tk_pid;
> - __entry->client_id = rqst->rq_task->tk_client ?
> - rqst->rq_task->tk_client-
> >cl_clid : -1;
> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> __entry->rc = rc;
> ),
>
> @@ -938,10 +919,7 @@ TRACE_EVENT(xprtrdma_post_linv_err,
> ),
>
> TP_fast_assign(
> - const struct rpc_task *task = req->rl_slot.rq_task;
> -
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(req->rl_slot.rq_task);
> __entry->status = status;
> ),
>
> @@ -1127,8 +1105,7 @@ TRACE_EVENT(xprtrdma_reply,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->xid = be32_to_cpu(rep->rr_xid);
> __entry->credits = credits;
> ),
> @@ -1162,8 +1139,7 @@ TRACE_EVENT(xprtrdma_err_vers,
> ),
>
> TP_fast_assign(
> - __entry->task_id = rqst->rq_task->tk_pid;
> - __entry->client_id = rqst->rq_task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> __entry->xid = be32_to_cpu(rqst->rq_xid);
> __entry->min = be32_to_cpup(min);
> __entry->max = be32_to_cpup(max);
> @@ -1189,8 +1165,7 @@ TRACE_EVENT(xprtrdma_err_chunk,
> ),
>
> TP_fast_assign(
> - __entry->task_id = rqst->rq_task->tk_pid;
> - __entry->client_id = rqst->rq_task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> __entry->xid = be32_to_cpu(rqst->rq_xid);
> ),
>
> @@ -1215,8 +1190,7 @@ TRACE_EVENT(xprtrdma_err_unrecognized,
> ),
>
> TP_fast_assign(
> - __entry->task_id = rqst->rq_task->tk_pid;
> - __entry->client_id = rqst->rq_task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> __entry->procedure = be32_to_cpup(procedure);
> ),
>
> @@ -1244,8 +1218,7 @@ TRACE_EVENT(xprtrdma_fixup,
> ),
>
> TP_fast_assign(
> - __entry->task_id = rqst->rq_task->tk_pid;
> - __entry->client_id = rqst->rq_task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> __entry->fixup = fixup;
> __entry->headlen = rqst->rq_rcv_buf.head[0].iov_len;
> __entry->pagelen = rqst->rq_rcv_buf.page_len;
> @@ -1298,8 +1271,7 @@ TRACE_EVENT(xprtrdma_mrs_zap,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> ),
>
> TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
> diff --git a/include/trace/events/sunrpc.h
> b/include/trace/events/sunrpc.h
> index 92def7d6663e..4fd6299bc907 100644
> --- a/include/trace/events/sunrpc.h
> +++ b/include/trace/events/sunrpc.h
> @@ -69,9 +69,7 @@ DECLARE_EVENT_CLASS(rpc_xdr_buf_class,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client ?
> - task->tk_client->cl_clid : -1;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->head_base = xdr->head[0].iov_base;
> __entry->head_len = xdr->head[0].iov_len;
> __entry->tail_base = xdr->tail[0].iov_base;
> @@ -248,8 +246,7 @@ DECLARE_EVENT_CLASS(rpc_task_status,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->status = task->tk_status;
> ),
>
> @@ -285,8 +282,7 @@ TRACE_EVENT(rpc_request,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->version = task->tk_client->cl_vers;
> __entry->async = RPC_IS_ASYNC(task);
> __assign_str(progname, task->tk_client->cl_program-
> >name);
> @@ -344,9 +340,7 @@ DECLARE_EVENT_CLASS(rpc_task_running,
> ),
>
> TP_fast_assign(
> - __entry->client_id = task->tk_client ?
> - task->tk_client->cl_clid : -1;
> - __entry->task_id = task->tk_pid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->action = action;
> __entry->runstate = task->tk_runstate;
> __entry->status = task->tk_status;
> @@ -396,9 +390,7 @@ DECLARE_EVENT_CLASS(rpc_task_queued,
> ),
>
> TP_fast_assign(
> - __entry->client_id = task->tk_client ?
> - task->tk_client->cl_clid : -1;
> - __entry->task_id = task->tk_pid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->timeout = rpc_task_timeout(task);
> __entry->runstate = task->tk_runstate;
> __entry->status = task->tk_status;
> @@ -439,8 +431,7 @@ DECLARE_EVENT_CLASS(rpc_failure,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> ),
>
> TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
> @@ -476,8 +467,7 @@ DECLARE_EVENT_CLASS(rpc_reply_event,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
> __assign_str(progname, task->tk_client->cl_program-
> >name);
> __entry->version = task->tk_client->cl_vers;
> @@ -539,8 +529,7 @@ TRACE_EVENT(rpc_buf_alloc,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->callsize = task->tk_rqstp->rq_callsize;
> __entry->recvsize = task->tk_rqstp->rq_rcvsize;
> __entry->status = status;
> @@ -570,8 +559,7 @@ TRACE_EVENT(rpc_call_rpcerror,
> ),
>
> TP_fast_assign(
> - __entry->client_id = task->tk_client->cl_clid;
> - __entry->task_id = task->tk_pid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->tk_status = tk_status;
> __entry->rpc_status = rpc_status;
> ),
> @@ -606,8 +594,7 @@ TRACE_EVENT(rpc_stats_latency,
> ),
>
> TP_fast_assign(
> - __entry->client_id = task->tk_client->cl_clid;
> - __entry->task_id = task->tk_pid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
> __entry->version = task->tk_client->cl_vers;
> __assign_str(progname, task->tk_client->cl_program-
> >name);
> @@ -655,8 +642,7 @@ TRACE_EVENT(rpc_xdr_overflow,
> if (xdr->rqst) {
> const struct rpc_task *task = xdr->rqst-
> >rq_task;
>
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __assign_str(progname,
> task->tk_client->cl_program-
> >name);
> __entry->version = task->tk_client->cl_vers;
> @@ -721,8 +707,7 @@ TRACE_EVENT(rpc_xdr_alignment,
> TP_fast_assign(
> const struct rpc_task *task = xdr->rqst->rq_task;
>
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __assign_str(progname,
> task->tk_client->cl_program->name);
> __entry->version = task->tk_client->cl_vers;
> @@ -922,8 +907,7 @@ TRACE_EVENT(rpc_socket_nospace,
> ),
>
> TP_fast_assign(
> - __entry->task_id = rqst->rq_task->tk_pid;
> - __entry->client_id = rqst->rq_task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> __entry->total = rqst->rq_slen;
> __entry->remaining = rqst->rq_slen - transport-
> >xmit.offset;
> ),
> @@ -1046,9 +1030,7 @@ TRACE_EVENT(xprt_transmit,
> ),
>
> TP_fast_assign(
> - __entry->task_id = rqst->rq_task->tk_pid;
> - __entry->client_id = rqst->rq_task->tk_client ?
> - rqst->rq_task->tk_client->cl_clid : -1;
> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> __entry->xid = be32_to_cpu(rqst->rq_xid);
> __entry->seqno = rqst->rq_seqno;
> __entry->status = status;
> @@ -1082,9 +1064,7 @@ TRACE_EVENT(xprt_retransmit,
> TP_fast_assign(
> struct rpc_task *task = rqst->rq_task;
>
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client ?
> - task->tk_client->cl_clid : -1;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->xid = be32_to_cpu(rqst->rq_xid);
> __entry->ntrans = rqst->rq_ntrans;
> __entry->timeout = task->tk_timeout;
> @@ -1137,14 +1117,7 @@ DECLARE_EVENT_CLASS(xprt_writelock_event,
> ),
>
> TP_fast_assign(
> - if (task) {
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client ?
> - task->tk_client->cl_clid
> : -1;
> - } else {
> - __entry->task_id = -1;
> - __entry->client_id = -1;
> - }
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->snd_task_id = xprt->snd_task ?
> xprt->snd_task->tk_pid : -1;
> ),
> @@ -1183,14 +1156,7 @@ DECLARE_EVENT_CLASS(xprt_cong_event,
> ),
>
> TP_fast_assign(
> - if (task) {
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client ?
> - task->tk_client->cl_clid
> : -1;
> - } else {
> - __entry->task_id = -1;
> - __entry->client_id = -1;
> - }
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->snd_task_id = xprt->snd_task ?
> xprt->snd_task->tk_pid : -1;
> __entry->cong = xprt->cong;
> @@ -1233,8 +1199,7 @@ TRACE_EVENT(xprt_reserve,
> ),
>
> TP_fast_assign(
> - __entry->task_id = rqst->rq_task->tk_pid;
> - __entry->client_id = rqst->rq_task->tk_client-
> >cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> __entry->xid = be32_to_cpu(rqst->rq_xid);
> ),
>
> @@ -1318,8 +1283,7 @@ TRACE_EVENT(rpcb_getport,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = clnt->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->program = clnt->cl_prog;
> __entry->version = clnt->cl_vers;
> __entry->protocol = task->tk_xprt->prot;
> @@ -1352,8 +1316,7 @@ TRACE_EVENT(rpcb_setport,
> ),
>
> TP_fast_assign(
> - __entry->task_id = task->tk_pid;
> - __entry->client_id = task->tk_client->cl_clid;
> + SUNRPC_TRACE_TASK_ASSIGN(task);
> __entry->status = status;
> __entry->port = port;
> ),
> diff --git a/include/trace/events/sunrpc_base.h
> b/include/trace/events/sunrpc_base.h
> index 588557d07ea8..2cbed4a9a63a 100644
> --- a/include/trace/events/sunrpc_base.h
> +++ b/include/trace/events/sunrpc_base.h
> @@ -10,6 +10,21 @@
>
> #include <linux/tracepoint.h>
>
> +#define SUNRPC_TRACE_PID_SPECIAL (-1)
> +
> +#define SUNRPC_TRACE_TASK_ASSIGN(t) \
> + do { \
> + if ((t) != NULL) { \
> + __entry->task_id = (t)->tk_pid; \
> + __entry->client_id = (t)->tk_client ? \
> + (t)->tk_client->cl_clid
> : \
> +
> SUNRPC_TRACE_PID_SPECIAL; \
> + } else { \
> + __entry->task_id = SUNRPC_TRACE_PID_SPECIAL;
> \
> + __entry->client_id =
> SUNRPC_TRACE_PID_SPECIAL; \
> + } \
> + } while (0);
> +
> #define SUNRPC_TRACE_PID_SPECIFIER "%08x"
> #define SUNRPC_TRACE_CLID_SPECIFIER "%08x"
> #define SUNRPC_TRACE_TASK_SPECIFIER \
>
--
Trond Myklebust
Linux NFS client maintainer, Hammerspace
trond.myklebust@hammerspace.com
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [PATCH v4 2/7] SUNRPC: Avoid NULL pointer dereferences in tracepoints
2021-10-20 18:43 ` Trond Myklebust
@ 2021-10-20 19:39 ` Chuck Lever III
2021-10-20 20:09 ` Trond Myklebust
0 siblings, 1 reply; 13+ messages in thread
From: Chuck Lever III @ 2021-10-20 19:39 UTC (permalink / raw)
To: Trond Myklebust; +Cc: Linux NFS Mailing List
> On Oct 20, 2021, at 2:43 PM, Trond Myklebust <trondmy@hammerspace.com> wrote:
>
> On Sat, 2021-10-16 at 18:02 -0400, Chuck Lever wrote:
>> On occasion, a NULL rpc_task pointer is passed into tracepoints.
>> We've open-coded a few places where this is expected, but let's
>> be defensive and protect every place that wants to dereference
>> a task to assign the tk_pid and cl_clid.
>>
>
> No, I won't apply this.
>
> This patch is going to lead to a bunch of static checkers complaining
> that we're checking 'task' for NULL after we've already dereferenced it
> in the same function, and/or complaining that we're dereferencing a
> value that might be null because we just had a check for it.
Interesting. I already run "make C=1 W=1" on every patch. I can update
my development workflow. Which static checker complains?
> Even within the macros touched by this patch, we have instances of the
> latter occurring, where we read task->tk_client->cl_vers (and other
> fields) immediately after we just declared that we had to check both
> task and task->tk_client for NULL.
Very likely copy-pasta mistakes, but again, my tool chain hadn't
complained.
>> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
>> ---
>> fs/nfs/nfs4trace.h | 8 +---
>> fs/nfs/nfstrace.h | 3 -
>> include/trace/events/rpcgss.h | 18 +++-----
>> include/trace/events/rpcrdma.h | 62 ++++++++------------------
>> ---
>> include/trace/events/sunrpc.h | 77 +++++++++-----------------
>> ----------
>> include/trace/events/sunrpc_base.h | 15 +++++++
>> 6 files changed, 61 insertions(+), 122 deletions(-)
>>
>> diff --git a/fs/nfs/nfs4trace.h b/fs/nfs/nfs4trace.h
>> index d4f061046c09..66fbd3c33c15 100644
>> --- a/fs/nfs/nfs4trace.h
>> +++ b/fs/nfs/nfs4trace.h
>> @@ -686,10 +686,8 @@ TRACE_EVENT(nfs4_xdr_bad_operation,
>>
>> TP_fast_assign(
>> const struct rpc_rqst *rqstp = xdr->rqst;
>> - const struct rpc_task *task = rqstp->rq_task;
>>
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqstp->rq_task);
>> __entry->xid = be32_to_cpu(rqstp->rq_xid);
>> __entry->op = op;
>> __entry->expected = expected;
>> @@ -721,10 +719,8 @@ DECLARE_EVENT_CLASS(nfs4_xdr_event,
>>
>> TP_fast_assign(
>> const struct rpc_rqst *rqstp = xdr->rqst;
>> - const struct rpc_task *task = rqstp->rq_task;
>>
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqstp->rq_task);
>> __entry->xid = be32_to_cpu(rqstp->rq_xid);
>> __entry->op = op;
>> __entry->error = error;
>> diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
>> index 82b51120450f..e9be65b52bfe 100644
>> --- a/fs/nfs/nfstrace.h
>> +++ b/fs/nfs/nfstrace.h
>> @@ -1401,8 +1401,7 @@ DECLARE_EVENT_CLASS(nfs_xdr_event,
>> const struct rpc_rqst *rqstp = xdr->rqst;
>> const struct rpc_task *task = rqstp->rq_task;
>>
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->xid = be32_to_cpu(rqstp->rq_xid);
>> __entry->version = task->tk_client->cl_vers;
>> __entry->error = error;
>> diff --git a/include/trace/events/rpcgss.h
>> b/include/trace/events/rpcgss.h
>> index 3ba63319af3c..87b17ebd09c3 100644
>> --- a/include/trace/events/rpcgss.h
>> +++ b/include/trace/events/rpcgss.h
>> @@ -96,8 +96,7 @@ DECLARE_EVENT_CLASS(rpcgss_gssapi_event,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->maj_stat = maj_stat;
>> ),
>>
>> @@ -330,8 +329,7 @@ TRACE_EVENT(rpcgss_unwrap_failed,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> ),
>>
>> TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
>> @@ -355,8 +353,7 @@ TRACE_EVENT(rpcgss_bad_seqno,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->expected = expected;
>> __entry->received = received;
>> ),
>> @@ -384,8 +381,7 @@ TRACE_EVENT(rpcgss_seqno,
>> TP_fast_assign(
>> const struct rpc_rqst *rqst = task->tk_rqstp;
>>
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->xid = be32_to_cpu(rqst->rq_xid);
>> __entry->seqno = rqst->rq_seqno;
>> ),
>> @@ -414,8 +410,7 @@ TRACE_EVENT(rpcgss_need_reencode,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
>> __entry->seq_xmit = seq_xmit;
>> __entry->seqno = task->tk_rqstp->rq_seqno;
>> @@ -448,8 +443,7 @@ TRACE_EVENT(rpcgss_update_slack,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
>> __entry->auth = auth;
>> __entry->rslack = auth->au_rslack;
>> diff --git a/include/trace/events/rpcrdma.h
>> b/include/trace/events/rpcrdma.h
>> index 7f46ef621c95..c2ab9e5d775b 100644
>> --- a/include/trace/events/rpcrdma.h
>> +++ b/include/trace/events/rpcrdma.h
>> @@ -271,8 +271,7 @@ DECLARE_EVENT_CLASS(xprtrdma_rdch_event,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->pos = pos;
>> __entry->nents = mr->mr_nents;
>> __entry->handle = mr->mr_handle;
>> @@ -320,8 +319,7 @@ DECLARE_EVENT_CLASS(xprtrdma_wrch_event,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->nents = mr->mr_nents;
>> __entry->handle = mr->mr_handle;
>> __entry->length = mr->mr_length;
>> @@ -380,15 +378,8 @@ DECLARE_EVENT_CLASS(xprtrdma_mr_class,
>> TP_fast_assign(
>> const struct rpcrdma_req *req = mr->mr_req;
>>
>> - if (req) {
>> - const struct rpc_task *task = req-
>>> rl_slot.rq_task;
>> -
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client-
>>> cl_clid;
>> - } else {
>> - __entry->task_id = 0;
>> - __entry->client_id = -1;
>> - }
>> + if (req)
>> + SUNRPC_TRACE_TASK_ASSIGN(req-
>>> rl_slot.rq_task);
>> __entry->mr_id = mr->mr_ibmr->res.id;
>> __entry->nents = mr->mr_nents;
>> __entry->handle = mr->mr_handle;
>> @@ -633,10 +624,7 @@ TRACE_EVENT(xprtrdma_nomrs_err,
>> ),
>>
>> TP_fast_assign(
>> - const struct rpc_rqst *rqst = &req->rl_slot;
>> -
>> - __entry->task_id = rqst->rq_task->tk_pid;
>> - __entry->client_id = rqst->rq_task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(req->rl_slot.rq_task);
>> __assign_str(addr, rpcrdma_addrstr(r_xprt));
>> __assign_str(port, rpcrdma_portstr(r_xprt));
>> ),
>> @@ -694,8 +682,7 @@ TRACE_EVENT(xprtrdma_marshal,
>> TP_fast_assign(
>> const struct rpc_rqst *rqst = &req->rl_slot;
>>
>> - __entry->task_id = rqst->rq_task->tk_pid;
>> - __entry->client_id = rqst->rq_task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
>> __entry->xid = be32_to_cpu(rqst->rq_xid);
>> __entry->hdrlen = req->rl_hdrbuf.len;
>> __entry->headlen = rqst->rq_snd_buf.head[0].iov_len;
>> @@ -730,8 +717,7 @@ TRACE_EVENT(xprtrdma_marshal_failed,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = rqst->rq_task->tk_pid;
>> - __entry->client_id = rqst->rq_task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
>> __entry->xid = be32_to_cpu(rqst->rq_xid);
>> __entry->ret = ret;
>> ),
>> @@ -757,8 +743,7 @@ TRACE_EVENT(xprtrdma_prepsend_failed,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = rqst->rq_task->tk_pid;
>> - __entry->client_id = rqst->rq_task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
>> __entry->xid = be32_to_cpu(rqst->rq_xid);
>> __entry->ret = ret;
>> ),
>> @@ -791,9 +776,7 @@ TRACE_EVENT(xprtrdma_post_send,
>>
>> __entry->cq_id = sc->sc_cid.ci_queue_id;
>> __entry->completion_id = sc->sc_cid.ci_completion_id;
>> - __entry->task_id = rqst->rq_task->tk_pid;
>> - __entry->client_id = rqst->rq_task->tk_client ?
>> - rqst->rq_task->tk_client-
>>> cl_clid : -1;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
>> __entry->num_sge = req->rl_wr.num_sge;
>> __entry->signaled = req->rl_wr.send_flags &
>> IB_SEND_SIGNALED;
>> ),
>> @@ -827,9 +810,7 @@ TRACE_EVENT(xprtrdma_post_send_err,
>> const struct rpcrdma_ep *ep = r_xprt->rx_ep;
>>
>> __entry->cq_id = ep ? ep->re_attr.recv_cq->res.id :
>> 0;
>> - __entry->task_id = rqst->rq_task->tk_pid;
>> - __entry->client_id = rqst->rq_task->tk_client ?
>> - rqst->rq_task->tk_client-
>>> cl_clid : -1;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
>> __entry->rc = rc;
>> ),
>>
>> @@ -938,10 +919,7 @@ TRACE_EVENT(xprtrdma_post_linv_err,
>> ),
>>
>> TP_fast_assign(
>> - const struct rpc_task *task = req->rl_slot.rq_task;
>> -
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(req->rl_slot.rq_task);
>> __entry->status = status;
>> ),
>>
>> @@ -1127,8 +1105,7 @@ TRACE_EVENT(xprtrdma_reply,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->xid = be32_to_cpu(rep->rr_xid);
>> __entry->credits = credits;
>> ),
>> @@ -1162,8 +1139,7 @@ TRACE_EVENT(xprtrdma_err_vers,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = rqst->rq_task->tk_pid;
>> - __entry->client_id = rqst->rq_task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
>> __entry->xid = be32_to_cpu(rqst->rq_xid);
>> __entry->min = be32_to_cpup(min);
>> __entry->max = be32_to_cpup(max);
>> @@ -1189,8 +1165,7 @@ TRACE_EVENT(xprtrdma_err_chunk,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = rqst->rq_task->tk_pid;
>> - __entry->client_id = rqst->rq_task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
>> __entry->xid = be32_to_cpu(rqst->rq_xid);
>> ),
>>
>> @@ -1215,8 +1190,7 @@ TRACE_EVENT(xprtrdma_err_unrecognized,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = rqst->rq_task->tk_pid;
>> - __entry->client_id = rqst->rq_task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
>> __entry->procedure = be32_to_cpup(procedure);
>> ),
>>
>> @@ -1244,8 +1218,7 @@ TRACE_EVENT(xprtrdma_fixup,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = rqst->rq_task->tk_pid;
>> - __entry->client_id = rqst->rq_task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
>> __entry->fixup = fixup;
>> __entry->headlen = rqst->rq_rcv_buf.head[0].iov_len;
>> __entry->pagelen = rqst->rq_rcv_buf.page_len;
>> @@ -1298,8 +1271,7 @@ TRACE_EVENT(xprtrdma_mrs_zap,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> ),
>>
>> TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
>> diff --git a/include/trace/events/sunrpc.h
>> b/include/trace/events/sunrpc.h
>> index 92def7d6663e..4fd6299bc907 100644
>> --- a/include/trace/events/sunrpc.h
>> +++ b/include/trace/events/sunrpc.h
>> @@ -69,9 +69,7 @@ DECLARE_EVENT_CLASS(rpc_xdr_buf_class,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client ?
>> - task->tk_client->cl_clid : -1;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->head_base = xdr->head[0].iov_base;
>> __entry->head_len = xdr->head[0].iov_len;
>> __entry->tail_base = xdr->tail[0].iov_base;
>> @@ -248,8 +246,7 @@ DECLARE_EVENT_CLASS(rpc_task_status,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->status = task->tk_status;
>> ),
>>
>> @@ -285,8 +282,7 @@ TRACE_EVENT(rpc_request,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->version = task->tk_client->cl_vers;
>> __entry->async = RPC_IS_ASYNC(task);
>> __assign_str(progname, task->tk_client->cl_program-
>>> name);
>> @@ -344,9 +340,7 @@ DECLARE_EVENT_CLASS(rpc_task_running,
>> ),
>>
>> TP_fast_assign(
>> - __entry->client_id = task->tk_client ?
>> - task->tk_client->cl_clid : -1;
>> - __entry->task_id = task->tk_pid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->action = action;
>> __entry->runstate = task->tk_runstate;
>> __entry->status = task->tk_status;
>> @@ -396,9 +390,7 @@ DECLARE_EVENT_CLASS(rpc_task_queued,
>> ),
>>
>> TP_fast_assign(
>> - __entry->client_id = task->tk_client ?
>> - task->tk_client->cl_clid : -1;
>> - __entry->task_id = task->tk_pid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->timeout = rpc_task_timeout(task);
>> __entry->runstate = task->tk_runstate;
>> __entry->status = task->tk_status;
>> @@ -439,8 +431,7 @@ DECLARE_EVENT_CLASS(rpc_failure,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> ),
>>
>> TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
>> @@ -476,8 +467,7 @@ DECLARE_EVENT_CLASS(rpc_reply_event,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
>> __assign_str(progname, task->tk_client->cl_program-
>>> name);
>> __entry->version = task->tk_client->cl_vers;
>> @@ -539,8 +529,7 @@ TRACE_EVENT(rpc_buf_alloc,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->callsize = task->tk_rqstp->rq_callsize;
>> __entry->recvsize = task->tk_rqstp->rq_rcvsize;
>> __entry->status = status;
>> @@ -570,8 +559,7 @@ TRACE_EVENT(rpc_call_rpcerror,
>> ),
>>
>> TP_fast_assign(
>> - __entry->client_id = task->tk_client->cl_clid;
>> - __entry->task_id = task->tk_pid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->tk_status = tk_status;
>> __entry->rpc_status = rpc_status;
>> ),
>> @@ -606,8 +594,7 @@ TRACE_EVENT(rpc_stats_latency,
>> ),
>>
>> TP_fast_assign(
>> - __entry->client_id = task->tk_client->cl_clid;
>> - __entry->task_id = task->tk_pid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->xid = be32_to_cpu(task->tk_rqstp->rq_xid);
>> __entry->version = task->tk_client->cl_vers;
>> __assign_str(progname, task->tk_client->cl_program-
>>> name);
>> @@ -655,8 +642,7 @@ TRACE_EVENT(rpc_xdr_overflow,
>> if (xdr->rqst) {
>> const struct rpc_task *task = xdr->rqst-
>>> rq_task;
>>
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __assign_str(progname,
>> task->tk_client->cl_program-
>>> name);
>> __entry->version = task->tk_client->cl_vers;
>> @@ -721,8 +707,7 @@ TRACE_EVENT(rpc_xdr_alignment,
>> TP_fast_assign(
>> const struct rpc_task *task = xdr->rqst->rq_task;
>>
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __assign_str(progname,
>> task->tk_client->cl_program->name);
>> __entry->version = task->tk_client->cl_vers;
>> @@ -922,8 +907,7 @@ TRACE_EVENT(rpc_socket_nospace,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = rqst->rq_task->tk_pid;
>> - __entry->client_id = rqst->rq_task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
>> __entry->total = rqst->rq_slen;
>> __entry->remaining = rqst->rq_slen - transport-
>>> xmit.offset;
>> ),
>> @@ -1046,9 +1030,7 @@ TRACE_EVENT(xprt_transmit,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = rqst->rq_task->tk_pid;
>> - __entry->client_id = rqst->rq_task->tk_client ?
>> - rqst->rq_task->tk_client->cl_clid : -1;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
>> __entry->xid = be32_to_cpu(rqst->rq_xid);
>> __entry->seqno = rqst->rq_seqno;
>> __entry->status = status;
>> @@ -1082,9 +1064,7 @@ TRACE_EVENT(xprt_retransmit,
>> TP_fast_assign(
>> struct rpc_task *task = rqst->rq_task;
>>
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client ?
>> - task->tk_client->cl_clid : -1;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->xid = be32_to_cpu(rqst->rq_xid);
>> __entry->ntrans = rqst->rq_ntrans;
>> __entry->timeout = task->tk_timeout;
>> @@ -1137,14 +1117,7 @@ DECLARE_EVENT_CLASS(xprt_writelock_event,
>> ),
>>
>> TP_fast_assign(
>> - if (task) {
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client ?
>> - task->tk_client->cl_clid
>> : -1;
>> - } else {
>> - __entry->task_id = -1;
>> - __entry->client_id = -1;
>> - }
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->snd_task_id = xprt->snd_task ?
>> xprt->snd_task->tk_pid : -1;
>> ),
>> @@ -1183,14 +1156,7 @@ DECLARE_EVENT_CLASS(xprt_cong_event,
>> ),
>>
>> TP_fast_assign(
>> - if (task) {
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client ?
>> - task->tk_client->cl_clid
>> : -1;
>> - } else {
>> - __entry->task_id = -1;
>> - __entry->client_id = -1;
>> - }
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->snd_task_id = xprt->snd_task ?
>> xprt->snd_task->tk_pid : -1;
>> __entry->cong = xprt->cong;
>> @@ -1233,8 +1199,7 @@ TRACE_EVENT(xprt_reserve,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = rqst->rq_task->tk_pid;
>> - __entry->client_id = rqst->rq_task->tk_client-
>>> cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
>> __entry->xid = be32_to_cpu(rqst->rq_xid);
>> ),
>>
>> @@ -1318,8 +1283,7 @@ TRACE_EVENT(rpcb_getport,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = clnt->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->program = clnt->cl_prog;
>> __entry->version = clnt->cl_vers;
>> __entry->protocol = task->tk_xprt->prot;
>> @@ -1352,8 +1316,7 @@ TRACE_EVENT(rpcb_setport,
>> ),
>>
>> TP_fast_assign(
>> - __entry->task_id = task->tk_pid;
>> - __entry->client_id = task->tk_client->cl_clid;
>> + SUNRPC_TRACE_TASK_ASSIGN(task);
>> __entry->status = status;
>> __entry->port = port;
>> ),
>> diff --git a/include/trace/events/sunrpc_base.h
>> b/include/trace/events/sunrpc_base.h
>> index 588557d07ea8..2cbed4a9a63a 100644
>> --- a/include/trace/events/sunrpc_base.h
>> +++ b/include/trace/events/sunrpc_base.h
>> @@ -10,6 +10,21 @@
>>
>> #include <linux/tracepoint.h>
>>
>> +#define SUNRPC_TRACE_PID_SPECIAL (-1)
>> +
>> +#define SUNRPC_TRACE_TASK_ASSIGN(t) \
>> + do { \
>> + if ((t) != NULL) { \
>> + __entry->task_id = (t)->tk_pid; \
>> + __entry->client_id = (t)->tk_client ? \
>> + (t)->tk_client->cl_clid
>> : \
>> +
>> SUNRPC_TRACE_PID_SPECIAL; \
>> + } else { \
>> + __entry->task_id = SUNRPC_TRACE_PID_SPECIAL;
>> \
>> + __entry->client_id =
>> SUNRPC_TRACE_PID_SPECIAL; \
>> + } \
>> + } while (0);
>> +
>> #define SUNRPC_TRACE_PID_SPECIFIER "%08x"
>> #define SUNRPC_TRACE_CLID_SPECIFIER "%08x"
>> #define SUNRPC_TRACE_TASK_SPECIFIER \
>>
>
> --
> Trond Myklebust
> Linux NFS client maintainer, Hammerspace
> trond.myklebust@hammerspace.com
--
Chuck Lever
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [PATCH v4 2/7] SUNRPC: Avoid NULL pointer dereferences in tracepoints
2021-10-20 19:39 ` Chuck Lever III
@ 2021-10-20 20:09 ` Trond Myklebust
0 siblings, 0 replies; 13+ messages in thread
From: Trond Myklebust @ 2021-10-20 20:09 UTC (permalink / raw)
To: chuck.lever; +Cc: linux-nfs
On Wed, 2021-10-20 at 19:39 +0000, Chuck Lever III wrote:
>
>
> > On Oct 20, 2021, at 2:43 PM, Trond Myklebust
> > <trondmy@hammerspace.com> wrote:
> >
> > On Sat, 2021-10-16 at 18:02 -0400, Chuck Lever wrote:
> > > On occasion, a NULL rpc_task pointer is passed into tracepoints.
> > > We've open-coded a few places where this is expected, but let's
> > > be defensive and protect every place that wants to dereference
> > > a task to assign the tk_pid and cl_clid.
> > >
> >
> > No, I won't apply this.
> >
> > This patch is going to lead to a bunch of static checkers
> > complaining
> > that we're checking 'task' for NULL after we've already
> > dereferenced it
> > in the same function, and/or complaining that we're dereferencing a
> > value that might be null because we just had a check for it.
>
> Interesting. I already run "make C=1 W=1" on every patch. I can
> update
> my development workflow. Which static checker complains?
I'm thinking of coverity in particular, that checks for dereferences
after a NULL test such as commit 85233a7a436a ("[PATCH] NFS:
__nfs_revalidate_inode() can use "inode" before checking it is non-
NULL"). However there are other checkers that look for this kind of
problem: see for instance commit e2751463eaa6 ("fs: nfs: Fix possible
null-pointer dereferences in encode_attrs()")
>
>
> > Even within the macros touched by this patch, we have instances of
> > the
> > latter occurring, where we read task->tk_client->cl_vers (and other
> > fields) immediately after we just declared that we had to check
> > both
> > task and task->tk_client for NULL.
>
> Very likely copy-pasta mistakes, but again, my tool chain hadn't
> complained.
>
>
> > > Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> > > ---
> > > fs/nfs/nfs4trace.h | 8 +---
> > > fs/nfs/nfstrace.h | 3 -
> > > include/trace/events/rpcgss.h | 18 +++-----
> > > include/trace/events/rpcrdma.h | 62 ++++++++--------------
> > > ----
> > > ---
> > > include/trace/events/sunrpc.h | 77 +++++++++-------------
> > > ----
> > > ----------
> > > include/trace/events/sunrpc_base.h | 15 +++++++
> > > 6 files changed, 61 insertions(+), 122 deletions(-)
> > >
> > > diff --git a/fs/nfs/nfs4trace.h b/fs/nfs/nfs4trace.h
> > > index d4f061046c09..66fbd3c33c15 100644
> > > --- a/fs/nfs/nfs4trace.h
> > > +++ b/fs/nfs/nfs4trace.h
> > > @@ -686,10 +686,8 @@ TRACE_EVENT(nfs4_xdr_bad_operation,
> > >
> > > TP_fast_assign(
> > > const struct rpc_rqst *rqstp = xdr->rqst;
> > > - const struct rpc_task *task = rqstp-
> > > >rq_task;
> > >
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqstp->rq_task);
> > > __entry->xid = be32_to_cpu(rqstp-
> > > >rq_xid);
> > > __entry->op = op;
> > > __entry->expected = expected;
> > > @@ -721,10 +719,8 @@ DECLARE_EVENT_CLASS(nfs4_xdr_event,
> > >
> > > TP_fast_assign(
> > > const struct rpc_rqst *rqstp = xdr->rqst;
> > > - const struct rpc_task *task = rqstp-
> > > >rq_task;
> > >
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqstp->rq_task);
> > > __entry->xid = be32_to_cpu(rqstp-
> > > >rq_xid);
> > > __entry->op = op;
> > > __entry->error = error;
> > > diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
> > > index 82b51120450f..e9be65b52bfe 100644
> > > --- a/fs/nfs/nfstrace.h
> > > +++ b/fs/nfs/nfstrace.h
> > > @@ -1401,8 +1401,7 @@ DECLARE_EVENT_CLASS(nfs_xdr_event,
> > > const struct rpc_rqst *rqstp = xdr->rqst;
> > > const struct rpc_task *task = rqstp-
> > > >rq_task;
> > >
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->xid = be32_to_cpu(rqstp-
> > > >rq_xid);
> > > __entry->version = task->tk_client-
> > > >cl_vers;
> > > __entry->error = error;
> > > diff --git a/include/trace/events/rpcgss.h
> > > b/include/trace/events/rpcgss.h
> > > index 3ba63319af3c..87b17ebd09c3 100644
> > > --- a/include/trace/events/rpcgss.h
> > > +++ b/include/trace/events/rpcgss.h
> > > @@ -96,8 +96,7 @@ DECLARE_EVENT_CLASS(rpcgss_gssapi_event,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->maj_stat = maj_stat;
> > > ),
> > >
> > > @@ -330,8 +329,7 @@ TRACE_EVENT(rpcgss_unwrap_failed,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > ),
> > >
> > > TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
> > > @@ -355,8 +353,7 @@ TRACE_EVENT(rpcgss_bad_seqno,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->expected = expected;
> > > __entry->received = received;
> > > ),
> > > @@ -384,8 +381,7 @@ TRACE_EVENT(rpcgss_seqno,
> > > TP_fast_assign(
> > > const struct rpc_rqst *rqst = task->tk_rqstp;
> > >
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->xid = be32_to_cpu(rqst->rq_xid);
> > > __entry->seqno = rqst->rq_seqno;
> > > ),
> > > @@ -414,8 +410,7 @@ TRACE_EVENT(rpcgss_need_reencode,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->xid = be32_to_cpu(task->tk_rqstp-
> > > >rq_xid);
> > > __entry->seq_xmit = seq_xmit;
> > > __entry->seqno = task->tk_rqstp->rq_seqno;
> > > @@ -448,8 +443,7 @@ TRACE_EVENT(rpcgss_update_slack,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->xid = be32_to_cpu(task->tk_rqstp-
> > > >rq_xid);
> > > __entry->auth = auth;
> > > __entry->rslack = auth->au_rslack;
> > > diff --git a/include/trace/events/rpcrdma.h
> > > b/include/trace/events/rpcrdma.h
> > > index 7f46ef621c95..c2ab9e5d775b 100644
> > > --- a/include/trace/events/rpcrdma.h
> > > +++ b/include/trace/events/rpcrdma.h
> > > @@ -271,8 +271,7 @@ DECLARE_EVENT_CLASS(xprtrdma_rdch_event,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->pos = pos;
> > > __entry->nents = mr->mr_nents;
> > > __entry->handle = mr->mr_handle;
> > > @@ -320,8 +319,7 @@ DECLARE_EVENT_CLASS(xprtrdma_wrch_event,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->nents = mr->mr_nents;
> > > __entry->handle = mr->mr_handle;
> > > __entry->length = mr->mr_length;
> > > @@ -380,15 +378,8 @@ DECLARE_EVENT_CLASS(xprtrdma_mr_class,
> > > TP_fast_assign(
> > > const struct rpcrdma_req *req = mr->mr_req;
> > >
> > > - if (req) {
> > > - const struct rpc_task *task = req-
> > > > rl_slot.rq_task;
> > > -
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client-
> > > > cl_clid;
> > > - } else {
> > > - __entry->task_id = 0;
> > > - __entry->client_id = -1;
> > > - }
> > > + if (req)
> > > + SUNRPC_TRACE_TASK_ASSIGN(req-
> > > > rl_slot.rq_task);
> > > __entry->mr_id = mr->mr_ibmr->res.id;
> > > __entry->nents = mr->mr_nents;
> > > __entry->handle = mr->mr_handle;
> > > @@ -633,10 +624,7 @@ TRACE_EVENT(xprtrdma_nomrs_err,
> > > ),
> > >
> > > TP_fast_assign(
> > > - const struct rpc_rqst *rqst = &req->rl_slot;
> > > -
> > > - __entry->task_id = rqst->rq_task->tk_pid;
> > > - __entry->client_id = rqst->rq_task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(req->rl_slot.rq_task);
> > > __assign_str(addr, rpcrdma_addrstr(r_xprt));
> > > __assign_str(port, rpcrdma_portstr(r_xprt));
> > > ),
> > > @@ -694,8 +682,7 @@ TRACE_EVENT(xprtrdma_marshal,
> > > TP_fast_assign(
> > > const struct rpc_rqst *rqst = &req->rl_slot;
> > >
> > > - __entry->task_id = rqst->rq_task->tk_pid;
> > > - __entry->client_id = rqst->rq_task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> > > __entry->xid = be32_to_cpu(rqst->rq_xid);
> > > __entry->hdrlen = req->rl_hdrbuf.len;
> > > __entry->headlen = rqst-
> > > >rq_snd_buf.head[0].iov_len;
> > > @@ -730,8 +717,7 @@ TRACE_EVENT(xprtrdma_marshal_failed,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = rqst->rq_task->tk_pid;
> > > - __entry->client_id = rqst->rq_task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> > > __entry->xid = be32_to_cpu(rqst->rq_xid);
> > > __entry->ret = ret;
> > > ),
> > > @@ -757,8 +743,7 @@ TRACE_EVENT(xprtrdma_prepsend_failed,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = rqst->rq_task->tk_pid;
> > > - __entry->client_id = rqst->rq_task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> > > __entry->xid = be32_to_cpu(rqst->rq_xid);
> > > __entry->ret = ret;
> > > ),
> > > @@ -791,9 +776,7 @@ TRACE_EVENT(xprtrdma_post_send,
> > >
> > > __entry->cq_id = sc->sc_cid.ci_queue_id;
> > > __entry->completion_id = sc-
> > > >sc_cid.ci_completion_id;
> > > - __entry->task_id = rqst->rq_task->tk_pid;
> > > - __entry->client_id = rqst->rq_task->tk_client ?
> > > - rqst->rq_task->tk_client-
> > > > cl_clid : -1;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> > > __entry->num_sge = req->rl_wr.num_sge;
> > > __entry->signaled = req->rl_wr.send_flags &
> > > IB_SEND_SIGNALED;
> > > ),
> > > @@ -827,9 +810,7 @@ TRACE_EVENT(xprtrdma_post_send_err,
> > > const struct rpcrdma_ep *ep = r_xprt->rx_ep;
> > >
> > > __entry->cq_id = ep ? ep->re_attr.recv_cq->res.id
> > > :
> > > 0;
> > > - __entry->task_id = rqst->rq_task->tk_pid;
> > > - __entry->client_id = rqst->rq_task->tk_client ?
> > > - rqst->rq_task->tk_client-
> > > > cl_clid : -1;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> > > __entry->rc = rc;
> > > ),
> > >
> > > @@ -938,10 +919,7 @@ TRACE_EVENT(xprtrdma_post_linv_err,
> > > ),
> > >
> > > TP_fast_assign(
> > > - const struct rpc_task *task = req-
> > > >rl_slot.rq_task;
> > > -
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(req->rl_slot.rq_task);
> > > __entry->status = status;
> > > ),
> > >
> > > @@ -1127,8 +1105,7 @@ TRACE_EVENT(xprtrdma_reply,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->xid = be32_to_cpu(rep->rr_xid);
> > > __entry->credits = credits;
> > > ),
> > > @@ -1162,8 +1139,7 @@ TRACE_EVENT(xprtrdma_err_vers,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = rqst->rq_task->tk_pid;
> > > - __entry->client_id = rqst->rq_task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> > > __entry->xid = be32_to_cpu(rqst->rq_xid);
> > > __entry->min = be32_to_cpup(min);
> > > __entry->max = be32_to_cpup(max);
> > > @@ -1189,8 +1165,7 @@ TRACE_EVENT(xprtrdma_err_chunk,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = rqst->rq_task->tk_pid;
> > > - __entry->client_id = rqst->rq_task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> > > __entry->xid = be32_to_cpu(rqst->rq_xid);
> > > ),
> > >
> > > @@ -1215,8 +1190,7 @@ TRACE_EVENT(xprtrdma_err_unrecognized,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = rqst->rq_task->tk_pid;
> > > - __entry->client_id = rqst->rq_task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> > > __entry->procedure = be32_to_cpup(procedure);
> > > ),
> > >
> > > @@ -1244,8 +1218,7 @@ TRACE_EVENT(xprtrdma_fixup,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = rqst->rq_task->tk_pid;
> > > - __entry->client_id = rqst->rq_task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> > > __entry->fixup = fixup;
> > > __entry->headlen = rqst-
> > > >rq_rcv_buf.head[0].iov_len;
> > > __entry->pagelen = rqst->rq_rcv_buf.page_len;
> > > @@ -1298,8 +1271,7 @@ TRACE_EVENT(xprtrdma_mrs_zap,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > ),
> > >
> > > TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
> > > diff --git a/include/trace/events/sunrpc.h
> > > b/include/trace/events/sunrpc.h
> > > index 92def7d6663e..4fd6299bc907 100644
> > > --- a/include/trace/events/sunrpc.h
> > > +++ b/include/trace/events/sunrpc.h
> > > @@ -69,9 +69,7 @@ DECLARE_EVENT_CLASS(rpc_xdr_buf_class,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client ?
> > > - task->tk_client->cl_clid : -
> > > 1;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->head_base = xdr->head[0].iov_base;
> > > __entry->head_len = xdr->head[0].iov_len;
> > > __entry->tail_base = xdr->tail[0].iov_base;
> > > @@ -248,8 +246,7 @@ DECLARE_EVENT_CLASS(rpc_task_status,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->status = task->tk_status;
> > > ),
> > >
> > > @@ -285,8 +282,7 @@ TRACE_EVENT(rpc_request,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->version = task->tk_client->cl_vers;
> > > __entry->async = RPC_IS_ASYNC(task);
> > > __assign_str(progname, task->tk_client-
> > > >cl_program-
> > > > name);
> > > @@ -344,9 +340,7 @@ DECLARE_EVENT_CLASS(rpc_task_running,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->client_id = task->tk_client ?
> > > - task->tk_client->cl_clid : -
> > > 1;
> > > - __entry->task_id = task->tk_pid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->action = action;
> > > __entry->runstate = task->tk_runstate;
> > > __entry->status = task->tk_status;
> > > @@ -396,9 +390,7 @@ DECLARE_EVENT_CLASS(rpc_task_queued,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->client_id = task->tk_client ?
> > > - task->tk_client->cl_clid : -
> > > 1;
> > > - __entry->task_id = task->tk_pid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->timeout = rpc_task_timeout(task);
> > > __entry->runstate = task->tk_runstate;
> > > __entry->status = task->tk_status;
> > > @@ -439,8 +431,7 @@ DECLARE_EVENT_CLASS(rpc_failure,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > ),
> > >
> > > TP_printk(SUNRPC_TRACE_TASK_SPECIFIER,
> > > @@ -476,8 +467,7 @@ DECLARE_EVENT_CLASS(rpc_reply_event,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->xid = be32_to_cpu(task->tk_rqstp-
> > > >rq_xid);
> > > __assign_str(progname, task->tk_client-
> > > >cl_program-
> > > > name);
> > > __entry->version = task->tk_client->cl_vers;
> > > @@ -539,8 +529,7 @@ TRACE_EVENT(rpc_buf_alloc,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->callsize = task->tk_rqstp->rq_callsize;
> > > __entry->recvsize = task->tk_rqstp->rq_rcvsize;
> > > __entry->status = status;
> > > @@ -570,8 +559,7 @@ TRACE_EVENT(rpc_call_rpcerror,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > - __entry->task_id = task->tk_pid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->tk_status = tk_status;
> > > __entry->rpc_status = rpc_status;
> > > ),
> > > @@ -606,8 +594,7 @@ TRACE_EVENT(rpc_stats_latency,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > - __entry->task_id = task->tk_pid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->xid = be32_to_cpu(task->tk_rqstp-
> > > >rq_xid);
> > > __entry->version = task->tk_client->cl_vers;
> > > __assign_str(progname, task->tk_client-
> > > >cl_program-
> > > > name);
> > > @@ -655,8 +642,7 @@ TRACE_EVENT(rpc_xdr_overflow,
> > > if (xdr->rqst) {
> > > const struct rpc_task *task = xdr->rqst-
> > > > rq_task;
> > >
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __assign_str(progname,
> > > task->tk_client->cl_program-
> > > > name);
> > > __entry->version = task->tk_client-
> > > >cl_vers;
> > > @@ -721,8 +707,7 @@ TRACE_EVENT(rpc_xdr_alignment,
> > > TP_fast_assign(
> > > const struct rpc_task *task = xdr->rqst->rq_task;
> > >
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __assign_str(progname,
> > > task->tk_client->cl_program->name);
> > > __entry->version = task->tk_client->cl_vers;
> > > @@ -922,8 +907,7 @@ TRACE_EVENT(rpc_socket_nospace,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = rqst->rq_task->tk_pid;
> > > - __entry->client_id = rqst->rq_task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> > > __entry->total = rqst->rq_slen;
> > > __entry->remaining = rqst->rq_slen - transport-
> > > > xmit.offset;
> > > ),
> > > @@ -1046,9 +1030,7 @@ TRACE_EVENT(xprt_transmit,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = rqst->rq_task->tk_pid;
> > > - __entry->client_id = rqst->rq_task->tk_client ?
> > > - rqst->rq_task->tk_client->cl_clid : -1;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> > > __entry->xid = be32_to_cpu(rqst->rq_xid);
> > > __entry->seqno = rqst->rq_seqno;
> > > __entry->status = status;
> > > @@ -1082,9 +1064,7 @@ TRACE_EVENT(xprt_retransmit,
> > > TP_fast_assign(
> > > struct rpc_task *task = rqst->rq_task;
> > >
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client ?
> > > - task->tk_client->cl_clid : -1;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->xid = be32_to_cpu(rqst->rq_xid);
> > > __entry->ntrans = rqst->rq_ntrans;
> > > __entry->timeout = task->tk_timeout;
> > > @@ -1137,14 +1117,7 @@ DECLARE_EVENT_CLASS(xprt_writelock_event,
> > > ),
> > >
> > > TP_fast_assign(
> > > - if (task) {
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client ?
> > > - task->tk_client-
> > > >cl_clid
> > > : -1;
> > > - } else {
> > > - __entry->task_id = -1;
> > > - __entry->client_id = -1;
> > > - }
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->snd_task_id = xprt->snd_task ?
> > > xprt->snd_task->tk_pid :
> > > -1;
> > > ),
> > > @@ -1183,14 +1156,7 @@ DECLARE_EVENT_CLASS(xprt_cong_event,
> > > ),
> > >
> > > TP_fast_assign(
> > > - if (task) {
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client ?
> > > - task->tk_client-
> > > >cl_clid
> > > : -1;
> > > - } else {
> > > - __entry->task_id = -1;
> > > - __entry->client_id = -1;
> > > - }
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->snd_task_id = xprt->snd_task ?
> > > xprt->snd_task->tk_pid :
> > > -1;
> > > __entry->cong = xprt->cong;
> > > @@ -1233,8 +1199,7 @@ TRACE_EVENT(xprt_reserve,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = rqst->rq_task->tk_pid;
> > > - __entry->client_id = rqst->rq_task->tk_client-
> > > > cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(rqst->rq_task);
> > > __entry->xid = be32_to_cpu(rqst->rq_xid);
> > > ),
> > >
> > > @@ -1318,8 +1283,7 @@ TRACE_EVENT(rpcb_getport,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = clnt->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->program = clnt->cl_prog;
> > > __entry->version = clnt->cl_vers;
> > > __entry->protocol = task->tk_xprt->prot;
> > > @@ -1352,8 +1316,7 @@ TRACE_EVENT(rpcb_setport,
> > > ),
> > >
> > > TP_fast_assign(
> > > - __entry->task_id = task->tk_pid;
> > > - __entry->client_id = task->tk_client->cl_clid;
> > > + SUNRPC_TRACE_TASK_ASSIGN(task);
> > > __entry->status = status;
> > > __entry->port = port;
> > > ),
> > > diff --git a/include/trace/events/sunrpc_base.h
> > > b/include/trace/events/sunrpc_base.h
> > > index 588557d07ea8..2cbed4a9a63a 100644
> > > --- a/include/trace/events/sunrpc_base.h
> > > +++ b/include/trace/events/sunrpc_base.h
> > > @@ -10,6 +10,21 @@
> > >
> > > #include <linux/tracepoint.h>
> > >
> > > +#define SUNRPC_TRACE_PID_SPECIAL (-1)
> > > +
> > > +#define SUNRPC_TRACE_TASK_ASSIGN(t) \
> > > + do { \
> > > + if ((t) != NULL) { \
> > > + __entry->task_id = (t)->tk_pid; \
> > > + __entry->client_id = (t)->tk_client ? \
> > > + (t)->tk_client-
> > > >cl_clid
> > > : \
> > > +
> > > SUNRPC_TRACE_PID_SPECIAL; \
> > > + } else { \
> > > + __entry->task_id =
> > > SUNRPC_TRACE_PID_SPECIAL;
> > > \
> > > + __entry->client_id =
> > > SUNRPC_TRACE_PID_SPECIAL; \
> > > + } \
> > > + } while (0);
> > > +
> > > #define SUNRPC_TRACE_PID_SPECIFIER "%08x"
> > > #define SUNRPC_TRACE_CLID_SPECIFIER "%08x"
> > > #define SUNRPC_TRACE_TASK_SPECIFIER \
> > >
> >
> > --
> > Trond Myklebust
> > Linux NFS client maintainer, Hammerspace
> > trond.myklebust@hammerspace.com
>
> --
> Chuck Lever
>
>
>
--
Trond Myklebust
Linux NFS client maintainer, Hammerspace
trond.myklebust@hammerspace.com
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [PATCH v4 5/7] NFS: Replace dprintk callsites in nfs_readpage(s)
2021-10-16 22:02 ` [PATCH v4 5/7] NFS: Replace dprintk callsites in nfs_readpage(s) Chuck Lever
@ 2021-11-02 19:36 ` David Wysochanski
2021-11-02 19:41 ` Chuck Lever III
0 siblings, 1 reply; 13+ messages in thread
From: David Wysochanski @ 2021-11-02 19:36 UTC (permalink / raw)
To: Chuck Lever; +Cc: Trond Myklebust, linux-nfs
On Sat, Oct 16, 2021 at 6:03 PM Chuck Lever <chuck.lever@oracle.com> wrote:
>
> These new events report slightly different information for readpage
> and readpages/readahead.
>
> For readpage:
> fsx-1387 [006] 380.761896: nfs_aop_readpage: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355910932437 offset=131072
> fsx-1387 [006] 380.761900: nfs_aop_readpage_done: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355910932437 offset=131072 ret=0
>
> The index of a synchronous single-page read is reported.
>
> For readpages:
>
> fsx-1387 [006] 380.760847: nfs_aop_readahead: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355909932456 nr_pages=3
> fsx-1387 [006] 380.760853: nfs_aop_readahead_done: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355909932456 nr_pages=3 ret=0
>
Chuck,
I was doing more debugging and thought about the readahead trace event.
Are you set on "nr_pages" output here, or was that mainly due to the parameter?
I think maybe it would be better to have byte fields, "offset" and
"count" like the other IO tracepoints (trace_nfs_initiate_read() for
example). Or do you see some advantages to using nr_pages?
We can get the offset with lru_to_page(pages) and of course "count"
with nr_pages*PAGE_SIZE
> The count of pages requested is reported. nfs_readpages does not
> wait for the READ requests to complete.
>
> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
> ---
> fs/nfs/nfstrace.h | 146 +++++++++++++++++++++++++++++++++++++++++++++++++++++
> fs/nfs/read.c | 11 ++--
> 2 files changed, 151 insertions(+), 6 deletions(-)
>
> diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
> index e9be65b52bfe..898308780df8 100644
> --- a/fs/nfs/nfstrace.h
> +++ b/fs/nfs/nfstrace.h
> @@ -862,6 +862,152 @@ TRACE_EVENT(nfs_sillyrename_unlink,
> )
> );
>
> +TRACE_EVENT(nfs_aop_readpage,
> + TP_PROTO(
> + const struct inode *inode,
> + struct page *page
> + ),
> +
> + TP_ARGS(inode, page),
> +
> + TP_STRUCT__entry(
> + __field(dev_t, dev)
> + __field(u32, fhandle)
> + __field(u64, fileid)
> + __field(u64, version)
> + __field(loff_t, offset)
> + ),
> +
> + TP_fast_assign(
> + const struct nfs_inode *nfsi = NFS_I(inode);
> +
> + __entry->dev = inode->i_sb->s_dev;
> + __entry->fileid = nfsi->fileid;
> + __entry->fhandle = nfs_fhandle_hash(&nfsi->fh);
> + __entry->version = inode_peek_iversion_raw(inode);
> + __entry->offset = page_index(page) << PAGE_SHIFT;
> + ),
> +
> + TP_printk(
> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu offset=%lld",
> + MAJOR(__entry->dev), MINOR(__entry->dev),
> + (unsigned long long)__entry->fileid,
> + __entry->fhandle, __entry->version,
> + __entry->offset
> + )
> +);
> +
> +TRACE_EVENT(nfs_aop_readpage_done,
> + TP_PROTO(
> + const struct inode *inode,
> + struct page *page,
> + int ret
> + ),
> +
> + TP_ARGS(inode, page, ret),
> +
> + TP_STRUCT__entry(
> + __field(dev_t, dev)
> + __field(u32, fhandle)
> + __field(int, ret)
> + __field(u64, fileid)
> + __field(u64, version)
> + __field(loff_t, offset)
> + ),
> +
> + TP_fast_assign(
> + const struct nfs_inode *nfsi = NFS_I(inode);
> +
> + __entry->dev = inode->i_sb->s_dev;
> + __entry->fileid = nfsi->fileid;
> + __entry->fhandle = nfs_fhandle_hash(&nfsi->fh);
> + __entry->version = inode_peek_iversion_raw(inode);
> + __entry->offset = page_index(page) << PAGE_SHIFT;
> + __entry->ret = ret;
> + ),
> +
> + TP_printk(
> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu offset=%lld ret=%d",
> + MAJOR(__entry->dev), MINOR(__entry->dev),
> + (unsigned long long)__entry->fileid,
> + __entry->fhandle, __entry->version,
> + __entry->offset, __entry->ret
> + )
> +);
> +
> +TRACE_EVENT(nfs_aop_readahead,
> + TP_PROTO(
> + const struct inode *inode,
> + unsigned int nr_pages
> + ),
> +
> + TP_ARGS(inode, nr_pages),
> +
> + TP_STRUCT__entry(
> + __field(dev_t, dev)
> + __field(u32, fhandle)
> + __field(u64, fileid)
> + __field(u64, version)
> + __field(unsigned int, nr_pages)
> + ),
> +
> + TP_fast_assign(
> + const struct nfs_inode *nfsi = NFS_I(inode);
> +
> + __entry->dev = inode->i_sb->s_dev;
> + __entry->fileid = nfsi->fileid;
> + __entry->fhandle = nfs_fhandle_hash(&nfsi->fh);
> + __entry->version = inode_peek_iversion_raw(inode);
> + __entry->nr_pages = nr_pages;
> + ),
> +
> + TP_printk(
> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu nr_pages=%u",
> + MAJOR(__entry->dev), MINOR(__entry->dev),
> + (unsigned long long)__entry->fileid,
> + __entry->fhandle, __entry->version,
> + __entry->nr_pages
> + )
> +);
> +
> +TRACE_EVENT(nfs_aop_readahead_done,
> + TP_PROTO(
> + const struct inode *inode,
> + unsigned int nr_pages,
> + int ret
> + ),
> +
> + TP_ARGS(inode, nr_pages, ret),
> +
> + TP_STRUCT__entry(
> + __field(dev_t, dev)
> + __field(u32, fhandle)
> + __field(int, ret)
> + __field(u64, fileid)
> + __field(u64, version)
> + __field(unsigned int, nr_pages)
> + ),
> +
> + TP_fast_assign(
> + const struct nfs_inode *nfsi = NFS_I(inode);
> +
> + __entry->dev = inode->i_sb->s_dev;
> + __entry->fileid = nfsi->fileid;
> + __entry->fhandle = nfs_fhandle_hash(&nfsi->fh);
> + __entry->version = inode_peek_iversion_raw(inode);
> + __entry->nr_pages = nr_pages;
> + __entry->ret = ret;
> + ),
> +
> + TP_printk(
> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu nr_pages=%u ret=%d",
> + MAJOR(__entry->dev), MINOR(__entry->dev),
> + (unsigned long long)__entry->fileid,
> + __entry->fhandle, __entry->version,
> + __entry->nr_pages, __entry->ret
> + )
> +);
> +
> TRACE_EVENT(nfs_initiate_read,
> TP_PROTO(
> const struct nfs_pgio_header *hdr
> diff --git a/fs/nfs/read.c b/fs/nfs/read.c
> index 08d6cc57cbc3..c8273d4b12ad 100644
> --- a/fs/nfs/read.c
> +++ b/fs/nfs/read.c
> @@ -337,8 +337,7 @@ int nfs_readpage(struct file *file, struct page *page)
> struct inode *inode = page_file_mapping(page)->host;
> int ret;
>
> - dprintk("NFS: nfs_readpage (%p %ld@%lu)\n",
> - page, PAGE_SIZE, page_index(page));
> + trace_nfs_aop_readpage(inode, page);
> nfs_inc_stats(inode, NFSIOS_VFSREADPAGE);
>
> /*
> @@ -390,9 +389,11 @@ int nfs_readpage(struct file *file, struct page *page)
> }
> out:
> put_nfs_open_context(desc.ctx);
> + trace_nfs_aop_readpage_done(inode, page, ret);
> return ret;
> out_unlock:
> unlock_page(page);
> + trace_nfs_aop_readpage_done(inode, page, ret);
> return ret;
> }
>
> @@ -403,10 +404,7 @@ int nfs_readpages(struct file *file, struct address_space *mapping,
> struct inode *inode = mapping->host;
> int ret;
>
> - dprintk("NFS: nfs_readpages (%s/%Lu %d)\n",
> - inode->i_sb->s_id,
> - (unsigned long long)NFS_FILEID(inode),
> - nr_pages);
> + trace_nfs_aop_readahead(inode, nr_pages);
> nfs_inc_stats(inode, NFSIOS_VFSREADPAGES);
>
> ret = -ESTALE;
> @@ -439,6 +437,7 @@ int nfs_readpages(struct file *file, struct address_space *mapping,
> read_complete:
> put_nfs_open_context(desc.ctx);
> out:
> + trace_nfs_aop_readahead_done(inode, nr_pages, ret);
> return ret;
> }
>
>
^ permalink raw reply [flat|nested] 13+ messages in thread
* Re: [PATCH v4 5/7] NFS: Replace dprintk callsites in nfs_readpage(s)
2021-11-02 19:36 ` David Wysochanski
@ 2021-11-02 19:41 ` Chuck Lever III
0 siblings, 0 replies; 13+ messages in thread
From: Chuck Lever III @ 2021-11-02 19:41 UTC (permalink / raw)
To: David Wysochanski; +Cc: Trond Myklebust, Linux NFS Mailing List
> On Nov 2, 2021, at 3:36 PM, David Wysochanski <dwysocha@redhat.com> wrote:
>
> On Sat, Oct 16, 2021 at 6:03 PM Chuck Lever <chuck.lever@oracle.com> wrote:
>>
>> These new events report slightly different information for readpage
>> and readpages/readahead.
>>
>> For readpage:
>> fsx-1387 [006] 380.761896: nfs_aop_readpage: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355910932437 offset=131072
>> fsx-1387 [006] 380.761900: nfs_aop_readpage_done: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355910932437 offset=131072 ret=0
>>
>> The index of a synchronous single-page read is reported.
>>
>> For readpages:
>>
>> fsx-1387 [006] 380.760847: nfs_aop_readahead: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355909932456 nr_pages=3
>> fsx-1387 [006] 380.760853: nfs_aop_readahead_done: fileid=00:28:2 fhandle=0x36fbbe51 version=1752899355909932456 nr_pages=3 ret=0
>>
>
> Chuck,
>
> I was doing more debugging and thought about the readahead trace event.
> Are you set on "nr_pages" output here, or was that mainly due to the parameter?
> I think maybe it would be better to have byte fields, "offset" and
> "count" like the other IO tracepoints (trace_nfs_initiate_read() for
> example). Or do you see some advantages to using nr_pages?
>
> We can get the offset with lru_to_page(pages) and of course "count"
> with nr_pages*PAGE_SIZE
IMO offset is interesting to include, but I don't think multiplying
by PAGE_SIZE adds much value. If you disagree, you can always tuck
that into the tracepoint's TP_fast_assign section.
>> The count of pages requested is reported. nfs_readpages does not
>> wait for the READ requests to complete.
>>
>> Signed-off-by: Chuck Lever <chuck.lever@oracle.com>
>> ---
>> fs/nfs/nfstrace.h | 146 +++++++++++++++++++++++++++++++++++++++++++++++++++++
>> fs/nfs/read.c | 11 ++--
>> 2 files changed, 151 insertions(+), 6 deletions(-)
>>
>> diff --git a/fs/nfs/nfstrace.h b/fs/nfs/nfstrace.h
>> index e9be65b52bfe..898308780df8 100644
>> --- a/fs/nfs/nfstrace.h
>> +++ b/fs/nfs/nfstrace.h
>> @@ -862,6 +862,152 @@ TRACE_EVENT(nfs_sillyrename_unlink,
>> )
>> );
>>
>> +TRACE_EVENT(nfs_aop_readpage,
>> + TP_PROTO(
>> + const struct inode *inode,
>> + struct page *page
>> + ),
>> +
>> + TP_ARGS(inode, page),
>> +
>> + TP_STRUCT__entry(
>> + __field(dev_t, dev)
>> + __field(u32, fhandle)
>> + __field(u64, fileid)
>> + __field(u64, version)
>> + __field(loff_t, offset)
>> + ),
>> +
>> + TP_fast_assign(
>> + const struct nfs_inode *nfsi = NFS_I(inode);
>> +
>> + __entry->dev = inode->i_sb->s_dev;
>> + __entry->fileid = nfsi->fileid;
>> + __entry->fhandle = nfs_fhandle_hash(&nfsi->fh);
>> + __entry->version = inode_peek_iversion_raw(inode);
>> + __entry->offset = page_index(page) << PAGE_SHIFT;
>> + ),
>> +
>> + TP_printk(
>> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu offset=%lld",
>> + MAJOR(__entry->dev), MINOR(__entry->dev),
>> + (unsigned long long)__entry->fileid,
>> + __entry->fhandle, __entry->version,
>> + __entry->offset
>> + )
>> +);
>> +
>> +TRACE_EVENT(nfs_aop_readpage_done,
>> + TP_PROTO(
>> + const struct inode *inode,
>> + struct page *page,
>> + int ret
>> + ),
>> +
>> + TP_ARGS(inode, page, ret),
>> +
>> + TP_STRUCT__entry(
>> + __field(dev_t, dev)
>> + __field(u32, fhandle)
>> + __field(int, ret)
>> + __field(u64, fileid)
>> + __field(u64, version)
>> + __field(loff_t, offset)
>> + ),
>> +
>> + TP_fast_assign(
>> + const struct nfs_inode *nfsi = NFS_I(inode);
>> +
>> + __entry->dev = inode->i_sb->s_dev;
>> + __entry->fileid = nfsi->fileid;
>> + __entry->fhandle = nfs_fhandle_hash(&nfsi->fh);
>> + __entry->version = inode_peek_iversion_raw(inode);
>> + __entry->offset = page_index(page) << PAGE_SHIFT;
>> + __entry->ret = ret;
>> + ),
>> +
>> + TP_printk(
>> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu offset=%lld ret=%d",
>> + MAJOR(__entry->dev), MINOR(__entry->dev),
>> + (unsigned long long)__entry->fileid,
>> + __entry->fhandle, __entry->version,
>> + __entry->offset, __entry->ret
>> + )
>> +);
>> +
>> +TRACE_EVENT(nfs_aop_readahead,
>> + TP_PROTO(
>> + const struct inode *inode,
>> + unsigned int nr_pages
>> + ),
>> +
>> + TP_ARGS(inode, nr_pages),
>> +
>> + TP_STRUCT__entry(
>> + __field(dev_t, dev)
>> + __field(u32, fhandle)
>> + __field(u64, fileid)
>> + __field(u64, version)
>> + __field(unsigned int, nr_pages)
>> + ),
>> +
>> + TP_fast_assign(
>> + const struct nfs_inode *nfsi = NFS_I(inode);
>> +
>> + __entry->dev = inode->i_sb->s_dev;
>> + __entry->fileid = nfsi->fileid;
>> + __entry->fhandle = nfs_fhandle_hash(&nfsi->fh);
>> + __entry->version = inode_peek_iversion_raw(inode);
>> + __entry->nr_pages = nr_pages;
>> + ),
>> +
>> + TP_printk(
>> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu nr_pages=%u",
>> + MAJOR(__entry->dev), MINOR(__entry->dev),
>> + (unsigned long long)__entry->fileid,
>> + __entry->fhandle, __entry->version,
>> + __entry->nr_pages
>> + )
>> +);
>> +
>> +TRACE_EVENT(nfs_aop_readahead_done,
>> + TP_PROTO(
>> + const struct inode *inode,
>> + unsigned int nr_pages,
>> + int ret
>> + ),
>> +
>> + TP_ARGS(inode, nr_pages, ret),
>> +
>> + TP_STRUCT__entry(
>> + __field(dev_t, dev)
>> + __field(u32, fhandle)
>> + __field(int, ret)
>> + __field(u64, fileid)
>> + __field(u64, version)
>> + __field(unsigned int, nr_pages)
>> + ),
>> +
>> + TP_fast_assign(
>> + const struct nfs_inode *nfsi = NFS_I(inode);
>> +
>> + __entry->dev = inode->i_sb->s_dev;
>> + __entry->fileid = nfsi->fileid;
>> + __entry->fhandle = nfs_fhandle_hash(&nfsi->fh);
>> + __entry->version = inode_peek_iversion_raw(inode);
>> + __entry->nr_pages = nr_pages;
>> + __entry->ret = ret;
>> + ),
>> +
>> + TP_printk(
>> + "fileid=%02x:%02x:%llu fhandle=0x%08x version=%llu nr_pages=%u ret=%d",
>> + MAJOR(__entry->dev), MINOR(__entry->dev),
>> + (unsigned long long)__entry->fileid,
>> + __entry->fhandle, __entry->version,
>> + __entry->nr_pages, __entry->ret
>> + )
>> +);
>> +
>> TRACE_EVENT(nfs_initiate_read,
>> TP_PROTO(
>> const struct nfs_pgio_header *hdr
>> diff --git a/fs/nfs/read.c b/fs/nfs/read.c
>> index 08d6cc57cbc3..c8273d4b12ad 100644
>> --- a/fs/nfs/read.c
>> +++ b/fs/nfs/read.c
>> @@ -337,8 +337,7 @@ int nfs_readpage(struct file *file, struct page *page)
>> struct inode *inode = page_file_mapping(page)->host;
>> int ret;
>>
>> - dprintk("NFS: nfs_readpage (%p %ld@%lu)\n",
>> - page, PAGE_SIZE, page_index(page));
>> + trace_nfs_aop_readpage(inode, page);
>> nfs_inc_stats(inode, NFSIOS_VFSREADPAGE);
>>
>> /*
>> @@ -390,9 +389,11 @@ int nfs_readpage(struct file *file, struct page *page)
>> }
>> out:
>> put_nfs_open_context(desc.ctx);
>> + trace_nfs_aop_readpage_done(inode, page, ret);
>> return ret;
>> out_unlock:
>> unlock_page(page);
>> + trace_nfs_aop_readpage_done(inode, page, ret);
>> return ret;
>> }
>>
>> @@ -403,10 +404,7 @@ int nfs_readpages(struct file *file, struct address_space *mapping,
>> struct inode *inode = mapping->host;
>> int ret;
>>
>> - dprintk("NFS: nfs_readpages (%s/%Lu %d)\n",
>> - inode->i_sb->s_id,
>> - (unsigned long long)NFS_FILEID(inode),
>> - nr_pages);
>> + trace_nfs_aop_readahead(inode, nr_pages);
>> nfs_inc_stats(inode, NFSIOS_VFSREADPAGES);
>>
>> ret = -ESTALE;
>> @@ -439,6 +437,7 @@ int nfs_readpages(struct file *file, struct address_space *mapping,
>> read_complete:
>> put_nfs_open_context(desc.ctx);
>> out:
>> + trace_nfs_aop_readahead_done(inode, nr_pages, ret);
>> return ret;
>> }
--
Chuck Lever
^ permalink raw reply [flat|nested] 13+ messages in thread
end of thread, other threads:[~2021-11-02 19:41 UTC | newest]
Thread overview: 13+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-10-16 22:02 [PATCH v4 0/7] Update RPC task pid as displayed by tracepoints Chuck Lever
2021-10-16 22:02 ` [PATCH v4 1/7] SUNRPC: Tracepoints should display tk_pid and cl_clid as a fixed-size field Chuck Lever
2021-10-16 22:02 ` [PATCH v4 2/7] SUNRPC: Avoid NULL pointer dereferences in tracepoints Chuck Lever
2021-10-20 18:43 ` Trond Myklebust
2021-10-20 19:39 ` Chuck Lever III
2021-10-20 20:09 ` Trond Myklebust
2021-10-16 22:02 ` [PATCH v4 3/7] SUNRPC: Use BIT() macro in rpc_show_xprt_state() Chuck Lever
2021-10-16 22:02 ` [PATCH v4 4/7] SUNRPC: Don't dereference xprt->snd_task if it's a cookie Chuck Lever
2021-10-16 22:02 ` [PATCH v4 5/7] NFS: Replace dprintk callsites in nfs_readpage(s) Chuck Lever
2021-11-02 19:36 ` David Wysochanski
2021-11-02 19:41 ` Chuck Lever III
2021-10-16 22:02 ` [PATCH v4 6/7] SUNRPC: Trace calls to .rpc_call_done Chuck Lever
2021-10-16 22:03 ` [PATCH v4 7/7] NFS: Remove --> and <-- dprintk call sites Chuck Lever
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.