[PATCH] Enhance time sampling of async IO VFS functions
Ralph Boehme
rb at sernet.de
Sun Feb 28 08:29:24 UTC 2016
On Fri, Feb 26, 2016 at 09:56:58PM +0100, Ralph Boehme wrote:
> On Fri, Feb 26, 2016 at 10:45:31AM -0800, Jeremy Allison wrote:
> > On Fri, Feb 26, 2016 at 06:39:36PM +0100, Ralph Boehme wrote:
> > > I though about adding struct tevent_req.async.(uint64_t)duration and
> > > getter/setter functions
> > > tevent_req_set_duration()/tevent_req_get_duration().
> > >
> > > This could then be used by the implementation of an async request to
> > > set the duration and the caller can read it, further passing up the
> > > stack and processing as needed.
> >
> > If we want to make this a generic feature of tevent, then
> > the above is the way to go - but I think that needs a bigger
> > discussion than just you and I.
> >
> > Metze, Volker - what do you think about adding duration
> > as a feature to tevent_req.async ?
>
> something like this.
the complete patchset would look like this.
-Ralph
--
SerNet GmbH, Bahnhofsallee 1b, 37081 Göttingen
phone: +49-551-370000-0, fax: +49-551-370000-9
AG Göttingen, HRB 2816, GF: Dr. Johannes Loxen
http://www.sernet.de,mailto:kontakt@sernet.de
-------------- next part --------------
From 28e29557292497c6e087e5a712f20dfeeeca9587 Mon Sep 17 00:00:00 2001
From: Ralph Boehme <slow at samba.org>
Date: Fri, 26 Feb 2016 21:49:11 +0100
Subject: [PATCH 1/8] tevent: add duration to tevent_req
Tevent doesn't profile the request processing, it's up to the
implementation of an async request to optionally make use of
tevent_req_set_duration() to store duration info in the request.
The caller of an async request can use tevent_req_get_duration() to read
the value.
This will be used in the async io VFS functions where we need to pass
this information up through the chained VFS calls.
Signed-off-by: Ralph Boehme <slow at samba.org>
---
lib/tevent/tevent.h | 28 ++++++++++++++++++++++++++++
lib/tevent/tevent_internal.h | 9 +++++++++
lib/tevent/tevent_req.c | 10 ++++++++++
3 files changed, 47 insertions(+)
diff --git a/lib/tevent/tevent.h b/lib/tevent/tevent.h
index cb95507..276ed55 100644
--- a/lib/tevent/tevent.h
+++ b/lib/tevent/tevent.h
@@ -1299,6 +1299,34 @@ bool tevent_req_is_error(struct tevent_req *req,
uint64_t *error);
/**
+ * @brief Use this in the implementation of an async request that wants
+ * to pass information about the completion time of the request to the
+ * caller of the async request.
+ *
+ * @param[in] req The tevent request to get the error from.
+ *
+ * @param[in] duration Set the duration of a request
+ *
+ * @see tevent_req_get_duration()
+ */
+void tevent_req_set_duration(struct tevent_req *req, uint64_t duration);
+
+/**
+ * @brief Used by the caller of any async request to retrieve duration
+ * info.
+ *
+ * @note It's up to the implementation of an async request to store
+ * duration information.
+ *
+ * @param[in] req The tevent request to get the error from.
+ *
+ * @param[in] duration Set the duration of a request
+ *
+ * @see tevent_req_get_duration()
+ */
+uint64_t tevent_req_get_duration(struct tevent_req *req);
+
+/**
* @brief Use as the last action of a _recv() function.
*
* This function destroys the attached private data.
diff --git a/lib/tevent/tevent_internal.h b/lib/tevent/tevent_internal.h
index 10cc4a4..369abc9 100644
--- a/lib/tevent/tevent_internal.h
+++ b/lib/tevent/tevent_internal.h
@@ -164,6 +164,15 @@ struct tevent_req {
*
*/
struct tevent_timer *timer;
+
+ /**
+ * @brief Can be used by the implementation of an
+ * async request to store the duration of the
+ * request via tevent_ret_set_duration(). The
+ * caller can read the value via
+ * tevent_ret_get_duration().
+ */
+ uint64_t duration;
} internal;
};
diff --git a/lib/tevent/tevent_req.c b/lib/tevent/tevent_req.c
index c86fb68..48ea30d 100644
--- a/lib/tevent/tevent_req.c
+++ b/lib/tevent/tevent_req.c
@@ -345,3 +345,13 @@ void tevent_req_set_cleanup_fn(struct tevent_req *req, tevent_req_cleanup_fn fn)
req->private_cleanup.state = req->internal.state;
req->private_cleanup.fn = fn;
}
+
+void tevent_req_set_duration(struct tevent_req *req, uint64_t duration)
+{
+ req->internal.duration = duration;
+}
+
+uint64_t tevent_req_get_duration(struct tevent_req *req)
+{
+ return req->internal.duration;
+}
--
2.5.0
From 4501317832c5d6bc5a543073c5f4808ba07b80ea Mon Sep 17 00:00:00 2001
From: Ralph Boehme <slow at samba.org>
Date: Thu, 25 Feb 2016 08:06:00 +0100
Subject: [PATCH 2/8] s3:lib/asys: measure async request syscall duration
This uses time functions from lib/util/ which requires pulling in
samba-util. This sucks, but there's just no way of rewrapping a minimal
time utility library without modifying the public samba-util.
Signed-off-by: Ralph Boehme <slow at samba.org>
---
source3/lib/asys/asys.c | 13 +++++++++++++
source3/lib/asys/asys.h | 1 +
source3/lib/asys/wscript_build | 2 +-
3 files changed, 15 insertions(+), 1 deletion(-)
diff --git a/source3/lib/asys/asys.c b/source3/lib/asys/asys.c
index 906d8cf..068b460 100644
--- a/source3/lib/asys/asys.c
+++ b/source3/lib/asys/asys.c
@@ -20,6 +20,7 @@
#include <stdlib.h>
#include <errno.h>
#include "../pthreadpool/pthreadpool.h"
+#include "lib/util/time.h"
struct asys_pwrite_args {
int fildes;
@@ -52,6 +53,8 @@ struct asys_job {
int err;
char busy;
char canceled;
+ struct timespec start_time;
+ struct timespec end_time;
};
struct asys_context {
@@ -189,7 +192,10 @@ static void asys_pwrite_do(void *private_data)
struct asys_job *job = (struct asys_job *)private_data;
struct asys_pwrite_args *args = &job->args.pwrite_args;
+ clock_gettime_mono(&job->start_time);
job->ret = pwrite(args->fildes, args->buf, args->nbyte, args->offset);
+ clock_gettime_mono(&job->end_time);
+
if (job->ret == -1) {
job->err = errno;
}
@@ -231,7 +237,10 @@ static void asys_pread_do(void *private_data)
struct asys_job *job = (struct asys_job *)private_data;
struct asys_pread_args *args = &job->args.pread_args;
+ clock_gettime_mono(&job->start_time);
job->ret = pread(args->fildes, args->buf, args->nbyte, args->offset);
+ clock_gettime_mono(&job->end_time);
+
if (job->ret == -1) {
job->err = errno;
}
@@ -269,7 +278,10 @@ static void asys_fsync_do(void *private_data)
struct asys_job *job = (struct asys_job *)private_data;
struct asys_fsync_args *args = &job->args.fsync_args;
+ clock_gettime_mono(&job->start_time);
job->ret = fsync(args->fildes);
+ clock_gettime_mono(&job->end_time);
+
if (job->ret == -1) {
job->err = errno;
}
@@ -320,6 +332,7 @@ int asys_results(struct asys_context *ctx, struct asys_result *results,
result->err = job->err;
}
result->private_data = job->private_data;
+ result->duration = nsec_time_diff(&job->end_time, &job->start_time);
job->busy = 0;
}
diff --git a/source3/lib/asys/asys.h b/source3/lib/asys/asys.h
index 7c3dfdf..f576bd3 100644
--- a/source3/lib/asys/asys.h
+++ b/source3/lib/asys/asys.h
@@ -108,6 +108,7 @@ struct asys_result {
ssize_t ret;
int err;
void *private_data;
+ uint64_t duration; /* nanoseconds */
};
/**
diff --git a/source3/lib/asys/wscript_build b/source3/lib/asys/wscript_build
index 15de977..520994f 100644
--- a/source3/lib/asys/wscript_build
+++ b/source3/lib/asys/wscript_build
@@ -2,7 +2,7 @@
bld.SAMBA3_SUBSYSTEM('LIBASYS',
source='asys.c',
- deps='PTHREADPOOL')
+ deps='PTHREADPOOL samba-util')
bld.SAMBA3_BINARY('asystest',
source='tests.c',
--
2.5.0
From e3cb27b917ced4667666054cec07e63a9ba4129f Mon Sep 17 00:00:00 2001
From: Ralph Boehme <slow at samba.org>
Date: Sat, 27 Feb 2016 14:33:09 +0100
Subject: [PATCH 3/8] s3/vfs: pass tevent_req duration up the chain
Signed-off-by: Ralph Boehme <slow at samba.org>
---
examples/VFS/skel_transparent.c | 6 ++++++
source3/modules/vfs_commit.c | 2 ++
source3/modules/vfs_full_audit.c | 6 ++++++
source3/modules/vfs_gpfs.c | 4 ++++
source3/modules/vfs_time_audit.c | 9 +++++++++
source3/modules/vfs_tsmsm.c | 4 ++++
source3/smbd/vfs.c | 3 +++
7 files changed, 34 insertions(+)
diff --git a/examples/VFS/skel_transparent.c b/examples/VFS/skel_transparent.c
index ac82432..58d5be1 100644
--- a/examples/VFS/skel_transparent.c
+++ b/examples/VFS/skel_transparent.c
@@ -275,6 +275,8 @@ static void skel_pread_done(struct tevent_req *subreq)
struct skel_pread_state *state =
tevent_req_data(req, struct skel_pread_state);
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err);
TALLOC_FREE(subreq);
tevent_req_done(req);
@@ -341,6 +343,8 @@ static void skel_pwrite_done(struct tevent_req *subreq)
struct skel_pwrite_state *state =
tevent_req_data(req, struct skel_pwrite_state);
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err);
TALLOC_FREE(subreq);
tevent_req_done(req);
@@ -423,6 +427,8 @@ static void skel_fsync_done(struct tevent_req *subreq)
struct skel_fsync_state *state =
tevent_req_data(req, struct skel_fsync_state);
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
state->ret = SMB_VFS_FSYNC_RECV(subreq, &state->err);
TALLOC_FREE(subreq);
tevent_req_done(req);
diff --git a/source3/modules/vfs_commit.c b/source3/modules/vfs_commit.c
index f1e2743..331ef5a 100644
--- a/source3/modules/vfs_commit.c
+++ b/source3/modules/vfs_commit.c
@@ -328,6 +328,8 @@ static void commit_pwrite_written(struct tevent_req *subreq)
req, struct commit_pwrite_state);
int commit_ret;
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err);
TALLOC_FREE(subreq);
diff --git a/source3/modules/vfs_full_audit.c b/source3/modules/vfs_full_audit.c
index 3dd2005..5c191d8 100644
--- a/source3/modules/vfs_full_audit.c
+++ b/source3/modules/vfs_full_audit.c
@@ -1063,6 +1063,8 @@ static void smb_full_audit_pread_done(struct tevent_req *subreq)
struct smb_full_audit_pread_state *state = tevent_req_data(
req, struct smb_full_audit_pread_state);
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err);
TALLOC_FREE(subreq);
tevent_req_done(req);
@@ -1161,6 +1163,8 @@ static void smb_full_audit_pwrite_done(struct tevent_req *subreq)
struct smb_full_audit_pwrite_state *state = tevent_req_data(
req, struct smb_full_audit_pwrite_state);
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err);
TALLOC_FREE(subreq);
tevent_req_done(req);
@@ -1299,6 +1303,8 @@ static void smb_full_audit_fsync_done(struct tevent_req *subreq)
struct smb_full_audit_fsync_state *state = tevent_req_data(
req, struct smb_full_audit_fsync_state);
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
state->ret = SMB_VFS_FSYNC_RECV(subreq, &state->err);
TALLOC_FREE(subreq);
tevent_req_done(req);
diff --git a/source3/modules/vfs_gpfs.c b/source3/modules/vfs_gpfs.c
index 33a30d0..44cefcf 100644
--- a/source3/modules/vfs_gpfs.c
+++ b/source3/modules/vfs_gpfs.c
@@ -2355,6 +2355,8 @@ static void vfs_gpfs_pread_done(struct tevent_req *subreq)
struct vfs_gpfs_pread_state *state = tevent_req_data(
req, struct vfs_gpfs_pread_state);
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err);
TALLOC_FREE(subreq);
tevent_req_done(req);
@@ -2442,6 +2444,8 @@ static void vfs_gpfs_pwrite_done(struct tevent_req *subreq)
struct vfs_gpfs_pwrite_state *state = tevent_req_data(
req, struct vfs_gpfs_pwrite_state);
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err);
TALLOC_FREE(subreq);
tevent_req_done(req);
diff --git a/source3/modules/vfs_time_audit.c b/source3/modules/vfs_time_audit.c
index 11866fa..c38d69e 100644
--- a/source3/modules/vfs_time_audit.c
+++ b/source3/modules/vfs_time_audit.c
@@ -716,6 +716,9 @@ static void smb_time_audit_pread_done(struct tevent_req *subreq)
req, struct smb_time_audit_pread_state);
state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err);
+
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
TALLOC_FREE(subreq);
tevent_req_done(req);
}
@@ -824,6 +827,9 @@ static void smb_time_audit_pwrite_done(struct tevent_req *subreq)
req, struct smb_time_audit_pwrite_state);
state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err);
+
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
TALLOC_FREE(subreq);
tevent_req_done(req);
}
@@ -989,6 +995,9 @@ static void smb_time_audit_fsync_done(struct tevent_req *subreq)
req, struct smb_time_audit_fsync_state);
state->ret = SMB_VFS_FSYNC_RECV(subreq, &state->err);
+
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
TALLOC_FREE(subreq);
tevent_req_done(req);
}
diff --git a/source3/modules/vfs_tsmsm.c b/source3/modules/vfs_tsmsm.c
index e4bc7eb..f5eb4a5 100644
--- a/source3/modules/vfs_tsmsm.c
+++ b/source3/modules/vfs_tsmsm.c
@@ -326,6 +326,8 @@ static void tsmsm_pread_done(struct tevent_req *subreq)
struct tsmsm_pread_state *state = tevent_req_data(
req, struct tsmsm_pread_state);
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err);
TALLOC_FREE(subreq);
tevent_req_done(req);
@@ -390,6 +392,8 @@ static void tsmsm_pwrite_done(struct tevent_req *subreq)
struct tsmsm_pwrite_state *state = tevent_req_data(
req, struct tsmsm_pwrite_state);
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err);
TALLOC_FREE(subreq);
tevent_req_done(req);
diff --git a/source3/smbd/vfs.c b/source3/smbd/vfs.c
index dfc22be..1760a60 100644
--- a/source3/smbd/vfs.c
+++ b/source3/smbd/vfs.c
@@ -1628,6 +1628,9 @@ static void smb_vfs_call_pread_done(struct tevent_req *subreq)
int err;
state->retval = state->recv_fn(subreq, &err);
+
+ tevent_req_set_duration(req, tevent_req_get_duration(subreq));
+
TALLOC_FREE(subreq);
if (state->retval == -1) {
tevent_req_error(req, err);
--
2.5.0
From 7282eef363709a8603b891a49836a879dbfe0c2c Mon Sep 17 00:00:00 2001
From: Ralph Boehme <slow at samba.org>
Date: Fri, 26 Feb 2016 12:29:02 +0100
Subject: [PATCH 4/8] vfs/default: store async VFS op duration we got from
libasys
Signed-off-by: Ralph Boehme <slow at samba.org>
---
source3/modules/vfs_default.c | 4 ++++
1 file changed, 4 insertions(+)
diff --git a/source3/modules/vfs_default.c b/source3/modules/vfs_default.c
index b13b517..26bc7e4 100644
--- a/source3/modules/vfs_default.c
+++ b/source3/modules/vfs_default.c
@@ -743,6 +743,7 @@ struct vfswrap_asys_state {
struct tevent_req *req;
ssize_t ret;
int err;
+ uint64_t duration;
SMBPROFILE_BASIC_ASYNC_STATE(profile_basic);
SMBPROFILE_BYTES_ASYNC_STATE(profile_bytes);
};
@@ -890,6 +891,7 @@ static void vfswrap_asys_finished(struct tevent_context *ev,
SMBPROFILE_BYTES_ASYNC_END(state->profile_bytes);
state->ret = result->ret;
state->err = result->err;
+ state->duration = result->duration;
tevent_req_defer_callback(req, ev);
tevent_req_done(req);
}
@@ -903,6 +905,7 @@ static ssize_t vfswrap_asys_ssize_t_recv(struct tevent_req *req, int *err)
if (tevent_req_is_unix_error(req, err)) {
return -1;
}
+ tevent_req_set_duration(req, state->duration);
*err = state->err;
return state->ret;
}
@@ -915,6 +918,7 @@ static int vfswrap_asys_int_recv(struct tevent_req *req, int *err)
if (tevent_req_is_unix_error(req, err)) {
return -1;
}
+ tevent_req_set_duration(req, state->duration);
*err = state->err;
return state->ret;
}
--
2.5.0
From f25d94c34340a78dcf0c2036a78e1e2cd03a2e10 Mon Sep 17 00:00:00 2001
From: Ralph Boehme <slow at samba.org>
Date: Fri, 26 Feb 2016 09:59:23 +0100
Subject: [PATCH 5/8] vfs/aio_fork: measure async request syscall duration
Signed-off-by: Ralph Boehme <slow at samba.org>
---
source3/modules/vfs_aio_fork.c | 9 +++++++++
1 file changed, 9 insertions(+)
diff --git a/source3/modules/vfs_aio_fork.c b/source3/modules/vfs_aio_fork.c
index 472ef0c..b17b55c 100644
--- a/source3/modules/vfs_aio_fork.c
+++ b/source3/modules/vfs_aio_fork.c
@@ -128,6 +128,7 @@ struct rw_cmd {
struct rw_ret {
ssize_t size;
int ret_errno;
+ uint64_t duration;
};
struct aio_child_list;
@@ -310,6 +311,7 @@ static void aio_child_loop(int sockfd, struct mmap_area *map)
ssize_t ret;
struct rw_cmd cmd_struct;
struct rw_ret ret_struct;
+ struct timespec start, end;
ret = read_fd(sockfd, &cmd_struct, sizeof(cmd_struct), &fd);
if (ret != sizeof(cmd_struct)) {
@@ -341,6 +343,8 @@ static void aio_child_loop(int sockfd, struct mmap_area *map)
ZERO_STRUCT(ret_struct);
+ clock_gettime_mono(&start);
+
switch (cmd_struct.cmd) {
case READ_CMD:
ret_struct.size = sys_pread(
@@ -366,6 +370,8 @@ static void aio_child_loop(int sockfd, struct mmap_area *map)
errno = EINVAL;
}
+ clock_gettime_mono(&end);
+ ret_struct.duration = nsec_time_diff(&end, &start);
DEBUG(10, ("aio_child_loop: syscall returned %d\n",
(int)ret_struct.size));
@@ -633,6 +639,7 @@ static void aio_fork_pread_done(struct tevent_req *subreq)
retbuf = (struct rw_ret *)buf;
state->ret = retbuf->size;
state->err = retbuf->ret_errno;
+ tevent_req_set_duration(req, retbuf->duration);
tevent_req_done(req);
}
@@ -749,6 +756,7 @@ static void aio_fork_pwrite_done(struct tevent_req *subreq)
retbuf = (struct rw_ret *)buf;
state->ret = retbuf->size;
state->err = retbuf->ret_errno;
+ tevent_req_set_duration(req, retbuf->duration);
tevent_req_done(req);
}
@@ -857,6 +865,7 @@ static void aio_fork_fsync_done(struct tevent_req *subreq)
retbuf = (struct rw_ret *)buf;
state->ret = retbuf->size;
state->err = retbuf->ret_errno;
+ tevent_req_set_duration(req, retbuf->duration);
tevent_req_done(req);
}
--
2.5.0
From 835d8211b085c938a962f7d555a23a171a38339f Mon Sep 17 00:00:00 2001
From: Ralph Boehme <slow at samba.org>
Date: Fri, 26 Feb 2016 10:52:39 +0100
Subject: [PATCH 6/8] vfs/aio_linux: measure libaio aio function call duration
Signed-off-by: Ralph Boehme <slow at samba.org>
---
source3/modules/vfs_aio_linux.c | 10 ++++++++++
1 file changed, 10 insertions(+)
diff --git a/source3/modules/vfs_aio_linux.c b/source3/modules/vfs_aio_linux.c
index 4f6230a..c599cf9 100644
--- a/source3/modules/vfs_aio_linux.c
+++ b/source3/modules/vfs_aio_linux.c
@@ -140,6 +140,7 @@ struct aio_linux_state {
struct iocb event_iocb;
ssize_t ret;
int err;
+ struct timespec start;
};
static struct tevent_req *aio_linux_pread_send(
@@ -167,6 +168,7 @@ static struct tevent_req *aio_linux_pread_send(
piocb = &state->event_iocb;
+ clock_gettime_mono(&state->start);
ret = io_submit(io_ctx, 1, &piocb);
if (ret < 0) {
tevent_req_error(req, -ret);
@@ -203,6 +205,7 @@ static struct tevent_req *aio_linux_pwrite_send(
piocb = &state->event_iocb;
+ clock_gettime_mono(&state->start);
ret = io_submit(io_ctx, 1, &piocb);
if (ret < 0) {
tevent_req_error(req, -ret);
@@ -237,6 +240,7 @@ static struct tevent_req *aio_linux_fsync_send(
piocb = &state->event_iocb;
+ clock_gettime_mono(&state->start);
ret = io_submit(io_ctx, 1, &piocb);
if (ret < 0) {
tevent_req_error(req, -ret);
@@ -252,10 +256,13 @@ static void aio_linux_done(struct tevent_context *event_ctx,
uint16_t flags, void *private_data)
{
uint64_t num_events = 0;
+ struct timespec end;
DEBUG(10, ("aio_linux_done called with flags=%d\n",
(int)flags));
+ clock_gettime_mono(&end);
+
/* Read the number of events available. */
if (sys_read(event_fd, &num_events, sizeof(num_events)) !=
sizeof(num_events)) {
@@ -268,6 +275,7 @@ static void aio_linux_done(struct tevent_context *event_ctx,
struct tevent_req *req;
struct aio_linux_state *state;
int ret;
+ uint64_t duration;
ret = io_getevents(io_ctx, 1, 1, &finished, &ts);
if (ret < 0) {
@@ -294,6 +302,8 @@ static void aio_linux_done(struct tevent_context *event_ctx,
state->ret = finished.res;
state->err = 0;
}
+ duration = nsec_time_diff(&end, &state->start);
+ tevent_req_set_duration(req, duration);
tevent_req_done(req);
num_events -= 1;
}
--
2.5.0
From 74828d476caed03131c93ed37d18f3d71f3efbd3 Mon Sep 17 00:00:00 2001
From: Ralph Boehme <slow at samba.org>
Date: Fri, 26 Feb 2016 11:14:36 +0100
Subject: [PATCH 7/8] vfs/glusterfs: measure libglusterfs aio function call
duration
Signed-off-by: Ralph Boehme <slow at samba.org>
---
source3/modules/vfs_glusterfs.c | 11 +++++++++++
1 file changed, 11 insertions(+)
diff --git a/source3/modules/vfs_glusterfs.c b/source3/modules/vfs_glusterfs.c
index 8e5316d..465c365 100644
--- a/source3/modules/vfs_glusterfs.c
+++ b/source3/modules/vfs_glusterfs.c
@@ -501,6 +501,8 @@ struct glusterfs_aio_state {
int err;
struct tevent_req *req;
bool cancelled;
+ struct timespec start;
+ uint64_t duration;
};
static int aio_wrapper_destructor(struct glusterfs_aio_wrapper *wrap)
@@ -519,9 +521,12 @@ static void aio_glusterfs_done(glfs_fd_t *fd, ssize_t ret, void *data)
{
struct glusterfs_aio_state *state = NULL;
int sts = 0;
+ struct timespec end;
state = (struct glusterfs_aio_state *)data;
+ clock_gettime_mono(&end);
+
if (ret < 0) {
state->ret = -1;
state->err = errno;
@@ -529,6 +534,7 @@ static void aio_glusterfs_done(glfs_fd_t *fd, ssize_t ret, void *data)
state->ret = ret;
state->err = 0;
}
+ state->duration = nsec_time_diff(&end, &state->start);
/*
* Write the state pointer to glusterfs_aio_state to the
@@ -690,6 +696,7 @@ static struct tevent_req *vfs_gluster_pread_send(struct vfs_handle_struct
return tevent_req_post(req, ev);
}
+ clock_gettime_mono(&state->start);
ret = glfs_pread_async(*(glfs_fd_t **)VFS_FETCH_FSP_EXTENSION(handle,
fsp), data, n, offset, 0, aio_glusterfs_done,
state);
@@ -725,6 +732,7 @@ static struct tevent_req *vfs_gluster_pwrite_send(struct vfs_handle_struct
return tevent_req_post(req, ev);
}
+ clock_gettime_mono(&state->start);
ret = glfs_pwrite_async(*(glfs_fd_t **)VFS_FETCH_FSP_EXTENSION(handle,
fsp), data, n, offset, 0, aio_glusterfs_done,
state);
@@ -762,6 +770,7 @@ static ssize_t vfs_gluster_recv(struct tevent_req *req, int *err)
}
ret = state->ret;
+ tevent_req_set_duration(req, state->duration);
/* Clean up the state, it is in a NULL context. */
@@ -841,6 +850,8 @@ static struct tevent_req *vfs_gluster_fsync_send(struct vfs_handle_struct
tevent_req_error(req, EIO);
return tevent_req_post(req, ev);
}
+
+ clock_gettime_mono(&state->start);
ret = glfs_fsync_async(*(glfs_fd_t **)VFS_FETCH_FSP_EXTENSION(handle,
fsp), aio_glusterfs_done, req);
if (ret < 0) {
--
2.5.0
From 264843e903308acc970562a450e014abada43d47 Mon Sep 17 00:00:00 2001
From: Ralph Boehme <slow at samba.org>
Date: Fri, 26 Feb 2016 12:54:23 +0100
Subject: [PATCH 8/8] vfs/time_audit: use duration we get from the async
backend
Finally! The previous commits changed the VFS and the async backend to
pass the duration of an aync operation up the stack.
We now can use this value instead of doing our own sampling which avoids
the following problem:
1. SMB2 read request received, added to the async queue
2. SMB2 create_file request comes in, is processed and blocks for N
seconds in open()
3. async read completes in the dispatcher thread, completion callback
will be called when we enter the main tevent loop
4. open() completes after N seconds
5. main tevent event loop is entered, async results are processed
6. async read result is processed, time sampling will include the N
seconds blocked in open()
Signed-off-by: Ralph Boehme <slow at samba.org>
---
source3/modules/vfs_time_audit.c | 24 ++++++------------------
1 file changed, 6 insertions(+), 18 deletions(-)
diff --git a/source3/modules/vfs_time_audit.c b/source3/modules/vfs_time_audit.c
index c38d69e..b6d7a36 100644
--- a/source3/modules/vfs_time_audit.c
+++ b/source3/modules/vfs_time_audit.c
@@ -676,7 +676,6 @@ static ssize_t smb_time_audit_pread(vfs_handle_struct *handle,
struct smb_time_audit_pread_state {
struct files_struct *fsp;
- struct timespec ts1;
ssize_t ret;
int err;
};
@@ -696,7 +695,6 @@ static struct tevent_req *smb_time_audit_pread_send(
if (req == NULL) {
return NULL;
}
- clock_gettime_mono(&state->ts1);
state->fsp = fsp;
subreq = SMB_VFS_NEXT_PREAD_SEND(state, ev, handle, fsp, data,
@@ -727,14 +725,12 @@ static ssize_t smb_time_audit_pread_recv(struct tevent_req *req, int *err)
{
struct smb_time_audit_pread_state *state = tevent_req_data(
req, struct smb_time_audit_pread_state);
- struct timespec ts2;
double timediff;
- clock_gettime_mono(&ts2);
- timediff = nsec_time_diff(&ts2,&state->ts1)*1.0e-9;
+ timediff = tevent_req_get_duration(req) * 1.0e-9;
if (timediff > audit_timeout) {
- smb_time_audit_log_fsp("pread", timediff, state->fsp);
+ smb_time_audit_log_fsp("async pread", timediff, state->fsp);
}
if (tevent_req_is_unix_error(req, err)) {
@@ -787,7 +783,6 @@ static ssize_t smb_time_audit_pwrite(vfs_handle_struct *handle,
struct smb_time_audit_pwrite_state {
struct files_struct *fsp;
- struct timespec ts1;
ssize_t ret;
int err;
};
@@ -807,7 +802,6 @@ static struct tevent_req *smb_time_audit_pwrite_send(
if (req == NULL) {
return NULL;
}
- clock_gettime_mono(&state->ts1);
state->fsp = fsp;
subreq = SMB_VFS_NEXT_PWRITE_SEND(state, ev, handle, fsp, data,
@@ -838,14 +832,12 @@ static ssize_t smb_time_audit_pwrite_recv(struct tevent_req *req, int *err)
{
struct smb_time_audit_pwrite_state *state = tevent_req_data(
req, struct smb_time_audit_pwrite_state);
- struct timespec ts2;
double timediff;
- clock_gettime_mono(&ts2);
- timediff = nsec_time_diff(&ts2,&state->ts1)*1.0e-9;
+ timediff = tevent_req_get_duration(req) * 1.0e-9;
if (timediff > audit_timeout) {
- smb_time_audit_log_fsp("pwrite", timediff, state->fsp);
+ smb_time_audit_log_fsp("async pwrite", timediff, state->fsp);
}
if (tevent_req_is_unix_error(req, err)) {
@@ -957,7 +949,6 @@ static int smb_time_audit_fsync(vfs_handle_struct *handle, files_struct *fsp)
struct smb_time_audit_fsync_state {
struct files_struct *fsp;
- struct timespec ts1;
int ret;
int err;
};
@@ -976,7 +967,6 @@ static struct tevent_req *smb_time_audit_fsync_send(
if (req == NULL) {
return NULL;
}
- clock_gettime_mono(&state->ts1);
state->fsp = fsp;
subreq = SMB_VFS_NEXT_FSYNC_SEND(state, ev, handle, fsp);
@@ -1006,14 +996,12 @@ static int smb_time_audit_fsync_recv(struct tevent_req *req, int *err)
{
struct smb_time_audit_fsync_state *state = tevent_req_data(
req, struct smb_time_audit_fsync_state);
- struct timespec ts2;
double timediff;
- clock_gettime_mono(&ts2);
- timediff = nsec_time_diff(&ts2,&state->ts1)*1.0e-9;
+ timediff = tevent_req_get_duration(req) * 1.0e-9;
if (timediff > audit_timeout) {
- smb_time_audit_log_fsp("fsync", timediff, state->fsp);
+ smb_time_audit_log_fsp("async fsync", timediff, state->fsp);
}
if (tevent_req_is_unix_error(req, err)) {
--
2.5.0
More information about the samba-technical
mailing list