| Message ID | CAH2r5mt4zNDMkqg1ioqfoiZpNmt2_VnbALG9X8piDeyx5hLdhw@mail.gmail.com |
|---|---|
| State | New |
| Headers | show |
| Series | smb3 tracepoints for read_enter, write_enter and query_dir_enter | expand |
вс, 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
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"
пн, 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
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
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