smb3: add trace point for tree connection

Message ID	CAH2r5msT48seA3GiX39e5NzAe2zhms0H1zO3oqu5A3WP-5NLSw@mail.gmail.com (mailing list archive)
State	New, archived
Headers	show Return-Path: <linux-cifs-owner@kernel.org> MIME-Version: 1.0 From: Steve French <smfrench@gmail.com> Date: Sun, 28 Oct 2018 00:55:49 -0500 Message-ID: <CAH2r5msT48seA3GiX39e5NzAe2zhms0H1zO3oqu5A3WP-5NLSw@mail.gmail.com> Subject: [PATCH] smb3: add trace point for tree connection To: CIFS <linux-cifs@vger.kernel.org> Content-Type: multipart/mixed; boundary="00000000000074e0ee0579439b9e" Sender: linux-cifs-owner@vger.kernel.org Precedence: bulk
Series	smb3: add trace point for tree connection \| expand smb3: add trace point for tree connection

Message ID

CAH2r5msT48seA3GiX39e5NzAe2zhms0H1zO3oqu5A3WP-5NLSw@mail.gmail.com (mailing list archive)

State

New, archived

Headers

MIME-Version: 1.0
From: Steve French <smfrench@gmail.com>
Date: Sun, 28 Oct 2018 00:55:49 -0500
Message-ID: 
 <CAH2r5msT48seA3GiX39e5NzAe2zhms0H1zO3oqu5A3WP-5NLSw@mail.gmail.com>
Subject: [PATCH] smb3: add trace point for tree connection
To: CIFS <linux-cifs@vger.kernel.org>
Content-Type: multipart/mixed; boundary="00000000000074e0ee0579439b9e"
Sender: linux-cifs-owner@vger.kernel.org
Precedence: bulk

Series

smb3: add trace point for tree connection | expand

Commit Message

Steve French Oct. 28, 2018, 5:55 a.m. UTC

In debugging certain scenarios, especially reconnect cases,
it can be helpful to have a dynamic trace point for the
result of tree connect.  See sample output below
from a reconnect event. The new event is 'smb3_tcon'

            TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
               | |       |   ||||       |         |
           cifsd-6071  [001] ....  2659.897923: smb3_reconnect:
server=localhost current_mid=0xa
     kworker/1:1-71    [001] ....  2666.026342: smb3_cmd_done:
sid=0x0 tid=0x0 cmd=0 mid=0
     kworker/1:1-71    [001] ....  2666.026576: smb3_cmd_err:
sid=0xc49e1787 tid=0x0 cmd=1 mid=1 status=0xc0000016 rc=-5
     kworker/1:1-71    [001] ....  2666.031677: smb3_cmd_done:
sid=0xc49e1787 tid=0x0 cmd=1 mid=2
     kworker/1:1-71    [001] ....  2666.031921: smb3_cmd_done:
sid=0xc49e1787 tid=0x6e78f05f cmd=3 mid=3
     kworker/1:1-71    [001] ....  2666.031923: smb3_tcon: xid=0
sid=0xc49e1787 tid=0x0 unc_name=\\localhost\test rc=0
     kworker/1:1-71    [001] ....  2666.032097: smb3_cmd_done:
sid=0xc49e1787 tid=0x6e78f05f cmd=11 mid=4
     kworker/1:1-71    [001] ....  2666.032265: smb3_cmd_done:
sid=0xc49e1787 tid=0x7912332f cmd=3 mid=5
     kworker/1:1-71    [001] ....  2666.032266: smb3_tcon: xid=0
sid=0xc49e1787 tid=0x0 unc_name=\\localhost\IPC$ rc=0
     kworker/1:1-71    [001] ....  2666.032386: smb3_cmd_done:
sid=0xc49e1787 tid=0x7912332f cmd=11 mid=6

Signed-off-by: Steve French <stfrench@microsoft.com>
---
 fs/cifs/smb2pdu.c |  3 ++-
 fs/cifs/trace.h   | 42 ++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 44 insertions(+), 1 deletion(-)

