From 5991a55c545bca32fc4f5e69ee58de86563a93fa Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Wed, 11 Jun 2014 09:56:49 +0200
Subject: [PATCH 01/17] trace: move trace declarations from cache.h to new
 trace.h

Also include direct dependencies (strbuf.h and git-compat-util.h for
__attribute__) so that trace.h can be used independently of cache.h, e.g.
in test programs.

Signed-off-by: Karsten Blees <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 cache.h | 13 ++-----------
 trace.h | 17 +++++++++++++++++
 2 files changed, 19 insertions(+), 11 deletions(-)
 create mode 100644 trace.h

diff --git a/cache.h b/cache.h
index cbe1935ba6..466f6b3471 100644
--- a/cache.h
+++ b/cache.h
@@ -7,6 +7,7 @@
 #include "advice.h"
 #include "gettext.h"
 #include "convert.h"
+#include "trace.h"
 
 #include SHA1_HEADER
 #ifndef git_SHA_CTX
@@ -1377,17 +1378,7 @@ extern void *alloc_tag_node(void);
 extern void *alloc_object_node(void);
 extern void alloc_report(void);
 
-/* trace.c */
-__attribute__((format (printf, 1, 2)))
-extern void trace_printf(const char *format, ...);
-__attribute__((format (printf, 2, 3)))
-extern void trace_argv_printf(const char **argv, const char *format, ...);
-extern void trace_repo_setup(const char *prefix);
-extern int trace_want(const char *key);
-__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);
-
+/* pkt-line.c */
 void packet_trace_identity(const char *prog);
 
 /* add */
diff --git a/trace.h b/trace.h
new file mode 100644
index 0000000000..6cc4541425
--- /dev/null
+++ b/trace.h
@@ -0,0 +1,17 @@
+#ifndef TRACE_H
+#define TRACE_H
+
+#include "git-compat-util.h"
+#include "strbuf.h"
+
+__attribute__((format (printf, 1, 2)))
+extern void trace_printf(const char *format, ...);
+__attribute__((format (printf, 2, 3)))
+extern void trace_argv_printf(const char **argv, const char *format, ...);
+extern void trace_repo_setup(const char *prefix);
+extern int trace_want(const char *key);
+__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);
+
+#endif /* TRACE_H */

From 4a3b0b25f182727876bfb01748b2d00dd43f9ad7 Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Wed, 11 Jun 2014 09:57:23 +0200
Subject: [PATCH 02/17] 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 <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 trace.c | 22 +++++++++++-----------
 trace.h |  2 +-
 2 files changed, 12 insertions(+), 12 deletions(-)

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);
diff --git a/trace.h b/trace.h
index 6cc4541425..8fea50bf1d 100644
--- a/trace.h
+++ b/trace.h
@@ -11,7 +11,7 @@ extern void trace_argv_printf(const char **argv, const char *format, ...);
 extern void trace_repo_setup(const char *prefix);
 extern int trace_want(const char *key);
 __attribute__((format (printf, 2, 3)))
-extern void trace_printf_key(const char *key, const char *fmt, ...);
+extern void trace_printf_key(const char *key, const char *format, ...);
 extern void trace_strbuf(const char *key, const struct strbuf *buf);
 
 #endif /* TRACE_H */

From 0d0424272f85afb5262613829cf1f48f994cebc7 Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Wed, 11 Jun 2014 09:57:59 +0200
Subject: [PATCH 03/17] 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 <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 trace.c | 1 -
 1 file changed, 1 deletion(-)

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;

From 6aa3085702cc7a436c12f4c4396958281df1da44 Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:00:06 +0200
Subject: [PATCH 04/17] 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 <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 builtin/receive-pack.c |   2 +-
 commit.h               |   1 +
 pkt-line.c             |   8 ++--
 shallow.c              |  10 ++---
 trace.c                | 100 ++++++++++++++++++++++-------------------
 trace.h                |  16 +++++--
 6 files changed, 78 insertions(+), 59 deletions(-)

diff --git a/builtin/receive-pack.c b/builtin/receive-pack.c
index c3230817db..1451050689 100644
--- a/builtin/receive-pack.c
+++ b/builtin/receive-pack.c
@@ -438,7 +438,7 @@ static int update_shallow_ref(struct command *cmd, struct shallow_info *si)
 	uint32_t mask = 1 << (cmd->index % 32);
 	int i;
 
