Commit Graph

18 Commits

Author SHA1 Message Date
Steve French 8191576a12 smb3: Add dynamic trace points for various compounded smb3 ops
Adds trace points for enter and exit (done vs. error) for:

	compounded query and setinfo, hardlink, rename,
	mkdir, rmdir, set_eof, delete (unlink)

Signed-off-by: Steve French <stfrench@microsoft.com>
Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>
2019-03-14 19:32:35 -05:00
Steve French 7937ca961c smb3: add dynamic tracepoint for timeout waiting for credits
To help debug credit starvation problems where we timeout
waiting for server to grant the client credits.

Signed-off-by: Steve French <stfrench@microsoft.com>
Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>
Reviewed-by: Pavel Shilovsky <pshilov@microsoft.com>
2019-03-14 19:32:35 -05:00
Steve French d42043a600 smb3: add dynamic trace point for query_info_enter/done
Adds dynamic trace points for the query_info_enter
and query_info_done (no error) case.  We only had one
existing trace point related to this which was on query_info
errors.  Note that these two new tracepoints are for the
non-compounded query_info paths.

Sample output (from: trace-cmd record -e smb3_query_info*)

          ls-24140 [001] .... 27811.866068: smb3_query_info_enter: xid=7 sid=0xd2d00587 tid=0xb5441939 fid=0xcf082bac class=18 type=0x1
          ls-24140 [001] .... 27811.867656: smb3_query_info_done: xid=7 sid=0xd2d00587 tid=0xb5441939 fid=0xcf082bac class=18 type=0x1
  getcifsacl-24149 [005] .... 27854.759873: smb3_query_info_enter: xid=15 sid=0xd2d00587 tid=0xb5441939 fid=0x99896e72 class=0 type=0x3
  getcifsacl-24149 [005] .... 27854.761730: smb3_query_info_done: xid=15 sid=0xd2d00587 tid=0xb5441939 fid=0x99896e72 class=0 type=0x3

Signed-off-by: Steve French <stfrench@microsoft.com>
Reviewed-by: Pavel Shilovsky <pshilov@microsoft.com>
2019-03-05 18:10:20 -06:00
Steve French 53a3e0d96c 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>
Reviewed-by: Pavel Shilovsky <pshilov@microsoft.com>
2019-03-05 18:10:13 -06:00
Steve French efe2e9f369 smb3: improve dynamic tracing of open and posix mkdir
Add dynamic trace point for open_enter (and posix mkdir enter)

Signed-off-by: Steve French <stfrench@microsoft.com>
Reviewed-by: Pavel Shilovsky <pshilov@microsoft.com>
2019-03-05 18:10:09 -06:00
Steve French d323c24617 smb3: Add tracepoints for read, write and query_dir enter
Allows tracing begin (not just completion) of read, write
and query_dir which may be helpful in finding slow requests
and other timing information

Signed-off-by: Steve French <stfrench@microsoft.com>
Reviewed-by: Pavel Shilovsky <pshilov@microsoft.com>
Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>
2019-03-05 18:10:04 -06:00
Steve French adb3b4e90e smb3: add tracepoints for query dir
Adds two tracepoints - one for query_dir done (no err) and one for query_dir_err

Sanple output:

To start the trace in one window:
       trace-cmd record -e smb3_query_dir*

Then in another window after doing an
       ls /mnt

View the trace output by:

        trace-cmd show

Sample output:

           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
              | |       |   ||||       |         |
             ls-24869 [007] .... 90695.452009: smb3_query_dir_done: xid=7 sid=0x5027d24d tid=0xb95cf25a fid=0xc41a8c3e offset=0x0 len=0x16
             ls-24869 [000] .... 90695.452764: smb3_query_dir_done: xid=8 sid=0x5027d24d tid=0xb95cf25a fid=0xc41a8c3e offset=0x0 len=0x0
             ls-24874 [003] .... 90701.506342: smb3_query_dir_done: xid=11 sid=0x5027d24d tid=0xb95cf25a fid=0x33ad3601 offset=0x0 len=0x8
             ls-24874 [003] .... 90701.506917: smb3_query_dir_done: xid=12 sid=0x5027d24d tid=0xb95cf25a fid=0x33ad3601 offset=0x0 len=0x0

Reviewed-by: Pavel Shilovsky <pshilov@microsoft.com>
Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>
Signed-off-by: Steve French <stfrench@microsoft.com>
2019-03-05 18:10:04 -06:00
Thomas Gleixner b0b2cac7e2 smb3: Cleanup license mess
Precise and non-ambiguous license information is important. The recently
added aegis header file has a SPDX license identifier, which is nice, but
at the same time it has a contradictionary license boiler plate text.

  SPDX-License-Identifier: GPL-2.0

