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