trace.c 11.6 KB
Newer Older
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20
/*
 * 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
21
 *  along with this program; if not, see <http://www.gnu.org/licenses/>.
22 23 24 25 26
 */

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

27
struct trace_key trace_default_key = { "GIT_TRACE", 0, 0, 0 };
28
struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE);
29
struct trace_key trace_setup_key = TRACE_KEY_INIT(SETUP);
30

31
/* Get a trace file descriptor from "key" env variable. */
32
static int get_trace_fd(struct trace_key *key)
33
{
34 35 36 37 38 39 40
	const char *trace;

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

	trace = getenv(key->key);
41

42 43
	if (!trace || !strcmp(trace, "") ||
	    !strcmp(trace, "0") || !strcasecmp(trace, "false"))
44 45 46 47 48 49
		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)) {
50 51
		int fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666);
		if (fd == -1) {
52
			warning("could not open '%s' for tracing: %s",
53
				trace, strerror(errno));
54
			trace_disable(key);
55 56 57
		} else {
			key->fd = fd;
			key->need_close = 1;
58
		}
59
	} else {
60 61
		warning("unknown trace value for '%s': %s\n"
			"         If you want to trace into a file, then please set %s\n"
62
			"         to an absolute pathname (starting with /)",
63
			key->key, trace, key->key);
64
		trace_disable(key);
65 66
	}

67 68 69
	key->initialized = 1;
	return key->fd;
}
70

71 72 73 74 75 76 77
void trace_disable(struct trace_key *key)
{
	if (key->need_close)
		close(key->fd);
	key->fd = 0;
	key->initialized = 1;
	key->need_close = 0;
78 79
}

80 81
static int prepare_trace_line(const char *file, int line,
			      struct trace_key *key, struct strbuf *buf)
82
{
83
	static struct trace_key trace_bare = TRACE_KEY_INIT(BARE);
84 85 86
	struct timeval tv;
	struct tm tm;
	time_t secs;
87

88 89 90 91 92
	if (!trace_want(key))
		return 0;

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

93 94 95 96
	/* unit tests may want to disable additional trace output */
	if (trace_want(&trace_bare))
		return 1;

97 98 99 100 101 102
	/* 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);
103

104 105 106 107 108 109 110 111
#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

112 113 114
	return 1;
}

115 116
static void trace_write(struct trace_key *key, const void *buf, unsigned len)
{
117 118 119
	if (write_in_full(get_trace_fd(key), buf, len) < 0) {
		warning("unable to write trace for %s: %s",
			key->key, strerror(errno));
120
		trace_disable(key);
121
	}
122 123
}

124 125 126 127
void trace_verbatim(struct trace_key *key, const void *buf, unsigned len)
{
	if (!trace_want(key))
		return;
128
	trace_write(key, buf, len);
129 130
}

131 132
static void print_trace_line(struct trace_key *key, struct strbuf *buf)
{
133
	strbuf_complete_line(buf);
134
	trace_write(key, buf->buf, buf->len);
135 136
}

137 138
static void trace_vprintf_fl(const char *file, int line, struct trace_key *key,
			     const char *format, va_list ap)
139
{
Jeff King's avatar
Jeff King committed
140
	struct strbuf buf = STRBUF_INIT;
141

142
	if (!prepare_trace_line(file, line, key, &buf))
143 144
		return;

145
	strbuf_vaddf(&buf, format, ap);
146
	print_trace_line(key, &buf);
147
	strbuf_release(&buf);
148 149
}

150 151 152
static void trace_argv_vprintf_fl(const char *file, int line,
				  const char **argv, const char *format,
				  va_list ap)
153
{
154
	struct strbuf buf = STRBUF_INIT;
155

156
	if (!prepare_trace_line(file, line, &trace_default_key, &buf))
157 158 159 160
		return;

	strbuf_vaddf(&buf, format, ap);

161
	sq_quote_argv_pretty(&buf, argv);
162
	print_trace_line(&trace_default_key, &buf);
163
	strbuf_release(&buf);
Jeff King's avatar
Jeff King committed
164 165
}

166 167
void trace_strbuf_fl(const char *file, int line, struct trace_key *key,
		     const struct strbuf *data)
Jeff King's avatar
Jeff King committed
168
{
169 170
	struct strbuf buf = STRBUF_INIT;

171
	if (!prepare_trace_line(file, line, key, &buf))
Jeff King's avatar
Jeff King committed
172 173
		return;

174 175
	strbuf_addbuf(&buf, data);
	print_trace_line(key, &buf);
176
	strbuf_release(&buf);
Jeff King's avatar
Jeff King committed
177 178
}

179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197
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;
}

198 199 200 201
static void trace_performance_vprintf_fl(const char *file, int line,
					 uint64_t nanos, const char *format,
					 va_list ap)
{
202
	static const char space[] = "          ";
203 204 205 206 207 208 209 210
	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) {
211 212 213 214
		if (perf_indent >= strlen(space))
			BUG("Too deep indentation");

		strbuf_addf(&buf, ":%.*s ", perf_indent, space);
215 216 217 218
		strbuf_vaddf(&buf, format, ap);
	}

	print_trace_line(&trace_perf_key, &buf);
219
	strbuf_release(&buf);
220 221
}

222 223
#ifndef HAVE_VARIADIC_MACROS

224
void trace_printf(const char *format, ...)
225
{
226
	va_list ap;
227
	va_start(ap, format);
228
	trace_vprintf_fl(NULL, 0, &trace_default_key, format, ap);
229
	va_end(ap);
230
}
231

232 233 234 235
void trace_printf_key(struct trace_key *key, const char *format, ...)
{
	va_list ap;
	va_start(ap, format);
236 237 238 239 240 241 242 243 244
	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);
245
	va_end(ap);
246
}
247

248
void trace_strbuf(struct trace_key *key, const struct strbuf *data)
249 250 251 252
{
	trace_strbuf_fl(NULL, 0, key, data);
}

253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269
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);
}

270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287
void trace_performance_leave(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(NULL, 0, getnanotime() - since,
				     format, ap);
	va_end(ap);
}

288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307
#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);
}

308 309 310 311 312 313 314 315 316
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);
}

317 318 319 320 321 322 323 324 325 326 327 328 329 330 331 332 333 334
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);
}

335 336 337
#endif /* HAVE_VARIADIC_MACROS */


338 339
static const char *quote_crnl(const char *path)
{
340
	static struct strbuf new_path = STRBUF_INIT;
341 342 343 344

	if (!path)
		return NULL;

345 346 347 348 349 350 351
	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;
352
		default:
353
			strbuf_addch(&new_path, *path);
354
		}
355
		path++;
356
	}
