]>
Commit | Line | Data |
---|---|---|
1 | /* | |
2 | * GIT - The information manager from hell | |
3 | * | |
4 | * Copyright (C) 2000-2002 Michael R. Elkins <me@mutt.org> | |
5 | * Copyright (C) 2002-2004 Oswald Buddenhagen <ossi@users.sf.net> | |
6 | * Copyright (C) 2004 Theodore Y. Ts'o <tytso@mit.edu> | |
7 | * Copyright (C) 2006 Mike McCormack | |
8 | * Copyright (C) 2006 Christian Couder | |
9 | * | |
10 | * This program is free software; you can redistribute it and/or modify | |
11 | * it under the terms of the GNU General Public License as published by | |
12 | * the Free Software Foundation; either version 2 of the License, or | |
13 | * (at your option) any later version. | |
14 | * | |
15 | * This program is distributed in the hope that it will be useful, | |
16 | * but WITHOUT ANY WARRANTY; without even the implied warranty of | |
17 | * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the | |
18 | * GNU General Public License for more details. | |
19 | * | |
20 | * 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 | #include "cache.h" | |
25 | #include "quote.h" | |
26 | ||
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, const char *override_envvar) | |
33 | { | |
34 | const char *trace; | |
35 | ||
36 | /* don't open twice */ | |
37 | if (key->initialized) | |
38 | return key->fd; | |
39 | ||
40 | trace = override_envvar ? override_envvar : getenv(key->key); | |
41 | ||
42 | if (!trace || !strcmp(trace, "") || | |
43 | !strcmp(trace, "0") || !strcasecmp(trace, "false")) | |
44 | key->fd = 0; | |
45 | else if (!strcmp(trace, "1") || !strcasecmp(trace, "true")) | |
46 | key->fd = STDERR_FILENO; | |
47 | else if (strlen(trace) == 1 && isdigit(*trace)) | |
48 | key->fd = atoi(trace); | |
49 | else if (is_absolute_path(trace)) { | |
50 | int fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666); | |
51 | if (fd == -1) { | |
52 | warning("could not open '%s' for tracing: %s", | |
53 | trace, strerror(errno)); | |
54 | trace_disable(key); | |
55 | } else { | |
56 | key->fd = fd; | |
57 | key->need_close = 1; | |
58 | } | |
59 | } else { | |
60 | warning("unknown trace value for '%s': %s\n" | |
61 | " 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 | key->initialized = 1; | |
68 | return key->fd; | |
69 | } | |
70 | ||
71 | void trace_override_envvar(struct trace_key *key, const char *value) | |
72 | { | |
73 | trace_disable(key); | |
74 | key->initialized = 0; | |
75 | ||
76 | /* | |
77 | * Invoke get_trace_fd() to initialize key using the given value | |
78 | * instead of the value of the environment variable. | |
79 | */ | |
80 | get_trace_fd(key, value); | |
81 | } | |
82 | ||
83 | void trace_disable(struct trace_key *key) | |
84 | { | |
85 | if (key->need_close) | |
86 | close(key->fd); | |
87 | key->fd = 0; | |
88 | key->initialized = 1; | |
89 | key->need_close = 0; | |
90 | } | |
91 | ||
92 | static int prepare_trace_line(const char *file, int line, | |
93 | struct trace_key *key, struct strbuf *buf) | |
94 | { | |
95 | static struct trace_key trace_bare = TRACE_KEY_INIT(BARE); | |
96 | struct timeval tv; | |
97 | struct tm tm; | |
98 | time_t secs; | |
99 | ||
100 | if (!trace_want(key)) | |
101 | return 0; | |
102 | ||
103 | /* unit tests may want to disable additional trace output */ | |
104 | if (trace_want(&trace_bare)) | |
105 | return 1; | |
106 | ||
107 | /* print current timestamp */ | |
108 | gettimeofday(&tv, NULL); | |
109 | secs = tv.tv_sec; | |
110 | localtime_r(&secs, &tm); | |
111 | strbuf_addf(buf, "%02d:%02d:%02d.%06ld ", tm.tm_hour, tm.tm_min, | |
112 | tm.tm_sec, (long) tv.tv_usec); | |
113 | ||
114 | #ifdef HAVE_VARIADIC_MACROS | |
115 | /* print file:line */ | |
116 | strbuf_addf(buf, "%s:%d ", file, line); | |
117 | /* align trace output (column 40 catches most files names in git) */ | |
118 | while (buf->len < 40) | |
119 | strbuf_addch(buf, ' '); | |
120 | #endif | |
121 | ||
122 | return 1; | |
123 | } | |
124 | ||
125 | static void trace_write(struct trace_key *key, const void *buf, unsigned len) | |
126 | { | |
127 | if (write_in_full(get_trace_fd(key, NULL), buf, len) < 0) { | |
128 | warning("unable to write trace for %s: %s", | |
129 | key->key, strerror(errno)); | |
130 | trace_disable(key); | |
131 | } | |
132 | } | |
133 | ||
134 | void trace_verbatim(struct trace_key *key, const void *buf, unsigned len) | |
135 | { | |
136 | if (!trace_want(key)) | |
137 | return; | |
138 | trace_write(key, buf, len); | |
139 | } | |
140 | ||
141 | static void print_trace_line(struct trace_key *key, struct strbuf *buf) | |
142 | { | |
143 | strbuf_complete_line(buf); | |
144 | trace_write(key, buf->buf, buf->len); | |
145 | } | |
146 | ||
147 | static void trace_vprintf_fl(const char *file, int line, struct trace_key *key, | |
148 | const char *format, va_list ap) | |
149 | { | |
150 | struct strbuf buf = STRBUF_INIT; | |
151 | ||
152 | if (!prepare_trace_line(file, line, key, &buf)) | |
153 | return; | |
154 | ||
155 | strbuf_vaddf(&buf, format, ap); | |
156 | print_trace_line(key, &buf); | |
157 | strbuf_release(&buf); | |
158 | } | |
159 | ||
160 | static void trace_argv_vprintf_fl(const char *file, int line, | |
161 | const char **argv, const char *format, | |
162 | va_list ap) | |
163 | { | |
164 | struct strbuf buf = STRBUF_INIT; | |
165 | ||
166 | if (!prepare_trace_line(file, line, &trace_default_key, &buf)) | |
167 | return; | |
168 | ||
169 | strbuf_vaddf(&buf, format, ap); | |
170 | ||
171 | sq_quote_argv_pretty(&buf, argv); | |
172 | print_trace_line(&trace_default_key, &buf); | |
173 | strbuf_release(&buf); | |
174 | } | |
175 | ||
176 | void trace_strbuf_fl(const char *file, int line, struct trace_key *key, | |
177 | const struct strbuf *data) | |
178 | { | |
179 | struct strbuf buf = STRBUF_INIT; | |
180 | ||
181 | if (!prepare_trace_line(file, line, key, &buf)) | |
182 | return; | |
183 | ||
184 | strbuf_addbuf(&buf, data); | |
185 | print_trace_line(key, &buf); | |
186 | strbuf_release(&buf); | |
187 | } | |
188 | ||
189 | static uint64_t perf_start_times[10]; | |
190 | static int perf_indent; | |
191 | ||
192 | uint64_t trace_performance_enter(void) | |
193 | { | |
194 | uint64_t now; | |
195 | ||
196 | if (!trace_want(&trace_perf_key)) | |
197 | return 0; | |
198 | ||
199 | now = getnanotime(); | |
200 | perf_start_times[perf_indent] = now; | |
201 | if (perf_indent + 1 < ARRAY_SIZE(perf_start_times)) | |
202 | perf_indent++; | |
203 | else | |
204 | BUG("Too deep indentation"); | |
205 | return now; | |
206 | } | |
207 | ||
208 | static void trace_performance_vprintf_fl(const char *file, int line, | |
209 | uint64_t nanos, const char *format, | |
210 | va_list ap) | |
211 | { | |
212 | static const char space[] = " "; | |
213 | struct strbuf buf = STRBUF_INIT; | |
214 | ||
215 | if (!prepare_trace_line(file, line, &trace_perf_key, &buf)) | |
216 | return; | |
217 | ||
218 | strbuf_addf(&buf, "performance: %.9f s", (double) nanos / 1000000000); | |
219 | ||
220 | if (format && *format) { | |
221 | if (perf_indent >= strlen(space)) | |
222 | BUG("Too deep indentation"); | |
223 | ||
224 | strbuf_addf(&buf, ":%.*s ", perf_indent, space); | |
225 | strbuf_vaddf(&buf, format, ap); | |
226 | } | |
227 | ||
228 | print_trace_line(&trace_perf_key, &buf); | |
229 | strbuf_release(&buf); | |
230 | } | |
231 | ||
232 | #ifndef HAVE_VARIADIC_MACROS | |
233 | ||
234 | void trace_printf(const char *format, ...) | |
235 | { | |
236 | va_list ap; | |
237 | va_start(ap, format); | |
238 | trace_vprintf_fl(NULL, 0, &trace_default_key, format, ap); | |
239 | va_end(ap); | |
240 | } | |
241 | ||
242 | void trace_printf_key(struct trace_key *key, const char *format, ...) | |
243 | { | |
244 | va_list ap; | |
245 | va_start(ap, format); | |
246 | trace_vprintf_fl(NULL, 0, key, format, ap); | |
247 | va_end(ap); | |
248 | } | |
249 | ||
250 | void trace_argv_printf(const char **argv, const char *format, ...) | |
251 | { | |
252 | va_list ap; | |
253 | va_start(ap, format); | |
254 | trace_argv_vprintf_fl(NULL, 0, argv, format, ap); | |
255 | va_end(ap); | |
256 | } | |
257 | ||
258 | void trace_strbuf(struct trace_key *key, const struct strbuf *data) | |
259 | { | |
260 | trace_strbuf_fl(NULL, 0, key, data); | |
261 | } | |
262 | ||
263 | void trace_performance(uint64_t nanos, const char *format, ...) | |
264 | { | |
265 | va_list ap; | |
266 | va_start(ap, format); | |
267 | trace_performance_vprintf_fl(NULL, 0, nanos, format, ap); | |
268 | va_end(ap); | |
269 | } | |
270 | ||
271 | void trace_performance_since(uint64_t start, const char *format, ...) | |
272 | { | |
273 | va_list ap; | |
274 | va_start(ap, format); | |
275 | trace_performance_vprintf_fl(NULL, 0, getnanotime() - start, | |
276 | format, ap); | |
277 | va_end(ap); | |
278 | } | |
279 | ||
280 | void trace_performance_leave(const char *format, ...) | |
281 | { | |
282 | va_list ap; | |
283 | uint64_t since; | |
284 | ||
285 | if (perf_indent) | |
286 | perf_indent--; | |
287 | ||
288 | if (!format) /* Allow callers to leave without tracing anything */ | |
289 | return; | |
290 | ||
291 | since = perf_start_times[perf_indent]; | |
292 | va_start(ap, format); | |
293 | trace_performance_vprintf_fl(NULL, 0, getnanotime() - since, | |
294 | format, ap); | |
295 | va_end(ap); | |
296 | } | |
297 | ||
298 | #else | |
299 | ||
300 | void trace_printf_key_fl(const char *file, int line, struct trace_key *key, | |
301 | const char *format, ...) | |
302 | { | |
303 | va_list ap; | |
304 | va_start(ap, format); | |
305 | trace_vprintf_fl(file, line, key, format, ap); | |
306 | va_end(ap); | |
307 | } | |
308 | ||
309 | void trace_argv_printf_fl(const char *file, int line, const char **argv, | |
310 | const char *format, ...) | |
311 | { | |
312 | va_list ap; | |
313 | va_start(ap, format); | |
314 | trace_argv_vprintf_fl(file, line, argv, format, ap); | |
315 | va_end(ap); | |
316 | } | |
317 | ||
318 | void trace_performance_fl(const char *file, int line, uint64_t nanos, | |
319 | const char *format, ...) | |
320 | { | |
321 | va_list ap; | |
322 | va_start(ap, format); | |
323 | trace_performance_vprintf_fl(file, line, nanos, format, ap); | |
324 | va_end(ap); | |
325 | } | |
326 | ||
327 | void trace_performance_leave_fl(const char *file, int line, | |
328 | uint64_t nanos, const char *format, ...) | |
329 | { | |
330 | va_list ap; | |
331 | uint64_t since; | |
332 | ||
333 | if (perf_indent) | |
334 | perf_indent--; | |
335 | ||
336 | if (!format) /* Allow callers to leave without tracing anything */ | |
337 | return; | |
338 | ||
339 | since = perf_start_times[perf_indent]; | |
340 | va_start(ap, format); | |
341 | trace_performance_vprintf_fl(file, line, nanos - since, format, ap); | |
342 | va_end(ap); | |
343 | } | |
344 | ||
345 | #endif /* HAVE_VARIADIC_MACROS */ | |
346 | ||
347 | ||
348 | static const char *quote_crnl(const char *path) | |
349 | { | |
350 | static struct strbuf new_path = STRBUF_INIT; | |
351 | ||
352 | if (!path) | |
353 | return NULL; | |
354 | ||
355 | strbuf_reset(&new_path); | |
356 | ||
357 | while (*path) { | |
358 | switch (*path) { | |
359 | case '\\': strbuf_addstr(&new_path, "\\\\"); break; | |
360 | case '\n': strbuf_addstr(&new_path, "\\n"); break; | |
361 | case '\r': strbuf_addstr(&new_path, "\\r"); break; | |
362 | default: | |
363 | strbuf_addch(&new_path, *path); | |
364 | } | |
365 | path++; | |
366 | } | |
367 | return new_path.buf; | |
368 | } | |
369 | ||
370 | /* FIXME: move prefix to startup_info struct and get rid of this arg */ | |
371 | void trace_repo_setup(const char *prefix) | |
372 | { | |
373 | const char *git_work_tree; | |
374 | char *cwd; | |
375 | ||
376 | if (!trace_want(&trace_setup_key)) | |
377 | return; | |
378 | ||
379 | cwd = xgetcwd(); | |
380 | ||
381 | if (!(git_work_tree = get_git_work_tree())) | |
382 | git_work_tree = "(null)"; | |
383 | ||
384 | if (!prefix) | |
385 | prefix = "(null)"; | |
386 | ||
387 | trace_printf_key(&trace_setup_key, "setup: git_dir: %s\n", quote_crnl(get_git_dir())); | |
388 | trace_printf_key(&trace_setup_key, "setup: git_common_dir: %s\n", quote_crnl(get_git_common_dir())); | |
389 | trace_printf_key(&trace_setup_key, "setup: worktree: %s\n", quote_crnl(git_work_tree)); | |
390 | trace_printf_key(&trace_setup_key, "setup: cwd: %s\n", quote_crnl(cwd)); | |
391 | trace_printf_key(&trace_setup_key, "setup: prefix: %s\n", quote_crnl(prefix)); | |
392 | ||
393 | free(cwd); | |
394 | } | |
395 | ||
396 | int trace_want(struct trace_key *key) | |
397 | { | |
398 | return !!get_trace_fd(key, NULL); | |
399 | } | |
400 | ||
401 | #if defined(HAVE_CLOCK_GETTIME) && defined(HAVE_CLOCK_MONOTONIC) | |
402 | ||
403 | static inline uint64_t highres_nanos(void) | |
404 | { | |
405 | struct timespec ts; | |
406 | if (clock_gettime(CLOCK_MONOTONIC, &ts)) | |
407 | return 0; | |
408 | return (uint64_t) ts.tv_sec * 1000000000 + ts.tv_nsec; | |
409 | } | |
410 | ||
411 | #elif defined (GIT_WINDOWS_NATIVE) | |
412 | ||
413 | static inline uint64_t highres_nanos(void) | |
414 | { | |
415 | static uint64_t high_ns, scaled_low_ns; | |
416 | static int scale; | |
417 | LARGE_INTEGER cnt; | |
418 | ||
419 | if (!scale) { | |
420 | if (!QueryPerformanceFrequency(&cnt)) | |
421 | return 0; | |
422 | ||
423 | /* high_ns = number of ns per cnt.HighPart */ | |
424 | high_ns = (1000000000LL << 32) / (uint64_t) cnt.QuadPart; | |
425 | ||
426 | /* | |
427 | * Number of ns per cnt.LowPart is 10^9 / frequency (or | |
428 | * high_ns >> 32). For maximum precision, we scale this factor | |
429 | * so that it just fits within 32 bit (i.e. won't overflow if | |
430 | * multiplied with cnt.LowPart). | |
431 | */ | |
432 | scaled_low_ns = high_ns; | |
433 | scale = 32; | |
434 | while (scaled_low_ns >= 0x100000000LL) { | |
435 | scaled_low_ns >>= 1; | |
436 | scale--; | |
437 | } | |
438 | } | |
439 | ||
440 | /* if QPF worked on initialization, we expect QPC to work as well */ | |
441 | QueryPerformanceCounter(&cnt); | |
442 | ||
443 | return (high_ns * cnt.HighPart) + | |
444 | ((scaled_low_ns * cnt.LowPart) >> scale); | |
445 | } | |
446 | ||
447 | #else | |
448 | # define highres_nanos() 0 | |
449 | #endif | |
450 | ||
451 | static inline uint64_t gettimeofday_nanos(void) | |
452 | { | |
453 | struct timeval tv; | |
454 | gettimeofday(&tv, NULL); | |
455 | return (uint64_t) tv.tv_sec * 1000000000 + tv.tv_usec * 1000; | |
456 | } | |
457 | ||
458 | /* | |
459 | * Returns nanoseconds since the epoch (01/01/1970), for performance tracing | |
460 | * (i.e. favoring high precision over wall clock time accuracy). | |
461 | */ | |
462 | uint64_t getnanotime(void) | |
463 | { | |
464 | static uint64_t offset; | |
465 | if (offset > 1) { | |
466 | /* initialization succeeded, return offset + high res time */ | |
467 | return offset + highres_nanos(); | |
468 | } else if (offset == 1) { | |
469 | /* initialization failed, fall back to gettimeofday */ | |
470 | return gettimeofday_nanos(); | |
471 | } else { | |
472 | /* initialize offset if high resolution timer works */ | |
473 | uint64_t now = gettimeofday_nanos(); | |
474 | uint64_t highres = highres_nanos(); | |
475 | if (highres) | |
476 | offset = now - highres; | |
477 | else | |
478 | offset = 1; | |
479 | return now; | |
480 | } | |
481 | } | |
482 | ||
483 | static struct strbuf command_line = STRBUF_INIT; | |
484 | ||
485 | static void print_command_performance_atexit(void) | |
486 | { | |
487 | trace_performance_leave("git command:%s", command_line.buf); | |
488 | } | |
489 | ||
490 | void trace_command_performance(const char **argv) | |
491 | { | |
492 | if (!trace_want(&trace_perf_key)) | |
493 | return; | |
494 | ||
495 | if (!command_line.len) | |
496 | atexit(print_command_performance_atexit); | |
497 | ||
498 | strbuf_reset(&command_line); | |
499 | sq_quote_argv_pretty(&command_line, argv); | |
500 | trace_performance_enter(); | |
501 | } |