diff mbox series

Updated ftrace patches for read/write/query_dir

Message ID CAH2r5mtPFfn+wi1LEfe=po+DYMFO51w+ZVtOAiY2Ex7CJMxdug@mail.gmail.com
State New
Headers show
Series Updated ftrace patches for read/write/query_dir | expand

Commit Message

Steve French Feb. 25, 2019, 8:52 p.m. UTC 
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

Comments

ronnie sahlberg Feb. 26, 2019, 2:32 a.m. UTC | #1 
In the first patch, do we really need different tracepoints for done
rc==0 and err rc!=0 ?

Othervise, for both:

Reweived-by: Ronnie Sahlberg <lsahlber@redhat.com>

On Tue, Feb 26, 2019 at 6:53 AM Steve French <smfrench@gmail.com> wrote:
>
> 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
Steve French Feb. 26, 2019, 10:08 p.m. UTC | #2 
I don't have strong opinion on the two different trace points for rc=0
error no more files ('query_dir_done') instead of collapsing that into
a 'query_dir_error' with rc=0 - but seems a little clearer to not log
an rc=0 as an error

On Mon, Feb 25, 2019 at 8:32 PM ronnie sahlberg
<ronniesahlberg@gmail.com> wrote:
>
> In the first patch, do we really need different tracepoints for done
> rc==0 and err rc!=0 ?
>
> Othervise, for both:
>
> Reweived-by: Ronnie Sahlberg <lsahlber@redhat.com>
>
> On Tue, Feb 26, 2019 at 6:53 AM Steve French <smfrench@gmail.com> wrote:
> >
> > 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
diff mbox series

Patch

From 6db924e70daae155845c6b7dd0f441dbff7bd658 Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@microsoft.com>
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@microsoft.com>
Reviewed-by: Pavel Shilovsky <pshilov@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 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