From patchwork Mon Feb 25 22:27:06 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steve French X-Patchwork-Id: 10829243 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 E0097139A for ; Mon, 25 Feb 2019 22:27:21 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id C57E52B361 for ; Mon, 25 Feb 2019 22:27:21 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id B6EF92B3A4; Mon, 25 Feb 2019 22:27:21 +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 D88F82B361 for ; Mon, 25 Feb 2019 22:27:20 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726842AbfBYW1U (ORCPT ); Mon, 25 Feb 2019 17:27:20 -0500 Received: from mail-pg1-f181.google.com ([209.85.215.181]:44445 "EHLO mail-pg1-f181.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726575AbfBYW1U (ORCPT ); Mon, 25 Feb 2019 17:27:20 -0500 Received: by mail-pg1-f181.google.com with SMTP id j3so5128583pgm.11 for ; Mon, 25 Feb 2019 14:27:19 -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=/Xisd/jqaO42X92M0XRoPwpL3ZRA/KYRxL1QG+fjxzM=; b=jbMC0iSYg9+yxxJvkM8t5R+eFfvNJ5+KmhNRX7Pj4r342R+WsS/cEjwnQjjNYA7U1G mVISLyB+VML/MyOeBSCR+W0DLbeagYrBpKMCSgpQIPdBg3xSfe1uS0d20s6AMn6Sobn6 6uxwPcp6HoSuRH+XDWRo1hLTIztDWb04M3TW51Y1krG5cfYutZRG6S926LjUPiPepnn2 GJZ3LA3B00PKX0fB62EduPo0NM8YeAc5b8PpE6imtPBtarNpmOHX36Nfq+CNbHvl9cwl Me0EgE9xZc0+2KGbfUmVhxFHGpH2N/5LLf9UqqVej2+mkQmLK0nNJ+G6hL8fQPjTpDxR 5Tnw== 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=/Xisd/jqaO42X92M0XRoPwpL3ZRA/KYRxL1QG+fjxzM=; b=QteNkFgJdpabYyWnlSzGP2g6F0HmaUS7JNv/CnAVXX74HfM+ZkVyyHuI+CqrnhIisj RpbSzDGKmd3AdJ7XBhw0MdXoTyCFjJd2rABDIZQ7YiV7+7SJexdCH28laCoqzC37/IWd Z78fVy5JOrCQYRvTYloLDWjuO7yVU3hknITA05gvppOASo5d2HIbq7sX7glwggxbt9cA HnQRnLaa118YHC3vYExL9HRvLsTRU2GdopbwsQFc66K3UgzAhrVmiG/8RwhfjJw0wIjp 9aHy7QgPjDZ1W/cnvWgH7jZWGz5v4OVIWUQzA9w3KEkAZSlCibmP0SO36A1nb3NHSoOr oqvA== X-Gm-Message-State: AHQUAuaFq+A3b4s7PXJomKPe95xKJEsg/hPAm4AQB3beDv4xygL9O7G+ dmPl56plbtcDQJW2SSqW0w1uoYwJOAR8gRcmDQ6krOpf X-Google-Smtp-Source: AHgI3IbIewNCyyHQ9m54p1YmA5YQ/Sdm5PLN+MkS2invkVgc9foNrCd+JL3K0SudWbHXuF6UFCWNijLlqH80ZO1A8bM= X-Received: by 2002:a63:2c8a:: with SMTP id s132mr21220006pgs.440.1551133638839; Mon, 25 Feb 2019 14:27:18 -0800 (PST) MIME-Version: 1.0 From: Steve French Date: Mon, 25 Feb 2019 16:27:06 -0600 Message-ID: Subject: [PATCH] dynamic tracing open_enter/done 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 Sample output (note that they are mostly compounded so fid is not very meaningful - and set to 0) # trace-cmd show # tracer: nop # # _-----=> irqs-off # / _----=> need-resched # | / _---=> hardirq/softirq # || / _--=> preempt-depth # ||| / delay # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | ls-1008 [001] .... 97979.221345: smb3_open_enter: xid=8 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x0 des_access=0x81 ls-1008 [001] .... 97979.222446: smb3_open_done: xid=8 sid=0xfab79a42 tid=0x4b599fda fid=0xec26ce8a cr_opts=0x0 des_access=0x81 ls-1009 [007] .... 97985.278984: smb3_open_enter: xid=11 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x0 des_access=0x80 ls-1009 [007] .... 97985.280496: smb3_open_done: xid=11 sid=0xfab79a42 tid=0x4b599fda fid=0x0 cr_opts=0x0 des_access=0x80 ls-1009 [007] .... 97985.280569: smb3_open_enter: xid=12 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x0 des_access=0x81 ls-1009 [003] .... 97985.281311: smb3_open_err: xid=12 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x0 des_access=0x81 rc=-13 stat-1013 [005] .... 97993.537550: smb3_open_enter: xid=14 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x0 des_access=0x80 stat-1013 [005] .... 97993.538634: smb3_open_err: xid=14 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x0 des_access=0x80 rc=-2 mkdir-1015 [006] .... 97997.445397: smb3_open_enter: xid=15 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x0 des_access=0x80 mkdir-1015 [006] .... 97997.446442: smb3_open_err: xid=15 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x0 des_access=0x80 rc=-2 mkdir-1015 [006] .... 97997.446457: smb3_open_enter: xid=16 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x1 des_access=0x100 mkdir-1015 [006] .... 97997.447839: smb3_open_done: xid=16 sid=0xfab79a42 tid=0x4b599fda fid=0x0 cr_opts=0x1 des_access=0x100 mkdir-1015 [006] .... 97997.447852: smb3_open_enter: xid=16 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x0 des_access=0x80 mkdir-1015 [006] .... 97997.449092: smb3_open_done: xid=16 sid=0xfab79a42 tid=0x4b599fda fid=0x0 cr_opts=0x0 des_access=0x80 stat-1017 [006] .... 98002.176448: smb3_open_enter: xid=17 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x0 des_access=0x80 stat-1017 [006] .... 98002.177836: smb3_open_done: xid=17 sid=0xfab79a42 tid=0x4b599fda fid=0x0 cr_opts=0x0 des_access=0x80 touch-1018 [007] .... 98006.350783: smb3_open_enter: xid=18 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x40 des_access=0x40000080 touch-1018 [007] .... 98006.351938: smb3_open_done: xid=18 sid=0xfab79a42 tid=0x4b599fda fid=0x25565488 cr_opts=0x40 des_access=0x40000080 touch-1018 [007] .... 98006.352410: smb3_open_enter: xid=19 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x0 des_access=0x100 touch-1018 [007] .... 98006.353429: smb3_open_done: xid=19 sid=0xfab79a42 tid=0x4b599fda fid=0x0 cr_opts=0x0 des_access=0x100 rm-1022 [006] .... 98011.406241: smb3_open_enter: xid=21 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x0 des_access=0x80 rm-1022 [006] .... 98011.407548: smb3_open_done: xid=21 sid=0xfab79a42 tid=0x4b599fda fid=0x0 cr_opts=0x0 des_access=0x80 rm-1022 [006] .... 98011.407596: smb3_open_enter: xid=22 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x201000 des_access=0x10000 rm-1022 [006] .... 98011.408723: smb3_open_done: xid=22 sid=0xfab79a42 tid=0x4b599fda fid=0x0 cr_opts=0x201000 des_access=0x10000 rmdir-1023 [001] .... 98017.810408: smb3_open_enter: xid=23 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x0 des_access=0x80 rmdir-1023 [001] .... 98017.811916: smb3_open_done: xid=23 sid=0xfab79a42 tid=0x4b599fda fid=0x0 cr_opts=0x0 des_access=0x80 rmdir-1023 [001] .... 98017.811934: smb3_open_enter: xid=24 sid=0xfab79a42 tid=0x4b599fda cr_opts=0x1 des_access=0x10000 rmdir-1023 [002] .... 98017.813449: smb3_open_done: xid=24 sid=0xfab79a42 tid=0x4b599fda fid=0x0 cr_opts=0x1 des_access=0x10000 Reviewed-by: Ronnie Sahlberg From a28e9bf2ebec7a9aabcd94497022e5a335c28f81 Mon Sep 17 00:00:00 2001 From: Steve French Date: Mon, 25 Feb 2019 16:18:18 -0600 Subject: [PATCH] smb3: improve dynamic tracing of open and compounding Add dynamic trace point for open_enter (and mkdir enter) and result of open on compounded calls. Signed-off-by: Steve French --- fs/cifs/smb2inode.c | 12 +++++++++++- fs/cifs/smb2ops.c | 6 +++--- fs/cifs/smb2pdu.c | 10 +++++++--- fs/cifs/smb2proto.h | 6 +++--- fs/cifs/trace.h | 41 ++++++++++++++++++++++++++++++++++++++++- 5 files changed, 64 insertions(+), 11 deletions(-) diff --git a/fs/cifs/smb2inode.c b/fs/cifs/smb2inode.c index 01a76bccdb8d..803ee490f7c7 100644 --- a/fs/cifs/smb2inode.c +++ b/fs/cifs/smb2inode.c @@ -90,7 +90,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon, memset(&open_iov, 0, sizeof(open_iov)); rqst[num_rqst].rq_iov = open_iov; rqst[num_rqst].rq_nvec = SMB2_CREATE_IOV_SIZE; - rc = SMB2_open_init(tcon, &rqst[num_rqst], &oplock, &oparms, + rc = SMB2_open_init(xid, tcon, &rqst[num_rqst], &oplock, &oparms, utf16_path); kfree(utf16_path); if (rc) @@ -237,6 +237,16 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon, finished: SMB2_open_free(&rqst[0]); + if (rc) + trace_smb3_open_err(xid, tcon->tid, ses->Suid, + oparms.create_options, + oparms.desired_access, rc); + else + trace_smb3_open_done(xid, 0 /* fid hard to parse here */, + tcon->tid, ses->Suid, + oparms.create_options, + oparms.desired_access); + switch (command) { case SMB2_OP_QUERY_INFO: if (rc == 0) { diff --git a/fs/cifs/smb2ops.c b/fs/cifs/smb2ops.c index 1243407c9546..37472fdeaff2 100644 --- a/fs/cifs/smb2ops.c +++ b/fs/cifs/smb2ops.c @@ -1020,7 +1020,7 @@ smb2_set_ea(const unsigned int xid, struct cifs_tcon *tcon, oparms.fid = &fid; oparms.reconnect = false; - rc = SMB2_open_init(tcon, &rqst[0], &oplock, &oparms, utf16_path); + rc = SMB2_open_init(xid, tcon, &rqst[0], &oplock, &oparms, utf16_path); if (rc) goto sea_exit; smb2_set_next_command(tcon, &rqst[0]); @@ -1306,7 +1306,7 @@ smb2_ioctl_query_info(const unsigned int xid, oparms.fid = &fid; oparms.reconnect = false; - rc = SMB2_open_init(tcon, &rqst[0], &oplock, &oparms, path); + rc = SMB2_open_init(xid, tcon, &rqst[0], &oplock, &oparms, path); if (rc) goto iqinf_exit; smb2_set_next_command(tcon, &rqst[0]); @@ -1972,7 +1972,7 @@ smb2_query_info_compound(const unsigned int xid, struct cifs_tcon *tcon, oparms.fid = &fid; oparms.reconnect = false; - rc = SMB2_open_init(tcon, &rqst[0], &oplock, &oparms, utf16_path); + rc = SMB2_open_init(xid, tcon, &rqst[0], &oplock, &oparms, utf16_path); if (rc) goto qic_exit; smb2_set_next_command(tcon, &rqst[0]); diff --git a/fs/cifs/smb2pdu.c b/fs/cifs/smb2pdu.c index b774b43edfbd..e6ff515fb4ce 100644 --- a/fs/cifs/smb2pdu.c +++ b/fs/cifs/smb2pdu.c @@ -2196,6 +2196,8 @@ int smb311_posix_mkdir(const unsigned int xid, struct inode *inode, rqst.rq_iov = iov; rqst.rq_nvec = n_iov; + trace_smb3_posix_mkdir_enter(xid, tcon->tid, ses->Suid, CREATE_NOT_FILE, + FILE_WRITE_ATTRIBUTES); /* resource #4: response buffer */ rc = cifs_send_recv(xid, ses, &rqst, &resp_buftype, flags, &rsp_iov); if (rc) { @@ -2226,7 +2228,8 @@ int smb311_posix_mkdir(const unsigned int xid, struct inode *inode, } int -SMB2_open_init(struct cifs_tcon *tcon, struct smb_rqst *rqst, __u8 *oplock, +SMB2_open_init(const unsigned int xid, struct cifs_tcon *tcon, + struct smb_rqst *rqst, __u8 *oplock, struct cifs_open_parms *oparms, __le16 *path) { struct TCP_Server_Info *server = tcon->ses->server; @@ -2359,7 +2362,8 @@ SMB2_open_init(struct cifs_tcon *tcon, struct smb_rqst *rqst, __u8 *oplock, return rc; } - + trace_smb3_open_enter(xid, tcon->tid, tcon->ses->Suid, + oparms->create_options, oparms->desired_access); rqst->rq_nvec = n_iov; return 0; } @@ -2410,7 +2414,7 @@ SMB2_open(const unsigned int xid, struct cifs_open_parms *oparms, __le16 *path, rqst.rq_iov = iov; rqst.rq_nvec = SMB2_CREATE_IOV_SIZE; - rc = SMB2_open_init(tcon, &rqst, oplock, oparms, path); + rc = SMB2_open_init(xid, tcon, &rqst, oplock, oparms, path); if (rc) goto creat_exit; diff --git a/fs/cifs/smb2proto.h b/fs/cifs/smb2proto.h index 87733b27a65f..1e5ba6a793ad 100644 --- a/fs/cifs/smb2proto.h +++ b/fs/cifs/smb2proto.h @@ -136,9 +136,9 @@ extern int SMB2_open(const unsigned int xid, struct cifs_open_parms *oparms, __le16 *path, __u8 *oplock, struct smb2_file_all_info *buf, struct kvec *err_iov, int *resp_buftype); -extern int SMB2_open_init(struct cifs_tcon *tcon, struct smb_rqst *rqst, - __u8 *oplock, struct cifs_open_parms *oparms, - __le16 *path); +extern int SMB2_open_init(const unsigned int xid, struct cifs_tcon *tcon, + struct smb_rqst *rqst, __u8 *oplock, + struct cifs_open_parms *oparms, __le16 *path); extern void SMB2_open_free(struct smb_rqst *rqst); extern int SMB2_ioctl(const unsigned int xid, struct cifs_tcon *tcon, u64 persistent_fid, u64 volatile_fid, u32 opcode, diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h index 660176e34dde..b6352b68f18b 100644 --- a/fs/cifs/trace.h +++ b/fs/cifs/trace.h @@ -411,8 +411,47 @@ DEFINE_SMB3_TCON_EVENT(tcon); /* - * For smb2/smb3 open call + * For smb2/smb3 open (including create and mkdir) calls */ + +DECLARE_EVENT_CLASS(smb3_open_enter_class, + TP_PROTO(unsigned int xid, + __u32 tid, + __u64 sesid, + int create_options, + int desired_access), + TP_ARGS(xid, tid, sesid, create_options, desired_access), + TP_STRUCT__entry( + __field(unsigned int, xid) + __field(__u32, tid) + __field(__u64, sesid) + __field(int, create_options) + __field(int, desired_access) + ), + TP_fast_assign( + __entry->xid = xid; + __entry->tid = tid; + __entry->sesid = sesid; + __entry->create_options = create_options; + __entry->desired_access = desired_access; + ), + TP_printk("xid=%u sid=0x%llx tid=0x%x cr_opts=0x%x des_access=0x%x", + __entry->xid, __entry->sesid, __entry->tid, + __entry->create_options, __entry->desired_access) +) + +#define DEFINE_SMB3_OPEN_ENTER_EVENT(name) \ +DEFINE_EVENT(smb3_open_enter_class, smb3_##name, \ + TP_PROTO(unsigned int xid, \ + __u32 tid, \ + __u64 sesid, \ + int create_options, \ + int desired_access), \ + TP_ARGS(xid, tid, sesid, create_options, desired_access)) + +DEFINE_SMB3_OPEN_ENTER_EVENT(open_enter); +DEFINE_SMB3_OPEN_ENTER_EVENT(posix_mkdir_enter); + DECLARE_EVENT_CLASS(smb3_open_err_class, TP_PROTO(unsigned int xid, __u32 tid, -- 2.17.1