linux-cifs.vger.kernel.org archive mirror
 help / color / mirror / Atom feed
From: Pavel Shilovsky <piastryyy@gmail.com>
To: Steve French <smfrench@gmail.com>
Cc: CIFS <linux-cifs@vger.kernel.org>
Subject: Re: [PATCH] Add a dynamic tracepoint for smb3_cmd_enter
Date: Wed, 27 Feb 2019 11:30:18 -0800	[thread overview]
Message-ID: <CAKywueRw7aBj3AhSADbU1pSWuTNa=7LKaXWNPrhB6isf2x-DWw@mail.gmail.com> (raw)
In-Reply-To: <CAH2r5mt_bKGxNVCchmwCo-J7T_WqZRW+HXsn=V7c57_s6cBgxA@mail.gmail.com>

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

  reply	other threads:[~2019-02-27 19:30 UTC|newest]

Thread overview: 3+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2019-02-27  3:28 [PATCH] Add a dynamic tracepoint for smb3_cmd_enter Steve French
2019-02-27 19:30 ` Pavel Shilovsky [this message]
2019-02-28 11:56   ` Aurélien Aptel

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to='CAKywueRw7aBj3AhSADbU1pSWuTNa=7LKaXWNPrhB6isf2x-DWw@mail.gmail.com' \
    --to=piastryyy@gmail.com \
    --cc=linux-cifs@vger.kernel.org \
    --cc=smfrench@gmail.com \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body. 
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).