diff mbox series

smb3 tracepoints for read_enter, write_enter and query_dir_enter

Message ID CAH2r5mt4zNDMkqg1ioqfoiZpNmt2_VnbALG9X8piDeyx5hLdhw@mail.gmail.com (mailing list archive)
State New, archived
Headers show
Series smb3 tracepoints for read_enter, write_enter and query_dir_enter | expand

Commit Message

Steve French Feb. 25, 2019, 7:10 a.m. UTC 
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

Comments

Pavel Shilovsky Feb. 25, 2019, 6:43 p.m. UTC | #1 
вс, 24 февр. 2019 г. в 23:11, Steve French <smfrench@gmail.com>:
>
> 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

query_dir_ERR and rc=0 looks weird, should be query_dir_DONE.

>               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
>

Other than the comment above, the patch looks fine

Reviewed-by: Pavel Shilovsky <pshilov@microsoft.com>

--
Best regards,
Pavel Shilovsky
Steve French Feb. 25, 2019, 6:52 p.m. UTC | #2 
On Mon, Feb 25, 2019 at 12:44 PM Pavel Shilovsky <piastryyy@gmail.com> wrote:
>
> вс, 24 февр. 2019 г. в 23:11, Steve French <smfrench@gmail.com>:
> >
> > 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
>
> query_dir_ERR and rc=0 looks weird, should be query_dir_DONE.

The reason I left it that way was it was slightly simpler (saved a few
lines of code)
but also allows us to distinguish the case of STATUS_NO_MORE_FILES
(which is mapped to rc = 0 so is logged as smb3_query_dir_err with
rc=0) ie the end of search example.

Alternatively, I could move the smb2_query_done / smb2_query_err lines
up (immediately after the send_rcv) but it could miss errors caught in
"smb2_validate_iov"
Pavel Shilovsky Feb. 25, 2019, 6:59 p.m. UTC | #3 
пн, 25 февр. 2019 г. в 10:52, Steve French <smfrench@gmail.com>:
>
> On Mon, Feb 25, 2019 at 12:44 PM Pavel Shilovsky <piastryyy@gmail.com> wrote:
> >
> > вс, 24 февр. 2019 г. в 23:11, Steve French <smfrench@gmail.com>:
> > >
> > > 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
> >
> > query_dir_ERR and rc=0 looks weird, should be query_dir_DONE.
>
> The reason I left it that way was it was slightly simpler (saved a few
> lines of code)
> but also allows us to distinguish the case of STATUS_NO_MORE_FILES
> (which is mapped to rc = 0 so is logged as smb3_query_dir_err with
> rc=0) ie the end of search example.
>
> Alternatively, I could move the smb2_query_done / smb2_query_err lines
> up (immediately after the send_rcv) but it could miss errors caught in
> "smb2_validate_iov"
>

I don't think we should hide STATUS_NO_MORE_FILES or any other status
code in tracing (even if we mask it off later). Let's trace
smb3_query_dir_err with the proper error code. Nobody except
developers is expected to look at the traces, so, should be fine.

--
Best regards,
Pavel Shilovsky
diff mbox series

Patch

From 7b4bedb17a56a20fa3b78678aad07a7eb9e7d762 Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@microsoft.com>
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@microsoft.com>
---
 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