trace2.c

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