trace2.c

   1 #include "git-compat-util.h"
   2 #include "config.h"
   3 #include "json-writer.h"
   4 #include "quote.h"
   5 #include "repository.h"
   6 #include "run-command.h"
   7 #include "sigchain.h"
   8 #include "thread-utils.h"
   9 #include "version.h"
  10 #include "trace.h"
  11 #include "trace2.h"
  12 #include "trace2/tr2_cfg.h"
  13 #include "trace2/tr2_cmd_name.h"
  14 #include "trace2/tr2_ctr.h"
  15 #include "trace2/tr2_dst.h"
  16 #include "trace2/tr2_sid.h"
  17 #include "trace2/tr2_sysenv.h"
  18 #include "trace2/tr2_tgt.h"
  19 #include "trace2/tr2_tls.h"
  20 #include "trace2/tr2_tmr.h"
  21
  22 static int trace2_enabled;
  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
 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 void trace2_cmd_start_fl(const char *file, int line, const char **argv)
 251 {
 252         struct tr2_tgt *tgt_j;
 253         int j;
 254         uint64_t us_now;
 255         uint64_t us_elapsed_absolute;
 256
 257         if (!trace2_enabled)
 258                 return;
 259
 260         us_now = getnanotime() / 1000;
 261         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 262
 263         for_each_wanted_builtin (j, tgt_j)
 264                 if (tgt_j->pfn_start_fl)
 265                         tgt_j->pfn_start_fl(file, line, us_elapsed_absolute,
 266                                             argv);
 267 }
 268
 269 void trace2_cmd_exit_fl(const char *file, int line, int code)
 270 {
 271         struct tr2_tgt *tgt_j;
 272         int j;
 273         uint64_t us_now;
 274         uint64_t us_elapsed_absolute;
 275
 276         if (!trace2_enabled)
 277                 return;
 278
 279         trace_git_fsync_stats();
 280         trace2_collect_process_info(TRACE2_PROCESS_INFO_EXIT);
 281
 282         tr2main_exit_code = code;
 283
 284         us_now = getnanotime() / 1000;
 285         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 286
 287         for_each_wanted_builtin (j, tgt_j)
 288                 if (tgt_j->pfn_exit_fl)
 289                         tgt_j->pfn_exit_fl(file, line, us_elapsed_absolute,
 290                                            code);
 291 }
 292
 293 void trace2_cmd_error_va_fl(const char *file, int line, const char *fmt,
 294                             va_list ap)
 295 {
 296         struct tr2_tgt *tgt_j;
 297         int j;
 298
 299         if (!trace2_enabled)
 300                 return;
 301
 302         /*
 303          * We expect each target function to treat 'ap' as constant
 304          * and use va_copy (because an 'ap' can only be walked once).
 305          */
 306         for_each_wanted_builtin (j, tgt_j)
 307                 if (tgt_j->pfn_error_va_fl)
 308                         tgt_j->pfn_error_va_fl(file, line, fmt, ap);
 309 }
 310
 311 void trace2_cmd_path_fl(const char *file, int line, const char *pathname)
 312 {
 313         struct tr2_tgt *tgt_j;
 314         int j;
 315
 316         if (!trace2_enabled)
 317                 return;
 318
 319         for_each_wanted_builtin (j, tgt_j)
 320                 if (tgt_j->pfn_command_path_fl)
 321                         tgt_j->pfn_command_path_fl(file, line, pathname);
 322 }
 323
 324 void trace2_cmd_ancestry_fl(const char *file, int line, const char **parent_names)
 325 {
 326         struct tr2_tgt *tgt_j;
 327         int j;
 328
 329         if (!trace2_enabled)
 330                 return;
 331
 332         for_each_wanted_builtin (j, tgt_j)
 333                 if (tgt_j->pfn_command_ancestry_fl)
 334                         tgt_j->pfn_command_ancestry_fl(file, line, parent_names);
 335 }
 336
 337 void trace2_cmd_name_fl(const char *file, int line, const char *name)
 338 {
 339         struct tr2_tgt *tgt_j;
 340         const char *hierarchy;
 341         int j;
 342
 343         if (!trace2_enabled)
 344                 return;
 345
 346         tr2_cmd_name_append_hierarchy(name);
 347         hierarchy = tr2_cmd_name_get_hierarchy();
 348
 349         for_each_wanted_builtin (j, tgt_j)
 350                 if (tgt_j->pfn_command_name_fl)
 351                         tgt_j->pfn_command_name_fl(file, line, name, hierarchy);
 352 }
 353
 354 void trace2_cmd_mode_fl(const char *file, int line, const char *mode)
 355 {
 356         struct tr2_tgt *tgt_j;
 357         int j;
 358
 359         if (!trace2_enabled)
 360                 return;
 361
 362         for_each_wanted_builtin (j, tgt_j)
 363                 if (tgt_j->pfn_command_mode_fl)
 364                         tgt_j->pfn_command_mode_fl(file, line, mode);
 365 }
 366
 367 void trace2_cmd_alias_fl(const char *file, int line, const char *alias,
 368                          const char **argv)
 369 {
 370         struct tr2_tgt *tgt_j;
 371         int j;
 372
 373         if (!trace2_enabled)
 374                 return;
 375
 376         for_each_wanted_builtin (j, tgt_j)
 377                 if (tgt_j->pfn_alias_fl)
 378                         tgt_j->pfn_alias_fl(file, line, alias, argv);
 379 }
 380
 381 void trace2_cmd_list_config_fl(const char *file, int line)
 382 {
 383         if (!trace2_enabled)
 384                 return;
 385
 386         tr2_cfg_list_config_fl(file, line);
 387 }
 388
 389 void trace2_cmd_list_env_vars_fl(const char *file, int line)
 390 {
 391         if (!trace2_enabled)
 392                 return;
 393
 394         tr2_list_env_vars_fl(file, line);
 395 }
 396
 397 void trace2_cmd_set_config_fl(const char *file, int line, const char *key,
 398                               const char *value)
 399 {
 400         if (!trace2_enabled)
 401                 return;
 402
 403         tr2_cfg_set_fl(file, line, key, value);
 404 }
 405
 406 void trace2_child_start_fl(const char *file, int line,
 407                            struct child_process *cmd)
 408 {
 409         struct tr2_tgt *tgt_j;
 410         int j;
 411         uint64_t us_now;
 412         uint64_t us_elapsed_absolute;
 413
 414         if (!trace2_enabled)
 415                 return;
 416
 417         us_now = getnanotime() / 1000;
 418         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 419
 420         cmd->trace2_child_id = tr2tls_locked_increment(&tr2_next_child_id);
 421         cmd->trace2_child_us_start = us_now;
 422
 423         for_each_wanted_builtin (j, tgt_j)
 424                 if (tgt_j->pfn_child_start_fl)
 425                         tgt_j->pfn_child_start_fl(file, line,
 426                                                   us_elapsed_absolute, cmd);
 427 }
 428
 429 void trace2_child_exit_fl(const char *file, int line, struct child_process *cmd,
 430                           int child_exit_code)
 431 {
 432         struct tr2_tgt *tgt_j;
 433         int j;
 434         uint64_t us_now;
 435         uint64_t us_elapsed_absolute;
 436         uint64_t us_elapsed_child;
 437
 438         if (!trace2_enabled)
 439                 return;
 440
 441         us_now = getnanotime() / 1000;
 442         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 443
 444         if (cmd->trace2_child_us_start)
 445                 us_elapsed_child = us_now - cmd->trace2_child_us_start;
 446         else
 447                 us_elapsed_child = 0;
 448
 449         for_each_wanted_builtin (j, tgt_j)
 450                 if (tgt_j->pfn_child_exit_fl)
 451                         tgt_j->pfn_child_exit_fl(file, line,
 452                                                  us_elapsed_absolute,
 453                                                  cmd->trace2_child_id, cmd->pid,
 454                                                  child_exit_code,
 455                                                  us_elapsed_child);
 456 }
 457
 458 void trace2_child_ready_fl(const char *file, int line,
 459                            struct child_process *cmd,
 460                            const char *ready)
 461 {
 462         struct tr2_tgt *tgt_j;
 463         int j;
 464         uint64_t us_now;
 465         uint64_t us_elapsed_absolute;
 466         uint64_t us_elapsed_child;
 467
 468         if (!trace2_enabled)
 469                 return;
 470
 471         us_now = getnanotime() / 1000;
 472         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 473
 474         if (cmd->trace2_child_us_start)
 475                 us_elapsed_child = us_now - cmd->trace2_child_us_start;
 476         else
 477                 us_elapsed_child = 0;
 478
 479         for_each_wanted_builtin (j, tgt_j)
 480                 if (tgt_j->pfn_child_ready_fl)
 481                         tgt_j->pfn_child_ready_fl(file, line,
 482                                                   us_elapsed_absolute,
 483                                                   cmd->trace2_child_id,
 484                                                   cmd->pid,
 485                                                   ready,
 486                                                   us_elapsed_child);
 487 }
 488
 489 int trace2_exec_fl(const char *file, int line, const char *exe,
 490                    const char **argv)
 491 {
 492         struct tr2_tgt *tgt_j;
 493         int j;
 494         int exec_id;
 495         uint64_t us_now;
 496         uint64_t us_elapsed_absolute;
 497
 498         if (!trace2_enabled)
 499                 return -1;
 500
 501         us_now = getnanotime() / 1000;
 502         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 503
 504         exec_id = tr2tls_locked_increment(&tr2_next_exec_id);
 505
 506         for_each_wanted_builtin (j, tgt_j)
 507                 if (tgt_j->pfn_exec_fl)
 508                         tgt_j->pfn_exec_fl(file, line, us_elapsed_absolute,
 509                                            exec_id, exe, argv);
 510
 511         return exec_id;
 512 }
 513
 514 void trace2_exec_result_fl(const char *file, int line, int exec_id, int code)
 515 {
 516         struct tr2_tgt *tgt_j;
 517         int j;
 518         uint64_t us_now;
 519         uint64_t us_elapsed_absolute;
 520
 521         if (!trace2_enabled)
 522                 return;
 523
 524         us_now = getnanotime() / 1000;
 525         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 526
 527         for_each_wanted_builtin (j, tgt_j)
 528                 if (tgt_j->pfn_exec_result_fl)
 529                         tgt_j->pfn_exec_result_fl(
 530                                 file, line, us_elapsed_absolute, exec_id, code);
 531 }
 532
 533 void trace2_thread_start_fl(const char *file, int line, const char *thread_base_name)
 534 {
 535         struct tr2_tgt *tgt_j;
 536         int j;
 537         uint64_t us_now;
 538         uint64_t us_elapsed_absolute;
 539
 540         if (!trace2_enabled)
 541                 return;
 542
 543         if (tr2tls_is_main_thread()) {
 544                 /*
 545                  * We should only be called from the new thread's thread-proc,
 546                  * so this is technically a bug.  But in those cases where the
 547                  * main thread also runs the thread-proc function (or when we
 548                  * are built with threading disabled), we need to allow it.
 549                  *
 550                  * Convert this call to a region-enter so the nesting looks
 551                  * correct.
 552                  */
 553                 trace2_region_enter_printf_fl(file, line, NULL, NULL, NULL,
 554                                               "thread-proc on main: %s",
 555                                               thread_base_name);
 556                 return;
 557         }
 558
 559         us_now = getnanotime() / 1000;
 560         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 561
 562         tr2tls_create_self(thread_base_name, us_now);
 563
 564         for_each_wanted_builtin (j, tgt_j)
 565                 if (tgt_j->pfn_thread_start_fl)
 566                         tgt_j->pfn_thread_start_fl(file, line,
 567                                                    us_elapsed_absolute);
 568 }
 569
 570 void trace2_thread_exit_fl(const char *file, int line)
 571 {
 572         struct tr2_tgt *tgt_j;
 573         int j;
 574         uint64_t us_now;
 575         uint64_t us_elapsed_absolute;
 576         uint64_t us_elapsed_thread;
 577
 578         if (!trace2_enabled)
 579                 return;
 580
 581         if (tr2tls_is_main_thread()) {
 582                 /*
 583                  * We should only be called from the exiting thread's
 584                  * thread-proc, so this is technically a bug.  But in
 585                  * those cases where the main thread also runs the
 586                  * thread-proc function (or when we are built with
 587                  * threading disabled), we need to allow it.
 588                  *
 589                  * Convert this call to a region-leave so the nesting
 590                  * looks correct.
 591                  */
 592                 trace2_region_leave_printf_fl(file, line, NULL, NULL, NULL,
 593                                               "thread-proc on main");
 594                 return;
 595         }
 596
 597         us_now = getnanotime() / 1000;
 598         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 599
 600         /*
 601          * Clear any unbalanced regions and then get the relative time
 602          * for the outer-most region (which we pushed when the thread
 603          * started).  This gives us the run time of the thread.
 604          */
 605         tr2tls_pop_unwind_self();
 606         us_elapsed_thread = tr2tls_region_elasped_self(us_now);
 607
 608         /*
 609          * Some timers want per-thread details.  If this thread used
 610          * one of those timers, emit the details now.
 611          *
 612          * Likewise for counters.
 613          */
 614         tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer);
 615         tr2_emit_per_thread_counters(tr2_tgt_emit_a_counter);
 616
 617         /*
 618          * Add stopwatch timer and counter data from the current
 619          * (non-main) thread to the final totals.  (We'll accumulate
 620          * data for the main thread later during "atexit".)
 621          */
 622         tr2tls_lock();
 623         tr2_update_final_timers();
 624         tr2_update_final_counters();
 625         tr2tls_unlock();
 626
 627         for_each_wanted_builtin (j, tgt_j)
 628                 if (tgt_j->pfn_thread_exit_fl)
 629                         tgt_j->pfn_thread_exit_fl(file, line,
 630                                                   us_elapsed_absolute,
 631                                                   us_elapsed_thread);
 632
 633         tr2tls_unset_self();
 634 }
 635
 636 void trace2_def_param_fl(const char *file, int line, const char *param,
 637                          const char *value)
 638 {
 639         struct tr2_tgt *tgt_j;
 640         int j;
 641
 642         if (!trace2_enabled)
 643                 return;
 644
 645         for_each_wanted_builtin (j, tgt_j)
 646                 if (tgt_j->pfn_param_fl)
 647                         tgt_j->pfn_param_fl(file, line, param, value);
 648 }
 649
 650 void trace2_def_repo_fl(const char *file, int line, struct repository *repo)
 651 {
 652         struct tr2_tgt *tgt_j;
 653         int j;
 654
 655         if (!trace2_enabled)
 656                 return;
 657
 658         if (repo->trace2_repo_id)
 659                 return;
 660
 661         repo->trace2_repo_id = tr2tls_locked_increment(&tr2_next_repo_id);
 662
 663         for_each_wanted_builtin (j, tgt_j)
 664                 if (tgt_j->pfn_repo_fl)
 665                         tgt_j->pfn_repo_fl(file, line, repo);
 666 }
 667
 668 void trace2_region_enter_printf_va_fl(const char *file, int line,
 669                                       const char *category, const char *label,
 670                                       const struct repository *repo,
 671                                       const char *fmt, va_list ap)
 672 {
 673         struct tr2_tgt *tgt_j;
 674         int j;
 675         uint64_t us_now;
 676         uint64_t us_elapsed_absolute;
 677
 678         if (!trace2_enabled)
 679                 return;
 680
 681         us_now = getnanotime() / 1000;
 682         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 683
 684         /*
 685          * Print the region-enter message at the current nesting
 686          * (indentation) level and then push a new level.
 687          *
 688          * We expect each target function to treat 'ap' as constant
 689          * and use va_copy.
 690          */
 691         for_each_wanted_builtin (j, tgt_j)
 692                 if (tgt_j->pfn_region_enter_printf_va_fl)
 693                         tgt_j->pfn_region_enter_printf_va_fl(
 694                                 file, line, us_elapsed_absolute, category,
 695                                 label, repo, fmt, ap);
 696
 697         tr2tls_push_self(us_now);
 698 }
 699
 700 void trace2_region_enter_fl(const char *file, int line, const char *category,
 701                             const char *label, const struct repository *repo, ...)
 702 {
 703         va_list ap;
 704         va_start(ap, repo);
 705         trace2_region_enter_printf_va_fl(file, line, category, label, repo,
 706                                          NULL, ap);
 707         va_end(ap);
 708
 709 }
 710
 711 void trace2_region_enter_printf_fl(const char *file, int line,
 712                                    const char *category, const char *label,
 713                                    const struct repository *repo,
 714                                    const char *fmt, ...)
 715 {
 716         va_list ap;
 717
 718         va_start(ap, fmt);
 719         trace2_region_enter_printf_va_fl(file, line, category, label, repo, fmt,
 720                                          ap);
 721         va_end(ap);
 722 }
 723
 724 void trace2_region_leave_printf_va_fl(const char *file, int line,
 725                                       const char *category, const char *label,
 726                                       const struct repository *repo,
 727                                       const char *fmt, va_list ap)
 728 {
 729         struct tr2_tgt *tgt_j;
 730         int j;
 731         uint64_t us_now;
 732         uint64_t us_elapsed_absolute;
 733         uint64_t us_elapsed_region;
 734
 735         if (!trace2_enabled)
 736                 return;
 737
 738         us_now = getnanotime() / 1000;
 739         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 740
 741         /*
 742          * Get the elapsed time in the current region before we
 743          * pop it off the stack.  Pop the stack.  And then print
 744          * the perf message at the new (shallower) level so that
 745          * it lines up with the corresponding push/enter.
 746          */
 747         us_elapsed_region = tr2tls_region_elasped_self(us_now);
 748
 749         tr2tls_pop_self();
 750
 751         /*
 752          * We expect each target function to treat 'ap' as constant
 753          * and use va_copy.
 754          */
 755         for_each_wanted_builtin (j, tgt_j)
 756                 if (tgt_j->pfn_region_leave_printf_va_fl)
 757                         tgt_j->pfn_region_leave_printf_va_fl(
 758                                 file, line, us_elapsed_absolute,
 759                                 us_elapsed_region, category, label, repo, fmt,
 760                                 ap);
 761 }
 762
 763 void trace2_region_leave_fl(const char *file, int line, const char *category,
 764                             const char *label, const struct repository *repo, ...)
 765 {
 766         va_list ap;
 767         va_start(ap, repo);
 768         trace2_region_leave_printf_va_fl(file, line, category, label, repo,
 769                                          NULL, ap);
 770         va_end(ap);
 771 }
 772
 773 void trace2_region_leave_printf_fl(const char *file, int line,
 774                                    const char *category, const char *label,
 775                                    const struct repository *repo,
 776                                    const char *fmt, ...)
 777 {
 778         va_list ap;
 779
 780         va_start(ap, fmt);
 781         trace2_region_leave_printf_va_fl(file, line, category, label, repo, fmt,
 782                                          ap);
 783         va_end(ap);
 784 }
 785
 786 void trace2_data_string_fl(const char *file, int line, const char *category,
 787                            const struct repository *repo, const char *key,
 788                            const char *value)
 789 {
 790         struct tr2_tgt *tgt_j;
 791         int j;
 792         uint64_t us_now;
 793         uint64_t us_elapsed_absolute;
 794         uint64_t us_elapsed_region;
 795
 796         if (!trace2_enabled)
 797                 return;
 798
 799         us_now = getnanotime() / 1000;
 800         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 801         us_elapsed_region = tr2tls_region_elasped_self(us_now);
 802
 803         for_each_wanted_builtin (j, tgt_j)
 804                 if (tgt_j->pfn_data_fl)
 805                         tgt_j->pfn_data_fl(file, line, us_elapsed_absolute,
 806                                            us_elapsed_region, category, repo,
 807                                            key, value);
 808 }
 809
 810 void trace2_data_intmax_fl(const char *file, int line, const char *category,
 811                            const struct repository *repo, const char *key,
 812                            intmax_t value)
 813 {
 814         struct strbuf buf_string = STRBUF_INIT;
 815
 816         if (!trace2_enabled)
 817                 return;
 818
 819         strbuf_addf(&buf_string, "%" PRIdMAX, value);
 820         trace2_data_string_fl(file, line, category, repo, key, buf_string.buf);
 821         strbuf_release(&buf_string);
 822 }
 823
 824 void trace2_data_json_fl(const char *file, int line, const char *category,
 825                          const struct repository *repo, const char *key,
 826                          const struct json_writer *value)
 827 {
 828         struct tr2_tgt *tgt_j;
 829         int j;
 830         uint64_t us_now;
 831         uint64_t us_elapsed_absolute;
 832         uint64_t us_elapsed_region;
 833
 834         if (!trace2_enabled)
 835                 return;
 836
 837         us_now = getnanotime() / 1000;
 838         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 839         us_elapsed_region = tr2tls_region_elasped_self(us_now);
 840
 841         for_each_wanted_builtin (j, tgt_j)
 842                 if (tgt_j->pfn_data_json_fl)
 843                         tgt_j->pfn_data_json_fl(file, line, us_elapsed_absolute,
 844                                                 us_elapsed_region, category,
 845                                                 repo, key, value);
 846 }
 847
 848 void trace2_printf_va_fl(const char *file, int line, const char *fmt,
 849                          va_list ap)
 850 {
 851         struct tr2_tgt *tgt_j;
 852         int j;
 853         uint64_t us_now;
 854         uint64_t us_elapsed_absolute;
 855
 856         if (!trace2_enabled)
 857                 return;
 858
 859         us_now = getnanotime() / 1000;
 860         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 861
 862         /*
 863          * We expect each target function to treat 'ap' as constant
 864          * and use va_copy.
 865          */
 866         for_each_wanted_builtin (j, tgt_j)
 867                 if (tgt_j->pfn_printf_va_fl)
 868                         tgt_j->pfn_printf_va_fl(file, line, us_elapsed_absolute,
 869                                                 fmt, ap);
 870 }
 871
 872 void trace2_printf_fl(const char *file, int line, const char *fmt, ...)
 873 {
 874         va_list ap;
 875
 876         va_start(ap, fmt);
 877         trace2_printf_va_fl(file, line, fmt, ap);
 878         va_end(ap);
 879 }
 880
 881 void trace2_timer_start(enum trace2_timer_id tid)
 882 {
 883         if (!trace2_enabled)
 884                 return;
 885
 886         if (tid < 0 || tid >= TRACE2_NUMBER_OF_TIMERS)
 887                 BUG("trace2_timer_start: invalid timer id: %d", tid);
 888
 889         tr2_start_timer(tid);
 890 }
 891
 892 void trace2_timer_stop(enum trace2_timer_id tid)
 893 {
 894         if (!trace2_enabled)
 895                 return;
 896
 897         if (tid < 0 || tid >= TRACE2_NUMBER_OF_TIMERS)
 898                 BUG("trace2_timer_stop: invalid timer id: %d", tid);
 899
 900         tr2_stop_timer(tid);
 901 }
 902
 903 void trace2_counter_add(enum trace2_counter_id cid, uint64_t value)
 904 {
 905         if (!trace2_enabled)
 906                 return;
 907
 908         if (cid < 0 || cid >= TRACE2_NUMBER_OF_COUNTERS)
 909                 BUG("trace2_counter_add: invalid counter id: %d", cid);
 910
 911         tr2_counter_increment(cid, value);
 912 }
 913
 914 const char *trace2_session_id(void)
 915 {
 916         return tr2_sid_get();
 917 }