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         if (!trace2_enabled)
 468                 return;
 469
 470         tr2_cfg_list_config_fl(file, line);
 471 }
 472
 473 void trace2_cmd_list_env_vars_fl(const char *file, int line)
 474 {
 475         if (!trace2_enabled)
 476                 return;
 477
 478         tr2_list_env_vars_fl(file, line);
 479 }
 480
 481 void trace2_cmd_set_config_fl(const char *file, int line, const char *key,
 482                               const char *value)
 483 {
 484         if (!trace2_enabled)
 485                 return;
 486
 487         tr2_cfg_set_fl(file, line, key, value);
 488 }
 489
 490 void trace2_child_start_fl(const char *file, int line,
 491                            struct child_process *cmd)
 492 {
 493         struct tr2_tgt *tgt_j;
 494         int j;
 495         uint64_t us_now;
 496         uint64_t us_elapsed_absolute;
 497         const char **orig_argv = cmd->args.v;
 498
 499         if (!trace2_enabled)
 500                 return;
 501
 502         us_now = getnanotime() / 1000;
 503         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 504
 505         cmd->trace2_child_id = tr2tls_locked_increment(&tr2_next_child_id);
 506         cmd->trace2_child_us_start = us_now;
 507
 508         /*
 509          * The `pfn_child_start_fl` API takes a `struct child_process`
 510          * rather than a simple `argv` for the child because some
 511          * targets make use of the additional context bits/values. So
 512          * temporarily replace the original argv (inside the `strvec`)
 513          * with a possibly redacted version.
 514          */
 515         cmd->args.v = redact_argv(orig_argv);
 516
 517         for_each_wanted_builtin (j, tgt_j)
 518                 if (tgt_j->pfn_child_start_fl)
 519                         tgt_j->pfn_child_start_fl(file, line,
 520                                                   us_elapsed_absolute, cmd);
 521
 522         if (cmd->args.v != orig_argv) {
 523                 free_redacted_argv(cmd->args.v, orig_argv);
 524                 cmd->args.v = orig_argv;
 525         }
 526 }
 527
 528 void trace2_child_exit_fl(const char *file, int line, struct child_process *cmd,
 529                           int child_exit_code)
 530 {
 531         struct tr2_tgt *tgt_j;
 532         int j;
 533         uint64_t us_now;
 534         uint64_t us_elapsed_absolute;
 535         uint64_t us_elapsed_child;
 536
 537         if (!trace2_enabled)
 538                 return;
 539
 540         us_now = getnanotime() / 1000;
 541         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 542
 543         if (cmd->trace2_child_us_start)
 544                 us_elapsed_child = us_now - cmd->trace2_child_us_start;
 545         else
 546                 us_elapsed_child = 0;
 547
 548         for_each_wanted_builtin (j, tgt_j)
 549                 if (tgt_j->pfn_child_exit_fl)
 550                         tgt_j->pfn_child_exit_fl(file, line,
 551                                                  us_elapsed_absolute,
 552                                                  cmd->trace2_child_id, cmd->pid,
 553                                                  child_exit_code,
 554                                                  us_elapsed_child);
 555 }
 556
 557 void trace2_child_ready_fl(const char *file, int line,
 558                            struct child_process *cmd,
 559                            const char *ready)
 560 {
 561         struct tr2_tgt *tgt_j;
 562         int j;
 563         uint64_t us_now;
 564         uint64_t us_elapsed_absolute;
 565         uint64_t us_elapsed_child;
 566
 567         if (!trace2_enabled)
 568                 return;
 569
 570         us_now = getnanotime() / 1000;
 571         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 572
 573         if (cmd->trace2_child_us_start)
 574                 us_elapsed_child = us_now - cmd->trace2_child_us_start;
 575         else
 576                 us_elapsed_child = 0;
 577
 578         for_each_wanted_builtin (j, tgt_j)
 579                 if (tgt_j->pfn_child_ready_fl)
 580                         tgt_j->pfn_child_ready_fl(file, line,
 581                                                   us_elapsed_absolute,
 582                                                   cmd->trace2_child_id,
 583                                                   cmd->pid,
 584                                                   ready,
 585                                                   us_elapsed_child);
 586 }
 587
 588 int trace2_exec_fl(const char *file, int line, const char *exe,
 589                    const char **argv)
 590 {
 591         struct tr2_tgt *tgt_j;
 592         int j;
 593         int exec_id;
 594         uint64_t us_now;
 595         uint64_t us_elapsed_absolute;
 596         const char **redacted;
 597
 598         if (!trace2_enabled)
 599                 return -1;
 600
 601         us_now = getnanotime() / 1000;
 602         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 603
 604         exec_id = tr2tls_locked_increment(&tr2_next_exec_id);
 605
 606         redacted = redact_argv(argv);
 607
 608         for_each_wanted_builtin (j, tgt_j)
 609                 if (tgt_j->pfn_exec_fl)
 610                         tgt_j->pfn_exec_fl(file, line, us_elapsed_absolute,
 611                                            exec_id, exe, redacted);
 612
 613         free_redacted_argv(redacted, argv);
 614
 615         return exec_id;
 616 }
 617
 618 void trace2_exec_result_fl(const char *file, int line, int exec_id, int code)
 619 {
 620         struct tr2_tgt *tgt_j;
 621         int j;
 622         uint64_t us_now;
 623         uint64_t us_elapsed_absolute;
 624
 625         if (!trace2_enabled)
 626                 return;
 627
 628         us_now = getnanotime() / 1000;
 629         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 630
 631         for_each_wanted_builtin (j, tgt_j)
 632                 if (tgt_j->pfn_exec_result_fl)
 633                         tgt_j->pfn_exec_result_fl(
 634                                 file, line, us_elapsed_absolute, exec_id, code);
 635 }
 636
 637 void trace2_thread_start_fl(const char *file, int line, const char *thread_base_name)
 638 {
 639         struct tr2_tgt *tgt_j;
 640         int j;
 641         uint64_t us_now;
 642         uint64_t us_elapsed_absolute;
 643
 644         if (!trace2_enabled)
 645                 return;
 646
 647         if (tr2tls_is_main_thread()) {
 648                 /*
 649                  * We should only be called from the new thread's thread-proc,
 650                  * so this is technically a bug.  But in those cases where the
 651                  * main thread also runs the thread-proc function (or when we
 652                  * are built with threading disabled), we need to allow it.
 653                  *
 654                  * Convert this call to a region-enter so the nesting looks
 655                  * correct.
 656                  */
 657                 trace2_region_enter_printf_fl(file, line, NULL, NULL, NULL,
 658                                               "thread-proc on main: %s",
 659                                               thread_base_name);
 660                 return;
 661         }
 662
 663         us_now = getnanotime() / 1000;
 664         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 665
 666         tr2tls_create_self(thread_base_name, us_now);
 667
 668         for_each_wanted_builtin (j, tgt_j)
 669                 if (tgt_j->pfn_thread_start_fl)
 670                         tgt_j->pfn_thread_start_fl(file, line,
 671                                                    us_elapsed_absolute);
 672 }
 673
 674 void trace2_thread_exit_fl(const char *file, int line)
 675 {
 676         struct tr2_tgt *tgt_j;
 677         int j;
 678         uint64_t us_now;
 679         uint64_t us_elapsed_absolute;
 680         uint64_t us_elapsed_thread;
 681
 682         if (!trace2_enabled)
 683                 return;
 684
 685         if (tr2tls_is_main_thread()) {
 686                 /*
 687                  * We should only be called from the exiting thread's
 688                  * thread-proc, so this is technically a bug.  But in
 689                  * those cases where the main thread also runs the
 690                  * thread-proc function (or when we are built with
 691                  * threading disabled), we need to allow it.
 692                  *
 693                  * Convert this call to a region-leave so the nesting
 694                  * looks correct.
 695                  */
 696                 trace2_region_leave_printf_fl(file, line, NULL, NULL, NULL,
 697                                               "thread-proc on main");
 698                 return;
 699         }
 700
 701         us_now = getnanotime() / 1000;
 702         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 703
 704         /*
 705          * Clear any unbalanced regions and then get the relative time
 706          * for the outer-most region (which we pushed when the thread
 707          * started).  This gives us the run time of the thread.
 708          */
 709         tr2tls_pop_unwind_self();
 710         us_elapsed_thread = tr2tls_region_elasped_self(us_now);
 711
 712         /*
 713          * Some timers want per-thread details.  If this thread used
 714          * one of those timers, emit the details now.
 715          *
 716          * Likewise for counters.
 717          */
 718         tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer);
 719         tr2_emit_per_thread_counters(tr2_tgt_emit_a_counter);
 720
 721         /*
 722          * Add stopwatch timer and counter data from the current
 723          * (non-main) thread to the final totals.  (We'll accumulate
 724          * data for the main thread later during "atexit".)
 725          */
 726         tr2tls_lock();
 727         tr2_update_final_timers();
 728         tr2_update_final_counters();
 729         tr2tls_unlock();
 730
 731         for_each_wanted_builtin (j, tgt_j)
 732                 if (tgt_j->pfn_thread_exit_fl)
 733                         tgt_j->pfn_thread_exit_fl(file, line,
 734                                                   us_elapsed_absolute,
 735                                                   us_elapsed_thread);
 736
 737         tr2tls_unset_self();
 738 }
 739
 740 void trace2_def_param_fl(const char *file, int line, const char *param,
 741                          const char *value, const struct key_value_info *kvi)
 742 {
 743         struct tr2_tgt *tgt_j;
 744         int j;
 745         const char *redacted;
 746
 747         if (!trace2_enabled)
 748                 return;
 749
 750         redacted = redact_arg(value);
 751
 752         for_each_wanted_builtin (j, tgt_j)
 753                 if (tgt_j->pfn_param_fl)
 754                         tgt_j->pfn_param_fl(file, line, param, redacted, kvi);
 755
 756         if (redacted != value)
 757                 free((void *)redacted);
 758 }
 759
 760 void trace2_def_repo_fl(const char *file, int line, struct repository *repo)
 761 {
 762         struct tr2_tgt *tgt_j;
 763         int j;
 764
 765         if (!trace2_enabled)
 766                 return;
 767
 768         if (repo->trace2_repo_id)
 769                 return;
 770
 771         repo->trace2_repo_id = tr2tls_locked_increment(&tr2_next_repo_id);
 772
 773         for_each_wanted_builtin (j, tgt_j)
 774                 if (tgt_j->pfn_repo_fl)
 775                         tgt_j->pfn_repo_fl(file, line, repo);
 776 }
 777
 778 void trace2_region_enter_printf_va_fl(const char *file, int line,
 779                                       const char *category, const char *label,
 780                                       const struct repository *repo,
 781                                       const char *fmt, va_list ap)
 782 {
 783         struct tr2_tgt *tgt_j;
 784         int j;
 785         uint64_t us_now;
 786         uint64_t us_elapsed_absolute;
 787
 788         if (!trace2_enabled)
 789                 return;
 790
 791         us_now = getnanotime() / 1000;
 792         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 793
 794         /*
 795          * Print the region-enter message at the current nesting
 796          * (indentation) level and then push a new level.
 797          *
 798          * We expect each target function to treat 'ap' as constant
 799          * and use va_copy.
 800          */
 801         for_each_wanted_builtin (j, tgt_j)
 802                 if (tgt_j->pfn_region_enter_printf_va_fl)
 803                         tgt_j->pfn_region_enter_printf_va_fl(
 804                                 file, line, us_elapsed_absolute, category,
 805                                 label, repo, fmt, ap);
 806
 807         tr2tls_push_self(us_now);
 808 }
 809
 810 void trace2_region_enter_fl(const char *file, int line, const char *category,
 811                             const char *label, const struct repository *repo, ...)
 812 {
 813         va_list ap;
 814         va_start(ap, repo);
 815         trace2_region_enter_printf_va_fl(file, line, category, label, repo,
 816                                          NULL, ap);
 817         va_end(ap);
 818
 819 }
 820
 821 void trace2_region_enter_printf_fl(const char *file, int line,
 822                                    const char *category, const char *label,
 823                                    const struct repository *repo,
 824                                    const char *fmt, ...)
 825 {
 826         va_list ap;
 827
 828         va_start(ap, fmt);
 829         trace2_region_enter_printf_va_fl(file, line, category, label, repo, fmt,
 830                                          ap);
 831         va_end(ap);
 832 }
 833
 834 void trace2_region_leave_printf_va_fl(const char *file, int line,
 835                                       const char *category, const char *label,
 836                                       const struct repository *repo,
 837                                       const char *fmt, va_list ap)
 838 {
 839         struct tr2_tgt *tgt_j;
 840         int j;
 841         uint64_t us_now;
 842         uint64_t us_elapsed_absolute;
 843         uint64_t us_elapsed_region;
 844
 845         if (!trace2_enabled)
 846                 return;
 847
 848         us_now = getnanotime() / 1000;
 849         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 850
 851         /*
 852          * Get the elapsed time in the current region before we
 853          * pop it off the stack.  Pop the stack.  And then print
 854          * the perf message at the new (shallower) level so that
 855          * it lines up with the corresponding push/enter.
 856          */
 857         us_elapsed_region = tr2tls_region_elasped_self(us_now);
 858
 859         tr2tls_pop_self();
 860
 861         /*
 862          * We expect each target function to treat 'ap' as constant
 863          * and use va_copy.
 864          */
 865         for_each_wanted_builtin (j, tgt_j)
 866                 if (tgt_j->pfn_region_leave_printf_va_fl)
 867                         tgt_j->pfn_region_leave_printf_va_fl(
 868                                 file, line, us_elapsed_absolute,
 869                                 us_elapsed_region, category, label, repo, fmt,
 870                                 ap);
 871 }
 872
 873 void trace2_region_leave_fl(const char *file, int line, const char *category,
 874                             const char *label, const struct repository *repo, ...)
 875 {
 876         va_list ap;
 877         va_start(ap, repo);
 878         trace2_region_leave_printf_va_fl(file, line, category, label, repo,
 879                                          NULL, ap);
 880         va_end(ap);
 881 }
 882
 883 void trace2_region_leave_printf_fl(const char *file, int line,
 884                                    const char *category, const char *label,
 885                                    const struct repository *repo,
 886                                    const char *fmt, ...)
 887 {
 888         va_list ap;
 889
 890         va_start(ap, fmt);
 891         trace2_region_leave_printf_va_fl(file, line, category, label, repo, fmt,
 892                                          ap);
 893         va_end(ap);
 894 }
 895
 896 void trace2_data_string_fl(const char *file, int line, const char *category,
 897                            const struct repository *repo, const char *key,
 898                            const char *value)
 899 {
 900         struct tr2_tgt *tgt_j;
 901         int j;
 902         uint64_t us_now;
 903         uint64_t us_elapsed_absolute;
 904         uint64_t us_elapsed_region;
 905
 906         if (!trace2_enabled)
 907                 return;
 908
 909         us_now = getnanotime() / 1000;
 910         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 911         us_elapsed_region = tr2tls_region_elasped_self(us_now);
 912
 913         for_each_wanted_builtin (j, tgt_j)
 914                 if (tgt_j->pfn_data_fl)
 915                         tgt_j->pfn_data_fl(file, line, us_elapsed_absolute,
 916                                            us_elapsed_region, category, repo,
 917                                            key, value);
 918 }
 919
 920 void trace2_data_intmax_fl(const char *file, int line, const char *category,
 921                            const struct repository *repo, const char *key,
 922                            intmax_t value)
 923 {
 924         struct strbuf buf_string = STRBUF_INIT;
 925
 926         if (!trace2_enabled)
 927                 return;
 928
 929         strbuf_addf(&buf_string, "%" PRIdMAX, value);
 930         trace2_data_string_fl(file, line, category, repo, key, buf_string.buf);
 931         strbuf_release(&buf_string);
 932 }
 933
 934 void trace2_data_json_fl(const char *file, int line, const char *category,
 935                          const struct repository *repo, const char *key,
 936                          const struct json_writer *value)
 937 {
 938         struct tr2_tgt *tgt_j;
 939         int j;
 940         uint64_t us_now;
 941         uint64_t us_elapsed_absolute;
 942         uint64_t us_elapsed_region;
 943
 944         if (!trace2_enabled)
 945                 return;
 946
 947         us_now = getnanotime() / 1000;
 948         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 949         us_elapsed_region = tr2tls_region_elasped_self(us_now);
 950
 951         for_each_wanted_builtin (j, tgt_j)
 952                 if (tgt_j->pfn_data_json_fl)
 953                         tgt_j->pfn_data_json_fl(file, line, us_elapsed_absolute,
 954                                                 us_elapsed_region, category,
 955                                                 repo, key, value);
 956 }
 957
 958 void trace2_printf_va_fl(const char *file, int line, const char *fmt,
 959                          va_list ap)
 960 {
 961         struct tr2_tgt *tgt_j;
 962         int j;
 963         uint64_t us_now;
 964         uint64_t us_elapsed_absolute;
 965
 966         if (!trace2_enabled)
 967                 return;
 968
 969         us_now = getnanotime() / 1000;
 970         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 971
 972         /*
 973          * We expect each target function to treat 'ap' as constant
 974          * and use va_copy.
 975          */
 976         for_each_wanted_builtin (j, tgt_j)
 977                 if (tgt_j->pfn_printf_va_fl)
 978                         tgt_j->pfn_printf_va_fl(file, line, us_elapsed_absolute,
 979                                                 fmt, ap);
 980 }
 981
 982 void trace2_printf_fl(const char *file, int line, const char *fmt, ...)
 983 {
 984         va_list ap;
 985
 986         va_start(ap, fmt);
 987         trace2_printf_va_fl(file, line, fmt, ap);
 988         va_end(ap);
 989 }
 990
 991 void trace2_timer_start(enum trace2_timer_id tid)
 992 {
 993         if (!trace2_enabled)
 994                 return;
 995
 996         if (tid < 0 || tid >= TRACE2_NUMBER_OF_TIMERS)
 997                 BUG("trace2_timer_start: invalid timer id: %d", tid);
 998
 999         tr2_start_timer(tid);
1000 }
1001
1002 void trace2_timer_stop(enum trace2_timer_id tid)
1003 {
1004         if (!trace2_enabled)
1005                 return;
1006
1007         if (tid < 0 || tid >= TRACE2_NUMBER_OF_TIMERS)
1008                 BUG("trace2_timer_stop: invalid timer id: %d", tid);
1009
1010         tr2_stop_timer(tid);
1011 }
1012
1013 void trace2_counter_add(enum trace2_counter_id cid, uint64_t value)
1014 {
1015         if (!trace2_enabled)
1016                 return;
1017
1018         if (cid < 0 || cid >= TRACE2_NUMBER_OF_COUNTERS)
1019                 BUG("trace2_counter_add: invalid counter id: %d", cid);
1020
1021         tr2_counter_increment(cid, value);
1022 }
1023
1024 const char *trace2_session_id(void)
1025 {
1026         return tr2_sid_get();
1027 }