| 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 | { |
| 40 | const char *trace; |
| 41 | |
| 42 | /* don't open twice */ |
| 43 | if (key->initialized) |
| 44 | return key->fd; |
| 45 | |
| 46 | trace = override_envvar ? override_envvar : getenv(key->key); |
| 47 | |
| 48 | if (!trace || !strcmp(trace, "") || |
| 49 | !strcmp(trace, "0") || !strcasecmp(trace, "false")) |
| 50 | key->fd = 0; |
| 51 | else if (!strcmp(trace, "1") || !strcasecmp(trace, "true")) |
| 52 | key->fd = STDERR_FILENO; |
| 53 | else if (strlen(trace) == 1 && isdigit(*trace)) |
| 54 | key->fd = atoi(trace); |
| 55 | else if (is_absolute_path(trace)) { |
| 56 | int fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666); |
| 57 | if (fd == -1) { |
| 58 | warning("could not open '%s' for tracing: %s", |
| 59 | trace, strerror(errno)); |
| 60 | trace_disable(key); |
| 61 | } else { |
| 62 | key->fd = fd; |
| 63 | key->need_close = 1; |
| 64 | } |
| 65 | } else { |
| 66 | warning("unknown trace value for '%s': %s\n" |
| 67 | " If you want to trace into a file, then please set %s\n" |
| 68 | " to an absolute pathname (starting with /)", |
| 69 | key->key, trace, key->key); |
| 70 | trace_disable(key); |
| 71 | } |
| 72 | |
| 73 | key->initialized = 1; |
| 74 | return key->fd; |
| 75 | } |
| 76 | |
| 77 | void trace_override_envvar(struct trace_key *key, const char *value) |
| 78 | { |
| 79 | trace_disable(key); |
| 80 | 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 | get_trace_fd(key, value); |
| 87 | } |
| 88 | |
| 89 | void trace_disable(struct trace_key *key) |
| 90 | { |
| 91 | if (key->need_close) |
| 92 | close(key->fd); |
| 93 | key->fd = 0; |
| 94 | key->initialized = 1; |
| 95 | key->need_close = 0; |
| 96 | } |
| 97 | |
| 98 | static int prepare_trace_line(const char *file, int line, |
| 99 | struct trace_key *key, struct strbuf *buf) |
| 100 | { |
| 101 | static struct trace_key trace_bare = TRACE_KEY_INIT(BARE); |
| 102 | struct timeval tv; |
| 103 | struct tm tm; |
| 104 | time_t secs; |
| 105 | |
| 106 | if (!trace_want(key)) |
| 107 | return 0; |
| 108 | |
| 109 | /* unit tests may want to disable additional trace output */ |
| 110 | if (trace_want(&trace_bare)) |
| 111 | return 1; |
| 112 | |
| 113 | /* print current timestamp */ |
| 114 | gettimeofday(&tv, NULL); |
| 115 | secs = tv.tv_sec; |
| 116 | localtime_r(&secs, &tm); |
| 117 | strbuf_addf(buf, "%02d:%02d:%02d.%06ld %s:%d", tm.tm_hour, tm.tm_min, |
| 118 | tm.tm_sec, (long) tv.tv_usec, file, line); |
| 119 | /* align trace output (column 40 catches most files names in git) */ |
| 120 | while (buf->len < 40) |
| 121 | strbuf_addch(buf, ' '); |
| 122 | |
| 123 | return 1; |
| 124 | } |
| 125 | |
| 126 | static void trace_write(struct trace_key *key, const void *buf, unsigned len) |
| 127 | { |
| 128 | if (write_in_full(get_trace_fd(key, NULL), buf, len) < 0) { |
| 129 | warning("unable to write trace for %s: %s", |
| 130 | key->key, strerror(errno)); |
| 131 | trace_disable(key); |
| 132 | } |
| 133 | } |
| 134 | |
| 135 | void trace_verbatim(struct trace_key *key, const void *buf, unsigned len) |
| 136 | { |
| 137 | if (!trace_want(key)) |
| 138 | return; |
| 139 | trace_write(key, buf, len); |
| 140 | } |
| 141 | |
| 142 | static void print_trace_line(struct trace_key *key, struct strbuf *buf) |
| 143 | { |
| 144 | strbuf_complete_line(buf); |
| 145 | trace_write(key, buf->buf, buf->len); |
| 146 | } |
| 147 | |
| 148 | static void trace_vprintf_fl(const char *file, int line, struct trace_key *key, |
| 149 | const char *format, va_list ap) |
| 150 | { |
| 151 | struct strbuf buf = STRBUF_INIT; |
| 152 | |
| 153 | if (!prepare_trace_line(file, line, key, &buf)) |
| 154 | return; |
| 155 | |
| 156 | strbuf_vaddf(&buf, format, ap); |
| 157 | print_trace_line(key, &buf); |
| 158 | strbuf_release(&buf); |
| 159 | } |
| 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 | { |
| 165 | struct strbuf buf = STRBUF_INIT; |
| 166 | |
| 167 | if (!prepare_trace_line(file, line, &trace_default_key, &buf)) |
| 168 | return; |
| 169 | |
| 170 | strbuf_vaddf(&buf, format, ap); |
| 171 | |
| 172 | sq_quote_argv_pretty(&buf, argv); |
| 173 | print_trace_line(&trace_default_key, &buf); |
| 174 | strbuf_release(&buf); |
| 175 | } |
| 176 | |
| 177 | void trace_strbuf_fl(const char *file, int line, struct trace_key *key, |
| 178 | const struct strbuf *data) |
| 179 | { |
| 180 | struct strbuf buf = STRBUF_INIT; |
| 181 | |
| 182 | if (!prepare_trace_line(file, line, key, &buf)) |
| 183 | return; |
| 184 | |
| 185 | strbuf_addbuf(&buf, data); |
| 186 | print_trace_line(key, &buf); |
| 187 | strbuf_release(&buf); |
| 188 | } |
| 189 | |
| 190 | static uint64_t perf_start_times[10]; |
| 191 | static int perf_indent; |
| 192 | |
| 193 | uint64_t trace_performance_enter(void) |
| 194 | { |
| 195 | uint64_t now; |
| 196 | |
| 197 | if (!trace_want(&trace_perf_key)) |
| 198 | return 0; |
| 199 | |
| 200 | now = getnanotime(); |
| 201 | perf_start_times[perf_indent] = now; |
| 202 | if (perf_indent + 1 < ARRAY_SIZE(perf_start_times)) |
| 203 | perf_indent++; |
| 204 | else |
| 205 | BUG("Too deep indentation"); |
| 206 | return now; |
| 207 | } |
| 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 | { |
| 213 | static const char space[] = " "; |
| 214 | struct strbuf buf = STRBUF_INIT; |
| 215 | |
| 216 | if (!prepare_trace_line(file, line, &trace_perf_key, &buf)) |
| 217 | return; |
| 218 | |
| 219 | strbuf_addf(&buf, "performance: %.9f s", (double) nanos / 1000000000); |
| 220 | |
| 221 | if (format && *format) { |
| 222 | if (perf_indent >= strlen(space)) |
| 223 | BUG("Too deep indentation"); |
| 224 | |
| 225 | strbuf_addf(&buf, ":%.*s ", perf_indent, space); |
| 226 | strbuf_vaddf(&buf, format, ap); |
| 227 | } |
| 228 | |
| 229 | print_trace_line(&trace_perf_key, &buf); |
| 230 | strbuf_release(&buf); |
| 231 | } |
| 232 | |
| 233 | void trace_printf_key_fl(const char *file, int line, struct trace_key *key, |
| 234 | const char *format, ...) |
| 235 | { |
| 236 | va_list ap; |
| 237 | va_start(ap, format); |
| 238 | trace_vprintf_fl(file, line, key, format, ap); |
| 239 | va_end(ap); |
| 240 | } |
| 241 | |
| 242 | void trace_argv_printf_fl(const char *file, int line, const char **argv, |
| 243 | const char *format, ...) |
| 244 | { |
| 245 | va_list ap; |
| 246 | va_start(ap, format); |
| 247 | trace_argv_vprintf_fl(file, line, argv, format, ap); |
| 248 | va_end(ap); |
| 249 | } |
| 250 | |
| 251 | void trace_performance_fl(const char *file, int line, uint64_t nanos, |
| 252 | const char *format, ...) |
| 253 | { |
| 254 | va_list ap; |
| 255 | va_start(ap, format); |
| 256 | trace_performance_vprintf_fl(file, line, nanos, format, ap); |
| 257 | va_end(ap); |
| 258 | } |
| 259 | |
| 260 | void trace_performance_leave_fl(const char *file, int line, |
| 261 | uint64_t nanos, const char *format, ...) |
| 262 | { |
| 263 | va_list ap; |
| 264 | uint64_t since; |
| 265 | |
| 266 | if (perf_indent) |
| 267 | perf_indent--; |
| 268 | |
| 269 | if (!format) /* Allow callers to leave without tracing anything */ |
| 270 | return; |
| 271 | |
| 272 | since = perf_start_times[perf_indent]; |
| 273 | va_start(ap, format); |
| 274 | trace_performance_vprintf_fl(file, line, nanos - since, format, ap); |
| 275 | va_end(ap); |
| 276 | } |
| 277 | |
| 278 | static const char *quote_crnl(const char *path) |
| 279 | { |
| 280 | static struct strbuf new_path = STRBUF_INIT; |
| 281 | |
| 282 | if (!path) |
| 283 | return NULL; |
| 284 | |
| 285 | strbuf_reset(&new_path); |
| 286 | |
| 287 | while (*path) { |
| 288 | switch (*path) { |
| 289 | case '\\': strbuf_addstr(&new_path, "\\\\"); break; |
| 290 | case '\n': strbuf_addstr(&new_path, "\\n"); break; |
| 291 | 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 | void trace_repo_setup(struct repository *r) |
| 301 | { |
| 302 | const char *git_work_tree, *prefix = r->prefix; |
| 303 | char *cwd; |
| 304 | |
| 305 | if (!trace_want(&trace_setup_key)) |
| 306 | return; |
| 307 | |
| 308 | cwd = xgetcwd(); |
| 309 | |
| 310 | if (!(git_work_tree = repo_get_work_tree(r))) |
| 311 | git_work_tree = "(null)"; |
| 312 | |
| 313 | if (!r->prefix) |
| 314 | prefix = "(null)"; |
| 315 | |
| 316 | trace_printf_key(&trace_setup_key, "setup: git_dir: %s\n", quote_crnl(repo_get_git_dir(r))); |
| 317 | trace_printf_key(&trace_setup_key, "setup: git_common_dir: %s\n", quote_crnl(repo_get_common_dir(r))); |
| 318 | trace_printf_key(&trace_setup_key, "setup: worktree: %s\n", quote_crnl(git_work_tree)); |
| 319 | trace_printf_key(&trace_setup_key, "setup: cwd: %s\n", quote_crnl(cwd)); |
| 320 | trace_printf_key(&trace_setup_key, "setup: prefix: %s\n", quote_crnl(prefix)); |
| 321 | |
| 322 | free(cwd); |
| 323 | } |
| 324 | |
| 325 | int trace_want(struct trace_key *key) |
| 326 | { |
| 327 | return !!get_trace_fd(key, NULL); |
| 328 | } |
| 329 | |
| 330 | #if defined(HAVE_CLOCK_GETTIME) && defined(HAVE_CLOCK_MONOTONIC) |
| 331 | |
| 332 | static inline uint64_t highres_nanos(void) |
| 333 | { |
| 334 | struct timespec ts; |
| 335 | if (clock_gettime(CLOCK_MONOTONIC, &ts)) |
| 336 | return 0; |
| 337 | return (uint64_t) ts.tv_sec * 1000000000 + ts.tv_nsec; |
| 338 | } |
| 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 | { |
| 382 | struct timeval tv; |
| 383 | gettimeofday(&tv, NULL); |
| 384 | return (uint64_t) tv.tv_sec * 1000000000 + tv.tv_usec * 1000; |
| 385 | } |
| 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 | { |
| 393 | static uint64_t offset; |
| 394 | if (offset > 1) { |
| 395 | /* initialization succeeded, return offset + high res time */ |
| 396 | return offset + highres_nanos(); |
| 397 | } else if (offset == 1) { |
| 398 | /* initialization failed, fall back to gettimeofday */ |
| 399 | return gettimeofday_nanos(); |
| 400 | } else { |
| 401 | /* initialize offset if high resolution timer works */ |
| 402 | uint64_t now = gettimeofday_nanos(); |
| 403 | uint64_t highres = highres_nanos(); |
| 404 | if (highres) |
| 405 | offset = now - highres; |
| 406 | else |
| 407 | offset = 1; |
| 408 | return now; |
| 409 | } |
| 410 | } |
| 411 | |
| 412 | static struct strbuf command_line = STRBUF_INIT; |
| 413 | |
| 414 | static void print_command_performance_atexit(void) |
| 415 | { |
| 416 | trace_performance_leave("git command:%s", command_line.buf); |
| 417 | } |
| 418 | |
| 419 | void trace_command_performance(const char **argv) |
| 420 | { |
| 421 | if (!trace_want(&trace_perf_key)) |
| 422 | return; |
| 423 | |
| 424 | if (!command_line.len) |
| 425 | atexit(print_command_performance_atexit); |
| 426 | |
| 427 | strbuf_reset(&command_line); |
| 428 | sq_quote_argv_pretty(&command_line, argv); |
| 429 | trace_performance_enter(); |
| 430 | } |