[RFC/PATCH v4 2/3] add trace_performance facility to debug performance issues

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

Add trace_performance and trace_performance_since macros that print file
name, line number, time and an optional printf-formatted text to the file
specified in environment variable GIT_TRACE_PERFORMANCE.

Unless enabled via GIT_TRACE_PERFORMANCE, these macros have no noticeable
impact on performance, so that test code may be shipped in release builds.

MSVC: variadic macros (__VA_ARGS__) require VC++ 2005 or newer.

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>
---
 cache.h | 18 ++++++++++++++++++
 trace.c | 40 ++++++++++++++++++++++++++++++++++++++++
 2 files changed, 58 insertions(+)

diff --git a/cache.h b/cache.h
index 48fc616..cb856d9 100644
--- a/cache.h
+++ b/cache.h
@@ -1363,6 +1363,24 @@ __attribute__((format (printf, 2, 3)))
 extern void trace_printf_key(const char *key, const char *fmt, ...);
 extern void trace_strbuf(const char *key, const struct strbuf *buf);
 extern uint64_t getnanotime(void);
+__attribute__((format (printf, 4, 5)))
+extern uint64_t trace_performance_file_line(const char *file, int lineno,
+	uint64_t nanos, const char *fmt, ...);
+
+/*
+ * Prints specified time (in nanoseconds) if GIT_TRACE_PERFORMANCE is enabled.
+ * Returns current time in nanoseconds.
+ */
+#define trace_performance(nanos, ...) \
+	trace_performance_file_line(__FILE__, __LINE__, nanos, __VA_ARGS__)
+
+/*
+ * Prints time since 'start' if GIT_TRACE_PERFORMANCE is enabled.
+ * Returns current time in nanoseconds.
+ */
+#define trace_performance_since(start, ...) \
+	trace_performance_file_line(__FILE__, __LINE__, \
+		getnanotime() - (start), __VA_ARGS__)
 
 void packet_trace_identity(const char *prog);
 
diff --git a/trace.c b/trace.c
index 3d72084..1b1903b 100644
--- a/trace.c
+++ b/trace.c
@@ -269,3 +269,43 @@ inline uint64_t getnanotime(void)
 		return now;
 	}
 }
+
+static const char *GIT_TRACE_PERFORMANCE = "GIT_TRACE_PERFORMANCE";
+
+static inline int trace_want_performance(void)
+{
+	static int enabled = -1;
+	if (enabled < 0)
+		enabled = trace_want(GIT_TRACE_PERFORMANCE);
+	return enabled;
+}
+
+/*
+ * Prints performance data if environment variable GIT_TRACE_PERFORMANCE is
+ * set, otherwise a NOOP. Returns the current time in nanoseconds.
+ */
+__attribute__((format (printf, 4, 5)))
+uint64_t trace_performance_file_line(const char *file, int lineno,
+				     uint64_t nanos, const char *fmt, ...)
+{
+	struct strbuf buf = STRBUF_INIT;
+	va_list args;
+
+	if (!trace_want_performance())
+		return 0;
+
+	strbuf_addf(&buf, "performance: at %s:%i, time: %.9f s", file, lineno,
+		    (double) nanos / 1000000000);
+
+	if (fmt && *fmt) {
+		strbuf_addstr(&buf, ": ");
+		va_start(args, fmt);
+		strbuf_vaddf(&buf, fmt, args);
+		va_end(args);
+	}
+	strbuf_addch(&buf, '\n');
+
+	trace_strbuf(GIT_TRACE_PERFORMANCE, &buf);
+	strbuf_release(&buf);
+	return getnanotime();
+}
-- 
1.9.2.msysgit.0.493.g47a82c3

-- 
-- 
*** 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.