lib-fs: Track operation timing statistics if enable_timing setting is set.

diff --git a/src/lib-fs/Makefile.am b/src/lib-fs/Makefile.am
index 20c1bcaac43c6dd6703f0e5b37d4b4661c0a3b28..aed58c18f37e7dc91a33429f2bb7be6c7db97086 100644 (file)
--- a/src/lib-fs/Makefile.am
+++ b/src/lib-fs/Makefile.am
@@ -16,6 +16,7 @@ libfs_la_SOURCES = \
        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 @@ headers = \
        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 --git a/src/lib-fs/fs-api-private.h b/src/lib-fs/fs-api-private.h
index e27ae1e715e543bf9f3dacba9733b8aa5bc1ced7..94f590782db8cd7d61cff695b0c02373bd875997 100644 (file)
--- a/src/lib-fs/fs-api-private.h
+++ b/src/lib-fs/fs-api-private.h
@@ -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 fs_file {
        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_iter {
 
        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 @@ void fs_default_set_metadata(struct fs_file *file,
                             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 --git a/src/lib-fs/fs-api.c b/src/lib-fs/fs-api.c
index ee92bd7288e29ff29670279e2e25071b849f1ae6..7620e745198e228ac41f986cb3b40c76b3c9e812 100644 (file)
--- a/src/lib-fs/fs-api.c
+++ b/src/lib-fs/fs-api.c
@@ -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 @@ int fs_init(const char *driver, const char *args,
 {
        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 @@ int fs_init(const char *driver, const char *args,
        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 @@ void fs_unref(struct fs **_fs)
        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 @@ void fs_unref(struct fs **_fs)
        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 @@ void fs_set_metadata(struct fs_file *file, const char *key, const char *value)
        } 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 @@ int fs_get_metadata(struct fs_file *file,
            !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 @@ bool fs_prefetch(struct fs_file *file, uoff_t length)
        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 @@ ssize_t fs_read(struct fs_file *file, void *buf, size_t size)
        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 @@ struct istream *fs_read_stream(struct fs_file *file, size_t max_buffer_size)
        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 @@ struct istream *fs_read_stream(struct fs_file *file, size_t max_buffer_size)
        } 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 fs_write(struct fs_file *file, const void *data, size_t size)
        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 @@ static int fs_write_stream_finish_int(struct fs_file *file, bool success)
 {
        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 @@ int fs_exists(struct fs_file *file)
                        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 @@ int fs_stat(struct fs_file *file, struct stat *st_r)
            !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 @@ int fs_copy(struct fs_file *src, struct fs_file *dest)
        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 @@ int fs_copy_finish_async(struct fs_file *dest)
        T_BEGIN {
                ret = dest->fs->v.copy(NULL, 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;
 }
 
@@ -786,9 +862,12 @@ int fs_rename(struct fs_file *src, struct fs_file *dest)
        i_assert(src->fs == dest->fs);
 
        dest->fs->stats.rename_count++;
+       fs_file_timing_start(dest, FS_OP_RENAME);
        T_BEGIN {
                ret = src->fs->v.rename(src, dest);
        } T_END;
+       if (!(ret < 0 && errno == EAGAIN))
+               fs_file_timing_end(dest, FS_OP_RENAME);
        return ret;
 }
 
@@ -797,9 +876,12 @@ int fs_delete(struct fs_file *file)
        int ret;
 
        file->fs->stats.delete_count++;
+       fs_file_timing_start(file, FS_OP_DELETE);
        T_BEGIN {
                ret = file->fs->v.delete_file(file);
        } T_END;
+       if (!(ret < 0 && errno == EAGAIN))
+               fs_file_timing_end(file, FS_OP_DELETE);
        return ret;
 }
 
@@ -807,14 +889,20 @@ struct fs_iter *
 fs_iter_init(struct fs *fs, const char *path, enum fs_iter_flags flags)
 {
        struct fs_iter *iter;
+       struct timeval now = ioloop_timeval;
 
        i_assert((flags & FS_ITER_FLAG_OBJECTIDS) == 0 ||
                 (fs_get_properties(fs) & FS_PROPERTY_OBJECTIDS) != 0);
 
        fs->stats.iter_count++;
+       if (fs->set.enable_timing) {
+               if (gettimeofday(&now, NULL) < 0)
+                       i_fatal("gettimeofday() failed: %m");
+       }
        T_BEGIN {
                iter = fs->v.iter_init(fs, path, flags);
        } T_END;
+       iter->start_time = now;
        DLLIST_PREPEND(&fs->iters, iter);
        return iter;
 }
@@ -839,6 +927,15 @@ const char *fs_iter_next(struct fs_iter *iter)
        T_BEGIN {
                ret = iter->fs->v.iter_next(iter);
        } T_END;
+       if (iter->start_time.tv_sec != 0 &&
+           (ret != NULL || !fs_iter_have_more(iter))) {
+               /* first result returned - count this as the finish time, since
+                  we don't want to count the time caller spends on this
+                  iteration. */
+               fs_timing_end(iter->fs->stats.timings[FS_OP_ITER], &iter->start_time);
+               /* don't count this again */
+               iter->start_time.tv_sec = 0;
+       }
        return ret;
 }
 

diff --git a/src/lib-fs/fs-api.h b/src/lib-fs/fs-api.h
index d2fafba685c5c08357a5b2d782a3055eff6abd24..5460d787bfc149b7a5a056031da1125a1ace8a99 100644 (file)
--- a/src/lib-fs/fs-api.h
+++ b/src/lib-fs/fs-api.h
@@ -93,6 +93,23 @@ enum fs_iter_flags {
        FS_ITER_FLAG_NOCACHE    = 0x08
 };
 
+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_settings {
        /* Username and session ID are mainly used for debugging/logging,
           but may also be useful for other purposes if they exist (they
@@ -120,6 +137,8 @@ struct fs_settings {
 
        /* Enable debugging */
        bool debug;
+       /* Enable timing statistics */
+       bool enable_timing;
 };
 
 struct fs_stats {
@@ -153,6 +172,10 @@ struct fs_stats {
        unsigned int rename_count;
        /* Number of fs_iter_init() calls. */
        unsigned int iter_count;
+
+       /* Cumulative sum of usecs spent on calls - set only if
+          fs_settings.enable_timing=TRUE */
+       struct timing *timings[FS_OP_COUNT];
 };
 
 struct fs_metadata {

diff --git a/src/lib-fs/istream-fs-stats.c b/src/lib-fs/istream-fs-stats.c
new file mode 100644 (file)
index 0000000..a184d81
--- /dev/null
+++ b/src/lib-fs/istream-fs-stats.c
@@ -0,0 +1,47 @@
+/* Copyright (c) 2015 Dovecot authors, see the included COPYING file */
+
+#include "lib.h"
+#include "fs-api-private.h"
+#include "istream-private.h"
+#include "istream-fs-stats.h"
+
+struct fs_stats_istream {
+       struct istream_private istream;
+       struct fs_file *file;
+};
+
+static ssize_t
+i_stream_mail_read(struct istream_private *stream)
+{
+       struct fs_stats_istream *sstream = (struct fs_stats_istream *)stream;
+       ssize_t ret;
+
+       i_stream_seek(stream->parent, stream->parent_start_offset +
+                     stream->istream.v_offset);
+
+       ret = i_stream_read_copy_from_parent(&stream->istream);
+       if (ret > 0) {
+               /* count the first returned bytes as the finish time, since
+                  we don't want to count the time caller spends on processing
+                  this stream. (only the first fs_file_timing_end() call
+                  actually does anything - the others are ignored.) */
+               fs_file_timing_end(sstream->file, FS_OP_READ);
+       }
+       return ret;
+}
+
+struct istream *
+i_stream_create_fs_stats(struct istream *input, struct fs_file *file)
+{
+       struct fs_stats_istream *sstream;
+
+       sstream = i_new(struct fs_stats_istream, 1);
+       sstream->file = file;
+       sstream->istream.max_buffer_size = input->real_stream->max_buffer_size;
+       sstream->istream.stream_size_passthrough = TRUE;
+       sstream->istream.read = i_stream_mail_read;
+       sstream->istream.istream.blocking = input->blocking;
+       sstream->istream.istream.seekable = input->seekable;
+       return i_stream_create(&sstream->istream, input,
+                              i_stream_get_fd(input));
+}

diff --git a/src/lib-fs/istream-fs-stats.h b/src/lib-fs/istream-fs-stats.h
new file mode 100644 (file)
index 0000000..aca74b6
--- /dev/null
+++ b/src/lib-fs/istream-fs-stats.h
@@ -0,0 +1,9 @@
+#ifndef ISTREAM_FS_STATS_H
+#define ISTREAM_FS_STATS_H
+
+struct fs_file;
+
+struct istream *
+i_stream_create_fs_stats(struct istream *input, struct fs_file *file);
+
+#endif