trace.c 10.8 KB
Newer Older
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27
/*
 * 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
 *  along with this program; if not, write to the Free Software
 *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA  02111-1307  USA
 */

#include "cache.h"
#include "quote.h"

28 29 30 31 32 33 34 35 36 37 38 39 40
/*
 * "Normalize" a key argument by converting NULL to our trace_default,
 * and otherwise passing through the value. All caller-facing functions
 * should normalize their inputs in this way, though most get it
 * for free by calling get_trace_fd() (directly or indirectly).
 */
static void normalize_trace_key(struct trace_key **key)
{
	static struct trace_key trace_default = { "GIT_TRACE" };
	if (!*key)
		*key = &trace_default;
}

41
/* Get a trace file descriptor from "key" env variable. */
42
static int get_trace_fd(struct trace_key *key)
43
{
44 45
	const char *trace;

46
	normalize_trace_key(&key);
47 48 49 50 51 52

	/* don't open twice */
	if (key->initialized)
		return key->fd;

	trace = getenv(key->key);
53

54 55
	if (!trace || !strcmp(trace, "") ||
	    !strcmp(trace, "0") || !strcasecmp(trace, "false"))
56 57 58 59 60 61
		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)) {
62 63
		int fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666);
		if (fd == -1) {
64
			warning("could not open '%s' for tracing: %s",
65
				trace, strerror(errno));
66
			trace_disable(key);
67 68 69
		} else {
			key->fd = fd;
			key->need_close = 1;
70
		}
71
	} else {
72 73
		warning("unknown trace value for '%s': %s\n"
			"         If you want to trace into a file, then please set %s\n"
74
			"         to an absolute pathname (starting with /)",
75
			key->key, trace, key->key);
76
		trace_disable(key);
77 78
	}

79 80 81
	key->initialized = 1;
	return key->fd;
}
82

83 84
void trace_disable(struct trace_key *key)
{
85 86
	normalize_trace_key(&key);

87 88 89 90 91
	if (key->need_close)
		close(key->fd);
	key->fd = 0;
	key->initialized = 1;
	key->need_close = 0;
92 93
}

94 95
static int prepare_trace_line(const char *file, int line,
			      struct trace_key *key, struct strbuf *buf)
96
{
97
	static struct trace_key trace_bare = TRACE_KEY_INIT(BARE);
98 99 100
	struct timeval tv;
	struct tm tm;
	time_t secs;
101

102 103 104 105 106
	if (!trace_want(key))
		return 0;

	set_try_to_free_routine(NULL);	/* is never reset */

107 108 109 110
	/* unit tests may want to disable additional trace output */
	if (trace_want(&trace_bare))
		return 1;

111 112 113 114 115 116
	/* 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);
117

118 119 120 121 122 123 124 125
#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

126 127 128
	return 1;
}

129 130
static void trace_write(struct trace_key *key, const void *buf, unsigned len)
{
131 132 133 134
	if (write_in_full(get_trace_fd(key), buf, len) < 0) {
		normalize_trace_key(&key);
		warning("unable to write trace for %s: %s",
			key->key, strerror(errno));
135
		trace_disable(key);
136
	}
137 138
}

139 140 141 142
void trace_verbatim(struct trace_key *key, const void *buf, unsigned len)
{
	if (!trace_want(key))
		return;
143
	trace_write(key, buf, len);
144 145
}

146 147
static void print_trace_line(struct trace_key *key, struct strbuf *buf)
{
148
	strbuf_complete_line(buf);
149
	trace_write(key, buf->buf, buf->len);
150 151 152
	strbuf_release(buf);
}

153 154
static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
			     const char *format, va_list ap)
155
{
Jeff King's avatar
Jeff King committed
156
	struct strbuf buf = STRBUF_INIT;
157

158
	if (!prepare_trace_line(file, line, key, &buf))
159 160
		return;

161
	strbuf_vaddf(&buf, format, ap);
162
	print_trace_line(key, &buf);
163 164
}

165 166 167
static void trace_argv_vprintf_fl(const char *file, int line,
				  const char **argv, const char *format,
				  va_list ap)
168
{
169
	struct strbuf buf = STRBUF_INIT;
170

171
	if (!prepare_trace_line(file, line, NULL, &buf))
172 173 174 175 176 177
		return;

	strbuf_vaddf(&buf, format, ap);

	sq_quote_argv(&buf, argv, 0);
	print_trace_line(NULL, &buf);
Jeff King's avatar
Jeff King committed
178 179
}

180 181
void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
		     const struct strbuf *data)
Jeff King's avatar
Jeff King committed
182
{
183 184
	struct strbuf buf = STRBUF_INIT;

185
	if (!prepare_trace_line(file, line, key, &buf))
Jeff King's avatar
Jeff King committed
186 187
		return;

188 189
	strbuf_addbuf(&buf, data);
	print_trace_line(key, &buf);
Jeff King's avatar
Jeff King committed
190 191
}

192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212
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);
}

213 214
#ifndef HAVE_VARIADIC_MACROS

215
void trace_printf(const char *format, ...)
216
{
217
	va_list ap;
218
	va_start(ap, format);
219
	trace_vprintf_fl(NULL, 0, NULL, format, ap);
220
	va_end(ap);
221
}
222

223 224 225 226
void trace_printf_key(struct trace_key *key, const char *format, ...)
{
	va_list ap;
	va_start(ap, format);
227 228 229 230 231 232 233 234 235
	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);
236
	va_end(ap);
237
}
238

239
void trace_strbuf(struct trace_key *key, const struct strbuf *data)
240 241 242 243
{
	trace_strbuf_fl(NULL, 0, key, data);
}

244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260
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);
}

261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280
#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);
}

281 282 283 284 285 286 287 288 289
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);
}

290 291 292
#endif /* HAVE_VARIADIC_MACROS */


293 294
static const char *quote_crnl(const char *path)
{
295
	static struct strbuf new_path = STRBUF_INIT;
296 297 298 299

	if (!path)
		return NULL;

300 301 302 303 304 305 306
	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;
307
		default:
308
			strbuf_addch(&new_path, *path);
309
		}
310
		path++;
311
	}
312
	return new_path.buf;
313 314 315 316 317
}

/* FIXME: move prefix to startup_info struct and get rid of this arg */
void trace_repo_setup(const char *prefix)
{
318
	static struct trace_key key = TRACE_KEY_INIT(SETUP);
319
	const char *git_work_tree;
320
	char *cwd;
321

322
	if (!trace_want(&key))
323 324
		return;

325
	cwd = xgetcwd();
326

327 328 329 330 331 332
	if (!(git_work_tree = get_git_work_tree()))
		git_work_tree = "(null)";

	if (!prefix)
		prefix = "(null)";

333
	trace_printf_key(&key, "setup: git_dir: %s\n", quote_crnl(get_git_dir()));
334
	trace_printf_key(&key, "setup: git_common_dir: %s\n", quote_crnl(get_git_common_dir()));
335 336 337
	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));
338 339

	free(cwd);
340
}
341

342
int trace_want(struct trace_key *key)
343
{
344
	return !!get_trace_fd(key);
345
}
346

347
#if defined(HAVE_CLOCK_GETTIME) && defined(HAVE_CLOCK_MONOTONIC)
348 349 350 351 352 353 354 355 356 357 358 359 360 361 362 363 364 365 366 367 368 369 370 371 372 373 374 375 376 377 378 379 380 381 382 383 384 385 386 387 388 389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404 405 406 407

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).
 */
408
uint64_t getnanotime(void)
409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424 425 426 427
{
	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;
	}
}
428 429 430 431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448 449

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