git/trace.h

140 lines
4.3 KiB
C
Raw Normal View History

#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;
};
extern struct trace_key trace_default_key;
#define TRACE_KEY_INIT(name) { "GIT_TRACE_" #name, 0, 0, 0 }
extern struct trace_key trace_perf_key;
extern void trace_repo_setup(const char *prefix);
extern int trace_want(struct trace_key *key);
extern void trace_disable(struct trace_key *key);
trace: add high resolution timer function to debug performance issues Add a getnanotime() function that returns nanoseconds since 01/01/1970 as unsigned 64-bit integer (i.e. overflows in july 2554). This is easier to work with than e.g. struct timeval or struct timespec. Basing the timer on the epoch allows using the results with other time-related APIs. To simplify adaption to different platforms, split the implementation into a common getnanotime() and a platform-specific highres_nanos() function. The common getnanotime() function handles errors, falling back to gettimeofday() if highres_nanos() isn't implemented or doesn't work. getnanotime() is also responsible for normalizing to the epoch. The offset to the system clock is calculated only once on initialization, i.e. manually setting the system clock has no impact on the timer (except if the fallback gettimeofday() is in use). Git processes are typically short lived, so we don't need to handle clock drift. The highres_nanos() function returns monotonically increasing nanoseconds relative to some arbitrary point in time (e.g. system boot), or 0 on failure. Providing platform-specific implementations should be relatively easy, e.g. adapting to clock_gettime() as defined by the POSIX realtime extensions is seven lines of code. This version includes highres_nanos() implementations for: * Linux: using clock_gettime(CLOCK_MONOTONIC) * Windows: using QueryPerformanceCounter() Todo: * enable clock_gettime() on more platforms * add Mac OSX version, e.g. using mach_absolute_time + mach_timebase_info Signed-off-by: Karsten Blees <blees@dcon.de> Signed-off-by: Junio C Hamano <gitster@pobox.com>
2014-07-12 08:05:42 +08:00
extern uint64_t getnanotime(void);
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>
2014-07-12 08:07:01 +08:00
extern void trace_command_performance(const char **argv);
extern void trace_verbatim(struct trace_key *key, const void *buf, unsigned len);
#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_key(key, ...) \
do { \
if (trace_pass_fl(key)) \
trace_printf_key_fl(TRACE_CONTEXT, __LINE__, key, \
__VA_ARGS__); \
} while (0)
#define trace_printf(...) trace_printf_key(&trace_default_key, __VA_ARGS__)
#define trace_argv_printf(argv, ...) \
do { \
if (trace_pass_fl(&trace_default_key)) \
trace_argv_printf_fl(TRACE_CONTEXT, __LINE__, \
argv, __VA_ARGS__); \
} while (0)
#define trace_strbuf(key, data) \
do { \
if (trace_pass_fl(key)) \
trace_strbuf_fl(TRACE_CONTEXT, __LINE__, key, data);\
} while (0)
#define trace_performance(nanos, ...) \
do { \
if (trace_pass_fl(&trace_perf_key)) \
trace_performance_fl(TRACE_CONTEXT, __LINE__, nanos,\
__VA_ARGS__); \
} while (0)
#define trace_performance_since(start, ...) \
do { \
if (trace_pass_fl(&trace_perf_key)) \
trace_performance_fl(TRACE_CONTEXT, __LINE__, \
getnanotime() - (start), \
__VA_ARGS__); \
} while (0)
/* 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, ...);
static inline int trace_pass_fl(struct trace_key *key)
{
return key->fd || !key->initialized;
}
#endif /* HAVE_VARIADIC_MACROS */
#endif /* TRACE_H */