[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  |   65 +++++++++++++++++++++++++++++++++++++++++++++++++++++++
 4 files changed, 124 insertions(+)


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 23420c23be240c..6255d960bd802f 100644
--- a/misc/fuse2fs.c
+++ b/misc/fuse2fs.c
@@ -165,6 +165,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
@@ -240,6 +246,13 @@ struct fuse2fs {
 	unsigned int next_generation;
 	unsigned long long cache_size;
 	char *lockfile;
+#ifdef HAVE_CLOCK_MONOTONIC
+	struct timespec lock_start_time;
+	struct timespec op_start_time;
+
+	/* options set by fuse_opt_parse must be of type int */
+	int timing;
+#endif
 };
 
 #define FUSE2FS_CHECK_HANDLE(ff, fh) \
@@ -456,15 +469,64 @@ fuse2fs_set_handle(struct fuse_file_info *fp, struct fuse2fs_file_handle *fh)
 	fp->fh = (uintptr_t)fh;
 }
 
+#ifdef HAVE_CLOCK_MONOTONIC
 static inline ext2_filsys fuse2fs_start(struct fuse2fs *ff)
 {
+	struct timespec lock_time;
+	int ret;
+
+	if (ff->timing)
+		clock_gettime(CLOCK_MONOTONIC, &lock_time);
+
 	pthread_mutex_lock(&ff->bfl);
+	if (ff->timing) {
+		ret = clock_gettime(CLOCK_MONOTONIC, &ff->op_start_time);
+		if (ret)
+			ff->timing = 0;
+		ff->lock_start_time = lock_time;
+	}
 	return ff->fs;
 }
 
+static inline double ms_from_timespec(const struct timespec *ts)
+{
+	return ((double)ts->tv_sec * 1000) + ((double)ts->tv_nsec / 1000000);
+}
+
+static inline void fuse2fs_finish_timing(struct fuse2fs *ff, const char *func)
+{
+	struct timespec now;
+	double lockf, startf, nowf;
+	int ret;
+
+	if (!ff->timing)
+		return;
+
+	ret = clock_gettime(CLOCK_MONOTONIC, &now);
+	if (ret) {
+		ff->timing = 0;
+		return;
+	}
+
+	lockf = ms_from_timespec(&ff->lock_start_time);
+	startf = ms_from_timespec(&ff->op_start_time);
+	nowf = ms_from_timespec(&now);
+	timing_printf(ff, "%s: lock=%.2fms elapsed=%.2fms\n", func,
+		      startf - lockf, nowf - startf);
+}
+#else
+static inline ext2_filsys fuse2fs_start(struct fuse2fs *ff)
+{
+	pthread_mutex_lock(&ff->bfl);
+	return ff->fs;
+}
+# define fuse2fs_finish_timing(...)	((void)0)
+#endif
+
 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);
@@ -4687,6 +4749,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),