[RFC/PATCH v4 3/3] add command performance tracing to debug scripted commands

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

Add performance tracing to identify which git commands are called and how
long they execute. This is particularly useful to debug performance issues
of scripted commands.

Usage example: > GIT_TRACE_PERFORMANCE=~/git-trace.log git stash list

Creates a log file like this:
performance: at trace.c:319, time: 0.000303280 s: git command: 'git' 'rev-parse' '--git-dir'
performance: at trace.c:319, time: 0.000334409 s: git command: 'git' 'rev-parse' '--is-inside-work-tree'
performance: at trace.c:319, time: 0.000215243 s: git command: 'git' 'rev-parse' '--show-toplevel'
performance: at trace.c:319, time: 0.000410639 s: git command: 'git' 'config' '--get-colorbool' 'color.interactive'
performance: at trace.c:319, time: 0.000394077 s: git command: 'git' 'config' '--get-color' 'color.interactive.help' 'red bold'
performance: at trace.c:319, time: 0.000280701 s: git command: 'git' 'config' '--get-color' '' 'reset'
performance: at trace.c:319, time: 0.000908185 s: git command: 'git' 'rev-parse' '--verify' 'refs/stash'
performance: at trace.c:319, time: 0.028827774 s: git command: 'git' 'stash' 'list'

Signed-off-by: Karsten Blees <blees@dcon.de>
---
 cache.h |  1 +
 git.c   |  2 ++
 trace.c | 22 ++++++++++++++++++++++
 3 files changed, 25 insertions(+)

diff --git a/cache.h b/cache.h
index cb856d9..289e8fd 100644
--- a/cache.h
+++ b/cache.h
@@ -1366,6 +1366,7 @@ extern uint64_t getnanotime(void);
 __attribute__((format (printf, 4, 5)))
 extern uint64_t trace_performance_file_line(const char *file, int lineno,
 	uint64_t nanos, const char *fmt, ...);
+extern void trace_command_performance(const char **argv);
 
 /*
  * Prints specified time (in nanoseconds) if GIT_TRACE_PERFORMANCE is enabled.
diff --git a/git.c b/git.c
index 9efd1a3..2ea65b1 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 1b1903b..9edcb59 100644
--- a/trace.c
+++ b/trace.c
@@ -309,3 +309,25 @@ uint64_t trace_performance_file_line(const char *file, int lineno,
 	strbuf_release(&buf);
 	return getnanotime();
 }
+
+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_performance())
+		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();
+}
-- 
1.9.2.msysgit.0.493.g47a82c3

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

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

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