From patchwork Mon Feb 25 07:10:48 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steve French X-Patchwork-Id: 10828303 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 87D2D1399 for ; Mon, 25 Feb 2019 07:11:02 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 6E2092A91C for ; Mon, 25 Feb 2019 07:11:02 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 60C102A9A4; Mon, 25 Feb 2019 07:11:02 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-8.0 required=2.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FROM,MAILING_LIST_MULTI,RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id BA1802A91C for ; Mon, 25 Feb 2019 07:11:01 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1727181AbfBYHLB (ORCPT ); Mon, 25 Feb 2019 02:11:01 -0500 Received: from mail-pf1-f178.google.com ([209.85.210.178]:36895 "EHLO mail-pf1-f178.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1727050AbfBYHLB (ORCPT ); Mon, 25 Feb 2019 02:11:01 -0500 Received: by mail-pf1-f178.google.com with SMTP id s22so4058500pfh.4 for ; Sun, 24 Feb 2019 23:11:00 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:from:date:message-id:subject:to; bh=NxZvqMR4DlkXx2V1Q3KmKoUxZ279xccaqMZH5shDUPg=; b=WUM4VQkwwFeP5GEW4YVuEMVsTFZ/cUsdTu69vUFNaAsQ9iwWB86BKhX+xIza8vRo71 kIG9uxBB2C1TLt71IoKmIkH9pJXEz5UuRfFy1KUIblMpnOgL97K9ovj4jGpEFsBYr5hG z4H9wdZ0E8JZlZrODdVw57vzkypChkFpWIVatapEZkypYR4VjKj4EN1oGy1t39XPxptb uTlESTqB3g6mkOw0f9OCwPzeYzymwwkynpBXy8xTiXsSmy6nWoZrBIzpafCjItZANBX4 ZIIBwucXbXw0NbhxObC65Oo+PtCwDLxQAvtW9+dYkCf2x9z4U+XU07oMNV6arNlkw8VB qPGQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:from:date:message-id:subject:to; bh=NxZvqMR4DlkXx2V1Q3KmKoUxZ279xccaqMZH5shDUPg=; b=QysXoD6ICppUq+sONOG2CBe6efcQIV/jJsrKDfl0ERNLUzDx3w44wb0lMsfUwWc5tr vgjKGckRH+KDchBhtZgDw0FwSkQlfB95MCx3WzIzaHzc3nUmfVTXSwTGw+5uHQ4pFFd9 GdfzGXyZNneOw2882ZENwYhLhZe2JVjj//tu2KxQOOroTnMR69UgrW1qqhAbFaJUO5tc p4uvtvT1Gusfz9IzFm/h13V1ciTFYtLU4zyhMiIkLSah/d3cUFJlc6Zm6ZMYi6W7eO3H HZr7+t36PYFfx4xn/sU9PA/DpenvQla6U1fq70+frlg680w33zll+mCLzCw4jNaeQxzf C5vw== X-Gm-Message-State: AHQUAubVsY0uTMj3NIhtdUCU6k4+vY9Ir+klX5Z+/Su6/r92fNBxR+ns 6MfxeUxIywKUuvLMmwj3s4BefqWwcBQuGltrHTYPGfJn X-Google-Smtp-Source: AHgI3Ibc5HFfcA5Qykv/l+oZxq8hX6scMpDct3G3zrE1Yg8+g4DVa1cp/0JCtiimF78AJlfIa/6xCkvK7ExSnRb/3Nw= X-Received: by 2002:a63:2c8a:: with SMTP id s132mr17593133pgs.440.1551078659583; Sun, 24 Feb 2019 23:10:59 -0800 (PST) MIME-Version: 1.0 From: Steve French Date: Mon, 25 Feb 2019 01:10:48 -0600 Message-ID: Subject: [PATCH] smb3 tracepoints for read_enter, write_enter and query_dir_enter To: CIFS Sender: linux-cifs-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-cifs@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP May be helpful to get timing info for large reads/writes/query_dirs or to better find hangs or operations that trigger reconnects. Sample output from various readdirs with the new tracepoints # trace-cmd show # tracer: nop # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | ls-30820 [004] .... 77492.662476: smb3_query_dir_enter: xid=8 sid=0x2fa2c9ab tid=0x1377432b fid=0xfc37e912 offset=0x0 len=0x4000 ls-30820 [004] .... 77492.663906: smb3_query_dir_done: xid=8 sid=0x2fa2c9ab tid=0x1377432b fid=0xfc37e912 offset=0x0 len=0x13 ls-30820 [004] .... 77492.664107: smb3_query_dir_enter: xid=9 sid=0x2fa2c9ab tid=0x1377432b fid=0xfc37e912 offset=0x0 len=0x4000 ls-30820 [004] .... 77492.664639: smb3_query_dir_err: xid=9 sid=0x2fa2c9ab tid=0x1377432b fid=0xfc37e912 offset=0x0 len=0x0 rc=0 bash-27628 [000] .... 77502.150630: smb3_query_dir_enter: xid=12 sid=0x2fa2c9ab tid=0x1377432b fid=0x26e379e1 offset=0x0 len=0x4000 bash-27628 [000] .... 77502.151783: smb3_query_dir_done: xid=12 sid=0x2fa2c9ab tid=0x1377432b fid=0x26e379e1 offset=0x0 len=0x13 bash-27628 [000] .... 77502.151855: smb3_query_dir_enter: xid=13 sid=0x2fa2c9ab tid=0x1377432b fid=0x26e379e1 offset=0x0 len=0x4000 bash-27628 [000] .... 77502.152378: smb3_query_dir_err: xid=13 sid=0x2fa2c9ab tid=0x1377432b fid=0x26e379e1 offset=0x0 len=0x0 rc=0 ls-30821 [001] .... 77502.156573: smb3_query_dir_enter: xid=15 sid=0x2fa2c9ab tid=0x1377432b fid=0x4f5cedcd offset=0x0 len=0x4000 ls-30821 [001] .... 77502.157308: smb3_query_dir_done: xid=15 sid=0x2fa2c9ab tid=0x1377432b fid=0x4f5cedcd offset=0x0 len=0x3 ls-30821 [001] .... 77502.157364: smb3_query_dir_enter: xid=16 sid=0x2fa2c9ab tid=0x1377432b fid=0x4f5cedcd offset=0x0 len=0x4000 ls-30821 [001] .... 77502.157880: smb3_query_dir_err: xid=16 sid=0x2fa2c9ab tid=0x1377432b fid=0x4f5cedcd offset=0x0 len=0x0 rc=0 ls-30821 [001] .... 77502.159819: smb3_query_dir_enter: xid=18 sid=0x2fa2c9ab tid=0x1377432b fid=0xcb88f96d offset=0x0 len=0x4000 ls-30821 [003] .... 77502.160591: smb3_query_dir_done: xid=18 sid=0x2fa2c9ab tid=0x1377432b fid=0xcb88f96d offset=0x0 len=0x3 ls-30821 [003] .... 77502.160651: smb3_query_dir_enter: xid=19 sid=0x2fa2c9ab tid=0x1377432b fid=0xcb88f96d offset=0x0 len=0x4000 ls-30821 [003] .... 77502.161106: smb3_query_dir_err: xid=19 sid=0x2fa2c9ab tid=0x1377432b fid=0xcb88f96d offset=0x0 len=0x0 rc=0 ls-30821 [003] .... 77502.162653: smb3_query_dir_enter: xid=21 sid=0x2fa2c9ab tid=0x1377432b fid=0x9ca0a6bc offset=0x0 len=0x4000 ls-30821 [003] .... 77502.163334: smb3_query_dir_done: xid=21 sid=0x2fa2c9ab tid=0x1377432b fid=0x9ca0a6bc offset=0x0 len=0x3 ls-30821 [003] .... 77502.163382: smb3_query_dir_enter: xid=22 sid=0x2fa2c9ab tid=0x1377432b fid=0x9ca0a6bc offset=0x0 len=0x4000 ls-30821 [003] .... 77502.163894: smb3_query_dir_err: xid=22 sid=0x2fa2c9ab tid=0x1377432b fid=0x9ca0a6bc offset=0x0 len=0x0 rc=0 Reviewed-by: Pavel Shilovsky From 7b4bedb17a56a20fa3b78678aad07a7eb9e7d762 Mon Sep 17 00:00:00 2001 From: Steve French Date: Mon, 25 Feb 2019 00:52:43 -0600 Subject: [PATCH] smb3: Add tracepoints for read, write and query_dir enter Allows tracing begin (not just completion) of read, write and query_dir which may be helpful in finding slow requests and other timing information Signed-off-by: Steve French --- fs/cifs/smb2pdu.c | 15 +++++++++++++++ fs/cifs/trace.h | 3 +++ 2 files changed, 18 insertions(+) diff --git a/fs/cifs/smb2pdu.c b/fs/cifs/smb2pdu.c index b6e2a1f40078..358951840756 100644 --- a/fs/cifs/smb2pdu.c +++ b/fs/cifs/smb2pdu.c @@ -3142,6 +3142,11 @@ smb2_new_read_req(void **buf, unsigned int *total_len, req->MinimumCount = 0; 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); #ifdef CONFIG_CIFS_SMB_DIRECT /* * If we want to do a RDMA write, fill in and append @@ -3541,6 +3546,9 @@ smb2_async_writev(struct cifs_writedata *wdata, req->DataOffset = cpu_to_le16( offsetof(struct smb2_write_req, Buffer)); req->RemainingBytes = 0; + + trace_smb3_write_enter(0 /* xid */, wdata->cfile->fid.persistent_fid, + tcon->tid, tcon->ses->Suid, wdata->offset, wdata->bytes); #ifdef CONFIG_CIFS_SMB_DIRECT /* * If we want to do a server RDMA read, fill in and append @@ -3688,6 +3696,10 @@ SMB2_write(const unsigned int xid, struct cifs_io_parms *io_parms, offsetof(struct smb2_write_req, Buffer)); req->RemainingBytes = 0; + trace_smb3_write_enter(xid, io_parms->persistent_fid, + io_parms->tcon->tid, io_parms->tcon->ses->Suid, + io_parms->offset, io_parms->length); + iov[0].iov_base = (char *)req; /* 1 for Buffer */ iov[0].iov_len = total_len - 1; @@ -3850,6 +3862,9 @@ SMB2_query_directory(const unsigned int xid, struct cifs_tcon *tcon, rqst.rq_iov = iov; rqst.rq_nvec = 2; + trace_smb3_query_dir_enter(xid, persistent_fid, tcon->tid, + tcon->ses->Suid, index, output_size); + rc = cifs_send_recv(xid, ses, &rqst, &resp_buftype, flags, &rsp_iov); cifs_small_buf_release(req); rsp = (struct smb2_query_directory_rsp *)rsp_iov.iov_base; diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h index bf4f43f6893b..660176e34dde 100644 --- a/fs/cifs/trace.h +++ b/fs/cifs/trace.h @@ -101,6 +101,9 @@ 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(write_done); DEFINE_SMB3_RW_DONE_EVENT(read_done); DEFINE_SMB3_RW_DONE_EVENT(query_dir_done); -- 2.17.1