| 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 | expand |
вт, 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
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
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
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