* [PATCH] smb3 tracepoints for read_enter, write_enter and query_dir_enter
@ 2019-02-25 7:10 Steve French
2019-02-25 18:43 ` Pavel Shilovsky
0 siblings, 1 reply; 4+ messages in thread
From: Steve French @ 2019-02-25 7:10 UTC (permalink / raw)
To: CIFS
[-- Attachment #1: Type: text/plain, Size: 3478 bytes --]
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
[-- Attachment #2: 0001-smb3-Add-tracepoints-for-read-write-and-query_dir-en.patch --]
[-- Type: text/x-patch, Size: 2871 bytes --]
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
^ permalink raw reply related [flat|nested] 4+ messages in thread
* Re: [PATCH] smb3 tracepoints for read_enter, write_enter and query_dir_enter
2019-02-25 7:10 [PATCH] smb3 tracepoints for read_enter, write_enter and query_dir_enter Steve French
@ 2019-02-25 18:43 ` Pavel Shilovsky
2019-02-25 18:52 ` Steve French
0 siblings, 1 reply; 4+ messages in thread
From: Pavel Shilovsky @ 2019-02-25 18:43 UTC (permalink / raw)
To: Steve French; +Cc: CIFS
вс, 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
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [PATCH] smb3 tracepoints for read_enter, write_enter and query_dir_enter
2019-02-25 18:43 ` Pavel Shilovsky
@ 2019-02-25 18:52 ` Steve French
2019-02-25 18:59 ` Pavel Shilovsky
0 siblings, 1 reply; 4+ messages in thread
From: Steve French @ 2019-02-25 18:52 UTC (permalink / raw)
To: Pavel Shilovsky; +Cc: CIFS
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"
--
Thanks,
Steve
^ permalink raw reply [flat|nested] 4+ messages in thread
* Re: [PATCH] smb3 tracepoints for read_enter, write_enter and query_dir_enter
2019-02-25 18:52 ` Steve French
@ 2019-02-25 18:59 ` Pavel Shilovsky
0 siblings, 0 replies; 4+ messages in thread
From: Pavel Shilovsky @ 2019-02-25 18:59 UTC (permalink / raw)
To: Steve French; +Cc: CIFS
пн, 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
^ permalink raw reply [flat|nested] 4+ messages in thread
end of thread, other threads:[~2019-02-25 19:00 UTC | newest]
Thread overview: 4+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2019-02-25 7:10 [PATCH] smb3 tracepoints for read_enter, write_enter and query_dir_enter Steve French
2019-02-25 18:43 ` Pavel Shilovsky
2019-02-25 18:52 ` Steve French
2019-02-25 18:59 ` Pavel Shilovsky
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).