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