1 #include "git-compat-util.h"
3 #include "json-writer.h"
5 #include "repository.h"
6 #include "run-command.h"
8 #include "thread-utils.h"
12 #include "trace2/tr2_cfg.h"
13 #include "trace2/tr2_cmd_name.h"
14 #include "trace2/tr2_ctr.h"
15 #include "trace2/tr2_dst.h"
16 #include "trace2/tr2_sid.h"
17 #include "trace2/tr2_sysenv.h"
18 #include "trace2/tr2_tgt.h"
19 #include "trace2/tr2_tls.h"
20 #include "trace2/tr2_tmr.h"
22 static int trace2_enabled
;
24 static int tr2_next_child_id
; /* modify under lock */
25 static int tr2_next_exec_id
; /* modify under lock */
26 static int tr2_next_repo_id
= 1; /* modify under lock. zero is reserved */
29 * A table of the builtin TRACE2 targets. Each of these may be independently
30 * enabled or disabled. Each TRACE2 API method will try to write an event to
31 * *each* of the enabled targets.
33 /* clang-format off */
34 static struct tr2_tgt
*tr2_tgt_builtins
[] =
43 /* clang-format off */
44 #define for_each_builtin(j, tgt_j) \
45 for (j = 0, tgt_j = tr2_tgt_builtins[j]; \
47 j++, tgt_j = tr2_tgt_builtins[j])
50 /* clang-format off */
51 #define for_each_wanted_builtin(j, tgt_j) \
52 for_each_builtin(j, tgt_j) \
53 if (tr2_dst_trace_want(tgt_j->pdst))
57 * Force (rather than lazily) initialize any of the requested
58 * builtin TRACE2 targets at startup (and before we've seen an
59 * actual TRACE2 event call) so we can see if we need to setup
60 * private data structures and thread-local storage.
62 * Return the number of builtin targets enabled.
64 static int tr2_tgt_want_builtins(void)
66 struct tr2_tgt
*tgt_j
;
70 for_each_builtin (j
, tgt_j
)
71 if (tgt_j
->pfn_init())
78 * Properly terminate each builtin target. Give each target
79 * a chance to write a summary event and/or flush if necessary
80 * and then close the fd.
82 static void tr2_tgt_disable_builtins(void)
84 struct tr2_tgt
*tgt_j
;
87 for_each_builtin (j
, tgt_j
)
92 * The signature of this function must match the pfn_timer
93 * method in the targets. (Think of this is an apply operation
94 * across the set of active targets.)
96 static void tr2_tgt_emit_a_timer(const struct tr2_timer_metadata
*meta
,
97 const struct tr2_timer
*timer
,
100 struct tr2_tgt
*tgt_j
;
103 for_each_wanted_builtin (j
, tgt_j
)
104 if (tgt_j
->pfn_timer
)
105 tgt_j
->pfn_timer(meta
, timer
, is_final_data
);
109 * The signature of this function must match the pfn_counter
110 * method in the targets.
112 static void tr2_tgt_emit_a_counter(const struct tr2_counter_metadata
*meta
,
113 const struct tr2_counter
*counter
,
116 struct tr2_tgt
*tgt_j
;
119 for_each_wanted_builtin (j
, tgt_j
)
120 if (tgt_j
->pfn_counter
)
121 tgt_j
->pfn_counter(meta
, counter
, is_final_data
);
124 static int tr2main_exit_code
;
127 * Our atexit routine should run after everything has finished.
129 * Note that events generated here might not actually appear if
130 * we are writing to fd 1 or 2 and our atexit routine runs after
131 * the pager's atexit routine (since it closes them to shutdown
134 static void tr2main_atexit_handler(void)
136 struct tr2_tgt
*tgt_j
;
139 uint64_t us_elapsed_absolute
;
141 us_now
= getnanotime() / 1000;
142 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
145 * Clear any unbalanced regions so that our atexit message
146 * does not appear nested. This improves the appearance of
147 * the trace output if someone calls die(), for example.
149 tr2tls_pop_unwind_self();
152 * Some timers want per-thread details. If the main thread
153 * used one of those timers, emit the details now (before
154 * we emit the aggregate timer values).
156 * Likewise for counters.
158 tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer
);
159 tr2_emit_per_thread_counters(tr2_tgt_emit_a_counter
);
162 * Add stopwatch timer and counter data for the main thread to
163 * the final totals. And then emit the final values.
165 * Technically, we shouldn't need to hold the lock to update
166 * and output the final_timer_block and final_counter_block
167 * (since all other threads should be dead by now), but it
168 * doesn't hurt anything.
171 tr2_update_final_timers();
172 tr2_update_final_counters();
173 tr2_emit_final_timers(tr2_tgt_emit_a_timer
);
174 tr2_emit_final_counters(tr2_tgt_emit_a_counter
);
177 for_each_wanted_builtin (j
, tgt_j
)
178 if (tgt_j
->pfn_atexit
)
179 tgt_j
->pfn_atexit(us_elapsed_absolute
,
182 tr2_tgt_disable_builtins();
186 tr2_cmd_name_release();
187 tr2_cfg_free_patterns();
188 tr2_cfg_free_env_vars();
189 tr2_sysenv_release();
194 static void tr2main_signal_handler(int signo
)
196 struct tr2_tgt
*tgt_j
;
199 uint64_t us_elapsed_absolute
;
201 us_now
= getnanotime() / 1000;
202 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
204 for_each_wanted_builtin (j
, tgt_j
)
205 if (tgt_j
->pfn_signal
)
206 tgt_j
->pfn_signal(us_elapsed_absolute
, signo
);
212 void trace2_initialize_clock(void)
214 tr2tls_start_process_clock();
217 void trace2_initialize_fl(const char *file
, int line
)
219 struct tr2_tgt
*tgt_j
;
227 if (!tr2_tgt_want_builtins())
233 atexit(tr2main_atexit_handler
);
234 sigchain_push(SIGPIPE
, tr2main_signal_handler
);
238 * Emit 'version' message on each active builtin target.
240 for_each_wanted_builtin (j
, tgt_j
)
241 if (tgt_j
->pfn_version_fl
)
242 tgt_j
->pfn_version_fl(file
, line
);
245 int trace2_is_enabled(void)
247 return trace2_enabled
;
250 void trace2_cmd_start_fl(const char *file
, int line
, const char **argv
)
252 struct tr2_tgt
*tgt_j
;
255 uint64_t us_elapsed_absolute
;
260 us_now
= getnanotime() / 1000;
261 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
263 for_each_wanted_builtin (j
, tgt_j
)
264 if (tgt_j
->pfn_start_fl
)
265 tgt_j
->pfn_start_fl(file
, line
, us_elapsed_absolute
,
269 void trace2_cmd_exit_fl(const char *file
, int line
, int code
)
271 struct tr2_tgt
*tgt_j
;
274 uint64_t us_elapsed_absolute
;
279 trace2_collect_process_info(TRACE2_PROCESS_INFO_EXIT
);
281 tr2main_exit_code
= code
;
283 us_now
= getnanotime() / 1000;
284 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
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
,
292 void trace2_cmd_error_va_fl(const char *file
, int line
, const char *fmt
,
295 struct tr2_tgt
*tgt_j
;
302 * We expect each target function to treat 'ap' as constant
303 * and use va_copy (because an 'ap' can only be walked once).
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
);
310 void trace2_cmd_path_fl(const char *file
, int line
, const char *pathname
)
312 struct tr2_tgt
*tgt_j
;
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
);
323 void trace2_cmd_ancestry_fl(const char *file
, int line
, const char **parent_names
)
325 struct tr2_tgt
*tgt_j
;
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
);
336 void trace2_cmd_name_fl(const char *file
, int line
, const char *name
)
338 struct tr2_tgt
*tgt_j
;
339 const char *hierarchy
;
345 tr2_cmd_name_append_hierarchy(name
);
346 hierarchy
= tr2_cmd_name_get_hierarchy();
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
);
353 void trace2_cmd_mode_fl(const char *file
, int line
, const char *mode
)
355 struct tr2_tgt
*tgt_j
;
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
);
366 void trace2_cmd_alias_fl(const char *file
, int line
, const char *alias
,
369 struct tr2_tgt
*tgt_j
;
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
);
380 void trace2_cmd_list_config_fl(const char *file
, int line
)
385 tr2_cfg_list_config_fl(file
, line
);
388 void trace2_cmd_list_env_vars_fl(const char *file
, int line
)
393 tr2_list_env_vars_fl(file
, line
);
396 void trace2_cmd_set_config_fl(const char *file
, int line
, const char *key
,
402 tr2_cfg_set_fl(file
, line
, key
, value
);
405 void trace2_child_start_fl(const char *file
, int line
,
406 struct child_process
*cmd
)
408 struct tr2_tgt
*tgt_j
;
411 uint64_t us_elapsed_absolute
;
416 us_now
= getnanotime() / 1000;
417 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
419 cmd
->trace2_child_id
= tr2tls_locked_increment(&tr2_next_child_id
);
420 cmd
->trace2_child_us_start
= us_now
;
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
);
428 void trace2_child_exit_fl(const char *file
, int line
, struct child_process
*cmd
,
431 struct tr2_tgt
*tgt_j
;
434 uint64_t us_elapsed_absolute
;
435 uint64_t us_elapsed_child
;
440 us_now
= getnanotime() / 1000;
441 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
443 if (cmd
->trace2_child_us_start
)
444 us_elapsed_child
= us_now
- cmd
->trace2_child_us_start
;
446 us_elapsed_child
= 0;
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
,
452 cmd
->trace2_child_id
, cmd
->pid
,
457 void trace2_child_ready_fl(const char *file
, int line
,
458 struct child_process
*cmd
,
461 struct tr2_tgt
*tgt_j
;
464 uint64_t us_elapsed_absolute
;
465 uint64_t us_elapsed_child
;
470 us_now
= getnanotime() / 1000;
471 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
473 if (cmd
->trace2_child_us_start
)
474 us_elapsed_child
= us_now
- cmd
->trace2_child_us_start
;
476 us_elapsed_child
= 0;
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
,
482 cmd
->trace2_child_id
,
488 int trace2_exec_fl(const char *file
, int line
, const char *exe
,
491 struct tr2_tgt
*tgt_j
;
495 uint64_t us_elapsed_absolute
;
500 us_now
= getnanotime() / 1000;
501 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
503 exec_id
= tr2tls_locked_increment(&tr2_next_exec_id
);
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
,
513 void trace2_exec_result_fl(const char *file
, int line
, int exec_id
, int code
)
515 struct tr2_tgt
*tgt_j
;
518 uint64_t us_elapsed_absolute
;
523 us_now
= getnanotime() / 1000;
524 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
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
);
532 void trace2_thread_start_fl(const char *file
, int line
, const char *thread_base_name
)
534 struct tr2_tgt
*tgt_j
;
537 uint64_t us_elapsed_absolute
;
542 if (tr2tls_is_main_thread()) {
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.
549 * Convert this call to a region-enter so the nesting looks
552 trace2_region_enter_printf_fl(file
, line
, NULL
, NULL
, NULL
,
553 "thread-proc on main: %s",
558 us_now
= getnanotime() / 1000;
559 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
561 tr2tls_create_self(thread_base_name
, us_now
);
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
);
569 void trace2_thread_exit_fl(const char *file
, int line
)
571 struct tr2_tgt
*tgt_j
;
574 uint64_t us_elapsed_absolute
;
575 uint64_t us_elapsed_thread
;
580 if (tr2tls_is_main_thread()) {
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.
588 * Convert this call to a region-leave so the nesting
591 trace2_region_leave_printf_fl(file
, line
, NULL
, NULL
, NULL
,
592 "thread-proc on main");
596 us_now
= getnanotime() / 1000;
597 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
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.
604 tr2tls_pop_unwind_self();
605 us_elapsed_thread
= tr2tls_region_elasped_self(us_now
);
608 * Some timers want per-thread details. If this thread used
609 * one of those timers, emit the details now.
611 * Likewise for counters.
613 tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer
);
614 tr2_emit_per_thread_counters(tr2_tgt_emit_a_counter
);
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".)
622 tr2_update_final_timers();
623 tr2_update_final_counters();
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
,
635 void trace2_def_param_fl(const char *file
, int line
, const char *param
,
636 const char *value
, const struct key_value_info
*kvi
)
638 struct tr2_tgt
*tgt_j
;
644 for_each_wanted_builtin (j
, tgt_j
)
645 if (tgt_j
->pfn_param_fl
)
646 tgt_j
->pfn_param_fl(file
, line
, param
, value
, kvi
);
649 void trace2_def_repo_fl(const char *file
, int line
, struct repository
*repo
)
651 struct tr2_tgt
*tgt_j
;
657 if (repo
->trace2_repo_id
)
660 repo
->trace2_repo_id
= tr2tls_locked_increment(&tr2_next_repo_id
);
662 for_each_wanted_builtin (j
, tgt_j
)
663 if (tgt_j
->pfn_repo_fl
)
664 tgt_j
->pfn_repo_fl(file
, line
, repo
);
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
)
672 struct tr2_tgt
*tgt_j
;
675 uint64_t us_elapsed_absolute
;
680 us_now
= getnanotime() / 1000;
681 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
684 * Print the region-enter message at the current nesting
685 * (indentation) level and then push a new level.
687 * We expect each target function to treat 'ap' as constant
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
);
696 tr2tls_push_self(us_now
);
699 void trace2_region_enter_fl(const char *file
, int line
, const char *category
,
700 const char *label
, const struct repository
*repo
, ...)
704 trace2_region_enter_printf_va_fl(file
, line
, category
, label
, repo
,
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
, ...)
718 trace2_region_enter_printf_va_fl(file
, line
, category
, label
, repo
, fmt
,
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
)
728 struct tr2_tgt
*tgt_j
;
731 uint64_t us_elapsed_absolute
;
732 uint64_t us_elapsed_region
;
737 us_now
= getnanotime() / 1000;
738 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
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.
746 us_elapsed_region
= tr2tls_region_elasped_self(us_now
);
751 * We expect each target function to treat 'ap' as constant
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
,
762 void trace2_region_leave_fl(const char *file
, int line
, const char *category
,
763 const char *label
, const struct repository
*repo
, ...)
767 trace2_region_leave_printf_va_fl(file
, line
, category
, label
, repo
,
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
, ...)
780 trace2_region_leave_printf_va_fl(file
, line
, category
, label
, repo
, fmt
,
785 void trace2_data_string_fl(const char *file
, int line
, const char *category
,
786 const struct repository
*repo
, const char *key
,
789 struct tr2_tgt
*tgt_j
;
792 uint64_t us_elapsed_absolute
;
793 uint64_t us_elapsed_region
;
798 us_now
= getnanotime() / 1000;
799 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
800 us_elapsed_region
= tr2tls_region_elasped_self(us_now
);
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
,
809 void trace2_data_intmax_fl(const char *file
, int line
, const char *category
,
810 const struct repository
*repo
, const char *key
,
813 struct strbuf buf_string
= STRBUF_INIT
;
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
);
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
)
827 struct tr2_tgt
*tgt_j
;
830 uint64_t us_elapsed_absolute
;
831 uint64_t us_elapsed_region
;
836 us_now
= getnanotime() / 1000;
837 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
838 us_elapsed_region
= tr2tls_region_elasped_self(us_now
);
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
,
847 void trace2_printf_va_fl(const char *file
, int line
, const char *fmt
,
850 struct tr2_tgt
*tgt_j
;
853 uint64_t us_elapsed_absolute
;
858 us_now
= getnanotime() / 1000;
859 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
862 * We expect each target function to treat 'ap' as constant
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
,
871 void trace2_printf_fl(const char *file
, int line
, const char *fmt
, ...)
876 trace2_printf_va_fl(file
, line
, fmt
, ap
);
880 void trace2_timer_start(enum trace2_timer_id tid
)
885 if (tid
< 0 || tid
>= TRACE2_NUMBER_OF_TIMERS
)
886 BUG("trace2_timer_start: invalid timer id: %d", tid
);
888 tr2_start_timer(tid
);
891 void trace2_timer_stop(enum trace2_timer_id tid
)
896 if (tid
< 0 || tid
>= TRACE2_NUMBER_OF_TIMERS
)
897 BUG("trace2_timer_stop: invalid timer id: %d", tid
);
902 void trace2_counter_add(enum trace2_counter_id cid
, uint64_t value
)
907 if (cid
< 0 || cid
>= TRACE2_NUMBER_OF_COUNTERS
)
908 BUG("trace2_counter_add: invalid counter id: %d", cid
);
910 tr2_counter_increment(cid
, value
);
913 const char *trace2_session_id(void)
915 return tr2_sid_get();