trace2.c

   1 #include "git-compat-util.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 "trace.h"
  10 #include "trace2.h"
  11 #include "trace2/tr2_cfg.h"
  12 #include "trace2/tr2_cmd_name.h"
  13 #include "trace2/tr2_ctr.h"
  14 #include "trace2/tr2_dst.h"
  15 #include "trace2/tr2_sid.h"
  16 #include "trace2/tr2_sysenv.h"
  17 #include "trace2/tr2_tgt.h"
  18 #include "trace2/tr2_tls.h"
  19 #include "trace2/tr2_tmr.h"
  20
  21 static int trace2_enabled;
  22
  23 static int tr2_next_child_id; /* modify under lock */
  24 static int tr2_next_exec_id; /* modify under lock */
  25 static int tr2_next_repo_id = 1; /* modify under lock. zero is reserved */
  26
  27 /*
  28  * A table of the builtin TRACE2 targets.  Each of these may be independently
  29  * enabled or disabled.  Each TRACE2 API method will try to write an event to
  30  * *each* of the enabled targets.
  31  */
  32 /* clang-format off */
  33 static struct tr2_tgt *tr2_tgt_builtins[] =
  34 {
  35         &tr2_tgt_normal,
  36         &tr2_tgt_perf,
  37         &tr2_tgt_event,
  38         NULL
  39 };
  40 /* clang-format on */
  41
  42 /* clang-format off */
  43 #define for_each_builtin(j, tgt_j)                      \
  44         for (j = 0, tgt_j = tr2_tgt_builtins[j];        \
  45              tgt_j;                                     \
  46              j++, tgt_j = tr2_tgt_builtins[j])
  47 /* clang-format on */
  48
  49 /* clang-format off */
  50 #define for_each_wanted_builtin(j, tgt_j)            \
  51         for_each_builtin(j, tgt_j)                   \
  52                 if (tr2_dst_trace_want(tgt_j->pdst))
  53 /* clang-format on */
  54
  55 /*
  56  * Force (rather than lazily) initialize any of the requested
  57  * builtin TRACE2 targets at startup (and before we've seen an
  58  * actual TRACE2 event call) so we can see if we need to setup
  59  * private data structures and thread-local storage.
  60  *
  61  * Return the number of builtin targets enabled.
  62  */
  63 static int tr2_tgt_want_builtins(void)
  64 {
  65         struct tr2_tgt *tgt_j;
  66         int j;
  67         int sum = 0;
  68
  69         for_each_builtin (j, tgt_j)
  70                 if (tgt_j->pfn_init())
  71                         sum++;
  72
  73         return sum;
  74 }
  75
  76 /*
  77  * Properly terminate each builtin target.  Give each target
  78  * a chance to write a summary event and/or flush if necessary
  79  * and then close the fd.
  80  */
  81 static void tr2_tgt_disable_builtins(void)
  82 {
  83         struct tr2_tgt *tgt_j;
  84         int j;
  85
  86         for_each_builtin (j, tgt_j)
  87                 tgt_j->pfn_term();
  88 }
  89
  90 /*
  91  * The signature of this function must match the pfn_timer
  92  * method in the targets.  (Think of this is an apply operation
  93  * across the set of active targets.)
  94  */
  95 static void tr2_tgt_emit_a_timer(const struct tr2_timer_metadata *meta,
  96                                  const struct tr2_timer *timer,
  97                                  int is_final_data)
  98 {
  99         struct tr2_tgt *tgt_j;
 100         int j;
 101
 102         for_each_wanted_builtin (j, tgt_j)
 103                 if (tgt_j->pfn_timer)
 104                         tgt_j->pfn_timer(meta, timer, is_final_data);
 105 }
 106
 107 /*
 108  * The signature of this function must match the pfn_counter
 109  * method in the targets.
 110  */
 111 static void tr2_tgt_emit_a_counter(const struct tr2_counter_metadata *meta,
 112                                    const struct tr2_counter *counter,
 113                                    int is_final_data)
 114 {
 115         struct tr2_tgt *tgt_j;
 116         int j;
 117
 118         for_each_wanted_builtin (j, tgt_j)
 119                 if (tgt_j->pfn_counter)
 120                         tgt_j->pfn_counter(meta, counter, is_final_data);
 121 }
 122
 123 static int tr2main_exit_code;
 124
 125 /*
 126  * Our atexit routine should run after everything has finished.
 127  *
 128  * Note that events generated here might not actually appear if
 129  * we are writing to fd 1 or 2 and our atexit routine runs after
 130  * the pager's atexit routine (since it closes them to shutdown
 131  * the pipes).
 132  */
 133 static void tr2main_atexit_handler(void)
 134 {
 135         struct tr2_tgt *tgt_j;
 136         int j;
 137         uint64_t us_now;
 138         uint64_t us_elapsed_absolute;
 139
 140         us_now = getnanotime() / 1000;
 141         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 142
 143         /*
 144          * Clear any unbalanced regions so that our atexit message
 145          * does not appear nested.  This improves the appearance of
 146          * the trace output if someone calls die(), for example.
 147          */
 148         tr2tls_pop_unwind_self();
 149
 150         /*
 151          * Some timers want per-thread details.  If the main thread
 152          * used one of those timers, emit the details now (before
 153          * we emit the aggregate timer values).
 154          *
 155          * Likewise for counters.
 156          */
 157         tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer);
 158         tr2_emit_per_thread_counters(tr2_tgt_emit_a_counter);
 159
 160         /*
 161          * Add stopwatch timer and counter data for the main thread to
 162          * the final totals.  And then emit the final values.
 163          *
 164          * Technically, we shouldn't need to hold the lock to update
 165          * and output the final_timer_block and final_counter_block
 166          * (since all other threads should be dead by now), but it
 167          * doesn't hurt anything.
 168          */
 169         tr2tls_lock();
 170         tr2_update_final_timers();
 171         tr2_update_final_counters();
 172         tr2_emit_final_timers(tr2_tgt_emit_a_timer);
 173         tr2_emit_final_counters(tr2_tgt_emit_a_counter);
 174         tr2tls_unlock();
 175
 176         for_each_wanted_builtin (j, tgt_j)
 177                 if (tgt_j->pfn_atexit)
 178                         tgt_j->pfn_atexit(us_elapsed_absolute,
 179                                           tr2main_exit_code);
 180
 181         tr2_tgt_disable_builtins();
 182
 183         tr2tls_release();
 184         tr2_sid_release();
 185         tr2_cmd_name_release();
 186         tr2_cfg_free_patterns();
 187         tr2_cfg_free_env_vars();
 188         tr2_sysenv_release();
 189
 190         trace2_enabled = 0;
 191 }
 192
 193 static void tr2main_signal_handler(int signo)
 194 {
 195         struct tr2_tgt *tgt_j;
 196         int j;
 197         uint64_t us_now;
 198         uint64_t us_elapsed_absolute;
 199
 200         us_now = getnanotime() / 1000;
 201         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 202
 203         for_each_wanted_builtin (j, tgt_j)
 204                 if (tgt_j->pfn_signal)
 205                         tgt_j->pfn_signal(us_elapsed_absolute, signo);
 206
 207         sigchain_pop(signo);
 208         raise(signo);
 209 }
 210
 211 void trace2_initialize_clock(void)
 212 {
 213         tr2tls_start_process_clock();
 214 }
 215
 216 void trace2_initialize_fl(const char *file, int line)
 217 {
 218         struct tr2_tgt *tgt_j;
 219         int j;
 220
 221         if (trace2_enabled)
 222                 return;
 223
 224         tr2_sysenv_load();
 225
 226         if (!tr2_tgt_want_builtins())
 227                 return;
 228         trace2_enabled = 1;
 229
 230         tr2_sid_get();
 231
 232         atexit(tr2main_atexit_handler);
 233         sigchain_push(SIGPIPE, tr2main_signal_handler);
 234         tr2tls_init();
 235
 236         /*
 237          * Emit 'version' message on each active builtin target.
 238          */
 239         for_each_wanted_builtin (j, tgt_j)
 240                 if (tgt_j->pfn_version_fl)
 241                         tgt_j->pfn_version_fl(file, line);
 242 }
 243
 244 int trace2_is_enabled(void)
 245 {
 246         return trace2_enabled;
 247 }
 248
 249 void trace2_cmd_start_fl(const char *file, int line, const char **argv)
 250 {
 251         struct tr2_tgt *tgt_j;
 252         int j;
 253         uint64_t us_now;
 254         uint64_t us_elapsed_absolute;
 255
 256         if (!trace2_enabled)
 257                 return;
 258
 259         us_now = getnanotime() / 1000;
 260         us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
 261
 262         for_each_wanted_builtin (j, tgt_j)
 263                 if (tgt_j->pfn_start_fl)
 264                         tgt_j->pfn_start_fl(file, line, us_elapsed_absolute,
 265                                             argv);
 266 }
 267
 268 void trace2_cmd_exit_fl(const char *file, int line, int code)
 269 {
 270         struct tr2_tgt *tgt_j;
 271         int j;
 272         uint64_t us_now;
 273         uint64_t us_elapsed_absolute;
 274
 275         if (!trace2_enabled)
 276                 return;
 277
 278         trace_git_fsync_stats();
 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)
 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);
 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 }