Add a dynamic tracepoint for smb3_cmd_enter
diff mbox series

Message ID CAH2r5mt_bKGxNVCchmwCo-J7T_WqZRW+HXsn=V7c57_s6cBgxA@mail.gmail.com
State New
Headers show
Series
  • Add a dynamic tracepoint for smb3_cmd_enter
Related show

Commit Message

Steve French Feb. 27, 2019, 3:28 a.m. UTC
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

Comments

Pavel Shilovsky Feb. 27, 2019, 7:30 p.m. UTC | #1
вт, 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
Aurélien Aptel Feb. 28, 2019, 11:56 a.m. UTC | #2
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

Patch
diff mbox series

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