Skip to content

Commit

Permalink
Merge branch 'kb/perf-trace'
Browse files Browse the repository at this point in the history
* kb/perf-trace:
  api-trace.txt: add trace API documentation
  progress: simplify performance measurement by using getnanotime()
  wt-status: simplify performance measurement by using getnanotime()
  git: add performance tracing for git's main() function to debug scripts
  trace: add trace_performance facility to debug performance issues
  trace: add high resolution timer function to debug performance issues
  trace: add 'file:line' to all trace output
  trace: move code around, in preparation to file:line output
  trace: add current timestamp to all trace output
  trace: disable additional trace output for unit tests
  trace: add infrastructure to augment trace output with additional info
  sha1_file: change GIT_TRACE_PACK_ACCESS logging to use trace API
  Documentation/git.txt: improve documentation of 'GIT_TRACE*' variables
  trace: improve trace performance
  trace: remove redundant printf format attribute
  trace: consistently name the format parameter
  trace: move trace declarations from cache.h to new trace.h
  • Loading branch information
Junio C Hamano committed Jul 22, 2014
2 parents 9ab0882 + c7d3f8c commit 9f2de9c
Show file tree
Hide file tree
Showing 17 changed files with 629 additions and 176 deletions.
59 changes: 41 additions & 18 deletions Documentation/git.txt
Original file line number Diff line number Diff line change
Expand Up @@ -906,31 +906,54 @@ 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
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'::
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_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.
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
Expand Down
97 changes: 97 additions & 0 deletions Documentation/technical/api-trace.txt
Original file line number Diff line number Diff line change
@@ -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");
------------
7 changes: 7 additions & 0 deletions Makefile
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -1500,6 +1502,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
Expand Down
2 changes: 1 addition & 1 deletion builtin/receive-pack.c
Original file line number Diff line number Diff line change
Expand Up @@ -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] &&
Expand Down
13 changes: 2 additions & 11 deletions cache.h
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
#include "advice.h"
#include "gettext.h"
#include "convert.h"
#include "trace.h"

#include SHA1_HEADER
#ifndef git_SHA_CTX
Expand Down Expand Up @@ -1402,17 +1403,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 */
Expand Down
1 change: 1 addition & 0 deletions commit.h
Original file line number Diff line number Diff line change
Expand Up @@ -271,6 +271,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 *);
Expand Down
1 change: 1 addition & 0 deletions config.mak.uname
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
4 changes: 4 additions & 0 deletions git-compat-util.h
Original file line number Diff line number Diff line change
Expand Up @@ -761,6 +761,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).
Expand Down
2 changes: 2 additions & 0 deletions git.c
Original file line number Diff line number Diff line change
Expand Up @@ -613,6 +613,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:
*
Expand Down
8 changes: 4 additions & 4 deletions pkt-line.c
Original file line number Diff line number Diff line change
Expand Up @@ -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)
{
Expand All @@ -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 */
Expand All @@ -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 */
Expand All @@ -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);
}

Expand Down
Loading

0 comments on commit 9f2de9c

Please sign in to comment.