May be helpful to get timing info for large reads/writes/query_dirs or
to better find hangs or operations that trigger reconnects. Sample
output from various readdirs with the new tracepoints
# trace-cmd show
# tracer: nop
#
# _-----=> irqs-off
# / _----=> need-resched
# | / _---=> hardirq/softirq
# || / _--=> preempt-depth
# ||| / delay
# TASK-PID CPU# |||| TIMESTAMP FUNCTION
# | | | |||| | |
ls-30820 [004] .... 77492.662476: smb3_query_dir_enter:
xid=8 sid=0x2fa2c9ab tid=0x1377432b fid=0xfc37e912 offset=0x0
len=0x4000
ls-30820 [004] .... 77492.663906: smb3_query_dir_done:
xid=8 sid=0x2fa2c9ab tid=0x1377432b fid=0xfc37e912 offset=0x0 len=0x13
ls-30820 [004] .... 77492.664107: smb3_query_dir_enter:
xid=9 sid=0x2fa2c9ab tid=0x1377432b fid=0xfc37e912 offset=0x0
len=0x4000
ls-30820 [004] .... 77492.664639: smb3_query_dir_err:
xid=9 sid=0x2fa2c9ab tid=0x1377432b fid=0xfc37e912 offset=0x0 len=0x0
rc=0
bash-27628 [000] .... 77502.150630: smb3_query_dir_enter:
xid=12 sid=0x2fa2c9ab tid=0x1377432b fid=0x26e379e1 offset=0x0
len=0x4000
bash-27628 [000] .... 77502.151783: smb3_query_dir_done:
xid=12 sid=0x2fa2c9ab tid=0x1377432b fid=0x26e379e1 offset=0x0
len=0x13
bash-27628 [000] .... 77502.151855: smb3_query_dir_enter:
xid=13 sid=0x2fa2c9ab tid=0x1377432b fid=0x26e379e1 offset=0x0
len=0x4000
bash-27628 [000] .... 77502.152378: smb3_query_dir_err:
xid=13 sid=0x2fa2c9ab tid=0x1377432b fid=0x26e379e1 offset=0x0
len=0x0 rc=0
ls-30821 [001] .... 77502.156573: smb3_query_dir_enter:
xid=15 sid=0x2fa2c9ab tid=0x1377432b fid=0x4f5cedcd offset=0x0
len=0x4000
ls-30821 [001] .... 77502.157308: smb3_query_dir_done:
xid=15 sid=0x2fa2c9ab tid=0x1377432b fid=0x4f5cedcd offset=0x0 len=0x3
ls-30821 [001] .... 77502.157364: smb3_query_dir_enter:
xid=16 sid=0x2fa2c9ab tid=0x1377432b fid=0x4f5cedcd offset=0x0
len=0x4000
ls-30821 [001] .... 77502.157880: smb3_query_dir_err:
xid=16 sid=0x2fa2c9ab tid=0x1377432b fid=0x4f5cedcd offset=0x0
len=0x0 rc=0
ls-30821 [001] .... 77502.159819: smb3_query_dir_enter:
xid=18 sid=0x2fa2c9ab tid=0x1377432b fid=0xcb88f96d offset=0x0
len=0x4000
ls-30821 [003] .... 77502.160591: smb3_query_dir_done:
xid=18 sid=0x2fa2c9ab tid=0x1377432b fid=0xcb88f96d offset=0x0 len=0x3
ls-30821 [003] .... 77502.160651: smb3_query_dir_enter:
xid=19 sid=0x2fa2c9ab tid=0x1377432b fid=0xcb88f96d offset=0x0
len=0x4000
ls-30821 [003] .... 77502.161106: smb3_query_dir_err:
xid=19 sid=0x2fa2c9ab tid=0x1377432b fid=0xcb88f96d offset=0x0
len=0x0 rc=0
ls-30821 [003] .... 77502.162653: smb3_query_dir_enter:
xid=21 sid=0x2fa2c9ab tid=0x1377432b fid=0x9ca0a6bc offset=0x0
len=0x4000
ls-30821 [003] .... 77502.163334: smb3_query_dir_done:
xid=21 sid=0x2fa2c9ab tid=0x1377432b fid=0x9ca0a6bc offset=0x0 len=0x3
ls-30821 [003] .... 77502.163382: smb3_query_dir_enter:
xid=22 sid=0x2fa2c9ab tid=0x1377432b fid=0x9ca0a6bc offset=0x0
len=0x4000
ls-30821 [003] .... 77502.163894: smb3_query_dir_err:
xid=22 sid=0x2fa2c9ab tid=0x1377432b fid=0x9ca0a6bc offset=0x0
len=0x0 rc=0
--
Thanks,
Steve
From 7b4bedb17a56a20fa3b78678aad07a7eb9e7d762 Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@xxxxxxxxxxxxx>
Date: Mon, 25 Feb 2019 00:52:43 -0600
Subject: [PATCH] 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>
---
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 b6e2a1f40078..358951840756 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