-	trace_printf_key("GIT_TRACE_SHALLOW",
+	trace_printf_key(&trace_shallow,
 			 "shallow: update_shallow_ref %s\n", cmd->ref_name);
 	for (i = 0; i < si->shallow->nr; i++)
 		if (si->used_shallow[i] &&
diff --git a/commit.h b/commit.h
index a9f177ba48..08ef643f20 100644
--- a/commit.h
+++ b/commit.h
@@ -235,6 +235,7 @@ extern void assign_shallow_commits_to_refs(struct shallow_info *info,
 					   int *ref_status);
 extern int delayed_reachability_test(struct shallow_info *si, int c);
 extern void prune_shallow(int show_only);
+extern struct trace_key trace_shallow;
 
 int is_descendant_of(struct commit *, struct commit_list *);
 int in_merge_bases(struct commit *, struct commit *);
diff --git a/pkt-line.c b/pkt-line.c
index bc63b3b80e..8bc89b1e0c 100644
--- a/pkt-line.c
+++ b/pkt-line.c
@@ -3,7 +3,7 @@
 
 char packet_buffer[LARGE_PACKET_MAX];
 static const char *packet_trace_prefix = "git";
-static const char trace_key[] = "GIT_TRACE_PACKET";
+static struct trace_key trace_packet = TRACE_KEY_INIT(PACKET);
 
 void packet_trace_identity(const char *prog)
 {
@@ -15,7 +15,7 @@ static void packet_trace(const char *buf, unsigned int len, int write)
 	int i;
 	struct strbuf out;
 
-	if (!trace_want(trace_key))
+	if (!trace_want(&trace_packet))
 		return;
 
 	/* +32 is just a guess for header + quoting */
@@ -27,7 +27,7 @@ static void packet_trace(const char *buf, unsigned int len, int write)
 	if ((len >= 4 && starts_with(buf, "PACK")) ||
 	    (len >= 5 && starts_with(buf+1, "PACK"))) {
 		strbuf_addstr(&out, "PACK ...");
-		unsetenv(trace_key);
+		trace_disable(&trace_packet);
 	}
 	else {
 		/* XXX we should really handle printable utf8 */
@@ -43,7 +43,7 @@ static void packet_trace(const char *buf, unsigned int len, int write)
 	}
 
 	strbuf_addch(&out, '\n');
-	trace_strbuf(trace_key, &out);
+	trace_strbuf(&trace_packet, &out);
 	strbuf_release(&out);
 }
 
diff --git a/shallow.c b/shallow.c
index 0b267b6411..de07709e33 100644
--- a/shallow.c
+++ b/shallow.c
@@ -325,7 +325,7 @@ void prune_shallow(int show_only)
 	strbuf_release(&sb);
 }
 
-#define TRACE_KEY "GIT_TRACE_SHALLOW"
+struct trace_key trace_shallow = TRACE_KEY_INIT(SHALLOW);
 
 /*
  * Step 1, split sender shallow commits into "ours" and "theirs"
@@ -334,7 +334,7 @@ void prune_shallow(int show_only)
 void prepare_shallow_info(struct shallow_info *info, struct sha1_array *sa)
 {
 	int i;
-	trace_printf_key(TRACE_KEY, "shallow: prepare_shallow_info\n");
+	trace_printf_key(&trace_shallow, "shallow: prepare_shallow_info\n");
 	memset(info, 0, sizeof(*info));
 	info->shallow = sa;
 	if (!sa)
@@ -365,7 +365,7 @@ void remove_nonexistent_theirs_shallow(struct shallow_info *info)
 {
 	unsigned char (*sha1)[20] = info->shallow->sha1;
 	int i, dst;
-	trace_printf_key(TRACE_KEY, "shallow: remove_nonexistent_theirs_shallow\n");
+	trace_printf_key(&trace_shallow, "shallow: remove_nonexistent_theirs_shallow\n");
 	for (i = dst = 0; i < info->nr_theirs; i++) {
 		if (i != dst)
 			info->theirs[dst] = info->theirs[i];
@@ -516,7 +516,7 @@ void assign_shallow_commits_to_refs(struct shallow_info *info,
 	int *shallow, nr_shallow = 0;
 	struct paint_info pi;
 
-	trace_printf_key(TRACE_KEY, "shallow: assign_shallow_commits_to_refs\n");
+	trace_printf_key(&trace_shallow, "shallow: assign_shallow_commits_to_refs\n");
 	shallow = xmalloc(sizeof(*shallow) * (info->nr_ours + info->nr_theirs));
 	for (i = 0; i < info->nr_ours; i++)
 		shallow[nr_shallow++] = info->ours[i];
@@ -622,7 +622,7 @@ static void post_assign_shallow(struct shallow_info *info,
 	int bitmap_nr = (info->ref->nr + 31) / 32;
 	struct commit_array ca;
 
-	trace_printf_key(TRACE_KEY, "shallow: post_assign_shallow\n");
+	trace_printf_key(&trace_shallow, "shallow: post_assign_shallow\n");
 	if (ref_status)
 		memset(ref_status, 0, sizeof(*ref_status) * info->ref->nr);
 
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);
 }
diff --git a/trace.h b/trace.h
index 8fea50bf1d..d85ac4c652 100644
--- a/trace.h
+++ b/trace.h
@@ -4,14 +4,24 @@
 #include "git-compat-util.h"
 #include "strbuf.h"
 
+struct trace_key {
+	const char * const key;
+	int fd;
+	unsigned int initialized : 1;
+	unsigned int  need_close : 1;
+};
+
+#define TRACE_KEY_INIT(name) { "GIT_TRACE_" #name, 0, 0, 0 }
+
 __attribute__((format (printf, 1, 2)))
 extern void trace_printf(const char *format, ...);
 __attribute__((format (printf, 2, 3)))
 extern void trace_argv_printf(const char **argv, const char *format, ...);
 extern void trace_repo_setup(const char *prefix);
-extern int trace_want(const char *key);
+extern int trace_want(struct trace_key *key);
+extern void trace_disable(struct trace_key *key);
 __attribute__((format (printf, 2, 3)))
-extern void trace_printf_key(const char *key, const char *format, ...);
-extern void trace_strbuf(const char *key, const struct strbuf *buf);
+extern void trace_printf_key(struct trace_key *key, const char *format, ...);
+extern void trace_strbuf(struct trace_key *key, const struct strbuf *buf);
 
 #endif /* TRACE_H */

From eb9250dfd5fbd7c9f95d0d3134006cd19a0c9099 Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:00:53 +0200
Subject: [PATCH 05/17] Documentation/git.txt: improve documentation of
 'GIT_TRACE*' variables

Separate GIT_TRACE description into what it prints and how to configure
where trace output is printed to. Change other GIT_TRACE_* descriptions to
refer to GIT_TRACE.

Add descriptions for GIT_TRACE_SETUP and GIT_TRACE_SHALLOW.

Signed-off-by: Karsten Blees <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 Documentation/git.txt | 50 +++++++++++++++++++++++++++++--------------
 1 file changed, 34 insertions(+), 16 deletions(-)

diff --git a/Documentation/git.txt b/Documentation/git.txt
index 3bd68b0167..75633e65da 100644
--- a/Documentation/git.txt
+++ b/Documentation/git.txt
@@ -904,18 +904,25 @@ for further details.
 	based on whether stdout appears to be redirected to a file or not.
 
 'GIT_TRACE'::
-	If this variable is set to "1", "2" or "true" (comparison
-	is case insensitive), Git will print `trace:` messages on
-	stderr telling about alias expansion, built-in command
-	execution and external command execution.
-	If this variable is set to an integer value greater than 1
-	and lower than 10 (strictly) then Git will interpret this
-	value as an open file descriptor and will try to write the
-	trace messages into this file descriptor.
-	Alternatively, if this variable is set to an absolute path
-	(starting with a '/' character), Git will interpret this
-	as a file path and will try to write the trace messages
-	into it.
+	Enables general trace messages, e.g. alias expansion, built-in
+	command execution and external command execution.
++
+If this variable is set to "1", "2" or "true" (comparison
+is case insensitive), trace messages will be printed to
+stderr.
++
+If the variable is set to an integer value greater than 2
+and lower than 10 (strictly) then Git will interpret this
+value as an open file descriptor and will try to write the
+trace messages into this file descriptor.
++
+Alternatively, if the variable is set to an absolute path
+(starting with a '/' character), Git will interpret this
+as a file path and will try to write the trace messages
+into it.
++
+Unsetting the variable, or setting it to empty, "0" or
+"false" (case insensitive) disables trace messages.
 
 'GIT_TRACE_PACK_ACCESS'::
 	If this variable is set to a path, a file will be created at
@@ -925,10 +932,21 @@ for further details.
 	pack-related performance problems.
 
 'GIT_TRACE_PACKET'::
-	If this variable is set, it shows a trace of all packets
-	coming in or out of a given program. This can help with
-	debugging object negotiation or other protocol issues. Tracing
-	is turned off at a packet starting with "PACK".
+	Enables trace messages for all packets coming in or out of a
+	given program. This can help with debugging object negotiation
+	or other protocol issues. Tracing is turned off at a packet
+	starting with "PACK".
+	See 'GIT_TRACE' for available trace output options.
+
+'GIT_TRACE_SETUP'::
+	Enables trace messages printing the .git, working tree and current
+	working directory after Git has completed its setup phase.
+	See 'GIT_TRACE' for available trace output options.
+
+'GIT_TRACE_SHALLOW'::
+	Enables trace messages that can help debugging fetching /
+	cloning of shallow repositories.
+	See 'GIT_TRACE' for available trace output options.
 
 GIT_LITERAL_PATHSPECS::
 	Setting this variable to `1` will cause Git to treat all

From 67dc598ec42ea25cda94ed8d283396c4ab385f50 Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:01:38 +0200
Subject: [PATCH 06/17] sha1_file: change GIT_TRACE_PACK_ACCESS logging to use
 trace API

This changes GIT_TRACE_PACK_ACCESS functionality as follows:
 * supports the same options as GIT_TRACE (e.g. printing to stderr)
 * no longer supports relative paths
 * appends to the trace file rather than overwriting

Signed-off-by: Karsten Blees <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 Documentation/git.txt |  4 ++--
 sha1_file.c           | 30 ++++--------------------------
 2 files changed, 6 insertions(+), 28 deletions(-)

diff --git a/Documentation/git.txt b/Documentation/git.txt
index 75633e65da..9d073f6adc 100644
--- a/Documentation/git.txt
+++ b/Documentation/git.txt
@@ -925,11 +925,11 @@ Unsetting the variable, or setting it to empty, "0" or
 "false" (case insensitive) disables trace messages.
 
 'GIT_TRACE_PACK_ACCESS'::
-	If this variable is set to a path, a file will be created at
-	the given path logging all accesses to any packs. For each
+	Enables trace messages for all accesses to any packs. For each
 	access, the pack file name and an offset in the pack is
 	recorded. This may be helpful for troubleshooting some
 	pack-related performance problems.
+	See 'GIT_TRACE' for available trace output options.
 
 'GIT_TRACE_PACKET'::
 	Enables trace messages for all packets coming in or out of a
diff --git a/sha1_file.c b/sha1_file.c
index 34d527f670..7a110b513e 100644
--- a/sha1_file.c
+++ b/sha1_file.c
@@ -36,9 +36,6 @@ static inline uintmax_t sz_fmt(size_t s) { return s; }
 
 const unsigned char null_sha1[20];
 
-static const char *no_log_pack_access = "no_log_pack_access";
-static const char *log_pack_access;
-
 /*
  * This is meant to hold a *small* number of objects that you would
  * want read_sha1_file() to be able to return, but yet you do not want
@@ -2085,27 +2082,9 @@ static void *read_object(const unsigned char *sha1, enum object_type *type,
 
 static void write_pack_access_log(struct packed_git *p, off_t obj_offset)
 {
-	static FILE *log_file;
-
-	if (!log_pack_access)
-		log_pack_access = getenv("GIT_TRACE_PACK_ACCESS");
-	if (!log_pack_access)
-		log_pack_access = no_log_pack_access;
-	if (log_pack_access == no_log_pack_access)
-		return;
-
-	if (!log_file) {
-		log_file = fopen(log_pack_access, "w");
-		if (!log_file) {
-			error("cannot open pack access log '%s' for writing: %s",
-			      log_pack_access, strerror(errno));
-			log_pack_access = no_log_pack_access;
-			return;
-		}
-	}
-	fprintf(log_file, "%s %"PRIuMAX"\n",
-		p->pack_name, (uintmax_t)obj_offset);
-	fflush(log_file);
+	static struct trace_key pack_access = TRACE_KEY_INIT(PACK_ACCESS);
+	trace_printf_key(&pack_access, "%s %"PRIuMAX"\n",
+			 p->pack_name, (uintmax_t)obj_offset);
 }
 
 int do_check_packed_object_crc;
@@ -2130,8 +2109,7 @@ void *unpack_entry(struct packed_git *p, off_t obj_offset,
 	int delta_stack_nr = 0, delta_stack_alloc = UNPACK_ENTRY_STACK_PREALLOC;
 	int base_from_cache = 0;
 
-	if (log_pack_access != no_log_pack_access)
-		write_pack_access_log(p, obj_offset);
+	write_pack_access_log(p, obj_offset);
 
 	/* PHASE 1: drill down to the innermost base object */
 	for (;;) {

From c69dfd24db21be54ec5a17bb3e07c81f4e96861a Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:02:18 +0200
Subject: [PATCH 07/17] 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 <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 trace.c | 47 +++++++++++++++++++++++++++++++++--------------
 trace.h |  2 +-
 2 files changed, 34 insertions(+), 15 deletions(-)

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)
diff --git a/trace.h b/trace.h
index d85ac4c652..28c10892df 100644
--- a/trace.h
+++ b/trace.h
@@ -22,6 +22,6 @@ extern int trace_want(struct trace_key *key);
 extern void trace_disable(struct trace_key *key);
 __attribute__((format (printf, 2, 3)))
 extern void trace_printf_key(struct trace_key *key, const char *format, ...);
-extern void trace_strbuf(struct trace_key *key, const struct strbuf *buf);
+extern void trace_strbuf(struct trace_key *key, const struct strbuf *data);
 
 #endif /* TRACE_H */

From 124647c4b007eff04144d75042d9d95f63e303f7 Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:03:01 +0200
Subject: [PATCH 08/17] 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 <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 t/test-lib.sh | 4 ++++
 trace.c       | 6 ++++++
 2 files changed, 10 insertions(+)

diff --git a/t/test-lib.sh b/t/test-lib.sh
index 81394c8c7c..e37da5a220 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -109,6 +109,10 @@ export GIT_AUTHOR_EMAIL GIT_AUTHOR_NAME
 export GIT_COMMITTER_EMAIL GIT_COMMITTER_NAME
 export EDITOR
 
+# Tests using GIT_TRACE typically don't want <timestamp> <file>:<line> output
+GIT_TRACE_BARE=1
+export GIT_TRACE_BARE
+
 if test -n "${TEST_GIT_INDEX_VERSION:+isset}"
 then
 	GIT_INDEX_VERSION="$TEST_GIT_INDEX_VERSION"
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;

From b72be02cfb402bbd6abac07af7231613cd37d594 Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:03:50 +0200
Subject: [PATCH 09/17] 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 <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 trace.c | 10 +++++++++-
 1 file changed, 9 insertions(+), 1 deletion(-)

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;
 }

