trace.c 10.4 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

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

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

	trace = getenv(key->key);
40

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

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

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

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

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

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

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

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

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

111 112 113
	return 1;
}

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

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

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

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

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

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

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

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

	strbuf_vaddf(&buf, format, ap);

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

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

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

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

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

198 199
#ifndef HAVE_VARIADIC_MACROS

200
void trace_printf(const char *format, ...)
201
{
202
	va_list ap;
203
	va_start(ap, format);
204
	trace_vprintf_fl(NULL, 0, &trace_default_key, format, ap);
205
	va_end(ap);
206
}
207

208 209 210 211
void trace_printf_key(struct trace_key *key, const char *format, ...)
{
	va_list ap;
	va_start(ap, format);
212 213 214 215 216 217 218 219 220
	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);
221
	va_end(ap);
222
}
223

224
void trace_strbuf(struct trace_key *key, const struct strbuf *data)
225 226 227 228
{
	trace_strbuf_fl(NULL, 0, key, data);
}

229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245
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);
}

246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265
#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);
}

266 267 268 269 270 271 272 273 274
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);
}

275 276 277
#endif /* HAVE_VARIADIC_MACROS */


278 279
static const char *quote_crnl(const char *path)
{
280
	static struct strbuf new_path = STRBUF_INIT;
281 282 283 284

	if (!path)
		return NULL;

285 286 287 288 289 290 291
	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;
292
		default:
293
			strbuf_addch(&new_path, *path);
294
		}
295
		path++;
296
	}
297
	return new_path.buf;
298 299 300 301 302
}

/* FIXME: move prefix to startup_info struct and get rid of this arg */
void trace_repo_setup(const char *prefix)
{
303
	static struct trace_key key = TRACE_KEY_INIT(SETUP);
304
	const char *git_work_tree;
305
	char *cwd;
306

307
	if (!trace_want(&key))
308 309
		return;

310
	cwd = xgetcwd();
311

312 313 314 315 316 317
	if (!(git_work_tree = get_git_work_tree()))
		git_work_tree = "(null)";

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

318
	trace_printf_key(&key, "setup: git_dir: %s\n", quote_crnl(get_git_dir()));
319
	trace_printf_key(&key, "setup: git_common_dir: %s\n", quote_crnl(get_git_common_dir()));
320 321 322
	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));
323 324

	free(cwd);
325
}
326

327
int trace_want(struct trace_key *key)
328
{
329
	return !!get_trace_fd(key);
330
}
331

332
#if defined(HAVE_CLOCK_GETTIME) && defined(HAVE_CLOCK_MONOTONIC)
333 334 335 336 337 338 339 340 341 342 343 344 345 346 347 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

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).
 */
393
uint64_t getnanotime(void)
394 395 396 397 398 399 400 401 402 403 404 405 406 407 408 409 410 411 412
{
	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;
	}
}
413 414 415 416 417 418 419 420 421 422 423 424 425 426 427 428 429 430 431

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);
Jeff King's avatar
Jeff King committed
432
	sq_quote_argv_pretty(&command_line, argv);
433 434
	command_start_time = getnanotime();
}