Sample output from tracing various newly added dynamic trace points
(with this patch)
(trace-cmd record -e *query_info_co* -e smb3_hardlink* -e
smb3_rename* -e smb3_set_eof* -e smb3_set_info_co* -e smb3_mkdir* -e
smb3_delete*)
# entries-in-buffer/entries-written: 44/44 #P:8
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
gvfsd-trash-2224 [004] .... 333095.401381:
smb3_query_info_compound_enter: xid=5 sid=0xbb2583e9 tid=0xe7ab49dc
gvfsd-trash-2224 [002] .... 333095.402056:
smb3_query_info_compound_err: xid=5 sid=0xbb2583e9 tid=0xe7ab49dc
rc=-2
gvfsd-trash-2224 [002] .... 333095.402189:
smb3_query_info_compound_enter: xid=6 sid=0xbb2583e9 tid=0xe7ab49dc
gvfsd-trash-2224 [002] .... 333095.402688:
smb3_query_info_compound_err: xid=6 sid=0xbb2583e9 tid=0xe7ab49dc
rc=-2
mkdir-16324 [002] .... 333123.559043:
smb3_query_info_compound_enter: xid=7 sid=0xbb2583e9 tid=0xe7ab49dc
mkdir-16324 [003] .... 333123.559654:
smb3_query_info_compound_err: xid=7 sid=0xbb2583e9 tid=0xe7ab49dc
rc=-2
mkdir-16324 [003] .... 333123.559673: smb3_mkdir_enter:
xid=8 sid=0xbb2583e9 tid=0xe7ab49dc
mkdir-16324 [003] .... 333123.560748: smb3_mkdir_done:
xid=8 sid=0xbb2583e9 tid=0xe7ab49dc
mkdir-16324 [003] .... 333123.560763:
smb3_query_info_compound_enter: xid=8 sid=0xbb2583e9 tid=0xe7ab49dc
mkdir-16324 [003] .... 333123.561516:
smb3_query_info_compound_done: xid=8 sid=0xbb2583e9 tid=0xe7ab49dc
mkdir-16325 [002] .... 333126.841897:
smb3_query_info_compound_enter: xid=9 sid=0xbb2583e9 tid=0xe7ab49dc
mkdir-16325 [003] .... 333126.842580:
smb3_query_info_compound_err: xid=9 sid=0xbb2583e9 tid=0xe7ab49dc
rc=-2
mkdir-16325 [003] .... 333126.842601: smb3_mkdir_enter:
xid=10 sid=0xbb2583e9 tid=0xe7ab49dc
mkdir-16325 [003] .... 333126.843513: smb3_mkdir_done:
xid=10 sid=0xbb2583e9 tid=0xe7ab49dc
mkdir-16325 [003] .... 333126.843529:
smb3_query_info_compound_enter: xid=10 sid=0xbb2583e9 tid=0xe7ab49dc
mkdir-16325 [003] .... 333126.844251:
smb3_query_info_compound_done: xid=10 sid=0xbb2583e9 tid=0xe7ab49dc
mkdir-16326 [000] .... 333129.858413:
smb3_query_info_compound_enter: xid=11 sid=0xbb2583e9 tid=0xe7ab49dc
mkdir-16326 [000] .... 333129.859193:
smb3_query_info_compound_done: xid=11 sid=0xbb2583e9 tid=0xe7ab49dc
rmdir-16328 [007] .... 333138.828049:
smb3_query_info_compound_enter: xid=12 sid=0xbb2583e9 tid=0xe7ab49dc
rmdir-16328 [007] .... 333138.828827:
smb3_query_info_compound_done: xid=12 sid=0xbb2583e9 tid=0xe7ab49dc
rmdir-16329 [006] .... 333141.388154:
smb3_query_info_compound_enter: xid=14 sid=0xbb2583e9 tid=0xe7ab49dc
rmdir-16329 [006] .... 333141.388813:
smb3_query_info_compound_err: xid=14 sid=0xbb2583e9 tid=0xe7ab49dc
rc=-2
rm-16340 [006] .... 333157.935975:
smb3_query_info_compound_enter: xid=15 sid=0xbb2583e9 tid=0xe7ab49dc
rm-16340 [006] .... 333157.936607:
smb3_query_info_compound_err: xid=15 sid=0xbb2583e9 tid=0xe7ab49dc
rc=-2
rm-16340 [006] .... 333157.936652:
smb3_query_info_compound_enter: xid=16 sid=0xbb2583e9 tid=0xe7ab49dc
rm-16340 [006] .... 333157.937146:
smb3_query_info_compound_err: xid=16 sid=0xbb2583e9 tid=0xe7ab49dc
rc=-2
touch-16349 [005] .... 333184.932302:
smb3_set_info_compound_enter: xid=18 sid=0xbb2583e9 tid=0xe7ab49dc
touch-16349 [005] .... 333184.938303:
smb3_set_info_compound_done: xid=18 sid=0xbb2583e9 tid=0xe7ab49dc
rm-16350 [003] .... 333187.920309:
smb3_query_info_compound_enter: xid=20 sid=0xbb2583e9 tid=0xe7ab49dc
rm-16350 [003] .... 333187.920999:
smb3_query_info_compound_done: xid=20 sid=0xbb2583e9 tid=0xe7ab49dc
rm-16350 [003] .... 333187.921043: smb3_delete_enter:
xid=21 sid=0xbb2583e9 tid=0xe7ab49dc
rm-16350 [003] .... 333187.921870: smb3_delete_done:
xid=21 sid=0xbb2583e9 tid=0xe7ab49dc
touch-16361 [005] .... 333237.447252:
smb3_set_info_compound_enter: xid=23 sid=0xbb2583e9 tid=0xe7ab49dc
touch-16361 [005] .... 333237.448044:
smb3_set_info_compound_done: xid=23 sid=0xbb2583e9 tid=0xe7ab49dc
ln-16366 [000] .... 333250.734035:
smb3_query_info_compound_enter: xid=25 sid=0xbb2583e9 tid=0xe7ab49dc
ln-16366 [001] .... 333250.734689:
smb3_query_info_compound_err: xid=25 sid=0xbb2583e9 tid=0xe7ab49dc
rc=-2
ln-16366 [001] .... 333250.734735:
smb3_query_info_compound_enter: xid=26 sid=0xbb2583e9 tid=0xe7ab49dc
ln-16366 [001] .... 333250.735368:
smb3_query_info_compound_done: xid=26 sid=0xbb2583e9 tid=0xe7ab49dc
ln-16366 [001] .... 333250.735413:
smb3_query_info_compound_enter: xid=27 sid=0xbb2583e9 tid=0xe7ab49dc
ln-16366 [001] .... 333250.735947:
smb3_query_info_compound_err: xid=27 sid=0xbb2583e9 tid=0xe7ab49dc
rc=-2
ln-16366 [001] .... 333250.735973: smb3_hardlink_enter:
xid=28 sid=0xbb2583e9 tid=0xe7ab49dc
ln-16366 [001] .... 333250.736679: smb3_hardlink_done:
xid=28 sid=0xbb2583e9 tid=0xe7ab49dc
gmain-2225 [000] .... 333250.736855:
smb3_query_info_compound_enter: xid=29 sid=0xbb2583e9 tid=0xe7ab49dc
gmain-2225 [001] .... 333250.737527:
smb3_query_info_compound_done: xid=29 sid=0xbb2583e9 tid=0xe7ab49dc
--
Thanks,
Steve
From ab7dbfbefe06f51b0fe9a5edbdab93469bc896f1 Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@xxxxxxxxxxxxx>
Date: Mon, 11 Mar 2019 16:20:17 -0500
Subject: [PATCH] [smb3] Add dynamic trace points for various compounded smb3
ops
Adds trace points for enter and exit (done vs. error) for:
compounded query and setinfo, hardlink, rename, mkdir, rmdir,
set_eof, delete (unlink)
Signed-off-by: Steve French <stfrench@xxxxxxxxxxxxx>
---
fs/cifs/smb2inode.c | 71 ++++++++++++++++++++++++++++++++++++---
fs/cifs/trace.h | 82 +++++++++++++++++++++++++++++++++++++++++++++
2 files changed, 148 insertions(+), 5 deletions(-)
diff --git a/fs/cifs/smb2inode.c b/fs/cifs/smb2inode.c
index 01a76bccdb8d..f3deb59625c0 100644
--- a/fs/cifs/smb2inode.c
+++ b/fs/cifs/smb2inode.c
@@ -37,6 +37,16 @@
#include "smb2pdu.h"
#include "smb2proto.h"
+static void
+free_set_inf_compound(struct smb_rqst *rqst)
+{
+ if (rqst[1].rq_iov)
+ SMB2_set_info_free(&rqst[1]);
+ if (rqst[2].rq_iov)
+ SMB2_close_free(&rqst[2]);
+}
+
+
static int
smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
struct cifs_sb_info *cifs_sb, const char *full_path,
@@ -104,7 +114,6 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
memset(&qi_iov, 0, sizeof(qi_iov));
rqst[num_rqst].rq_iov = qi_iov;
rqst[num_rqst].rq_nvec = 1;
-
rc = SMB2_query_info_init(tcon, &rqst[num_rqst], COMPOUND_FID,
COMPOUND_FID, FILE_ALL_INFORMATION,
SMB2_O_INFO_FILE, 0,
@@ -112,14 +121,17 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
PATH_MAX * 2, 0, NULL);
smb2_set_next_command(tcon, &rqst[num_rqst]);
smb2_set_related(&rqst[num_rqst++]);
+ trace_smb3_query_info_compound_enter(xid, ses->Suid, tcon->tid);
break;
case SMB2_OP_DELETE:
+ trace_smb3_delete_enter(xid, ses->Suid, tcon->tid);
break;
case SMB2_OP_MKDIR:
/*
* Directories are created through parameters in the
* SMB2_open() call.
*/
+ trace_smb3_mkdir_enter(xid, ses->Suid, tcon->tid);
break;
case SMB2_OP_RMDIR:
memset(&si_iov, 0, sizeof(si_iov));
@@ -135,6 +147,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
SMB2_O_INFO_FILE, 0, data, size);
smb2_set_next_command(tcon, &rqst[num_rqst]);
smb2_set_related(&rqst[num_rqst++]);
+ trace_smb3_rmdir_enter(xid, ses->Suid, tcon->tid);
break;
case SMB2_OP_SET_EOF:
memset(&si_iov, 0, sizeof(si_iov));
@@ -150,6 +163,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
SMB2_O_INFO_FILE, 0, data, size);
smb2_set_next_command(tcon, &rqst[num_rqst]);
smb2_set_related(&rqst[num_rqst++]);
+ trace_smb3_set_eof_enter(xid, ses->Suid, tcon->tid);
break;
case SMB2_OP_SET_INFO:
memset(&si_iov, 0, sizeof(si_iov));
@@ -166,6 +180,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
SMB2_O_INFO_FILE, 0, data, size);
smb2_set_next_command(tcon, &rqst[num_rqst]);
smb2_set_related(&rqst[num_rqst++]);
+ trace_smb3_set_info_compound_enter(xid, ses->Suid, tcon->tid);
break;
case SMB2_OP_RENAME:
memset(&si_iov, 0, sizeof(si_iov));
@@ -190,6 +205,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
SMB2_O_INFO_FILE, 0, data, size);
smb2_set_next_command(tcon, &rqst[num_rqst]);
smb2_set_related(&rqst[num_rqst++]);
+ trace_smb3_rename_enter(xid, ses->Suid, tcon->tid);
break;
case SMB2_OP_HARDLINK:
memset(&si_iov, 0, sizeof(si_iov));
@@ -214,6 +230,7 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
SMB2_O_INFO_FILE, 0, data, size);
smb2_set_next_command(tcon, &rqst[num_rqst]);
smb2_set_related(&rqst[num_rqst++]);
+ trace_smb3_hardlink_enter(xid, ses->Suid, tcon->tid);
break;
default:
cifs_dbg(VFS, "Invalid command\n");
@@ -252,21 +269,65 @@ smb2_compound_op(const unsigned int xid, struct cifs_tcon *tcon,
SMB2_query_info_free(&rqst[1]);
if (rqst[2].rq_iov)
SMB2_close_free(&rqst[2]);
+ if (rc)
+ trace_smb3_query_info_compound_err(xid, ses->Suid,
+ tcon->tid, rc);
+ else
+ trace_smb3_query_info_compound_done(xid, ses->Suid,
+ tcon->tid);
break;
case SMB2_OP_DELETE:
+ if (rc)
+ trace_smb3_delete_err(xid, ses->Suid, tcon->tid, rc);
+ else
+ trace_smb3_delete_done(xid, ses->Suid, tcon->tid);
+ if (rqst[1].rq_iov)
+ SMB2_close_free(&rqst[1]);
+ break;
case SMB2_OP_MKDIR:
+ if (rc)
+ trace_smb3_mkdir_err(xid, ses->Suid, tcon->tid, rc);
+ else
+ trace_smb3_mkdir_done(xid, ses->Suid, tcon->tid);
if (rqst[1].rq_iov)
SMB2_close_free(&rqst[1]);
break;
case SMB2_OP_HARDLINK:
+ if (rc)
+ trace_smb3_hardlink_err(xid, ses->Suid, tcon->tid, rc);
+ else
+ trace_smb3_hardlink_done(xid, ses->Suid, tcon->tid);
+ free_set_inf_compound(rqst);
+ break;
case SMB2_OP_RENAME:
+ if (rc)
+ trace_smb3_rename_err(xid, ses->Suid, tcon->tid, rc);
+ else
+ trace_smb3_rename_done(xid, ses->Suid, tcon->tid);
+ free_set_inf_compound(rqst);
+ break;
case SMB2_OP_RMDIR:
+ if (rc)
+ trace_smb3_rmdir_err(xid, ses->Suid, tcon->tid, rc);
+ else
+ trace_smb3_rmdir_done(xid, ses->Suid, tcon->tid);
+ free_set_inf_compound(rqst);
+ break;
case SMB2_OP_SET_EOF:
+ if (rc)
+ trace_smb3_set_eof_err(xid, ses->Suid, tcon->tid, rc);
+ else
+ trace_smb3_set_eof_done(xid, ses->Suid, tcon->tid);
+ free_set_inf_compound(rqst);
+ break;
case SMB2_OP_SET_INFO:
- if (rqst[1].rq_iov)
- SMB2_set_info_free(&rqst[1]);
- if (rqst[2].rq_iov)
- SMB2_close_free(&rqst[2]);
+ if (rc)
+ trace_smb3_set_info_compound_err(xid, ses->Suid,
+ tcon->tid, rc);
+ else
+ trace_smb3_set_info_compound_done(xid, ses->Suid,
+ tcon->tid);
+ free_set_inf_compound(rqst);
break;
}
free_rsp_buf(resp_buftype[0], rsp_iov[0].iov_base);
diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h
index c78e96c4cc53..0455fc7e5235 100644
--- a/fs/cifs/trace.h
+++ b/fs/cifs/trace.h
@@ -242,6 +242,88 @@ DEFINE_SMB3_INF_ERR_EVENT(query_info_err);
DEFINE_SMB3_INF_ERR_EVENT(set_info_err);
DEFINE_SMB3_INF_ERR_EVENT(fsctl_err);
+DECLARE_EVENT_CLASS(smb3_inf_compound_enter_class,
+ TP_PROTO(unsigned int xid,
+ __u32 tid,
+ __u64 sesid),
+ TP_ARGS(xid, tid, sesid),
+ TP_STRUCT__entry(
+ __field(unsigned int, xid)
+ __field(__u32, tid)
+ __field(__u64, sesid)
+ ),
+ TP_fast_assign(
+ __entry->xid = xid;
+ __entry->tid = tid;
+ __entry->sesid = sesid;
+ ),
+ TP_printk("xid=%u sid=0x%llx tid=0x%x",
+ __entry->xid, __entry->sesid, __entry->tid)
+)
+
+#define DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(name) \
+DEFINE_EVENT(smb3_inf_compound_enter_class, smb3_##name, \
+ TP_PROTO(unsigned int xid, \
+ __u32 tid, \
+ __u64 sesid), \
+ TP_ARGS(xid, tid, sesid))
+
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(query_info_compound_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(query_info_compound_done);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(hardlink_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(hardlink_done);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(rename_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(rename_done);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(rmdir_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(rmdir_done);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(set_eof_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(set_eof_done);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(set_info_compound_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(set_info_compound_done);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(delete_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(delete_done);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(mkdir_enter);
+DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(mkdir_done);
+
+DECLARE_EVENT_CLASS(smb3_inf_compound_err_class,
+ TP_PROTO(unsigned int xid,
+ __u32 tid,
+ __u64 sesid,
+ int rc),
+ TP_ARGS(xid, tid, sesid, rc),
+ TP_STRUCT__entry(
+ __field(unsigned int, xid)
+ __field(__u32, tid)
+ __field(__u64, sesid)
+ __field(int, rc)
+ ),
+ TP_fast_assign(
+ __entry->xid = xid;
+ __entry->tid = tid;
+ __entry->sesid = sesid;
+ __entry->rc = rc;
+ ),
+ TP_printk("xid=%u sid=0x%llx tid=0x%x rc=%d",
+ __entry->xid, __entry->sesid, __entry->tid, __entry->rc)
+)
+
+#define DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(name) \
+DEFINE_EVENT(smb3_inf_compound_err_class, smb3_##name, \
+ TP_PROTO(unsigned int xid, \
+ __u32 tid, \
+ __u64 sesid, \
+ int rc), \
+ TP_ARGS(xid, tid, sesid, rc))
+
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(query_info_compound_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(hardlink_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(rename_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(rmdir_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(set_eof_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(set_info_compound_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(mkdir_err);
+DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(delete_err);
+
/*
* For logging SMB3 Status code and Command for responses which return errors
*/
--
2.17.1
