Allow tracing before sending a command (add an smb3_cmd_enter)
on the wire - this allows us to look in much more detail at response
times (between request and response).
See below sample output from doing
trace-cmd record -e smb3*cmd*
in one window and then "trace-cmd show" in another
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
mkdir-22002 [001] .... 25557.965367: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=28
mkdir-22002 [001] .... 25557.965370: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=29
mkdir-22002 [001] .... 25557.965371: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=30
mkdir-22002 [002] .... 25557.972623: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=28
mkdir-22002 [002] .... 25557.972625: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=29
mkdir-22002 [002] .... 25557.972626: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=30
rm-22003 [001] .... 25563.125131: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=31
rm-22003 [001] .... 25563.125134: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=32
rm-22003 [001] .... 25563.125135: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=33
rm-22003 [001] .... 25563.134590: smb3_cmd_err:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=31 status=0xc0000034 rc=-2
rm-22003 [001] .... 25563.134643: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=34
rm-22003 [001] .... 25563.134645: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=35
rm-22003 [001] .... 25563.134646: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=36
rm-22003 [001] .... 25563.138544: smb3_cmd_err:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=34 status=0xc0000034 rc=-2
dd-22004 [005] .... 25567.863084: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=37
dd-22004 [005] .... 25567.869415: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=37
dd-22004 [005] .... 25567.869424: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=38
dd-22004 [005] .... 25567.870319: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=38
dd-22004 [005] .... 25567.870369: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=17 mid=39
dd-22004 [005] .... 25567.871073: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=17 mid=39
dd-22004 [005] .... 25567.871094: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=40
dd-22004 [005] .... 25567.871095: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=17 mid=41
dd-22004 [005] .... 25567.871096: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=42
dd-22004 [006] .... 25567.882760: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=40
dd-22004 [006] .... 25567.882763: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=17 mid=41
dd-22004 [006] .... 25567.882764: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=42
dd-22004 [006] .... 25567.882876: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=43
cifsd-21979 [007] .... 25567.884150: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=43
dd-22004 [006] .... 25567.884278: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=44
cifsd-21979 [007] .... 25567.885189: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=44
dd-22004 [006] .... 25567.885299: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=45
cifsd-21979 [007] .... 25567.886174: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=45
dd-22004 [006] .... 25567.886283: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=46
cifsd-21979 [007] .... 25567.887145: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=9 mid=46
dd-22004 [006] .... 25567.887269: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=47
dd-22004 [006] .... 25567.889631: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=47
ls-22009 [005] .... 25613.476023: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=48
ls-22009 [005] .... 25613.477997: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=16 mid=48
ls-22009 [005] .... 25613.478067: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=49
ls-22009 [006] .... 25613.485037: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=5 mid=49
ls-22009 [006] .... 25613.485048: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=14 mid=50
ls-22009 [006] .... 25613.490983: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=14 mid=50
ls-22009 [006] .... 25613.491151: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=14 mid=51
ls-22009 [006] .... 25613.491898: smb3_cmd_err:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=14 mid=51 status=0x80000006 rc=-61
ls-22009 [006] .... 25613.491947: smb3_cmd_enter:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=52
ls-22009 [006] .... 25613.494271: smb3_cmd_done:
sid=0xf3f1eab7 tid=0xe3c55496 cmd=6 mid=52
--
Thanks,
Steve
From 59a164b25656d009d942325e1aba4074a97592f3 Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@xxxxxxxxxxxxx>
Date: Tue, 26 Feb 2019 21:26:20 -0600
Subject: [PATCH] smb3: add dynamic trace point for smb3_cmd_enter
Add tracepoint before sending an SMB3 command on the wire (ie add
an smb3_cmd_enter tracepoint). This allows us to look in much
more detail at response times (between request and response).
Signed-off-by: Steve French <stfrench@xxxxxxxxxxxxx>
---
fs/cifs/smb2transport.c | 3 +++
fs/cifs/trace.h | 1 +
2 files changed, 4 insertions(+)
diff --git a/fs/cifs/smb2transport.c b/fs/cifs/smb2transport.c
index 5609c0b8d5fe..9b1cfd3ed52d 100644
--- a/fs/cifs/smb2transport.c
+++ b/fs/cifs/smb2transport.c
@@ -600,6 +600,8 @@ smb2_mid_entry_alloc(const struct smb2_sync_hdr *shdr,
atomic_inc(&midCount);
temp->mid_state = MID_REQUEST_ALLOCATED;
+ trace_smb3_cmd_enter(shdr->TreeId, shdr->SessionId,
+ le16_to_cpu(shdr->Command), temp->mid);
return temp;
}
@@ -634,6 +636,7 @@ smb2_get_mid_entry(struct cifs_ses *ses, struct smb2_sync_hdr *shdr,
spin_lock(&GlobalMid_Lock);
list_add_tail(&(*mid)->qhead, &ses->server->pending_mid_q);
spin_unlock(&GlobalMid_Lock);
+
return 0;
}
diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h
index b6352b68f18b..2a0be3e1927f 100644
--- a/fs/cifs/trace.h
+++ b/fs/cifs/trace.h
@@ -275,6 +275,7 @@ DEFINE_EVENT(smb3_cmd_done_class, smb3_##name, \
__u64 mid), \
TP_ARGS(tid, sesid, cmd, mid))
+DEFINE_SMB3_CMD_DONE_EVENT(cmd_enter);
DEFINE_SMB3_CMD_DONE_EVENT(cmd_done);
DEFINE_SMB3_CMD_DONE_EVENT(ses_expired);
--
2.17.1
