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