[PATCH 9/9] fuse2fs: collect runtime of various operations

["Darrick J. Wong" <djwong@kernel.org>]

From: Darrick J. Wong <djwong@kernel.org>

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

Signed-off-by: "Darrick J. Wong" <djwong@kernel.org>
---
 configure       |   37 +++++++++++++++++++++++++++++++++++++
 configure.ac    |   19 +++++++++++++++++++
 lib/config.h.in |    3 +++
 misc/fuse2fs.c  |   43 ++++++++++++++++++++++++++++++++++++++++++-
 4 files changed, 101 insertions(+), 1 deletion(-)


diff --git a/configure b/configure
index 2ed61db3602dc9..ba2e5380f6d20b 100755
--- a/configure
+++ b/configure
@@ -14725,6 +14725,43 @@ then
 printf "%s\n" "#define FUSE_USE_VERSION $FUSE_USE_VERSION" >>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 $as_nop
+  { printf "%s\n" "$as_me:${as_lineno-$LINENO}: result: no" >&5
+printf "%s\n" "no" >&6; }
+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 bdd5f1f69d267d..051161c5848072 100644
--- a/configure.ac
+++ b/configure.ac
@@ -1452,6 +1452,25 @@ then
 	AC_DEFINE_UNQUOTED(FUSE_USE_VERSION, $FUSE_USE_VERSION,
 		[Define to the version of FUSE to use])
 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 480717abd9b4be..364d6e865b7115 100644
--- a/lib/config.h.in
+++ b/lib/config.h.in
@@ -683,4 +683,7 @@
 /* Define for large files, on AIX-style hosts. */
 #undef _LARGE_FILES
 
+/* 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 9d50ebb6d08f8a..9db0b17af27438 100644
--- 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);
@@ -4959,6 +4997,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),