fuse2fs: collect runtime of various operations

Collect the run time of various operations so that we can do some simple
profiling.

Signed-off-by: "Darrick J. Wong" <djwong@kernel.org>

diff --git a/configure b/configure
index d47c94890ce24ddd119ea34c3d877000fce6b964..a70ed0f810d720864be3d2cfae3e35310db180da 100755 (executable)
--- a/configure
+++ b/configure
@@ -15201,6 +15201,44 @@ printf "%s\n" "#define HAVE_FUSE_CACHE_READDIR 1" >>confdefs.h
 
 fi
 
+{ printf "%s\n" "$as_me:${as_lineno-$LINENO}: checking for CLOCK_MONOTONIC" >&5
+printf %s "checking for CLOCK_MONOTONIC... " >&6; }
+cat confdefs.h - <<_ACEOF >conftest.$ac_ext
+/* end confdefs.h.  */
+
+#define _GNU_SOURCE
+#include <time.h>
+
+int
+main (void)
+{
+
+struct timespec nuts;
+clock_gettime(CLOCK_MONOTONIC, &nuts);
+
+  ;
+  return 0;
+}
+
+_ACEOF
+if ac_fn_c_try_link "$LINENO"
+then :
+  have_clock_monotonic=yes
+   { printf "%s\n" "$as_me:${as_lineno-$LINENO}: result: yes" >&5
+printf "%s\n" "yes" >&6; }
+else case e in #(
+  e) { printf "%s\n" "$as_me:${as_lineno-$LINENO}: result: no" >&5
+printf "%s\n" "no" >&6; } ;;
+esac
+fi
+rm -f core conftest.err conftest.$ac_objext conftest.beam \
+    conftest$ac_exeext conftest.$ac_ext
+if test "$have_clock_monotonic" = yes; then
+
+printf "%s\n" "#define HAVE_CLOCK_MONOTONIC 1" >>confdefs.h
+
+fi
+
 { printf "%s\n" "$as_me:${as_lineno-$LINENO}: checking for optreset" >&5
 printf %s "checking for optreset... " >&6; }
 if test ${ac_cv_have_optreset+y}

diff --git a/configure.ac b/configure.ac
index 135eedce4641d4e56299f8d2b735310de72c7dbc..4227ab9f448911bd5d01efe36d43455fd8fa04d5 100644 (file)
--- a/configure.ac
+++ b/configure.ac
@@ -1481,6 +1481,25 @@ then
                  [Define to 1 if fuse supports cache_readdir])
 fi
 
+dnl
+dnl see if CLOCK_MONOTONIC exists
+dnl
+AC_MSG_CHECKING(for CLOCK_MONOTONIC)
+AC_LINK_IFELSE(
+[      AC_LANG_PROGRAM([[
+#define _GNU_SOURCE
+#include <time.h>
+       ]], [[
+struct timespec nuts;
+clock_gettime(CLOCK_MONOTONIC, &nuts);
+       ]])
+], have_clock_monotonic=yes
+   AC_MSG_RESULT(yes),
+   AC_MSG_RESULT(no))
+if test "$have_clock_monotonic" = yes; then
+  AC_DEFINE(HAVE_CLOCK_MONOTONIC, 1, [Define to 1 if CLOCK_MONOTONIC is present])
+fi
+
 dnl
 dnl See if optreset exists
 dnl

diff --git a/lib/config.h.in b/lib/config.h.in
index 6616b7750b81a233340f177ca7ae50750bf5d619..9b21b9082cdb728c8af20905033b31428097440f 100644 (file)
--- a/lib/config.h.in
+++ b/lib/config.h.in
@@ -696,4 +696,7 @@
 /* Define to 1 on platforms where this makes time_t a 64-bit type. */
 #undef __MINGW_USE_VC2005_COMPAT
 
+/* Define to 1 if CLOCK_MONOTONIC is present */
+#undef HAVE_CLOCK_MONOTONIC
+
 #include <dirpaths.h>

diff --git a/misc/fuse2fs.c b/misc/fuse2fs.c
index ae3cf49ad5bdf3a3608f87e003d3e9ea31c54af9..2f0dc907c60b4c570967bf23beb87baa2e62f19e 100644 (file)
--- a/misc/fuse2fs.c
+++ b/misc/fuse2fs.c
@@ -166,6 +166,12 @@ static inline uint64_t round_down(uint64_t b, unsigned int align)
                fflush(stderr); \
        } while (0)
 
+#define timing_printf(fuse2fs, format, ...) \
+       while ((fuse2fs)->timing) { \
+               printf("FUSE2FS (%s): " format, (fuse2fs)->shortdev, ##__VA_ARGS__); \
+               break; \
+       }
+
 #if FUSE_VERSION >= FUSE_MAKE_VERSION(2, 8)
 # ifdef _IOR
 #  ifdef _IOW
@@ -246,6 +252,13 @@ struct fuse2fs {
        struct bthread *mmp_thread;
        unsigned int mmp_update_interval;
 #endif
+#ifdef HAVE_CLOCK_MONOTONIC
+       double lock_start_time;
+       double op_start_time;
+
+       /* options set by fuse_opt_parse must be of type int */
+       int timing;
+#endif
 };
 
 #define FUSE2FS_CHECK_HANDLE(ff, fh) \
@@ -494,13 +507,38 @@ static inline errcode_t fuse2fs_write_inode(ext2_filsys fs, ext2_ino_t ino,
 
 static inline ext2_filsys fuse2fs_start(struct fuse2fs *ff)
 {
-       pthread_mutex_lock(&ff->bfl);
+       if (ff->timing) {
+               double lock_time = gettime_monotonic();
+
+               pthread_mutex_lock(&ff->bfl);
+
+               ff->op_start_time = gettime_monotonic();
+               ff->lock_start_time = lock_time;
+       } else {
+               pthread_mutex_lock(&ff->bfl);
+       }
+
        return ff->fs;
 }
 
+static inline void fuse2fs_finish_timing(struct fuse2fs *ff, const char *func)
+{
+       double now;
+
+       if (!ff->timing)
+               return;
+
+       now = gettime_monotonic();
+
+       timing_printf(ff, "%s: lock=%.2fms elapsed=%.2fms\n", func,
+                     (ff->op_start_time - ff->lock_start_time) * 1000.0,
+                     (now - ff->op_start_time) * 1000.0);
+}
+
 static inline void __fuse2fs_finish(struct fuse2fs *ff, int ret,
                                    const char *func)
 {
+       fuse2fs_finish_timing(ff, func);
        if (ret)
                dbg_printf(ff, "%s: libfuse ret=%d\n", func, ret);
        pthread_mutex_unlock(&ff->bfl);
@@ -4966,6 +5004,9 @@ static struct fuse_opt fuse2fs_opts[] = {
        FUSE2FS_OPT("acl",              acl,                    1),
        FUSE2FS_OPT("noacl",            acl,                    0),
        FUSE2FS_OPT("lockfile=%s",      lockfile,               0),
+#ifdef HAVE_CLOCK_MONOTONIC
+       FUSE2FS_OPT("timing",           timing,                 1),
+#endif
 
        FUSE_OPT_KEY("user_xattr",      FUSE2FS_IGNORED),
        FUSE_OPT_KEY("noblock_validity", FUSE2FS_IGNORED),