trace2.c

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