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