* [PATCH] Add a dynamic tracepoint for smb3_cmd_enter
@ 2019-02-27 3:28 Steve French
2019-02-27 19:30 ` Pavel Shilovsky
0 siblings, 1 reply; 3+ messages in thread
From: Steve French @ 2019-02-27 3:28 UTC (permalink / raw)
To: CIFS; +Cc: Pavel Shilovsky
[-- Attachment #1: Type: text/plain, Size: 5411 bytes --]
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
[-- Attachment #2: 0001-smb3-add-dynamic-trace-point-for-smb3_cmd_enter.patch --]
[-- Type: text/x-patch, Size: 1616 bytes --]
From 59a164b25656d009d942325e1aba4074a97592f3 Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@microsoft.com>
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@microsoft.com>
---
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
^ permalink raw reply related [flat|nested] 3+ messages in thread
* Re: [PATCH] Add a dynamic tracepoint for smb3_cmd_enter
2019-02-27 3:28 [PATCH] Add a dynamic tracepoint for smb3_cmd_enter Steve French
@ 2019-02-27 19:30 ` Pavel Shilovsky
2019-02-28 11:56 ` Aurélien Aptel
0 siblings, 1 reply; 3+ messages in thread
From: Pavel Shilovsky @ 2019-02-27 19:30 UTC (permalink / raw)
To: Steve French; +Cc: CIFS
вт, 26 февр. 2019 г. в 19:28, Steve French <smfrench@gmail.com>:
>
> 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
smb3_cmd_enter trace point is called 3 times for mids 31, 32 and 33
and only mid 31 is logged with smb3_cmd_err. This is happening because
we skip processing mids in compound_send_recv() once the hit a
failure. We need to fix compound_send_recv() to be able to log all the
mids in the compounded chain in a case of error but this is out of
scope of this patch.
> 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, now we have a great tool to start analyzing client latency.
The more advanced step would be to start aggregate latency numbers and
count percentiles (especially for specific commands).
Reviewed-by: Pavel Shilovsky <pshilov@microsoft.com>
--
Best regards,
Pavel Shilovsky
^ permalink raw reply [flat|nested] 3+ messages in thread
* Re: [PATCH] Add a dynamic tracepoint for smb3_cmd_enter
2019-02-27 19:30 ` Pavel Shilovsky
@ 2019-02-28 11:56 ` Aurélien Aptel
0 siblings, 0 replies; 3+ messages in thread
From: Aurélien Aptel @ 2019-02-28 11:56 UTC (permalink / raw)
To: Pavel Shilovsky, Steve French; +Cc: CIFS
Pavel Shilovsky <piastryyy@gmail.com> writes:
> Thanks, now we have a great tool to start analyzing client latency.
> The more advanced step would be to start aggregate latency numbers and
> count percentiles (especially for specific commands).
As a side note, Wireshark can report some of this.
tshark -z smb2,srt -r dump.pcap
SMB2 SRT Statistics:
Filter: smb2.cmd
Index Commands Calls Min SRT Max SRT Avg SRT Sum SRT
5 Create 14759 0.000387 0.035268 0.001288 19.003702
6 Close 14713 0.000253 0.029454 0.000629 9.260241
14 Find 27468 0.000237 0.035798 0.000678 18.634827
16 GetInfo 983 0.000276 0.020349 0.000553 0.543487
SRT is Service Response time. You have RTT and other metrics as well. I
discovered this via Ronnie's SDC talk from years back [1] very good
reference. You can also graph all sorts of things, look at the slides 28
and on.
1: https://wiki.wireshark.org/Presentations?action=AttachFile&do=view&target=RonnieSahlberg_UsingWireshark.pdf
--
Aurélien Aptel / SUSE Labs Samba Team
GPG: 1839 CB5F 9F5B FB9B AA97 8C99 03C8 A49B 521B D5D3
SUSE Linux GmbH, Maxfeldstraße 5, 90409 Nürnberg, Germany
GF: Felix Imendörffer, Jane Smithard, Graham Norton, HRB 21284 (AG Nürnberg)
^ permalink raw reply [flat|nested] 3+ messages in thread
end of thread, other threads:[~2019-02-28 11:56 UTC | newest]
Thread overview: 3+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2019-02-27 3:28 [PATCH] Add a dynamic tracepoint for smb3_cmd_enter Steve French
2019-02-27 19:30 ` Pavel Shilovsky
2019-02-28 11:56 ` Aurélien Aptel
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.