2006-09-02 16:23:48 +00:00
|
|
|
/*
|
|
|
|
* GIT - The information manager from hell
|
|
|
|
*
|
|
|
|
* Copyright (C) 2000-2002 Michael R. Elkins <me@mutt.org>
|
|
|
|
* Copyright (C) 2002-2004 Oswald Buddenhagen <ossi@users.sf.net>
|
|
|
|
* Copyright (C) 2004 Theodore Y. Ts'o <tytso@mit.edu>
|
|
|
|
* Copyright (C) 2006 Mike McCormack
|
|
|
|
* Copyright (C) 2006 Christian Couder
|
|
|
|
*
|
|
|
|
* This program is free software; you can redistribute it and/or modify
|
|
|
|
* it under the terms of the GNU General Public License as published by
|
|
|
|
* the Free Software Foundation; either version 2 of the License, or
|
|
|
|
* (at your option) any later version.
|
|
|
|
*
|
|
|
|
* This program is distributed in the hope that it will be useful,
|
|
|
|
* but WITHOUT ANY WARRANTY; without even the implied warranty of
|
|
|
|
* MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
|
|
|
|
* GNU General Public License for more details.
|
|
|
|
*
|
|
|
|
* You should have received a copy of the GNU General Public License
|
2017-11-07 05:39:33 +00:00
|
|
|
* along with this program; if not, see <http://www.gnu.org/licenses/>.
|
2006-09-02 16:23:48 +00:00
|
|
|
*/
|
|
|
|
|
|
|
|
#include "cache.h"
|
|
|
|
#include "quote.h"
|
|
|
|
|
2017-11-26 20:11:18 +00:00
|
|
|
struct trace_key trace_default_key = { "GIT_TRACE", 0, 0, 0 };
|
2017-11-26 20:11:19 +00:00
|
|
|
struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);
|
2018-03-30 18:34:59 +00:00
|
|
|
struct trace_key trace_setup_key = TRACE_KEY_INIT(SETUP);
|
2016-08-03 22:56:57 +00:00
|
|
|
|
2011-02-24 14:28:41 +00:00
|
|
|
/* Get a trace file descriptor from "key" env variable. */
|
2020-05-11 17:43:10 +00:00
|
|
|
static int get_trace_fd(struct trace_key *key, const char *override_envvar)
|
2006-09-02 16:23:48 +00:00
|
|
|
{
|
2014-07-12 00:00:06 +00:00
|
|
|
const char *trace;
|
|
|
|
|
|
|
|
/* don't open twice */
|
|
|
|
if (key->initialized)
|
|
|
|
return key->fd;
|
|
|
|
|
2020-05-11 17:43:10 +00:00
|
|
|
trace = override_envvar ? override_envvar : getenv(key->key);
|
2006-09-02 16:23:48 +00:00
|
|
|
|
2006-10-14 14:05:25 +00:00
|
|
|
if (!trace || !strcmp(trace, "") ||
|
|
|
|
!strcmp(trace, "0") || !strcasecmp(trace, "false"))
|
2014-07-12 00:00:06 +00:00
|
|
|
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)) {
|
2006-09-02 16:23:48 +00:00
|
|
|
int fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666);
|
|
|
|
if (fd == -1) {
|
2016-08-05 07:58:38 +00:00
|
|
|
warning("could not open '%s' for tracing: %s",
|
2006-09-02 16:23:48 +00:00
|
|
|
trace, strerror(errno));
|
2016-08-05 07:58:38 +00:00
|
|
|
trace_disable(key);
|
2014-07-12 00:00:06 +00:00
|
|
|
} else {
|
|
|
|
key->fd = fd;
|
|
|
|
key->need_close = 1;
|
2006-09-02 16:23:48 +00:00
|
|
|
}
|
2014-07-12 00:00:06 +00:00
|
|
|
} else {
|
2016-08-03 23:00:23 +00:00
|
|
|
warning("unknown trace value for '%s': %s\n"
|
|
|
|
" If you want to trace into a file, then please set %s\n"
|
2016-08-05 07:58:38 +00:00
|
|
|
" to an absolute pathname (starting with /)",
|
2016-08-03 23:00:23 +00:00
|
|
|
key->key, trace, key->key);
|
2016-08-05 07:58:38 +00:00
|
|
|
trace_disable(key);
|
2006-09-02 16:23:48 +00:00
|
|
|
}
|
|
|
|
|
2014-07-12 00:00:06 +00:00
|
|
|
key->initialized = 1;
|
|
|
|
return key->fd;
|
|
|
|
}
|
2006-09-02 16:23:48 +00:00
|
|
|
|
2020-05-11 17:43:10 +00:00
|
|
|
void trace_override_envvar(struct trace_key *key, const char *value)
|
|
|
|
{
|
|
|
|
trace_disable(key);
|
|
|
|
key->initialized = 0;
|
|
|
|
|
|
|
|
/*
|
|
|
|
* Invoke get_trace_fd() to initialize key using the given value
|
|
|
|
* instead of the value of the environment variable.
|
|
|
|
*/
|
|
|
|
get_trace_fd(key, value);
|
|
|
|
}
|
|
|
|
|
2014-07-12 00:00:06 +00:00
|
|
|
void trace_disable(struct trace_key *key)
|
|
|
|
{
|
|
|
|
if (key->need_close)
|
|
|
|
close(key->fd);
|
|
|
|
key->fd = 0;
|
|
|
|
key->initialized = 1;
|
|
|
|
key->need_close = 0;
|
2006-09-02 16:23:48 +00:00
|
|
|
}
|
|
|
|
|
2014-07-12 00:05:03 +00:00
|
|
|
static int prepare_trace_line(const char *file, int line,
|
|
|
|
struct trace_key *key, struct strbuf *buf)
|
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>
2014-07-12 00:02:18 +00:00
|
|
|
{
|
2014-07-12 00:03:01 +00:00
|
|
|
static struct trace_key trace_bare = TRACE_KEY_INIT(BARE);
|
2014-07-12 00:03:50 +00:00
|
|
|
struct timeval tv;
|
|
|
|
struct tm tm;
|
|
|
|
time_t secs;
|
2014-07-12 00:03:01 +00:00
|
|
|
|
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>
2014-07-12 00:02:18 +00:00
|
|
|
if (!trace_want(key))
|
|
|
|
return 0;
|
|
|
|
|
2014-07-12 00:03:01 +00:00
|
|
|
/* unit tests may want to disable additional trace output */
|
|
|
|
if (trace_want(&trace_bare))
|
|
|
|
return 1;
|
|
|
|
|
2014-07-12 00:03:50 +00:00
|
|
|
/* print current timestamp */
|
|
|
|
gettimeofday(&tv, NULL);
|
|
|
|
secs = tv.tv_sec;
|
|
|
|
localtime_r(&secs, &tm);
|
C99: remove hardcoded-out !HAVE_VARIADIC_MACROS code
Remove the "else" branches of the HAVE_VARIADIC_MACROS macro, which
have been unconditionally omitted since 765dc168882 (git-compat-util:
always enable variadic macros, 2021-01-28).
Since were always omitted, anyone trying to use a compiler without
variadic macro support to compile a git since version
git v2.31.0 or later would have had a compilation error. 10 months
across a few releases since then should have been enough time for
anyone who cared to run into that and report the issue.
In addition to that, for anyone unsetting HAVE_VARIADIC_MACROS we've
been emitting extremely verbose warnings since at least
ee4512ed481 (trace2: create new combined trace facility,
2019-02-22). That's because there is no such thing as a
"region_enter_printf" or "region_leave_printf" format, so at least
under GCC and Clang everything that includes trace.h (almost every
file) emits a couple of warnings about that.
There's a large benefit to being able to have a hard dependency rely
on variadic macros, the code surrounding usage.c is hard to maintain
if we need to write two implementations of everything, and by relying
on "__FILE__" and "__LINE__" along with "__VA_ARGS__" we can in the
future make error(), die() etc. log where they were called from. We've
also recently merged d67fc4bf0ba (Merge branch 'bc/require-c99',
2021-12-10) which further cements our hard dependency on C99.
So let's delete the fallback code, and update our CodingGuidelines to
note that we depend on this. The added bullet-point starts with
lower-case for consistency with other bullet-points in that section.
The diff in "trace.h" is relatively hard to read, since we need to
retain the existing API docs, which were comments on the code used if
HAVE_VARIADIC_MACROS was not defined.
Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
2022-02-21 16:05:27 +00:00
|
|
|
strbuf_addf(buf, "%02d:%02d:%02d.%06ld %s:%d", tm.tm_hour, tm.tm_min,
|
|
|
|
tm.tm_sec, (long) tv.tv_usec, file, line);
|
2014-07-12 00:05:03 +00:00
|
|
|
/* align trace output (column 40 catches most files names in git) */
|
|
|
|
while (buf->len < 40)
|
|
|
|
strbuf_addch(buf, ' ');
|
|
|
|
|
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>
2014-07-12 00:02:18 +00:00
|
|
|
return 1;
|
|
|
|
}
|
|
|
|
|
trace: stop using write_or_whine_pipe()
The write_or_whine_pipe function does two things:
1. it checks for EPIPE and converts it into a signal death
2. it prints a message to stderr on error
The first thing does not help us, and actively hurts.
Generally we would simply die from SIGPIPE in this case,
unless somebody has taken the time to ignore SIGPIPE for the
whole process. And if they _did_ do that, it seems rather
silly for the trace code, which otherwise takes pains to
continue even in the face of errors (e.g., by not using
write_or_die!), to take down the whole process for one
specific type of error.
Nor does the second thing help us; it just makes it harder
to write our error message, because we have to feed bits of
it as an argument to write_or_whine_pipe(). Translators
never get to see the full message, and it's hard for us to
customize it.
Let's switch to just using write_in_full() and writing our
own error string. For now, the error is identical to what
write_or_whine_pipe() would say, but now that it's more
under our control, we can improve it in future patches.
Signed-off-by: Jeff King <peff@peff.net>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
2016-08-03 22:58:00 +00:00
|
|
|
static void trace_write(struct trace_key *key, const void *buf, unsigned len)
|
|
|
|
{
|
2020-05-11 17:43:10 +00:00
|
|
|
if (write_in_full(get_trace_fd(key, NULL), buf, len) < 0) {
|
2016-08-03 23:00:32 +00:00
|
|
|
warning("unable to write trace for %s: %s",
|
|
|
|
key->key, strerror(errno));
|
trace: disable key after write error
If we get a write error writing to a trace descriptor, the
error isn't likely to go away if we keep writing. Instead,
you'll just get the same error over and over. E.g., try:
GIT_TRACE_PACKET=42 git ls-remote >/dev/null
You don't really need to see:
warning: unable to write trace for GIT_TRACE_PACKET: Bad file descriptor
hundreds of times. We could fallback to tracing to stderr,
as we do in the error code-path for open(), but there's not
much point. If the user fed us a bogus descriptor, they're
probably better off fixing their invocation. And if they
didn't, and we saw a transient error (e.g., ENOSPC writing
to a file), it probably doesn't help anybody to have half of
the trace in a file, and half on stderr.
Signed-off-by: Jeff King <peff@peff.net>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
2016-08-03 23:01:04 +00:00
|
|
|
trace_disable(key);
|
2016-08-03 23:00:32 +00:00
|
|
|
}
|
trace: stop using write_or_whine_pipe()
The write_or_whine_pipe function does two things:
1. it checks for EPIPE and converts it into a signal death
2. it prints a message to stderr on error
The first thing does not help us, and actively hurts.
Generally we would simply die from SIGPIPE in this case,
unless somebody has taken the time to ignore SIGPIPE for the
whole process. And if they _did_ do that, it seems rather
silly for the trace code, which otherwise takes pains to
continue even in the face of errors (e.g., by not using
write_or_die!), to take down the whole process for one
specific type of error.
Nor does the second thing help us; it just makes it harder
to write our error message, because we have to feed bits of
it as an argument to write_or_whine_pipe(). Translators
never get to see the full message, and it's hard for us to
customize it.
Let's switch to just using write_in_full() and writing our
own error string. For now, the error is identical to what
write_or_whine_pipe() would say, but now that it's more
under our control, we can improve it in future patches.
Signed-off-by: Jeff King <peff@peff.net>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
2016-08-03 22:58:00 +00:00
|
|
|
}
|
|
|
|
|
2015-06-16 17:23:20 +00:00
|
|
|
void trace_verbatim(struct trace_key *key, const void *buf, unsigned len)
|
|
|
|
{
|
|
|
|
if (!trace_want(key))
|
|
|
|
return;
|
trace: stop using write_or_whine_pipe()
The write_or_whine_pipe function does two things:
1. it checks for EPIPE and converts it into a signal death
2. it prints a message to stderr on error
The first thing does not help us, and actively hurts.
Generally we would simply die from SIGPIPE in this case,
unless somebody has taken the time to ignore SIGPIPE for the
whole process. And if they _did_ do that, it seems rather
silly for the trace code, which otherwise takes pains to
continue even in the face of errors (e.g., by not using
write_or_die!), to take down the whole process for one
specific type of error.
Nor does the second thing help us; it just makes it harder
to write our error message, because we have to feed bits of
it as an argument to write_or_whine_pipe(). Translators
never get to see the full message, and it's hard for us to
customize it.
Let's switch to just using write_in_full() and writing our
own error string. For now, the error is identical to what
write_or_whine_pipe() would say, but now that it's more
under our control, we can improve it in future patches.
Signed-off-by: Jeff King <peff@peff.net>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
2016-08-03 22:58:00 +00:00
|
|
|
trace_write(key, buf, len);
|
2015-06-16 17:23:20 +00:00
|
|
|
}
|
|
|
|
|
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>
2014-07-12 00:02:18 +00:00
|
|
|
static void print_trace_line(struct trace_key *key, struct strbuf *buf)
|
|
|
|
{
|
2014-12-12 19:16:38 +00:00
|
|
|
strbuf_complete_line(buf);
|
trace: stop using write_or_whine_pipe()
The write_or_whine_pipe function does two things:
1. it checks for EPIPE and converts it into a signal death
2. it prints a message to stderr on error
The first thing does not help us, and actively hurts.
Generally we would simply die from SIGPIPE in this case,
unless somebody has taken the time to ignore SIGPIPE for the
whole process. And if they _did_ do that, it seems rather
silly for the trace code, which otherwise takes pains to
continue even in the face of errors (e.g., by not using
write_or_die!), to take down the whole process for one
specific type of error.
Nor does the second thing help us; it just makes it harder
to write our error message, because we have to feed bits of
it as an argument to write_or_whine_pipe(). Translators
never get to see the full message, and it's hard for us to
customize it.
Let's switch to just using write_in_full() and writing our
own error string. For now, the error is identical to what
write_or_whine_pipe() would say, but now that it's more
under our control, we can improve it in future patches.
Signed-off-by: Jeff King <peff@peff.net>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
2016-08-03 22:58:00 +00:00
|
|
|
trace_write(key, buf->buf, buf->len);
|
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>
2014-07-12 00:02:18 +00:00
|
|
|
}
|
|
|
|
|
2014-07-12 00:05:03 +00:00
|
|
|
static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
|
|
|
|
const char *format, va_list ap)
|
2006-09-02 16:23:48 +00:00
|
|
|
{
|
2011-02-26 05:08:53 +00:00
|
|
|
struct strbuf buf = STRBUF_INIT;
|
2006-09-02 16:23:48 +00:00
|
|
|
|
2014-07-12 00:05:03 +00:00
|
|
|
if (!prepare_trace_line(file, line, key, &buf))
|
2006-09-02 16:23:48 +00:00
|
|
|
return;
|
|
|
|
|
2014-06-11 07:57:23 +00:00
|
|
|
strbuf_vaddf(&buf, format, ap);
|
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>
2014-07-12 00:02:18 +00:00
|
|
|
print_trace_line(key, &buf);
|
2018-01-15 10:59:45 +00:00
|
|
|
strbuf_release(&buf);
|
2006-09-02 16:23:48 +00:00
|
|
|
}
|
|
|
|
|
2014-07-12 00:05:03 +00:00
|
|
|
static void trace_argv_vprintf_fl(const char *file, int line,
|
|
|
|
const char **argv, const char *format,
|
|
|
|
va_list ap)
|
2011-02-24 14:28:41 +00:00
|
|
|
{
|
2014-07-12 00:04:29 +00:00
|
|
|
struct strbuf buf = STRBUF_INIT;
|
2011-02-24 14:28:41 +00:00
|
|
|
|
2017-11-26 20:11:18 +00:00
|
|
|
if (!prepare_trace_line(file, line, &trace_default_key, &buf))
|
2014-07-12 00:04:29 +00:00
|
|
|
return;
|
|
|
|
|
|
|
|
strbuf_vaddf(&buf, format, ap);
|
|
|
|
|
2018-01-15 10:59:44 +00:00
|
|
|
sq_quote_argv_pretty(&buf, argv);
|
2017-11-26 20:11:18 +00:00
|
|
|
print_trace_line(&trace_default_key, &buf);
|
2018-01-15 10:59:45 +00:00
|
|
|
strbuf_release(&buf);
|
2011-02-24 14:28:15 +00:00
|
|
|
}
|
|
|
|
|
2014-07-12 00:05:03 +00:00
|
|
|
void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
|
|
|
|
const struct strbuf *data)
|
2011-02-24 14:29:50 +00:00
|
|
|
{
|
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>
2014-07-12 00:02:18 +00:00
|
|
|
struct strbuf buf = STRBUF_INIT;
|
|
|
|
|
2014-07-12 00:05:03 +00:00
|
|
|
if (!prepare_trace_line(file, line, key, &buf))
|
2011-02-24 14:29:50 +00:00
|
|
|
return;
|
|
|
|
|
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>
2014-07-12 00:02:18 +00:00
|
|
|
strbuf_addbuf(&buf, data);
|
|
|
|
print_trace_line(key, &buf);
|
2018-01-15 10:59:45 +00:00
|
|
|
strbuf_release(&buf);
|
2011-02-24 14:29:50 +00:00
|
|
|
}
|
|
|
|
|
2018-08-18 14:41:22 +00:00
|
|
|
static uint64_t perf_start_times[10];
|
|
|
|
static int perf_indent;
|
|
|
|
|
|
|
|
uint64_t trace_performance_enter(void)
|
|
|
|
{
|
|
|
|
uint64_t now;
|
|
|
|
|
|
|
|
if (!trace_want(&trace_perf_key))
|
|
|
|
return 0;
|
|
|
|
|
|
|
|
now = getnanotime();
|
|
|
|
perf_start_times[perf_indent] = now;
|
|
|
|
if (perf_indent + 1 < ARRAY_SIZE(perf_start_times))
|
|
|
|
perf_indent++;
|
|
|
|
else
|
|
|
|
BUG("Too deep indentation");
|
|
|
|
return now;
|
|
|
|
}
|
|
|
|
|
2014-07-12 00:06:28 +00:00
|
|
|
static void trace_performance_vprintf_fl(const char *file, int line,
|
|
|
|
uint64_t nanos, const char *format,
|
|
|
|
va_list ap)
|
|
|
|
{
|
2018-08-18 14:41:22 +00:00
|
|
|
static const char space[] = " ";
|
2014-07-12 00:06:28 +00:00
|
|
|
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) {
|
2018-08-18 14:41:22 +00:00
|
|
|
if (perf_indent >= strlen(space))
|
|
|
|
BUG("Too deep indentation");
|
|
|
|
|
|
|
|
strbuf_addf(&buf, ":%.*s ", perf_indent, space);
|
2014-07-12 00:06:28 +00:00
|
|
|
strbuf_vaddf(&buf, format, ap);
|
|
|
|
}
|
|
|
|
|
|
|
|
print_trace_line(&trace_perf_key, &buf);
|
2018-01-15 10:59:45 +00:00
|
|
|
strbuf_release(&buf);
|
2014-07-12 00:06:28 +00:00
|
|
|
}
|
|
|
|
|
2014-07-12 00:05:03 +00:00
|
|
|
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);
|
|
|
|
}
|
|
|
|
|
2014-07-12 00:06:28 +00:00
|
|
|
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);
|
|
|
|
}
|
|
|
|
|
2018-08-18 14:41:22 +00:00
|
|
|
void trace_performance_leave_fl(const char *file, int line,
|
|
|
|
uint64_t nanos, const char *format, ...)
|
|
|
|
{
|
|
|
|
va_list ap;
|
|
|
|
uint64_t since;
|
|
|
|
|
|
|
|
if (perf_indent)
|
|
|
|
perf_indent--;
|
|
|
|
|
|
|
|
if (!format) /* Allow callers to leave without tracing anything */
|
|
|
|
return;
|
|
|
|
|
|
|
|
since = perf_start_times[perf_indent];
|
|
|
|
va_start(ap, format);
|
|
|
|
trace_performance_vprintf_fl(file, line, nanos - since, format, ap);
|
|
|
|
va_end(ap);
|
|
|
|
}
|
|
|
|
|
2010-11-26 15:31:57 +00:00
|
|
|
static const char *quote_crnl(const char *path)
|
|
|
|
{
|
2015-09-24 21:05:54 +00:00
|
|
|
static struct strbuf new_path = STRBUF_INIT;
|
2010-11-26 15:31:57 +00:00
|
|
|
|
|
|
|
if (!path)
|
|
|
|
return NULL;
|
|
|
|
|
2015-09-24 21:05:54 +00:00
|
|
|
strbuf_reset(&new_path);
|
|
|
|
|
|
|
|
while (*path) {
|
|
|
|
switch (*path) {
|
|
|
|
case '\\': strbuf_addstr(&new_path, "\\\\"); break;
|
|
|
|
case '\n': strbuf_addstr(&new_path, "\\n"); break;
|
|
|
|
case '\r': strbuf_addstr(&new_path, "\\r"); break;
|
2010-11-26 15:31:57 +00:00
|
|
|
default:
|
2015-09-24 21:05:54 +00:00
|
|
|
strbuf_addch(&new_path, *path);
|
2010-11-26 15:31:57 +00:00
|
|
|
}
|
2015-09-24 21:05:54 +00:00
|
|
|
path++;
|
2010-11-26 15:31:57 +00:00
|
|
|
}
|
2015-09-24 21:05:54 +00:00
|
|
|
return new_path.buf;
|
2010-11-26 15:31:57 +00:00
|
|
|
}
|
|
|
|
|
2023-02-19 00:25:27 +00:00
|
|
|
void trace_repo_setup(void)
|
2010-11-26 15:31:57 +00:00
|
|
|
{
|
2023-02-19 00:25:27 +00:00
|
|
|
const char *git_work_tree, *prefix = startup_info->prefix;
|
2014-07-28 18:30:39 +00:00
|
|
|
char *cwd;
|
2010-11-26 15:31:57 +00:00
|
|
|
|
2018-03-30 18:34:59 +00:00
|
|
|
if (!trace_want(&trace_setup_key))
|
2010-11-26 15:31:57 +00:00
|
|
|
return;
|
|
|
|
|
2014-07-28 18:30:39 +00:00
|
|
|
cwd = xgetcwd();
|
2010-11-26 15:31:57 +00:00
|
|
|
|
2011-01-06 00:30:01 +00:00
|
|
|
if (!(git_work_tree = get_git_work_tree()))
|
|
|
|
git_work_tree = "(null)";
|
|
|
|
|
2023-02-19 00:25:27 +00:00
|
|
|
if (!startup_info->prefix)
|
2011-01-06 00:30:01 +00:00
|
|
|
prefix = "(null)";
|
|
|
|
|
2018-03-30 18:34:59 +00:00
|
|
|
trace_printf_key(&trace_setup_key, "setup: git_dir: %s\n", quote_crnl(get_git_dir()));
|
|
|
|
trace_printf_key(&trace_setup_key, "setup: git_common_dir: %s\n", quote_crnl(get_git_common_dir()));
|
|
|
|
trace_printf_key(&trace_setup_key, "setup: worktree: %s\n", quote_crnl(git_work_tree));
|
|
|
|
trace_printf_key(&trace_setup_key, "setup: cwd: %s\n", quote_crnl(cwd));
|
|
|
|
trace_printf_key(&trace_setup_key, "setup: prefix: %s\n", quote_crnl(prefix));
|
2014-07-28 18:30:39 +00:00
|
|
|
|
|
|
|
free(cwd);
|
2010-11-26 15:31:57 +00:00
|
|
|
}
|
2011-02-24 14:28:59 +00:00
|
|
|
|
2014-07-12 00:00:06 +00:00
|
|
|
int trace_want(struct trace_key *key)
|
2011-02-24 14:28:59 +00:00
|
|
|
{
|
2020-05-11 17:43:10 +00:00
|
|
|
return !!get_trace_fd(key, NULL);
|
2011-02-24 14:28:59 +00:00
|
|
|
}
|
2014-07-12 00:05:42 +00:00
|
|
|
|
2015-01-08 20:00:56 +00:00
|
|
|
#if defined(HAVE_CLOCK_GETTIME) && defined(HAVE_CLOCK_MONOTONIC)
|
2014-07-12 00:05:42 +00:00
|
|
|
|
|
|
|
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).
|
|
|
|
*/
|
2014-09-28 07:50:26 +00:00
|
|
|
uint64_t getnanotime(void)
|
2014-07-12 00:05:42 +00:00
|
|
|
{
|
|
|
|
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;
|
|
|
|
}
|
|
|
|
}
|
2014-07-12 00:07:01 +00:00
|
|
|
|
|
|
|
static struct strbuf command_line = STRBUF_INIT;
|
|
|
|
|
|
|
|
static void print_command_performance_atexit(void)
|
|
|
|
{
|
2018-08-18 14:41:22 +00:00
|
|
|
trace_performance_leave("git command:%s", command_line.buf);
|
2014-07-12 00:07:01 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
void trace_command_performance(const char **argv)
|
|
|
|
{
|
|
|
|
if (!trace_want(&trace_perf_key))
|
|
|
|
return;
|
|
|
|
|
2018-08-18 14:41:22 +00:00
|
|
|
if (!command_line.len)
|
2014-07-12 00:07:01 +00:00
|
|
|
atexit(print_command_performance_atexit);
|
|
|
|
|
|
|
|
strbuf_reset(&command_line);
|
2018-01-15 10:59:44 +00:00
|
|
|
sq_quote_argv_pretty(&command_line, argv);
|
2018-08-18 14:41:22 +00:00
|
|
|
trace_performance_enter();
|
2014-07-12 00:07:01 +00:00
|
|
|
}
|