Comments

ronnie sahlberg Oct. 29, 2018, 3:16 a.m. UTC | #1

Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>
On Sun, Oct 28, 2018 at 4:10 PM Steve French <smfrench@gmail.com> wrote:
>
> In debugging certain scenarios, especially reconnect cases,
> it can be helpful to have a dynamic trace point for the
> result of tree connect.  See sample output below
> from a reconnect event. The new event is 'smb3_tcon'
>
>             TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
>                | |       |   ||||       |         |
>            cifsd-6071  [001] ....  2659.897923: smb3_reconnect:
> server=localhost current_mid=0xa
>      kworker/1:1-71    [001] ....  2666.026342: smb3_cmd_done:
> sid=0x0 tid=0x0 cmd=0 mid=0
>      kworker/1:1-71    [001] ....  2666.026576: smb3_cmd_err:
> sid=0xc49e1787 tid=0x0 cmd=1 mid=1 status=0xc0000016 rc=-5
>      kworker/1:1-71    [001] ....  2666.031677: smb3_cmd_done:
> sid=0xc49e1787 tid=0x0 cmd=1 mid=2
>      kworker/1:1-71    [001] ....  2666.031921: smb3_cmd_done:
> sid=0xc49e1787 tid=0x6e78f05f cmd=3 mid=3
>      kworker/1:1-71    [001] ....  2666.031923: smb3_tcon: xid=0
> sid=0xc49e1787 tid=0x0 unc_name=\\localhost\test rc=0
>      kworker/1:1-71    [001] ....  2666.032097: smb3_cmd_done:
> sid=0xc49e1787 tid=0x6e78f05f cmd=11 mid=4
>      kworker/1:1-71    [001] ....  2666.032265: smb3_cmd_done:
> sid=0xc49e1787 tid=0x7912332f cmd=3 mid=5
>      kworker/1:1-71    [001] ....  2666.032266: smb3_tcon: xid=0
> sid=0xc49e1787 tid=0x0 unc_name=\\localhost\IPC$ rc=0
>      kworker/1:1-71    [001] ....  2666.032386: smb3_cmd_done:
> sid=0xc49e1787 tid=0x7912332f cmd=11 mid=6
>
> Signed-off-by: Steve French <stfrench@microsoft.com>
> ---
>  fs/cifs/smb2pdu.c |  3 ++-
>  fs/cifs/trace.h   | 42 ++++++++++++++++++++++++++++++++++++++++++
>  2 files changed, 44 insertions(+), 1 deletion(-)
>
> diff --git a/fs/cifs/smb2pdu.c b/fs/cifs/smb2pdu.c
> index 7d7b016fe8bb..a92d3840db9d 100644
> --- a/fs/cifs/smb2pdu.c
> +++ b/fs/cifs/smb2pdu.c
> @@ -1512,7 +1512,7 @@ SMB2_tcon(const unsigned int xid, struct
> cifs_ses *ses, const char *tree,
>      rc = cifs_send_recv(xid, ses, &rqst, &resp_buftype, flags, &rsp_iov);
>      cifs_small_buf_release(req);
>      rsp = (struct smb2_tree_connect_rsp *)rsp_iov.iov_base;
> -
> +    trace_smb3_tcon(xid, tcon->tid, ses->Suid, tree, rc);
>      if (rc != 0) {
>          if (tcon) {
>              cifs_stats_fail_inc(tcon, SMB2_TREE_CONNECT_HE);
> @@ -1559,6 +1559,7 @@ SMB2_tcon(const unsigned int xid, struct
> cifs_ses *ses, const char *tree,
>      if (tcon->ses->server->ops->validate_negotiate)
>          rc = tcon->ses->server->ops->validate_negotiate(xid, tcon);
>  tcon_exit:
> +
>      free_rsp_buf(resp_buftype, rsp);
>      kfree(unc_path);
>      return rc;
> diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h
> index cce8414fe7ec..fb049809555f 100644
> --- a/fs/cifs/trace.h
> +++ b/fs/cifs/trace.h
> @@ -373,6 +373,48 @@ DEFINE_EVENT(smb3_enter_exit_class, smb3_##name,  \
>  DEFINE_SMB3_ENTER_EXIT_EVENT(enter);
>  DEFINE_SMB3_ENTER_EXIT_EVENT(exit_done);
>
> +/*
> + * For SMB2/SMB3 tree connect
> + */
> +
> +DECLARE_EVENT_CLASS(smb3_tcon_class,
> +    TP_PROTO(unsigned int xid,
> +        __u32    tid,
> +        __u64    sesid,
> +        const char *unc_name,
> +        int    rc),
> +    TP_ARGS(xid, tid, sesid, unc_name, rc),
> +    TP_STRUCT__entry(
> +        __field(unsigned int, xid)
> +        __field(__u32, tid)
> +        __field(__u64, sesid)
> +        __field(const char *,  unc_name)
> +        __field(int, rc)
> +    ),
> +    TP_fast_assign(
> +        __entry->xid = xid;
> +        __entry->tid = tid;
> +        __entry->sesid = sesid;
> +        __entry->unc_name = unc_name;
> +        __entry->rc = rc;
> +    ),
> +    TP_printk("xid=%u sid=0x%llx tid=0x%x unc_name=%s rc=%d",
> +        __entry->xid, __entry->sesid, __entry->tid,
> +        __entry->unc_name, __entry->rc)
> +)
> +
> +#define DEFINE_SMB3_TCON_EVENT(name)          \
> +DEFINE_EVENT(smb3_tcon_class, smb3_##name,    \
> +    TP_PROTO(unsigned int xid,        \
> +        __u32    tid,            \
> +        __u64    sesid,            \
> +        const char *unc_name,        \
> +        int    rc),            \
> +    TP_ARGS(xid, tid, sesid, unc_name, rc))
> +
> +DEFINE_SMB3_TCON_EVENT(tcon);
> +
> +
>  /*
>   * For smb2/smb3 open call
>   */
>
> --
> Thanks,
>
> Steve

From 05a5757ba776af6af593561028bb275fb9e3737e Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@microsoft.com>
Date: Sun, 28 Oct 2018 00:47:11 -0500
Subject: [PATCH] smb3: add trace point for tree connection

In debugging certain scenarios, especially reconnect cases,
it can be helpful to have a dynamic trace point for the
result of tree connect.  See sample output below
from a reconnect event. The new event is 'smb3_tcon'

            TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
               | |       |   ||||       |         |
           cifsd-6071  [001] ....  2659.897923: smb3_reconnect: server=localhost current_mid=0xa
     kworker/1:1-71    [001] ....  2666.026342: smb3_cmd_done: 	sid=0x0 tid=0x0 cmd=0 mid=0
     kworker/1:1-71    [001] ....  2666.026576: smb3_cmd_err: 	sid=0xc49e1787 tid=0x0 cmd=1 mid=1 status=0xc0000016 rc=-5
     kworker/1:1-71    [001] ....  2666.031677: smb3_cmd_done: 	sid=0xc49e1787 tid=0x0 cmd=1 mid=2
     kworker/1:1-71    [001] ....  2666.031921: smb3_cmd_done: 	sid=0xc49e1787 tid=0x6e78f05f cmd=3 mid=3
     kworker/1:1-71    [001] ....  2666.031923: smb3_tcon: xid=0 sid=0xc49e1787 tid=0x0 unc_name=\\localhost\test rc=0
     kworker/1:1-71    [001] ....  2666.032097: smb3_cmd_done: 	sid=0xc49e1787 tid=0x6e78f05f cmd=11 mid=4
     kworker/1:1-71    [001] ....  2666.032265: smb3_cmd_done: 	sid=0xc49e1787 tid=0x7912332f cmd=3 mid=5
     kworker/1:1-71    [001] ....  2666.032266: smb3_tcon: xid=0 sid=0xc49e1787 tid=0x0 unc_name=\\localhost\IPC$ rc=0
     kworker/1:1-71    [001] ....  2666.032386: smb3_cmd_done: 	sid=0xc49e1787 tid=0x7912332f cmd=11 mid=6

Signed-off-by: Steve French <stfrench@microsoft.com>
---
 fs/cifs/smb2pdu.c |  3 ++-
 fs/cifs/trace.h   | 42 ++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 44 insertions(+), 1 deletion(-)

diff --git a/fs/cifs/smb2pdu.c b/fs/cifs/smb2pdu.c
index 7d7b016fe8bb..a92d3840db9d 100644
--- a/fs/cifs/smb2pdu.c
+++ b/fs/cifs/smb2pdu.c
@@ -1512,7 +1512,7 @@  SMB2_tcon(const unsigned int xid, struct cifs_ses *ses, const char *tree,
 	rc = cifs_send_recv(xid, ses, &rqst, &resp_buftype, flags, &rsp_iov);
 	cifs_small_buf_release(req);
 	rsp = (struct smb2_tree_connect_rsp *)rsp_iov.iov_base;
-
+	trace_smb3_tcon(xid, tcon->tid, ses->Suid, tree, rc);
 	if (rc != 0) {
 		if (tcon) {
 			cifs_stats_fail_inc(tcon, SMB2_TREE_CONNECT_HE);
@@ -1559,6 +1559,7 @@  SMB2_tcon(const unsigned int xid, struct cifs_ses *ses, const char *tree,
 	if (tcon->ses->server->ops->validate_negotiate)
 		rc = tcon->ses->server->ops->validate_negotiate(xid, tcon);
 tcon_exit:
+
 	free_rsp_buf(resp_buftype, rsp);
 	kfree(unc_path);
 	return rc;
diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h
index cce8414fe7ec..fb049809555f 100644
--- a/fs/cifs/trace.h
+++ b/fs/cifs/trace.h
@@ -373,6 +373,48 @@  DEFINE_EVENT(smb3_enter_exit_class, smb3_##name,  \
 DEFINE_SMB3_ENTER_EXIT_EVENT(enter);
 DEFINE_SMB3_ENTER_EXIT_EVENT(exit_done);
 
+/*
+ * For SMB2/SMB3 tree connect
+ */
+
+DECLARE_EVENT_CLASS(smb3_tcon_class,
+	TP_PROTO(unsigned int xid,
+		__u32	tid,
+		__u64	sesid,
+		const char *unc_name,
+		int	rc),
+	TP_ARGS(xid, tid, sesid, unc_name, rc),
+	TP_STRUCT__entry(
+		__field(unsigned int, xid)
+		__field(__u32, tid)
+		__field(__u64, sesid)
+		__field(const char *,  unc_name)
+		__field(int, rc)
+	),
+	TP_fast_assign(
+		__entry->xid = xid;
+		__entry->tid = tid;
+		__entry->sesid = sesid;
+		__entry->unc_name = unc_name;
+		__entry->rc = rc;
+	),
+	TP_printk("xid=%u sid=0x%llx tid=0x%x unc_name=%s rc=%d",
+		__entry->xid, __entry->sesid, __entry->tid,
+		__entry->unc_name, __entry->rc)
+)
+
+#define DEFINE_SMB3_TCON_EVENT(name)          \
+DEFINE_EVENT(smb3_tcon_class, smb3_##name,    \
+	TP_PROTO(unsigned int xid,		\
+		__u32	tid,			\
+		__u64	sesid,			\
+		const char *unc_name,		\
+		int	rc),			\
+	TP_ARGS(xid, tid, sesid, unc_name, rc))
+
+DEFINE_SMB3_TCON_EVENT(tcon);
+
+
 /*
  * For smb2/smb3 open call
  */
-- 
2.17.1

smb3: add trace point for tree connection

Commit Message

Comments

Patch