undef/git-commit-vandalism
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

Merge branch 'kb/perf-trace'

Browse Source 
* 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
This commit is contained in:
Junio C Hamano 2014-07-22 10:59:18 -07:00
commit 9f2de9c121
17 changed files with 643 additions and 190 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

59
Documentation/git.txt
View File

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

97
Documentation/technical/api-trace.txt Normal file
View File

@ -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
Makefile
View File

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

2
builtin/receive-pack.c
View File

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

13
cache.h
View File

@ -7,6 +7,7 @@
#include "advice.h"
#include "gettext.h"
#include "convert.h"
#include "trace.h"
#include SHA1_HEADER
#ifndef git_SHA_CTX
@ -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 */

1
commit.h
View File

@ -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 *);

1
config.mak.uname
View File

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

4
git-compat-util.h
View File

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

2
git.c
View File

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

8
pkt-line.c
View File

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

71
progress.c
View File

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

30
sha1_file.c
View File

@ -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
@ -2086,27 +2083,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;
@ -2131,8 +2110,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 (;;) {

10
shallow.c
View File

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

4
t/test-lib.sh
View File

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

397
trace.c
View File

@ -26,110 +26,250 @@
#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 *fmt, va_list ap)
static int prepare_trace_line(const char *file, int line,
struct trace_key *key, struct strbuf *buf)
{
struct strbuf buf = STRBUF_INIT;
static struct trace_key trace_bare = TRACE_KEY_INIT(BARE);
struct timeval tv;
struct tm tm;
time_t secs;
if (!trace_want(key))
return;
return 0;
set_try_to_free_routine(NULL); /* is never reset */
strbuf_vaddf(&buf, fmt, ap);
trace_strbuf(key, &buf);
strbuf_release(&buf);
/* unit tests may want to disable additional trace output */
if (trace_want(&trace_bare))
return 1;
/* 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);
#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;
}
__attribute__((format (printf, 2, 3)))
void trace_printf_key(const char *key, const char *fmt, ...)
static void print_trace_line(struct trace_key *key, struct strbuf *buf)
{
va_list ap;
va_start(ap, fmt);
trace_vprintf(key, fmt, ap);
va_end(ap);
/* 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);
}
void trace_printf(const char *fmt, ...)
{
va_list ap;
va_start(ap, fmt);
trace_vprintf("GIT_TRACE", fmt, ap);
va_end(ap);
}
void trace_strbuf(const char *key, const struct strbuf *buf)
{
int fd, need_close = 0;
fd = get_trace_fd(key, &need_close);
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 *fmt, ...)
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;
va_list ap;
int fd, need_close = 0;
fd = get_trace_fd("GIT_TRACE", &need_close);
if (!fd)
if (!prepare_trace_line(file, line, key, &buf))
return;
set_try_to_free_routine(NULL); /* is never reset */
va_start(ap, fmt);
strbuf_vaddf(&buf, fmt, ap);
va_end(ap);
strbuf_vaddf(&buf, format, ap);
print_trace_line(key, &buf);
}
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;
if (!prepare_trace_line(file, line, NULL, &buf))
return;
strbuf_vaddf(&buf, format, 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);
if (need_close)
close(fd);
print_trace_line(NULL, &buf);
}
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(file, line, key, &buf))
return;
strbuf_addbuf(&buf, data);
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, ...)
{
va_list ap;
va_start(ap, format);
trace_vprintf_fl(NULL, 0, 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_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);
}
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,
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);
}
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 */
static const char *quote_crnl(const char *path)
{
static char new_path[PATH_MAX];
@ -156,11 +296,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))
@ -172,18 +312,117 @@ 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);
}
#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;
}
}
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();
}

113
trace.h Normal file
View File

@ -0,0 +1,113 @@
#ifndef TRACE_H
#define TRACE_H
#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 }
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
__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);
/* 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
/*
* 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)
#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,
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);
__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 */
#endif /* TRACE_H */

14
wt-status.c
View File

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