From 66f66c596fa2b4e7d4c00575a5731d33ab28d4ed Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:04:29 +0200
Subject: [PATCH 10/17] 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 <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 trace.c | 54 +++++++++++++++++++++++++++---------------------------
 trace.h | 12 ++++++++----
 2 files changed, 35 insertions(+), 31 deletions(-)

diff --git a/trace.c b/trace.c
index 18e5d93c1f..e8ce619696 100644
--- a/trace.c
+++ b/trace.c
@@ -132,33 +132,6 @@ 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, ...)
-{
-	va_list ap;
-	va_start(ap, format);
-	trace_vprintf(key, format, ap);
-	va_end(ap);
-}
-
-void trace_printf(const char *format, ...)
-{
-	va_list ap;
-	va_start(ap, format);
-	trace_vprintf(NULL, format, ap);
-	va_end(ap);
-}
-
-void trace_strbuf(struct trace_key *key, const struct strbuf *data)
-{
-	struct strbuf buf = STRBUF_INIT;
-
-	if (!prepare_trace_line(key, &buf))
-		return;
-
-	strbuf_addbuf(&buf, data);
-	print_trace_line(key, &buf);
-}
-
 void trace_argv_printf(const char **argv, const char *format, ...)
 {
 	struct strbuf buf = STRBUF_INIT;
@@ -175,6 +148,33 @@ void trace_argv_printf(const char **argv, const char *format, ...)
 	print_trace_line(NULL, &buf);
 }
 
