Patch updated with additional tracepoint locations and some formatting
improvements. There are some obvious additional tracepoints that could
be added, but this should be a reasonable group to start with.
From edc02d6f9dc24963d510c7ef59067428d3b082d3 Mon Sep 17 00:00:00 2001
From: Steve French <[email protected]>
Date: Thu, 17 May 2018 21:16:55 -0500
Subject: [PATCH] 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 <[email protected]>
---
fs/cifs/Makefile | 7 +-
fs/cifs/smb2maperror.c | 10 +-
fs/cifs/smb2pdu.c | 56 +++++++-
fs/cifs/trace.c | 18 +++
fs/cifs/trace.h | 298 +++++++++++++++++++++++++++++++++++++++++
5 files changed, 379 insertions(+), 10 deletions(-)
create mode 100644 fs/cifs/trace.c
create mode 100644 fs/cifs/trace.h
diff --git a/fs/cifs/Makefile b/fs/cifs/Makefile
index 7e4a1e2f0696..85817991ee68 100644
--- a/fs/cifs/Makefile
+++ b/fs/cifs/Makefile
@@ -1,11 +1,12 @@
# SPDX-License-Identifier: GPL-2.0
#
-# Makefile for Linux CIFS VFS client
+# Makefile for Linux CIFS/SMB2/SMB3 VFS client
#
+ccflags-y += -I$(src) # needed for trace events
obj-$(CONFIG_CIFS) += cifs.o
-cifs-y := cifsfs.o cifssmb.o cifs_debug.o connect.o dir.o file.o inode.o \
- link.o misc.o netmisc.o smbencrypt.o transport.o asn1.o \
+cifs-y := trace.o cifsfs.o cifssmb.o cifs_debug.o connect.o dir.o file.o \
+ inode.o link.o misc.o netmisc.o smbencrypt.o transport.o asn1.o \
cifs_unicode.o nterr.o cifsencrypt.o \
readdir.o ioctl.o sess.o export.o smb1ops.o winucase.o \
smb2ops.o smb2maperror.o smb2transport.o \
diff --git a/fs/cifs/smb2maperror.c b/fs/cifs/smb2maperror.c
index 3bfc9c990724..20185be4a93d 100644
--- a/fs/cifs/smb2maperror.c
+++ b/fs/cifs/smb2maperror.c
@@ -27,6 +27,7 @@
#include "smb2proto.h"
#include "smb2status.h"
#include "smb2glob.h"
+#include "trace.h"
struct status_to_posix_error {
__le32 smb2_status;
@@ -2455,8 +2456,12 @@ map_smb2_to_linux_error(char *buf, bool log_err)
int rc = -EIO;
__le32 smb2err = shdr->Status;
- if (smb2err == 0)
+ if (smb2err == 0) {
+ trace_smb3_cmd_done(le32_to_cpu(shdr->ProcessId), shdr->TreeId,
+ shdr->SessionId, le16_to_cpu(shdr->Command),
+ le64_to_cpu(shdr->MessageId));
return 0;
+ }
/* mask facility */
if (log_err && (smb2err != STATUS_MORE_PROCESSING_REQUIRED) &&
@@ -2478,5 +2483,8 @@ map_smb2_to_linux_error(char *buf, bool log_err)
cifs_dbg(FYI, "Mapping SMB2 status code 0x%08x to POSIX err %d\n",
__le32_to_cpu(smb2err), rc);
+ trace_smb3_cmd_err(le32_to_cpu(shdr->ProcessId), shdr->TreeId,
+ shdr->SessionId, le16_to_cpu(shdr->Command),
+ le64_to_cpu(shdr->MessageId), le32_to_cpu(smb2err), rc);
return rc;
}
diff --git a/fs/cifs/smb2pdu.c b/fs/cifs/smb2pdu.c
index 35350057fc23..47d53314fc7f 100644
--- a/fs/cifs/smb2pdu.c
+++ b/fs/cifs/smb2pdu.c
@@ -49,6 +49,7 @@
#include "cifspdu.h"
#include "cifs_spnego.h"
#include "smbdirect.h"
+#include "trace.h"
/*
* The following table defines the expected "StructureSize" of SMB2 requests
@@ -2090,6 +2091,10 @@ SMB2_ioctl(const unsigned int xid, struct
cifs_tcon *tcon, u64 persistent_fid,
cifs_small_buf_release(req);
rsp = (struct smb2_ioctl_rsp *)rsp_iov.iov_base;
+ if (rc != 0)
+ trace_smb3_fsctl_err(xid, persistent_fid, tcon->tid,
+ ses->Suid, 0, opcode, rc);
+
if ((rc != 0) && (rc != -EINVAL)) {
cifs_stats_fail_inc(tcon, SMB2_IOCTL_HE);
goto ioctl_exit;
@@ -2200,6 +2205,8 @@ SMB2_close_flags(const unsigned int xid, struct
cifs_tcon *tcon,
if (rc != 0) {
cifs_stats_fail_inc(tcon, SMB2_CLOSE_HE);
+ trace_smb3_close_err(xid, persistent_fid, tcon->tid, ses->Suid,
+ rc);
goto close_exit;
}
@@ -2326,6 +2333,8 @@ query_info(const unsigned int xid, struct cifs_tcon *tcon,
if (rc) {
cifs_stats_fail_inc(tcon, SMB2_QUERY_INFO_HE);
+ trace_smb3_query_info_err(xid, persistent_fid, tcon->tid,
+ ses->Suid, info_class, (__u32)info_type, rc);
goto qinf_exit;
}
@@ -2556,8 +2565,11 @@ SMB2_flush(const unsigned int xid, struct
cifs_tcon *tcon, u64 persistent_fid,
rc = smb2_send_recv(xid, ses, iov, 1, &resp_buftype, flags, &rsp_iov);
cifs_small_buf_release(req);
- if (rc != 0)
+ if (rc != 0) {
cifs_stats_fail_inc(tcon, SMB2_FLUSH_HE);
+ trace_smb3_flush_err(xid, persistent_fid, tcon->tid, ses->Suid,
+ rc);
+ }
free_rsp_buf(resp_buftype, rsp_iov.iov_base);
return rc;
@@ -2799,7 +2811,13 @@ smb2_async_readv(struct cifs_readdata *rdata)
if (rc) {
kref_put(&rdata->refcount, cifs_readdata_release);
cifs_stats_fail_inc(io_parms.tcon, SMB2_READ_HE);
- }
+ trace_smb3_read_err(rc, 0 /* xid */, io_parms.persistent_fid,
+ io_parms.tcon->tid, io_parms.tcon->ses->Suid,
+ io_parms.offset, io_parms.length);
+ } else
+ trace_smb3_read_done(0 /* xid */, io_parms.persistent_fid,
+ io_parms.tcon->tid, io_parms.tcon->ses->Suid,
+ io_parms.offset, io_parms.length);
cifs_small_buf_release(buf);
return rc;
@@ -2840,9 +2858,15 @@ SMB2_read(const unsigned int xid, struct
cifs_io_parms *io_parms,
cifs_stats_fail_inc(io_parms->tcon, SMB2_READ_HE);
cifs_dbg(VFS, "Send error in read = %d\n", rc);
}
+ trace_smb3_read_err(rc, xid, req->PersistentFileId,
+ io_parms->tcon->tid, ses->Suid,
+ io_parms->offset, io_parms->length);
free_rsp_buf(resp_buftype, rsp_iov.iov_base);
return rc == -ENODATA ? 0 : rc;
- }
+ } else
+ trace_smb3_read_done(xid, req->PersistentFileId,
+ io_parms->tcon->tid, ses->Suid,
+ io_parms->offset, io_parms->length);
*nbytes = le32_to_cpu(rsp->DataLength);
if ((*nbytes > CIFS_MAX_MSGSIZE) ||
@@ -3058,9 +3082,15 @@ smb2_async_writev(struct cifs_writedata *wdata,
wdata, flags);
if (rc) {
+ trace_smb3_write_err(0 /* no xid */, req->PersistentFileId,
+ tcon->tid, tcon->ses->Suid, wdata->offset,
+ wdata->bytes, rc);
kref_put(&wdata->refcount, release);
cifs_stats_fail_inc(tcon, SMB2_WRITE_HE);
- }
+ } else
+ trace_smb3_write_done(0 /* no xid */, req->PersistentFileId,
+ tcon->tid, tcon->ses->Suid, wdata->offset,
+ wdata->bytes);
async_writev_out:
cifs_small_buf_release(req);
@@ -3124,10 +3154,19 @@ SMB2_write(const unsigned int xid, struct
cifs_io_parms *io_parms,
rsp = (struct smb2_write_rsp *)rsp_iov.iov_base;
if (rc) {
+ trace_smb3_write_err(xid, req->PersistentFileId,
+ io_parms->tcon->tid,
+ io_parms->tcon->ses->Suid,
+ io_parms->offset, io_parms->length, rc);
cifs_stats_fail_inc(io_parms->tcon, SMB2_WRITE_HE);
cifs_dbg(VFS, "Send error in write = %d\n", rc);
- } else
+ } else {
*nbytes = le32_to_cpu(rsp->DataLength);
+ trace_smb3_write_done(xid, req->PersistentFileId,
+ io_parms->tcon->tid,
+ io_parms->tcon->ses->Suid,
+ io_parms->offset, *nbytes);
+ }
free_rsp_buf(resp_buftype, rsp);
return rc;
@@ -3374,8 +3413,11 @@ send_set_info(const unsigned int xid, struct
cifs_tcon *tcon,
cifs_small_buf_release(req);
rsp = (struct smb2_set_info_rsp *)rsp_iov.iov_base;
- if (rc != 0)
+ if (rc != 0) {
cifs_stats_fail_inc(tcon, SMB2_SET_INFO_HE);
+ trace_smb3_set_info_err(xid, persistent_fid, tcon->tid,
+ ses->Suid, info_class, (__u32)info_type, rc);
+ }
free_rsp_buf(resp_buftype, rsp);
kfree(iov);
@@ -3766,6 +3808,8 @@ smb2_lockv(const unsigned int xid, struct cifs_tcon *tcon,
if (rc) {
cifs_dbg(FYI, "Send error in smb2_lockv = %d\n", rc);
cifs_stats_fail_inc(tcon, SMB2_LOCK_HE);
+ trace_smb3_lock_err(xid, persist_fid, tcon->tid,
+ tcon->ses->Suid, rc);
}
return rc;
diff --git a/fs/cifs/trace.c b/fs/cifs/trace.c
new file mode 100644
index 000000000000..bd4a546feec1
--- /dev/null
+++ b/fs/cifs/trace.c
@@ -0,0 +1,18 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Copyright (C) 2018, Microsoft Corporation.
+ *
+ * Author(s): Steve French <[email protected]>
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See
+ * the GNU General Public License for more details.
+ */
+#define CREATE_TRACE_POINTS
+#include "trace.h"
diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h
new file mode 100644
index 000000000000..935a58979e1b
--- /dev/null
+++ b/fs/cifs/trace.h
@@ -0,0 +1,298 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+/*
+ * Copyright (C) 2018, Microsoft Corporation.
+ *
+ * Author(s): Steve French <[email protected]>
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See
+ * the GNU General Public License for more details.
+ */
+#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("xid=%u fid=0x%llx tid=0x%x sid=0x%llx offset=0x%llx
len=0x%x rc=%d",
+ __entry->xid, __entry->fid, __entry->tid, __entry->sesid,
+ __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);
+
+
+/* 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 fid=0x%llx tid=0x%x sid=0x%llx offset=0x%llx len=0x%x",
+ __entry->xid, __entry->fid, __entry->tid, __entry->sesid,
+ __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_done);
+DEFINE_SMB3_RW_DONE_EVENT(read_done);
+
+/*
+ * For handle based calls other than read and write, and get/set info
+ */
+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("xid=%u fid=0x%llx tid=0x%x sid=0x%llx rc=%d",
+ __entry->xid, __entry->fid, __entry->tid, __entry->sesid,
+ __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_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 fid=0x%llx tid=0x%x sid=0x%llx class=%u type=0x%x rc=%d",
+ __entry->xid, __entry->fid, __entry->tid, __entry->sesid,
+ __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(fsctl_err);
+
+/*
+ * For logging SMB3 Status code and Command for responses which return errors
+ */
+DECLARE_EVENT_CLASS(smb3_cmd_err_class,
+ TP_PROTO(__u32 pid,
+ __u32 tid,
+ __u64 sesid,
+ __u16 cmd,
+ __u64 mid,
+ __u32 status,
+ int rc),
+ TP_ARGS(pid, tid, sesid, cmd, mid, status, rc),
+ TP_STRUCT__entry(
+ __field(__u32, pid)
+ __field(__u32, tid)
+ __field(__u64, sesid)
+ __field(__u16, cmd)
+ __field(__u64, mid)
+ __field(__u32, status)
+ __field(int, rc)
+ ),
+ TP_fast_assign(
+ __entry->pid = pid;
+ __entry->tid = tid;
+ __entry->sesid = sesid;
+ __entry->cmd = cmd;
+ __entry->mid = mid;
+ __entry->status = status;
+ __entry->rc = rc;
+ ),
+ TP_printk(" pid=%u tid=0x%x sid=0x%llx cmd=%u mid=%llu status=0x%x rc=%d",
+ __entry->pid, __entry->tid, __entry->sesid,
+ __entry->cmd, __entry->mid, __entry->status, __entry->rc)
+)
+
+#define DEFINE_SMB3_CMD_ERR_EVENT(name) \
+DEFINE_EVENT(smb3_cmd_err_class, smb3_##name, \
+ TP_PROTO(unsigned int pid, \
+ __u32 tid, \
+ __u64 sesid, \
+ __u16 cmd, \
+ __u64 mid, \
+ __u32 status, \
+ int rc), \
+ TP_ARGS(pid, tid, sesid, cmd, mid, status, rc))
+
+DEFINE_SMB3_CMD_ERR_EVENT(cmd_err);
+
+DECLARE_EVENT_CLASS(smb3_cmd_done_class,
+ TP_PROTO(__u32 pid,
+ __u32 tid,
+ __u64 sesid,
+ __u16 cmd,
+ __u64 mid),
+ TP_ARGS(pid, tid, sesid, cmd, mid),
+ TP_STRUCT__entry(
+ __field(__u32, pid)
+ __field(__u32, tid)
+ __field(__u64, sesid)
+ __field(__u16, cmd)
+ __field(__u64, mid)
+ ),
+ TP_fast_assign(
+ __entry->pid = pid;
+ __entry->tid = tid;
+ __entry->sesid = sesid;
+ __entry->cmd = cmd;
+ __entry->mid = mid;
+ ),
+ TP_printk("pid=%u tid=0x%x sid=0x%llx cmd=%u mid=%llu",
+ __entry->pid, __entry->tid, __entry->sesid,
+ __entry->cmd, __entry->mid)
+)
+
+#define DEFINE_SMB3_CMD_DONE_EVENT(name) \
+DEFINE_EVENT(smb3_cmd_done_class, smb3_##name, \
+ TP_PROTO(unsigned int pid, \
+ __u32 tid, \
+ __u64 sesid, \
+ __u16 cmd, \
+ __u64 mid), \
+ TP_ARGS(pid, tid, sesid, cmd, mid))
+
+DEFINE_SMB3_CMD_DONE_EVENT(cmd_done);
+
+#endif /* _CIFS_TRACE_H */
+
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+#define TRACE_INCLUDE_FILE trace
+#include <trace/define_trace.h>
--
--
Thanks,
Steve
Very nice.
Acked-by: Ronnie Sahlberg <[email protected]>
Possibly change the output from
pid=6633 tid=0x0 sid=0x0 cmd=0 mid=0
to
cmd=0 mid=0 pid=6633 tid=0x0 sid=0x0
just to make it easier for human-searching. I think the cmd will be useful much more often than pid/tid/sid
and this would make it easier to look for as all cmd= entries will be aligned to the same column.
----- Original Message -----
From: "Steve French" <[email protected]>
To: "CIFS" <[email protected]>, "LKML" <[email protected]>, "samba-technical" <[email protected]>, "linux-fsdevel" <[email protected]>
Sent: Friday, 18 May, 2018 12:36:36 PM
Subject: [PATCHv2][SMB3] Add kernel trace support
Patch updated with additional tracepoint locations and some formatting
improvements. There are some obvious additional tracepoints that could
be added, but this should be a reasonable group to start with.
From edc02d6f9dc24963d510c7ef59067428d3b082d3 Mon Sep 17 00:00:00 2001
From: Steve French <[email protected]>
Date: Thu, 17 May 2018 21:16:55 -0500
Subject: [PATCH] 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 <[email protected]>
---
fs/cifs/Makefile | 7 +-
fs/cifs/smb2maperror.c | 10 +-
fs/cifs/smb2pdu.c | 56 +++++++-
fs/cifs/trace.c | 18 +++
fs/cifs/trace.h | 298 +++++++++++++++++++++++++++++++++++++++++
5 files changed, 379 insertions(+), 10 deletions(-)
create mode 100644 fs/cifs/trace.c
create mode 100644 fs/cifs/trace.h
diff --git a/fs/cifs/Makefile b/fs/cifs/Makefile
index 7e4a1e2f0696..85817991ee68 100644
--- a/fs/cifs/Makefile
+++ b/fs/cifs/Makefile
@@ -1,11 +1,12 @@
# SPDX-License-Identifier: GPL-2.0
#
-# Makefile for Linux CIFS VFS client
+# Makefile for Linux CIFS/SMB2/SMB3 VFS client
#
+ccflags-y += -I$(src) # needed for trace events
obj-$(CONFIG_CIFS) += cifs.o
-cifs-y := cifsfs.o cifssmb.o cifs_debug.o connect.o dir.o file.o inode.o \
- link.o misc.o netmisc.o smbencrypt.o transport.o asn1.o \
+cifs-y := trace.o cifsfs.o cifssmb.o cifs_debug.o connect.o dir.o file.o \
+ inode.o link.o misc.o netmisc.o smbencrypt.o transport.o asn1.o \
cifs_unicode.o nterr.o cifsencrypt.o \
readdir.o ioctl.o sess.o export.o smb1ops.o winucase.o \
smb2ops.o smb2maperror.o smb2transport.o \
diff --git a/fs/cifs/smb2maperror.c b/fs/cifs/smb2maperror.c
index 3bfc9c990724..20185be4a93d 100644
--- a/fs/cifs/smb2maperror.c
+++ b/fs/cifs/smb2maperror.c
@@ -27,6 +27,7 @@
#include "smb2proto.h"
#include "smb2status.h"
#include "smb2glob.h"
+#include "trace.h"
struct status_to_posix_error {
__le32 smb2_status;
@@ -2455,8 +2456,12 @@ map_smb2_to_linux_error(char *buf, bool log_err)
int rc = -EIO;
__le32 smb2err = shdr->Status;
- if (smb2err == 0)
+ if (smb2err == 0) {
+ trace_smb3_cmd_done(le32_to_cpu(shdr->ProcessId), shdr->TreeId,
+ shdr->SessionId, le16_to_cpu(shdr->Command),
+ le64_to_cpu(shdr->MessageId));
return 0;
+ }
/* mask facility */
if (log_err && (smb2err != STATUS_MORE_PROCESSING_REQUIRED) &&
@@ -2478,5 +2483,8 @@ map_smb2_to_linux_error(char *buf, bool log_err)
cifs_dbg(FYI, "Mapping SMB2 status code 0x%08x to POSIX err %d\n",
__le32_to_cpu(smb2err), rc);
+ trace_smb3_cmd_err(le32_to_cpu(shdr->ProcessId), shdr->TreeId,
+ shdr->SessionId, le16_to_cpu(shdr->Command),
+ le64_to_cpu(shdr->MessageId), le32_to_cpu(smb2err), rc);
return rc;
}
diff --git a/fs/cifs/smb2pdu.c b/fs/cifs/smb2pdu.c
index 35350057fc23..47d53314fc7f 100644
--- a/fs/cifs/smb2pdu.c
+++ b/fs/cifs/smb2pdu.c
@@ -49,6 +49,7 @@
#include "cifspdu.h"
#include "cifs_spnego.h"
#include "smbdirect.h"
+#include "trace.h"
/*
* The following table defines the expected "StructureSize" of SMB2 requests
@@ -2090,6 +2091,10 @@ SMB2_ioctl(const unsigned int xid, struct
cifs_tcon *tcon, u64 persistent_fid,
cifs_small_buf_release(req);
rsp = (struct smb2_ioctl_rsp *)rsp_iov.iov_base;
+ if (rc != 0)
+ trace_smb3_fsctl_err(xid, persistent_fid, tcon->tid,
+ ses->Suid, 0, opcode, rc);
+
if ((rc != 0) && (rc != -EINVAL)) {
cifs_stats_fail_inc(tcon, SMB2_IOCTL_HE);
goto ioctl_exit;
@@ -2200,6 +2205,8 @@ SMB2_close_flags(const unsigned int xid, struct
cifs_tcon *tcon,
if (rc != 0) {
cifs_stats_fail_inc(tcon, SMB2_CLOSE_HE);
+ trace_smb3_close_err(xid, persistent_fid, tcon->tid, ses->Suid,
+ rc);
goto close_exit;
}
@@ -2326,6 +2333,8 @@ query_info(const unsigned int xid, struct cifs_tcon *tcon,
if (rc) {
cifs_stats_fail_inc(tcon, SMB2_QUERY_INFO_HE);
+ trace_smb3_query_info_err(xid, persistent_fid, tcon->tid,
+ ses->Suid, info_class, (__u32)info_type, rc);
goto qinf_exit;
}
@@ -2556,8 +2565,11 @@ SMB2_flush(const unsigned int xid, struct
cifs_tcon *tcon, u64 persistent_fid,
rc = smb2_send_recv(xid, ses, iov, 1, &resp_buftype, flags, &rsp_iov);
cifs_small_buf_release(req);
- if (rc != 0)
+ if (rc != 0) {
cifs_stats_fail_inc(tcon, SMB2_FLUSH_HE);
+ trace_smb3_flush_err(xid, persistent_fid, tcon->tid, ses->Suid,
+ rc);
+ }
free_rsp_buf(resp_buftype, rsp_iov.iov_base);
return rc;
@@ -2799,7 +2811,13 @@ smb2_async_readv(struct cifs_readdata *rdata)
if (rc) {
kref_put(&rdata->refcount, cifs_readdata_release);
cifs_stats_fail_inc(io_parms.tcon, SMB2_READ_HE);
- }
+ trace_smb3_read_err(rc, 0 /* xid */, io_parms.persistent_fid,
+ io_parms.tcon->tid, io_parms.tcon->ses->Suid,
+ io_parms.offset, io_parms.length);
+ } else
+ trace_smb3_read_done(0 /* xid */, io_parms.persistent_fid,
+ io_parms.tcon->tid, io_parms.tcon->ses->Suid,
+ io_parms.offset, io_parms.length);
cifs_small_buf_release(buf);
return rc;
@@ -2840,9 +2858,15 @@ SMB2_read(const unsigned int xid, struct
cifs_io_parms *io_parms,
cifs_stats_fail_inc(io_parms->tcon, SMB2_READ_HE);
cifs_dbg(VFS, "Send error in read = %d\n", rc);
}
+ trace_smb3_read_err(rc, xid, req->PersistentFileId,
+ io_parms->tcon->tid, ses->Suid,
+ io_parms->offset, io_parms->length);
free_rsp_buf(resp_buftype, rsp_iov.iov_base);
return rc == -ENODATA ? 0 : rc;
- }
+ } else
+ trace_smb3_read_done(xid, req->PersistentFileId,
+ io_parms->tcon->tid, ses->Suid,
+ io_parms->offset, io_parms->length);
*nbytes = le32_to_cpu(rsp->DataLength);
if ((*nbytes > CIFS_MAX_MSGSIZE) ||
@@ -3058,9 +3082,15 @@ smb2_async_writev(struct cifs_writedata *wdata,
wdata, flags);
if (rc) {
+ trace_smb3_write_err(0 /* no xid */, req->PersistentFileId,
+ tcon->tid, tcon->ses->Suid, wdata->offset,
+ wdata->bytes, rc);
kref_put(&wdata->refcount, release);
cifs_stats_fail_inc(tcon, SMB2_WRITE_HE);
- }
+ } else
+ trace_smb3_write_done(0 /* no xid */, req->PersistentFileId,
+ tcon->tid, tcon->ses->Suid, wdata->offset,
+ wdata->bytes);
async_writev_out:
cifs_small_buf_release(req);
@@ -3124,10 +3154,19 @@ SMB2_write(const unsigned int xid, struct
cifs_io_parms *io_parms,
rsp = (struct smb2_write_rsp *)rsp_iov.iov_base;
if (rc) {
+ trace_smb3_write_err(xid, req->PersistentFileId,
+ io_parms->tcon->tid,
+ io_parms->tcon->ses->Suid,
+ io_parms->offset, io_parms->length, rc);
cifs_stats_fail_inc(io_parms->tcon, SMB2_WRITE_HE);
cifs_dbg(VFS, "Send error in write = %d\n", rc);
- } else
+ } else {
*nbytes = le32_to_cpu(rsp->DataLength);
+ trace_smb3_write_done(xid, req->PersistentFileId,
+ io_parms->tcon->tid,
+ io_parms->tcon->ses->Suid,
+ io_parms->offset, *nbytes);
+ }
free_rsp_buf(resp_buftype, rsp);
return rc;
@@ -3374,8 +3413,11 @@ send_set_info(const unsigned int xid, struct
cifs_tcon *tcon,
cifs_small_buf_release(req);
rsp = (struct smb2_set_info_rsp *)rsp_iov.iov_base;
- if (rc != 0)
+ if (rc != 0) {
cifs_stats_fail_inc(tcon, SMB2_SET_INFO_HE);
+ trace_smb3_set_info_err(xid, persistent_fid, tcon->tid,
+ ses->Suid, info_class, (__u32)info_type, rc);
+ }
free_rsp_buf(resp_buftype, rsp);
kfree(iov);
@@ -3766,6 +3808,8 @@ smb2_lockv(const unsigned int xid, struct cifs_tcon *tcon,
if (rc) {
cifs_dbg(FYI, "Send error in smb2_lockv = %d\n", rc);
cifs_stats_fail_inc(tcon, SMB2_LOCK_HE);
+ trace_smb3_lock_err(xid, persist_fid, tcon->tid,
+ tcon->ses->Suid, rc);
}
return rc;
diff --git a/fs/cifs/trace.c b/fs/cifs/trace.c
new file mode 100644
index 000000000000..bd4a546feec1
--- /dev/null
+++ b/fs/cifs/trace.c
@@ -0,0 +1,18 @@
+// SPDX-License-Identifier: GPL-2.0
+/*
+ * Copyright (C) 2018, Microsoft Corporation.
+ *
+ * Author(s): Steve French <[email protected]>
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See
+ * the GNU General Public License for more details.
+ */
+#define CREATE_TRACE_POINTS
+#include "trace.h"
diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h
new file mode 100644
index 000000000000..935a58979e1b
--- /dev/null
+++ b/fs/cifs/trace.h
@@ -0,0 +1,298 @@
+/* SPDX-License-Identifier: GPL-2.0 */
+/*
+ * Copyright (C) 2018, Microsoft Corporation.
+ *
+ * Author(s): Steve French <[email protected]>
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See
+ * the GNU General Public License for more details.
+ */
+#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("xid=%u fid=0x%llx tid=0x%x sid=0x%llx offset=0x%llx
len=0x%x rc=%d",
+ __entry->xid, __entry->fid, __entry->tid, __entry->sesid,
+ __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);
+
+
+/* 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 fid=0x%llx tid=0x%x sid=0x%llx offset=0x%llx len=0x%x",
+ __entry->xid, __entry->fid, __entry->tid, __entry->sesid,
+ __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_done);
+DEFINE_SMB3_RW_DONE_EVENT(read_done);
+
+/*
+ * For handle based calls other than read and write, and get/set info
+ */
+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("xid=%u fid=0x%llx tid=0x%x sid=0x%llx rc=%d",
+ __entry->xid, __entry->fid, __entry->tid, __entry->sesid,
+ __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_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 fid=0x%llx tid=0x%x sid=0x%llx class=%u type=0x%x rc=%d",
+ __entry->xid, __entry->fid, __entry->tid, __entry->sesid,
+ __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(fsctl_err);
+
+/*
+ * For logging SMB3 Status code and Command for responses which return errors
+ */
+DECLARE_EVENT_CLASS(smb3_cmd_err_class,
+ TP_PROTO(__u32 pid,
+ __u32 tid,
+ __u64 sesid,
+ __u16 cmd,
+ __u64 mid,
+ __u32 status,
+ int rc),
+ TP_ARGS(pid, tid, sesid, cmd, mid, status, rc),
+ TP_STRUCT__entry(
+ __field(__u32, pid)
+ __field(__u32, tid)
+ __field(__u64, sesid)
+ __field(__u16, cmd)
+ __field(__u64, mid)
+ __field(__u32, status)
+ __field(int, rc)
+ ),
+ TP_fast_assign(
+ __entry->pid = pid;
+ __entry->tid = tid;
+ __entry->sesid = sesid;
+ __entry->cmd = cmd;
+ __entry->mid = mid;
+ __entry->status = status;
+ __entry->rc = rc;
+ ),
+ TP_printk(" pid=%u tid=0x%x sid=0x%llx cmd=%u mid=%llu status=0x%x rc=%d",
+ __entry->pid, __entry->tid, __entry->sesid,
+ __entry->cmd, __entry->mid, __entry->status, __entry->rc)
+)
+
+#define DEFINE_SMB3_CMD_ERR_EVENT(name) \
+DEFINE_EVENT(smb3_cmd_err_class, smb3_##name, \
+ TP_PROTO(unsigned int pid, \
+ __u32 tid, \
+ __u64 sesid, \
+ __u16 cmd, \
+ __u64 mid, \
+ __u32 status, \
+ int rc), \
+ TP_ARGS(pid, tid, sesid, cmd, mid, status, rc))
+
+DEFINE_SMB3_CMD_ERR_EVENT(cmd_err);
+
+DECLARE_EVENT_CLASS(smb3_cmd_done_class,
+ TP_PROTO(__u32 pid,
+ __u32 tid,
+ __u64 sesid,
+ __u16 cmd,
+ __u64 mid),
+ TP_ARGS(pid, tid, sesid, cmd, mid),
+ TP_STRUCT__entry(
+ __field(__u32, pid)
+ __field(__u32, tid)
+ __field(__u64, sesid)
+ __field(__u16, cmd)
+ __field(__u64, mid)
+ ),
+ TP_fast_assign(
+ __entry->pid = pid;
+ __entry->tid = tid;
+ __entry->sesid = sesid;
+ __entry->cmd = cmd;
+ __entry->mid = mid;
+ ),
+ TP_printk("pid=%u tid=0x%x sid=0x%llx cmd=%u mid=%llu",
+ __entry->pid, __entry->tid, __entry->sesid,
+ __entry->cmd, __entry->mid)
+)
+
+#define DEFINE_SMB3_CMD_DONE_EVENT(name) \
+DEFINE_EVENT(smb3_cmd_done_class, smb3_##name, \
+ TP_PROTO(unsigned int pid, \
+ __u32 tid, \
+ __u64 sesid, \
+ __u16 cmd, \
+ __u64 mid), \
+ TP_ARGS(pid, tid, sesid, cmd, mid))
+
+DEFINE_SMB3_CMD_DONE_EVENT(cmd_done);
+
+#endif /* _CIFS_TRACE_H */
+
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH .
+#define TRACE_INCLUDE_FILE trace
+#include <trace/define_trace.h>
--
--
Thanks,
Steve
On Thu, May 17, 2018 at 10:28 PM, Ronnie Sahlberg <[email protected]> wrote:
> Very nice.
>
> Acked-by: Ronnie Sahlberg <[email protected]>
>
> Possibly change the output from
> pid=6633 tid=0x0 sid=0x0 cmd=0 mid=0
> to
> cmd=0 mid=0 pid=6633 tid=0x0 sid=0x0
>
> just to make it easier for human-searching. I think the cmd will be useful much more often than pid/tid/sid
> and this would make it easier to look for as all cmd= entries will be aligned to the same column.
My instinct is to preserve the consistency by beginning with the the
fields that will be in 90% of the commands: tree id and session id
(tid and sid), which would cause pid to move after sid or after cmd,
but I would prefer to wait on reordering fields and fixing alignment
till we add another set of tracepoints (e.g. in FreeXid, and in
SMB2_open and in the caller of negprot/sessionsetup) - we should then
have a better idea what formatting would make it slightly more
consistent and readable.
Fair enough.
Onto a second point then, for future patches.
There are a lot of places where we do not (yet) pass a tcon as argument.
Can we make a policy decision to mandate that every tracepoint MUST
log tid, sid?
And thus, if you need a new tracepoint in a function where tcon is not
available you then first
have to do the plumbing to pass the tcon all the way down to the tracepoint?
Ideally we should pass tcon into any and every leaf function for
tracepoints as well as debug logging.
On Fri, May 18, 2018 at 4:19 PM, Steve French <[email protected]> wrote:
> On Thu, May 17, 2018 at 10:28 PM, Ronnie Sahlberg <[email protected]> wrote:
>> Very nice.
>>
>> Acked-by: Ronnie Sahlberg <[email protected]>
>>
>> Possibly change the output from
>> pid=6633 tid=0x0 sid=0x0 cmd=0 mid=0
>> to
>> cmd=0 mid=0 pid=6633 tid=0x0 sid=0x0
>>
>> just to make it easier for human-searching. I think the cmd will be useful much more often than pid/tid/sid
>> and this would make it easier to look for as all cmd= entries will be aligned to the same column.
>
> My instinct is to preserve the consistency by beginning with the the
> fields that will be in 90% of the commands: tree id and session id
> (tid and sid), which would cause pid to move after sid or after cmd,
> but I would prefer to wait on reordering fields and fixing alignment
> till we add another set of tracepoints (e.g. in FreeXid, and in
> SMB2_open and in the caller of negprot/sessionsetup) - we should then
> have a better idea what formatting would make it slightly more
> consistent and readable.
> --
> To unsubscribe from this list: send the line "unsubscribe linux-cifs" in
> the body of a message to [email protected]
> More majordomo info at http://vger.kernel.org/majordomo-info.html
On Fri, May 18, 2018 at 1:00 AM, ronnie sahlberg
<[email protected]> wrote:
> Fair enough.
>
> Onto a second point then, for future patches.
>
> There are a lot of places where we do not (yet) pass a tcon as argument.
> Can we make a policy decision to mandate that every tracepoint MUST
> log tid, sid?
>
> And thus, if you need a new tracepoint in a function where tcon is not
> available you then first
> have to do the plumbing to pass the tcon all the way down to the tracepoint?
I think this can be relaxed in a few cases (not just session setup),
but is a good
general rule. If only the parent function needs to be changed it is
easy decision,
but if changes more than two layers, perhaps not.
> Ideally we should pass tcon into any and every leaf function for
> tracepoints as well as debug logging.
We also have to
- log the tid and session id somewhere in human readable form
- perhaps allow an IOCtl to retrieve the UNC name from the tid, and similarly
something human readable for the session id (server and username)
(or add the tid and session id to what is displayed in
/proc/fs/cifs/DebugData so
we can extract it from the DebugData output)
> On Fri, May 18, 2018 at 4:19 PM, Steve French <[email protected]> wrote:
>> On Thu, May 17, 2018 at 10:28 PM, Ronnie Sahlberg <[email protected]> wrote:
>>> Very nice.
>>>
>>> Acked-by: Ronnie Sahlberg <[email protected]>
>>>
>>> Possibly change the output from
>>> pid=6633 tid=0x0 sid=0x0 cmd=0 mid=0
>>> to
>>> cmd=0 mid=0 pid=6633 tid=0x0 sid=0x0
>>>
>>> just to make it easier for human-searching. I think the cmd will be useful much more often than pid/tid/sid
>>> and this would make it easier to look for as all cmd= entries will be aligned to the same column.
>>
>> My instinct is to preserve the consistency by beginning with the the
>> fields that will be in 90% of the commands: tree id and session id
>> (tid and sid), which would cause pid to move after sid or after cmd,
>> but I would prefer to wait on reordering fields and fixing alignment
>> till we add another set of tracepoints (e.g. in FreeXid, and in
>> SMB2_open and in the caller of negprot/sessionsetup) - we should then
>> have a better idea what formatting would make it slightly more
>> consistent and readable.
--
Thanks,
Steve
On Thu, May 17, 2018 at 09:36:36PM -0500, Steve French via samba-technical wrote:
> Patch updated with additional tracepoint locations and some formatting
> improvements. There are some obvious additional tracepoints that could
> be added, but this should be a reasonable group to start with.
>
> From edc02d6f9dc24963d510c7ef59067428d3b082d3 Mon Sep 17 00:00:00 2001
> From: Steve French <[email protected]>
> Date: Thu, 17 May 2018 21:16:55 -0500
> Subject: [PATCH] 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
pardon my ignorance, but are these tracepoints usable with other tracing
frameworks like Systemtap?
Last time I checked, Systemtap looked like *the* tool. Is there a generic trace
point infrastructure that tracing tools can consume, so we're not tied to
ftrace?
Thanks!
-slow
--
Ralph Boehme, Samba Team https://samba.org/
Samba Developer, SerNet GmbH https://sernet.de/en/samba/
GPG Key Fingerprint: FAE2 C608 8A24 2520 51C5
59E4 AA1E 9B71 2639 9E46
On Fri, May 18, 2018 at 11:46 AM, Ralph Böhme <[email protected]> wrote:
> On Thu, May 17, 2018 at 09:36:36PM -0500, Steve French via samba-technical wrote:
>> Patch updated with additional tracepoint locations and some formatting
>> improvements. There are some obvious additional tracepoints that could
>> be added, but this should be a reasonable group to start with.
>>
>> From edc02d6f9dc24963d510c7ef59067428d3b082d3 Mon Sep 17 00:00:00 2001
>> From: Steve French <[email protected]>
>> Date: Thu, 17 May 2018 21:16:55 -0500
>> Subject: [PATCH] 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
>
> pardon my ignorance, but are these tracepoints usable with other tracing
> frameworks like Systemtap?
>
> Last time I checked, Systemtap looked like *the* tool. Is there a generic trace
> point infrastructure that tracing tools can consume, so we're not tied to
> ftrace?
At the kernel filesystem/mm summit a few recommended using ftrace
(trace-cmd). Don't know what
the thinking is about this vs. systemtap these days. There was a nice
three part series
describing ftrace/trace-cmd on lwn
(https://old.lwn.net/Articles/365835/) a while ago.
In terms of useability "trace-cmd" looked good to me and much more
powerful than the
current dmesg based printk style debugging.
Since the most active file systems (except for cifs.ko) on Linux
btrfs, xfs, nfs and ext4 (and
even dax and ocfs2 and nfsd and fscache etc. and of course various
drivers) already use it, seems like
it is widely accepted still and overhead is small when not logging (default).
--
Thanks,
Steve
On Fri, May 18, 2018 at 01:43:14PM -0700, Steve French wrote:
> On Fri, May 18, 2018 at 11:46 AM, Ralph B?hme <[email protected]> wrote:
> > On Thu, May 17, 2018 at 09:36:36PM -0500, Steve French via samba-technical wrote:
> >> Patch updated with additional tracepoint locations and some formatting
> >> improvements. There are some obvious additional tracepoints that could
> >> be added, but this should be a reasonable group to start with.
> >>
> >> From edc02d6f9dc24963d510c7ef59067428d3b082d3 Mon Sep 17 00:00:00 2001
> >> From: Steve French <[email protected]>
> >> Date: Thu, 17 May 2018 21:16:55 -0500
> >> Subject: [PATCH] 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
> >
> > pardon my ignorance, but are these tracepoints usable with other tracing
> > frameworks like Systemtap?
> >
> > Last time I checked, Systemtap looked like *the* tool.
Systemtap is great when you have a need for custom tracing. But for
day-to-day kernel development, tracepoints are far more useful
because they are always there and can cover all the common
situations that you need to trace.
And when it comes to debugging a one-off user problem when the user
knows nothing about systemtap? Nothing beats asking the user
to run a trace on built-in tracepoints, reproduce the problem and
send the trace report back as per the above example.
> > Is there a generic trace
> > point infrastructure that tracing tools can consume, so we're not tied to
> > ftrace?
>
> At the kernel filesystem/mm summit a few recommended using ftrace
> (trace-cmd). Don't know what
> the thinking is about this vs. systemtap these days. There was a nice
> three part series
> describing ftrace/trace-cmd on lwn
> (https://old.lwn.net/Articles/365835/) a while ago.
>
> In terms of useability "trace-cmd" looked good to me and much more
> powerful than the
> current dmesg based printk style debugging.
And then you learn about trace_printk() for putting custom one-off
debug into the tracepoint stream and wonder why you didn't know
about this years ago :P
Cheers,
Dave.
--
Dave Chinner
[email protected]
On Sat, May 19, 2018 at 6:22 PM, Dave Chinner <[email protected]> wrote:
> On Fri, May 18, 2018 at 01:43:14PM -0700, Steve French wrote:
>> On Fri, May 18, 2018 at 11:46 AM, Ralph Böhme <[email protected]> wrote:
>> > On Thu, May 17, 2018 at 09:36:36PM -0500, Steve French via samba-technical wrote:
>> >> Patch updated with additional tracepoint locations and some formatting
>> >> improvements. There are some obvious additional tracepoints that could
>> >> be added, but this should be a reasonable group to start with.
>> >>
>> >> From edc02d6f9dc24963d510c7ef59067428d3b082d3 Mon Sep 17 00:00:00 2001
>> >> From: Steve French <[email protected]>
>> >> Date: Thu, 17 May 2018 21:16:55 -0500
>> >> Subject: [PATCH] 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
>> >
>> > pardon my ignorance, but are these tracepoints usable with other tracing
>> > frameworks like Systemtap?
>> >
>> > Last time I checked, Systemtap looked like *the* tool.
>
> Systemtap is great when you have a need for custom tracing. But for
> day-to-day kernel development, tracepoints are far more useful
> because they are always there and can cover all the common
> situations that you need to trace.
>
> And when it comes to debugging a one-off user problem when the user
> knows nothing about systemtap? Nothing beats asking the user
> to run a trace on built-in tracepoints, reproduce the problem and
> send the trace report back as per the above example.
Yep - it has already been helpful in debugging problems.
Main problem I hit using the new tracepoints over the past few days
was entries being discarded from the buffer - I had a counter leak (now
fixed) that xfstest showed ... but about 90% of the entries were dropped.
Tried increasing buffer size but might have made things worse not better.
Ideas how to force more entries to be saved?
>> > Is there a generic trace
>> > point infrastructure that tracing tools can consume, so we're not tied to
>> > ftrace?
>>
>> At the kernel filesystem/mm summit a few recommended using ftrace
>> (trace-cmd). Don't know what
>> the thinking is about this vs. systemtap these days. There was a nice
>> three part series
>> describing ftrace/trace-cmd on lwn
>> (https://old.lwn.net/Articles/365835/) a while ago.
>>
>> In terms of useability "trace-cmd" looked good to me and much more
>> powerful than the
>> current dmesg based printk style debugging.
>
> And then you learn about trace_printk() for putting custom one-off
> debug into the tracepoint stream and wonder why you didn't know
> about this years ago :P
Thanks for the pointers at the summit ...
--
Thanks,
Steve
On Sat, May 19, 2018 at 08:56:39PM -0500, Steve French wrote:
> On Sat, May 19, 2018 at 6:22 PM, Dave Chinner <[email protected]> wrote:
> > On Fri, May 18, 2018 at 01:43:14PM -0700, Steve French wrote:
> >> On Fri, May 18, 2018 at 11:46 AM, Ralph B?hme <[email protected]> wrote:
> >> > On Thu, May 17, 2018 at 09:36:36PM -0500, Steve French via samba-technical wrote:
> >> >> Patch updated with additional tracepoint locations and some formatting
> >> >> improvements. There are some obvious additional tracepoints that could
> >> >> be added, but this should be a reasonable group to start with.
> >> >>
> >> >> From edc02d6f9dc24963d510c7ef59067428d3b082d3 Mon Sep 17 00:00:00 2001
> >> >> From: Steve French <[email protected]>
> >> >> Date: Thu, 17 May 2018 21:16:55 -0500
> >> >> Subject: [PATCH] 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
> >> >
> >> > pardon my ignorance, but are these tracepoints usable with other tracing
> >> > frameworks like Systemtap?
> >> >
> >> > Last time I checked, Systemtap looked like *the* tool.
> >
> > Systemtap is great when you have a need for custom tracing. But for
> > day-to-day kernel development, tracepoints are far more useful
> > because they are always there and can cover all the common
> > situations that you need to trace.
> >
> > And when it comes to debugging a one-off user problem when the user
> > knows nothing about systemtap? Nothing beats asking the user
> > to run a trace on built-in tracepoints, reproduce the problem and
> > send the trace report back as per the above example.
>
> Yep - it has already been helpful in debugging problems.
>
> Main problem I hit using the new tracepoints over the past few days
> was entries being discarded from the buffer - I had a counter leak (now
> fixed) that xfstest showed ... but about 90% of the entries were dropped.
> Tried increasing buffer size but might have made things worse not better.
> Ideas how to force more entries to be saved?
The only tends to be a problem when you are generating events faster
than userspace can drain the kernel ring buffer. Generally speaking,
this happens when you try to trace too many events for userspace to
drain in the CPU time the kernel assigns it.
I'm guessing that tracing an interrupt driven workload like a
network protocol this is going to be more of a problem than
filesystems - it's the perennial "tcpdump/wireshark/etc cannot keep
up with the incoming packet rate" problem - increasing buffer sizes
never fixes that problem. :)
Storing the trace data output file on tmpfs can be helpful here, as
can reducing the number of events to just the layer you need info
from, filter the specific events you want to see (e.g. filter by
client/server connection, by process/CPU, etc), set up trigger
events so tracing doesn't start until you want it to, etc...
Cheers,
Dave.
--
Dave Chinner
[email protected]