trace2.c

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