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