versus

  *   This program is free software;  you can redistribute it and/or modify
  *   it under the terms of the GNU General Public License as published by
  *   the Free Software Foundation; either version 2 of the License, or
  *   (at your option) any later version.

Oh well.

Assuming that the SPDX identifier is correct and according to x86/hyper-v
contributions from Microsoft GPL V2 only is the usual license.

Remove the boiler plate as it is wrong and even if correct it is redundant.

Fixes: eccb4422cf ("smb3: Add ftrace tracepoints for improved SMB3 debugging")
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Cc: Steve French <sfrench@samba.org>
Cc: linux-cifs@vger.kernel.org
Signed-off-by: Steve French <stfrench@microsoft.com>
2019-01-24 09:37:33 -06:00
Steve French f8af49dd17 smb3: add trace point for tree connection
In debugging certain scenarios, especially reconnect cases,
it can be helpful to have a dynamic trace point for the
result of tree connect.  See sample output below
from a reconnect event. The new event is 'smb3_tcon'

            TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
               | |       |   ||||       |         |
           cifsd-6071  [001] ....  2659.897923: smb3_reconnect: server=localhost current_mid=0xa
     kworker/1:1-71    [001] ....  2666.026342: smb3_cmd_done: 	sid=0x0 tid=0x0 cmd=0 mid=0
     kworker/1:1-71    [001] ....  2666.026576: smb3_cmd_err: 	sid=0xc49e1787 tid=0x0 cmd=1 mid=1 status=0xc0000016 rc=-5
     kworker/1:1-71    [001] ....  2666.031677: smb3_cmd_done: 	sid=0xc49e1787 tid=0x0 cmd=1 mid=2
     kworker/1:1-71    [001] ....  2666.031921: smb3_cmd_done: 	sid=0xc49e1787 tid=0x6e78f05f cmd=3 mid=3
     kworker/1:1-71    [001] ....  2666.031923: smb3_tcon: xid=0 sid=0xc49e1787 tid=0x0 unc_name=\\localhost\test rc=0
     kworker/1:1-71    [001] ....  2666.032097: smb3_cmd_done: 	sid=0xc49e1787 tid=0x6e78f05f cmd=11 mid=4
     kworker/1:1-71    [001] ....  2666.032265: smb3_cmd_done: 	sid=0xc49e1787 tid=0x7912332f cmd=3 mid=5
     kworker/1:1-71    [001] ....  2666.032266: smb3_tcon: xid=0 sid=0xc49e1787 tid=0x0 unc_name=\\localhost\IPC$ rc=0
     kworker/1:1-71    [001] ....  2666.032386: smb3_cmd_done: 	sid=0xc49e1787 tid=0x7912332f cmd=11 mid=6

Signed-off-by: Steve French <stfrench@microsoft.com>
Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>
2018-11-02 14:09:41 -05:00
Steve French 179e44d49c smb3: add tracepoint for sending lease break responses to server
Be able to log a ftrace message on success and/or failure of
sending a lease break response to the server.

Example output:

           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
             | |       |   ||||       |         |
     kworker/1:1-5681  [001] .... 11123.530457: smb3_lease_done: sid=0x291e3e0f tid=0x8ba43071 lease_key=0x1852ca0d3ecd9b55847750a86716fde lease_state=0x0

Signed-off-by: Steve French <stfrench@microsoft.com>
Reviewed-by: Aurelien Aptel <aaptel@suse.com>
2018-10-23 21:16:05 -05:00
Steve French b340a4d4aa smb3: add tracepoint to catch cases where credit refund of failed op overlaps reconnect
Add tracepoint to catch potential cases where a pending operation overlapping a
reconnect could fail and incorrectly refund its credits causing the client
to think it has more credits available than the server thinks it does.

Signed-off-by: Steve French <stfrench@microsoft.com>
Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>
2018-10-23 21:16:03 -05:00
Steve French 020eec5f71 smb3: add tracepoint for slow responses
If responses take longer than one second from the server,
we can optionally log them to dmesg in current cifs.ko code
(CONFIG_CIFS_STATS2 must be configured and a
/proc/fs/cifs/cifsFYI flag must be set), but can be more useful
to log these via ftrace (tracepoint is smb3_slow_rsp) which
is easier and more granular (still requires CONFIG_CIFS_STATS2
to be configured in the build though).

Signed-off-by: Steve French <stfrench@microsoft.com>
Reviewed-by: Pavel Shilovsky <pshilov@microsoft.com>
2018-08-07 14:28:01 -05:00
Steve French bf1fdeb789 smb3: add reconnect tracepoints
Add tracepoints for reconnecting an smb3 session

