From 4a3b0b25f182727876bfb01748b2d00dd43f9ad7 Mon Sep 17 00:00:00 2001 From: Karsten Blees Date: Wed, 11 Jun 2014 09:57:23 +0200 Subject: trace: consistently name the format parameter The format parameter to trace_printf functions is sometimes abbreviated 'fmt'. Rename to 'format' everywhere (consistent with POSIX' printf specification). Signed-off-by: Karsten Blees Signed-off-by: Junio C Hamano --- trace.c | 22 +++++++++++----------- 1 file changed, 11 insertions(+), 11 deletions(-) (limited to 'trace.c') diff --git a/trace.c b/trace.c index 08180a90bc..37a7fa9640 100644 --- a/trace.c +++ b/trace.c @@ -62,7 +62,7 @@ static int get_trace_fd(const char *key, int *need_close) static const char err_msg[] = "Could not trace into fd given by " "GIT_TRACE environment variable"; -static void trace_vprintf(const char *key, const char *fmt, va_list ap) +static void trace_vprintf(const char *key, const char *format, va_list ap) { struct strbuf buf = STRBUF_INIT; @@ -70,25 +70,25 @@ static void trace_vprintf(const char *key, const char *fmt, va_list ap) return; set_try_to_free_routine(NULL); /* is never reset */ - strbuf_vaddf(&buf, fmt, ap); + strbuf_vaddf(&buf, format, ap); trace_strbuf(key, &buf); strbuf_release(&buf); } __attribute__((format (printf, 2, 3))) -void trace_printf_key(const char *key, const char *fmt, ...) +void trace_printf_key(const char *key, const char *format, ...) { va_list ap; - va_start(ap, fmt); - trace_vprintf(key, fmt, ap); + va_start(ap, format); + trace_vprintf(key, format, ap); va_end(ap); } -void trace_printf(const char *fmt, ...) +void trace_printf(const char *format, ...) { va_list ap; - va_start(ap, fmt); - trace_vprintf("GIT_TRACE", fmt, ap); + va_start(ap, format); + trace_vprintf("GIT_TRACE", format, ap); va_end(ap); } @@ -106,7 +106,7 @@ void trace_strbuf(const char *key, const struct strbuf *buf) close(fd); } -void trace_argv_printf(const char **argv, const char *fmt, ...) +void trace_argv_printf(const char **argv, const char *format, ...) { struct strbuf buf = STRBUF_INIT; va_list ap; @@ -117,8 +117,8 @@ void trace_argv_printf(const char **argv, const char *fmt, ...) return; set_try_to_free_routine(NULL); /* is never reset */ - va_start(ap, fmt); - strbuf_vaddf(&buf, fmt, ap); + va_start(ap, format); + strbuf_vaddf(&buf, format, ap); va_end(ap); sq_quote_argv(&buf, argv, 0); -- cgit v1.2.1 From 0d0424272f85afb5262613829cf1f48f994cebc7 Mon Sep 17 00:00:00 2001 From: Karsten Blees Date: Wed, 11 Jun 2014 09:57:59 +0200 Subject: trace: remove redundant printf format attribute trace_printf_key() is the only non-static function that duplicates the printf format attribute in the .c file, remove it for consistency. Signed-off-by: Karsten Blees Signed-off-by: Junio C Hamano --- trace.c | 1 - 1 file changed, 1 deletion(-) (limited to 'trace.c') diff --git a/trace.c b/trace.c index 37a7fa9640..3e315587e0 100644 --- a/trace.c +++ b/trace.c @@ -75,7 +75,6 @@ static void trace_vprintf(const char *key, const char *format, va_list ap) strbuf_release(&buf); } -__attribute__((format (printf, 2, 3))) void trace_printf_key(const char *key, const char *format, ...) { va_list ap; -- cgit v1.2.1 From 6aa3085702cc7a436c12f4c4396958281df1da44 Mon Sep 17 00:00:00 2001 From: Karsten Blees Date: Sat, 12 Jul 2014 02:00:06 +0200 Subject: trace: improve trace performance The trace API currently rechecks the environment variable and reopens the trace file on every API call. This has the ugly side effect that errors (e.g. file cannot be opened, or the user specified a relative path) are also reported on every call. Performance can be improved by about factor three by remembering the environment state and keeping the file open. Replace the 'const char *key' parameter in the API with a pointer to a 'struct trace_key' that bundles the environment variable name with additional, trace-internal state. Change the call sites of these APIs to use a static 'struct trace_key' instead of a string constant. In trace.c::get_trace_fd(), save and reuse the file descriptor in 'struct trace_key'. Add a 'trace_disable()' API, so that packet_trace() can cleanly disable tracing when it encounters packed data (instead of using unsetenv()). Signed-off-by: Karsten Blees Signed-off-by: Junio C Hamano --- trace.c | 100 +++++++++++++++++++++++++++++++++++----------------------------- 1 file changed, 54 insertions(+), 46 deletions(-) (limited to 'trace.c') diff --git a/trace.c b/trace.c index 3e315587e0..8662b79801 100644 --- a/trace.c +++ b/trace.c @@ -26,43 +26,66 @@ #include "quote.h" /* Get a trace file descriptor from "key" env variable. */ -static int get_trace_fd(const char *key, int *need_close) +static int get_trace_fd(struct trace_key *key) { - char *trace = getenv(key); + static struct trace_key trace_default = { "GIT_TRACE" }; + const char *trace; + + /* use default "GIT_TRACE" if NULL */ + if (!key) + key = &trace_default; + + /* don't open twice */ + if (key->initialized) + return key->fd; + + trace = getenv(key->key); if (!trace || !strcmp(trace, "") || !strcmp(trace, "0") || !strcasecmp(trace, "false")) - return 0; - if (!strcmp(trace, "1") || !strcasecmp(trace, "true")) - return STDERR_FILENO; - if (strlen(trace) == 1 && isdigit(*trace)) - return atoi(trace); - if (is_absolute_path(trace)) { + key->fd = 0; + else if (!strcmp(trace, "1") || !strcasecmp(trace, "true")) + key->fd = STDERR_FILENO; + else if (strlen(trace) == 1 && isdigit(*trace)) + key->fd = atoi(trace); + else if (is_absolute_path(trace)) { int fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666); if (fd == -1) { fprintf(stderr, "Could not open '%s' for tracing: %s\n" "Defaulting to tracing on stderr...\n", trace, strerror(errno)); - return STDERR_FILENO; + key->fd = STDERR_FILENO; + } else { + key->fd = fd; + key->need_close = 1; } - *need_close = 1; - return fd; + } else { + fprintf(stderr, "What does '%s' for %s mean?\n" + "If you want to trace into a file, then please set " + "%s to an absolute pathname (starting with /).\n" + "Defaulting to tracing on stderr...\n", + trace, key->key, key->key); + key->fd = STDERR_FILENO; } - fprintf(stderr, "What does '%s' for %s mean?\n", trace, key); - fprintf(stderr, "If you want to trace into a file, " - "then please set %s to an absolute pathname " - "(starting with /).\n", key); - fprintf(stderr, "Defaulting to tracing on stderr...\n"); + key->initialized = 1; + return key->fd; +} - return STDERR_FILENO; +void trace_disable(struct trace_key *key) +{ + if (key->need_close) + close(key->fd); + key->fd = 0; + key->initialized = 1; + key->need_close = 0; } static const char err_msg[] = "Could not trace into fd given by " "GIT_TRACE environment variable"; -static void trace_vprintf(const char *key, const char *format, va_list ap) +static void trace_vprintf(struct trace_key *key, const char *format, va_list ap) { struct strbuf buf = STRBUF_INIT; @@ -75,7 +98,7 @@ static void trace_vprintf(const char *key, const char *format, va_list ap) strbuf_release(&buf); } -void trace_printf_key(const char *key, const char *format, ...) +void trace_printf_key(struct trace_key *key, const char *format, ...) { va_list ap; va_start(ap, format); @@ -87,31 +110,24 @@ void trace_printf(const char *format, ...) { va_list ap; va_start(ap, format); - trace_vprintf("GIT_TRACE", format, ap); + trace_vprintf(NULL, format, ap); va_end(ap); } -void trace_strbuf(const char *key, const struct strbuf *buf) +void trace_strbuf(struct trace_key *key, const struct strbuf *buf) { - int fd, need_close = 0; - - fd = get_trace_fd(key, &need_close); + int fd = get_trace_fd(key); if (!fd) return; write_or_whine_pipe(fd, buf->buf, buf->len, err_msg); - - if (need_close) - close(fd); } void trace_argv_printf(const char **argv, const char *format, ...) { struct strbuf buf = STRBUF_INIT; va_list ap; - int fd, need_close = 0; - - fd = get_trace_fd("GIT_TRACE", &need_close); + int fd = get_trace_fd(NULL); if (!fd) return; @@ -124,9 +140,6 @@ void trace_argv_printf(const char **argv, const char *format, ...) strbuf_addch(&buf, '\n'); write_or_whine_pipe(fd, buf.buf, buf.len, err_msg); strbuf_release(&buf); - - if (need_close) - close(fd); } static const char *quote_crnl(const char *path) @@ -155,11 +168,11 @@ static const char *quote_crnl(const char *path) /* FIXME: move prefix to startup_info struct and get rid of this arg */ void trace_repo_setup(const char *prefix) { - static const char *key = "GIT_TRACE_SETUP"; + static struct trace_key key = TRACE_KEY_INIT(SETUP); const char *git_work_tree; char cwd[PATH_MAX]; - if (!trace_want(key)) + if (!trace_want(&key)) return; if (!getcwd(cwd, PATH_MAX)) @@ -171,18 +184,13 @@ void trace_repo_setup(const char *prefix) if (!prefix) prefix = "(null)"; - trace_printf_key(key, "setup: git_dir: %s\n", quote_crnl(get_git_dir())); - trace_printf_key(key, "setup: worktree: %s\n", quote_crnl(git_work_tree)); - trace_printf_key(key, "setup: cwd: %s\n", quote_crnl(cwd)); - trace_printf_key(key, "setup: prefix: %s\n", quote_crnl(prefix)); + trace_printf_key(&key, "setup: git_dir: %s\n", quote_crnl(get_git_dir())); + trace_printf_key(&key, "setup: worktree: %s\n", quote_crnl(git_work_tree)); + trace_printf_key(&key, "setup: cwd: %s\n", quote_crnl(cwd)); + trace_printf_key(&key, "setup: prefix: %s\n", quote_crnl(prefix)); } -int trace_want(const char *key) +int trace_want(struct trace_key *key) { - const char *trace = getenv(key); - - if (!trace || !strcmp(trace, "") || - !strcmp(trace, "0") || !strcasecmp(trace, "false")) - return 0; - return 1; + return !!get_trace_fd(key); } -- cgit v1.2.1 From c69dfd24db21be54ec5a17bb3e07c81f4e96861a Mon Sep 17 00:00:00 2001 From: Karsten Blees Date: Sat, 12 Jul 2014 02:02:18 +0200 Subject: trace: add infrastructure to augment trace output with additional info To be able to add a common prefix or suffix to all trace output (e.g. a timestamp or file:line of the caller), factor out common setup and cleanup tasks of the trace* functions. When adding a common prefix, it makes sense that the output of each trace call starts on a new line. Add '\n' in case the caller forgot. Note that this explicitly limits trace output to line-by-line, it is no longer possible to trace-print just part of a line. Until now, this was just an implicit assumption (trace-printing part of a line worked, but messed up the trace file if multiple threads or processes were involved). Thread-safety / inter-process-safety is also the reason why we need to do the prefixing and suffixing in memory rather than issuing multiple write() calls. Write_or_whine_pipe() / xwrite() is atomic unless the size exceeds MAX_IO_SIZE (8MB, see wrapper.c). In case of trace_strbuf, this costs an additional string copy (which should be irrelevant for performance in light of actual file IO). While we're at it, rename trace_strbuf's 'buf' argument, which suggests that the function is modifying the buffer. Trace_strbuf() currently is the only trace API that can print arbitrary binary data (without barfing on '%' or stopping at '\0'), so 'data' seems more appropriate. Signed-off-by: Karsten Blees Signed-off-by: Junio C Hamano --- trace.c | 47 +++++++++++++++++++++++++++++++++-------------- 1 file changed, 33 insertions(+), 14 deletions(-) (limited to 'trace.c') diff --git a/trace.c b/trace.c index 8662b79801..3d02bcc239 100644 --- a/trace.c +++ b/trace.c @@ -85,17 +85,37 @@ void trace_disable(struct trace_key *key) static const char err_msg[] = "Could not trace into fd given by " "GIT_TRACE environment variable"; +static int prepare_trace_line(struct trace_key *key, struct strbuf *buf) +{ + if (!trace_want(key)) + return 0; + + set_try_to_free_routine(NULL); /* is never reset */ + + /* add line prefix here */ + + return 1; +} + +static void print_trace_line(struct trace_key *key, struct strbuf *buf) +{ + /* append newline if missing */ + if (buf->len && buf->buf[buf->len - 1] != '\n') + strbuf_addch(buf, '\n'); + + write_or_whine_pipe(get_trace_fd(key), buf->buf, buf->len, err_msg); + strbuf_release(buf); +} + static void trace_vprintf(struct trace_key *key, const char *format, va_list ap) { struct strbuf buf = STRBUF_INIT; - if (!trace_want(key)) + if (!prepare_trace_line(key, &buf)) return; - set_try_to_free_routine(NULL); /* is never reset */ strbuf_vaddf(&buf, format, ap); - trace_strbuf(key, &buf); - strbuf_release(&buf); + print_trace_line(key, &buf); } void trace_printf_key(struct trace_key *key, const char *format, ...) @@ -114,32 +134,31 @@ void trace_printf(const char *format, ...) va_end(ap); } -void trace_strbuf(struct trace_key *key, const struct strbuf *buf) +void trace_strbuf(struct trace_key *key, const struct strbuf *data) { - int fd = get_trace_fd(key); - if (!fd) + struct strbuf buf = STRBUF_INIT; + + if (!prepare_trace_line(key, &buf)) return; - write_or_whine_pipe(fd, buf->buf, buf->len, err_msg); + strbuf_addbuf(&buf, data); + print_trace_line(key, &buf); } void trace_argv_printf(const char **argv, const char *format, ...) { struct strbuf buf = STRBUF_INIT; va_list ap; - int fd = get_trace_fd(NULL); - if (!fd) + + if (!prepare_trace_line(NULL, &buf)) return; - set_try_to_free_routine(NULL); /* is never reset */ va_start(ap, format); strbuf_vaddf(&buf, format, ap); va_end(ap); sq_quote_argv(&buf, argv, 0); - strbuf_addch(&buf, '\n'); - write_or_whine_pipe(fd, buf.buf, buf.len, err_msg); - strbuf_release(&buf); + print_trace_line(NULL, &buf); } static const char *quote_crnl(const char *path) -- cgit v1.2.1 From 124647c4b007eff04144d75042d9d95f63e303f7 Mon Sep 17 00:00:00 2001 From: Karsten Blees Date: Sat, 12 Jul 2014 02:03:01 +0200 Subject: trace: disable additional trace output for unit tests Some unit-tests use trace output to verify internal state, and unstable output such as timestamps and line numbers are not useful there. Disable additional trace output if GIT_TRACE_BARE is set. Signed-off-by: Karsten Blees Signed-off-by: Junio C Hamano --- trace.c | 6 ++++++ 1 file changed, 6 insertions(+) (limited to 'trace.c') diff --git a/trace.c b/trace.c index 3d02bcc239..a194b16000 100644 --- a/trace.c +++ b/trace.c @@ -87,11 +87,17 @@ static const char err_msg[] = "Could not trace into fd given by " static int prepare_trace_line(struct trace_key *key, struct strbuf *buf) { + static struct trace_key trace_bare = TRACE_KEY_INIT(BARE); + if (!trace_want(key)) return 0; set_try_to_free_routine(NULL); /* is never reset */ + /* unit tests may want to disable additional trace output */ + if (trace_want(&trace_bare)) + return 1; + /* add line prefix here */ return 1; -- cgit v1.2.1 From b72be02cfb402bbd6abac07af7231613cd37d594 Mon Sep 17 00:00:00 2001 From: Karsten Blees Date: Sat, 12 Jul 2014 02:03:50 +0200 Subject: trace: add current timestamp to all trace output This is useful to tell apart trace output of separate test runs. It can also be used for basic, coarse-grained performance analysis. Note that the accuracy is tainted by writing to the trace file, and you have to calculate the deltas yourself (which is next to impossible if multiple threads or processes are involved). Signed-off-by: Karsten Blees Signed-off-by: Junio C Hamano --- trace.c | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) (limited to 'trace.c') diff --git a/trace.c b/trace.c index a194b16000..18e5d93c1f 100644 --- a/trace.c +++ b/trace.c @@ -88,6 +88,9 @@ static const char err_msg[] = "Could not trace into fd given by " static int prepare_trace_line(struct trace_key *key, struct strbuf *buf) { static struct trace_key trace_bare = TRACE_KEY_INIT(BARE); + struct timeval tv; + struct tm tm; + time_t secs; if (!trace_want(key)) return 0; @@ -98,7 +101,12 @@ static int prepare_trace_line(struct trace_key *key, struct strbuf *buf) if (trace_want(&trace_bare)) return 1; - /* add line prefix here */ + /* print current timestamp */ + gettimeofday(&tv, NULL); + secs = tv.tv_sec; + localtime_r(&secs, &tm); + strbuf_addf(buf, "%02d:%02d:%02d.%06ld ", tm.tm_hour, tm.tm_min, + tm.tm_sec, (long) tv.tv_usec); return 1; } -- cgit v1.2.1 From 66f66c596fa2b4e7d4c00575a5731d33ab28d4ed Mon Sep 17 00:00:00 2001 From: Karsten Blees Date: Sat, 12 Jul 2014 02:04:29 +0200 Subject: trace: move code around, in preparation to file:line output No functional changes, just move stuff around so that the next patch isn't that ugly... Signed-off-by: Karsten Blees Signed-off-by: Junio C Hamano --- trace.c | 36 ++++++++++++++++++------------------ 1 file changed, 18 insertions(+), 18 deletions(-) (limited to 'trace.c') diff --git a/trace.c b/trace.c index 18e5d93c1f..e8ce619696 100644 --- a/trace.c +++ b/trace.c @@ -132,20 +132,20 @@ static void trace_vprintf(struct trace_key *key, const char *format, va_list ap) print_trace_line(key, &buf); } -void trace_printf_key(struct trace_key *key, const char *format, ...) +void trace_argv_printf(const char **argv, const char *format, ...) { + struct strbuf buf = STRBUF_INIT; va_list ap; - va_start(ap, format); - trace_vprintf(key, format, ap); - va_end(ap); -} -void trace_printf(const char *format, ...) -{ - va_list ap; + if (!prepare_trace_line(NULL, &buf)) + return; + va_start(ap, format); - trace_vprintf(NULL, format, ap); + strbuf_vaddf(&buf, format, ap); va_end(ap); + + sq_quote_argv(&buf, argv, 0); + print_trace_line(NULL, &buf); } void trace_strbuf(struct trace_key *key, const struct strbuf *data) @@ -159,20 +159,20 @@ void trace_strbuf(struct trace_key *key, const struct strbuf *data) print_trace_line(key, &buf); } -void trace_argv_printf(const char **argv, const char *format, ...) +void trace_printf(const char *format, ...) { - struct strbuf buf = STRBUF_INIT; va_list ap; - - if (!prepare_trace_line(NULL, &buf)) - return; - va_start(ap, format); - strbuf_vaddf(&buf, format, ap); + trace_vprintf(NULL, format, ap); va_end(ap); +} - sq_quote_argv(&buf, argv, 0); - print_trace_line(NULL, &buf); +void trace_printf_key(struct trace_key *key, const char *format, ...) +{ + va_list ap; + va_start(ap, format); + trace_vprintf(key, format, ap); + va_end(ap); } static const char *quote_crnl(const char *path) -- cgit v1.2.1 From e05bed960d3bf3bcfd0f27ab882df3da93e118ed Mon Sep 17 00:00:00 2001 From: Karsten Blees Date: Sat, 12 Jul 2014 02:05:03 +0200 Subject: trace: add 'file:line' to all trace output This is useful to see where trace output came from. Add 'const char *file, int line' parameters to the printing functions and rename them to *_fl. Add trace_printf* and trace_strbuf macros resolving to the *_fl functions and let the preprocessor fill in __FILE__ and __LINE__. As the trace_printf* functions take a variable number of arguments, this requires variadic macros (i.e. '#define foo(...) foo_impl(__VA_ARGS__)'. Though part of C99, it is unclear whether older compilers support this. Thus keep the old functions and only enable variadic macros for GNUC and MSVC 2005+ (_MSC_VER 1400). This has the nice side effect that the old C-style declarations serve as documentation how the macros are to be used. Print 'file:line ' as prefix to each trace line. Align the remaining trace output at column 40 to accommodate 18 char file names + 4 digit line number (currently there are 30 *.c files of length 18 and just 11 of 19). Trace output from longer source files (e.g. builtin/receive-pack.c) will not be aligned. Signed-off-by: Karsten Blees Signed-off-by: Junio C Hamano --- trace.c | 72 ++++++++++++++++++++++++++++++++++++++++++++++++++++++----------- 1 file changed, 60 insertions(+), 12 deletions(-) (limited to 'trace.c') diff --git a/trace.c b/trace.c index e8ce619696..f013958d0a 100644 --- a/trace.c +++ b/trace.c @@ -85,7 +85,8 @@ void trace_disable(struct trace_key *key) static const char err_msg[] = "Could not trace into fd given by " "GIT_TRACE environment variable"; -static int prepare_trace_line(struct trace_key *key, struct strbuf *buf) +static int prepare_trace_line(const char *file, int line, + struct trace_key *key, struct strbuf *buf) { static struct trace_key trace_bare = TRACE_KEY_INIT(BARE); struct timeval tv; @@ -108,6 +109,14 @@ static int prepare_trace_line(struct trace_key *key, struct strbuf *buf) strbuf_addf(buf, "%02d:%02d:%02d.%06ld ", tm.tm_hour, tm.tm_min, tm.tm_sec, (long) tv.tv_usec); +#ifdef HAVE_VARIADIC_MACROS + /* print file:line */ + strbuf_addf(buf, "%s:%d ", file, line); + /* align trace output (column 40 catches most files names in git) */ + while (buf->len < 40) + strbuf_addch(buf, ' '); +#endif + return 1; } @@ -121,49 +130,52 @@ static void print_trace_line(struct trace_key *key, struct strbuf *buf) strbuf_release(buf); } -static void trace_vprintf(struct trace_key *key, const char *format, va_list ap) +static void trace_vprintf_fl(const char *file, int line, struct trace_key *key, + const char *format, va_list ap) { struct strbuf buf = STRBUF_INIT; - if (!prepare_trace_line(key, &buf)) + if (!prepare_trace_line(file, line, key, &buf)) return; strbuf_vaddf(&buf, format, ap); print_trace_line(key, &buf); } -void trace_argv_printf(const char **argv, const char *format, ...) +static void trace_argv_vprintf_fl(const char *file, int line, + const char **argv, const char *format, + va_list ap) { struct strbuf buf = STRBUF_INIT; - va_list ap; - if (!prepare_trace_line(NULL, &buf)) + if (!prepare_trace_line(file, line, NULL, &buf)) return; - va_start(ap, format); strbuf_vaddf(&buf, format, ap); - va_end(ap); sq_quote_argv(&buf, argv, 0); print_trace_line(NULL, &buf); } -void trace_strbuf(struct trace_key *key, const struct strbuf *data) +void trace_strbuf_fl(const char *file, int line, struct trace_key *key, + const struct strbuf *data) { struct strbuf buf = STRBUF_INIT; - if (!prepare_trace_line(key, &buf)) + if (!prepare_trace_line(file, line, key, &buf)) return; strbuf_addbuf(&buf, data); print_trace_line(key, &buf); } +#ifndef HAVE_VARIADIC_MACROS + void trace_printf(const char *format, ...) { va_list ap; va_start(ap, format); - trace_vprintf(NULL, format, ap); + trace_vprintf_fl(NULL, 0, NULL, format, ap); va_end(ap); } @@ -171,10 +183,46 @@ void trace_printf_key(struct trace_key *key, const char *format, ...) { va_list ap; va_start(ap, format); - trace_vprintf(key, format, ap); + trace_vprintf_fl(NULL, 0, key, format, ap); + va_end(ap); +} + +void trace_argv_printf(const char **argv, const char *format, ...) +{ + va_list ap; + va_start(ap, format); + trace_argv_vprintf_fl(NULL, 0, argv, format, ap); va_end(ap); } +void trace_strbuf(const char *key, const struct strbuf *data) +{ + trace_strbuf_fl(NULL, 0, key, data); +} + +#else + +void trace_printf_key_fl(const char *file, int line, struct trace_key *key, + const char *format, ...) +{ + va_list ap; + va_start(ap, format); + trace_vprintf_fl(file, line, key, format, ap); + va_end(ap); +} + +void trace_argv_printf_fl(const char *file, int line, const char **argv, + const char *format, ...) +{ + va_list ap; + va_start(ap, format); + trace_argv_vprintf_fl(file, line, argv, format, ap); + va_end(ap); +} + +#endif /* HAVE_VARIADIC_MACROS */ + + static const char *quote_crnl(const char *path) { static char new_path[PATH_MAX]; -- cgit v1.2.1 From 148d6771bf5e00aa1d7fa2221507a3dfe4c1e37f Mon Sep 17 00:00:00 2001 From: Karsten Blees Date: Sat, 12 Jul 2014 02:05:42 +0200 Subject: trace: add high resolution timer function to debug performance issues Add a getnanotime() function that returns nanoseconds since 01/01/1970 as unsigned 64-bit integer (i.e. overflows in july 2554). This is easier to work with than e.g. struct timeval or struct timespec. Basing the timer on the epoch allows using the results with other time-related APIs. To simplify adaption to different platforms, split the implementation into a common getnanotime() and a platform-specific highres_nanos() function. The common getnanotime() function handles errors, falling back to gettimeofday() if highres_nanos() isn't implemented or doesn't work. getnanotime() is also responsible for normalizing to the epoch. The offset to the system clock is calculated only once on initialization, i.e. manually setting the system clock has no impact on the timer (except if the fallback gettimeofday() is in use). Git processes are typically short lived, so we don't need to handle clock drift. The highres_nanos() function returns monotonically increasing nanoseconds relative to some arbitrary point in time (e.g. system boot), or 0 on failure. Providing platform-specific implementations should be relatively easy, e.g. adapting to clock_gettime() as defined by the POSIX realtime extensions is seven lines of code. This version includes highres_nanos() implementations for: * Linux: using clock_gettime(CLOCK_MONOTONIC) * Windows: using QueryPerformanceCounter() Todo: * enable clock_gettime() on more platforms * add Mac OSX version, e.g. using mach_absolute_time + mach_timebase_info Signed-off-by: Karsten Blees Signed-off-by: Junio C Hamano --- trace.c | 82 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 82 insertions(+) (limited to 'trace.c') diff --git a/trace.c b/trace.c index f013958d0a..b9d7272318 100644 --- a/trace.c +++ b/trace.c @@ -275,3 +275,85 @@ int trace_want(struct trace_key *key) { return !!get_trace_fd(key); } + +#ifdef HAVE_CLOCK_GETTIME + +static inline uint64_t highres_nanos(void) +{ + struct timespec ts; + if (clock_gettime(CLOCK_MONOTONIC, &ts)) + return 0; + return (uint64_t) ts.tv_sec * 1000000000 + ts.tv_nsec; +} + +#elif defined (GIT_WINDOWS_NATIVE) + +static inline uint64_t highres_nanos(void) +{ + static uint64_t high_ns, scaled_low_ns; + static int scale; + LARGE_INTEGER cnt; + + if (!scale) { + if (!QueryPerformanceFrequency(&cnt)) + return 0; + + /* high_ns = number of ns per cnt.HighPart */ + high_ns = (1000000000LL << 32) / (uint64_t) cnt.QuadPart; + + /* + * Number of ns per cnt.LowPart is 10^9 / frequency (or + * high_ns >> 32). For maximum precision, we scale this factor + * so that it just fits within 32 bit (i.e. won't overflow if + * multiplied with cnt.LowPart). + */ + scaled_low_ns = high_ns; + scale = 32; + while (scaled_low_ns >= 0x100000000LL) { + scaled_low_ns >>= 1; + scale--; + } + } + + /* if QPF worked on initialization, we expect QPC to work as well */ + QueryPerformanceCounter(&cnt); + + return (high_ns * cnt.HighPart) + + ((scaled_low_ns * cnt.LowPart) >> scale); +} + +#else +# define highres_nanos() 0 +#endif + +static inline uint64_t gettimeofday_nanos(void) +{ + struct timeval tv; + gettimeofday(&tv, NULL); + return (uint64_t) tv.tv_sec * 1000000000 + tv.tv_usec * 1000; +} + +/* + * Returns nanoseconds since the epoch (01/01/1970), for performance tracing + * (i.e. favoring high precision over wall clock time accuracy). + */ +inline uint64_t getnanotime(void) +{ + static uint64_t offset; + if (offset > 1) { + /* initialization succeeded, return offset + high res time */ + return offset + highres_nanos(); + } else if (offset == 1) { + /* initialization failed, fall back to gettimeofday */ + return gettimeofday_nanos(); + } else { + /* initialize offset if high resolution timer works */ + uint64_t now = gettimeofday_nanos(); + uint64_t highres = highres_nanos(); + if (highres) + offset = now - highres; + else + offset = 1; + return now; + } +} -- cgit v1.2.1 From 09b2c1c769a69d3ff03ee7913fa50fa05b4f5a46 Mon Sep 17 00:00:00 2001 From: Karsten Blees Date: Sat, 12 Jul 2014 02:06:28 +0200 Subject: trace: add trace_performance facility to debug performance issues 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 Signed-off-by: Junio C Hamano --- trace.c | 47 +++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 47 insertions(+) (limited to 'trace.c') diff --git a/trace.c b/trace.c index b9d7272318..af64dbbcf3 100644 --- a/trace.c +++ b/trace.c @@ -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, ...) @@ -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, @@ -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 */ -- cgit v1.2.1 From 578da0391a7958510b960eaf1ef30d13e791554e Mon Sep 17 00:00:00 2001 From: Karsten Blees Date: Sat, 12 Jul 2014 02:07:01 +0200 Subject: git: add performance tracing for git's main() function to debug scripts Use trace_performance to measure and print execution time and command line arguments of the entire main() function. In constrast to the shell's 'time' utility, which measures total time of the parent process, this logs all involved git commands recursively. This is particularly useful to debug performance issues of scripted commands (i.e. which git commands were called with which parameters, and how long did they execute). Due to git's deliberate use of exit(), the implementation uses an atexit routine rather than just adding trace_performance_since() at the end of main(). Usage example: > GIT_TRACE_PERFORMANCE=~/git-trace.log git stash list Creates a log file like this: 23:57:38.638765 trace.c:405 performance: 0.000310107 s: git command: 'git' 'rev-parse' '--git-dir' 23:57:38.644387 trace.c:405 performance: 0.000261759 s: git command: 'git' 'rev-parse' '--show-toplevel' 23:57:38.646207 trace.c:405 performance: 0.000304468 s: git command: 'git' 'config' '--get-colorbool' 'color.interactive' 23:57:38.648491 trace.c:405 performance: 0.000241667 s: git command: 'git' 'config' '--get-color' 'color.interactive.help' 'red bold' 23:57:38.650465 trace.c:405 performance: 0.000243063 s: git command: 'git' 'config' '--get-color' '' 'reset' 23:57:38.654850 trace.c:405 performance: 0.025126313 s: git command: 'git' 'stash' 'list' Signed-off-by: Karsten Blees Signed-off-by: Junio C Hamano --- trace.c | 22 ++++++++++++++++++++++ 1 file changed, 22 insertions(+) (limited to 'trace.c') diff --git a/trace.c b/trace.c index af64dbbcf3..e583dc63bb 100644 --- a/trace.c +++ b/trace.c @@ -404,3 +404,25 @@ inline uint64_t getnanotime(void) return now; } } + +static uint64_t command_start_time; +static struct strbuf command_line = STRBUF_INIT; + +static void print_command_performance_atexit(void) +{ + trace_performance_since(command_start_time, "git command:%s", + command_line.buf); +} + +void trace_command_performance(const char **argv) +{ + if (!trace_want(&trace_perf_key)) + return; + + if (!command_start_time) + atexit(print_command_performance_atexit); + + strbuf_reset(&command_line); + sq_quote_argv(&command_line, argv, 0); + command_start_time = getnanotime(); +} -- cgit v1.2.1