357
	return new_path.buf;
358 359 360 361 362
}

/* FIXME: move prefix to startup_info struct and get rid of this arg */
void trace_repo_setup(const char *prefix)
{
363
	const char *git_work_tree;
364
	char *cwd;
365

366
	if (!trace_want(&trace_setup_key))
367 368
		return;

369
	cwd = xgetcwd();
370

371 372 373 374 375 376
	if (!(git_work_tree = get_git_work_tree()))
		git_work_tree = "(null)";

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

377 378 379 380 381
	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));
382 383

	free(cwd);
384
}
385

386
int trace_want(struct trace_key *key)
387
{
388
	return !!get_trace_fd(key);
389
}
390

391
#if defined(HAVE_CLOCK_GETTIME) && defined(HAVE_CLOCK_MONOTONIC)
392 393 394 395 396 397 398 399 400 401 402 403 404 405 406 407 408 409 410 411 412 413 414 415 416 417 418 419 420 421 422 423 424 425 426 427 428 429 430 431 432 433 434 435 436 437 438 439 440 441 442 443 444 445 446 447 448 449 450 451

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).
 */
452
uint64_t getnanotime(void)
453 454 455 456 457 458 459 460 461 462 463 464 465 466 467 468 469 470 471
{
	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;
	}
}
472 473 474 475 476

static struct strbuf command_line = STRBUF_INIT;

static void print_command_performance_atexit(void)
{
477
	trace_performance_leave("git command:%s", command_line.buf);
478 479 480 481 482 483 484
}

void trace_command_performance(const char **argv)
{
	if (!trace_want(&trace_perf_key))
		return;

485
	if (!command_line.len)
486 487 488
		atexit(print_command_performance_atexit);

	strbuf_reset(&command_line);
489
	sq_quote_argv_pretty(&command_line, argv);
490
	trace_performance_enter();
491
}