Example output (from trace-cmd) with the patch
(showing the session marked for reconnect, the stat failing, and then
the subsequent SMB3 commands after the server comes back up).
The "smb3_reconnect" event is the new one.

           cifsd-25993 [000] .... 29635.368265: smb3_reconnect: server=localhost current_mid=0x1e
            stat-26200 [001] .... 29638.516403: smb3_enter: 	cifs_revalidate_dentry_attr: xid=22
            stat-26200 [001] .... 29648.723296: smb3_exit_err: 	cifs_revalidate_dentry_attr: xid=22 rc=-112
     kworker/0:1-22830 [000] .... 29653.850947: smb3_cmd_done: 	sid=0x0 tid=0x0 cmd=0 mid=0
     kworker/0:1-22830 [000] .... 29653.851191: smb3_cmd_err: 	sid=0x8ae4683c tid=0x0 cmd=1 mid=1 status=0xc0000016 rc=-5
     kworker/0:1-22830 [000] .... 29653.855254: smb3_cmd_done: 	sid=0x8ae4683c tid=0x0 cmd=1 mid=2
     kworker/0:1-22830 [000] .... 29653.855482: smb3_cmd_done: 	sid=0x8ae4683c tid=0x8084f30d cmd=3 mid=3

Signed-off-by: Steve French <stfrench@microsoft.com>
Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>
Reviewed-by: Aurelien Aptel <aaptel@suse.com>
2018-08-07 14:20:22 -05:00
Steve French e68a932b0b smb3: add tracepoint for session expired or deleted
In debugging reconnection problems, want to be able to more easily
trace cases in which the server has marked the SMB3 session
expired or deleted (to distinguish from timeout cases).

Signed-off-by: Steve French <stfrench@microsoft.com>
Reviewed-by: Ronnie Sahlberg <lsahlber@redhat.com>
2018-08-07 14:15:57 -05:00
Steve French bea851b8ba smb3: Fix mode on mkdir on smb311 mounts
mkdir was not passing the mode on smb3.11 mounts with posix extensions

Signed-off-by: Steve French <stfrench@microsoft.com>
2018-06-15 02:38:08 -05:00
Steve French 28d59363ae smb3: add tracepoints for smb2/smb3 open
add two tracepoints for open completion. One for error one for completion (open_done).
Sample output below

            TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
               | |       |   ||||       |         |
            bash-15348 [007] .... 42441.027492: smb3_enter: 	cifs_lookup: xid=45
            bash-15348 [007] .... 42441.028214: smb3_cmd_err: 	sid=0x6173e4ce tid=0xa05150e6 cmd=5 mid=105 status=0xc0000034 rc=-2
            bash-15348 [007] .... 42441.028219: smb3_open_err: xid=45 sid=0x6173e4ce tid=0xa05150e6 cr_opts=0x0 des_access=0x80 rc=-2
            bash-15348 [007] .... 42441.028225: smb3_exit_done: 	cifs_lookup: xid=45
          fop777-24560 [002] .... 42442.627617: smb3_enter: 	cifs_revalidate_dentry_attr: xid=46
          fop777-24560 [003] .... 42442.628301: smb3_cmd_err: 	sid=0x6173e4ce tid=0xa05150e6 cmd=5 mid=106 status=0xc0000034 rc=-2
          fop777-24560 [003] .... 42442.628319: smb3_open_err: xid=46 sid=0x6173e4ce tid=0xa05150e6 cr_opts=0x0 des_access=0x80 rc=-2
          fop777-24560 [003] .... 42442.628335: smb3_enter: 	cifs_atomic_open: xid=47
          fop777-24560 [003] .... 42442.629587: smb3_cmd_done: 	sid=0x6173e4ce tid=0xa05150e6 cmd=5 mid=107
          fop777-24560 [003] .... 42442.629592: smb3_open_done: xid=47 sid=0x6173e4ce tid=0xa05150e6 fid=0xb8a0984d cr_opts=0x40 des_access=0x40000080

Signed-off-by: Steve French <smfrench@gmail.com>
2018-05-30 21:42:34 -05:00
Steve French d683bcd3e5 smb3: add additional ftrace entry points for entry/exit to cifs.ko
Signed-off-by: Steve French <smfrench@gmail.com>
2018-05-30 16:06:18 -05:00
Steve French eccb4422cf smb3: Add ftrace tracepoints for improved SMB3 debugging
Although dmesg logs and wireshark network traces can be
helpful, being able to dynamically enable/disable tracepoints
(in this case via the kernel ftrace mechanism) can also be
helpful in more quickly debugging problems, and more
selectively tracing the events related to the bug report.

