diff mbox series

dynamic tracing open_enter/done

Message ID CAH2r5msOkMhOOSK1838dsWfiNm6ZTGMRQ2m3jVK0ReNP63LT5g@mail.gmail.com (mailing list archive)
State New, archived
Headers show
Series dynamic tracing open_enter/done | expand

Commit Message

Steve French Feb. 25, 2019, 10:27 p.m. UTC 
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

Comments

ronnie sahlberg Feb. 26, 2019, 2:25 a.m. UTC | #1 
Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>

On Tue, Feb 26, 2019 at 8:27 AM Steve French <smfrench@gmail.com> wrote:
>
> 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
>
>
>
> --
> Thanks,
>
> Steve
diff mbox series

Patch

From a28e9bf2ebec7a9aabcd94497022e5a335c28f81 Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@microsoft.com>
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 <stfrench@microsoft.com>
---
 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