[PATCH v5 10/11] trace: add trace_performance facility to debug performance issues

[Karsten Blees <karsten.blees@gmail.com>]

Add trace_performance and trace_performance_since macros that print a
duration and an optional printf-formatted text to the file specified in
environment variable GIT_TRACE_PERFORMANCE.

These macros, in conjunction with getnanotime(), are intended to simplify
performance measurements from within the application (i.e. profiling via
manual instrumentation, rather than using an external profiling tool).

Unless enabled via GIT_TRACE_PERFORMANCE, these macros have no noticeable
impact on performance, so that test code for well known time killers may
be shipped in release builds. Alternatively, a developer could provide an
additional performance patch (not meant for master) that allows reviewers
to reproduce performance tests more easily, e.g. on other platforms or
using their own repositories.

Usage examples:

Simple use case (measure one code section):

  uint64_t start = getnanotime();
  /* code section to measure */
  trace_performance_since(start, "foobar");

Medium use case (measure consecutive code sections):

  uint64_t start = getnanotime();
  /* first code section to measure */
  start = trace_performance_since(start, "first foobar");
  /* second code section to measure */
  trace_performance_since(start, "second foobar");

Complex use case (measure repetitive code sections):

  uint64_t t = 0;
  for (;;) {
    /* ignore */
    t -= getnanotime();
    /* code section to measure */
    t += getnanotime();
    /* ignore */
  }
  trace_performance(t, "frotz");

Signed-off-by: Karsten Blees <blees@dcon.de>
---
 trace.c | 49 +++++++++++++++++++++++++++++++++++++++++++++++++
 trace.h | 24 ++++++++++++++++++++++++
 2 files changed, 73 insertions(+)

diff --git a/trace.c b/trace.c
index 4bd52f2..0551509 100644
--- a/trace.c
+++ b/trace.c
@@ -153,6 +153,27 @@ void trace_strbuf_fl(const char *file, int line, const char *key,
 	print_trace_line(key, &buf);
 }
 
+static const char *GIT_TRACE_PERFORMANCE = "GIT_TRACE_PERFORMANCE";
+
+static void trace_performance_vfl(const char *file, int line,
+				      uint64_t nanos, const char *format,
+				      va_list ap)
+{
+	struct strbuf buf = STRBUF_INIT;
+
+	if (!prepare_trace_line(file, line, GIT_TRACE_PERFORMANCE, &buf))
+		return;
+
+	strbuf_addf(&buf, "performance: %.9f s", (double) nanos / 1000000000);
+
+	if (format && *format) {
+		strbuf_addstr(&buf, ": ");
+		strbuf_vaddf(&buf, format, ap);
+	}
+
+	print_trace_line(GIT_TRACE_PERFORMANCE, &buf);
+}
+
 #ifndef HAVE_VARIADIC_MACROS
 
 void trace_printf(const char *format, ...)
@@ -184,6 +205,24 @@ void trace_strbuf(const char *key, const struct strbuf *data)
 	trace_strbuf_fl(NULL, 0, key, data);
 }
 
+uint64_t trace_performance(uint64_t nanos, const char *format, ...)
+{
+	va_list ap;
+	va_start(ap, format);
+	trace_performance_vfl(NULL, 0, nanos, format, ap);
+	va_end(ap);
+	return getnanotime();
+}
+
+uint64_t trace_performance_since(uint64_t start, const char *format, ...)
+{
+	va_list ap;
+	va_start(ap, format);
+	trace_performance_vfl(NULL, 0, getnanotime() - start, format, ap);
+	va_end(ap);
+	return getnanotime();
+}
+
 #else
 
 void trace_printf_key_fl(const char *file, int line, const char *key,
@@ -204,6 +243,16 @@ void trace_argv_printf_fl(const char *file, int line, const char **argv,
 	va_end(ap);
 }
 
+uint64_t trace_performance_fl(const char *file, int line, uint64_t nanos,
+			      const char *format, ...)
+{
+	va_list ap;
+	va_start(ap, format);
+	trace_performance_vfl(file, line, nanos, format, ap);
+	va_end(ap);
+	return getnanotime();
+}
+
 #endif /* HAVE_VARIADIC_MACROS */
 
 
diff --git a/trace.h b/trace.h
index c4964aa..9687563 100644
--- a/trace.h
+++ b/trace.h
@@ -21,6 +21,20 @@ extern void trace_argv_printf(const char **argv, const char *format, ...);
 
 extern void trace_strbuf(const char *key, const struct strbuf *data);
 
+/*
+ * Prints specified time (in nanoseconds) if GIT_TRACE_PERFORMANCE is enabled.
+ * Returns current time in nanoseconds.
+ */
+__attribute__((format (printf, 2, 3)))
+extern uint64_t trace_performance(uint64_t nanos, const char *format, ...);
+
+/*
+ * Prints time since 'start' if GIT_TRACE_PERFORMANCE is enabled.
+ * Returns current time in nanoseconds.
+ */
+__attribute__((format (printf, 2, 3)))
+extern uint64_t trace_performance_since(uint64_t start, const char *format, ...);
+
 #else
 
 /*
@@ -56,6 +70,13 @@ extern void trace_strbuf(const char *key, const struct strbuf *data);
 #define trace_strbuf(key, data) \
 	trace_strbuf_fl(__FILE__, __LINE__, key, data)
 
+#define trace_performance(nanos, ...) \
+	trace_performance_fl(__FILE__, __LINE__, nanos, __VA_ARGS__)
+
+#define trace_performance_since(start, ...) \
+	trace_performance_fl(__FILE__, __LINE__, getnanotime() - (start), \
+			     __VA_ARGS__)
+
 /* backend functions, use non-*fl macros instead */
 __attribute__((format (printf, 4, 5)))
 extern void trace_printf_key_fl(const char *file, int line, const char *key,
@@ -65,6 +86,9 @@ extern void trace_argv_printf_fl(const char *file, int line, const char **argv,
 				 const char *format, ...);
 extern void trace_strbuf_fl(const char *file, int line, const char *key,
 			    const struct strbuf *data);
+__attribute__((format (printf, 4, 5)))
+extern uint64_t trace_performance_fl(const char *file, int line,
+				     uint64_t nanos, const char *fmt, ...);
 
 #endif /* HAVE_VARIADIC_MACROS */
 
-- 
1.9.2.msysgit.0.501.gaeecf09

-- 
-- 
*** Please reply-to-all at all times ***
*** (do not pretend to know who is subscribed and who is not) ***
*** Please avoid top-posting. ***
The msysGit Wiki is here: https://github.com/msysgit/msysgit/wiki - Github accounts are free.

You received this message because you are subscribed to the Google
Groups "msysGit" group.
To post to this group, send email to msysgit@googlegroups.com
To unsubscribe from this group, send email to
msysgit+unsubscribe@googlegroups.com
For more options, and view previous threads, visit this group at
http://groups.google.com/group/msysgit?hl=en_US?hl=en

--- 
You received this message because you are subscribed to the Google Groups "msysGit" group.
To unsubscribe from this group and stop receiving emails from it, send an email to msysgit+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.