| 1 | #define DISABLE_SIGN_COMPARE_WARNINGS |
| 2 | |
| 3 | #include "git-compat-util.h" |
| 4 | #include "config.h" |
| 5 | #include "repository.h" |
| 6 | #include "run-command.h" |
| 7 | #include "sigchain.h" |
| 8 | #include "thread-utils.h" |
| 9 | #include "trace.h" |
| 10 | #include "trace2.h" |
| 11 | #include "trace2/tr2_cfg.h" |
| 12 | #include "trace2/tr2_cmd_name.h" |
| 13 | #include "trace2/tr2_ctr.h" |
| 14 | #include "trace2/tr2_dst.h" |
| 15 | #include "trace2/tr2_sid.h" |
| 16 | #include "trace2/tr2_sysenv.h" |
| 17 | #include "trace2/tr2_tgt.h" |
| 18 | #include "trace2/tr2_tls.h" |
| 19 | #include "trace2/tr2_tmr.h" |
| 20 | |
| 21 | static int trace2_enabled; |
| 22 | static int trace2_redact = 1; |
| 23 | |
| 24 | static int tr2_next_child_id; /* modify under lock */ |
| 25 | static int tr2_next_exec_id; /* modify under lock */ |
| 26 | static int tr2_next_repo_id = 1; /* modify under lock. zero is reserved */ |
| 27 | |
| 28 | /* |
| 29 | * A table of the builtin TRACE2 targets. Each of these may be independently |
| 30 | * enabled or disabled. Each TRACE2 API method will try to write an event to |
| 31 | * *each* of the enabled targets. |
| 32 | */ |
| 33 | /* clang-format off */ |
| 34 | static struct tr2_tgt *tr2_tgt_builtins[] = |
| 35 | { |
| 36 | &tr2_tgt_normal, |
| 37 | &tr2_tgt_perf, |
| 38 | &tr2_tgt_event, |
| 39 | NULL |
| 40 | }; |
| 41 | /* clang-format on */ |
| 42 | |
| 43 | /* clang-format off */ |
| 44 | #define for_each_builtin(j, tgt_j) \ |
| 45 | for (j = 0, tgt_j = tr2_tgt_builtins[j]; \ |
| 46 | tgt_j; \ |
| 47 | j++, tgt_j = tr2_tgt_builtins[j]) |
| 48 | /* clang-format on */ |
| 49 | |
| 50 | /* clang-format off */ |
| 51 | #define for_each_wanted_builtin(j, tgt_j) \ |
| 52 | for_each_builtin(j, tgt_j) \ |
| 53 | if (tr2_dst_trace_want(tgt_j->pdst)) |
| 54 | /* clang-format on */ |
| 55 | |
| 56 | /* |
| 57 | * Force (rather than lazily) initialize any of the requested |
| 58 | * builtin TRACE2 targets at startup (and before we've seen an |
| 59 | * actual TRACE2 event call) so we can see if we need to setup |
| 60 | * private data structures and thread-local storage. |
| 61 | * |
| 62 | * Return the number of builtin targets enabled. |
| 63 | */ |
| 64 | static int tr2_tgt_want_builtins(void) |
| 65 | { |
| 66 | struct tr2_tgt *tgt_j; |
| 67 | int j; |
| 68 | int sum = 0; |
| 69 | |
| 70 | for_each_builtin (j, tgt_j) |
| 71 | if (tgt_j->pfn_init()) |
| 72 | sum++; |
| 73 | |
| 74 | return sum; |
| 75 | } |
| 76 | |
| 77 | /* |
| 78 | * Properly terminate each builtin target. Give each target |
| 79 | * a chance to write a summary event and/or flush if necessary |
| 80 | * and then close the fd. |
| 81 | */ |
| 82 | static void tr2_tgt_disable_builtins(void) |
| 83 | { |
| 84 | struct tr2_tgt *tgt_j; |
| 85 | int j; |
| 86 | |
| 87 | for_each_builtin (j, tgt_j) |
| 88 | tgt_j->pfn_term(); |
| 89 | } |
| 90 | |
| 91 | /* |
| 92 | * The signature of this function must match the pfn_timer |
| 93 | * method in the targets. (Think of this is an apply operation |
| 94 | * across the set of active targets.) |
| 95 | */ |
| 96 | static void tr2_tgt_emit_a_timer(const struct tr2_timer_metadata *meta, |
| 97 | const struct tr2_timer *timer, |
| 98 | int is_final_data) |
| 99 | { |
| 100 | struct tr2_tgt *tgt_j; |
| 101 | int j; |
| 102 | |
| 103 | for_each_wanted_builtin (j, tgt_j) |
| 104 | if (tgt_j->pfn_timer) |
| 105 | tgt_j->pfn_timer(meta, timer, is_final_data); |
| 106 | } |
| 107 | |
| 108 | /* |
| 109 | * The signature of this function must match the pfn_counter |
| 110 | * method in the targets. |
| 111 | */ |
| 112 | static void tr2_tgt_emit_a_counter(const struct tr2_counter_metadata *meta, |
| 113 | const struct tr2_counter *counter, |
| 114 | int is_final_data) |
| 115 | { |
| 116 | struct tr2_tgt *tgt_j; |
| 117 | int j; |
| 118 | |
| 119 | for_each_wanted_builtin (j, tgt_j) |
| 120 | if (tgt_j->pfn_counter) |
| 121 | tgt_j->pfn_counter(meta, counter, is_final_data); |
| 122 | } |
| 123 | |
| 124 | static int tr2main_exit_code; |
| 125 | |
| 126 | /* |
| 127 | * Our atexit routine should run after everything has finished. |
| 128 | * |
| 129 | * Note that events generated here might not actually appear if |
| 130 | * we are writing to fd 1 or 2 and our atexit routine runs after |
| 131 | * the pager's atexit routine (since it closes them to shutdown |
| 132 | * the pipes). |
| 133 | */ |
| 134 | static void tr2main_atexit_handler(void) |
| 135 | { |
| 136 | struct tr2_tgt *tgt_j; |
| 137 | int j; |
| 138 | uint64_t us_now; |
| 139 | uint64_t us_elapsed_absolute; |
| 140 | |
| 141 | us_now = getnanotime() / 1000; |
| 142 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 143 | |
| 144 | /* |
| 145 | * Clear any unbalanced regions so that our atexit message |
| 146 | * does not appear nested. This improves the appearance of |
| 147 | * the trace output if someone calls die(), for example. |
| 148 | */ |
| 149 | tr2tls_pop_unwind_self(); |
| 150 | |
| 151 | /* |
| 152 | * Some timers want per-thread details. If the main thread |
| 153 | * used one of those timers, emit the details now (before |
| 154 | * we emit the aggregate timer values). |
| 155 | * |
| 156 | * Likewise for counters. |
| 157 | */ |
| 158 | tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer); |
| 159 | tr2_emit_per_thread_counters(tr2_tgt_emit_a_counter); |
| 160 | |
| 161 | /* |
| 162 | * Add stopwatch timer and counter data for the main thread to |
| 163 | * the final totals. And then emit the final values. |
| 164 | * |
| 165 | * Technically, we shouldn't need to hold the lock to update |
| 166 | * and output the final_timer_block and final_counter_block |
| 167 | * (since all other threads should be dead by now), but it |
| 168 | * doesn't hurt anything. |
| 169 | */ |
| 170 | tr2tls_lock(); |
| 171 | tr2_update_final_timers(); |
| 172 | tr2_update_final_counters(); |
| 173 | tr2_emit_final_timers(tr2_tgt_emit_a_timer); |
| 174 | tr2_emit_final_counters(tr2_tgt_emit_a_counter); |
| 175 | tr2tls_unlock(); |
| 176 | |
| 177 | for_each_wanted_builtin (j, tgt_j) |
| 178 | if (tgt_j->pfn_atexit) |
| 179 | tgt_j->pfn_atexit(us_elapsed_absolute, |
| 180 | tr2main_exit_code); |
| 181 | |
| 182 | tr2_tgt_disable_builtins(); |
| 183 | |
| 184 | tr2tls_release(); |
| 185 | tr2_sid_release(); |
| 186 | tr2_cmd_name_release(); |
| 187 | tr2_cfg_free_patterns(); |
| 188 | tr2_cfg_free_env_vars(); |
| 189 | tr2_sysenv_release(); |
| 190 | |
| 191 | trace2_enabled = 0; |
| 192 | } |
| 193 | |
| 194 | static void tr2main_signal_handler(int signo) |
| 195 | { |
| 196 | struct tr2_tgt *tgt_j; |
| 197 | int j; |
| 198 | uint64_t us_now; |
| 199 | uint64_t us_elapsed_absolute; |
| 200 | |
| 201 | us_now = getnanotime() / 1000; |
| 202 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 203 | |
| 204 | for_each_wanted_builtin (j, tgt_j) |
| 205 | if (tgt_j->pfn_signal) |
| 206 | tgt_j->pfn_signal(us_elapsed_absolute, signo); |
| 207 | |
| 208 | sigchain_pop(signo); |
| 209 | raise(signo); |
| 210 | } |
| 211 | |
| 212 | void trace2_initialize_clock(void) |
| 213 | { |
| 214 | tr2tls_start_process_clock(); |
| 215 | } |
| 216 | |
| 217 | void trace2_initialize_fl(const char *file, int line) |
| 218 | { |
| 219 | struct tr2_tgt *tgt_j; |
| 220 | int j; |
| 221 | |
| 222 | if (trace2_enabled) |
| 223 | return; |
| 224 | |
| 225 | tr2_sysenv_load(); |
| 226 | |
| 227 | if (!tr2_tgt_want_builtins()) |
| 228 | return; |
| 229 | trace2_enabled = 1; |
| 230 | if (!git_env_bool("GIT_TRACE2_REDACT", 1)) |
| 231 | trace2_redact = 0; |
| 232 | |
| 233 | tr2_sid_get(); |
| 234 | |
| 235 | atexit(tr2main_atexit_handler); |
| 236 | sigchain_push(SIGPIPE, tr2main_signal_handler); |
| 237 | tr2tls_init(); |
| 238 | |
| 239 | /* |
| 240 | * Emit 'version' message on each active builtin target. |
| 241 | */ |
| 242 | for_each_wanted_builtin (j, tgt_j) |
| 243 | if (tgt_j->pfn_version_fl) |
| 244 | tgt_j->pfn_version_fl(file, line); |
| 245 | } |
| 246 | |
| 247 | int trace2_is_enabled(void) |
| 248 | { |
| 249 | return trace2_enabled; |
| 250 | } |
| 251 | |
| 252 | /* |
| 253 | * Redacts an argument, i.e. ensures that no password in |
| 254 | * https://user:password@host/-style URLs is logged. |
| 255 | * |
| 256 | * Returns the original if nothing needed to be redacted. |
| 257 | * Returns a pointer that needs to be `free()`d otherwise. |
| 258 | */ |
| 259 | static const char *redact_arg(const char *arg) |
| 260 | { |
| 261 | const char *p, *colon; |
| 262 | size_t at; |
| 263 | |
| 264 | if (!trace2_redact || |
| 265 | (!skip_prefix(arg, "https://", &p) && |
| 266 | !skip_prefix(arg, "http://", &p))) |
| 267 | return arg; |
| 268 | |
| 269 | at = strcspn(p, "@/"); |
| 270 | if (p[at] != '@') |
| 271 | return arg; |
| 272 | |
| 273 | colon = memchr(p, ':', at); |
| 274 | if (!colon) |
| 275 | return arg; |
| 276 | |
| 277 | return xstrfmt("%.*s:<REDACTED>%s", (int)(colon - arg), arg, p + at); |
| 278 | } |
| 279 | |
| 280 | /* |
| 281 | * Redacts arguments in an argument list. |
| 282 | * |
| 283 | * Returns the original if nothing needed to be redacted. |
| 284 | * Otherwise, returns a new array that needs to be released |
| 285 | * via `free_redacted_argv()`. |
| 286 | */ |
| 287 | static const char **redact_argv(const char **argv) |
| 288 | { |
| 289 | int i, j; |
| 290 | const char *redacted = NULL; |
| 291 | const char **ret; |
| 292 | |
| 293 | if (!trace2_redact) |
| 294 | return argv; |
| 295 | |
| 296 | for (i = 0; argv[i]; i++) |
| 297 | if ((redacted = redact_arg(argv[i])) != argv[i]) |
| 298 | break; |
| 299 | |
| 300 | if (!argv[i]) |
| 301 | return argv; |
| 302 | |
| 303 | for (j = 0; argv[j]; j++) |
| 304 | ; /* keep counting */ |
| 305 | |
| 306 | ALLOC_ARRAY(ret, j + 1); |
| 307 | ret[j] = NULL; |
| 308 | |
| 309 | for (j = 0; j < i; j++) |
| 310 | ret[j] = argv[j]; |
| 311 | ret[i] = redacted; |
| 312 | for (++i; argv[i]; i++) { |
| 313 | redacted = redact_arg(argv[i]); |
| 314 | ret[i] = redacted ? redacted : argv[i]; |
| 315 | } |
| 316 | |
| 317 | return ret; |
| 318 | } |
| 319 | |
| 320 | static void free_redacted_argv(const char **redacted, const char **argv) |
| 321 | { |
| 322 | int i; |
| 323 | |
| 324 | if (redacted != argv) { |
| 325 | for (i = 0; argv[i]; i++) |
| 326 | if (redacted[i] != argv[i]) |
| 327 | free((void *)redacted[i]); |
| 328 | free((void *)redacted); |
| 329 | } |
| 330 | } |
| 331 | |
| 332 | void trace2_cmd_start_fl(const char *file, int line, const char **argv) |
| 333 | { |
| 334 | struct tr2_tgt *tgt_j; |
| 335 | int j; |
| 336 | uint64_t us_now; |
| 337 | uint64_t us_elapsed_absolute; |
| 338 | const char **redacted; |
| 339 | |
| 340 | if (!trace2_enabled) |
| 341 | return; |
| 342 | |
| 343 | us_now = getnanotime() / 1000; |
| 344 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 345 | |
| 346 | redacted = redact_argv(argv); |
| 347 | |
| 348 | for_each_wanted_builtin (j, tgt_j) |
| 349 | if (tgt_j->pfn_start_fl) |
| 350 | tgt_j->pfn_start_fl(file, line, us_elapsed_absolute, |
| 351 | redacted); |
| 352 | |
| 353 | free_redacted_argv(redacted, argv); |
| 354 | } |
| 355 | |
| 356 | void trace2_cmd_exit_fl(const char *file, int line, int code) |
| 357 | { |
| 358 | struct tr2_tgt *tgt_j; |
| 359 | int j; |
| 360 | uint64_t us_now; |
| 361 | uint64_t us_elapsed_absolute; |
| 362 | |
| 363 | if (!trace2_enabled) |
| 364 | return; |
| 365 | |
| 366 | trace2_collect_process_info(TRACE2_PROCESS_INFO_EXIT); |
| 367 | |
| 368 | tr2main_exit_code = code; |
| 369 | |
| 370 | us_now = getnanotime() / 1000; |
| 371 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 372 | |
| 373 | for_each_wanted_builtin (j, tgt_j) |
| 374 | if (tgt_j->pfn_exit_fl) |
| 375 | tgt_j->pfn_exit_fl(file, line, us_elapsed_absolute, |
| 376 | code); |
| 377 | } |
| 378 | |
| 379 | void trace2_cmd_error_va_fl(const char *file, int line, const char *fmt, |
| 380 | va_list ap) |
| 381 | { |
| 382 | struct tr2_tgt *tgt_j; |
| 383 | int j; |
| 384 | |
| 385 | if (!trace2_enabled) |
| 386 | return; |
| 387 | |
| 388 | /* |
| 389 | * We expect each target function to treat 'ap' as constant |
| 390 | * and use va_copy (because an 'ap' can only be walked once). |
| 391 | */ |
| 392 | for_each_wanted_builtin (j, tgt_j) |
| 393 | if (tgt_j->pfn_error_va_fl) |
| 394 | tgt_j->pfn_error_va_fl(file, line, fmt, ap); |
| 395 | } |
| 396 | |
| 397 | void trace2_cmd_path_fl(const char *file, int line, const char *pathname) |
| 398 | { |
| 399 | struct tr2_tgt *tgt_j; |
| 400 | int j; |
| 401 | |
| 402 | if (!trace2_enabled) |
| 403 | return; |
| 404 | |
| 405 | for_each_wanted_builtin (j, tgt_j) |
| 406 | if (tgt_j->pfn_command_path_fl) |
| 407 | tgt_j->pfn_command_path_fl(file, line, pathname); |
| 408 | } |
| 409 | |
| 410 | void trace2_cmd_ancestry_fl(const char *file, int line, const char **parent_names) |
| 411 | { |
| 412 | struct tr2_tgt *tgt_j; |
| 413 | int j; |
| 414 | |
| 415 | if (!trace2_enabled) |
| 416 | return; |
| 417 | |
| 418 | for_each_wanted_builtin (j, tgt_j) |
| 419 | if (tgt_j->pfn_command_ancestry_fl) |
| 420 | tgt_j->pfn_command_ancestry_fl(file, line, parent_names); |
| 421 | } |
| 422 | |
| 423 | void trace2_cmd_name_fl(const char *file, int line, const char *name) |
| 424 | { |
| 425 | struct tr2_tgt *tgt_j; |
| 426 | const char *hierarchy; |
| 427 | int j; |
| 428 | |
| 429 | if (!trace2_enabled) |
| 430 | return; |
| 431 | |
| 432 | tr2_cmd_name_append_hierarchy(name); |
| 433 | hierarchy = tr2_cmd_name_get_hierarchy(); |
| 434 | |
| 435 | for_each_wanted_builtin (j, tgt_j) |
| 436 | if (tgt_j->pfn_command_name_fl) |
| 437 | tgt_j->pfn_command_name_fl(file, line, name, hierarchy); |
| 438 | |
| 439 | trace2_cmd_list_config(); |
| 440 | trace2_cmd_list_env_vars(); |
| 441 | } |
| 442 | |
| 443 | void trace2_cmd_mode_fl(const char *file, int line, const char *mode) |
| 444 | { |
| 445 | struct tr2_tgt *tgt_j; |
| 446 | int j; |
| 447 | |
| 448 | if (!trace2_enabled) |
| 449 | return; |
| 450 | |
| 451 | for_each_wanted_builtin (j, tgt_j) |
| 452 | if (tgt_j->pfn_command_mode_fl) |
| 453 | tgt_j->pfn_command_mode_fl(file, line, mode); |
| 454 | } |
| 455 | |
| 456 | void trace2_cmd_alias_fl(const char *file, int line, const char *alias, |
| 457 | const char **argv) |
| 458 | { |
| 459 | struct tr2_tgt *tgt_j; |
| 460 | int j; |
| 461 | |
| 462 | if (!trace2_enabled) |
| 463 | return; |
| 464 | |
| 465 | for_each_wanted_builtin (j, tgt_j) |
| 466 | if (tgt_j->pfn_alias_fl) |
| 467 | tgt_j->pfn_alias_fl(file, line, alias, argv); |
| 468 | } |
| 469 | |
| 470 | void trace2_cmd_list_config_fl(const char *file, int line) |
| 471 | { |
| 472 | static int emitted = 0; |
| 473 | |
| 474 | if (!trace2_enabled) |
| 475 | return; |
| 476 | |
| 477 | if (emitted) |
| 478 | return; |
| 479 | emitted = 1; |
| 480 | |
| 481 | tr2_cfg_list_config_fl(file, line); |
| 482 | } |
| 483 | |
| 484 | void trace2_cmd_list_env_vars_fl(const char *file, int line) |
| 485 | { |
| 486 | static int emitted = 0; |
| 487 | |
| 488 | if (!trace2_enabled) |
| 489 | return; |
| 490 | |
| 491 | if (emitted) |
| 492 | return; |
| 493 | emitted = 1; |
| 494 | |
| 495 | tr2_list_env_vars_fl(file, line); |
| 496 | } |
| 497 | |
| 498 | void trace2_cmd_set_config_fl(const char *file, int line, const char *key, |
| 499 | const char *value) |
| 500 | { |
| 501 | if (!trace2_enabled) |
| 502 | return; |
| 503 | |
| 504 | tr2_cfg_set_fl(file, line, key, value); |
| 505 | } |
| 506 | |
| 507 | void trace2_child_start_fl(const char *file, int line, |
| 508 | struct child_process *cmd) |
| 509 | { |
| 510 | struct tr2_tgt *tgt_j; |
| 511 | int j; |
| 512 | uint64_t us_now; |
| 513 | uint64_t us_elapsed_absolute; |
| 514 | const char **orig_argv = cmd->args.v; |
| 515 | |
| 516 | if (!trace2_enabled) |
| 517 | return; |
| 518 | |
| 519 | us_now = getnanotime() / 1000; |
| 520 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 521 | |
| 522 | cmd->trace2_child_id = tr2tls_locked_increment(&tr2_next_child_id); |
| 523 | cmd->trace2_child_us_start = us_now; |
| 524 | |
| 525 | /* |
| 526 | * The `pfn_child_start_fl` API takes a `struct child_process` |
| 527 | * rather than a simple `argv` for the child because some |
| 528 | * targets make use of the additional context bits/values. So |
| 529 | * temporarily replace the original argv (inside the `strvec`) |
| 530 | * with a possibly redacted version. |
| 531 | */ |
| 532 | cmd->args.v = redact_argv(orig_argv); |
| 533 | |
| 534 | for_each_wanted_builtin (j, tgt_j) |
| 535 | if (tgt_j->pfn_child_start_fl) |
| 536 | tgt_j->pfn_child_start_fl(file, line, |
| 537 | us_elapsed_absolute, cmd); |
| 538 | |
| 539 | if (cmd->args.v != orig_argv) { |
| 540 | free_redacted_argv(cmd->args.v, orig_argv); |
| 541 | cmd->args.v = orig_argv; |
| 542 | } |
| 543 | } |
| 544 | |
| 545 | void trace2_child_exit_fl(const char *file, int line, struct child_process *cmd, |
| 546 | int child_exit_code) |
| 547 | { |
| 548 | struct tr2_tgt *tgt_j; |
| 549 | int j; |
| 550 | uint64_t us_now; |
| 551 | uint64_t us_elapsed_absolute; |
| 552 | uint64_t us_elapsed_child; |
| 553 | |
| 554 | if (!trace2_enabled) |
| 555 | return; |
| 556 | |
| 557 | us_now = getnanotime() / 1000; |
| 558 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 559 | |
| 560 | if (cmd->trace2_child_us_start) |
| 561 | us_elapsed_child = us_now - cmd->trace2_child_us_start; |
| 562 | else |
| 563 | us_elapsed_child = 0; |
| 564 | |
| 565 | for_each_wanted_builtin (j, tgt_j) |
| 566 | if (tgt_j->pfn_child_exit_fl) |
| 567 | tgt_j->pfn_child_exit_fl(file, line, |
| 568 | us_elapsed_absolute, |
| 569 | cmd->trace2_child_id, cmd->pid, |
| 570 | child_exit_code, |
| 571 | us_elapsed_child); |
| 572 | } |
| 573 | |
| 574 | void trace2_child_ready_fl(const char *file, int line, |
| 575 | struct child_process *cmd, |
| 576 | const char *ready) |
| 577 | { |
| 578 | struct tr2_tgt *tgt_j; |
| 579 | int j; |
| 580 | uint64_t us_now; |
| 581 | uint64_t us_elapsed_absolute; |
| 582 | uint64_t us_elapsed_child; |
| 583 | |
| 584 | if (!trace2_enabled) |
| 585 | return; |
| 586 | |
| 587 | us_now = getnanotime() / 1000; |
| 588 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 589 | |
| 590 | if (cmd->trace2_child_us_start) |
| 591 | us_elapsed_child = us_now - cmd->trace2_child_us_start; |
| 592 | else |
| 593 | us_elapsed_child = 0; |
| 594 | |
| 595 | for_each_wanted_builtin (j, tgt_j) |
| 596 | if (tgt_j->pfn_child_ready_fl) |
| 597 | tgt_j->pfn_child_ready_fl(file, line, |
| 598 | us_elapsed_absolute, |
| 599 | cmd->trace2_child_id, |
| 600 | cmd->pid, |
| 601 | ready, |
| 602 | us_elapsed_child); |
| 603 | } |
| 604 | |
| 605 | int trace2_exec_fl(const char *file, int line, const char *exe, |
| 606 | const char **argv) |
| 607 | { |
| 608 | struct tr2_tgt *tgt_j; |
| 609 | int j; |
| 610 | int exec_id; |
| 611 | uint64_t us_now; |
| 612 | uint64_t us_elapsed_absolute; |
| 613 | const char **redacted; |
| 614 | |
| 615 | if (!trace2_enabled) |
| 616 | return -1; |
| 617 | |
| 618 | us_now = getnanotime() / 1000; |
| 619 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 620 | |
| 621 | exec_id = tr2tls_locked_increment(&tr2_next_exec_id); |
| 622 | |
| 623 | redacted = redact_argv(argv); |
| 624 | |
| 625 | for_each_wanted_builtin (j, tgt_j) |
| 626 | if (tgt_j->pfn_exec_fl) |
| 627 | tgt_j->pfn_exec_fl(file, line, us_elapsed_absolute, |
| 628 | exec_id, exe, redacted); |
| 629 | |
| 630 | free_redacted_argv(redacted, argv); |
| 631 | |
| 632 | return exec_id; |
| 633 | } |
| 634 | |
| 635 | void trace2_exec_result_fl(const char *file, int line, int exec_id, int code) |
| 636 | { |
| 637 | struct tr2_tgt *tgt_j; |
| 638 | int j; |
| 639 | uint64_t us_now; |
| 640 | uint64_t us_elapsed_absolute; |
| 641 | |
| 642 | if (!trace2_enabled) |
| 643 | return; |
| 644 | |
| 645 | us_now = getnanotime() / 1000; |
| 646 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 647 | |
| 648 | for_each_wanted_builtin (j, tgt_j) |
| 649 | if (tgt_j->pfn_exec_result_fl) |
| 650 | tgt_j->pfn_exec_result_fl( |
| 651 | file, line, us_elapsed_absolute, exec_id, code); |
| 652 | } |
| 653 | |
| 654 | void trace2_thread_start_fl(const char *file, int line, const char *thread_base_name) |
| 655 | { |
| 656 | struct tr2_tgt *tgt_j; |
| 657 | int j; |
| 658 | uint64_t us_now; |
| 659 | uint64_t us_elapsed_absolute; |
| 660 | |
| 661 | if (!trace2_enabled) |
| 662 | return; |
| 663 | |
| 664 | if (tr2tls_is_main_thread()) { |
| 665 | /* |
| 666 | * We should only be called from the new thread's thread-proc, |
| 667 | * so this is technically a bug. But in those cases where the |
| 668 | * main thread also runs the thread-proc function (or when we |
| 669 | * are built with threading disabled), we need to allow it. |
| 670 | * |
| 671 | * Convert this call to a region-enter so the nesting looks |
| 672 | * correct. |
| 673 | */ |
| 674 | trace2_region_enter_printf_fl(file, line, NULL, NULL, NULL, |
| 675 | "thread-proc on main: %s", |
| 676 | thread_base_name); |
| 677 | return; |
| 678 | } |
| 679 | |
| 680 | us_now = getnanotime() / 1000; |
| 681 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 682 | |
| 683 | tr2tls_create_self(thread_base_name, us_now); |
| 684 | |
| 685 | for_each_wanted_builtin (j, tgt_j) |
| 686 | if (tgt_j->pfn_thread_start_fl) |
| 687 | tgt_j->pfn_thread_start_fl(file, line, |
| 688 | us_elapsed_absolute); |
| 689 | } |
| 690 | |
| 691 | void trace2_thread_exit_fl(const char *file, int line) |
| 692 | { |
| 693 | struct tr2_tgt *tgt_j; |
| 694 | int j; |
| 695 | uint64_t us_now; |
| 696 | uint64_t us_elapsed_absolute; |
| 697 | uint64_t us_elapsed_thread; |
| 698 | |
| 699 | if (!trace2_enabled) |
| 700 | return; |
| 701 | |
| 702 | if (tr2tls_is_main_thread()) { |
| 703 | /* |
| 704 | * We should only be called from the exiting thread's |
| 705 | * thread-proc, so this is technically a bug. But in |
| 706 | * those cases where the main thread also runs the |
| 707 | * thread-proc function (or when we are built with |
| 708 | * threading disabled), we need to allow it. |
| 709 | * |
| 710 | * Convert this call to a region-leave so the nesting |
| 711 | * looks correct. |
| 712 | */ |
| 713 | trace2_region_leave_printf_fl(file, line, NULL, NULL, NULL, |
| 714 | "thread-proc on main"); |
| 715 | return; |
| 716 | } |
| 717 | |
| 718 | us_now = getnanotime() / 1000; |
| 719 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 720 | |
| 721 | /* |
| 722 | * Clear any unbalanced regions and then get the relative time |
| 723 | * for the outer-most region (which we pushed when the thread |
| 724 | * started). This gives us the run time of the thread. |
| 725 | */ |
| 726 | tr2tls_pop_unwind_self(); |
| 727 | us_elapsed_thread = tr2tls_region_elasped_self(us_now); |
| 728 | |
| 729 | /* |
| 730 | * Some timers want per-thread details. If this thread used |
| 731 | * one of those timers, emit the details now. |
| 732 | * |
| 733 | * Likewise for counters. |
| 734 | */ |
| 735 | tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer); |
| 736 | tr2_emit_per_thread_counters(tr2_tgt_emit_a_counter); |
| 737 | |
| 738 | /* |
| 739 | * Add stopwatch timer and counter data from the current |
| 740 | * (non-main) thread to the final totals. (We'll accumulate |
| 741 | * data for the main thread later during "atexit".) |
| 742 | */ |
| 743 | tr2tls_lock(); |
| 744 | tr2_update_final_timers(); |
| 745 | tr2_update_final_counters(); |
| 746 | tr2tls_unlock(); |
| 747 | |
| 748 | for_each_wanted_builtin (j, tgt_j) |
| 749 | if (tgt_j->pfn_thread_exit_fl) |
| 750 | tgt_j->pfn_thread_exit_fl(file, line, |
| 751 | us_elapsed_absolute, |
| 752 | us_elapsed_thread); |
| 753 | |
| 754 | tr2tls_unset_self(); |
| 755 | } |
| 756 | |
| 757 | void trace2_def_param_fl(const char *file, int line, const char *param, |
| 758 | const char *value, const struct key_value_info *kvi) |
| 759 | { |
| 760 | struct tr2_tgt *tgt_j; |
| 761 | int j; |
| 762 | const char *redacted; |
| 763 | |
| 764 | if (!trace2_enabled) |
| 765 | return; |
| 766 | |
| 767 | redacted = value ? redact_arg(value) : NULL; |
| 768 | |
| 769 | for_each_wanted_builtin (j, tgt_j) |
| 770 | if (tgt_j->pfn_param_fl) |
| 771 | tgt_j->pfn_param_fl(file, line, param, redacted, kvi); |
| 772 | |
| 773 | if (redacted != value) |
| 774 | free((void *)redacted); |
| 775 | } |
| 776 | |
| 777 | void trace2_def_repo_fl(const char *file, int line, struct repository *repo) |
| 778 | { |
| 779 | struct tr2_tgt *tgt_j; |
| 780 | int j; |
| 781 | |
| 782 | if (!trace2_enabled) |
| 783 | return; |
| 784 | |
| 785 | if (repo->trace2_repo_id) |
| 786 | return; |
| 787 | |
| 788 | repo->trace2_repo_id = tr2tls_locked_increment(&tr2_next_repo_id); |
| 789 | |
| 790 | for_each_wanted_builtin (j, tgt_j) |
| 791 | if (tgt_j->pfn_repo_fl) |
| 792 | tgt_j->pfn_repo_fl(file, line, repo); |
| 793 | } |
| 794 | |
| 795 | void trace2_region_enter_printf_va_fl(const char *file, int line, |
| 796 | const char *category, const char *label, |
| 797 | const struct repository *repo, |
| 798 | const char *fmt, va_list ap) |
| 799 | { |
| 800 | struct tr2_tgt *tgt_j; |
| 801 | int j; |
| 802 | uint64_t us_now; |
| 803 | uint64_t us_elapsed_absolute; |
| 804 | |
| 805 | if (!trace2_enabled) |
| 806 | return; |
| 807 | |
| 808 | us_now = getnanotime() / 1000; |
| 809 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 810 | |
| 811 | /* |
| 812 | * Print the region-enter message at the current nesting |
| 813 | * (indentation) level and then push a new level. |
| 814 | * |
| 815 | * We expect each target function to treat 'ap' as constant |
| 816 | * and use va_copy. |
| 817 | */ |
| 818 | for_each_wanted_builtin (j, tgt_j) |
| 819 | if (tgt_j->pfn_region_enter_printf_va_fl) |
| 820 | tgt_j->pfn_region_enter_printf_va_fl( |
| 821 | file, line, us_elapsed_absolute, category, |
| 822 | label, repo, fmt, ap); |
| 823 | |
| 824 | tr2tls_push_self(us_now); |
| 825 | } |
| 826 | |
| 827 | void trace2_region_enter_fl(const char *file, int line, const char *category, |
| 828 | const char *label, const struct repository *repo, ...) |
| 829 | { |
| 830 | va_list ap; |
| 831 | va_start(ap, repo); |
| 832 | trace2_region_enter_printf_va_fl(file, line, category, label, repo, |
| 833 | NULL, ap); |
| 834 | va_end(ap); |
| 835 | |
| 836 | } |
| 837 | |
| 838 | void trace2_region_enter_printf_fl(const char *file, int line, |
| 839 | const char *category, const char *label, |
| 840 | const struct repository *repo, |
| 841 | const char *fmt, ...) |
| 842 | { |
| 843 | va_list ap; |
| 844 | |
| 845 | va_start(ap, fmt); |
| 846 | trace2_region_enter_printf_va_fl(file, line, category, label, repo, fmt, |
| 847 | ap); |
| 848 | va_end(ap); |
| 849 | } |
| 850 | |
| 851 | void trace2_region_leave_printf_va_fl(const char *file, int line, |
| 852 | const char *category, const char *label, |
| 853 | const struct repository *repo, |
| 854 | const char *fmt, va_list ap) |
| 855 | { |
| 856 | struct tr2_tgt *tgt_j; |
| 857 | int j; |
| 858 | uint64_t us_now; |
| 859 | uint64_t us_elapsed_absolute; |
| 860 | uint64_t us_elapsed_region; |
| 861 | |
| 862 | if (!trace2_enabled) |
| 863 | return; |
| 864 | |
| 865 | us_now = getnanotime() / 1000; |
| 866 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 867 | |
| 868 | /* |
| 869 | * Get the elapsed time in the current region before we |
| 870 | * pop it off the stack. Pop the stack. And then print |
| 871 | * the perf message at the new (shallower) level so that |
| 872 | * it lines up with the corresponding push/enter. |
| 873 | */ |
| 874 | us_elapsed_region = tr2tls_region_elasped_self(us_now); |
| 875 | |
| 876 | tr2tls_pop_self(); |
| 877 | |
| 878 | /* |
| 879 | * We expect each target function to treat 'ap' as constant |
| 880 | * and use va_copy. |
| 881 | */ |
| 882 | for_each_wanted_builtin (j, tgt_j) |
| 883 | if (tgt_j->pfn_region_leave_printf_va_fl) |
| 884 | tgt_j->pfn_region_leave_printf_va_fl( |
| 885 | file, line, us_elapsed_absolute, |
| 886 | us_elapsed_region, category, label, repo, fmt, |
| 887 | ap); |
| 888 | } |
| 889 | |
| 890 | void trace2_region_leave_fl(const char *file, int line, const char *category, |
| 891 | const char *label, const struct repository *repo, ...) |
| 892 | { |
| 893 | va_list ap; |
| 894 | va_start(ap, repo); |
| 895 | trace2_region_leave_printf_va_fl(file, line, category, label, repo, |
| 896 | NULL, ap); |
| 897 | va_end(ap); |
| 898 | } |
| 899 | |
| 900 | void trace2_region_leave_printf_fl(const char *file, int line, |
| 901 | const char *category, const char *label, |
| 902 | const struct repository *repo, |
| 903 | const char *fmt, ...) |
| 904 | { |
| 905 | va_list ap; |
| 906 | |
| 907 | va_start(ap, fmt); |
| 908 | trace2_region_leave_printf_va_fl(file, line, category, label, repo, fmt, |
| 909 | ap); |
| 910 | va_end(ap); |
| 911 | } |
| 912 | |
| 913 | void trace2_data_string_fl(const char *file, int line, const char *category, |
| 914 | const struct repository *repo, const char *key, |
| 915 | const char *value) |
| 916 | { |
| 917 | struct tr2_tgt *tgt_j; |
| 918 | int j; |
| 919 | uint64_t us_now; |
| 920 | uint64_t us_elapsed_absolute; |
| 921 | uint64_t us_elapsed_region; |
| 922 | |
| 923 | if (!trace2_enabled) |
| 924 | return; |
| 925 | |
| 926 | us_now = getnanotime() / 1000; |
| 927 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 928 | us_elapsed_region = tr2tls_region_elasped_self(us_now); |
| 929 | |
| 930 | for_each_wanted_builtin (j, tgt_j) |
| 931 | if (tgt_j->pfn_data_fl) |
| 932 | tgt_j->pfn_data_fl(file, line, us_elapsed_absolute, |
| 933 | us_elapsed_region, category, repo, |
| 934 | key, value); |
| 935 | } |
| 936 | |
| 937 | void trace2_data_intmax_fl(const char *file, int line, const char *category, |
| 938 | const struct repository *repo, const char *key, |
| 939 | intmax_t value) |
| 940 | { |
| 941 | struct strbuf buf_string = STRBUF_INIT; |
| 942 | |
| 943 | if (!trace2_enabled) |
| 944 | return; |
| 945 | |
| 946 | strbuf_addf(&buf_string, "%" PRIdMAX, value); |
| 947 | trace2_data_string_fl(file, line, category, repo, key, buf_string.buf); |
| 948 | strbuf_release(&buf_string); |
| 949 | } |
| 950 | |
| 951 | void trace2_data_json_fl(const char *file, int line, const char *category, |
| 952 | const struct repository *repo, const char *key, |
| 953 | const struct json_writer *value) |
| 954 | { |
| 955 | struct tr2_tgt *tgt_j; |
| 956 | int j; |
| 957 | uint64_t us_now; |
| 958 | uint64_t us_elapsed_absolute; |
| 959 | uint64_t us_elapsed_region; |
| 960 | |
| 961 | if (!trace2_enabled) |
| 962 | return; |
| 963 | |
| 964 | us_now = getnanotime() / 1000; |
| 965 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 966 | us_elapsed_region = tr2tls_region_elasped_self(us_now); |
| 967 | |
| 968 | for_each_wanted_builtin (j, tgt_j) |
| 969 | if (tgt_j->pfn_data_json_fl) |
| 970 | tgt_j->pfn_data_json_fl(file, line, us_elapsed_absolute, |
| 971 | us_elapsed_region, category, |
| 972 | repo, key, value); |
| 973 | } |
| 974 | |
| 975 | void trace2_printf_va_fl(const char *file, int line, const char *fmt, |
| 976 | va_list ap) |
| 977 | { |
| 978 | struct tr2_tgt *tgt_j; |
| 979 | int j; |
| 980 | uint64_t us_now; |
| 981 | uint64_t us_elapsed_absolute; |
| 982 | |
| 983 | if (!trace2_enabled) |
| 984 | return; |
| 985 | |
| 986 | us_now = getnanotime() / 1000; |
| 987 | us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); |
| 988 | |
| 989 | /* |
| 990 | * We expect each target function to treat 'ap' as constant |
| 991 | * and use va_copy. |
| 992 | */ |
| 993 | for_each_wanted_builtin (j, tgt_j) |
| 994 | if (tgt_j->pfn_printf_va_fl) |
| 995 | tgt_j->pfn_printf_va_fl(file, line, us_elapsed_absolute, |
| 996 | fmt, ap); |
| 997 | } |
| 998 | |
| 999 | void trace2_printf_fl(const char *file, int line, const char *fmt, ...) |
| 1000 | { |
| 1001 | va_list ap; |
| 1002 | |
| 1003 | va_start(ap, fmt); |
| 1004 | trace2_printf_va_fl(file, line, fmt, ap); |
| 1005 | va_end(ap); |
| 1006 | } |
| 1007 | |
| 1008 | void trace2_timer_start(enum trace2_timer_id tid) |
| 1009 | { |
| 1010 | if (!trace2_enabled) |
| 1011 | return; |
| 1012 | |
| 1013 | if (tid < 0 || tid >= TRACE2_NUMBER_OF_TIMERS) |
| 1014 | BUG("trace2_timer_start: invalid timer id: %d", tid); |
| 1015 | |
| 1016 | tr2_start_timer(tid); |
| 1017 | } |
| 1018 | |
| 1019 | void trace2_timer_stop(enum trace2_timer_id tid) |
| 1020 | { |
| 1021 | if (!trace2_enabled) |
| 1022 | return; |
| 1023 | |
| 1024 | if (tid < 0 || tid >= TRACE2_NUMBER_OF_TIMERS) |
| 1025 | BUG("trace2_timer_stop: invalid timer id: %d", tid); |
| 1026 | |
| 1027 | tr2_stop_timer(tid); |
| 1028 | } |
| 1029 | |
| 1030 | void trace2_counter_add(enum trace2_counter_id cid, uint64_t value) |
| 1031 | { |
| 1032 | if (!trace2_enabled) |
| 1033 | return; |
| 1034 | |
| 1035 | if (cid < 0 || cid >= TRACE2_NUMBER_OF_COUNTERS) |
| 1036 | BUG("trace2_counter_add: invalid counter id: %d", cid); |
| 1037 | |
| 1038 | tr2_counter_increment(cid, value); |
| 1039 | } |
| 1040 | |
| 1041 | const char *trace2_session_id(void) |
| 1042 | { |
| 1043 | return tr2_sid_get(); |
| 1044 | } |