This patch adds 12 ftrace tracepoints to cifs.ko for SMB3 events
in some obvious locations.  Subsequent patches will add more
as needed.

Example use:
   trace-cmd record -e cifs
   <run test case>
   trace-cmd show

Various trace events can be filtered. See:
       trace-cmd list | grep cifs
for the current list of cifs tracepoints.

Sample output (from mount and writing to a file):

root@smf:/sys/kernel/debug/tracing/events/cifs# trace-cmd show
<snip>
      mount.cifs-6633  [006] ....  7246.936461: smb3_cmd_done: pid=6633 tid=0x0 sid=0x0 cmd=0 mid=0
      mount.cifs-6633  [006] ....  7246.936701: smb3_cmd_err:  pid=6633 tid=0x0 sid=0x3d9cf8e5 cmd=1 mid=1 status=0xc0000016 rc=-5
      mount.cifs-6633  [006] ....  7246.943055: smb3_cmd_done: pid=6633 tid=0x0 sid=0x3d9cf8e5 cmd=1 mid=2
      mount.cifs-6633  [006] ....  7246.943298: smb3_cmd_done: pid=6633 tid=0xf9447636 sid=0x3d9cf8e5 cmd=3 mid=3
      mount.cifs-6633  [006] ....  7246.943446: smb3_cmd_done: pid=6633 tid=0xf9447636 sid=0x3d9cf8e5 cmd=11 mid=4
      mount.cifs-6633  [006] ....  7246.943659: smb3_cmd_done: pid=6633 tid=0xe1b781a sid=0x3d9cf8e5 cmd=3 mid=5
      mount.cifs-6633  [006] ....  7246.943766: smb3_cmd_done: pid=6633 tid=0xe1b781a sid=0x3d9cf8e5 cmd=11 mid=6
      mount.cifs-6633  [006] ....  7246.943937: smb3_cmd_done: pid=6633 tid=0xe1b781a sid=0x3d9cf8e5 cmd=5 mid=7
      mount.cifs-6633  [006] ....  7246.944020: smb3_cmd_done: pid=6633 tid=0xe1b781a sid=0x3d9cf8e5 cmd=16 mid=8
      mount.cifs-6633  [006] ....  7246.944091: smb3_cmd_done: pid=6633 tid=0xe1b781a sid=0x3d9cf8e5 cmd=16 mid=9
      mount.cifs-6633  [006] ....  7246.944163: smb3_cmd_done: pid=6633 tid=0xe1b781a sid=0x3d9cf8e5 cmd=16 mid=10
      mount.cifs-6633  [006] ....  7246.944218: smb3_cmd_err:  pid=6633 tid=0xf9447636 sid=0x3d9cf8e5 cmd=11 mid=11 status=0xc0000225 rc=-2
      mount.cifs-6633  [006] ....  7246.944219: smb3_fsctl_err: xid=0 fid=0xffffffffffffffff tid=0xf9447636 sid=0x3d9cf8e5 class=0 type=393620 rc=-2
      mount.cifs-6633  [007] ....  7246.944353: smb3_cmd_done: pid=6633 tid=0xe1b781a sid=0x3d9cf8e5 cmd=16 mid=12
            bash-2071  [000] ....  7256.903844: smb3_cmd_done: pid=2071 tid=0xe1b781a sid=0x3d9cf8e5 cmd=5 mid=13
            bash-2071  [000] ....  7256.904172: smb3_cmd_done: pid=2071 tid=0xe1b781a sid=0x3d9cf8e5 cmd=16 mid=14
            bash-2071  [000] ....  7256.904471: smb3_cmd_done: pid=2071 tid=0xe1b781a sid=0x3d9cf8e5 cmd=17 mid=15
            bash-2071  [000] ....  7256.904950: smb3_cmd_done: pid=2071 tid=0xe1b781a sid=0x3d9cf8e5 cmd=5 mid=16
            bash-2071  [000] ....  7256.905305: smb3_cmd_done: pid=2071 tid=0xe1b781a sid=0x3d9cf8e5 cmd=17 mid=17
            bash-2071  [000] ....  7256.905688: smb3_cmd_done: pid=2071 tid=0xe1b781a sid=0x3d9cf8e5 cmd=6 mid=18
            bash-2071  [000] ....  7256.905809: smb3_write_done: xid=0 fid=0xd628f511 tid=0xe1b781a sid=0x3d9cf8e5 offset=0x0 len=0x1b

Signed-off-by: Steve French <stfrench@microsoft.com>
Acked-by: Ronnie Sahlberg <lsahlber@redhat.com>
2018-05-27 17:56:35 -05:00