trace2.c

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