Skip to content

Commit

Permalink
trace: add trace_performance facility to debug performance issues
Browse files Browse the repository at this point in the history
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");

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>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
  • Loading branch information
Karsten Blees authored and Junio C Hamano committed Jul 14, 2014
1 parent 148d677 commit 09b2c1c
Show file tree
Hide file tree
Showing 2 changed files with 65 additions and 0 deletions.
47 changes: 47 additions & 0 deletions trace.c
Original file line number Diff line number Diff line change
Expand Up @@ -169,6 +169,27 @@ void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
print_trace_line(key, &buf);
}

static struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);

static void trace_performance_vprintf_fl(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, &trace_perf_key, &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(&trace_perf_key, &buf);
}

#ifndef HAVE_VARIADIC_MACROS

void trace_printf(const char *format, ...)
Expand Down Expand Up @@ -200,6 +221,23 @@ void trace_strbuf(const char *key, const struct strbuf *data)
trace_strbuf_fl(NULL, 0, key, data);
}

void trace_performance(uint64_t nanos, const char *format, ...)
{
va_list ap;
va_start(ap, format);
trace_performance_vprintf_fl(NULL, 0, nanos, format, ap);
va_end(ap);
}

void trace_performance_since(uint64_t start, const char *format, ...)
{
va_list ap;
va_start(ap, format);
trace_performance_vprintf_fl(NULL, 0, getnanotime() - start,
format, ap);
va_end(ap);
}

#else

void trace_printf_key_fl(const char *file, int line, struct trace_key *key,
Expand All @@ -220,6 +258,15 @@ void trace_argv_printf_fl(const char *file, int line, const char **argv,
va_end(ap);
}

void trace_performance_fl(const char *file, int line, uint64_t nanos,
const char *format, ...)
{
va_list ap;
va_start(ap, format);
trace_performance_vprintf_fl(file, line, nanos, format, ap);
va_end(ap);
}

#endif /* HAVE_VARIADIC_MACROS */


Expand Down
18 changes: 18 additions & 0 deletions trace.h
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,14 @@ extern void trace_argv_printf(const char **argv, const char *format, ...);

extern void trace_strbuf(struct trace_key *key, const struct strbuf *data);

/* Prints elapsed time (in nanoseconds) if GIT_TRACE_PERFORMANCE is enabled. */
__attribute__((format (printf, 2, 3)))
extern void trace_performance(uint64_t nanos, const char *format, ...);

/* Prints elapsed time since 'start' if GIT_TRACE_PERFORMANCE is enabled. */
__attribute__((format (printf, 2, 3)))
extern void trace_performance_since(uint64_t start, const char *format, ...);

#else

/*
Expand Down Expand Up @@ -79,6 +87,13 @@ extern void trace_strbuf(struct trace_key *key, const struct strbuf *data);
#define trace_strbuf(key, data) \
trace_strbuf_fl(TRACE_CONTEXT, __LINE__, key, data)

#define trace_performance(nanos, ...) \
trace_performance_fl(TRACE_CONTEXT, __LINE__, nanos, __VA_ARGS__)

#define trace_performance_since(start, ...) \
trace_performance_fl(TRACE_CONTEXT, __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, struct trace_key *key,
Expand All @@ -88,6 +103,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, struct trace_key *key,
const struct strbuf *data);
__attribute__((format (printf, 4, 5)))
extern void trace_performance_fl(const char *file, int line,
uint64_t nanos, const char *fmt, ...);

#endif /* HAVE_VARIADIC_MACROS */

Expand Down

0 comments on commit 09b2c1c

Please sign in to comment.