dovecot-2.2: lib-fs: Track operation timing statistics if enable...
dovecot at dovecot.org
dovecot at dovecot.org
Tue Sep 15 20:03:06 UTC 2015
details: http://hg.dovecot.org/dovecot-2.2/rev/d8c27e220815
changeset: 19148:d8c27e220815
user: Timo Sirainen <tss at iki.fi>
date: Wed Sep 16 05:01:40 2015 +0900
description:
lib-fs: Track operation timing statistics if enable_timing setting is set.
diffstat:
src/lib-fs/Makefile.am | 2 +
src/lib-fs/fs-api-private.h | 22 ++------
src/lib-fs/fs-api.c | 103 ++++++++++++++++++++++++++++++++++++++++-
src/lib-fs/fs-api.h | 23 +++++++++
src/lib-fs/istream-fs-stats.c | 47 +++++++++++++++++++
src/lib-fs/istream-fs-stats.h | 9 +++
6 files changed, 186 insertions(+), 20 deletions(-)
diffs (truncated from 484 to 300 lines):
diff -r 9add45266550 -r d8c27e220815 src/lib-fs/Makefile.am
--- a/src/lib-fs/Makefile.am Wed Sep 16 04:44:37 2015 +0900
+++ b/src/lib-fs/Makefile.am Wed Sep 16 05:01:40 2015 +0900
@@ -16,6 +16,7 @@
fs-sis-common.c \
fs-sis-queue.c \
istream-fs-file.c \
+ istream-fs-stats.c \
istream-metawrap.c \
ostream-metawrap.c \
ostream-cmp.c
@@ -25,6 +26,7 @@
fs-api-private.h \
fs-sis-common.h \
istream-fs-file.h \
+ istream-fs-stats.h \
istream-metawrap.h \
ostream-metawrap.h \
ostream-cmp.h
diff -r 9add45266550 -r d8c27e220815 src/lib-fs/fs-api-private.h
--- a/src/lib-fs/fs-api-private.h Wed Sep 16 04:44:37 2015 +0900
+++ b/src/lib-fs/fs-api-private.h Wed Sep 16 05:01:40 2015 +0900
@@ -4,23 +4,6 @@
#include "fs-api.h"
#include "module-context.h"
-enum fs_op {
- FS_OP_WAIT,
- FS_OP_METADATA,
- FS_OP_PREFETCH,
- FS_OP_READ,
- FS_OP_WRITE,
- FS_OP_LOCK,
- FS_OP_EXISTS,
- FS_OP_STAT,
- FS_OP_COPY,
- FS_OP_RENAME,
- FS_OP_DELETE,
- FS_OP_ITER,
-
- FS_OP_COUNT
-};
-
struct fs_api_module_register {
unsigned int id;
};
@@ -127,6 +110,8 @@
struct istream *copy_input;
struct ostream *copy_output;
+ struct timeval timing_start[FS_OP_COUNT];
+
unsigned int write_pending:1;
unsigned int metadata_changed:1;
@@ -145,6 +130,7 @@
struct fs *fs;
enum fs_iter_flags flags;
+ struct timeval start_time;
bool async_have_more;
fs_file_async_callback_t *async_callback;
@@ -172,4 +158,6 @@
const char *key, const char *value);
int fs_default_copy(struct fs_file *src, struct fs_file *dest);
+void fs_file_timing_end(struct fs_file *file, enum fs_op op);
+
#endif
diff -r 9add45266550 -r d8c27e220815 src/lib-fs/fs-api.c
--- a/src/lib-fs/fs-api.c Wed Sep 16 04:44:37 2015 +0900
+++ b/src/lib-fs/fs-api.c Wed Sep 16 05:01:40 2015 +0900
@@ -9,6 +9,9 @@
#include "istream.h"
#include "istream-seekable.h"
#include "ostream.h"
+#include "timing.h"
+#include "time-util.h"
+#include "istream-fs-stats.h"
#include "fs-api-private.h"
struct fs_api_module_register fs_api_module_register = { 0 };
@@ -128,6 +131,7 @@
{
const struct fs *fs_class;
const char *temp_file_prefix;
+ unsigned int i;
fs_class = fs_class_find(driver);
if (fs_class == NULL) {
@@ -143,6 +147,9 @@
if (fs_alloc(fs_class, args, set, fs_r, error_r) < 0)
return -1;
+ for (i = 0; i < FS_OP_COUNT; i++)
+ (*fs_r)->stats.timings[i] = timing_init();
+
temp_file_prefix = set->temp_file_prefix != NULL ?
set->temp_file_prefix : ".temp.dovecot";
(*fs_r)->temp_path_prefix = i_strconcat(set->temp_dir, "/",
@@ -167,6 +174,7 @@
struct fs *fs = *_fs;
string_t *last_error = fs->last_error;
struct array module_contexts_arr = fs->module_contexts.arr;
+ unsigned int i;
i_assert(fs->refcount > 0);
@@ -187,6 +195,8 @@
T_BEGIN {
fs->v.deinit(fs);
} T_END;
+ for (i = 0; i < FS_OP_COUNT; i++)
+ timing_deinit(&fs->stats.timings[i]);
array_free_i(&module_contexts_arr);
str_free(&last_error);
}
@@ -296,6 +306,40 @@
} T_END;
}
+static void fs_file_timing_start(struct fs_file *file, enum fs_op op)
+{
+ if (!file->fs->set.enable_timing)
+ return;
+ if (file->timing_start[op].tv_sec == 0) {
+ if (gettimeofday(&file->timing_start[op], NULL) < 0)
+ i_fatal("gettimeofday() failed: %m");
+ }
+}
+
+static void
+fs_timing_end(struct timing *timing, const struct timeval *start_tv)
+{
+ struct timeval now;
+ long long diff;
+
+ if (gettimeofday(&now, NULL) < 0)
+ i_fatal("gettimeofday() failed: %m");
+
+ diff = timeval_diff_usecs(&now, start_tv);
+ if (diff > 0)
+ timing_add_usecs(timing, diff);
+}
+
+void fs_file_timing_end(struct fs_file *file, enum fs_op op)
+{
+ if (!file->fs->set.enable_timing || file->timing_start[op].tv_sec == 0)
+ return;
+
+ fs_timing_end(file->fs->stats.timings[op], &file->timing_start[op]);
+ /* don't count this again */
+ file->timing_start[op].tv_sec = 0;
+}
+
int fs_get_metadata(struct fs_file *file,
const ARRAY_TYPE(fs_metadata) **metadata_r)
{
@@ -309,10 +353,13 @@
!file->lookup_metadata_counted) {
file->lookup_metadata_counted = TRUE;
file->fs->stats.lookup_metadata_count++;
+ fs_file_timing_start(file, FS_OP_METADATA);
}
T_BEGIN {
ret = file->fs->v.get_metadata(file, metadata_r);
} T_END;
+ if (!(ret < 0 && errno == EAGAIN))
+ fs_file_timing_end(file, FS_OP_METADATA);
return ret;
}
@@ -380,10 +427,12 @@
if (!file->read_or_prefetch_counted) {
file->read_or_prefetch_counted = TRUE;
file->fs->stats.prefetch_count++;
+ fs_file_timing_start(file, FS_OP_PREFETCH);
}
T_BEGIN {
ret = file->fs->v.prefetch(file, length);
} T_END;
+ fs_file_timing_end(file, FS_OP_PREFETCH);
return ret;
}
@@ -422,12 +471,15 @@
if (!file->read_or_prefetch_counted) {
file->read_or_prefetch_counted = TRUE;
file->fs->stats.read_count++;
+ fs_file_timing_start(file, FS_OP_READ);
}
if (file->fs->v.read != NULL) {
T_BEGIN {
ret = file->fs->v.read(file, buf, size);
} T_END;
+ if (!(ret < 0 && errno == EAGAIN))
+ fs_file_timing_end(file, FS_OP_READ);
return ret;
}
@@ -447,6 +499,7 @@
if (!file->read_or_prefetch_counted) {
file->read_or_prefetch_counted = TRUE;
file->fs->stats.read_count++;
+ fs_file_timing_start(file, FS_OP_READ);
}
if (file->seekable_input != NULL) {
@@ -459,8 +512,15 @@
} T_END;
if (input->stream_errno != 0) {
/* read failed already */
+ fs_file_timing_end(file, FS_OP_READ);
return input;
}
+ if (file->fs->set.enable_timing) {
+ struct istream *input2 = i_stream_create_fs_stats(input, file);
+
+ i_stream_unref(&input);
+ input = input2;
+ }
if ((file->flags & FS_OPEN_FLAG_SEEKABLE) != 0)
want_seekable = TRUE;
@@ -532,11 +592,14 @@
int ret;
if (file->fs->v.write != NULL) {
+ fs_file_timing_start(file, FS_OP_WRITE);
T_BEGIN {
ret = file->fs->v.write(file, data, size);
} T_END;
- if (!(ret < 0 && errno == EAGAIN))
+ if (!(ret < 0 && errno == EAGAIN)) {
file->fs->stats.write_count++;
+ fs_file_timing_end(file, FS_OP_WRITE);
+ }
return ret;
}
@@ -560,10 +623,12 @@
{
int ret;
+ fs_file_timing_start(file, FS_OP_WRITE);
T_BEGIN {
ret = file->fs->v.write_stream_finish(file, success);
} T_END;
if (ret != 0) {
+ fs_file_timing_end(file, FS_OP_WRITE);
file->metadata_changed = FALSE;
} else {
/* write didn't finish yet. this shouldn't happen if we
@@ -681,9 +746,12 @@
return errno == ENOENT ? 0 : -1;
}
file->fs->stats.exists_count++;
+ fs_file_timing_start(file, FS_OP_EXISTS);
T_BEGIN {
ret = file->fs->v.exists(file);
} T_END;
+ if (!(ret < 0 && errno == EAGAIN))
+ fs_file_timing_end(file, FS_OP_EXISTS);
return ret;
}
@@ -695,10 +763,13 @@
!file->lookup_metadata_counted && !file->stat_counted) {
file->stat_counted = TRUE;
file->fs->stats.stat_count++;
+ fs_file_timing_start(file, FS_OP_STAT);
}
T_BEGIN {
ret = file->fs->v.stat(file, st_r);
} T_END;
+ if (!(ret < 0 && errno == EAGAIN))
+ fs_file_timing_end(file, FS_OP_STAT);
return ret;
}
@@ -759,11 +830,14 @@
i_assert(src->fs == dest->fs);
dest->fs->stats.copy_count++;
+ fs_file_timing_start(dest, FS_OP_COPY);
T_BEGIN {
ret = src->fs->v.copy(src, dest);
} T_END;
- if (!(ret < 0 && errno == EAGAIN))
+ if (!(ret < 0 && errno == EAGAIN)) {
+ fs_file_timing_end(dest, FS_OP_COPY);
dest->metadata_changed = FALSE;
+ }
return ret;
}
@@ -774,8 +848,10 @@
T_BEGIN {
More information about the dovecot-cvs
mailing list