From patchwork Wed Apr 6 23:04:51 2022 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: David Howells X-Patchwork-Id: 12804207 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 kanga.kvack.org (kanga.kvack.org [205.233.56.17]) by smtp.lore.kernel.org (Postfix) with ESMTP id 65183C433EF for ; Wed, 6 Apr 2022 23:09:33 +0000 (UTC) Received: by kanga.kvack.org (Postfix) id 12D606B0085; Wed, 6 Apr 2022 19:05:10 -0400 (EDT) Received: by kanga.kvack.org (Postfix, from userid 40) id 08EE56B0087; Wed, 6 Apr 2022 19:05:10 -0400 (EDT) X-Delivered-To: int-list-linux-mm@kvack.org Received: by kanga.kvack.org (Postfix, from userid 63042) id E23CF6B0088; Wed, 6 Apr 2022 19:05:09 -0400 (EDT) X-Delivered-To: linux-mm@kvack.org Received: from relay.hostedemail.com (relay.hostedemail.com [64.99.140.26]) by kanga.kvack.org (Postfix) with ESMTP id D09BC6B0085 for ; Wed, 6 Apr 2022 19:05:09 -0400 (EDT) Received: from smtpin18.hostedemail.com (a10.router.float.18 [10.200.18.1]) by unirelay13.hostedemail.com (Postfix) with ESMTP id AE51461DAB for ; Wed, 6 Apr 2022 23:04:59 +0000 (UTC) X-FDA: 79327986318.18.886C421 Received: from us-smtp-delivery-124.mimecast.com (us-smtp-delivery-124.mimecast.com [170.10.129.124]) by imf16.hostedemail.com (Postfix) with ESMTP id 18A4C180002 for ; Wed, 6 Apr 2022 23:04:58 +0000 (UTC) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=redhat.com; s=mimecast20190719; t=1649286298; h=from:from:reply-to:subject:subject:date:date:message-id:message-id: to:to:cc:cc:mime-version:mime-version:content-type:content-type: content-transfer-encoding:content-transfer-encoding: in-reply-to:in-reply-to:references:references; bh=7ksHuD9EsHcVMNVLSmO/uWKDVO0pBQnbXvRVLyq28ew=; b=NMJf5OglpLUqTCVYs3+YNZXYK13GaoXc+zS4pwWjxXMLR3RccisXeN1Vsg6xNGNN54TcUZ vVWs+Rh5nK5auEgHHWpIzj6k8WdYu+e9YHEpEGH+cO8nxMNyGITCFF2XK9nwfaOgi2WfM1 nW2bcy7F448DMMIhX/tB/y2jrUY4puU= Received: from mimecast-mx02.redhat.com (mimecast-mx02.redhat.com [66.187.233.88]) by relay.mimecast.com with ESMTP with STARTTLS (version=TLSv1.2, cipher=TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384) id us-mta-177-dI7o37mHPsuDVVUf2e_fkA-1; Wed, 06 Apr 2022 19:04:53 -0400 X-MC-Unique: dI7o37mHPsuDVVUf2e_fkA-1 Received: from smtp.corp.redhat.com (int-mx01.intmail.prod.int.rdu2.redhat.com [10.11.54.1]) (using TLSv1.2 with cipher AECDH-AES256-SHA (256/256 bits)) (No client certificate requested) by mimecast-mx02.redhat.com (Postfix) with ESMTPS id 49EDE85A5BC; Wed, 6 Apr 2022 23:04:53 +0000 (UTC) Received: from warthog.procyon.org.uk (unknown [10.33.37.45]) by smtp.corp.redhat.com (Postfix) with ESMTP id DAF4640CF910; Wed, 6 Apr 2022 23:04:51 +0000 (UTC) Organization: Red Hat UK Ltd. Registered Address: Red Hat UK Ltd, Amberley Place, 107-111 Peascod Street, Windsor, Berkshire, SI4 1TE, United Kingdom. Registered in England and Wales under Company Registration No. 3798903 Subject: [PATCH 12/14] cifs: Expose netfs subrequest debug ID and index in read tracepoints From: David Howells To: linux-cachefs@redhat.com Cc: Steve French , Shyam Prasad N , Rohith Surabattula , linux-cifs@vger.kernel.org, dhowells@redhat.com, Steve French , Shyam Prasad N , Rohith Surabattula , Jeff Layton , linux-cifs@vger.kernel.org, linux-fsdevel@vger.kernel.org, linux-kernel@vger.kernel.org, linux-mm@kvack.org Date: Thu, 07 Apr 2022 00:04:51 +0100 Message-ID: <164928629102.457102.17739324885642025232.stgit@warthog.procyon.org.uk> In-Reply-To: <164928615045.457102.10607899252434268982.stgit@warthog.procyon.org.uk> References: <164928615045.457102.10607899252434268982.stgit@warthog.procyon.org.uk> User-Agent: StGit/1.4 MIME-Version: 1.0 X-Scanned-By: MIMEDefang 2.84 on 10.11.54.1 Authentication-Results: imf16.hostedemail.com; dkim=pass header.d=redhat.com header.s=mimecast20190719 header.b=NMJf5Ogl; spf=none (imf16.hostedemail.com: domain of dhowells@redhat.com has no SPF policy when checking 170.10.129.124) smtp.mailfrom=dhowells@redhat.com; dmarc=pass (policy=none) header.from=redhat.com X-Stat-Signature: yru5p8uksteix3m5wkdzrs3urep547zk X-Rspam-User: X-Rspamd-Server: rspam12 X-Rspamd-Queue-Id: 18A4C180002 X-HE-Tag: 1649286298-396095 X-Bogosity: Ham, tests=bogofilter, spamicity=0.000000, version=1.2.4 Sender: owner-linux-mm@kvack.org Precedence: bulk X-Loop: owner-majordomo@kvack.org List-ID: Expose the netfs request debug ID and subrequest index in the smb3_read_enter, smb3_read_done and smb3_read_err tracepoints to match the netfs tracepoints for convenient grepping. Also expose the xid in some tracepoints where it is now available by virtue of being stashed in the cifs_io_subrequest struct. In future, the write tracepoints should be able to expose this also. Signed-off-by: David Howells cc: Steve French cc: Shyam Prasad N cc: Rohith Surabattula cc: linux-cifs@vger.kernel.org --- fs/cifs/smb2pdu.c | 35 ++++++++----- fs/cifs/trace.h | 144 ++++++++++++++++++++++++++++++++++++++++++++++------- 2 files changed, 147 insertions(+), 32 deletions(-) diff --git a/fs/cifs/smb2pdu.c b/fs/cifs/smb2pdu.c index 952f242bee55..9a828b56d95a 100644 --- a/fs/cifs/smb2pdu.c +++ b/fs/cifs/smb2pdu.c @@ -4041,10 +4041,12 @@ smb2_new_read_req(void **buf, unsigned int *total_len, req->Length = cpu_to_le32(io_parms->length); req->Offset = cpu_to_le64(io_parms->offset); - trace_smb3_read_enter(0 /* xid */, - io_parms->persistent_fid, - io_parms->tcon->tid, io_parms->tcon->ses->Suid, - io_parms->offset, io_parms->length); + trace_smb3_read_enter(rdata ? rdata->rreq->debug_id : 0, + rdata ? rdata->subreq.debug_index : 0, + rdata ? rdata->xid : 0, + io_parms->persistent_fid, + io_parms->tcon->tid, io_parms->tcon->ses->Suid, + io_parms->offset, io_parms->length); #ifdef CONFIG_CIFS_SMB_DIRECT /* * If we want to do a RDMA write, fill in and append @@ -4174,12 +4176,16 @@ smb2_readv_callback(struct mid_q_entry *mid) #endif if (rdata->result && rdata->result != -ENODATA) { cifs_stats_fail_inc(tcon, SMB2_READ_HE); - trace_smb3_read_err(rdata->xid, + trace_smb3_read_err(rdata->rreq->debug_id, + rdata->subreq.debug_index, + rdata->xid, rdata->req->cfile->fid.persistent_fid, tcon->tid, tcon->ses->Suid, rdata->offset, rdata->bytes, rdata->result); } else - trace_smb3_read_done(0 /* xid */, + trace_smb3_read_done(rdata->rreq->debug_id, + rdata->subreq.debug_index, + rdata->xid, rdata->req->cfile->fid.persistent_fid, tcon->tid, tcon->ses->Suid, rdata->offset, rdata->got_bytes); @@ -4260,7 +4266,9 @@ smb2_async_readv(struct cifs_io_subrequest *rdata) &rdata->credits); if (rc) { cifs_stats_fail_inc(io_parms.tcon, SMB2_READ_HE); - trace_smb3_read_err(rdata->xid, io_parms.persistent_fid, + trace_smb3_read_err(rdata->rreq->debug_id, + rdata->subreq.debug_index, + rdata->xid, io_parms.persistent_fid, io_parms.tcon->tid, io_parms.tcon->ses->Suid, io_parms.offset, io_parms.length, rc); @@ -4311,22 +4319,23 @@ SMB2_read(const unsigned int xid, struct cifs_io_parms *io_parms, if (rc != -ENODATA) { cifs_stats_fail_inc(io_parms->tcon, SMB2_READ_HE); cifs_dbg(VFS, "Send error in read = %d\n", rc); - trace_smb3_read_err(xid, + trace_smb3_read_err(0, 0, xid, req->PersistentFileId, io_parms->tcon->tid, ses->Suid, io_parms->offset, io_parms->length, rc); } else - trace_smb3_read_done(xid, req->PersistentFileId, io_parms->tcon->tid, + trace_smb3_read_done(0, 0, xid, + req->PersistentFileId, io_parms->tcon->tid, ses->Suid, io_parms->offset, 0); free_rsp_buf(resp_buftype, rsp_iov.iov_base); cifs_small_buf_release(req); return rc == -ENODATA ? 0 : rc; } else - trace_smb3_read_done(xid, - req->PersistentFileId, - io_parms->tcon->tid, ses->Suid, - io_parms->offset, io_parms->length); + trace_smb3_read_done(0, 0, xid, + req->PersistentFileId, + io_parms->tcon->tid, ses->Suid, + io_parms->offset, io_parms->length); cifs_small_buf_release(req); diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h index 6cecf302dcfd..c85cf0971eee 100644 --- a/fs/cifs/trace.h +++ b/fs/cifs/trace.h @@ -21,6 +21,62 @@ /* For logging errors in read or write */ DECLARE_EVENT_CLASS(smb3_rw_err_class, + TP_PROTO(unsigned int rreq_debug_id, + unsigned int rreq_debug_index, + unsigned int xid, + __u64 fid, + __u32 tid, + __u64 sesid, + __u64 offset, + __u32 len, + int rc), + TP_ARGS(rreq_debug_id, rreq_debug_index, + xid, fid, tid, sesid, offset, len, rc), + TP_STRUCT__entry( + __field(unsigned int, rreq_debug_id) + __field(unsigned int, rreq_debug_index) + __field(unsigned int, xid) + __field(__u64, fid) + __field(__u32, tid) + __field(__u64, sesid) + __field(__u64, offset) + __field(__u32, len) + __field(int, rc) + ), + TP_fast_assign( + __entry->rreq_debug_id = rreq_debug_id; + __entry->rreq_debug_index = rreq_debug_index; + __entry->xid = xid; + __entry->fid = fid; + __entry->tid = tid; + __entry->sesid = sesid; + __entry->offset = offset; + __entry->len = len; + __entry->rc = rc; + ), + TP_printk("\tR=%08x[%x] xid=%u sid=0x%llx tid=0x%x fid=0x%llx offset=0x%llx len=0x%x rc=%d", + __entry->rreq_debug_id, __entry->rreq_debug_index, + __entry->xid, __entry->sesid, __entry->tid, __entry->fid, + __entry->offset, __entry->len, __entry->rc) +) + +#define DEFINE_SMB3_RW_ERR_EVENT(name) \ +DEFINE_EVENT(smb3_rw_err_class, smb3_##name, \ + TP_PROTO(unsigned int rreq_debug_id, \ + unsigned int rreq_debug_index, \ + unsigned int xid, \ + __u64 fid, \ + __u32 tid, \ + __u64 sesid, \ + __u64 offset, \ + __u32 len, \ + int rc), \ + TP_ARGS(rreq_debug_id, rreq_debug_index, xid, fid, tid, sesid, offset, len, rc)) + +DEFINE_SMB3_RW_ERR_EVENT(read_err); + +/* For logging errors in other file I/O ops */ +DECLARE_EVENT_CLASS(smb3_other_err_class, TP_PROTO(unsigned int xid, __u64 fid, __u32 tid, @@ -52,8 +108,8 @@ DECLARE_EVENT_CLASS(smb3_rw_err_class, __entry->offset, __entry->len, __entry->rc) ) -#define DEFINE_SMB3_RW_ERR_EVENT(name) \ -DEFINE_EVENT(smb3_rw_err_class, smb3_##name, \ +#define DEFINE_SMB3_OTHER_ERR_EVENT(name) \ +DEFINE_EVENT(smb3_other_err_class, smb3_##name, \ TP_PROTO(unsigned int xid, \ __u64 fid, \ __u32 tid, \ @@ -63,15 +119,67 @@ DEFINE_EVENT(smb3_rw_err_class, smb3_##name, \ int rc), \ TP_ARGS(xid, fid, tid, sesid, offset, len, rc)) -DEFINE_SMB3_RW_ERR_EVENT(write_err); -DEFINE_SMB3_RW_ERR_EVENT(read_err); -DEFINE_SMB3_RW_ERR_EVENT(query_dir_err); -DEFINE_SMB3_RW_ERR_EVENT(zero_err); -DEFINE_SMB3_RW_ERR_EVENT(falloc_err); +DEFINE_SMB3_OTHER_ERR_EVENT(write_err); +DEFINE_SMB3_OTHER_ERR_EVENT(query_dir_err); +DEFINE_SMB3_OTHER_ERR_EVENT(zero_err); +DEFINE_SMB3_OTHER_ERR_EVENT(falloc_err); /* For logging successful read or write */ DECLARE_EVENT_CLASS(smb3_rw_done_class, + TP_PROTO(unsigned int rreq_debug_id, + unsigned int rreq_debug_index, + unsigned int xid, + __u64 fid, + __u32 tid, + __u64 sesid, + __u64 offset, + __u32 len), + TP_ARGS(rreq_debug_id, rreq_debug_index, + xid, fid, tid, sesid, offset, len), + TP_STRUCT__entry( + __field(unsigned int, rreq_debug_id) + __field(unsigned int, rreq_debug_index) + __field(unsigned int, xid) + __field(__u64, fid) + __field(__u32, tid) + __field(__u64, sesid) + __field(__u64, offset) + __field(__u32, len) + ), + TP_fast_assign( + __entry->rreq_debug_id = rreq_debug_id; + __entry->rreq_debug_index = rreq_debug_index; + __entry->xid = xid; + __entry->fid = fid; + __entry->tid = tid; + __entry->sesid = sesid; + __entry->offset = offset; + __entry->len = len; + ), + TP_printk("R=%08x[%x] xid=%u sid=0x%llx tid=0x%x fid=0x%llx offset=0x%llx len=0x%x", + __entry->rreq_debug_id, __entry->rreq_debug_index, + __entry->xid, __entry->sesid, __entry->tid, __entry->fid, + __entry->offset, __entry->len) +) + +#define DEFINE_SMB3_RW_DONE_EVENT(name) \ +DEFINE_EVENT(smb3_rw_done_class, smb3_##name, \ + TP_PROTO(unsigned int rreq_debug_id, \ + unsigned int rreq_debug_index, \ + unsigned int xid, \ + __u64 fid, \ + __u32 tid, \ + __u64 sesid, \ + __u64 offset, \ + __u32 len), \ + TP_ARGS(rreq_debug_id, rreq_debug_index, xid, fid, tid, sesid, offset, len)) + +DEFINE_SMB3_RW_DONE_EVENT(read_enter); +DEFINE_SMB3_RW_DONE_EVENT(read_done); + +/* For logging successful other op */ +DECLARE_EVENT_CLASS(smb3_other_done_class, TP_PROTO(unsigned int xid, __u64 fid, __u32 tid, @@ -100,8 +208,8 @@ DECLARE_EVENT_CLASS(smb3_rw_done_class, __entry->offset, __entry->len) ) -#define DEFINE_SMB3_RW_DONE_EVENT(name) \ -DEFINE_EVENT(smb3_rw_done_class, smb3_##name, \ +#define DEFINE_SMB3_OTHER_DONE_EVENT(name) \ +DEFINE_EVENT(smb3_other_done_class, smb3_##name, \ TP_PROTO(unsigned int xid, \ __u64 fid, \ __u32 tid, \ @@ -110,16 +218,14 @@ DEFINE_EVENT(smb3_rw_done_class, smb3_##name, \ __u32 len), \ TP_ARGS(xid, fid, tid, sesid, offset, len)) -DEFINE_SMB3_RW_DONE_EVENT(write_enter); -DEFINE_SMB3_RW_DONE_EVENT(read_enter); -DEFINE_SMB3_RW_DONE_EVENT(query_dir_enter); -DEFINE_SMB3_RW_DONE_EVENT(zero_enter); -DEFINE_SMB3_RW_DONE_EVENT(falloc_enter); -DEFINE_SMB3_RW_DONE_EVENT(write_done); -DEFINE_SMB3_RW_DONE_EVENT(read_done); -DEFINE_SMB3_RW_DONE_EVENT(query_dir_done); -DEFINE_SMB3_RW_DONE_EVENT(zero_done); -DEFINE_SMB3_RW_DONE_EVENT(falloc_done); +DEFINE_SMB3_OTHER_DONE_EVENT(write_enter); +DEFINE_SMB3_OTHER_DONE_EVENT(query_dir_enter); +DEFINE_SMB3_OTHER_DONE_EVENT(zero_enter); +DEFINE_SMB3_OTHER_DONE_EVENT(falloc_enter); +DEFINE_SMB3_OTHER_DONE_EVENT(write_done); +DEFINE_SMB3_OTHER_DONE_EVENT(query_dir_done); +DEFINE_SMB3_OTHER_DONE_EVENT(zero_done); +DEFINE_SMB3_OTHER_DONE_EVENT(falloc_done); /* * For handle based calls other than read and write, and get/set info