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>
This commit is contained in:
Karsten Blees 2014-07-12 02:07:01 +02:00 committed by Junio C Hamano
parent 09b2c1c769
commit 578da0391a
4 changed files with 30 additions and 0 deletions

View File

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

2
git.c
View File

@ -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:
*

22
trace.c
View File

@ -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();
}

View File

@ -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