[PATCH] Enhance time sampling of async IO VFS functions
Ralph Boehme
rb at sernet.de
Fri Feb 26 14:33:42 UTC 2016
Hi!
The problem:
when using vfs_time_audit to log slow VFS functions, a blocking sync
operation will cause previously sheduled async IO operations to
accumulate the penalty from the blocking sync operation. Example:
1. SMB2 read request received, added to the async queue
2. SMB2 create_file request comes in, is processed and blocks
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()
Fixing this involves adding time sampling to all async IO "backends"
(libasys, used in vfs_default, and all VFS modules that do their own
async IO, so glusterfs, aio_fork and aio_linux) and passing the time
sample up the VFS stack.
For passing it up the VFS stack I need to stick an additional arg to
all $IO_recv() VFS functions, which is cumbersome but the only way I
see to get this through.
Using clock_gettime_mono() and nsec_time_diff() in libasys means
pulling in samba-util, sorry. I don't see any other way the using
private copies which I considered worse.
Please review and push if ok. Thanks!
-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 c759784bce1edb1e41ca4f17ca7021e8b18dbb38 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 1/7] 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 2272918ce6079e59ad715e224896d93c37feecfe 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 2/7] 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 | 2 ++
1 file changed, 2 insertions(+)
diff --git a/source3/modules/vfs_default.c b/source3/modules/vfs_default.c
index b13b517..f74bd17 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);
}
--
2.5.0
From 634a5f683ab09c38e80da7fd848a8b27c4f9e7a1 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 3/7] vfs/aio_fork: measure async request syscall duration
Signed-off-by: Ralph Boehme <slow at samba.org>
---
source3/modules/vfs_aio_fork.c | 18 +++++++++++++++---
1 file changed, 15 insertions(+), 3 deletions(-)
diff --git a/source3/modules/vfs_aio_fork.c b/source3/modules/vfs_aio_fork.c
index 472ef0c..6878371 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));
@@ -535,6 +541,7 @@ struct aio_fork_pread_state {
struct aio_child *child;
ssize_t ret;
int err;
+ uint64_t duration;
};
static void aio_fork_pread_done(struct tevent_req *subreq);
@@ -633,10 +640,11 @@ static void aio_fork_pread_done(struct tevent_req *subreq)
retbuf = (struct rw_ret *)buf;
state->ret = retbuf->size;
state->err = retbuf->ret_errno;
+ state->duration = retbuf->duration;
tevent_req_done(req);
}
-static ssize_t aio_fork_pread_recv(struct tevent_req *req, int *err)
+static ssize_t aio_fork_pread_recv(struct tevent_req *req, int *err, uint64_t *pduration)
{
struct aio_fork_pread_state *state = tevent_req_data(
req, struct aio_fork_pread_state);
@@ -654,6 +662,7 @@ struct aio_fork_pwrite_state {
struct aio_child *child;
ssize_t ret;
int err;
+ uint64_t duration;
};
static void aio_fork_pwrite_done(struct tevent_req *subreq);
@@ -749,10 +758,11 @@ static void aio_fork_pwrite_done(struct tevent_req *subreq)
retbuf = (struct rw_ret *)buf;
state->ret = retbuf->size;
state->err = retbuf->ret_errno;
+ state->duration = retbuf->duration;
tevent_req_done(req);
}
-static ssize_t aio_fork_pwrite_recv(struct tevent_req *req, int *err)
+static ssize_t aio_fork_pwrite_recv(struct tevent_req *req, int *err, uint64_t *pduration)
{
struct aio_fork_pwrite_state *state = tevent_req_data(
req, struct aio_fork_pwrite_state);
@@ -770,6 +780,7 @@ struct aio_fork_fsync_state {
struct aio_child *child;
ssize_t ret;
int err;
+ uint64_t duration;
};
static void aio_fork_fsync_done(struct tevent_req *subreq);
@@ -857,10 +868,11 @@ static void aio_fork_fsync_done(struct tevent_req *subreq)
retbuf = (struct rw_ret *)buf;
state->ret = retbuf->size;
state->err = retbuf->ret_errno;
+ state->duration = retbuf->duration;
tevent_req_done(req);
}
-static int aio_fork_fsync_recv(struct tevent_req *req, int *err)
+static int aio_fork_fsync_recv(struct tevent_req *req, int *err, uint64_t *pduration)
{
struct aio_fork_fsync_state *state = tevent_req_data(
req, struct aio_fork_fsync_state);
--
2.5.0
From 2fce69eb45de56e7926362f953a1ab3afc593744 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 4/7] vfs/aio_linux: measure libaio aio function call duration
Signed-off-by: Ralph Boehme <slow at samba.org>
---
source3/modules/vfs_aio_linux.c | 12 +++++++++++-
1 file changed, 11 insertions(+), 1 deletion(-)
diff --git a/source3/modules/vfs_aio_linux.c b/source3/modules/vfs_aio_linux.c
index 4f6230a..1922690 100644
--- a/source3/modules/vfs_aio_linux.c
+++ b/source3/modules/vfs_aio_linux.c
@@ -140,6 +140,8 @@ struct aio_linux_state {
struct iocb event_iocb;
ssize_t ret;
int err;
+ struct timespec start;
+ uint64_t duration;
};
static struct tevent_req *aio_linux_pread_send(
@@ -167,6 +169,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 +206,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 +241,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 +257,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)) {
@@ -294,12 +302,14 @@ static void aio_linux_done(struct tevent_context *event_ctx,
state->ret = finished.res;
state->err = 0;
}
+ state->duration = nsec_time_diff(&end, &state->start);
tevent_req_done(req);
num_events -= 1;
}
}
-static ssize_t aio_linux_recv(struct tevent_req *req, int *err)
+static ssize_t aio_linux_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct aio_linux_state *state = tevent_req_data(
req, struct aio_linux_state);
--
2.5.0
From 353e5a924f05ea360425e56c822fc0ad3e5592bc 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 5/7] vfs/glusterfs: measure libglusterfs aio function call
duration
Signed-off-by: Ralph Boehme <slow at samba.org>
---
source3/modules/vfs_glusterfs.c | 10 ++++++++++
1 file changed, 10 insertions(+)
diff --git a/source3/modules/vfs_glusterfs.c b/source3/modules/vfs_glusterfs.c
index 8e5316d..27f32ea 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);
@@ -841,6 +849,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 6b022f40eca9d1d65ab819905d2112fa1938d759 Mon Sep 17 00:00:00 2001
From: Ralph Boehme <slow at samba.org>
Date: Fri, 26 Feb 2016 10:54:01 +0100
Subject: [PATCH 6/7] s3/vfs: add duration arg to async recv functions
This adds a uint64_t * arg to the async pread, pwrite and fsync receive
functions.
The async backend will sample the syscall or function call and return
the duration via this argument.
Signed-off-by: Ralph Boehme <slow at samba.org>
---
examples/VFS/skel_opaque.c | 7 ++++---
examples/VFS/skel_transparent.c | 21 +++++++++++++++------
source3/include/vfs.h | 13 +++++++------
source3/modules/vfs_aio_fork.c | 3 +++
source3/modules/vfs_aio_linux.c | 5 +++--
source3/modules/vfs_commit.c | 6 ++++--
source3/modules/vfs_default.c | 8 ++++++--
source3/modules/vfs_full_audit.c | 21 +++++++++++++++------
source3/modules/vfs_glusterfs.c | 7 ++++---
source3/modules/vfs_gpfs.c | 14 ++++++++++----
source3/modules/vfs_time_audit.c | 21 +++++++++++++++------
source3/modules/vfs_tsmsm.c | 14 ++++++++++----
source3/smbd/aio.c | 12 ++++++++----
source3/smbd/smb2_flush.c | 3 ++-
source3/smbd/vfs.c | 24 +++++++++++++++---------
15 files changed, 121 insertions(+), 58 deletions(-)
diff --git a/examples/VFS/skel_opaque.c b/examples/VFS/skel_opaque.c
index 8961627..d57e01c 100644
--- a/examples/VFS/skel_opaque.c
+++ b/examples/VFS/skel_opaque.c
@@ -241,7 +241,8 @@ static struct tevent_req *skel_pread_send(struct vfs_handle_struct *handle,
return NULL;
}
-static ssize_t skel_pread_recv(struct tevent_req *req, int *err)
+static ssize_t skel_pread_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
*err = ENOSYS;
return -1;
@@ -271,7 +272,7 @@ static struct tevent_req *skel_pwrite_send(struct vfs_handle_struct *handle,
return NULL;
}
-static ssize_t skel_pwrite_recv(struct tevent_req *req, int *err)
+static ssize_t skel_pwrite_recv(struct tevent_req *req, int *err, uint64_t *pduration)
{
*err = ENOSYS;
return -1;
@@ -321,7 +322,7 @@ static struct tevent_req *skel_fsync_send(struct vfs_handle_struct *handle,
return NULL;
}
-static int skel_fsync_recv(struct tevent_req *req, int *err)
+static int skel_fsync_recv(struct tevent_req *req, int *err, uint64_t *pduration)
{
*err = ENOSYS;
return -1;
diff --git a/examples/VFS/skel_transparent.c b/examples/VFS/skel_transparent.c
index ac82432..c86f0d6 100644
--- a/examples/VFS/skel_transparent.c
+++ b/examples/VFS/skel_transparent.c
@@ -242,6 +242,7 @@ static ssize_t skel_pread(vfs_handle_struct *handle, files_struct *fsp,
struct skel_pread_state {
ssize_t ret;
int err;
+ uint64_t duration;
};
static void skel_pread_done(struct tevent_req *subreq);
@@ -275,12 +276,13 @@ static void skel_pread_done(struct tevent_req *subreq)
struct skel_pread_state *state =
tevent_req_data(req, struct skel_pread_state);
- state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
tevent_req_done(req);
}
-static ssize_t skel_pread_recv(struct tevent_req *req, int *err)
+static ssize_t skel_pread_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct skel_pread_state *state =
tevent_req_data(req, struct skel_pread_state);
@@ -289,6 +291,7 @@ static ssize_t skel_pread_recv(struct tevent_req *req, int *err)
return -1;
}
*err = state->err;
+ *pduration = state->duration;
return state->ret;
}
@@ -307,6 +310,7 @@ static ssize_t skel_pwrite(vfs_handle_struct *handle, files_struct *fsp,
struct skel_pwrite_state {
ssize_t ret;
int err;
+ uint64_t duration;
};
static void skel_pwrite_done(struct tevent_req *subreq);
@@ -341,12 +345,13 @@ static void skel_pwrite_done(struct tevent_req *subreq)
struct skel_pwrite_state *state =
tevent_req_data(req, struct skel_pwrite_state);
- state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
tevent_req_done(req);
}
-static ssize_t skel_pwrite_recv(struct tevent_req *req, int *err)
+static ssize_t skel_pwrite_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct skel_pwrite_state *state =
tevent_req_data(req, struct skel_pwrite_state);
@@ -355,6 +360,7 @@ static ssize_t skel_pwrite_recv(struct tevent_req *req, int *err)
return -1;
}
*err = state->err;
+ *pduration = state->duration;
return state->ret;
}
@@ -392,6 +398,7 @@ static int skel_fsync(vfs_handle_struct *handle, files_struct *fsp)
struct skel_fsync_state {
int ret;
int err;
+ uint64_t duration;
};
static void skel_fsync_done(struct tevent_req *subreq);
@@ -423,12 +430,13 @@ static void skel_fsync_done(struct tevent_req *subreq)
struct skel_fsync_state *state =
tevent_req_data(req, struct skel_fsync_state);
- state->ret = SMB_VFS_FSYNC_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_FSYNC_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
tevent_req_done(req);
}
-static int skel_fsync_recv(struct tevent_req *req, int *err)
+static int skel_fsync_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct skel_fsync_state *state =
tevent_req_data(req, struct skel_fsync_state);
@@ -437,6 +445,7 @@ static int skel_fsync_recv(struct tevent_req *req, int *err)
return -1;
}
*err = state->err;
+ *pduration = state->duration;
return state->ret;
}
diff --git a/source3/include/vfs.h b/source3/include/vfs.h
index b291206..550c83a 100644
--- a/source3/include/vfs.h
+++ b/source3/include/vfs.h
@@ -177,6 +177,7 @@
const struct smb_filename * */
/* Version 35 - Change rmdir from const char *, to
const struct smb_filename * */
+/* Version 35 - Add duration arg to async funtions */
#define SMB_VFS_INTERFACE_VERSION 35
@@ -599,7 +600,7 @@ struct vfs_fn_pointers {
struct files_struct *fsp,
void *data,
size_t n, off_t offset);
- ssize_t (*pread_recv_fn)(struct tevent_req *req, int *err);
+ ssize_t (*pread_recv_fn)(struct tevent_req *req, int *err, uint64_t *pduration);
ssize_t (*write_fn)(struct vfs_handle_struct *handle, struct files_struct *fsp, const void *data, size_t n);
ssize_t (*pwrite_fn)(struct vfs_handle_struct *handle, struct files_struct *fsp, const void *data, size_t n, off_t offset);
struct tevent_req *(*pwrite_send_fn)(struct vfs_handle_struct *handle,
@@ -608,7 +609,7 @@ struct vfs_fn_pointers {
struct files_struct *fsp,
const void *data,
size_t n, off_t offset);
- ssize_t (*pwrite_recv_fn)(struct tevent_req *req, int *err);
+ ssize_t (*pwrite_recv_fn)(struct tevent_req *req, int *err, uint64_t *pduration);
off_t (*lseek_fn)(struct vfs_handle_struct *handle, struct files_struct *fsp, off_t offset, int whence);
ssize_t (*sendfile_fn)(struct vfs_handle_struct *handle, int tofd, files_struct *fromfsp, const DATA_BLOB *header, off_t offset, size_t count);
ssize_t (*recvfile_fn)(struct vfs_handle_struct *handle, int fromfd, files_struct *tofsp, off_t offset, size_t count);
@@ -620,7 +621,7 @@ struct vfs_fn_pointers {
TALLOC_CTX *mem_ctx,
struct tevent_context *ev,
struct files_struct *fsp);
- int (*fsync_recv_fn)(struct tevent_req *req, int *err);
+ int (*fsync_recv_fn)(struct tevent_req *req, int *err, uint64_t *pduration);
int (*stat_fn)(struct vfs_handle_struct *handle, struct smb_filename *smb_fname);
int (*fstat_fn)(struct vfs_handle_struct *handle, struct files_struct *fsp, SMB_STRUCT_STAT *sbuf);
int (*lstat_fn)(struct vfs_handle_struct *handle, struct smb_filename *smb_filename);
@@ -1022,7 +1023,7 @@ struct tevent_req *smb_vfs_call_pread_send(struct vfs_handle_struct *handle,
struct files_struct *fsp,
void *data,
size_t n, off_t offset);
-ssize_t SMB_VFS_PREAD_RECV(struct tevent_req *req, int *perrno);
+ssize_t SMB_VFS_PREAD_RECV(struct tevent_req *req, int *perrno, uint64_t *pduration);
ssize_t smb_vfs_call_write(struct vfs_handle_struct *handle,
struct files_struct *fsp, const void *data,
@@ -1036,7 +1037,7 @@ struct tevent_req *smb_vfs_call_pwrite_send(struct vfs_handle_struct *handle,
struct files_struct *fsp,
const void *data,
size_t n, off_t offset);
-ssize_t SMB_VFS_PWRITE_RECV(struct tevent_req *req, int *perrno);
+ssize_t SMB_VFS_PWRITE_RECV(struct tevent_req *req, int *perrno, uint64_t *pduration);
off_t smb_vfs_call_lseek(struct vfs_handle_struct *handle,
struct files_struct *fsp, off_t offset,
@@ -1057,7 +1058,7 @@ struct tevent_req *smb_vfs_call_fsync_send(struct vfs_handle_struct *handle,
TALLOC_CTX *mem_ctx,
struct tevent_context *ev,
struct files_struct *fsp);
-int SMB_VFS_FSYNC_RECV(struct tevent_req *req, int *perrno);
+int SMB_VFS_FSYNC_RECV(struct tevent_req *req, int *perrno, uint64_t *pduration);
int smb_vfs_call_stat(struct vfs_handle_struct *handle,
struct smb_filename *smb_fname);
diff --git a/source3/modules/vfs_aio_fork.c b/source3/modules/vfs_aio_fork.c
index 6878371..2b823b2 100644
--- a/source3/modules/vfs_aio_fork.c
+++ b/source3/modules/vfs_aio_fork.c
@@ -655,6 +655,7 @@ static ssize_t aio_fork_pread_recv(struct tevent_req *req, int *err, uint64_t *p
if (state->ret == -1) {
*err = state->err;
}
+ *pduration = state->duration;
return state->ret;
}
@@ -773,6 +774,7 @@ static ssize_t aio_fork_pwrite_recv(struct tevent_req *req, int *err, uint64_t *
if (state->ret == -1) {
*err = state->err;
}
+ *pduration = state->duration;
return state->ret;
}
@@ -883,6 +885,7 @@ static int aio_fork_fsync_recv(struct tevent_req *req, int *err, uint64_t *pdura
if (state->ret == -1) {
*err = state->err;
}
+ *pduration = state->duration;
return state->ret;
}
diff --git a/source3/modules/vfs_aio_linux.c b/source3/modules/vfs_aio_linux.c
index 1922690..87cad3d 100644
--- a/source3/modules/vfs_aio_linux.c
+++ b/source3/modules/vfs_aio_linux.c
@@ -320,15 +320,16 @@ static ssize_t aio_linux_recv(struct tevent_req *req, int *err,
if (state->ret == -1) {
*err = state->err;
}
+ *pduration = state->duration;
return state->ret;
}
-static int aio_linux_int_recv(struct tevent_req *req, int *err)
+static int aio_linux_int_recv(struct tevent_req *req, int *err, uint64_t *pduration)
{
/*
* Use implicit conversion ssize_t->int
*/
- return aio_linux_recv(req, err);
+ return aio_linux_recv(req, err, pduration);
}
static struct vfs_fn_pointers vfs_aio_linux_fns = {
diff --git a/source3/modules/vfs_commit.c b/source3/modules/vfs_commit.c
index f1e2743..2be67c1 100644
--- a/source3/modules/vfs_commit.c
+++ b/source3/modules/vfs_commit.c
@@ -290,6 +290,7 @@ struct commit_pwrite_state {
struct files_struct *fsp;
ssize_t ret;
int err;
+ uint64_t duration;
};
static void commit_pwrite_written(struct tevent_req *subreq);
@@ -328,7 +329,7 @@ static void commit_pwrite_written(struct tevent_req *subreq)
req, struct commit_pwrite_state);
int commit_ret;
- state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
if (state->ret <= 0) {
@@ -350,7 +351,7 @@ static void commit_pwrite_written(struct tevent_req *subreq)
tevent_req_done(req);
}
-static ssize_t commit_pwrite_recv(struct tevent_req *req, int *err)
+static ssize_t commit_pwrite_recv(struct tevent_req *req, int *err, uint64_t *pduration)
{
struct commit_pwrite_state *state =
tevent_req_data(req, struct commit_pwrite_state);
@@ -359,6 +360,7 @@ static ssize_t commit_pwrite_recv(struct tevent_req *req, int *err)
return -1;
}
*err = state->err;
+ *pduration = state->duration;
return state->ret;
}
diff --git a/source3/modules/vfs_default.c b/source3/modules/vfs_default.c
index f74bd17..349b1e6 100644
--- a/source3/modules/vfs_default.c
+++ b/source3/modules/vfs_default.c
@@ -897,7 +897,8 @@ static void vfswrap_asys_finished(struct tevent_context *ev,
}
}
-static ssize_t vfswrap_asys_ssize_t_recv(struct tevent_req *req, int *err)
+static ssize_t vfswrap_asys_ssize_t_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct vfswrap_asys_state *state = tevent_req_data(
req, struct vfswrap_asys_state);
@@ -906,10 +907,12 @@ static ssize_t vfswrap_asys_ssize_t_recv(struct tevent_req *req, int *err)
return -1;
}
*err = state->err;
+ *pduration = state->duration;
return state->ret;
}
-static int vfswrap_asys_int_recv(struct tevent_req *req, int *err)
+static int vfswrap_asys_int_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct vfswrap_asys_state *state = tevent_req_data(
req, struct vfswrap_asys_state);
@@ -918,6 +921,7 @@ static int vfswrap_asys_int_recv(struct tevent_req *req, int *err)
return -1;
}
*err = state->err;
+ *pduration = state->duration;
return state->ret;
}
diff --git a/source3/modules/vfs_full_audit.c b/source3/modules/vfs_full_audit.c
index 3dd2005..7e87120 100644
--- a/source3/modules/vfs_full_audit.c
+++ b/source3/modules/vfs_full_audit.c
@@ -1021,6 +1021,7 @@ struct smb_full_audit_pread_state {
files_struct *fsp;
ssize_t ret;
int err;
+ uint64_t duration;
};
static void smb_full_audit_pread_done(struct tevent_req *subreq);
@@ -1063,12 +1064,13 @@ 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);
- state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
tevent_req_done(req);
}
-static ssize_t smb_full_audit_pread_recv(struct tevent_req *req, int *err)
+static ssize_t smb_full_audit_pread_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct smb_full_audit_pread_state *state = tevent_req_data(
req, struct smb_full_audit_pread_state);
@@ -1083,6 +1085,7 @@ static ssize_t smb_full_audit_pread_recv(struct tevent_req *req, int *err)
fsp_str_do_log(state->fsp));
*err = state->err;
+ *pduration = state->duration;
return state->ret;
}
@@ -1118,6 +1121,7 @@ struct smb_full_audit_pwrite_state {
files_struct *fsp;
ssize_t ret;
int err;
+ uint64_t duration;
};
static void smb_full_audit_pwrite_done(struct tevent_req *subreq);
@@ -1161,12 +1165,13 @@ 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);
- state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
tevent_req_done(req);
}
-static ssize_t smb_full_audit_pwrite_recv(struct tevent_req *req, int *err)
+static ssize_t smb_full_audit_pwrite_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct smb_full_audit_pwrite_state *state = tevent_req_data(
req, struct smb_full_audit_pwrite_state);
@@ -1181,6 +1186,7 @@ static ssize_t smb_full_audit_pwrite_recv(struct tevent_req *req, int *err)
fsp_str_do_log(state->fsp));
*err = state->err;
+ *pduration = state->duration;
return state->ret;
}
@@ -1259,6 +1265,7 @@ struct smb_full_audit_fsync_state {
files_struct *fsp;
int ret;
int err;
+ uint64_t duration;
};
static void smb_full_audit_fsync_done(struct tevent_req *subreq);
@@ -1299,12 +1306,13 @@ 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);
- state->ret = SMB_VFS_FSYNC_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_FSYNC_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
tevent_req_done(req);
}
-static int smb_full_audit_fsync_recv(struct tevent_req *req, int *err)
+static int smb_full_audit_fsync_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct smb_full_audit_fsync_state *state = tevent_req_data(
req, struct smb_full_audit_fsync_state);
@@ -1319,6 +1327,7 @@ static int smb_full_audit_fsync_recv(struct tevent_req *req, int *err)
fsp_str_do_log(state->fsp));
*err = state->err;
+ *err = state->duration;
return state->ret;
}
diff --git a/source3/modules/vfs_glusterfs.c b/source3/modules/vfs_glusterfs.c
index 27f32ea..7cebecb 100644
--- a/source3/modules/vfs_glusterfs.c
+++ b/source3/modules/vfs_glusterfs.c
@@ -744,7 +744,7 @@ static struct tevent_req *vfs_gluster_pwrite_send(struct vfs_handle_struct
return req;
}
-static ssize_t vfs_gluster_recv(struct tevent_req *req, int *err)
+static ssize_t vfs_gluster_recv(struct tevent_req *req, int *err, uint64_t *pduration)
{
struct glusterfs_aio_state *state = NULL;
struct glusterfs_aio_wrapper *wrapper = NULL;
@@ -770,6 +770,7 @@ static ssize_t vfs_gluster_recv(struct tevent_req *req, int *err)
}
ret = state->ret;
+ *pduration = state->duration;
/* Clean up the state, it is in a NULL context. */
@@ -860,12 +861,12 @@ static struct tevent_req *vfs_gluster_fsync_send(struct vfs_handle_struct
return req;
}
-static int vfs_gluster_fsync_recv(struct tevent_req *req, int *err)
+static int vfs_gluster_fsync_recv(struct tevent_req *req, int *err, uint64_t *pduration)
{
/*
* Use implicit conversion ssize_t->int
*/
- return vfs_gluster_recv(req, err);
+ return vfs_gluster_recv(req, err, pduration);
}
static int vfs_gluster_stat(struct vfs_handle_struct *handle,
diff --git a/source3/modules/vfs_gpfs.c b/source3/modules/vfs_gpfs.c
index 33a30d0..d6ba203 100644
--- a/source3/modules/vfs_gpfs.c
+++ b/source3/modules/vfs_gpfs.c
@@ -2319,6 +2319,7 @@ struct vfs_gpfs_pread_state {
ssize_t ret;
int err;
bool was_offline;
+ uint64_t duration;
};
static void vfs_gpfs_pread_done(struct tevent_req *subreq);
@@ -2355,12 +2356,13 @@ 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);
- state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
tevent_req_done(req);
}
-static ssize_t vfs_gpfs_pread_recv(struct tevent_req *req, int *err)
+static ssize_t vfs_gpfs_pread_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct vfs_gpfs_pread_state *state = tevent_req_data(
req, struct vfs_gpfs_pread_state);
@@ -2370,6 +2372,7 @@ static ssize_t vfs_gpfs_pread_recv(struct tevent_req *req, int *err)
return -1;
}
*err = state->err;
+ *pduration = state->duration;
if ((state->ret != -1) && state->was_offline) {
DEBUG(10, ("sending notify\n"));
@@ -2405,6 +2408,7 @@ struct vfs_gpfs_pwrite_state {
ssize_t ret;
int err;
bool was_offline;
+ uint64_t duration;
};
static void vfs_gpfs_pwrite_done(struct tevent_req *subreq);
@@ -2442,12 +2446,13 @@ 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);
- state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
tevent_req_done(req);
}
-static ssize_t vfs_gpfs_pwrite_recv(struct tevent_req *req, int *err)
+static ssize_t vfs_gpfs_pwrite_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct vfs_gpfs_pwrite_state *state = tevent_req_data(
req, struct vfs_gpfs_pwrite_state);
@@ -2457,6 +2462,7 @@ static ssize_t vfs_gpfs_pwrite_recv(struct tevent_req *req, int *err)
return -1;
}
*err = state->err;
+ *pduration = state->duration;
if ((state->ret != -1) && state->was_offline) {
DEBUG(10, ("sending notify\n"));
diff --git a/source3/modules/vfs_time_audit.c b/source3/modules/vfs_time_audit.c
index 11866fa..ab694de 100644
--- a/source3/modules/vfs_time_audit.c
+++ b/source3/modules/vfs_time_audit.c
@@ -679,6 +679,7 @@ struct smb_time_audit_pread_state {
struct timespec ts1;
ssize_t ret;
int err;
+ uint64_t duration;
};
static void smb_time_audit_pread_done(struct tevent_req *subreq);
@@ -715,12 +716,13 @@ static void smb_time_audit_pread_done(struct tevent_req *subreq)
struct smb_time_audit_pread_state *state = tevent_req_data(
req, struct smb_time_audit_pread_state);
- state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
tevent_req_done(req);
}
-static ssize_t smb_time_audit_pread_recv(struct tevent_req *req, int *err)
+static ssize_t smb_time_audit_pread_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct smb_time_audit_pread_state *state = tevent_req_data(
req, struct smb_time_audit_pread_state);
@@ -738,6 +740,7 @@ static ssize_t smb_time_audit_pread_recv(struct tevent_req *req, int *err)
return -1;
}
*err = state->err;
+ *pduration = state->duration;
return state->ret;
}
@@ -787,6 +790,7 @@ struct smb_time_audit_pwrite_state {
struct timespec ts1;
ssize_t ret;
int err;
+ uint64_t duration;
};
static void smb_time_audit_pwrite_done(struct tevent_req *subreq);
@@ -823,12 +827,13 @@ static void smb_time_audit_pwrite_done(struct tevent_req *subreq)
struct smb_time_audit_pwrite_state *state = tevent_req_data(
req, struct smb_time_audit_pwrite_state);
- state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
tevent_req_done(req);
}
-static ssize_t smb_time_audit_pwrite_recv(struct tevent_req *req, int *err)
+static ssize_t smb_time_audit_pwrite_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct smb_time_audit_pwrite_state *state = tevent_req_data(
req, struct smb_time_audit_pwrite_state);
@@ -846,6 +851,7 @@ static ssize_t smb_time_audit_pwrite_recv(struct tevent_req *req, int *err)
return -1;
}
*err = state->err;
+ *pduration = state->duration;
return state->ret;
}
@@ -954,6 +960,7 @@ struct smb_time_audit_fsync_state {
struct timespec ts1;
int ret;
int err;
+ uint64_t duration;
};
static void smb_time_audit_fsync_done(struct tevent_req *subreq);
@@ -988,12 +995,13 @@ static void smb_time_audit_fsync_done(struct tevent_req *subreq)
struct smb_time_audit_fsync_state *state = tevent_req_data(
req, struct smb_time_audit_fsync_state);
- state->ret = SMB_VFS_FSYNC_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_FSYNC_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
tevent_req_done(req);
}
-static int smb_time_audit_fsync_recv(struct tevent_req *req, int *err)
+static int smb_time_audit_fsync_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct smb_time_audit_fsync_state *state = tevent_req_data(
req, struct smb_time_audit_fsync_state);
@@ -1011,6 +1019,7 @@ static int smb_time_audit_fsync_recv(struct tevent_req *req, int *err)
return -1;
}
*err = state->err;
+ *pduration = state->duration;
return state->ret;
}
diff --git a/source3/modules/vfs_tsmsm.c b/source3/modules/vfs_tsmsm.c
index e4bc7eb..76a614a 100644
--- a/source3/modules/vfs_tsmsm.c
+++ b/source3/modules/vfs_tsmsm.c
@@ -291,6 +291,7 @@ struct tsmsm_pread_state {
ssize_t ret;
int err;
bool was_offline;
+ uint64_t duration;
};
static void tsmsm_pread_done(struct tevent_req *subreq);
@@ -326,12 +327,13 @@ static void tsmsm_pread_done(struct tevent_req *subreq)
struct tsmsm_pread_state *state = tevent_req_data(
req, struct tsmsm_pread_state);
- state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_PREAD_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
tevent_req_done(req);
}
-static ssize_t tsmsm_pread_recv(struct tevent_req *req, int *err)
+static ssize_t tsmsm_pread_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct tsmsm_pread_state *state = tevent_req_data(
req, struct tsmsm_pread_state);
@@ -346,6 +348,7 @@ static ssize_t tsmsm_pread_recv(struct tevent_req *req, int *err)
fsp->fsp_name->base_name);
}
*err = state->err;
+ *pduration = state->duration;
return state->ret;
}
@@ -354,6 +357,7 @@ struct tsmsm_pwrite_state {
ssize_t ret;
int err;
bool was_offline;
+ uint64_t duration;
};
static void tsmsm_pwrite_done(struct tevent_req *subreq);
@@ -390,12 +394,13 @@ static void tsmsm_pwrite_done(struct tevent_req *subreq)
struct tsmsm_pwrite_state *state = tevent_req_data(
req, struct tsmsm_pwrite_state);
- state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err);
+ state->ret = SMB_VFS_PWRITE_RECV(subreq, &state->err, &state->duration);
TALLOC_FREE(subreq);
tevent_req_done(req);
}
-static ssize_t tsmsm_pwrite_recv(struct tevent_req *req, int *err)
+static ssize_t tsmsm_pwrite_recv(struct tevent_req *req, int *err,
+ uint64_t *pduration)
{
struct tsmsm_pwrite_state *state = tevent_req_data(
req, struct tsmsm_pwrite_state);
@@ -410,6 +415,7 @@ static ssize_t tsmsm_pwrite_recv(struct tevent_req *req, int *err)
fsp->fsp_name->base_name);
}
*err = state->err;
+ *pduration = state->duration;
return state->ret;
}
diff --git a/source3/smbd/aio.c b/source3/smbd/aio.c
index 32a1ce0..243b625 100644
--- a/source3/smbd/aio.c
+++ b/source3/smbd/aio.c
@@ -275,8 +275,9 @@ static void aio_pread_smb1_done(struct tevent_req *req)
char *data = smb_buf(outbuf) + 1 /* padding byte */;
ssize_t nread;
int err;
+ uint64_t duration;
- nread = SMB_VFS_PREAD_RECV(req, &err);
+ nread = SMB_VFS_PREAD_RECV(req, &err, &duration);
TALLOC_FREE(req);
DEBUG(10, ("pread_recv returned %d, err = %s\n", (int)nread,
@@ -379,8 +380,9 @@ static void pwrite_fsync_write_done(struct tevent_req *subreq)
connection_struct *conn = state->fsp->conn;
int err;
bool do_sync;
+ uint64_t duration;
- state->nwritten = SMB_VFS_PWRITE_RECV(subreq, &err);
+ state->nwritten = SMB_VFS_PWRITE_RECV(subreq, &err, &duration);
TALLOC_FREE(subreq);
if (state->nwritten == -1) {
tevent_req_error(req, err);
@@ -406,8 +408,9 @@ static void pwrite_fsync_sync_done(struct tevent_req *subreq)
struct tevent_req *req = tevent_req_callback_data(
subreq, struct tevent_req);
int ret, err;
+ uint64_t duration;
- ret = SMB_VFS_FSYNC_RECV(subreq, &err);
+ ret = SMB_VFS_FSYNC_RECV(subreq, &err, &duration);
TALLOC_FREE(subreq);
if (ret == -1) {
tevent_req_error(req, err);
@@ -776,8 +779,9 @@ static void aio_pread_smb2_done(struct tevent_req *req)
NTSTATUS status;
ssize_t nread;
int err = 0;
+ uint64_t duration;
- nread = SMB_VFS_PREAD_RECV(req, &err);
+ nread = SMB_VFS_PREAD_RECV(req, &err, &duration);
TALLOC_FREE(req);
DEBUG(10, ("pread_recv returned %d, err = %s\n", (int)nread,
diff --git a/source3/smbd/smb2_flush.c b/source3/smbd/smb2_flush.c
index 00b0535..9bdd239 100644
--- a/source3/smbd/smb2_flush.c
+++ b/source3/smbd/smb2_flush.c
@@ -191,10 +191,11 @@ static void smbd_smb2_flush_done(struct tevent_req *subreq)
struct tevent_req *req = tevent_req_callback_data(
subreq, struct tevent_req);
int ret, err;
+ uint64_t duration;
decrement_outstanding_aio_calls();
- ret = SMB_VFS_FSYNC_RECV(subreq, &err);
+ ret = SMB_VFS_FSYNC_RECV(subreq, &err, &duration);
TALLOC_FREE(subreq);
if (ret == -1) {
tevent_req_error(req, err);
diff --git a/source3/smbd/vfs.c b/source3/smbd/vfs.c
index dfc22be..1be9b94 100644
--- a/source3/smbd/vfs.c
+++ b/source3/smbd/vfs.c
@@ -1586,8 +1586,9 @@ ssize_t smb_vfs_call_pread(struct vfs_handle_struct *handle,
}
struct smb_vfs_call_pread_state {
- ssize_t (*recv_fn)(struct tevent_req *req, int *err);
+ ssize_t (*recv_fn)(struct tevent_req *req, int *err, uint64_t *pduration);
ssize_t retval;
+ uint64_t duration;
};
static void smb_vfs_call_pread_done(struct tevent_req *subreq);
@@ -1627,7 +1628,7 @@ static void smb_vfs_call_pread_done(struct tevent_req *subreq)
req, struct smb_vfs_call_pread_state);
int err;
- state->retval = state->recv_fn(subreq, &err);
+ state->retval = state->recv_fn(subreq, &err, &state->duration);
TALLOC_FREE(subreq);
if (state->retval == -1) {
tevent_req_error(req, err);
@@ -1636,7 +1637,7 @@ static void smb_vfs_call_pread_done(struct tevent_req *subreq)
tevent_req_done(req);
}
-ssize_t SMB_VFS_PREAD_RECV(struct tevent_req *req, int *perrno)
+ssize_t SMB_VFS_PREAD_RECV(struct tevent_req *req, int *perrno, uint64_t *pduration)
{
struct smb_vfs_call_pread_state *state = tevent_req_data(
req, struct smb_vfs_call_pread_state);
@@ -1646,6 +1647,7 @@ ssize_t SMB_VFS_PREAD_RECV(struct tevent_req *req, int *perrno)
*perrno = err;
return -1;
}
+ *pduration = state->duration;
return state->retval;
}
@@ -1666,8 +1668,9 @@ ssize_t smb_vfs_call_pwrite(struct vfs_handle_struct *handle,
}
struct smb_vfs_call_pwrite_state {
- ssize_t (*recv_fn)(struct tevent_req *req, int *err);
+ ssize_t (*recv_fn)(struct tevent_req *req, int *err, uint64_t *pduration);
ssize_t retval;
+ uint64_t duration;
};
static void smb_vfs_call_pwrite_done(struct tevent_req *subreq);
@@ -1707,7 +1710,7 @@ static void smb_vfs_call_pwrite_done(struct tevent_req *subreq)
req, struct smb_vfs_call_pwrite_state);
int err;
- state->retval = state->recv_fn(subreq, &err);
+ state->retval = state->recv_fn(subreq, &err, &state->duration);
TALLOC_FREE(subreq);
if (state->retval == -1) {
tevent_req_error(req, err);
@@ -1716,7 +1719,7 @@ static void smb_vfs_call_pwrite_done(struct tevent_req *subreq)
tevent_req_done(req);
}
-ssize_t SMB_VFS_PWRITE_RECV(struct tevent_req *req, int *perrno)
+ssize_t SMB_VFS_PWRITE_RECV(struct tevent_req *req, int *perrno, uint64_t *pduration)
{
struct smb_vfs_call_pwrite_state *state = tevent_req_data(
req, struct smb_vfs_call_pwrite_state);
@@ -1726,6 +1729,7 @@ ssize_t SMB_VFS_PWRITE_RECV(struct tevent_req *req, int *perrno)
*perrno = err;
return -1;
}
+ *pduration = state->duration;
return state->retval;
}
@@ -1770,8 +1774,9 @@ int smb_vfs_call_fsync(struct vfs_handle_struct *handle,
}
struct smb_vfs_call_fsync_state {
- int (*recv_fn)(struct tevent_req *req, int *err);
+ int (*recv_fn)(struct tevent_req *req, int *err, uint64_t *pduration);
int retval;
+ uint64_t duration;
};
static void smb_vfs_call_fsync_done(struct tevent_req *subreq);
@@ -1808,7 +1813,7 @@ static void smb_vfs_call_fsync_done(struct tevent_req *subreq)
req, struct smb_vfs_call_fsync_state);
int err;
- state->retval = state->recv_fn(subreq, &err);
+ state->retval = state->recv_fn(subreq, &err, &state->duration);
TALLOC_FREE(subreq);
if (state->retval == -1) {
tevent_req_error(req, err);
@@ -1817,7 +1822,7 @@ static void smb_vfs_call_fsync_done(struct tevent_req *subreq)
tevent_req_done(req);
}
-int SMB_VFS_FSYNC_RECV(struct tevent_req *req, int *perrno)
+int SMB_VFS_FSYNC_RECV(struct tevent_req *req, int *perrno, uint64_t *pduration)
{
struct smb_vfs_call_fsync_state *state = tevent_req_data(
req, struct smb_vfs_call_fsync_state);
@@ -1827,6 +1832,7 @@ int SMB_VFS_FSYNC_RECV(struct tevent_req *req, int *perrno)
*perrno = err;
return -1;
}
+ *pduration = state->duration;
return state->retval;
}
--
2.5.0
From 1c17495c608f4a83f48e8132567f113dd0f5617e 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 7/7] 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 ab694de..fdfc1a0 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;
uint64_t duration;
@@ -697,7 +696,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,
@@ -726,14 +724,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 = state->duration * 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;
uint64_t duration;
@@ -808,7 +803,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,
@@ -837,14 +831,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 = state->duration * 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;
uint64_t duration;
@@ -977,7 +968,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);
@@ -1005,14 +995,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 = state->duration * 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