OpenCloudOS-Kernel/fs/cifs/trace.h

941 lines
24 KiB
C
Raw Normal View History

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-18 10:16:55 +08:00
/* SPDX-License-Identifier: GPL-2.0 */
/*
* Copyright (C) 2018, Microsoft Corporation.
*
* Author(s): Steve French <stfrench@microsoft.com>
*/
#undef TRACE_SYSTEM
#define TRACE_SYSTEM cifs
#if !defined(_CIFS_TRACE_H) || defined(TRACE_HEADER_MULTI_READ)
#define _CIFS_TRACE_H
#include <linux/tracepoint.h>
/* For logging errors in read or write */
DECLARE_EVENT_CLASS(smb3_rw_err_class,
TP_PROTO(unsigned int xid,
__u64 fid,
__u32 tid,
__u64 sesid,
__u64 offset,
__u32 len,
int rc),
TP_ARGS(xid, fid, tid, sesid, offset, len, rc),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(__u64, fid)
__field(__u32, tid)
__field(__u64, sesid)
__field(__u64, offset)
__field(__u32, len)
__field(int, rc)
),
TP_fast_assign(
__entry->xid = xid;
__entry->fid = fid;
__entry->tid = tid;
__entry->sesid = sesid;
__entry->offset = offset;
__entry->len = len;
__entry->rc = rc;
),
TP_printk("\txid=%u sid=0x%llx tid=0x%x fid=0x%llx offset=0x%llx len=0x%x rc=%d",
__entry->xid, __entry->sesid, __entry->tid, __entry->fid,
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-18 10:16:55 +08:00
__entry->offset, __entry->len, __entry->rc)
)
#define DEFINE_SMB3_RW_ERR_EVENT(name) \
DEFINE_EVENT(smb3_rw_err_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
__u64 fid, \
__u32 tid, \
__u64 sesid, \
__u64 offset, \
__u32 len, \
int rc), \
TP_ARGS(xid, fid, tid, sesid, offset, len, rc))
DEFINE_SMB3_RW_ERR_EVENT(write_err);
DEFINE_SMB3_RW_ERR_EVENT(read_err);
DEFINE_SMB3_RW_ERR_EVENT(query_dir_err);
DEFINE_SMB3_RW_ERR_EVENT(zero_err);
DEFINE_SMB3_RW_ERR_EVENT(falloc_err);
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-18 10:16:55 +08:00
/* For logging successful read or write */
DECLARE_EVENT_CLASS(smb3_rw_done_class,
TP_PROTO(unsigned int xid,
__u64 fid,
__u32 tid,
__u64 sesid,
__u64 offset,
__u32 len),
TP_ARGS(xid, fid, tid, sesid, offset, len),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(__u64, fid)
__field(__u32, tid)
__field(__u64, sesid)
__field(__u64, offset)
__field(__u32, len)
),
TP_fast_assign(
__entry->xid = xid;
__entry->fid = fid;
__entry->tid = tid;
__entry->sesid = sesid;
__entry->offset = offset;
__entry->len = len;
),
TP_printk("xid=%u sid=0x%llx tid=0x%x fid=0x%llx offset=0x%llx len=0x%x",
__entry->xid, __entry->sesid, __entry->tid, __entry->fid,
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-18 10:16:55 +08:00
__entry->offset, __entry->len)
)
#define DEFINE_SMB3_RW_DONE_EVENT(name) \
DEFINE_EVENT(smb3_rw_done_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
__u64 fid, \
__u32 tid, \
__u64 sesid, \
__u64 offset, \
__u32 len), \
TP_ARGS(xid, fid, tid, sesid, offset, len))
DEFINE_SMB3_RW_DONE_EVENT(write_enter);
DEFINE_SMB3_RW_DONE_EVENT(read_enter);
DEFINE_SMB3_RW_DONE_EVENT(query_dir_enter);
DEFINE_SMB3_RW_DONE_EVENT(zero_enter);
DEFINE_SMB3_RW_DONE_EVENT(falloc_enter);
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-18 10:16:55 +08:00
DEFINE_SMB3_RW_DONE_EVENT(write_done);
DEFINE_SMB3_RW_DONE_EVENT(read_done);
DEFINE_SMB3_RW_DONE_EVENT(query_dir_done);
DEFINE_SMB3_RW_DONE_EVENT(zero_done);
DEFINE_SMB3_RW_DONE_EVENT(falloc_done);
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-18 10:16:55 +08:00
/*
* For handle based calls other than read and write, and get/set info
*/
DECLARE_EVENT_CLASS(smb3_fd_class,
TP_PROTO(unsigned int xid,
__u64 fid,
__u32 tid,
__u64 sesid),
TP_ARGS(xid, fid, tid, sesid),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(__u64, fid)
__field(__u32, tid)
__field(__u64, sesid)
),
TP_fast_assign(
__entry->xid = xid;
__entry->fid = fid;
__entry->tid = tid;
__entry->sesid = sesid;
),
TP_printk("\txid=%u sid=0x%llx tid=0x%x fid=0x%llx",
__entry->xid, __entry->sesid, __entry->tid, __entry->fid)
)
#define DEFINE_SMB3_FD_EVENT(name) \
DEFINE_EVENT(smb3_fd_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
__u64 fid, \
__u32 tid, \
__u64 sesid), \
TP_ARGS(xid, fid, tid, sesid))
DEFINE_SMB3_FD_EVENT(flush_enter);
DEFINE_SMB3_FD_EVENT(flush_done);
DEFINE_SMB3_FD_EVENT(close_enter);
DEFINE_SMB3_FD_EVENT(close_done);
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-18 10:16:55 +08:00
DECLARE_EVENT_CLASS(smb3_fd_err_class,
TP_PROTO(unsigned int xid,
__u64 fid,
__u32 tid,
__u64 sesid,
int rc),
TP_ARGS(xid, fid, tid, sesid, rc),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(__u64, fid)
__field(__u32, tid)
__field(__u64, sesid)
__field(int, rc)
),
TP_fast_assign(
__entry->xid = xid;
__entry->fid = fid;
__entry->tid = tid;
__entry->sesid = sesid;
__entry->rc = rc;
),
TP_printk("\txid=%u sid=0x%llx tid=0x%x fid=0x%llx rc=%d",
__entry->xid, __entry->sesid, __entry->tid, __entry->fid,
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-18 10:16:55 +08:00
__entry->rc)
)
#define DEFINE_SMB3_FD_ERR_EVENT(name) \
DEFINE_EVENT(smb3_fd_err_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
__u64 fid, \
__u32 tid, \
__u64 sesid, \
int rc), \
TP_ARGS(xid, fid, tid, sesid, rc))
DEFINE_SMB3_FD_ERR_EVENT(flush_err);
DEFINE_SMB3_FD_ERR_EVENT(lock_err);
DEFINE_SMB3_FD_ERR_EVENT(close_err);
/*
* For handle based query/set info calls
*/
DECLARE_EVENT_CLASS(smb3_inf_enter_class,
TP_PROTO(unsigned int xid,
__u64 fid,
__u32 tid,
__u64 sesid,
__u8 infclass,
__u32 type),
TP_ARGS(xid, fid, tid, sesid, infclass, type),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(__u64, fid)
__field(__u32, tid)
__field(__u64, sesid)
__field(__u8, infclass)
__field(__u32, type)
),
TP_fast_assign(
__entry->xid = xid;
__entry->fid = fid;
__entry->tid = tid;
__entry->sesid = sesid;
__entry->infclass = infclass;
__entry->type = type;
),
TP_printk("xid=%u sid=0x%llx tid=0x%x fid=0x%llx class=%u type=0x%x",
__entry->xid, __entry->sesid, __entry->tid, __entry->fid,
__entry->infclass, __entry->type)
)
#define DEFINE_SMB3_INF_ENTER_EVENT(name) \
DEFINE_EVENT(smb3_inf_enter_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
__u64 fid, \
__u32 tid, \
__u64 sesid, \
__u8 infclass, \
__u32 type), \
TP_ARGS(xid, fid, tid, sesid, infclass, type))
DEFINE_SMB3_INF_ENTER_EVENT(query_info_enter);
DEFINE_SMB3_INF_ENTER_EVENT(query_info_done);
DEFINE_SMB3_INF_ENTER_EVENT(notify_enter);
DEFINE_SMB3_INF_ENTER_EVENT(notify_done);
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-18 10:16:55 +08:00
DECLARE_EVENT_CLASS(smb3_inf_err_class,
TP_PROTO(unsigned int xid,
__u64 fid,
__u32 tid,
__u64 sesid,
__u8 infclass,
__u32 type,
int rc),
TP_ARGS(xid, fid, tid, sesid, infclass, type, rc),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(__u64, fid)
__field(__u32, tid)
__field(__u64, sesid)
__field(__u8, infclass)
__field(__u32, type)
__field(int, rc)
),
TP_fast_assign(
__entry->xid = xid;
__entry->fid = fid;
__entry->tid = tid;
__entry->sesid = sesid;
__entry->infclass = infclass;
__entry->type = type;
__entry->rc = rc;
),
TP_printk("xid=%u sid=0x%llx tid=0x%x fid=0x%llx class=%u type=0x%x rc=%d",
__entry->xid, __entry->sesid, __entry->tid, __entry->fid,
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-18 10:16:55 +08:00
__entry->infclass, __entry->type, __entry->rc)
)
#define DEFINE_SMB3_INF_ERR_EVENT(name) \
DEFINE_EVENT(smb3_inf_err_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
__u64 fid, \
__u32 tid, \
__u64 sesid, \
__u8 infclass, \
__u32 type, \
int rc), \
TP_ARGS(xid, fid, tid, sesid, infclass, type, rc))
DEFINE_SMB3_INF_ERR_EVENT(query_info_err);
DEFINE_SMB3_INF_ERR_EVENT(set_info_err);
DEFINE_SMB3_INF_ERR_EVENT(notify_err);
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-18 10:16:55 +08:00
DEFINE_SMB3_INF_ERR_EVENT(fsctl_err);
DECLARE_EVENT_CLASS(smb3_inf_compound_enter_class,
TP_PROTO(unsigned int xid,
__u32 tid,
__u64 sesid,
const char *full_path),
TP_ARGS(xid, tid, sesid, full_path),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(__u32, tid)
__field(__u64, sesid)
__string(path, full_path)
),
TP_fast_assign(
__entry->xid = xid;
__entry->tid = tid;
__entry->sesid = sesid;
__assign_str(path, full_path);
),
TP_printk("xid=%u sid=0x%llx tid=0x%x path=%s",
__entry->xid, __entry->sesid, __entry->tid,
__get_str(path))
)
#define DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(name) \
DEFINE_EVENT(smb3_inf_compound_enter_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
__u32 tid, \
__u64 sesid, \
const char *full_path), \
TP_ARGS(xid, tid, sesid, full_path))
DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(query_info_compound_enter);
DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(posix_query_info_compound_enter);
DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(hardlink_enter);
DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(rename_enter);
DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(rmdir_enter);
DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(set_eof_enter);
DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(set_info_compound_enter);
DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(delete_enter);
DEFINE_SMB3_INF_COMPOUND_ENTER_EVENT(mkdir_enter);
DECLARE_EVENT_CLASS(smb3_inf_compound_done_class,
TP_PROTO(unsigned int xid,
__u32 tid,
__u64 sesid),
TP_ARGS(xid, tid, sesid),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(__u32, tid)
__field(__u64, sesid)
),
TP_fast_assign(
__entry->xid = xid;
__entry->tid = tid;
__entry->sesid = sesid;
),
TP_printk("xid=%u sid=0x%llx tid=0x%x",
__entry->xid, __entry->sesid, __entry->tid)
)
#define DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(name) \
DEFINE_EVENT(smb3_inf_compound_done_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
__u32 tid, \
__u64 sesid), \
TP_ARGS(xid, tid, sesid))
DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(query_info_compound_done);
DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(posix_query_info_compound_done);
DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(hardlink_done);
DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(rename_done);
DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(rmdir_done);
DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(set_eof_done);
DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(set_info_compound_done);
DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(delete_done);
DEFINE_SMB3_INF_COMPOUND_DONE_EVENT(mkdir_done);
DECLARE_EVENT_CLASS(smb3_inf_compound_err_class,
TP_PROTO(unsigned int xid,
__u32 tid,
__u64 sesid,
int rc),
TP_ARGS(xid, tid, sesid, rc),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(__u32, tid)
__field(__u64, sesid)
__field(int, rc)
),
TP_fast_assign(
__entry->xid = xid;
__entry->tid = tid;
__entry->sesid = sesid;
__entry->rc = rc;
),
TP_printk("xid=%u sid=0x%llx tid=0x%x rc=%d",
__entry->xid, __entry->sesid, __entry->tid,
__entry->rc)
)
#define DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(name) \
DEFINE_EVENT(smb3_inf_compound_err_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
__u32 tid, \
__u64 sesid, \
int rc), \
TP_ARGS(xid, tid, sesid, rc))
DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(query_info_compound_err);
DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(posix_query_info_compound_err);
DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(hardlink_err);
DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(rename_err);
DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(rmdir_err);
DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(set_eof_err);
DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(set_info_compound_err);
DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(mkdir_err);
DEFINE_SMB3_INF_COMPOUND_ERR_EVENT(delete_err);
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-18 10:16:55 +08:00
/*
* For logging SMB3 Status code and Command for responses which return errors
*/
DECLARE_EVENT_CLASS(smb3_cmd_err_class,
TP_PROTO(__u32 tid,
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-18 10:16:55 +08:00
__u64 sesid,
__u16 cmd,
__u64 mid,
__u32 status,
int rc),
TP_ARGS(tid, sesid, cmd, mid, status, rc),
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-18 10:16:55 +08:00
TP_STRUCT__entry(
__field(__u32, tid)
__field(__u64, sesid)
__field(__u16, cmd)
__field(__u64, mid)
__field(__u32, status)
__field(int, rc)
),
TP_fast_assign(
__entry->tid = tid;
__entry->sesid = sesid;
__entry->cmd = cmd;
__entry->mid = mid;
__entry->status = status;
__entry->rc = rc;
),
TP_printk("\tsid=0x%llx tid=0x%x cmd=%u mid=%llu status=0x%x rc=%d",
__entry->sesid, __entry->tid, __entry->cmd, __entry->mid,
__entry->status, __entry->rc)
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-18 10:16:55 +08:00
)
#define DEFINE_SMB3_CMD_ERR_EVENT(name) \
DEFINE_EVENT(smb3_cmd_err_class, smb3_##name, \
TP_PROTO(__u32 tid, \
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-18 10:16:55 +08:00
__u64 sesid, \
__u16 cmd, \
__u64 mid, \
__u32 status, \
int rc), \
TP_ARGS(tid, sesid, cmd, mid, status, rc))
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-18 10:16:55 +08:00
DEFINE_SMB3_CMD_ERR_EVENT(cmd_err);
DECLARE_EVENT_CLASS(smb3_cmd_done_class,
TP_PROTO(__u32 tid,
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-18 10:16:55 +08:00
__u64 sesid,
__u16 cmd,
__u64 mid),
TP_ARGS(tid, sesid, cmd, mid),
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-18 10:16:55 +08:00
TP_STRUCT__entry(
__field(__u32, tid)
__field(__u64, sesid)
__field(__u16, cmd)
__field(__u64, mid)
),
TP_fast_assign(
__entry->tid = tid;
__entry->sesid = sesid;
__entry->cmd = cmd;
__entry->mid = mid;
),
TP_printk("\tsid=0x%llx tid=0x%x cmd=%u mid=%llu",
__entry->sesid, __entry->tid,
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-18 10:16:55 +08:00
__entry->cmd, __entry->mid)
)
#define DEFINE_SMB3_CMD_DONE_EVENT(name) \
DEFINE_EVENT(smb3_cmd_done_class, smb3_##name, \
TP_PROTO(__u32 tid, \
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-18 10:16:55 +08:00
__u64 sesid, \
__u16 cmd, \
__u64 mid), \
TP_ARGS(tid, sesid, cmd, mid))
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-18 10:16:55 +08:00
DEFINE_SMB3_CMD_DONE_EVENT(cmd_enter);
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-18 10:16:55 +08:00
DEFINE_SMB3_CMD_DONE_EVENT(cmd_done);
DEFINE_SMB3_CMD_DONE_EVENT(ses_expired);
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-18 10:16:55 +08:00
DECLARE_EVENT_CLASS(smb3_mid_class,
TP_PROTO(__u16 cmd,
__u64 mid,
__u32 pid,
unsigned long when_sent,
unsigned long when_received),
TP_ARGS(cmd, mid, pid, when_sent, when_received),
TP_STRUCT__entry(
__field(__u16, cmd)
__field(__u64, mid)
__field(__u32, pid)
__field(unsigned long, when_sent)
__field(unsigned long, when_received)
),
TP_fast_assign(
__entry->cmd = cmd;
__entry->mid = mid;
__entry->pid = pid;
__entry->when_sent = when_sent;
__entry->when_received = when_received;
),
TP_printk("\tcmd=%u mid=%llu pid=%u, when_sent=%lu when_rcv=%lu",
__entry->cmd, __entry->mid, __entry->pid, __entry->when_sent,
__entry->when_received)
)
#define DEFINE_SMB3_MID_EVENT(name) \
DEFINE_EVENT(smb3_mid_class, smb3_##name, \
TP_PROTO(__u16 cmd, \
__u64 mid, \
__u32 pid, \
unsigned long when_sent, \
unsigned long when_received), \
TP_ARGS(cmd, mid, pid, when_sent, when_received))
DEFINE_SMB3_MID_EVENT(slow_rsp);
DECLARE_EVENT_CLASS(smb3_exit_err_class,
TP_PROTO(unsigned int xid,
const char *func_name,
int rc),
TP_ARGS(xid, func_name, rc),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(const char *, func_name)
__field(int, rc)
),
TP_fast_assign(
__entry->xid = xid;
__entry->func_name = func_name;
__entry->rc = rc;
),
TP_printk("\t%s: xid=%u rc=%d",
__entry->func_name, __entry->xid, __entry->rc)
)
#define DEFINE_SMB3_EXIT_ERR_EVENT(name) \
DEFINE_EVENT(smb3_exit_err_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
const char *func_name, \
int rc), \
TP_ARGS(xid, func_name, rc))
DEFINE_SMB3_EXIT_ERR_EVENT(exit_err);
DECLARE_EVENT_CLASS(smb3_sync_err_class,
TP_PROTO(unsigned long ino,
int rc),
TP_ARGS(ino, rc),
TP_STRUCT__entry(
__field(unsigned long, ino)
__field(int, rc)
),
TP_fast_assign(
__entry->ino = ino;
__entry->rc = rc;
),
TP_printk("\tino=%lu rc=%d",
__entry->ino, __entry->rc)
)
#define DEFINE_SMB3_SYNC_ERR_EVENT(name) \
DEFINE_EVENT(smb3_sync_err_class, cifs_##name, \
TP_PROTO(unsigned long ino, \
int rc), \
TP_ARGS(ino, rc))
DEFINE_SMB3_SYNC_ERR_EVENT(fsync_err);
DEFINE_SMB3_SYNC_ERR_EVENT(flush_err);
DECLARE_EVENT_CLASS(smb3_enter_exit_class,
TP_PROTO(unsigned int xid,
const char *func_name),
TP_ARGS(xid, func_name),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(const char *, func_name)
),
TP_fast_assign(
__entry->xid = xid;
__entry->func_name = func_name;
),
TP_printk("\t%s: xid=%u",
__entry->func_name, __entry->xid)
)
#define DEFINE_SMB3_ENTER_EXIT_EVENT(name) \
DEFINE_EVENT(smb3_enter_exit_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
const char *func_name), \
TP_ARGS(xid, func_name))
DEFINE_SMB3_ENTER_EXIT_EVENT(enter);
DEFINE_SMB3_ENTER_EXIT_EVENT(exit_done);
/*
* For SMB2/SMB3 tree connect
*/
DECLARE_EVENT_CLASS(smb3_tcon_class,
TP_PROTO(unsigned int xid,
__u32 tid,
__u64 sesid,
const char *unc_name,
int rc),
TP_ARGS(xid, tid, sesid, unc_name, rc),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(__u32, tid)
__field(__u64, sesid)
cifs: Fix slab-out-of-bounds when tracing SMB tcon This patch fixes the following KASAN report: [ 779.044746] BUG: KASAN: slab-out-of-bounds in string+0xab/0x180 [ 779.044750] Read of size 1 at addr ffff88814f327968 by task trace-cmd/2812 [ 779.044756] CPU: 1 PID: 2812 Comm: trace-cmd Not tainted 5.1.0-rc1+ #62 [ 779.044760] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.0-0-ga698c89-prebuilt.qemu.org 04/01/2014 [ 779.044761] Call Trace: [ 779.044769] dump_stack+0x5b/0x90 [ 779.044775] ? string+0xab/0x180 [ 779.044781] print_address_description+0x6c/0x23c [ 779.044787] ? string+0xab/0x180 [ 779.044792] ? string+0xab/0x180 [ 779.044797] kasan_report.cold.3+0x1a/0x32 [ 779.044803] ? string+0xab/0x180 [ 779.044809] string+0xab/0x180 [ 779.044816] ? widen_string+0x160/0x160 [ 779.044822] ? vsnprintf+0x5bf/0x7f0 [ 779.044829] vsnprintf+0x4e7/0x7f0 [ 779.044836] ? pointer+0x4a0/0x4a0 [ 779.044841] ? seq_buf_vprintf+0x79/0xc0 [ 779.044848] seq_buf_vprintf+0x62/0xc0 [ 779.044855] trace_seq_printf+0x113/0x210 [ 779.044861] ? trace_seq_puts+0x110/0x110 [ 779.044867] ? trace_raw_output_prep+0xd8/0x110 [ 779.044876] trace_raw_output_smb3_tcon_class+0x9f/0xc0 [ 779.044882] print_trace_line+0x377/0x890 [ 779.044888] ? tracing_buffers_read+0x300/0x300 [ 779.044893] ? ring_buffer_read+0x58/0x70 [ 779.044899] s_show+0x6e/0x140 [ 779.044906] seq_read+0x505/0x6a0 [ 779.044913] vfs_read+0xaf/0x1b0 [ 779.044919] ksys_read+0xa1/0x130 [ 779.044925] ? kernel_write+0xa0/0xa0 [ 779.044931] ? __do_page_fault+0x3d5/0x620 [ 779.044938] do_syscall_64+0x63/0x150 [ 779.044944] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 779.044949] RIP: 0033:0x7f62c2c2db31 [ 779.044955] Code: fe ff ff 48 8d 3d 17 9e 09 00 48 83 ec 08 e8 96 02 02 00 66 0f 1f 44 00 00 8b 05 fa fc 2c 00 48 63 ff 85 c0 75 13 31 c0 0f 05 <48> 3d 00 f0 ff ff 77 57 f3 c3 0f 1f 44 00 00 55 53 48 89 d5 48 89 [ 779.044958] RSP: 002b:00007ffd6e116678 EFLAGS: 00000246 ORIG_RAX: 0000000000000000 [ 779.044964] RAX: ffffffffffffffda RBX: 0000560a38be9260 RCX: 00007f62c2c2db31 [ 779.044966] RDX: 0000000000002000 RSI: 00007ffd6e116710 RDI: 0000000000000003 [ 779.044966] RDX: 0000000000002000 RSI: 00007ffd6e116710 RDI: 0000000000000003 [ 779.044969] RBP: 00007f62c2ef5420 R08: 0000000000000000 R09: 0000000000000003 [ 779.044972] R10: ffffffffffffffa8 R11: 0000000000000246 R12: 00007ffd6e116710 [ 779.044975] R13: 0000000000002000 R14: 0000000000000d68 R15: 0000000000002000 [ 779.044981] Allocated by task 1257: [ 779.044987] __kasan_kmalloc.constprop.5+0xc1/0xd0 [ 779.044992] kmem_cache_alloc+0xad/0x1a0 [ 779.044997] getname_flags+0x6c/0x2a0 [ 779.045003] user_path_at_empty+0x1d/0x40 [ 779.045008] do_faccessat+0x12a/0x330 [ 779.045012] do_syscall_64+0x63/0x150 [ 779.045017] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 779.045019] Freed by task 1257: [ 779.045023] __kasan_slab_free+0x12e/0x180 [ 779.045029] kmem_cache_free+0x85/0x1b0 [ 779.045034] filename_lookup.part.70+0x176/0x250 [ 779.045039] do_faccessat+0x12a/0x330 [ 779.045043] do_syscall_64+0x63/0x150 [ 779.045048] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 779.045052] The buggy address belongs to the object at ffff88814f326600 which belongs to the cache names_cache of size 4096 [ 779.045057] The buggy address is located 872 bytes to the right of 4096-byte region [ffff88814f326600, ffff88814f327600) [ 779.045058] The buggy address belongs to the page: [ 779.045062] page:ffffea00053cc800 count:1 mapcount:0 mapping:ffff88815b191b40 index:0x0 compound_mapcount: 0 [ 779.045067] flags: 0x200000000010200(slab|head) [ 779.045075] raw: 0200000000010200 dead000000000100 dead000000000200 ffff88815b191b40 [ 779.045081] raw: 0000000000000000 0000000000070007 00000001ffffffff 0000000000000000 [ 779.045083] page dumped because: kasan: bad access detected [ 779.045085] Memory state around the buggy address: [ 779.045089] ffff88814f327800: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045093] ffff88814f327880: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045097] >ffff88814f327900: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045099] ^ [ 779.045103] ffff88814f327980: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045107] ffff88814f327a00: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045109] ================================================================== [ 779.045110] Disabling lock debugging due to kernel taint Correctly assign tree name str for smb3_tcon event. Signed-off-by: Paulo Alcantara (SUSE) <paulo@paulo.ac> Signed-off-by: Steve French <stfrench@microsoft.com>
2019-03-22 06:31:22 +08:00
__string(name, unc_name)
__field(int, rc)
),
TP_fast_assign(
__entry->xid = xid;
__entry->tid = tid;
__entry->sesid = sesid;
cifs: Fix slab-out-of-bounds when tracing SMB tcon This patch fixes the following KASAN report: [ 779.044746] BUG: KASAN: slab-out-of-bounds in string+0xab/0x180 [ 779.044750] Read of size 1 at addr ffff88814f327968 by task trace-cmd/2812 [ 779.044756] CPU: 1 PID: 2812 Comm: trace-cmd Not tainted 5.1.0-rc1+ #62 [ 779.044760] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.0-0-ga698c89-prebuilt.qemu.org 04/01/2014 [ 779.044761] Call Trace: [ 779.044769] dump_stack+0x5b/0x90 [ 779.044775] ? string+0xab/0x180 [ 779.044781] print_address_description+0x6c/0x23c [ 779.044787] ? string+0xab/0x180 [ 779.044792] ? string+0xab/0x180 [ 779.044797] kasan_report.cold.3+0x1a/0x32 [ 779.044803] ? string+0xab/0x180 [ 779.044809] string+0xab/0x180 [ 779.044816] ? widen_string+0x160/0x160 [ 779.044822] ? vsnprintf+0x5bf/0x7f0 [ 779.044829] vsnprintf+0x4e7/0x7f0 [ 779.044836] ? pointer+0x4a0/0x4a0 [ 779.044841] ? seq_buf_vprintf+0x79/0xc0 [ 779.044848] seq_buf_vprintf+0x62/0xc0 [ 779.044855] trace_seq_printf+0x113/0x210 [ 779.044861] ? trace_seq_puts+0x110/0x110 [ 779.044867] ? trace_raw_output_prep+0xd8/0x110 [ 779.044876] trace_raw_output_smb3_tcon_class+0x9f/0xc0 [ 779.044882] print_trace_line+0x377/0x890 [ 779.044888] ? tracing_buffers_read+0x300/0x300 [ 779.044893] ? ring_buffer_read+0x58/0x70 [ 779.044899] s_show+0x6e/0x140 [ 779.044906] seq_read+0x505/0x6a0 [ 779.044913] vfs_read+0xaf/0x1b0 [ 779.044919] ksys_read+0xa1/0x130 [ 779.044925] ? kernel_write+0xa0/0xa0 [ 779.044931] ? __do_page_fault+0x3d5/0x620 [ 779.044938] do_syscall_64+0x63/0x150 [ 779.044944] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 779.044949] RIP: 0033:0x7f62c2c2db31 [ 779.044955] Code: fe ff ff 48 8d 3d 17 9e 09 00 48 83 ec 08 e8 96 02 02 00 66 0f 1f 44 00 00 8b 05 fa fc 2c 00 48 63 ff 85 c0 75 13 31 c0 0f 05 <48> 3d 00 f0 ff ff 77 57 f3 c3 0f 1f 44 00 00 55 53 48 89 d5 48 89 [ 779.044958] RSP: 002b:00007ffd6e116678 EFLAGS: 00000246 ORIG_RAX: 0000000000000000 [ 779.044964] RAX: ffffffffffffffda RBX: 0000560a38be9260 RCX: 00007f62c2c2db31 [ 779.044966] RDX: 0000000000002000 RSI: 00007ffd6e116710 RDI: 0000000000000003 [ 779.044966] RDX: 0000000000002000 RSI: 00007ffd6e116710 RDI: 0000000000000003 [ 779.044969] RBP: 00007f62c2ef5420 R08: 0000000000000000 R09: 0000000000000003 [ 779.044972] R10: ffffffffffffffa8 R11: 0000000000000246 R12: 00007ffd6e116710 [ 779.044975] R13: 0000000000002000 R14: 0000000000000d68 R15: 0000000000002000 [ 779.044981] Allocated by task 1257: [ 779.044987] __kasan_kmalloc.constprop.5+0xc1/0xd0 [ 779.044992] kmem_cache_alloc+0xad/0x1a0 [ 779.044997] getname_flags+0x6c/0x2a0 [ 779.045003] user_path_at_empty+0x1d/0x40 [ 779.045008] do_faccessat+0x12a/0x330 [ 779.045012] do_syscall_64+0x63/0x150 [ 779.045017] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 779.045019] Freed by task 1257: [ 779.045023] __kasan_slab_free+0x12e/0x180 [ 779.045029] kmem_cache_free+0x85/0x1b0 [ 779.045034] filename_lookup.part.70+0x176/0x250 [ 779.045039] do_faccessat+0x12a/0x330 [ 779.045043] do_syscall_64+0x63/0x150 [ 779.045048] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 779.045052] The buggy address belongs to the object at ffff88814f326600 which belongs to the cache names_cache of size 4096 [ 779.045057] The buggy address is located 872 bytes to the right of 4096-byte region [ffff88814f326600, ffff88814f327600) [ 779.045058] The buggy address belongs to the page: [ 779.045062] page:ffffea00053cc800 count:1 mapcount:0 mapping:ffff88815b191b40 index:0x0 compound_mapcount: 0 [ 779.045067] flags: 0x200000000010200(slab|head) [ 779.045075] raw: 0200000000010200 dead000000000100 dead000000000200 ffff88815b191b40 [ 779.045081] raw: 0000000000000000 0000000000070007 00000001ffffffff 0000000000000000 [ 779.045083] page dumped because: kasan: bad access detected [ 779.045085] Memory state around the buggy address: [ 779.045089] ffff88814f327800: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045093] ffff88814f327880: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045097] >ffff88814f327900: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045099] ^ [ 779.045103] ffff88814f327980: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045107] ffff88814f327a00: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045109] ================================================================== [ 779.045110] Disabling lock debugging due to kernel taint Correctly assign tree name str for smb3_tcon event. Signed-off-by: Paulo Alcantara (SUSE) <paulo@paulo.ac> Signed-off-by: Steve French <stfrench@microsoft.com>
2019-03-22 06:31:22 +08:00
__assign_str(name, unc_name);
__entry->rc = rc;
),
TP_printk("xid=%u sid=0x%llx tid=0x%x unc_name=%s rc=%d",
__entry->xid, __entry->sesid, __entry->tid,
cifs: Fix slab-out-of-bounds when tracing SMB tcon This patch fixes the following KASAN report: [ 779.044746] BUG: KASAN: slab-out-of-bounds in string+0xab/0x180 [ 779.044750] Read of size 1 at addr ffff88814f327968 by task trace-cmd/2812 [ 779.044756] CPU: 1 PID: 2812 Comm: trace-cmd Not tainted 5.1.0-rc1+ #62 [ 779.044760] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.12.0-0-ga698c89-prebuilt.qemu.org 04/01/2014 [ 779.044761] Call Trace: [ 779.044769] dump_stack+0x5b/0x90 [ 779.044775] ? string+0xab/0x180 [ 779.044781] print_address_description+0x6c/0x23c [ 779.044787] ? string+0xab/0x180 [ 779.044792] ? string+0xab/0x180 [ 779.044797] kasan_report.cold.3+0x1a/0x32 [ 779.044803] ? string+0xab/0x180 [ 779.044809] string+0xab/0x180 [ 779.044816] ? widen_string+0x160/0x160 [ 779.044822] ? vsnprintf+0x5bf/0x7f0 [ 779.044829] vsnprintf+0x4e7/0x7f0 [ 779.044836] ? pointer+0x4a0/0x4a0 [ 779.044841] ? seq_buf_vprintf+0x79/0xc0 [ 779.044848] seq_buf_vprintf+0x62/0xc0 [ 779.044855] trace_seq_printf+0x113/0x210 [ 779.044861] ? trace_seq_puts+0x110/0x110 [ 779.044867] ? trace_raw_output_prep+0xd8/0x110 [ 779.044876] trace_raw_output_smb3_tcon_class+0x9f/0xc0 [ 779.044882] print_trace_line+0x377/0x890 [ 779.044888] ? tracing_buffers_read+0x300/0x300 [ 779.044893] ? ring_buffer_read+0x58/0x70 [ 779.044899] s_show+0x6e/0x140 [ 779.044906] seq_read+0x505/0x6a0 [ 779.044913] vfs_read+0xaf/0x1b0 [ 779.044919] ksys_read+0xa1/0x130 [ 779.044925] ? kernel_write+0xa0/0xa0 [ 779.044931] ? __do_page_fault+0x3d5/0x620 [ 779.044938] do_syscall_64+0x63/0x150 [ 779.044944] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 779.044949] RIP: 0033:0x7f62c2c2db31 [ 779.044955] Code: fe ff ff 48 8d 3d 17 9e 09 00 48 83 ec 08 e8 96 02 02 00 66 0f 1f 44 00 00 8b 05 fa fc 2c 00 48 63 ff 85 c0 75 13 31 c0 0f 05 <48> 3d 00 f0 ff ff 77 57 f3 c3 0f 1f 44 00 00 55 53 48 89 d5 48 89 [ 779.044958] RSP: 002b:00007ffd6e116678 EFLAGS: 00000246 ORIG_RAX: 0000000000000000 [ 779.044964] RAX: ffffffffffffffda RBX: 0000560a38be9260 RCX: 00007f62c2c2db31 [ 779.044966] RDX: 0000000000002000 RSI: 00007ffd6e116710 RDI: 0000000000000003 [ 779.044966] RDX: 0000000000002000 RSI: 00007ffd6e116710 RDI: 0000000000000003 [ 779.044969] RBP: 00007f62c2ef5420 R08: 0000000000000000 R09: 0000000000000003 [ 779.044972] R10: ffffffffffffffa8 R11: 0000000000000246 R12: 00007ffd6e116710 [ 779.044975] R13: 0000000000002000 R14: 0000000000000d68 R15: 0000000000002000 [ 779.044981] Allocated by task 1257: [ 779.044987] __kasan_kmalloc.constprop.5+0xc1/0xd0 [ 779.044992] kmem_cache_alloc+0xad/0x1a0 [ 779.044997] getname_flags+0x6c/0x2a0 [ 779.045003] user_path_at_empty+0x1d/0x40 [ 779.045008] do_faccessat+0x12a/0x330 [ 779.045012] do_syscall_64+0x63/0x150 [ 779.045017] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 779.045019] Freed by task 1257: [ 779.045023] __kasan_slab_free+0x12e/0x180 [ 779.045029] kmem_cache_free+0x85/0x1b0 [ 779.045034] filename_lookup.part.70+0x176/0x250 [ 779.045039] do_faccessat+0x12a/0x330 [ 779.045043] do_syscall_64+0x63/0x150 [ 779.045048] entry_SYSCALL_64_after_hwframe+0x44/0xa9 [ 779.045052] The buggy address belongs to the object at ffff88814f326600 which belongs to the cache names_cache of size 4096 [ 779.045057] The buggy address is located 872 bytes to the right of 4096-byte region [ffff88814f326600, ffff88814f327600) [ 779.045058] The buggy address belongs to the page: [ 779.045062] page:ffffea00053cc800 count:1 mapcount:0 mapping:ffff88815b191b40 index:0x0 compound_mapcount: 0 [ 779.045067] flags: 0x200000000010200(slab|head) [ 779.045075] raw: 0200000000010200 dead000000000100 dead000000000200 ffff88815b191b40 [ 779.045081] raw: 0000000000000000 0000000000070007 00000001ffffffff 0000000000000000 [ 779.045083] page dumped because: kasan: bad access detected [ 779.045085] Memory state around the buggy address: [ 779.045089] ffff88814f327800: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045093] ffff88814f327880: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045097] >ffff88814f327900: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045099] ^ [ 779.045103] ffff88814f327980: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045107] ffff88814f327a00: fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc fc [ 779.045109] ================================================================== [ 779.045110] Disabling lock debugging due to kernel taint Correctly assign tree name str for smb3_tcon event. Signed-off-by: Paulo Alcantara (SUSE) <paulo@paulo.ac> Signed-off-by: Steve French <stfrench@microsoft.com>
2019-03-22 06:31:22 +08:00
__get_str(name), __entry->rc)
)
#define DEFINE_SMB3_TCON_EVENT(name) \
DEFINE_EVENT(smb3_tcon_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
__u32 tid, \
__u64 sesid, \
const char *unc_name, \
int rc), \
TP_ARGS(xid, tid, sesid, unc_name, rc))
DEFINE_SMB3_TCON_EVENT(tcon);
/*
* For smb2/smb3 open (including create and mkdir) calls
*/
DECLARE_EVENT_CLASS(smb3_open_enter_class,
TP_PROTO(unsigned int xid,
__u32 tid,
__u64 sesid,
int create_options,
int desired_access),
TP_ARGS(xid, tid, sesid, create_options, desired_access),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(__u32, tid)
__field(__u64, sesid)
__field(int, create_options)
__field(int, desired_access)
),
TP_fast_assign(
__entry->xid = xid;
__entry->tid = tid;
__entry->sesid = sesid;
__entry->create_options = create_options;
__entry->desired_access = desired_access;
),
TP_printk("xid=%u sid=0x%llx tid=0x%x cr_opts=0x%x des_access=0x%x",
__entry->xid, __entry->sesid, __entry->tid,
__entry->create_options, __entry->desired_access)
)
#define DEFINE_SMB3_OPEN_ENTER_EVENT(name) \
DEFINE_EVENT(smb3_open_enter_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
__u32 tid, \
__u64 sesid, \
int create_options, \
int desired_access), \
TP_ARGS(xid, tid, sesid, create_options, desired_access))
DEFINE_SMB3_OPEN_ENTER_EVENT(open_enter);
DEFINE_SMB3_OPEN_ENTER_EVENT(posix_mkdir_enter);
DECLARE_EVENT_CLASS(smb3_open_err_class,
TP_PROTO(unsigned int xid,
__u32 tid,
__u64 sesid,
int create_options,
int desired_access,
int rc),
TP_ARGS(xid, tid, sesid, create_options, desired_access, rc),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(__u32, tid)
__field(__u64, sesid)
__field(int, create_options)
__field(int, desired_access)
__field(int, rc)
),
TP_fast_assign(
__entry->xid = xid;
__entry->tid = tid;
__entry->sesid = sesid;
__entry->create_options = create_options;
__entry->desired_access = desired_access;
__entry->rc = rc;
),
TP_printk("xid=%u sid=0x%llx tid=0x%x cr_opts=0x%x des_access=0x%x rc=%d",
__entry->xid, __entry->sesid, __entry->tid,
__entry->create_options, __entry->desired_access, __entry->rc)
)
#define DEFINE_SMB3_OPEN_ERR_EVENT(name) \
DEFINE_EVENT(smb3_open_err_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
__u32 tid, \
__u64 sesid, \
int create_options, \
int desired_access, \
int rc), \
TP_ARGS(xid, tid, sesid, create_options, desired_access, rc))
DEFINE_SMB3_OPEN_ERR_EVENT(open_err);
DEFINE_SMB3_OPEN_ERR_EVENT(posix_mkdir_err);
DECLARE_EVENT_CLASS(smb3_open_done_class,
TP_PROTO(unsigned int xid,
__u64 fid,
__u32 tid,
__u64 sesid,
int create_options,
int desired_access),
TP_ARGS(xid, fid, tid, sesid, create_options, desired_access),
TP_STRUCT__entry(
__field(unsigned int, xid)
__field(__u64, fid)
__field(__u32, tid)
__field(__u64, sesid)
__field(int, create_options)
__field(int, desired_access)
),
TP_fast_assign(
__entry->xid = xid;
__entry->fid = fid;
__entry->tid = tid;
__entry->sesid = sesid;
__entry->create_options = create_options;
__entry->desired_access = desired_access;
),
TP_printk("xid=%u sid=0x%llx tid=0x%x fid=0x%llx cr_opts=0x%x des_access=0x%x",
__entry->xid, __entry->sesid, __entry->tid, __entry->fid,
__entry->create_options, __entry->desired_access)
)
#define DEFINE_SMB3_OPEN_DONE_EVENT(name) \
DEFINE_EVENT(smb3_open_done_class, smb3_##name, \
TP_PROTO(unsigned int xid, \
__u64 fid, \
__u32 tid, \
__u64 sesid, \
int create_options, \
int desired_access), \
TP_ARGS(xid, fid, tid, sesid, create_options, desired_access))
DEFINE_SMB3_OPEN_DONE_EVENT(open_done);
DEFINE_SMB3_OPEN_DONE_EVENT(posix_mkdir_done);
DECLARE_EVENT_CLASS(smb3_lease_done_class,
TP_PROTO(__u32 lease_state,
__u32 tid,
__u64 sesid,
__u64 lease_key_low,
__u64 lease_key_high),
TP_ARGS(lease_state, tid, sesid, lease_key_low, lease_key_high),
TP_STRUCT__entry(
__field(__u32, lease_state)
__field(__u32, tid)
__field(__u64, sesid)
__field(__u64, lease_key_low)
__field(__u64, lease_key_high)
),
TP_fast_assign(
__entry->lease_state = lease_state;
__entry->tid = tid;
__entry->sesid = sesid;
__entry->lease_key_low = lease_key_low;
__entry->lease_key_high = lease_key_high;
),
TP_printk("sid=0x%llx tid=0x%x lease_key=0x%llx%llx lease_state=0x%x",
__entry->sesid, __entry->tid, __entry->lease_key_high,
__entry->lease_key_low, __entry->lease_state)
)
#define DEFINE_SMB3_LEASE_DONE_EVENT(name) \
DEFINE_EVENT(smb3_lease_done_class, smb3_##name, \
TP_PROTO(__u32 lease_state, \
__u32 tid, \
__u64 sesid, \
__u64 lease_key_low, \
__u64 lease_key_high), \
TP_ARGS(lease_state, tid, sesid, lease_key_low, lease_key_high))
DEFINE_SMB3_LEASE_DONE_EVENT(lease_done);
DECLARE_EVENT_CLASS(smb3_lease_err_class,
TP_PROTO(__u32 lease_state,
__u32 tid,
__u64 sesid,
__u64 lease_key_low,
__u64 lease_key_high,
int rc),
TP_ARGS(lease_state, tid, sesid, lease_key_low, lease_key_high, rc),
TP_STRUCT__entry(
__field(__u32, lease_state)
__field(__u32, tid)
__field(__u64, sesid)
__field(__u64, lease_key_low)
__field(__u64, lease_key_high)
__field(int, rc)
),
TP_fast_assign(
__entry->lease_state = lease_state;
__entry->tid = tid;
__entry->sesid = sesid;
__entry->lease_key_low = lease_key_low;
__entry->lease_key_high = lease_key_high;
__entry->rc = rc;
),
TP_printk("sid=0x%llx tid=0x%x lease_key=0x%llx%llx lease_state=0x%x rc=%d",
__entry->sesid, __entry->tid, __entry->lease_key_high,
__entry->lease_key_low, __entry->lease_state, __entry->rc)
)
#define DEFINE_SMB3_LEASE_ERR_EVENT(name) \
DEFINE_EVENT(smb3_lease_err_class, smb3_##name, \
TP_PROTO(__u32 lease_state, \
__u32 tid, \
__u64 sesid, \
__u64 lease_key_low, \
__u64 lease_key_high, \
int rc), \
TP_ARGS(lease_state, tid, sesid, lease_key_low, lease_key_high, rc))
DEFINE_SMB3_LEASE_ERR_EVENT(lease_err);
DECLARE_EVENT_CLASS(smb3_reconnect_class,
TP_PROTO(__u64 currmid,
__u64 conn_id,
char *hostname),
TP_ARGS(currmid, conn_id, hostname),
TP_STRUCT__entry(
__field(__u64, currmid)
__field(__u64, conn_id)
__field(char *, hostname)
),
TP_fast_assign(
__entry->currmid = currmid;
__entry->conn_id = conn_id;
__entry->hostname = hostname;
),
TP_printk("conn_id=0x%llx server=%s current_mid=%llu",
__entry->conn_id,
__entry->hostname,
__entry->currmid)
)
#define DEFINE_SMB3_RECONNECT_EVENT(name) \
DEFINE_EVENT(smb3_reconnect_class, smb3_##name, \
TP_PROTO(__u64 currmid, \
__u64 conn_id, \
char *hostname), \
TP_ARGS(currmid, conn_id, hostname))
DEFINE_SMB3_RECONNECT_EVENT(reconnect);
DEFINE_SMB3_RECONNECT_EVENT(partial_send_reconnect);
DECLARE_EVENT_CLASS(smb3_credit_class,
TP_PROTO(__u64 currmid,
__u64 conn_id,
char *hostname,
int credits,
int credits_to_add,
int in_flight),
TP_ARGS(currmid, conn_id, hostname, credits, credits_to_add, in_flight),
TP_STRUCT__entry(
__field(__u64, currmid)
__field(__u64, conn_id)
__field(char *, hostname)
__field(int, credits)
__field(int, credits_to_add)
__field(int, in_flight)
),
TP_fast_assign(
__entry->currmid = currmid;
__entry->conn_id = conn_id;
__entry->hostname = hostname;
__entry->credits = credits;
__entry->credits_to_add = credits_to_add;
__entry->in_flight = in_flight;
),
TP_printk("conn_id=0x%llx server=%s current_mid=%llu "
"credits=%d credit_change=%d in_flight=%d",
__entry->conn_id,
__entry->hostname,
__entry->currmid,
__entry->credits,
__entry->credits_to_add,
__entry->in_flight)
)
#define DEFINE_SMB3_CREDIT_EVENT(name) \
DEFINE_EVENT(smb3_credit_class, smb3_##name, \
TP_PROTO(__u64 currmid, \
__u64 conn_id, \
char *hostname, \
int credits, \
int credits_to_add, \
int in_flight), \
TP_ARGS(currmid, conn_id, hostname, credits, credits_to_add, in_flight))
DEFINE_SMB3_CREDIT_EVENT(reconnect_with_invalid_credits);
DEFINE_SMB3_CREDIT_EVENT(reconnect_detected);
DEFINE_SMB3_CREDIT_EVENT(credit_timeout);
DEFINE_SMB3_CREDIT_EVENT(insufficient_credits);
DEFINE_SMB3_CREDIT_EVENT(too_many_credits);
DEFINE_SMB3_CREDIT_EVENT(add_credits);
DEFINE_SMB3_CREDIT_EVENT(set_credits);
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-18 10:16:55 +08:00
#endif /* _CIFS_TRACE_H */
#undef TRACE_INCLUDE_PATH
#define TRACE_INCLUDE_PATH .
#define TRACE_INCLUDE_FILE trace
#include <trace/define_trace.h>