+void trace_strbuf(struct trace_key *key, const struct strbuf *data)
+{
+	struct strbuf buf = STRBUF_INIT;
+
+	if (!prepare_trace_line(key, &buf))
+		return;
+
+	strbuf_addbuf(&buf, data);
+	print_trace_line(key, &buf);
+}
+
+void trace_printf(const char *format, ...)
+{
+	va_list ap;
+	va_start(ap, format);
+	trace_vprintf(NULL, format, ap);
+	va_end(ap);
+}
+
+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)
 {
 	static char new_path[PATH_MAX];
diff --git a/trace.h b/trace.h
index 28c10892df..b4800e7461 100644
--- a/trace.h
+++ b/trace.h
@@ -13,15 +13,19 @@ struct trace_key {
 
 #define TRACE_KEY_INIT(name) { "GIT_TRACE_" #name, 0, 0, 0 }
 
-__attribute__((format (printf, 1, 2)))
-extern void trace_printf(const char *format, ...);
-__attribute__((format (printf, 2, 3)))
-extern void trace_argv_printf(const char **argv, const char *format, ...);
 extern void trace_repo_setup(const char *prefix);
 extern int trace_want(struct trace_key *key);
 extern void trace_disable(struct trace_key *key);
+
+__attribute__((format (printf, 1, 2)))
+extern void trace_printf(const char *format, ...);
+
 __attribute__((format (printf, 2, 3)))
 extern void trace_printf_key(struct trace_key *key, const char *format, ...);
+
+__attribute__((format (printf, 2, 3)))
+extern void trace_argv_printf(const char **argv, const char *format, ...);
+
 extern void trace_strbuf(struct trace_key *key, const struct strbuf *data);
 
 #endif /* TRACE_H */

From e05bed960d3bf3bcfd0f27ab882df3da93e118ed Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:05:03 +0200
Subject: [PATCH 11/17] 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 <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 git-compat-util.h |  4 +++
 trace.c           | 72 +++++++++++++++++++++++++++++++++++++++--------
 trace.h           | 62 ++++++++++++++++++++++++++++++++++++++++
 3 files changed, 126 insertions(+), 12 deletions(-)

diff --git a/git-compat-util.h b/git-compat-util.h
index b6f03b36dc..4dd065d7f3 100644
--- a/git-compat-util.h
+++ b/git-compat-util.h
@@ -704,6 +704,10 @@ void git_qsort(void *base, size_t nmemb, size_t size,
 #endif
 #endif
 
+#if defined(__GNUC__) || (_MSC_VER >= 1400)
+#define HAVE_VARIADIC_MACROS 1
+#endif
+
 /*
  * Preserves errno, prints a message, but gives no warning for ENOENT.
  * Always returns the return value of unlink(2).
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];
diff --git a/trace.h b/trace.h
index b4800e7461..7a5ba2e61c 100644
--- a/trace.h
+++ b/trace.h
@@ -17,6 +17,8 @@ extern void trace_repo_setup(const char *prefix);
 extern int trace_want(struct trace_key *key);
 extern void trace_disable(struct trace_key *key);
 
+#ifndef HAVE_VARIADIC_MACROS
+
 __attribute__((format (printf, 1, 2)))
 extern void trace_printf(const char *format, ...);
 
@@ -28,4 +30,64 @@ extern void trace_argv_printf(const char **argv, const char *format, ...);
 
 extern void trace_strbuf(struct trace_key *key, const struct strbuf *data);
 
+#else
+
+/*
+ * Macros to add file:line - see above for C-style declarations of how these
+ * should be used.
+ */
+
+/*
+ * TRACE_CONTEXT may be set to __FUNCTION__ if the compiler supports it. The
+ * default is __FILE__, as it is consistent with assert(), and static function
+ * names are not necessarily unique.
+ *
+ * __FILE__ ":" __FUNCTION__ doesn't work with GNUC, as __FILE__ is supplied
+ * by the preprocessor as a string literal, and __FUNCTION__ is filled in by
+ * the compiler as a string constant.
+ */
+#ifndef TRACE_CONTEXT
+# define TRACE_CONTEXT __FILE__
+#endif
+
+/*
+ * Note: with C99 variadic macros, __VA_ARGS__ must include the last fixed
+ * parameter ('format' in this case). Otherwise, a call without variable
+ * arguments will have a surplus ','. E.g.:
+ *
+ *  #define foo(format, ...) bar(format, __VA_ARGS__)
+ *  foo("test");
+ *
+ * will expand to
+ *
+ *  bar("test",);
+ *
+ * which is invalid (note the ',)'). With GNUC, '##__VA_ARGS__' drops the
+ * comma, but this is non-standard.
+ */
+
+#define trace_printf(...) \
+	trace_printf_key_fl(TRACE_CONTEXT, __LINE__, NULL, __VA_ARGS__)
+
+#define trace_printf_key(key, ...) \
+	trace_printf_key_fl(TRACE_CONTEXT, __LINE__, key, __VA_ARGS__)
+
+#define trace_argv_printf(argv, ...) \
+	trace_argv_printf_fl(TRACE_CONTEXT, __LINE__, argv, __VA_ARGS__)
+
+#define trace_strbuf(key, data) \
+	trace_strbuf_fl(TRACE_CONTEXT, __LINE__, key, data)
+
+/* 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,
+				const char *format, ...);
+__attribute__((format (printf, 4, 5)))
+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);
+
+#endif /* HAVE_VARIADIC_MACROS */
+
 #endif /* TRACE_H */

From 148d6771bf5e00aa1d7fa2221507a3dfe4c1e37f Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:05:42 +0200
Subject: [PATCH 12/17] 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 <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 Makefile         |  7 +++++
 config.mak.uname |  1 +
 trace.c          | 82 ++++++++++++++++++++++++++++++++++++++++++++++++
 trace.h          |  1 +
 4 files changed, 91 insertions(+)

diff --git a/Makefile b/Makefile
index 07ea105837..80f4390abb 100644
--- a/Makefile
+++ b/Makefile
@@ -340,6 +340,8 @@ all::
 #
 # Define GMTIME_UNRELIABLE_ERRORS if your gmtime() function does not
 # return NULL when it receives a bogus time_t.
+#
+# Define HAVE_CLOCK_GETTIME if your platform has clock_gettime in librt.
 
 GIT-VERSION-FILE: FORCE
 	@$(SHELL_PATH) ./GIT-VERSION-GEN
@@ -1497,6 +1499,11 @@ ifdef GMTIME_UNRELIABLE_ERRORS
 	BASIC_CFLAGS += -DGMTIME_UNRELIABLE_ERRORS
 endif
 
+ifdef HAVE_CLOCK_GETTIME
+	BASIC_CFLAGS += -DHAVE_CLOCK_GETTIME
+	EXTLIBS += -lrt
+endif
+
 ifeq ($(TCLTK_PATH),)
 NO_TCLTK = NoThanks
 endif
diff --git a/config.mak.uname b/config.mak.uname
index 1ae675b053..dad2618329 100644
--- a/config.mak.uname
+++ b/config.mak.uname
@@ -34,6 +34,7 @@ ifeq ($(uname_S),Linux)
 	HAVE_PATHS_H = YesPlease
 	LIBC_CONTAINS_LIBINTL = YesPlease
 	HAVE_DEV_TTY = YesPlease
+	HAVE_CLOCK_GETTIME = YesPlease
 endif
 ifeq ($(uname_S),GNU/kFreeBSD)
 	HAVE_ALLOCA_H = YesPlease
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;
+	}
+}
diff --git a/trace.h b/trace.h
index 7a5ba2e61c..4b893a55cf 100644
--- a/trace.h
+++ b/trace.h
@@ -16,6 +16,7 @@ struct trace_key {
 extern void trace_repo_setup(const char *prefix);
 extern int trace_want(struct trace_key *key);
 extern void trace_disable(struct trace_key *key);
+extern uint64_t getnanotime(void);
 
 #ifndef HAVE_VARIADIC_MACROS
 

From 09b2c1c769a69d3ff03ee7913fa50fa05b4f5a46 Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:06:28 +0200
Subject: [PATCH 13/17] 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 <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 trace.c | 47 +++++++++++++++++++++++++++++++++++++++++++++++
 trace.h | 18 ++++++++++++++++++
 2 files changed, 65 insertions(+)

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 */
 
 
diff --git a/trace.h b/trace.h
index 4b893a55cf..c843e681a7 100644
--- a/trace.h
+++ b/trace.h
@@ -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
 
 /*
@@ -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,
@@ -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 */
 

From 578da0391a7958510b960eaf1ef30d13e791554e Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:07:01 +0200
Subject: [PATCH 14/17] 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 <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 Documentation/git.txt |  5 +++++
 git.c                 |  2 ++
 trace.c               | 22 ++++++++++++++++++++++
 trace.h               |  1 +
 4 files changed, 30 insertions(+)

diff --git a/Documentation/git.txt b/Documentation/git.txt
index 9d073f6adc..fcb8afa200 100644
--- a/Documentation/git.txt
+++ b/Documentation/git.txt
@@ -938,6 +938,11 @@ Unsetting the variable, or setting it to empty, "0" or
 	starting with "PACK".
 	See 'GIT_TRACE' for available trace output options.
 
+'GIT_TRACE_PERFORMANCE'::
+	Enables performance related trace messages, e.g. total execution
+	time of each Git command.
+	See 'GIT_TRACE' for available trace output options.
+
 'GIT_TRACE_SETUP'::
 	Enables trace messages printing the .git, working tree and current
 	working directory after Git has completed its setup phase.
diff --git a/git.c b/git.c
index 7780572948..d4daeb8604 100644
--- a/git.c
+++ b/git.c
@@ -568,6 +568,8 @@ int main(int argc, char **av)
 
 	git_setup_gettext();
 
+	trace_command_performance(argv);
+
 	/*
 	 * "git-xxxx" is the same as "git xxxx", but we obviously:
 	 *
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();
+}
diff --git a/trace.h b/trace.h
index c843e681a7..ae6a332947 100644
--- a/trace.h
+++ b/trace.h
@@ -17,6 +17,7 @@ extern void trace_repo_setup(const char *prefix);
 extern int trace_want(struct trace_key *key);
 extern void trace_disable(struct trace_key *key);
 extern uint64_t getnanotime(void);
+extern void trace_command_performance(const char **argv);
 
 #ifndef HAVE_VARIADIC_MACROS
 

From 132d41e69a460f1bb72ba9eb41c513c42d9a8532 Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:07:36 +0200
Subject: [PATCH 15/17] wt-status: simplify performance measurement by using
 getnanotime()

Calculating duration from a single uint64_t is simpler than from a struct
timeval. Change performance measurement for 'advice.statusuoption' from
gettimeofday() to getnanotime().

Also initialize t_begin to prevent uninitialized variable warning.

Signed-off-by: Karsten Blees <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 wt-status.c | 14 +++-----------
 1 file changed, 3 insertions(+), 11 deletions(-)

diff --git a/wt-status.c b/wt-status.c
index 318a191238..dfdc018f1b 100644
--- a/wt-status.c
+++ b/wt-status.c
@@ -574,14 +574,11 @@ static void wt_status_collect_untracked(struct wt_status *s)
 {
 	int i;
 	struct dir_struct dir;
-	struct timeval t_begin;
+	uint64_t t_begin = getnanotime();
 
 	if (!s->show_untracked_files)
 		return;
 
-	if (advice_status_u_option)
-		gettimeofday(&t_begin, NULL);
-
 	memset(&dir, 0, sizeof(dir));
 	if (s->show_untracked_files != SHOW_ALL_UNTRACKED_FILES)
 		dir.flags |=
@@ -612,13 +609,8 @@ static void wt_status_collect_untracked(struct wt_status *s)
 	free(dir.ignored);
 	clear_directory(&dir);
 
-	if (advice_status_u_option) {
-		struct timeval t_end;
-		gettimeofday(&t_end, NULL);
-		s->untracked_in_ms =
-			(uint64_t)t_end.tv_sec * 1000 + t_end.tv_usec / 1000 -
-			((uint64_t)t_begin.tv_sec * 1000 + t_begin.tv_usec / 1000);
-	}
+	if (advice_status_u_option)
+		s->untracked_in_ms = (getnanotime() - t_begin) / 1000000;
 }
 
 void wt_status_collect(struct wt_status *s)

From 83d26fa724ef2efbeb332fa3dc92b00c0e579f28 Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:08:11 +0200
Subject: [PATCH 16/17] progress: simplify performance measurement by using
 getnanotime()

Calculating duration from a single uint64_t is simpler than from a struct
timeval. Change throughput measurement from gettimeofday() to
getnanotime().

Also calculate misec only if needed, and change integer division to integer
multiplication + shift, which should be slightly faster.

Signed-off-by: Karsten Blees <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 progress.c | 71 +++++++++++++++++++++++++++---------------------------
 1 file changed, 36 insertions(+), 35 deletions(-)

diff --git a/progress.c b/progress.c
index 261314ef3c..412e6b1ecc 100644
--- a/progress.c
+++ b/progress.c
@@ -12,13 +12,14 @@
 #include "gettext.h"
 #include "progress.h"
 #include "strbuf.h"
+#include "trace.h"
 
 #define TP_IDX_MAX      8
 
 struct throughput {
 	off_t curr_total;
 	off_t prev_total;
-	struct timeval prev_tv;
+	uint64_t prev_ns;
 	unsigned int avg_bytes;
 	unsigned int avg_misecs;
 	unsigned int last_bytes[TP_IDX_MAX];
@@ -127,65 +128,65 @@ static void throughput_string(struct strbuf *buf, off_t total,
 void display_throughput(struct progress *progress, off_t total)
 {
 	struct throughput *tp;
-	struct timeval tv;
-	unsigned int misecs;
+	uint64_t now_ns;
+	unsigned int misecs, count, rate;
+	struct strbuf buf = STRBUF_INIT;
 
 	if (!progress)
 		return;
 	tp = progress->throughput;
 
-	gettimeofday(&tv, NULL);
+	now_ns = getnanotime();
 
 	if (!tp) {
 		progress->throughput = tp = calloc(1, sizeof(*tp));
 		if (tp) {
 			tp->prev_total = tp->curr_total = total;
-			tp->prev_tv = tv;
+			tp->prev_ns = now_ns;
 		}
 		return;
 	}
 	tp->curr_total = total;
 
+	/* only update throughput every 0.5 s */
+	if (now_ns - tp->prev_ns <= 500000000)
+		return;
+
 	/*
-	 * We have x = bytes and y = microsecs.  We want z = KiB/s:
+	 * We have x = bytes and y = nanosecs.  We want z = KiB/s:
 	 *
-	 *	z = (x / 1024) / (y / 1000000)
-	 *	z = x / y * 1000000 / 1024
-	 *	z = x / (y * 1024 / 1000000)
+	 *	z = (x / 1024) / (y / 1000000000)
+	 *	z = x / y * 1000000000 / 1024
+	 *	z = x / (y * 1024 / 1000000000)
 	 *	z = x / y'
 	 *
 	 * To simplify things we'll keep track of misecs, or 1024th of a sec
 	 * obtained with:
 	 *
-	 *	y' = y * 1024 / 1000000
-	 *	y' = y / (1000000 / 1024)
-	 *	y' = y / 977
+	 *	y' = y * 1024 / 1000000000
+	 *	y' = y * (2^10 / 2^42) * (2^42 / 1000000000)
+	 *	y' = y / 2^32 * 4398
+	 *	y' = (y * 4398) >> 32
 	 */
-	misecs = (tv.tv_sec - tp->prev_tv.tv_sec) * 1024;
-	misecs += (int)(tv.tv_usec - tp->prev_tv.tv_usec) / 977;
+	misecs = ((now_ns - tp->prev_ns) * 4398) >> 32;
 
-	if (misecs > 512) {
-		struct strbuf buf = STRBUF_INIT;
-		unsigned int count, rate;
+	count = total - tp->prev_total;
+	tp->prev_total = total;
+	tp->prev_ns = now_ns;
+	tp->avg_bytes += count;
+	tp->avg_misecs += misecs;
+	rate = tp->avg_bytes / tp->avg_misecs;
+	tp->avg_bytes -= tp->last_bytes[tp->idx];
+	tp->avg_misecs -= tp->last_misecs[tp->idx];
+	tp->last_bytes[tp->idx] = count;
+	tp->last_misecs[tp->idx] = misecs;
+	tp->idx = (tp->idx + 1) % TP_IDX_MAX;
 
-		count = total - tp->prev_total;
-		tp->prev_total = total;
-		tp->prev_tv = tv;
-		tp->avg_bytes += count;
-		tp->avg_misecs += misecs;
-		rate = tp->avg_bytes / tp->avg_misecs;
-		tp->avg_bytes -= tp->last_bytes[tp->idx];
-		tp->avg_misecs -= tp->last_misecs[tp->idx];
-		tp->last_bytes[tp->idx] = count;
-		tp->last_misecs[tp->idx] = misecs;
-		tp->idx = (tp->idx + 1) % TP_IDX_MAX;
-
-		throughput_string(&buf, total, rate);
-		strncpy(tp->display, buf.buf, sizeof(tp->display));
-		strbuf_release(&buf);
-		if (progress->last_value != -1 && progress_update)
-			display(progress, progress->last_value, NULL);
-	}
+	throughput_string(&buf, total, rate);
+	strncpy(tp->display, buf.buf, sizeof(tp->display));
+	strbuf_release(&buf);
+	if (progress->last_value != -1 && progress_update)
+		display(progress, progress->last_value, NULL);
 }
 
 int display_progress(struct progress *progress, unsigned n)

From c7d3f8cb48d754371343c5a48cf392135bb4d77b Mon Sep 17 00:00:00 2001
From: Karsten Blees <karsten.blees@gmail.com>
Date: Sat, 12 Jul 2014 02:08:48 +0200
Subject: [PATCH 17/17] api-trace.txt: add trace API documentation

Signed-off-by: Karsten Blees <blees@dcon.de>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 Documentation/technical/api-trace.txt | 97 +++++++++++++++++++++++++++
 1 file changed, 97 insertions(+)
 create mode 100644 Documentation/technical/api-trace.txt

diff --git a/Documentation/technical/api-trace.txt b/Documentation/technical/api-trace.txt
new file mode 100644
index 0000000000..097a651d96
--- /dev/null
+++ b/Documentation/technical/api-trace.txt
@@ -0,0 +1,97 @@
+trace API
+=========
+
+The trace API can be used to print debug messages to stderr or a file. Trace
+code is inactive unless explicitly enabled by setting `GIT_TRACE*` environment
+variables.
+
+The trace implementation automatically adds `timestamp file:line ... \n` to
+all trace messages. E.g.:
+
+------------
+23:59:59.123456 git.c:312               trace: built-in: git 'foo'
+00:00:00.000001 builtin/foo.c:99        foo: some message
+------------
+
+Data Structures
+---------------
+
+`struct trace_key`::
+
+	Defines a trace key (or category). The default (for API functions that
+	don't take a key) is `GIT_TRACE`.
++
+E.g. to define a trace key controlled by environment variable `GIT_TRACE_FOO`:
++
+------------
+static struct trace_key trace_foo = TRACE_KEY_INIT(FOO);
+
+static void trace_print_foo(const char *message)
+{
+	trace_print_key(&trace_foo, message);
+}
+------------
++
+Note: don't use `const` as the trace implementation stores internal state in
+the `trace_key` structure.
+
+Functions
+---------
+
+`int trace_want(struct trace_key *key)`::
+
+	Checks whether the trace key is enabled. Used to prevent expensive
+	string formatting before calling one of the printing APIs.
+
+`void trace_disable(struct trace_key *key)`::
+
+	Disables tracing for the specified key, even if the environment
+	variable was set.
+
+`void trace_printf(const char *format, ...)`::
+`void trace_printf_key(struct trace_key *key, const char *format, ...)`::
+
+	Prints a formatted message, similar to printf.
+
+`void trace_argv_printf(const char **argv, const char *format, ...)``::
+
+	Prints a formatted message, followed by a quoted list of arguments.
+
+`void trace_strbuf(struct trace_key *key, const struct strbuf *data)`::
+
+	Prints the strbuf, without additional formatting (i.e. doesn't
+	choke on `%` or even `\0`).
+
+`uint64_t getnanotime(void)`::
+
+	Returns nanoseconds since the epoch (01/01/1970), typically used
+	for performance measurements.
++
+Currently there are high precision timer implementations for Linux (using
+`clock_gettime(CLOCK_MONOTONIC)`) and Windows (`QueryPerformanceCounter`).
+Other platforms use `gettimeofday` as time source.
+
+`void trace_performance(uint64_t nanos, const char *format, ...)`::
+`void trace_performance_since(uint64_t start, const char *format, ...)`::
+
+	Prints the elapsed time (in nanoseconds), or elapsed time since
+	`start`, followed by a formatted message. Enabled via environment
+	variable `GIT_TRACE_PERFORMANCE`. Used for manual profiling, e.g.:
++
+------------
+uint64_t start = getnanotime();
+/* code section to measure */
+trace_performance_since(start, "foobar");
+------------
++
+------------
+uint64_t t = 0;
+for (;;) {
+	/* ignore */
+	t -= getnanotime();
+	/* code section to measure */
+	t += getnanotime();
+	/* ignore */
+}
+trace_performance(t, "frotz");
+------------