From patchwork Sat Oct 16 22:02:24 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Chuck Lever III X-Patchwork-Id: 12563917 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 1DC26C433F5 for ; Sat, 16 Oct 2021 22:02:37 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 015F160F46 for ; Sat, 16 Oct 2021 22:02:36 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S244689AbhJPWEn (ORCPT ); Sat, 16 Oct 2021 18:04:43 -0400 Received: from mail.kernel.org ([198.145.29.99]:35894 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S235312AbhJPWEe (ORCPT ); Sat, 16 Oct 2021 18:04:34 -0400 Received: by mail.kernel.org (Postfix) with ESMTPSA id DD08360E98; Sat, 16 Oct 2021 22:02:25 +0000 (UTC) From: Chuck Lever To: trondmy@hammerspace.com Cc: linux-nfs@vger.kernel.org Subject: [PATCH v4 1/7] SUNRPC: Tracepoints should display tk_pid and cl_clid as a fixed-size field Date: Sat, 16 Oct 2021 18:02:24 -0400 Message-Id: <163442174475.1585.11324752452421571022.stgit@morisot.1015granger.net> X-Mailer: git-send-email 2.33.0 In-Reply-To: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> References: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> User-Agent: StGit/1.3 MIME-Version: 1.0 X-Developer-Signature: v=1; a=openpgp-sha256; l=21196; h=from:subject:message-id; bh=oZVCKndZ5rCodU9tsigAl6RQ84zdBUB4zTUab++GOJ8=; b=owEBbQKS/ZANAwAIATNqszNvZn+XAcsmYgBha0vwS741v/oy04N2nX0PGdbO4TtNJkjngzWyN9mj nwtG9EWJAjMEAAEIAB0WIQQosuWwEobfJDzyPv4zarMzb2Z/lwUCYWtL8AAKCRAzarMzb2Z/l3Y/D/ 0VXo0NBvpw/ibqkvFFcMcIe6yKOkXjknrkGFKsmIMZyKiwQPmxfQ/BC3i9o6O7qlhB6wzvvY5ZHjRA 3Ah0htw1x4+Ejf/un+UzgRC402QMbltW/DAa78+fmaKL5IUpn9NsigKlCzbL5bGrXSDDlvwedGbGJm u7xfLgfvW2xksDaT3eA+w2nbJ4lMzivDs0Q7fezVrsG5YurPZKIqZrdkSNzfYvheTRPxXotmCn++At e2SMUs72lxUxJmsHmipACCdwabvdIKkqqdTjCXCzf7mAvnj12omIf7UBEO+c7tc/bRty5PbSm9O+4J 0EleZfWuG6IG2MFKNh3w6G0Pfd/qTFfXHBYm3GcesxyVstcGgPchJPrFaoyR4C3KiG8pXt4ZSKtm/+ hjP+uOGID1pX24fKI1zr1XBlBgWfQS/dX/xtCqD0vHzuY+BUSvXsBoza0M2Ei9P2Y/2wFC4WJKG1y4 krBq+Z4Mi7YGFbEar+eawdTlLeUNsvSjX9uP/AHGvCwqeYyMtx+E71bjeWWE3FCcyK+afLiyCOJHft xxPe++ddlcaWseg3OxG+A8ryG0At0RHjpPQyigRDLOj8FmWz/cyNUxkL7BETwzTZmsMg3rdALbNq2W rOmtMLAHBjo/eTHJmH6SD5niNwU0fKGmEM0SqjxYA1E3js2pO8Pz6j9siRdQ== X-Developer-Key: i=chuck.lever@oracle.com; a=openpgp; fpr=28B2E5B01286DF243CF23EFE336AB3336F667F97 Precedence: bulk List-ID: X-Mailing-List: linux-nfs@vger.kernel.org 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 --- 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 +#include 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 #include +#include + #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 +#include + /** ** 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 #include #include + #include +#include /** ** 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 #include +#include + 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 + +#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 */ From patchwork Sat Oct 16 22:02:31 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Chuck Lever III X-Patchwork-Id: 12563915 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 21234C433FE for ; Sat, 16 Oct 2021 22:02:37 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id E4CAA60F44 for ; Sat, 16 Oct 2021 22:02:36 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S235312AbhJPWEo (ORCPT ); Sat, 16 Oct 2021 18:04:44 -0400 Received: from mail.kernel.org ([198.145.29.99]:35944 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S244675AbhJPWEl (ORCPT ); Sat, 16 Oct 2021 18:04:41 -0400 Received: by mail.kernel.org (Postfix) with ESMTPSA id 79F3B60EFF; Sat, 16 Oct 2021 22:02:32 +0000 (UTC) From: Chuck Lever To: trondmy@hammerspace.com Cc: linux-nfs@vger.kernel.org Subject: [PATCH v4 2/7] SUNRPC: Avoid NULL pointer dereferences in tracepoints Date: Sat, 16 Oct 2021 18:02:31 -0400 Message-Id: <163442175137.1585.5220370195383350175.stgit@morisot.1015granger.net> X-Mailer: git-send-email 2.33.0 In-Reply-To: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> References: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> User-Agent: StGit/1.3 MIME-Version: 1.0 X-Developer-Signature: v=1; a=openpgp-sha256; l=18085; h=from:subject:message-id; bh=au/ZwR11OhfwYnzM9ABThEmr7OmbAH6kXBN2yN17kqQ=; b=owEBbQKS/ZANAwAIATNqszNvZn+XAcsmYgBha0v3By/4UMR94thUI22Qqk/POABCoERI3dyQSc1m o7nw2vmJAjMEAAEIAB0WIQQosuWwEobfJDzyPv4zarMzb2Z/lwUCYWtL9wAKCRAzarMzb2Z/l8O1D/ 4iuWgHP3ythuwOYPFCKnJMOOrpXuHMmwae/8kUuGw1aeHJnF8P6otT+oypeJv2KfPe+12JBXs4Ne+L uBOzsCl5ML1bQubnpkq6aQ9Ot5BvYBxhmQeTeuR9S7HGOo1jqQtE7zZGc2mUbxVDebC9+VayX754jl jUdI/Bpwf4jhc64+IGhEGaMLplkvvbqsYNT8odlk84rX0cpHz1vHsyf6jHaw7O18CfZstBjZL42mQU dPUg9zfjH/0aEFEjkrH6G+sx8UV6zS+I4sV0hMCYB0AfNBKORXmbQL2bfKq2KMRXM6+ncEBSuWTupG VSJr6Dl4BC+yqEe08wr6Kz/2msdtpaSjSFAolNfIjZH5jG+dbuCF/qF0JM+wjcJNqO5KV64c8xlazW b9FwIgJwq04Icm8Vh/wqENbHAFDSxUg9l6mZNV4t0ELFjJUIH3Mm5w5VDAy0woA3b3XsQgxKthrvil EoLGUQ1hLfeKsG1RF+tjDulB15tokPVaxissqpQmA9BkPDXI4LENUrdPMJgwtEdn6QF42W7Yr2HGmk 83es1HSeQFsd/7h6mQ8DUM6snAfiWwteAp5kQslmPVUUjcHGzXorP7vYVsV1x4cxvyzkOXpf87G9bv Ag2IqyrIRIn77BMOwaOrn8YTykE2+eIvFv7tDLivSXDA5i0ysT+Ghsh/08zw== X-Developer-Key: i=chuck.lever@oracle.com; a=openpgp; fpr=28B2E5B01286DF243CF23EFE336AB3336F667F97 Precedence: bulk List-ID: X-Mailing-List: linux-nfs@vger.kernel.org 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 --- 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 +#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 \ From patchwork Sat Oct 16 22:02:38 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Chuck Lever III X-Patchwork-Id: 12563919 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 9401AC433F5 for ; Sat, 16 Oct 2021 22:02:42 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 7C4A560EE9 for ; Sat, 16 Oct 2021 22:02:42 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S244690AbhJPWEs (ORCPT ); Sat, 16 Oct 2021 18:04:48 -0400 Received: from mail.kernel.org ([198.145.29.99]:35994 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S244675AbhJPWEr (ORCPT ); Sat, 16 Oct 2021 18:04:47 -0400 Received: by mail.kernel.org (Postfix) with ESMTPSA id 16C3360EE9; Sat, 16 Oct 2021 22:02:39 +0000 (UTC) From: Chuck Lever To: trondmy@hammerspace.com Cc: linux-nfs@vger.kernel.org Subject: [PATCH v4 3/7] SUNRPC: Use BIT() macro in rpc_show_xprt_state() Date: Sat, 16 Oct 2021 18:02:38 -0400 Message-Id: <163442175797.1585.4544033531964902715.stgit@morisot.1015granger.net> X-Mailer: git-send-email 2.33.0 In-Reply-To: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> References: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> User-Agent: StGit/1.3 MIME-Version: 1.0 X-Developer-Signature: v=1; a=openpgp-sha256; l=1696; h=from:subject:message-id; bh=1EiWbj6QUPzM5ywUkYTzPyLkzpq9RCePMcHQI1S/3zw=; b=owEBbQKS/ZANAwAIATNqszNvZn+XAcsmYgBha0v+2o3BYOPkz/YgQaS6dYvBHfXOXvPuZGLNDYF2 ehYVBj+JAjMEAAEIAB0WIQQosuWwEobfJDzyPv4zarMzb2Z/lwUCYWtL/gAKCRAzarMzb2Z/l7LoD/ 9MvfKuCo1+ZAfAAMqJxlKlPQg+f5CZob+byZxXDSG9lJYYwCjqxB/oiryMhQPRjGCyNs9HyKdQBpKC z0dBOsiFha/uLk01aqIIXmXz337aLtJ1O5YWu6S5M5avy4x5IGrhmpwAUCFCWmazLxMHzazZb3IsNN XYwTsnDQQjnE3vFqnkzbsFgMk8P9Xas4EtfGi4Z1MAm+JeDr68KGkdVFdhZJxpaLfEePLvvpY68m4K rplX76DV7/f374GbSiB9e7/QG9z7JAjErZJ+B1DyLMxPauBFwDJv+HYHssqpRy4iAMW62rMcw33pM5 HwlnygiQMMC36wE/eGFSumZbwdTVp6s6vRhoPqJd1c/utt8DK6c9AF5piKCrfVfsgXMqCKsZAFiYSO Xnb9Jytn6N34g5jVVWvKHQahAlyY71o/pXXJBvqBKbB1KiQvLYwhVBqRQ2jfSn2rZ2vFe1TX0bA8mF 4Aogj2C8Dr18e9SXI473Z+CexmYbp6BFKUo3Hrj8T+XqM+5xizSfb9egQ1E1dGwHDrJpukq9bM2EaY AJtQ/qEKAoOcBnpu7+SeOjFtxpmnH+AfxNRTJtgSgLBKxsU6HWzuKVSdC3B8yS6/Ji3sohJ7xiHnSd 8r1szkC+stjQRSPsNyx123yhrfgpWyQL2b/aH/qB7JJs7FWYZSKQQJsXZS9g== X-Developer-Key: i=chuck.lever@oracle.com; a=openpgp; fpr=28B2E5B01286DF243CF23EFE336AB3336F667F97 Precedence: bulk List-ID: X-Mailing-List: linux-nfs@vger.kernel.org Clean up: BIT() is preferred over open-coding the shift. Signed-off-by: Chuck Lever --- 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( From patchwork Sat Oct 16 22:02:44 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Chuck Lever III X-Patchwork-Id: 12563921 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id B8DB4C433F5 for ; Sat, 16 Oct 2021 22:02:50 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id A01B860EE9 for ; Sat, 16 Oct 2021 22:02:50 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S244691AbhJPWE5 (ORCPT ); Sat, 16 Oct 2021 18:04:57 -0400 Received: from mail.kernel.org ([198.145.29.99]:36048 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S244675AbhJPWEy (ORCPT ); Sat, 16 Oct 2021 18:04:54 -0400 Received: by mail.kernel.org (Postfix) with ESMTPSA id 9580060EE9; Sat, 16 Oct 2021 22:02:45 +0000 (UTC) From: Chuck Lever To: trondmy@hammerspace.com Cc: linux-nfs@vger.kernel.org Subject: [PATCH v4 4/7] SUNRPC: Don't dereference xprt->snd_task if it's a cookie Date: Sat, 16 Oct 2021 18:02:44 -0400 Message-Id: <163442176448.1585.14151942803213662102.stgit@morisot.1015granger.net> X-Mailer: git-send-email 2.33.0 In-Reply-To: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> References: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> User-Agent: StGit/1.3 MIME-Version: 1.0 X-Developer-Signature: v=1; a=openpgp-sha256; l=2181; h=from:subject:message-id; bh=Kw4yNjULbSjcpbOVAfTWvgi1gPr+frxbyoW4hgZ0ecc=; b=owEBbQKS/ZANAwAIATNqszNvZn+XAcsmYgBha0wEAjFubBrKAcg8Wh/6K/4gdDjr0WbgD+isj+5M l2PWRkqJAjMEAAEIAB0WIQQosuWwEobfJDzyPv4zarMzb2Z/lwUCYWtMBAAKCRAzarMzb2Z/l0mYD/ 4wRYk6fXpfZnK+wNWNPHEOO5ct2Rdp19K10/VF0/2ZAx7WmxWSTPG1k+qxA1lTaQVaGSSahU9Zd5DJ VOwmFBGQ57/lnB1mOz5pXIEzgJgPadasYV1Of9boHM+XEtid1Cn8+Wr2JjfLVZRvSCrUki9qvEAJO1 ac5uM5fSWSPU9eupmDBEATKjKNhNmvUlmIkc0uE17bnQthFfoavz+36laSBWuAxPlUEOYoxU967vZk XhjmWsJGZ4reW/UOgUc/+iHvUtHSLuF+WXV7le8F4jDF03fHuwIFA76TL3xvGMMTdrF8LN3nYD/f25 8BTJQmQyshhNX2whU/DiAvm6eFf/aEqppJx7vvC4G73KmNmmoQsN49wK7rma8U49MMKIu2g6ONQ7vA /8vlHVPd/Zuh86r4a0qA0F72iptViH1/B5D/THp6Fv8zRTwhOX5S03xC0cuF/MO08brv9AmuPLQlt+ GPyOrWGYCE2l1GN4J/D/uLw59vZYc8isrgHBgc/7rh/6jhqLCpq28MO69ljgl6iPkyb27H/U/L2P7h OIQk36dVc61EV/7jjZIn8YhMVqCP/KYkmfliHydE/O8MH70lHZU0AHONCC5WIQNl5dhAEgJPmu7PNN MExioHjC/vwNHNt1KmKOD1rzHFnqHPTjONR6l82V07iCsaEVIAy5NThZ87Pw== X-Developer-Key: i=chuck.lever@oracle.com; a=openpgp; fpr=28B2E5B01286DF243CF23EFE336AB3336F667F97 Precedence: bulk List-ID: X-Mailing-List: linux-nfs@vger.kernel.org Fixes: e26d9972720e ("SUNRPC: Clean up scheduling of autoclose") Signed-off-by: Chuck Lever --- 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 \ From patchwork Sat Oct 16 22:02:51 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Chuck Lever III X-Patchwork-Id: 12563923 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id B6B4AC433F5 for ; Sat, 16 Oct 2021 22:02:55 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id A0D6A60F44 for ; Sat, 16 Oct 2021 22:02:55 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S236924AbhJPWFB (ORCPT ); Sat, 16 Oct 2021 18:05:01 -0400 Received: from mail.kernel.org ([198.145.29.99]:36104 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S235616AbhJPWFA (ORCPT ); Sat, 16 Oct 2021 18:05:00 -0400 Received: by mail.kernel.org (Postfix) with ESMTPSA id 231C060F44; Sat, 16 Oct 2021 22:02:52 +0000 (UTC) From: Chuck Lever To: trondmy@hammerspace.com Cc: linux-nfs@vger.kernel.org Subject: [PATCH v4 5/7] NFS: Replace dprintk callsites in nfs_readpage(s) Date: Sat, 16 Oct 2021 18:02:51 -0400 Message-Id: <163442177101.1585.8852378085253353318.stgit@morisot.1015granger.net> X-Mailer: git-send-email 2.33.0 In-Reply-To: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> References: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> User-Agent: StGit/1.3 MIME-Version: 1.0 X-Developer-Signature: v=1; a=openpgp-sha256; l=6475; h=from:subject:message-id; bh=QRIi+ucGa28hhEpCKpW5Hvpm8ML8uMSVa6gsQjDQ7qE=; b=owEBbQKS/ZANAwAIATNqszNvZn+XAcsmYgBha0wLHGakPi5LNF6mbd57fy3JZ9quFD295C6wpLev xTRX5v+JAjMEAAEIAB0WIQQosuWwEobfJDzyPv4zarMzb2Z/lwUCYWtMCwAKCRAzarMzb2Z/l20kEA CTxLYg7k4huyg9UqQ76bThKWhpp5jalJqCxrA3uZcsJK1/vJp470q7jzi1NM0Il0jGsv4RP4w06Mnf +0kBvv919iAsAwfLmwloV9iLcuzR1LD2snBBG3MlxHJ5bsktop9sF3ctWX4qnHop5DG/h4kJfaHVE/ POmKcrrXzOj/19ByWj3Xhij69aJ70VLflABK6iggQdOhW1XA+sTdsGdlng/kZUJOv2kwhEIRhsXdM6 4oOSNNQDlQRGHI7US5iJTp6HmgMAqNDTNEZjaK3g3n0XsJHow0eFV+2hTjfP2A1cEQJyv+a4q0kL2v Tlm9eYp0yH1msJpwA9Uomil4h+lTciEyErKAE1iXiahf1j8b3DAOlrRFHFIpAGsc5eS0Kw3zeV49e/ LCGLK1OwGy3F2I5jXKo/V186TAF1nhwARpNMsdPjoDcfTk/AJzMewJdk3UO5KoJB32B4OI/MeGZ/nv ZT/mqLiDyJtchQqHO35t8PhgfImvkpfIfxdDzhHvDIyzgTh401xIZJLTIwrjCDk/2dU6XtTXy91gEj cged0s8Rzag5ouYiKOg+641UixUloPMrP/4Qm9aXywsUToc3AsHaYdwTwVXeGbXENyVe5tQzQvWPui wM/UX/4FGg7op84CZj6jvPUmeNNPys0GHScSwZm6nFPaWRE1Rnw3hgCCr70w== X-Developer-Key: i=chuck.lever@oracle.com; a=openpgp; fpr=28B2E5B01286DF243CF23EFE336AB3336F667F97 Precedence: bulk List-ID: X-Mailing-List: linux-nfs@vger.kernel.org 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 --- 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; } From patchwork Sat Oct 16 22:02:57 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Chuck Lever III X-Patchwork-Id: 12563925 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id CEB66C433F5 for ; Sat, 16 Oct 2021 22:03:00 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id B2D0560F46 for ; Sat, 16 Oct 2021 22:03:00 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S244675AbhJPWFI (ORCPT ); Sat, 16 Oct 2021 18:05:08 -0400 Received: from mail.kernel.org ([198.145.29.99]:36170 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S235616AbhJPWFH (ORCPT ); Sat, 16 Oct 2021 18:05:07 -0400 Received: by mail.kernel.org (Postfix) with ESMTPSA id A4E4660EE9; Sat, 16 Oct 2021 22:02:58 +0000 (UTC) From: Chuck Lever To: trondmy@hammerspace.com Cc: linux-nfs@vger.kernel.org Subject: [PATCH v4 6/7] SUNRPC: Trace calls to .rpc_call_done Date: Sat, 16 Oct 2021 18:02:57 -0400 Message-Id: <163442177754.1585.5840349306714736549.stgit@morisot.1015granger.net> X-Mailer: git-send-email 2.33.0 In-Reply-To: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> References: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> User-Agent: StGit/1.3 MIME-Version: 1.0 X-Developer-Signature: v=1; a=openpgp-sha256; l=5603; h=from:subject:message-id; bh=u10Cv/Zc4BbSfP51ipbDMeZmXW6FIPjDZTzR66hjdf8=; b=owEBbQKS/ZANAwAIATNqszNvZn+XAcsmYgBha0wRYMNuy2nqJenhab2+r75jBsGcQ0EZzOGIkeQ7 iWI3IxuJAjMEAAEIAB0WIQQosuWwEobfJDzyPv4zarMzb2Z/lwUCYWtMEQAKCRAzarMzb2Z/l3NZD/ 9G7KRsXNLyUwPJVyUWcOa80uc9tnPxhrBEQ2iWf+EogePflhtPuEJTTUi8atw1rCtdesWAA9zKZmnI b0Ip2lPVFXcxClqjMWC9KSo1Fbf1QXvOdcRmPlntV3alxs3LpI43BCR96qOqbO6QqnX8dXCIM95KBZ jjFmKv0dHVyPHQsawOQHy9PV7mTC0DHlB156LgCTiA6uGyQ/sksnNmkAy0f6Te3sZtMi2PhN1CdCWo x5SxyU5tBQUQvGLoO9UxNtxeEG4CtQdC36/GBUfxVGsd+ITMLfHo36Q7cJw8A55OHWWpMdW0R3lXCF lm85hSLQ35r8h5s7mXzSLJzLz7BAQr5Spt7RxZmeKRWgfH9VFncaLHsRaugeX9KKGOeQ/pMBnHQLeQ 7BUZvxPbPdYHizmUOEs7X0RsfLF6mzfMDRhYPMti1oU9vSKflMZGyU4NHDX5SoirkgK2z6mZS6FXZ0 t5HhwtJCKPwd6+ONfx9LrLK4qC+JBsTJWV/Y41tKmszRClxDrT4Cq4FE9u5D7iAqnAhZNO9TXnoR77 bvGJEE0yICVXgRJX4ndZTImUl2EemcFdL8LgJ+Ji6+eXV/BCtD6YOr8WhBgwydhUZ15esTvnlQd2yr WDgylTClDPrFHPPdWAuvdtzXcCgzzwAFmDYtqwRBs0sILZmxMRsIrUIn8g7Q== X-Developer-Key: i=chuck.lever@oracle.com; a=openpgp; fpr=28B2E5B01286DF243CF23EFE336AB3336F667F97 Precedence: bulk List-ID: X-Mailing-List: linux-nfs@vger.kernel.org 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 --- 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 */ From patchwork Sat Oct 16 22:03:04 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Chuck Lever III X-Patchwork-Id: 12563927 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 83456C433EF for ; Sat, 16 Oct 2021 22:03:07 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 656F360F57 for ; Sat, 16 Oct 2021 22:03:07 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S244692AbhJPWFO (ORCPT ); Sat, 16 Oct 2021 18:05:14 -0400 Received: from mail.kernel.org ([198.145.29.99]:36216 "EHLO mail.kernel.org" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S235616AbhJPWFN (ORCPT ); Sat, 16 Oct 2021 18:05:13 -0400 Received: by mail.kernel.org (Postfix) with ESMTPSA id 318AA60F57; Sat, 16 Oct 2021 22:03:05 +0000 (UTC) From: Chuck Lever To: trondmy@hammerspace.com Cc: linux-nfs@vger.kernel.org Subject: [PATCH v4 7/7] NFS: Remove --> and <-- dprintk call sites Date: Sat, 16 Oct 2021 18:03:04 -0400 Message-Id: <163442178407.1585.13005264694170305348.stgit@morisot.1015granger.net> X-Mailer: git-send-email 2.33.0 In-Reply-To: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> References: <163442096873.1585.8967342784030733636.stgit@morisot.1015granger.net> User-Agent: StGit/1.3 MIME-Version: 1.0 X-Developer-Signature: v=1; a=openpgp-sha256; l=12007; h=from:subject:message-id; bh=VSc6Cb0mFxPIAQDYsqnvw8sxZZ5cuebOYaZR04iQupc=; b=owEBbQKS/ZANAwAIATNqszNvZn+XAcsmYgBha0wY+lE+V5a6qUFWOsmTw2jnT1FsOj/lL3kXRglf 7zZabMKJAjMEAAEIAB0WIQQosuWwEobfJDzyPv4zarMzb2Z/lwUCYWtMGAAKCRAzarMzb2Z/l56bD/ sHkzSw6cfTbUFqh62JhkB7qniVjQLc0XV7HxeR5rqEar9G15rvTF/YimUG1/nw6HSG3t/xqssvy/Oo gZ+Bajbe0ui0aioIPCjj/4pcPPrJ2hoSLZGHqpORMIqFBMXlmk6eLsEaPzblSKOkKn41MhuW2yWsxj 443DCz+TOe2KNSJGFI0hXgFlAJETt96k3smP/DOMz9AHq9DQs0YXp4GD2c+p1X8mX8zUfLw8tdUMd2 rERwMSTeMyiDGaBZoTXeL7l3B8d6rGTSw2cbulEmeZl3T6kn5Oymc5dpekEPlrR0q6cMb9spFP59Y/ gNY9lCIbodtZS7/CmYw4AAkGCRTrN0ywWIdRbRpZJaYMjvzXfJyxD4wwCZEvnpVxLfS3Pb2VhtCSgF yieH4DCYC2gPuIIe0vnURqDtUPqscwtyyb+Zt+jyorqG/5Q43ly39fwP0QUVGXB5/zdgmwedvLBhgU tJJkQ/mNNVv+n0ir2h8E/bgZ6JOV8z44xjiLn1j+4XPel9mUGwcsuXwlmsEuQw0Wq/mWPvb7+EQVTO zA8A+0Ymujx/Phxcn6Xciaycg1jsDDjGixeQRgQMnqLVLS0RPTP1U5EjQVgqybVIuhFx97cE/LrlVn 9G7Sh4fWpzVD8Zi36MgRX78MlL1EzRx+Fml+3LqHqEK29t8eaBm2o4uWe/9Q== X-Developer-Key: i=chuck.lever@oracle.com; a=openpgp; fpr=28B2E5B01286DF243CF23EFE336AB3336F667F97 Precedence: bulk List-ID: X-Mailing-List: linux-nfs@vger.kernel.org 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 --- 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);