Sample output (from "trace-cmd record -e smb3_query* -e smb3_read* -e
smb3_write*")
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
ls-25909 [004] .... 91084.368421: smb3_query_dir_enter:
xid=8 sid=0x45a21759 tid=0x821ad8fd fid=0x50da7b4 offset=0x0
len=0x4000
ls-25909 [004] .... 91084.369413: smb3_query_dir_done:
xid=8 sid=0x45a21759 tid=0x821ad8fd fid=0x50da7b4 offset=0x0 len=0x8
ls-25909 [004] .... 91084.369530: smb3_query_dir_enter:
xid=9 sid=0x45a21759 tid=0x821ad8fd fid=0x50da7b4 offset=0x0
len=0x4000
ls-25909 [004] .... 91084.370020: smb3_query_dir_done:
xid=9 sid=0x45a21759 tid=0x821ad8fd fid=0x50da7b4 offset=0x0 len=0x0
dd-25915 [004] .... 91101.999225: smb3_read_enter: xid=0
sid=0x45a21759 tid=0x821ad8fd fid=0x85b15605 offset=0x0 len=0x400000
cifsd-25891 [005] .... 91102.010600: smb3_read_done: xid=0
sid=0x45a21759 tid=0x821ad8fd fid=0x85b15605 offset=0x0 len=0x400000
dd-25915 [004] .... 91102.015131: smb3_read_enter: xid=0
sid=0x45a21759 tid=0x821ad8fd fid=0x85b15605 offset=0x400000
len=0x3d0000
cifsd-25891 [005] .... 91102.026541: smb3_read_done: xid=0
sid=0x45a21759 tid=0x821ad8fd fid=0x85b15605 offset=0x400000
len=0x3d0000
dd-25915 [004] .... 91102.028261: smb3_read_enter: xid=0
sid=0x45a21759 tid=0x821ad8fd fid=0x85b15605 offset=0x7d0000
len=0x1000
dd-25919 [006] .... 91121.554908: smb3_write_enter:
xid=0 sid=0x45a21759 tid=0x821ad8fd fid=0x402ee709 offset=0x0
len=0x400000
dd-25919 [006] .... 91121.556448: smb3_write_enter:
xid=0 sid=0x45a21759 tid=0x821ad8fd fid=0x402ee709 offset=0x400000
len=0x3d0000
cifsd-25891 [005] .... 91121.559831: smb3_write_done: xid=0
sid=0x45a21759 tid=0x821ad8fd fid=0x402ee709 offset=0x0 len=0x400000
cifsd-25891 [005] .... 91121.561798: smb3_write_done: xid=0
sid=0x45a21759 tid=0x821ad8fd fid=0x402ee709 offset=0x400000
len=0x3d0000
dd-25931 [007] .... 91161.643194: smb3_read_enter: xid=0
sid=0x45a21759 tid=0x821ad8fd fid=0x115afb41 offset=0x0 len=0x400000
cifsd-25891 [005] .... 91161.650859: smb3_read_done: xid=0
sid=0x45a21759 tid=0x821ad8fd fid=0x115afb41 offset=0x0 len=0x400000
dd-25931 [007] .... 91161.655470: smb3_read_enter: xid=0
sid=0x45a21759 tid=0x821ad8fd fid=0x115afb41 offset=0x400000
len=0x3d0000
cifsd-25891 [004] .... 91161.663517: smb3_read_done: xid=0
sid=0x45a21759 tid=0x821ad8fd fid=0x115afb41 offset=0x400000
len=0x3d0000
dd-25931 [001] .... 91161.664921: smb3_read_enter: xid=0
sid=0x45a21759 tid=0x821ad8fd fid=0x115afb41 offset=0x7d0000
len=0x1000
--
Thanks,
Steve
From 2ad016a6166761d08f7596eb63b3188074b65e79 Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@xxxxxxxxxxxxx>
Date: Mon, 25 Feb 2019 13:51:11 -0600
Subject: [PATCH 1/2] smb3: add tracepoints for query dir
Adds two tracepoints - one for query_dir done (no err) and one for query_dir_err
Sanple output:
To start the trace in one window:
trace-cmd record -e smb3_query_dir*
Then in another window after doing an
ls /mnt
View the trace output by:
trace-cmd show
Sample output:
TASK-PID CPU# |||| TIMESTAMP FUNCTION
| | | |||| | |
ls-24869 [007] .... 90695.452009: smb3_query_dir_done: xid=7 sid=0x5027d24d tid=0xb95cf25a fid=0xc41a8c3e offset=0x0 len=0x16
ls-24869 [000] .... 90695.452764: smb3_query_dir_done: xid=8 sid=0x5027d24d tid=0xb95cf25a fid=0xc41a8c3e offset=0x0 len=0x0
ls-24874 [003] .... 90701.506342: smb3_query_dir_done: xid=11 sid=0x5027d24d tid=0xb95cf25a fid=0x33ad3601 offset=0x0 len=0x8
ls-24874 [003] .... 90701.506917: smb3_query_dir_done: xid=12 sid=0x5027d24d tid=0xb95cf25a fid=0x33ad3601 offset=0x0 len=0x0
Reviewed-by: Pavel Shilovsky <pshilov@xxxxxxxxxxxxx>
Signed-off-by: Steve French <stfrench@xxxxxxxxxxxxx>
---
fs/cifs/smb2pdu.c | 14 ++++++++++++--
fs/cifs/trace.h | 2 ++
2 files changed, 14 insertions(+), 2 deletions(-)
diff --git a/fs/cifs/smb2pdu.c b/fs/cifs/smb2pdu.c
index 64e172633bc4..965c4c7e87f9 100644
--- a/fs/cifs/smb2pdu.c
+++ b/fs/cifs/smb2pdu.c
@@ -3857,18 +3857,26 @@ SMB2_query_directory(const unsigned int xid, struct cifs_tcon *tcon,
if (rc) {
if (rc == -ENODATA &&
rsp->sync_hdr.Status == STATUS_NO_MORE_FILES) {
+ trace_smb3_query_dir_done(xid, persistent_fid,
+ tcon->tid, tcon->ses->Suid, index, 0);
srch_inf->endOfSearch = true;
rc = 0;
- } else
+ } else {
+ trace_smb3_query_dir_err(xid, persistent_fid, tcon->tid,
+ tcon->ses->Suid, index, 0, rc);
cifs_stats_fail_inc(tcon, SMB2_QUERY_DIRECTORY_HE);
+ }
goto qdir_exit;
}
rc = smb2_validate_iov(le16_to_cpu(rsp->OutputBufferOffset),
le32_to_cpu(rsp->OutputBufferLength), &rsp_iov,
info_buf_size);
- if (rc)
+ if (rc) {
+ trace_smb3_query_dir_err(xid, persistent_fid, tcon->tid,
+ tcon->ses->Suid, index, 0, rc);
goto qdir_exit;
+ }
srch_inf->unicode = true;
@@ -3896,6 +3904,8 @@ SMB2_query_directory(const unsigned int xid, struct cifs_tcon *tcon,
else
cifs_dbg(VFS, "illegal search buffer type\n");
+ trace_smb3_query_dir_done(xid, persistent_fid, tcon->tid,
+ tcon->ses->Suid, index, srch_inf->entries_in_buffer);
return rc;
qdir_exit:
diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h
index 59be48206932..bf4f43f6893b 100644
--- a/fs/cifs/trace.h
+++ b/fs/cifs/trace.h
@@ -58,6 +58,7 @@ DEFINE_EVENT(smb3_rw_err_class, smb3_##name, \
DEFINE_SMB3_RW_ERR_EVENT(write_err);
DEFINE_SMB3_RW_ERR_EVENT(read_err);
+DEFINE_SMB3_RW_ERR_EVENT(query_dir_err);
/* For logging successful read or write */
@@ -102,6 +103,7 @@ DEFINE_EVENT(smb3_rw_done_class, smb3_##name, \
DEFINE_SMB3_RW_DONE_EVENT(write_done);
DEFINE_SMB3_RW_DONE_EVENT(read_done);
+DEFINE_SMB3_RW_DONE_EVENT(query_dir_done);
/*
* For handle based calls other than read and write, and get/set info
--
2.17.1
From 6db924e70daae155845c6b7dd0f441dbff7bd658 Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@xxxxxxxxxxxxx>
Date: Mon, 25 Feb 2019 00:52:43 -0600
Subject: [PATCH 2/2] smb3: Add tracepoints for read, write and query_dir enter
Allows tracing begin (not just completion) of read, write
and query_dir which may be helpful in finding slow requests
and other timing information
Signed-off-by: Steve French <stfrench@xxxxxxxxxxxxx>
Reviewed-by: Pavel Shilovsky <pshilov@xxxxxxxxxxxxx>
---
fs/cifs/smb2pdu.c | 15 +++++++++++++++
fs/cifs/trace.h | 3 +++
2 files changed, 18 insertions(+)
diff --git a/fs/cifs/smb2pdu.c b/fs/cifs/smb2pdu.c
index 965c4c7e87f9..ec9abe293279 100644
--- a/fs/cifs/smb2pdu.c
+++ b/fs/cifs/smb2pdu.c
@@ -3142,6 +3142,11 @@ smb2_new_read_req(void **buf, unsigned int *total_len,
req->MinimumCount = 0;
req->Length = cpu_to_le32(io_parms->length);
req->Offset = cpu_to_le64(io_parms->offset);
+
+ trace_smb3_read_enter(0 /* xid */,
+ io_parms->persistent_fid,
+ io_parms->tcon->tid, io_parms->tcon->ses->Suid,
+ io_parms->offset, io_parms->length);
#ifdef CONFIG_CIFS_SMB_DIRECT
/*
* If we want to do a RDMA write, fill in and append
@@ -3541,6 +3546,9 @@ smb2_async_writev(struct cifs_writedata *wdata,
req->DataOffset = cpu_to_le16(
offsetof(struct smb2_write_req, Buffer));
req->RemainingBytes = 0;
+
+ trace_smb3_write_enter(0 /* xid */, wdata->cfile->fid.persistent_fid,
+ tcon->tid, tcon->ses->Suid, wdata->offset, wdata->bytes);
#ifdef CONFIG_CIFS_SMB_DIRECT
/*
* If we want to do a server RDMA read, fill in and append
@@ -3688,6 +3696,10 @@ SMB2_write(const unsigned int xid, struct cifs_io_parms *io_parms,
offsetof(struct smb2_write_req, Buffer));
req->RemainingBytes = 0;
+ trace_smb3_write_enter(xid, io_parms->persistent_fid,
+ io_parms->tcon->tid, io_parms->tcon->ses->Suid,
+ io_parms->offset, io_parms->length);
+
iov[0].iov_base = (char *)req;
/* 1 for Buffer */
iov[0].iov_len = total_len - 1;
@@ -3850,6 +3862,9 @@ SMB2_query_directory(const unsigned int xid, struct cifs_tcon *tcon,
rqst.rq_iov = iov;
rqst.rq_nvec = 2;
+ trace_smb3_query_dir_enter(xid, persistent_fid, tcon->tid,
+ tcon->ses->Suid, index, output_size);
+
rc = cifs_send_recv(xid, ses, &rqst, &resp_buftype, flags, &rsp_iov);
cifs_small_buf_release(req);
rsp = (struct smb2_query_directory_rsp *)rsp_iov.iov_base;
diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h
index bf4f43f6893b..660176e34dde 100644
--- a/fs/cifs/trace.h
+++ b/fs/cifs/trace.h
@@ -101,6 +101,9 @@ DEFINE_EVENT(smb3_rw_done_class, smb3_##name, \
__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(write_done);
DEFINE_SMB3_RW_DONE_EVENT(read_done);
DEFINE_SMB3_RW_DONE_EVENT(query_dir_done);
--
2.17.1
