1 #include "git-compat-util.h"
3 #include "json-writer.h"
5 #include "run-command.h"
7 #include "thread-utils.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"
20 static int trace2_enabled
;
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 */
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.
31 /* clang-format off */
32 static struct tr2_tgt
*tr2_tgt_builtins
[] =
41 /* clang-format off */
42 #define for_each_builtin(j, tgt_j) \
43 for (j = 0, tgt_j = tr2_tgt_builtins[j]; \
45 j++, tgt_j = tr2_tgt_builtins[j])
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))
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.
60 * Return the number of builtin targets enabled.
62 static int tr2_tgt_want_builtins(void)
64 struct tr2_tgt
*tgt_j
;
68 for_each_builtin (j
, tgt_j
)
69 if (tgt_j
->pfn_init())
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.
80 static void tr2_tgt_disable_builtins(void)
82 struct tr2_tgt
*tgt_j
;
85 for_each_builtin (j
, tgt_j
)
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.)
94 static void tr2_tgt_emit_a_timer(const struct tr2_timer_metadata
*meta
,
95 const struct tr2_timer
*timer
,
98 struct tr2_tgt
*tgt_j
;
101 for_each_wanted_builtin (j
, tgt_j
)
102 if (tgt_j
->pfn_timer
)
103 tgt_j
->pfn_timer(meta
, timer
, is_final_data
);
107 * The signature of this function must match the pfn_counter
108 * method in the targets.
110 static void tr2_tgt_emit_a_counter(const struct tr2_counter_metadata
*meta
,
111 const struct tr2_counter
*counter
,
114 struct tr2_tgt
*tgt_j
;
117 for_each_wanted_builtin (j
, tgt_j
)
118 if (tgt_j
->pfn_counter
)
119 tgt_j
->pfn_counter(meta
, counter
, is_final_data
);
122 static int tr2main_exit_code
;
125 * Our atexit routine should run after everything has finished.
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
132 static void tr2main_atexit_handler(void)
134 struct tr2_tgt
*tgt_j
;
137 uint64_t us_elapsed_absolute
;
139 us_now
= getnanotime() / 1000;
140 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
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.
147 tr2tls_pop_unwind_self();
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).
154 * Likewise for counters.
156 tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer
);
157 tr2_emit_per_thread_counters(tr2_tgt_emit_a_counter
);
160 * Add stopwatch timer and counter data for the main thread to
161 * the final totals. And then emit the final values.
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.
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
);
175 for_each_wanted_builtin (j
, tgt_j
)
176 if (tgt_j
->pfn_atexit
)
177 tgt_j
->pfn_atexit(us_elapsed_absolute
,
180 tr2_tgt_disable_builtins();
184 tr2_cmd_name_release();
185 tr2_cfg_free_patterns();
186 tr2_cfg_free_env_vars();
187 tr2_sysenv_release();
192 static void tr2main_signal_handler(int signo
)
194 struct tr2_tgt
*tgt_j
;
197 uint64_t us_elapsed_absolute
;
199 us_now
= getnanotime() / 1000;
200 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
202 for_each_wanted_builtin (j
, tgt_j
)
203 if (tgt_j
->pfn_signal
)
204 tgt_j
->pfn_signal(us_elapsed_absolute
, signo
);
210 void trace2_initialize_clock(void)
212 tr2tls_start_process_clock();
215 void trace2_initialize_fl(const char *file
, int line
)
217 struct tr2_tgt
*tgt_j
;
225 if (!tr2_tgt_want_builtins())
231 atexit(tr2main_atexit_handler
);
232 sigchain_push(SIGPIPE
, tr2main_signal_handler
);
236 * Emit 'version' message on each active builtin target.
238 for_each_wanted_builtin (j
, tgt_j
)
239 if (tgt_j
->pfn_version_fl
)
240 tgt_j
->pfn_version_fl(file
, line
);
243 int trace2_is_enabled(void)
245 return trace2_enabled
;
248 void trace2_cmd_start_fl(const char *file
, int line
, const char **argv
)
250 struct tr2_tgt
*tgt_j
;
253 uint64_t us_elapsed_absolute
;
258 us_now
= getnanotime() / 1000;
259 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
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
,
267 void trace2_cmd_exit_fl(const char *file
, int line
, int code
)
269 struct tr2_tgt
*tgt_j
;
272 uint64_t us_elapsed_absolute
;
277 trace_git_fsync_stats();
278 trace2_collect_process_info(TRACE2_PROCESS_INFO_EXIT
);
280 tr2main_exit_code
= code
;
282 us_now
= getnanotime() / 1000;
283 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
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
,
291 void trace2_cmd_error_va_fl(const char *file
, int line
, const char *fmt
,
294 struct tr2_tgt
*tgt_j
;
301 * We expect each target function to treat 'ap' as constant
302 * and use va_copy (because an 'ap' can only be walked once).
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
);
309 void trace2_cmd_path_fl(const char *file
, int line
, const char *pathname
)
311 struct tr2_tgt
*tgt_j
;
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
);
322 void trace2_cmd_ancestry_fl(const char *file
, int line
, const char **parent_names
)
324 struct tr2_tgt
*tgt_j
;
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
);
335 void trace2_cmd_name_fl(const char *file
, int line
, const char *name
)
337 struct tr2_tgt
*tgt_j
;
338 const char *hierarchy
;
344 tr2_cmd_name_append_hierarchy(name
);
345 hierarchy
= tr2_cmd_name_get_hierarchy();
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
);
352 void trace2_cmd_mode_fl(const char *file
, int line
, const char *mode
)
354 struct tr2_tgt
*tgt_j
;
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
);
365 void trace2_cmd_alias_fl(const char *file
, int line
, const char *alias
,
368 struct tr2_tgt
*tgt_j
;
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
);
379 void trace2_cmd_list_config_fl(const char *file
, int line
)
384 tr2_cfg_list_config_fl(file
, line
);
387 void trace2_cmd_list_env_vars_fl(const char *file
, int line
)
392 tr2_list_env_vars_fl(file
, line
);
395 void trace2_cmd_set_config_fl(const char *file
, int line
, const char *key
,
401 tr2_cfg_set_fl(file
, line
, key
, value
);
404 void trace2_child_start_fl(const char *file
, int line
,
405 struct child_process
*cmd
)
407 struct tr2_tgt
*tgt_j
;
410 uint64_t us_elapsed_absolute
;
415 us_now
= getnanotime() / 1000;
416 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
418 cmd
->trace2_child_id
= tr2tls_locked_increment(&tr2_next_child_id
);
419 cmd
->trace2_child_us_start
= us_now
;
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
);
427 void trace2_child_exit_fl(const char *file
, int line
, struct child_process
*cmd
,
430 struct tr2_tgt
*tgt_j
;
433 uint64_t us_elapsed_absolute
;
434 uint64_t us_elapsed_child
;
439 us_now
= getnanotime() / 1000;
440 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
442 if (cmd
->trace2_child_us_start
)
443 us_elapsed_child
= us_now
- cmd
->trace2_child_us_start
;
445 us_elapsed_child
= 0;
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
,
451 cmd
->trace2_child_id
, cmd
->pid
,
456 void trace2_child_ready_fl(const char *file
, int line
,
457 struct child_process
*cmd
,
460 struct tr2_tgt
*tgt_j
;
463 uint64_t us_elapsed_absolute
;
464 uint64_t us_elapsed_child
;
469 us_now
= getnanotime() / 1000;
470 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
472 if (cmd
->trace2_child_us_start
)
473 us_elapsed_child
= us_now
- cmd
->trace2_child_us_start
;
475 us_elapsed_child
= 0;
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
,
481 cmd
->trace2_child_id
,
487 int trace2_exec_fl(const char *file
, int line
, const char *exe
,
490 struct tr2_tgt
*tgt_j
;
494 uint64_t us_elapsed_absolute
;
499 us_now
= getnanotime() / 1000;
500 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
502 exec_id
= tr2tls_locked_increment(&tr2_next_exec_id
);
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
,
512 void trace2_exec_result_fl(const char *file
, int line
, int exec_id
, int code
)
514 struct tr2_tgt
*tgt_j
;
517 uint64_t us_elapsed_absolute
;
522 us_now
= getnanotime() / 1000;
523 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
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
);
531 void trace2_thread_start_fl(const char *file
, int line
, const char *thread_base_name
)
533 struct tr2_tgt
*tgt_j
;
536 uint64_t us_elapsed_absolute
;
541 if (tr2tls_is_main_thread()) {
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.
548 * Convert this call to a region-enter so the nesting looks
551 trace2_region_enter_printf_fl(file
, line
, NULL
, NULL
, NULL
,
552 "thread-proc on main: %s",
557 us_now
= getnanotime() / 1000;
558 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
560 tr2tls_create_self(thread_base_name
, us_now
);
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
);
568 void trace2_thread_exit_fl(const char *file
, int line
)
570 struct tr2_tgt
*tgt_j
;
573 uint64_t us_elapsed_absolute
;
574 uint64_t us_elapsed_thread
;
579 if (tr2tls_is_main_thread()) {
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.
587 * Convert this call to a region-leave so the nesting
590 trace2_region_leave_printf_fl(file
, line
, NULL
, NULL
, NULL
,
591 "thread-proc on main");
595 us_now
= getnanotime() / 1000;
596 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
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.
603 tr2tls_pop_unwind_self();
604 us_elapsed_thread
= tr2tls_region_elasped_self(us_now
);
607 * Some timers want per-thread details. If this thread used
608 * one of those timers, emit the details now.
610 * Likewise for counters.
612 tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer
);
613 tr2_emit_per_thread_counters(tr2_tgt_emit_a_counter
);
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".)
621 tr2_update_final_timers();
622 tr2_update_final_counters();
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
,
634 void trace2_def_param_fl(const char *file
, int line
, const char *param
,
637 struct tr2_tgt
*tgt_j
;
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
);
648 void trace2_def_repo_fl(const char *file
, int line
, struct repository
*repo
)
650 struct tr2_tgt
*tgt_j
;
656 if (repo
->trace2_repo_id
)
659 repo
->trace2_repo_id
= tr2tls_locked_increment(&tr2_next_repo_id
);
661 for_each_wanted_builtin (j
, tgt_j
)
662 if (tgt_j
->pfn_repo_fl
)
663 tgt_j
->pfn_repo_fl(file
, line
, repo
);
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
)
671 struct tr2_tgt
*tgt_j
;
674 uint64_t us_elapsed_absolute
;
679 us_now
= getnanotime() / 1000;
680 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
683 * Print the region-enter message at the current nesting
684 * (indentation) level and then push a new level.
686 * We expect each target function to treat 'ap' as constant
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
);
695 tr2tls_push_self(us_now
);
698 void trace2_region_enter_fl(const char *file
, int line
, const char *category
,
699 const char *label
, const struct repository
*repo
, ...)
703 trace2_region_enter_printf_va_fl(file
, line
, category
, label
, repo
,
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
, ...)
717 trace2_region_enter_printf_va_fl(file
, line
, category
, label
, repo
, fmt
,
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
)
727 struct tr2_tgt
*tgt_j
;
730 uint64_t us_elapsed_absolute
;
731 uint64_t us_elapsed_region
;
736 us_now
= getnanotime() / 1000;
737 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
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.
745 us_elapsed_region
= tr2tls_region_elasped_self(us_now
);
750 * We expect each target function to treat 'ap' as constant
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
,
761 void trace2_region_leave_fl(const char *file
, int line
, const char *category
,
762 const char *label
, const struct repository
*repo
, ...)
766 trace2_region_leave_printf_va_fl(file
, line
, category
, label
, repo
,
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
, ...)
779 trace2_region_leave_printf_va_fl(file
, line
, category
, label
, repo
, fmt
,
784 void trace2_data_string_fl(const char *file
, int line
, const char *category
,
785 const struct repository
*repo
, const char *key
,
788 struct tr2_tgt
*tgt_j
;
791 uint64_t us_elapsed_absolute
;
792 uint64_t us_elapsed_region
;
797 us_now
= getnanotime() / 1000;
798 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
799 us_elapsed_region
= tr2tls_region_elasped_self(us_now
);
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
,
808 void trace2_data_intmax_fl(const char *file
, int line
, const char *category
,
809 const struct repository
*repo
, const char *key
,
812 struct strbuf buf_string
= STRBUF_INIT
;
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
);
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
)
826 struct tr2_tgt
*tgt_j
;
829 uint64_t us_elapsed_absolute
;
830 uint64_t us_elapsed_region
;
835 us_now
= getnanotime() / 1000;
836 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
837 us_elapsed_region
= tr2tls_region_elasped_self(us_now
);
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
,
846 void trace2_printf_va_fl(const char *file
, int line
, const char *fmt
,
849 struct tr2_tgt
*tgt_j
;
852 uint64_t us_elapsed_absolute
;
857 us_now
= getnanotime() / 1000;
858 us_elapsed_absolute
= tr2tls_absolute_elapsed(us_now
);
861 * We expect each target function to treat 'ap' as constant
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
,
870 void trace2_printf_fl(const char *file
, int line
, const char *fmt
, ...)
875 trace2_printf_va_fl(file
, line
, fmt
, ap
);
879 void trace2_timer_start(enum trace2_timer_id tid
)
884 if (tid
< 0 || tid
>= TRACE2_NUMBER_OF_TIMERS
)
885 BUG("trace2_timer_start: invalid timer id: %d", tid
);
887 tr2_start_timer(tid
);
890 void trace2_timer_stop(enum trace2_timer_id tid
)
895 if (tid
< 0 || tid
>= TRACE2_NUMBER_OF_TIMERS
)
896 BUG("trace2_timer_stop: invalid timer id: %d", tid
);
901 void trace2_counter_add(enum trace2_counter_id cid
, uint64_t value
)
906 if (cid
< 0 || cid
>= TRACE2_NUMBER_OF_COUNTERS
)
907 BUG("trace2_counter_add: invalid counter id: %d", cid
);
909 tr2_counter_increment(cid
, value
);
912 const char *trace2_session_id(void)
914 return tr2_sid_get();