Line | Count | Source |
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 <https://www.gnu.org/licenses/>. |
22 | | */ |
23 | | |
24 | | #define DISABLE_SIGN_COMPARE_WARNINGS |
25 | | |
26 | | #include "git-compat-util.h" |
27 | | #include "abspath.h" |
28 | | #include "repository.h" |
29 | | #include "quote.h" |
30 | | #include "setup.h" |
31 | | #include "trace.h" |
32 | | |
33 | | struct trace_key trace_default_key = { "GIT_TRACE", 0, 0, 0 }; |
34 | | struct trace_key trace_perf_key = TRACE_KEY_INIT(PERFORMANCE); |
35 | | struct trace_key trace_setup_key = TRACE_KEY_INIT(SETUP); |
36 | | |
37 | | /* Get a trace file descriptor from "key" env variable. */ |
38 | | static int get_trace_fd(struct trace_key *key, const char *override_envvar) |
39 | 0 | { |
40 | 0 | const char *trace; |
41 | | |
42 | | /* don't open twice */ |
43 | 0 | if (key->initialized) |
44 | 0 | return key->fd; |
45 | | |
46 | 0 | trace = override_envvar ? override_envvar : getenv(key->key); |
47 | |
|
48 | 0 | if (!trace || !strcmp(trace, "") || |
49 | 0 | !strcmp(trace, "0") || !strcasecmp(trace, "false")) |
50 | 0 | key->fd = 0; |
51 | 0 | else if (!strcmp(trace, "1") || !strcasecmp(trace, "true")) |
52 | 0 | key->fd = STDERR_FILENO; |
53 | 0 | else if (strlen(trace) == 1 && isdigit(*trace)) |
54 | 0 | key->fd = atoi(trace); |
55 | 0 | else if (is_absolute_path(trace)) { |
56 | 0 | int fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666); |
57 | 0 | if (fd == -1) { |
58 | 0 | warning("could not open '%s' for tracing: %s", |
59 | 0 | trace, strerror(errno)); |
60 | 0 | trace_disable(key); |
61 | 0 | } else { |
62 | 0 | key->fd = fd; |
63 | 0 | key->need_close = 1; |
64 | 0 | } |
65 | 0 | } else { |
66 | 0 | warning("unknown trace value for '%s': %s\n" |
67 | 0 | " If you want to trace into a file, then please set %s\n" |
68 | 0 | " to an absolute pathname (starting with /)", |
69 | 0 | key->key, trace, key->key); |
70 | 0 | trace_disable(key); |
71 | 0 | } |
72 | |
|
73 | 0 | key->initialized = 1; |
74 | 0 | return key->fd; |
75 | 0 | } |
76 | | |
77 | | void trace_override_envvar(struct trace_key *key, const char *value) |
78 | 0 | { |
79 | 0 | trace_disable(key); |
80 | 0 | key->initialized = 0; |
81 | | |
82 | | /* |
83 | | * Invoke get_trace_fd() to initialize key using the given value |
84 | | * instead of the value of the environment variable. |
85 | | */ |
86 | 0 | get_trace_fd(key, value); |
87 | 0 | } |
88 | | |
89 | | void trace_disable(struct trace_key *key) |
90 | 0 | { |
91 | 0 | if (key->need_close) |
92 | 0 | close(key->fd); |
93 | 0 | key->fd = 0; |
94 | 0 | key->initialized = 1; |
95 | 0 | key->need_close = 0; |
96 | 0 | } |
97 | | |
98 | | static int prepare_trace_line(const char *file, int line, |
99 | | struct trace_key *key, struct strbuf *buf) |
100 | 0 | { |
101 | 0 | static struct trace_key trace_bare = TRACE_KEY_INIT(BARE); |
102 | 0 | struct timeval tv; |
103 | 0 | struct tm tm; |
104 | 0 | time_t secs; |
105 | |
|
106 | 0 | if (!trace_want(key)) |
107 | 0 | return 0; |
108 | | |
109 | | /* unit tests may want to disable additional trace output */ |
110 | 0 | if (trace_want(&trace_bare)) |
111 | 0 | return 1; |
112 | | |
113 | | /* print current timestamp */ |
114 | 0 | gettimeofday(&tv, NULL); |
115 | 0 | secs = tv.tv_sec; |
116 | 0 | localtime_r(&secs, &tm); |
117 | 0 | strbuf_addf(buf, "%02d:%02d:%02d.%06ld %s:%d", tm.tm_hour, tm.tm_min, |
118 | 0 | tm.tm_sec, (long) tv.tv_usec, file, line); |
119 | | /* align trace output (column 40 catches most files names in git) */ |
120 | 0 | while (buf->len < 40) |
121 | 0 | strbuf_addch(buf, ' '); |
122 | |
|
123 | 0 | return 1; |
124 | 0 | } |
125 | | |
126 | | static void trace_write(struct trace_key *key, const void *buf, unsigned len) |
127 | 0 | { |
128 | 0 | if (write_in_full(get_trace_fd(key, NULL), buf, len) < 0) { |
129 | 0 | warning("unable to write trace for %s: %s", |
130 | 0 | key->key, strerror(errno)); |
131 | 0 | trace_disable(key); |
132 | 0 | } |
133 | 0 | } |
134 | | |
135 | | void trace_verbatim(struct trace_key *key, const void *buf, unsigned len) |
136 | 0 | { |
137 | 0 | if (!trace_want(key)) |
138 | 0 | return; |
139 | 0 | trace_write(key, buf, len); |
140 | 0 | } |
141 | | |
142 | | static void print_trace_line(struct trace_key *key, struct strbuf *buf) |
143 | 0 | { |
144 | 0 | strbuf_complete_line(buf); |
145 | 0 | trace_write(key, buf->buf, buf->len); |
146 | 0 | } |
147 | | |
148 | | static void trace_vprintf_fl(const char *file, int line, struct trace_key *key, |
149 | | const char *format, va_list ap) |
150 | 0 | { |
151 | 0 | struct strbuf buf = STRBUF_INIT; |
152 | |
|
153 | 0 | if (!prepare_trace_line(file, line, key, &buf)) |
154 | 0 | return; |
155 | | |
156 | 0 | strbuf_vaddf(&buf, format, ap); |
157 | 0 | print_trace_line(key, &buf); |
158 | 0 | strbuf_release(&buf); |
159 | 0 | } |
160 | | |
161 | | static void trace_argv_vprintf_fl(const char *file, int line, |
162 | | const char **argv, const char *format, |
163 | | va_list ap) |
164 | 0 | { |
165 | 0 | struct strbuf buf = STRBUF_INIT; |
166 | |
|
167 | 0 | if (!prepare_trace_line(file, line, &trace_default_key, &buf)) |
168 | 0 | return; |
169 | | |
170 | 0 | strbuf_vaddf(&buf, format, ap); |
171 | |
|
172 | 0 | sq_quote_argv_pretty(&buf, argv); |
173 | 0 | print_trace_line(&trace_default_key, &buf); |
174 | 0 | strbuf_release(&buf); |
175 | 0 | } |
176 | | |
177 | | void trace_strbuf_fl(const char *file, int line, struct trace_key *key, |
178 | | const struct strbuf *data) |
179 | 0 | { |
180 | 0 | struct strbuf buf = STRBUF_INIT; |
181 | |
|
182 | 0 | if (!prepare_trace_line(file, line, key, &buf)) |
183 | 0 | return; |
184 | | |
185 | 0 | strbuf_addbuf(&buf, data); |
186 | 0 | print_trace_line(key, &buf); |
187 | 0 | strbuf_release(&buf); |
188 | 0 | } |
189 | | |
190 | | static uint64_t perf_start_times[10]; |
191 | | static int perf_indent; |
192 | | |
193 | | uint64_t trace_performance_enter(void) |
194 | 0 | { |
195 | 0 | uint64_t now; |
196 | |
|
197 | 0 | if (!trace_want(&trace_perf_key)) |
198 | 0 | return 0; |
199 | | |
200 | 0 | now = getnanotime(); |
201 | 0 | perf_start_times[perf_indent] = now; |
202 | 0 | if (perf_indent + 1 < ARRAY_SIZE(perf_start_times)) |
203 | 0 | perf_indent++; |
204 | 0 | else |
205 | 0 | BUG("Too deep indentation"); |
206 | 0 | return now; |
207 | 0 | } |
208 | | |
209 | | static void trace_performance_vprintf_fl(const char *file, int line, |
210 | | uint64_t nanos, const char *format, |
211 | | va_list ap) |
212 | 0 | { |
213 | 0 | static const char space[] = " "; |
214 | 0 | struct strbuf buf = STRBUF_INIT; |
215 | |
|
216 | 0 | if (!prepare_trace_line(file, line, &trace_perf_key, &buf)) |
217 | 0 | return; |
218 | | |
219 | 0 | strbuf_addf(&buf, "performance: %.9f s", (double) nanos / 1000000000); |
220 | |
|
221 | 0 | if (format && *format) { |
222 | 0 | if (perf_indent >= strlen(space)) |
223 | 0 | BUG("Too deep indentation"); |
224 | | |
225 | 0 | strbuf_addf(&buf, ":%.*s ", perf_indent, space); |
226 | 0 | strbuf_vaddf(&buf, format, ap); |
227 | 0 | } |
228 | | |
229 | 0 | print_trace_line(&trace_perf_key, &buf); |
230 | 0 | strbuf_release(&buf); |
231 | 0 | } |
232 | | |
233 | | void trace_printf_key_fl(const char *file, int line, struct trace_key *key, |
234 | | const char *format, ...) |
235 | 0 | { |
236 | 0 | va_list ap; |
237 | 0 | va_start(ap, format); |
238 | 0 | trace_vprintf_fl(file, line, key, format, ap); |
239 | 0 | va_end(ap); |
240 | 0 | } |
241 | | |
242 | | void trace_argv_printf_fl(const char *file, int line, const char **argv, |
243 | | const char *format, ...) |
244 | 0 | { |
245 | 0 | va_list ap; |
246 | 0 | va_start(ap, format); |
247 | 0 | trace_argv_vprintf_fl(file, line, argv, format, ap); |
248 | 0 | va_end(ap); |
249 | 0 | } |
250 | | |
251 | | void trace_performance_fl(const char *file, int line, uint64_t nanos, |
252 | | const char *format, ...) |
253 | 0 | { |
254 | 0 | va_list ap; |
255 | 0 | va_start(ap, format); |
256 | 0 | trace_performance_vprintf_fl(file, line, nanos, format, ap); |
257 | 0 | va_end(ap); |
258 | 0 | } |
259 | | |
260 | | void trace_performance_leave_fl(const char *file, int line, |
261 | | uint64_t nanos, const char *format, ...) |
262 | 0 | { |
263 | 0 | va_list ap; |
264 | 0 | uint64_t since; |
265 | |
|
266 | 0 | if (perf_indent) |
267 | 0 | perf_indent--; |
268 | |
|
269 | 0 | if (!format) /* Allow callers to leave without tracing anything */ |
270 | 0 | return; |
271 | | |
272 | 0 | since = perf_start_times[perf_indent]; |
273 | 0 | va_start(ap, format); |
274 | 0 | trace_performance_vprintf_fl(file, line, nanos - since, format, ap); |
275 | 0 | va_end(ap); |
276 | 0 | } |
277 | | |
278 | | static const char *quote_crnl(const char *path) |
279 | 0 | { |
280 | 0 | static struct strbuf new_path = STRBUF_INIT; |
281 | |
|
282 | 0 | if (!path) |
283 | 0 | return NULL; |
284 | | |
285 | 0 | strbuf_reset(&new_path); |
286 | |
|
287 | 0 | while (*path) { |
288 | 0 | switch (*path) { |
289 | 0 | case '\\': strbuf_addstr(&new_path, "\\\\"); break; |
290 | 0 | case '\n': strbuf_addstr(&new_path, "\\n"); break; |
291 | 0 | case '\r': strbuf_addstr(&new_path, "\\r"); break; |
292 | 0 | default: |
293 | 0 | strbuf_addch(&new_path, *path); |
294 | 0 | } |
295 | 0 | path++; |
296 | 0 | } |
297 | 0 | return new_path.buf; |
298 | 0 | } |
299 | | |
300 | | void trace_repo_setup(struct repository *r) |
301 | 0 | { |
302 | 0 | const char *git_work_tree, *prefix = startup_info->prefix; |
303 | 0 | char *cwd; |
304 | |
|
305 | 0 | if (!trace_want(&trace_setup_key)) |
306 | 0 | return; |
307 | | |
308 | 0 | cwd = xgetcwd(); |
309 | |
|
310 | 0 | if (!(git_work_tree = repo_get_work_tree(r))) |
311 | 0 | git_work_tree = "(null)"; |
312 | |
|
313 | 0 | if (!startup_info->prefix) |
314 | 0 | prefix = "(null)"; |
315 | |
|
316 | 0 | trace_printf_key(&trace_setup_key, "setup: git_dir: %s\n", quote_crnl(repo_get_git_dir(r))); |
317 | 0 | trace_printf_key(&trace_setup_key, "setup: git_common_dir: %s\n", quote_crnl(repo_get_common_dir(r))); |
318 | 0 | trace_printf_key(&trace_setup_key, "setup: worktree: %s\n", quote_crnl(git_work_tree)); |
319 | 0 | trace_printf_key(&trace_setup_key, "setup: cwd: %s\n", quote_crnl(cwd)); |
320 | 0 | trace_printf_key(&trace_setup_key, "setup: prefix: %s\n", quote_crnl(prefix)); |
321 | |
|
322 | 0 | free(cwd); |
323 | 0 | } |
324 | | |
325 | | int trace_want(struct trace_key *key) |
326 | 0 | { |
327 | 0 | return !!get_trace_fd(key, NULL); |
328 | 0 | } |
329 | | |
330 | | #if defined(HAVE_CLOCK_GETTIME) && defined(HAVE_CLOCK_MONOTONIC) |
331 | | |
332 | | static inline uint64_t highres_nanos(void) |
333 | 0 | { |
334 | 0 | struct timespec ts; |
335 | 0 | if (clock_gettime(CLOCK_MONOTONIC, &ts)) |
336 | 0 | return 0; |
337 | 0 | return (uint64_t) ts.tv_sec * 1000000000 + ts.tv_nsec; |
338 | 0 | } |
339 | | |
340 | | #elif defined (GIT_WINDOWS_NATIVE) |
341 | | |
342 | | static inline uint64_t highres_nanos(void) |
343 | | { |
344 | | static uint64_t high_ns, scaled_low_ns; |
345 | | static int scale; |
346 | | LARGE_INTEGER cnt; |
347 | | |
348 | | if (!scale) { |
349 | | if (!QueryPerformanceFrequency(&cnt)) |
350 | | return 0; |
351 | | |
352 | | /* high_ns = number of ns per cnt.HighPart */ |
353 | | high_ns = (1000000000LL << 32) / (uint64_t) cnt.QuadPart; |
354 | | |
355 | | /* |
356 | | * Number of ns per cnt.LowPart is 10^9 / frequency (or |
357 | | * high_ns >> 32). For maximum precision, we scale this factor |
358 | | * so that it just fits within 32 bit (i.e. won't overflow if |
359 | | * multiplied with cnt.LowPart). |
360 | | */ |
361 | | scaled_low_ns = high_ns; |
362 | | scale = 32; |
363 | | while (scaled_low_ns >= 0x100000000LL) { |
364 | | scaled_low_ns >>= 1; |
365 | | scale--; |
366 | | } |
367 | | } |
368 | | |
369 | | /* if QPF worked on initialization, we expect QPC to work as well */ |
370 | | QueryPerformanceCounter(&cnt); |
371 | | |
372 | | return (high_ns * cnt.HighPart) + |
373 | | ((scaled_low_ns * cnt.LowPart) >> scale); |
374 | | } |
375 | | |
376 | | #else |
377 | | # define highres_nanos() 0 |
378 | | #endif |
379 | | |
380 | | static inline uint64_t gettimeofday_nanos(void) |
381 | 0 | { |
382 | 0 | struct timeval tv; |
383 | 0 | gettimeofday(&tv, NULL); |
384 | 0 | return (uint64_t) tv.tv_sec * 1000000000 + tv.tv_usec * 1000; |
385 | 0 | } |
386 | | |
387 | | /* |
388 | | * Returns nanoseconds since the epoch (01/01/1970), for performance tracing |
389 | | * (i.e. favoring high precision over wall clock time accuracy). |
390 | | */ |
391 | | uint64_t getnanotime(void) |
392 | 0 | { |
393 | 0 | static uint64_t offset; |
394 | 0 | if (offset > 1) { |
395 | | /* initialization succeeded, return offset + high res time */ |
396 | 0 | return offset + highres_nanos(); |
397 | 0 | } else if (offset == 1) { |
398 | | /* initialization failed, fall back to gettimeofday */ |
399 | 0 | return gettimeofday_nanos(); |
400 | 0 | } else { |
401 | | /* initialize offset if high resolution timer works */ |
402 | 0 | uint64_t now = gettimeofday_nanos(); |
403 | 0 | uint64_t highres = highres_nanos(); |
404 | 0 | if (highres) |
405 | 0 | offset = now - highres; |
406 | 0 | else |
407 | 0 | offset = 1; |
408 | 0 | return now; |
409 | 0 | } |
410 | 0 | } |
411 | | |
412 | | static struct strbuf command_line = STRBUF_INIT; |
413 | | |
414 | | static void print_command_performance_atexit(void) |
415 | 0 | { |
416 | 0 | trace_performance_leave("git command:%s", command_line.buf); |
417 | 0 | } |
418 | | |
419 | | void trace_command_performance(const char **argv) |
420 | 0 | { |
421 | 0 | if (!trace_want(&trace_perf_key)) |
422 | 0 | return; |
423 | | |
424 | 0 | if (!command_line.len) |
425 | 0 | atexit(print_command_performance_atexit); |
426 | |
|
427 | 0 | strbuf_reset(&command_line); |
428 | 0 | sq_quote_argv_pretty(&command_line, argv); |
429 | 0 | trace_performance_enter(); |
430 | 0 | } |