diff options
author | Daniel Baumann <daniel.baumann@progress-linux.org> | 2024-04-07 14:47:53 +0000 |
---|---|---|
committer | Daniel Baumann <daniel.baumann@progress-linux.org> | 2024-04-07 14:47:53 +0000 |
commit | c8bae7493d2f2910b57f13ded012e86bdcfb0532 (patch) | |
tree | 24e09d9f84dec336720cf393e156089ca2835791 /trace2 | |
parent | Initial commit. (diff) | |
download | git-upstream.tar.xz git-upstream.zip |
Adding upstream version 1:2.39.2.upstream/1%2.39.2upstream
Signed-off-by: Daniel Baumann <daniel.baumann@progress-linux.org>
Diffstat (limited to '')
-rw-r--r-- | trace2.c | 914 | ||||
-rw-r--r-- | trace2.h | 584 | ||||
-rw-r--r-- | trace2/tr2_cfg.c | 147 | ||||
-rw-r--r-- | trace2/tr2_cfg.h | 27 | ||||
-rw-r--r-- | trace2/tr2_cmd_name.c | 30 | ||||
-rw-r--r-- | trace2/tr2_cmd_name.h | 24 | ||||
-rw-r--r-- | trace2/tr2_ctr.c | 101 | ||||
-rw-r--r-- | trace2/tr2_ctr.h | 104 | ||||
-rw-r--r-- | trace2/tr2_dst.c | 394 | ||||
-rw-r--r-- | trace2/tr2_dst.h | 38 | ||||
-rw-r--r-- | trace2/tr2_sid.c | 112 | ||||
-rw-r--r-- | trace2/tr2_sid.h | 18 | ||||
-rw-r--r-- | trace2/tr2_sysenv.c | 132 | ||||
-rw-r--r-- | trace2/tr2_sysenv.h | 39 | ||||
-rw-r--r-- | trace2/tr2_tbuf.c | 47 | ||||
-rw-r--r-- | trace2/tr2_tbuf.h | 24 | ||||
-rw-r--r-- | trace2/tr2_tgt.h | 158 | ||||
-rw-r--r-- | trace2/tr2_tgt_event.c | 696 | ||||
-rw-r--r-- | trace2/tr2_tgt_normal.c | 402 | ||||
-rw-r--r-- | trace2/tr2_tgt_perf.c | 630 | ||||
-rw-r--r-- | trace2/tr2_tls.c | 193 | ||||
-rw-r--r-- | trace2/tr2_tls.h | 124 | ||||
-rw-r--r-- | trace2/tr2_tmr.c | 182 | ||||
-rw-r--r-- | trace2/tr2_tmr.h | 140 |
24 files changed, 5260 insertions, 0 deletions
diff --git a/trace2.c b/trace2.c new file mode 100644 index 0000000..279bddf --- /dev/null +++ b/trace2.c @@ -0,0 +1,914 @@ +#include "cache.h" +#include "config.h" +#include "json-writer.h" +#include "quote.h" +#include "run-command.h" +#include "sigchain.h" +#include "thread-utils.h" +#include "version.h" +#include "trace2/tr2_cfg.h" +#include "trace2/tr2_cmd_name.h" +#include "trace2/tr2_ctr.h" +#include "trace2/tr2_dst.h" +#include "trace2/tr2_sid.h" +#include "trace2/tr2_sysenv.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" +#include "trace2/tr2_tmr.h" + +static int trace2_enabled; + +static int tr2_next_child_id; /* modify under lock */ +static int tr2_next_exec_id; /* modify under lock */ +static int tr2_next_repo_id = 1; /* modify under lock. zero is reserved */ + +/* + * A table of the builtin TRACE2 targets. Each of these may be independently + * enabled or disabled. Each TRACE2 API method will try to write an event to + * *each* of the enabled targets. + */ +/* clang-format off */ +static struct tr2_tgt *tr2_tgt_builtins[] = +{ + &tr2_tgt_normal, + &tr2_tgt_perf, + &tr2_tgt_event, + NULL +}; +/* clang-format on */ + +/* clang-format off */ +#define for_each_builtin(j, tgt_j) \ + for (j = 0, tgt_j = tr2_tgt_builtins[j]; \ + tgt_j; \ + j++, tgt_j = tr2_tgt_builtins[j]) +/* clang-format on */ + +/* clang-format off */ +#define for_each_wanted_builtin(j, tgt_j) \ + for_each_builtin(j, tgt_j) \ + if (tr2_dst_trace_want(tgt_j->pdst)) +/* clang-format on */ + +/* + * Force (rather than lazily) initialize any of the requested + * builtin TRACE2 targets at startup (and before we've seen an + * actual TRACE2 event call) so we can see if we need to setup + * private data structures and thread-local storage. + * + * Return the number of builtin targets enabled. + */ +static int tr2_tgt_want_builtins(void) +{ + struct tr2_tgt *tgt_j; + int j; + int sum = 0; + + for_each_builtin (j, tgt_j) + if (tgt_j->pfn_init()) + sum++; + + return sum; +} + +/* + * Properly terminate each builtin target. Give each target + * a chance to write a summary event and/or flush if necessary + * and then close the fd. + */ +static void tr2_tgt_disable_builtins(void) +{ + struct tr2_tgt *tgt_j; + int j; + + for_each_builtin (j, tgt_j) + tgt_j->pfn_term(); +} + +/* + * The signature of this function must match the pfn_timer + * method in the targets. (Think of this is an apply operation + * across the set of active targets.) + */ +static void tr2_tgt_emit_a_timer(const struct tr2_timer_metadata *meta, + const struct tr2_timer *timer, + int is_final_data) +{ + struct tr2_tgt *tgt_j; + int j; + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_timer) + tgt_j->pfn_timer(meta, timer, is_final_data); +} + +/* + * The signature of this function must match the pfn_counter + * method in the targets. + */ +static void tr2_tgt_emit_a_counter(const struct tr2_counter_metadata *meta, + const struct tr2_counter *counter, + int is_final_data) +{ + struct tr2_tgt *tgt_j; + int j; + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_counter) + tgt_j->pfn_counter(meta, counter, is_final_data); +} + +static int tr2main_exit_code; + +/* + * Our atexit routine should run after everything has finished. + * + * Note that events generated here might not actually appear if + * we are writing to fd 1 or 2 and our atexit routine runs after + * the pager's atexit routine (since it closes them to shutdown + * the pipes). + */ +static void tr2main_atexit_handler(void) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + /* + * Clear any unbalanced regions so that our atexit message + * does not appear nested. This improves the appearance of + * the trace output if someone calls die(), for example. + */ + tr2tls_pop_unwind_self(); + + /* + * Some timers want per-thread details. If the main thread + * used one of those timers, emit the details now (before + * we emit the aggregate timer values). + * + * Likewise for counters. + */ + tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer); + tr2_emit_per_thread_counters(tr2_tgt_emit_a_counter); + + /* + * Add stopwatch timer and counter data for the main thread to + * the final totals. And then emit the final values. + * + * Technically, we shouldn't need to hold the lock to update + * and output the final_timer_block and final_counter_block + * (since all other threads should be dead by now), but it + * doesn't hurt anything. + */ + tr2tls_lock(); + tr2_update_final_timers(); + tr2_update_final_counters(); + tr2_emit_final_timers(tr2_tgt_emit_a_timer); + tr2_emit_final_counters(tr2_tgt_emit_a_counter); + tr2tls_unlock(); + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_atexit) + tgt_j->pfn_atexit(us_elapsed_absolute, + tr2main_exit_code); + + tr2_tgt_disable_builtins(); + + tr2tls_release(); + tr2_sid_release(); + tr2_cmd_name_release(); + tr2_cfg_free_patterns(); + tr2_cfg_free_env_vars(); + tr2_sysenv_release(); + + trace2_enabled = 0; +} + +static void tr2main_signal_handler(int signo) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_signal) + tgt_j->pfn_signal(us_elapsed_absolute, signo); + + sigchain_pop(signo); + raise(signo); +} + +void trace2_initialize_clock(void) +{ + tr2tls_start_process_clock(); +} + +void trace2_initialize_fl(const char *file, int line) +{ + struct tr2_tgt *tgt_j; + int j; + + if (trace2_enabled) + return; + + tr2_sysenv_load(); + + if (!tr2_tgt_want_builtins()) + return; + trace2_enabled = 1; + + tr2_sid_get(); + + atexit(tr2main_atexit_handler); + sigchain_push(SIGPIPE, tr2main_signal_handler); + tr2tls_init(); + + /* + * Emit 'version' message on each active builtin target. + */ + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_version_fl) + tgt_j->pfn_version_fl(file, line); +} + +int trace2_is_enabled(void) +{ + return trace2_enabled; +} + +void trace2_cmd_start_fl(const char *file, int line, const char **argv) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + + if (!trace2_enabled) + return; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_start_fl) + tgt_j->pfn_start_fl(file, line, us_elapsed_absolute, + argv); +} + +void trace2_cmd_exit_fl(const char *file, int line, int code) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + + if (!trace2_enabled) + return; + + trace_git_fsync_stats(); + trace2_collect_process_info(TRACE2_PROCESS_INFO_EXIT); + + tr2main_exit_code = code; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_exit_fl) + tgt_j->pfn_exit_fl(file, line, us_elapsed_absolute, + code); +} + +void trace2_cmd_error_va_fl(const char *file, int line, const char *fmt, + va_list ap) +{ + struct tr2_tgt *tgt_j; + int j; + + if (!trace2_enabled) + return; + + /* + * We expect each target function to treat 'ap' as constant + * and use va_copy (because an 'ap' can only be walked once). + */ + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_error_va_fl) + tgt_j->pfn_error_va_fl(file, line, fmt, ap); +} + +void trace2_cmd_path_fl(const char *file, int line, const char *pathname) +{ + struct tr2_tgt *tgt_j; + int j; + + if (!trace2_enabled) + return; + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_command_path_fl) + tgt_j->pfn_command_path_fl(file, line, pathname); +} + +void trace2_cmd_ancestry_fl(const char *file, int line, const char **parent_names) +{ + struct tr2_tgt *tgt_j; + int j; + + if (!trace2_enabled) + return; + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_command_ancestry_fl) + tgt_j->pfn_command_ancestry_fl(file, line, parent_names); +} + +void trace2_cmd_name_fl(const char *file, int line, const char *name) +{ + struct tr2_tgt *tgt_j; + const char *hierarchy; + int j; + + if (!trace2_enabled) + return; + + tr2_cmd_name_append_hierarchy(name); + hierarchy = tr2_cmd_name_get_hierarchy(); + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_command_name_fl) + tgt_j->pfn_command_name_fl(file, line, name, hierarchy); +} + +void trace2_cmd_mode_fl(const char *file, int line, const char *mode) +{ + struct tr2_tgt *tgt_j; + int j; + + if (!trace2_enabled) + return; + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_command_mode_fl) + tgt_j->pfn_command_mode_fl(file, line, mode); +} + +void trace2_cmd_alias_fl(const char *file, int line, const char *alias, + const char **argv) +{ + struct tr2_tgt *tgt_j; + int j; + + if (!trace2_enabled) + return; + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_alias_fl) + tgt_j->pfn_alias_fl(file, line, alias, argv); +} + +void trace2_cmd_list_config_fl(const char *file, int line) +{ + if (!trace2_enabled) + return; + + tr2_cfg_list_config_fl(file, line); +} + +void trace2_cmd_list_env_vars_fl(const char *file, int line) +{ + if (!trace2_enabled) + return; + + tr2_list_env_vars_fl(file, line); +} + +void trace2_cmd_set_config_fl(const char *file, int line, const char *key, + const char *value) +{ + if (!trace2_enabled) + return; + + tr2_cfg_set_fl(file, line, key, value); +} + +void trace2_child_start_fl(const char *file, int line, + struct child_process *cmd) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + + if (!trace2_enabled) + return; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + cmd->trace2_child_id = tr2tls_locked_increment(&tr2_next_child_id); + cmd->trace2_child_us_start = us_now; + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_child_start_fl) + tgt_j->pfn_child_start_fl(file, line, + us_elapsed_absolute, cmd); +} + +void trace2_child_exit_fl(const char *file, int line, struct child_process *cmd, + int child_exit_code) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + uint64_t us_elapsed_child; + + if (!trace2_enabled) + return; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + if (cmd->trace2_child_us_start) + us_elapsed_child = us_now - cmd->trace2_child_us_start; + else + us_elapsed_child = 0; + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_child_exit_fl) + tgt_j->pfn_child_exit_fl(file, line, + us_elapsed_absolute, + cmd->trace2_child_id, cmd->pid, + child_exit_code, + us_elapsed_child); +} + +void trace2_child_ready_fl(const char *file, int line, + struct child_process *cmd, + const char *ready) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + uint64_t us_elapsed_child; + + if (!trace2_enabled) + return; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + if (cmd->trace2_child_us_start) + us_elapsed_child = us_now - cmd->trace2_child_us_start; + else + us_elapsed_child = 0; + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_child_ready_fl) + tgt_j->pfn_child_ready_fl(file, line, + us_elapsed_absolute, + cmd->trace2_child_id, + cmd->pid, + ready, + us_elapsed_child); +} + +int trace2_exec_fl(const char *file, int line, const char *exe, + const char **argv) +{ + struct tr2_tgt *tgt_j; + int j; + int exec_id; + uint64_t us_now; + uint64_t us_elapsed_absolute; + + if (!trace2_enabled) + return -1; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + exec_id = tr2tls_locked_increment(&tr2_next_exec_id); + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_exec_fl) + tgt_j->pfn_exec_fl(file, line, us_elapsed_absolute, + exec_id, exe, argv); + + return exec_id; +} + +void trace2_exec_result_fl(const char *file, int line, int exec_id, int code) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + + if (!trace2_enabled) + return; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_exec_result_fl) + tgt_j->pfn_exec_result_fl( + file, line, us_elapsed_absolute, exec_id, code); +} + +void trace2_thread_start_fl(const char *file, int line, const char *thread_base_name) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + + if (!trace2_enabled) + return; + + if (tr2tls_is_main_thread()) { + /* + * We should only be called from the new thread's thread-proc, + * so this is technically a bug. But in those cases where the + * main thread also runs the thread-proc function (or when we + * are built with threading disabled), we need to allow it. + * + * Convert this call to a region-enter so the nesting looks + * correct. + */ + trace2_region_enter_printf_fl(file, line, NULL, NULL, NULL, + "thread-proc on main: %s", + thread_base_name); + return; + } + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + tr2tls_create_self(thread_base_name, us_now); + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_thread_start_fl) + tgt_j->pfn_thread_start_fl(file, line, + us_elapsed_absolute); +} + +void trace2_thread_exit_fl(const char *file, int line) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + uint64_t us_elapsed_thread; + + if (!trace2_enabled) + return; + + if (tr2tls_is_main_thread()) { + /* + * We should only be called from the exiting thread's + * thread-proc, so this is technically a bug. But in + * those cases where the main thread also runs the + * thread-proc function (or when we are built with + * threading disabled), we need to allow it. + * + * Convert this call to a region-leave so the nesting + * looks correct. + */ + trace2_region_leave_printf_fl(file, line, NULL, NULL, NULL, + "thread-proc on main"); + return; + } + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + /* + * Clear any unbalanced regions and then get the relative time + * for the outer-most region (which we pushed when the thread + * started). This gives us the run time of the thread. + */ + tr2tls_pop_unwind_self(); + us_elapsed_thread = tr2tls_region_elasped_self(us_now); + + /* + * Some timers want per-thread details. If this thread used + * one of those timers, emit the details now. + * + * Likewise for counters. + */ + tr2_emit_per_thread_timers(tr2_tgt_emit_a_timer); + tr2_emit_per_thread_counters(tr2_tgt_emit_a_counter); + + /* + * Add stopwatch timer and counter data from the current + * (non-main) thread to the final totals. (We'll accumulate + * data for the main thread later during "atexit".) + */ + tr2tls_lock(); + tr2_update_final_timers(); + tr2_update_final_counters(); + tr2tls_unlock(); + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_thread_exit_fl) + tgt_j->pfn_thread_exit_fl(file, line, + us_elapsed_absolute, + us_elapsed_thread); + + tr2tls_unset_self(); +} + +void trace2_def_param_fl(const char *file, int line, const char *param, + const char *value) +{ + struct tr2_tgt *tgt_j; + int j; + + if (!trace2_enabled) + return; + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_param_fl) + tgt_j->pfn_param_fl(file, line, param, value); +} + +void trace2_def_repo_fl(const char *file, int line, struct repository *repo) +{ + struct tr2_tgt *tgt_j; + int j; + + if (!trace2_enabled) + return; + + if (repo->trace2_repo_id) + return; + + repo->trace2_repo_id = tr2tls_locked_increment(&tr2_next_repo_id); + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_repo_fl) + tgt_j->pfn_repo_fl(file, line, repo); +} + +void trace2_region_enter_printf_va_fl(const char *file, int line, + const char *category, const char *label, + const struct repository *repo, + const char *fmt, va_list ap) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + + if (!trace2_enabled) + return; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + /* + * Print the region-enter message at the current nesting + * (indentation) level and then push a new level. + * + * We expect each target function to treat 'ap' as constant + * and use va_copy. + */ + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_region_enter_printf_va_fl) + tgt_j->pfn_region_enter_printf_va_fl( + file, line, us_elapsed_absolute, category, + label, repo, fmt, ap); + + tr2tls_push_self(us_now); +} + +void trace2_region_enter_fl(const char *file, int line, const char *category, + const char *label, const struct repository *repo, ...) +{ + va_list ap; + va_start(ap, repo); + trace2_region_enter_printf_va_fl(file, line, category, label, repo, + NULL, ap); + va_end(ap); + +} + +void trace2_region_enter_printf_fl(const char *file, int line, + const char *category, const char *label, + const struct repository *repo, + const char *fmt, ...) +{ + va_list ap; + + va_start(ap, fmt); + trace2_region_enter_printf_va_fl(file, line, category, label, repo, fmt, + ap); + va_end(ap); +} + +void trace2_region_leave_printf_va_fl(const char *file, int line, + const char *category, const char *label, + const struct repository *repo, + const char *fmt, va_list ap) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + uint64_t us_elapsed_region; + + if (!trace2_enabled) + return; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + /* + * Get the elapsed time in the current region before we + * pop it off the stack. Pop the stack. And then print + * the perf message at the new (shallower) level so that + * it lines up with the corresponding push/enter. + */ + us_elapsed_region = tr2tls_region_elasped_self(us_now); + + tr2tls_pop_self(); + + /* + * We expect each target function to treat 'ap' as constant + * and use va_copy. + */ + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_region_leave_printf_va_fl) + tgt_j->pfn_region_leave_printf_va_fl( + file, line, us_elapsed_absolute, + us_elapsed_region, category, label, repo, fmt, + ap); +} + +void trace2_region_leave_fl(const char *file, int line, const char *category, + const char *label, const struct repository *repo, ...) +{ + va_list ap; + va_start(ap, repo); + trace2_region_leave_printf_va_fl(file, line, category, label, repo, + NULL, ap); + va_end(ap); +} + +void trace2_region_leave_printf_fl(const char *file, int line, + const char *category, const char *label, + const struct repository *repo, + const char *fmt, ...) +{ + va_list ap; + + va_start(ap, fmt); + trace2_region_leave_printf_va_fl(file, line, category, label, repo, fmt, + ap); + va_end(ap); +} + +void trace2_data_string_fl(const char *file, int line, const char *category, + const struct repository *repo, const char *key, + const char *value) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + uint64_t us_elapsed_region; + + if (!trace2_enabled) + return; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + us_elapsed_region = tr2tls_region_elasped_self(us_now); + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_data_fl) + tgt_j->pfn_data_fl(file, line, us_elapsed_absolute, + us_elapsed_region, category, repo, + key, value); +} + +void trace2_data_intmax_fl(const char *file, int line, const char *category, + const struct repository *repo, const char *key, + intmax_t value) +{ + struct strbuf buf_string = STRBUF_INIT; + + if (!trace2_enabled) + return; + + strbuf_addf(&buf_string, "%" PRIdMAX, value); + trace2_data_string_fl(file, line, category, repo, key, buf_string.buf); + strbuf_release(&buf_string); +} + +void trace2_data_json_fl(const char *file, int line, const char *category, + const struct repository *repo, const char *key, + const struct json_writer *value) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + uint64_t us_elapsed_region; + + if (!trace2_enabled) + return; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + us_elapsed_region = tr2tls_region_elasped_self(us_now); + + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_data_json_fl) + tgt_j->pfn_data_json_fl(file, line, us_elapsed_absolute, + us_elapsed_region, category, + repo, key, value); +} + +void trace2_printf_va_fl(const char *file, int line, const char *fmt, + va_list ap) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + + if (!trace2_enabled) + return; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + /* + * We expect each target function to treat 'ap' as constant + * and use va_copy. + */ + for_each_wanted_builtin (j, tgt_j) + if (tgt_j->pfn_printf_va_fl) + tgt_j->pfn_printf_va_fl(file, line, us_elapsed_absolute, + fmt, ap); +} + +void trace2_printf_fl(const char *file, int line, const char *fmt, ...) +{ + va_list ap; + + va_start(ap, fmt); + trace2_printf_va_fl(file, line, fmt, ap); + va_end(ap); +} + +void trace2_timer_start(enum trace2_timer_id tid) +{ + if (!trace2_enabled) + return; + + if (tid < 0 || tid >= TRACE2_NUMBER_OF_TIMERS) + BUG("trace2_timer_start: invalid timer id: %d", tid); + + tr2_start_timer(tid); +} + +void trace2_timer_stop(enum trace2_timer_id tid) +{ + if (!trace2_enabled) + return; + + if (tid < 0 || tid >= TRACE2_NUMBER_OF_TIMERS) + BUG("trace2_timer_stop: invalid timer id: %d", tid); + + tr2_stop_timer(tid); +} + +void trace2_counter_add(enum trace2_counter_id cid, uint64_t value) +{ + if (!trace2_enabled) + return; + + if (cid < 0 || cid >= TRACE2_NUMBER_OF_COUNTERS) + BUG("trace2_counter_add: invalid counter id: %d", cid); + + tr2_counter_increment(cid, value); +} + +const char *trace2_session_id(void) +{ + return tr2_sid_get(); +} diff --git a/trace2.h b/trace2.h new file mode 100644 index 0000000..4ced30c --- /dev/null +++ b/trace2.h @@ -0,0 +1,584 @@ +#ifndef TRACE2_H +#define TRACE2_H + +/** + * The Trace2 API can be used to print debug, performance, and telemetry + * information to stderr or a file. The Trace2 feature is inactive unless + * explicitly enabled by enabling one or more Trace2 Targets. + * + * The Trace2 API is intended to replace the existing (Trace1) + * printf-style tracing provided by the existing `GIT_TRACE` and + * `GIT_TRACE_PERFORMANCE` facilities. During initial implementation, + * Trace2 and Trace1 may operate in parallel. + * + * The Trace2 API defines a set of high-level messages with known fields, + * such as (`start`: `argv`) and (`exit`: {`exit-code`, `elapsed-time`}). + * + * Trace2 instrumentation throughout the Git code base sends Trace2 + * messages to the enabled Trace2 Targets. Targets transform these + * messages content into purpose-specific formats and write events to + * their data streams. In this manner, the Trace2 API can drive + * many different types of analysis. + * + * Targets are defined using a VTable allowing easy extension to other + * formats in the future. This might be used to define a binary format, + * for example. + * + * Trace2 is controlled using `trace2.*` config values in the system and + * global config files and `GIT_TRACE2*` environment variables. Trace2 does + * not read from repo local or worktree config files or respect `-c` + * command line config settings. + * + * For more info about: trace2 targets, conventions for public functions and + * macros, trace2 target formats and examples on trace2 API usage refer to + * Documentation/technical/api-trace2.txt + * + */ + +struct child_process; +struct repository; +struct json_writer; + +/* + * The public TRACE2 routines are grouped into the following groups: + * + * [] trace2_initialize -- initialization. + * [] trace2_cmd_* -- emit command/control messages. + * [] trace2_child* -- emit child start/stop messages. + * [] trace2_exec* -- emit exec start/stop messages. + * [] trace2_thread* -- emit thread start/stop messages. + * [] trace2_def* -- emit definition/parameter mesasges. + * [] trace2_region* -- emit region nesting messages. + * [] trace2_data* -- emit region/thread/repo data messages. + * [] trace2_printf* -- legacy trace[1] messages. + * [] trace2_timer* -- stopwatch timers (messages are deferred). + * [] trace2_counter* -- global counters (messages are deferred). + */ + +/* + * Initialize the TRACE2 clock and do nothing else, in particular + * no mallocs, no system inspection, and no environment inspection. + * + * This should be called at the very top of main() to capture the + * process start time. This is intended to reduce chicken-n-egg + * bootstrap pressure. + * + * It is safe to call this more than once. This allows capturing + * absolute startup costs on Windows which uses a little trickery + * to do setup work before common-main.c:main() is called. + * + * The main trace2_initialize_fl() may be called a little later + * after more infrastructure is established. + */ +void trace2_initialize_clock(void); + +/* + * Initialize TRACE2 tracing facility if any of the builtin TRACE2 + * targets are enabled in the system config or the environment. + * This emits a 'version' message containing the version of git + * and the Trace2 protocol. + * + * This function should be called from `main()` as early as possible in + * the life of the process after essential process initialization. + * + * Cleanup/Termination is handled automatically by a registered + * atexit() routine. + */ +void trace2_initialize_fl(const char *file, int line); + +#define trace2_initialize() trace2_initialize_fl(__FILE__, __LINE__) + +/* + * Return 1 if trace2 is enabled (at least one target is active). + */ +int trace2_is_enabled(void); + +/* + * Emit a 'start' event with the original (unmodified) argv. + */ +void trace2_cmd_start_fl(const char *file, int line, const char **argv); + +#define trace2_cmd_start(argv) trace2_cmd_start_fl(__FILE__, __LINE__, (argv)) + +/* + * Emit an 'exit' event. + */ +void trace2_cmd_exit_fl(const char *file, int line, int code); + +#define trace2_cmd_exit(code) (trace2_cmd_exit_fl(__FILE__, __LINE__, (code))) + +/* + * Emit an 'error' event. + * + * Write an error message to the TRACE2 targets. + */ +void trace2_cmd_error_va_fl(const char *file, int line, const char *fmt, + va_list ap); + +#define trace2_cmd_error_va(fmt, ap) \ + trace2_cmd_error_va_fl(__FILE__, __LINE__, (fmt), (ap)) + +/* + * Emit a 'pathname' event with the canonical pathname of the current process + * This gives post-processors a simple field to identify the command without + * having to parse the argv. For example, to distinguish invocations from + * installed versus debug executables. + */ +void trace2_cmd_path_fl(const char *file, int line, const char *pathname); + +#define trace2_cmd_path(p) trace2_cmd_path_fl(__FILE__, __LINE__, (p)) + +/* + * Emit an 'ancestry' event with the process name of the current process's + * parent process. + * This gives post-processors a way to determine what invoked the command and + * learn more about usage patterns. + */ +void trace2_cmd_ancestry_fl(const char *file, int line, const char **parent_names); + +#define trace2_cmd_ancestry(v) trace2_cmd_ancestry_fl(__FILE__, __LINE__, (v)) + +/* + * Emit a 'cmd_name' event with the canonical name of the command. + * This gives post-processors a simple field to identify the command + * without having to parse the argv. + */ +void trace2_cmd_name_fl(const char *file, int line, const char *name); + +#define trace2_cmd_name(v) trace2_cmd_name_fl(__FILE__, __LINE__, (v)) + +/* + * Emit a 'cmd_mode' event to further describe the command being run. + * For example, "checkout" can checkout a single file or can checkout a + * different branch. This gives post-processors a simple field to compare + * equivalent commands without having to parse the argv. + */ +void trace2_cmd_mode_fl(const char *file, int line, const char *mode); + +#define trace2_cmd_mode(sv) trace2_cmd_mode_fl(__FILE__, __LINE__, (sv)) + +/* + * Emits an "alias" message containing the alias used and the argument + * expansion. + */ +void trace2_cmd_alias_fl(const char *file, int line, const char *alias, + const char **argv); + +#define trace2_cmd_alias(alias, argv) \ + trace2_cmd_alias_fl(__FILE__, __LINE__, (alias), (argv)) + +/* + * Emit one or more 'def_param' events for "important" configuration + * settings. + * + * Use the TR2_SYSENV_CFG_PARAM setting to register a comma-separated + * list of patterns configured important. For example: + * git config --system trace2.configParams 'core.*,remote.*.url' + * or: + * GIT_TRACE2_CONFIG_PARAMS=core.*,remote.*.url" + * + * Note: this routine does a read-only iteration on the config data + * (using read_early_config()), so it must not be called until enough + * of the process environment has been established. This includes the + * location of the git and worktree directories, expansion of any "-c" + * and "-C" command line options, and etc. + */ +void trace2_cmd_list_config_fl(const char *file, int line); + +#define trace2_cmd_list_config() trace2_cmd_list_config_fl(__FILE__, __LINE__) + +/* + * Emit one or more 'def_param' events for "important" environment variables. + * + * Use the TR2_SYSENV_ENV_VARS setting to register a comma-separated list of + * environment variables considered important. For example: + * git config --system trace2.envVars 'GIT_HTTP_USER_AGENT,GIT_CONFIG' + * or: + * GIT_TRACE2_ENV_VARS="GIT_HTTP_USER_AGENT,GIT_CONFIG" + */ +void trace2_cmd_list_env_vars_fl(const char *file, int line); + +#define trace2_cmd_list_env_vars() trace2_cmd_list_env_vars_fl(__FILE__, __LINE__) + +/* + * Emit a "def_param" event for the given config key/value pair IF + * we consider the key to be "important". + * + * Use this for new/updated config settings created/updated after + * trace2_cmd_list_config() is called. + */ +void trace2_cmd_set_config_fl(const char *file, int line, const char *key, + const char *value); + +#define trace2_cmd_set_config(k, v) \ + trace2_cmd_set_config_fl(__FILE__, __LINE__, (k), (v)) + +/** + * Emits a "child_start" message containing the "child-id", + * "child-argv", and "child-classification". + * + * Before calling optionally set "cmd->trace2_child_class" to a string + * describing the type of the child process. For example, "editor" or + * "pager". + * + * This function assigns a unique "child-id" to `cmd->trace2_child_id`. + * This field is used later during the "child_exit" message to associate + * it with the "child_start" message. + * + * This function should be called before spawning the child process. + */ +void trace2_child_start_fl(const char *file, int line, + struct child_process *cmd); + +#define trace2_child_start(cmd) trace2_child_start_fl(__FILE__, __LINE__, (cmd)) + +/** + * Emits a "child_exit" message containing the "child-id", + * the child's elapsed time and exit-code. + * + * The reported elapsed time includes the process creation overhead and + * time spend waiting for it to exit, so it may be slightly longer than + * the time reported by the child itself. + * + * This function should be called after reaping the child process. + */ +void trace2_child_exit_fl(const char *file, int line, struct child_process *cmd, + int child_exit_code); + +#define trace2_child_exit(cmd, code) \ + trace2_child_exit_fl(__FILE__, __LINE__, (cmd), (code)) + +/** + * Emits a "child_ready" message containing the "child-id" and a flag + * indicating whether the child was considered "ready" when we + * released it. + * + * This function should be called after starting a daemon process in + * the background (and after giving it sufficient time to boot + * up) to indicate that we no longer control or own it. + * + * The "ready" argument should contain one of { "ready", "timeout", + * "error" } to indicate the state of the running daemon when we + * released it. + * + * If the daemon process fails to start or it exits or is terminated + * while we are still waiting for it, the caller should emit a + * regular "child_exit" to report the normal process exit information. + * + */ +void trace2_child_ready_fl(const char *file, int line, + struct child_process *cmd, + const char *ready); + +#define trace2_child_ready(cmd, ready) \ + trace2_child_ready_fl(__FILE__, __LINE__, (cmd), (ready)) + +/** + * Emit an 'exec' event prior to calling one of exec(), execv(), + * execvp(), and etc. On Unix-derived systems, this will be the + * last event emitted for the current process, unless the exec + * fails. On Windows, exec() behaves like 'child_start' and a + * waitpid(), so additional events may be emitted. + * + * Returns a unique "exec-id". This value is used later + * if the exec() fails and a "exec-result" message is necessary. + */ +int trace2_exec_fl(const char *file, int line, const char *exe, + const char **argv); + +#define trace2_exec(exe, argv) trace2_exec_fl(__FILE__, __LINE__, (exe), (argv)) + +/** + * Emit an 'exec_result' when possible. On Unix-derived systems, + * this should be called after exec() returns (which only happens + * when there is an error starting the new process). On Windows, + * this should be called after the waitpid(). + * + * The "exec_id" should be the value returned from trace2_exec(). + */ +void trace2_exec_result_fl(const char *file, int line, int exec_id, int code); + +#define trace2_exec_result(id, code) \ + trace2_exec_result_fl(__FILE__, __LINE__, (id), (code)) + +/* + * Emit a 'thread_start' event. This must be called from inside the + * thread-proc to allow the thread to create its own thread-local + * storage. + * + * The thread base name should be descriptive, like "preload_index" or + * taken from the thread-proc function. A unique thread name will be + * created from the given base name and the thread id automatically. + */ +void trace2_thread_start_fl(const char *file, int line, + const char *thread_base_name); + +#define trace2_thread_start(thread_base_name) \ + trace2_thread_start_fl(__FILE__, __LINE__, (thread_base_name)) + +/* + * Emit a 'thread_exit' event. This must be called from inside the + * thread-proc so that the thread can access and clean up its + * thread-local storage. + */ +void trace2_thread_exit_fl(const char *file, int line); + +#define trace2_thread_exit() trace2_thread_exit_fl(__FILE__, __LINE__) + +/* + * Emits a "def_param" message containing a key/value pair. + * + * This message is intended to report some global aspect of the current + * command, such as a configuration setting or command line switch that + * significantly affects program performance or behavior, such as + * `core.abbrev`, `status.showUntrackedFiles`, or `--no-ahead-behind`. + */ +void trace2_def_param_fl(const char *file, int line, const char *param, + const char *value); + +#define trace2_def_param(param, value) \ + trace2_def_param_fl(__FILE__, __LINE__, (param), (value)) + +/* + * Tell trace2 about a newly instantiated repo object and assign + * a trace2-repo-id to be used in subsequent activity events. + * + * Emits a 'worktree' event for this repo instance. + * + * Region and data messages may refer to this repo-id. + * + * The main/top-level repository will have repo-id value 1 (aka "r1"). + * + * The repo-id field is in anticipation of future in-proc submodule + * repositories. + */ +void trace2_def_repo_fl(const char *file, int line, struct repository *repo); + +#define trace2_def_repo(repo) trace2_def_repo_fl(__FILE__, __LINE__, repo) + +/** + * Emit a 'region_enter' event for <category>.<label> with optional + * repo-id and printf message. + * + * This function pushes a new region nesting stack level on the current + * thread and starts a clock for the new stack frame. + * + * The `category` field is an arbitrary category name used to classify + * regions by feature area, such as "status" or "index". At this time + * it is only just printed along with the rest of the message. It may + * be used in the future to filter messages. + * + * The `label` field is an arbitrary label used to describe the activity + * being started, such as "read_recursive" or "do_read_index". + * + * The `repo` field, if set, will be used to get the "repo-id", so that + * recursive operations can be attributed to the correct repository. + */ +void trace2_region_enter_fl(const char *file, int line, const char *category, + const char *label, const struct repository *repo, ...); + +#define trace2_region_enter(category, label, repo) \ + trace2_region_enter_fl(__FILE__, __LINE__, (category), (label), (repo)) + +void trace2_region_enter_printf_va_fl(const char *file, int line, + const char *category, const char *label, + const struct repository *repo, + const char *fmt, va_list ap); + +#define trace2_region_enter_printf_va(category, label, repo, fmt, ap) \ + trace2_region_enter_printf_va_fl(__FILE__, __LINE__, (category), \ + (label), (repo), (fmt), (ap)) + +void trace2_region_enter_printf_fl(const char *file, int line, + const char *category, const char *label, + const struct repository *repo, + const char *fmt, ...); + +#define trace2_region_enter_printf(category, label, repo, ...) \ + trace2_region_enter_printf_fl(__FILE__, __LINE__, (category), (label), \ + (repo), __VA_ARGS__) + +/** + * Emit a 'region_leave' event for <category>.<label> with optional + * repo-id and printf message. + * + * Leave current nesting level and report the elapsed time spent + * in this nesting level. + * + * The `category`, `label`, and `repo` fields are the same as + * trace2_region_enter_fl. The `category` and `label` do not + * need to match the corresponding "region_enter" message, + * but it makes the data stream easier to understand. + */ +void trace2_region_leave_fl(const char *file, int line, const char *category, + const char *label, const struct repository *repo, ...); + +#define trace2_region_leave(category, label, repo) \ + trace2_region_leave_fl(__FILE__, __LINE__, (category), (label), (repo)) + +void trace2_region_leave_printf_va_fl(const char *file, int line, + const char *category, const char *label, + const struct repository *repo, + const char *fmt, va_list ap); + +#define trace2_region_leave_printf_va(category, label, repo, fmt, ap) \ + trace2_region_leave_printf_va_fl(__FILE__, __LINE__, (category), \ + (label), (repo), (fmt), (ap)) + +void trace2_region_leave_printf_fl(const char *file, int line, + const char *category, const char *label, + const struct repository *repo, + const char *fmt, ...); + +#define trace2_region_leave_printf(category, label, repo, ...) \ + trace2_region_leave_printf_fl(__FILE__, __LINE__, (category), (label), \ + (repo), __VA_ARGS__) + +/** + * Emit a key-value pair 'data' event of the form <category>.<key> = <value>. + * This event implicitly contains information about thread, nesting region, + * and optional repo-id. + * This could be used to print the number of files in a directory during + * a multi-threaded recursive tree walk. + * + * On event-based TRACE2 targets, this generates a 'data' event suitable + * for post-processing. On printf-based TRACE2 targets, this is converted + * into a fixed-format printf message. + */ +void trace2_data_string_fl(const char *file, int line, const char *category, + const struct repository *repo, const char *key, + const char *value); + +#define trace2_data_string(category, repo, key, value) \ + trace2_data_string_fl(__FILE__, __LINE__, (category), (repo), (key), \ + (value)) + +void trace2_data_intmax_fl(const char *file, int line, const char *category, + const struct repository *repo, const char *key, + intmax_t value); + +#define trace2_data_intmax(category, repo, key, value) \ + trace2_data_intmax_fl(__FILE__, __LINE__, (category), (repo), (key), \ + (value)) + +void trace2_data_json_fl(const char *file, int line, const char *category, + const struct repository *repo, const char *key, + const struct json_writer *jw); + +#define trace2_data_json(category, repo, key, value) \ + trace2_data_json_fl(__FILE__, __LINE__, (category), (repo), (key), \ + (value)) + +/* + * Emit a 'printf' event. + * + * Write an arbitrary formatted message to the TRACE2 targets. These + * text messages should be considered as human-readable strings without + * any formatting guidelines. Post-processors may choose to ignore + * them. + */ +void trace2_printf_va_fl(const char *file, int line, const char *fmt, + va_list ap); + +#define trace2_printf_va(fmt, ap) \ + trace2_printf_va_fl(__FILE__, __LINE__, (fmt), (ap)) + +void trace2_printf_fl(const char *file, int line, const char *fmt, ...); + +#define trace2_printf(...) trace2_printf_fl(__FILE__, __LINE__, __VA_ARGS__) + +/* + * Define the set of stopwatch timers. + * + * We can add more at any time, but they must be defined at compile + * time (to avoid the need to dynamically allocate and synchronize + * them between different threads). + * + * These must start at 0 and be contiguous (because we use them + * elsewhere as array indexes). + * + * Any values added to this enum must also be added to the + * `tr2_timer_metadata[]` in `trace2/tr2_tmr.c`. + */ +enum trace2_timer_id { + /* + * Define two timers for testing. See `t/helper/test-trace2.c`. + * These can be used for ad hoc testing, but should not be used + * for permanent analysis code. + */ + TRACE2_TIMER_ID_TEST1 = 0, /* emits summary event only */ + TRACE2_TIMER_ID_TEST2, /* emits summary and thread events */ + + /* Add additional timer definitions before here. */ + TRACE2_NUMBER_OF_TIMERS +}; + +/* + * Start/Stop the indicated stopwatch timer in the current thread. + * + * The time spent by the current thread between the _start and _stop + * calls will be added to the thread's partial sum for this timer. + * + * Timer events are emitted at thread and program exit. + * + * Note: Since the stopwatch API routines do not generate individual + * events, they do not take (file, line) arguments. Similarly, the + * category and timer name values are defined at compile-time in the + * timer definitions array, so they are not needed here in the API. + */ +void trace2_timer_start(enum trace2_timer_id tid); +void trace2_timer_stop(enum trace2_timer_id tid); + +/* + * Define the set of global counters. + * + * We can add more at any time, but they must be defined at compile + * time (to avoid the need to dynamically allocate and synchronize + * them between different threads). + * + * These must start at 0 and be contiguous (because we use them + * elsewhere as array indexes). + * + * Any values added to this enum be also be added to the + * `tr2_counter_metadata[]` in `trace2/tr2_tr2_ctr.c`. + */ +enum trace2_counter_id { + /* + * Define two counters for testing. See `t/helper/test-trace2.c`. + * These can be used for ad hoc testing, but should not be used + * for permanent analysis code. + */ + TRACE2_COUNTER_ID_TEST1 = 0, /* emits summary event only */ + TRACE2_COUNTER_ID_TEST2, /* emits summary and thread events */ + + /* Add additional counter definitions before here. */ + TRACE2_NUMBER_OF_COUNTERS +}; + +/* + * Increase the named global counter by value. + * + * Note that this adds `value` to the current thread's partial sum for + * this counter (without locking) and that the complete sum is not + * available until all threads have exited, so it does not return the + * new value of the counter. + */ +void trace2_counter_add(enum trace2_counter_id cid, uint64_t value); + +/* + * Optional platform-specific code to dump information about the + * current and any parent process(es). This is intended to allow + * post-processors to know who spawned this git instance and anything + * else that the platform may be able to tell us about the current process. + */ + +enum trace2_process_info_reason { + TRACE2_PROCESS_INFO_STARTUP, + TRACE2_PROCESS_INFO_EXIT, +}; + +void trace2_collect_process_info(enum trace2_process_info_reason reason); + +const char *trace2_session_id(void); + +#endif /* TRACE2_H */ diff --git a/trace2/tr2_cfg.c b/trace2/tr2_cfg.c new file mode 100644 index 0000000..ec9ac1a --- /dev/null +++ b/trace2/tr2_cfg.c @@ -0,0 +1,147 @@ +#include "cache.h" +#include "config.h" +#include "trace2/tr2_cfg.h" +#include "trace2/tr2_sysenv.h" + +static struct strbuf **tr2_cfg_patterns; +static int tr2_cfg_count_patterns; +static int tr2_cfg_loaded; + +static struct strbuf **tr2_cfg_env_vars; +static int tr2_cfg_env_vars_count; +static int tr2_cfg_env_vars_loaded; + +/* + * Parse a string containing a comma-delimited list of config keys + * or wildcard patterns into a list of strbufs. + */ +static int tr2_cfg_load_patterns(void) +{ + struct strbuf **s; + const char *envvar; + + if (tr2_cfg_loaded) + return tr2_cfg_count_patterns; + tr2_cfg_loaded = 1; + + envvar = tr2_sysenv_get(TR2_SYSENV_CFG_PARAM); + if (!envvar || !*envvar) + return tr2_cfg_count_patterns; + + tr2_cfg_patterns = strbuf_split_buf(envvar, strlen(envvar), ',', -1); + for (s = tr2_cfg_patterns; *s; s++) { + struct strbuf *buf = *s; + + if (buf->len && buf->buf[buf->len - 1] == ',') + strbuf_setlen(buf, buf->len - 1); + strbuf_trim_trailing_newline(*s); + strbuf_trim(*s); + } + + tr2_cfg_count_patterns = s - tr2_cfg_patterns; + return tr2_cfg_count_patterns; +} + +void tr2_cfg_free_patterns(void) +{ + if (tr2_cfg_patterns) + strbuf_list_free(tr2_cfg_patterns); + tr2_cfg_count_patterns = 0; + tr2_cfg_loaded = 0; +} + +/* + * Parse a string containing a comma-delimited list of environment variable + * names into a list of strbufs. + */ +static int tr2_load_env_vars(void) +{ + struct strbuf **s; + const char *varlist; + + if (tr2_cfg_env_vars_loaded) + return tr2_cfg_env_vars_count; + tr2_cfg_env_vars_loaded = 1; + + varlist = tr2_sysenv_get(TR2_SYSENV_ENV_VARS); + if (!varlist || !*varlist) + return tr2_cfg_env_vars_count; + + tr2_cfg_env_vars = strbuf_split_buf(varlist, strlen(varlist), ',', -1); + for (s = tr2_cfg_env_vars; *s; s++) { + struct strbuf *buf = *s; + + if (buf->len && buf->buf[buf->len - 1] == ',') + strbuf_setlen(buf, buf->len - 1); + strbuf_trim_trailing_newline(*s); + strbuf_trim(*s); + } + + tr2_cfg_env_vars_count = s - tr2_cfg_env_vars; + return tr2_cfg_env_vars_count; +} + +void tr2_cfg_free_env_vars(void) +{ + if (tr2_cfg_env_vars) + strbuf_list_free(tr2_cfg_env_vars); + tr2_cfg_env_vars_count = 0; + tr2_cfg_env_vars_loaded = 0; +} + +struct tr2_cfg_data { + const char *file; + int line; +}; + +/* + * See if the given config key matches any of our patterns of interest. + */ +static int tr2_cfg_cb(const char *key, const char *value, void *d) +{ + struct strbuf **s; + struct tr2_cfg_data *data = (struct tr2_cfg_data *)d; + + for (s = tr2_cfg_patterns; *s; s++) { + struct strbuf *buf = *s; + int wm = wildmatch(buf->buf, key, WM_CASEFOLD); + if (wm == WM_MATCH) { + trace2_def_param_fl(data->file, data->line, key, value); + return 0; + } + } + + return 0; +} + +void tr2_cfg_list_config_fl(const char *file, int line) +{ + struct tr2_cfg_data data = { file, line }; + + if (tr2_cfg_load_patterns() > 0) + read_early_config(tr2_cfg_cb, &data); +} + +void tr2_list_env_vars_fl(const char *file, int line) +{ + struct strbuf **s; + + if (tr2_load_env_vars() <= 0) + return; + + for (s = tr2_cfg_env_vars; *s; s++) { + struct strbuf *buf = *s; + const char *val = getenv(buf->buf); + if (val && *val) + trace2_def_param_fl(file, line, buf->buf, val); + } +} + +void tr2_cfg_set_fl(const char *file, int line, const char *key, + const char *value) +{ + struct tr2_cfg_data data = { file, line }; + + if (tr2_cfg_load_patterns() > 0) + tr2_cfg_cb(key, value, &data); +} diff --git a/trace2/tr2_cfg.h b/trace2/tr2_cfg.h new file mode 100644 index 0000000..a11d71f --- /dev/null +++ b/trace2/tr2_cfg.h @@ -0,0 +1,27 @@ +#ifndef TR2_CFG_H +#define TR2_CFG_H + +/* + * Iterate over all config settings and emit 'def_param' events for the + * "interesting" ones to TRACE2. + */ +void tr2_cfg_list_config_fl(const char *file, int line); + +/* + * Iterate over all "interesting" environment variables and emit 'def_param' + * events for them to TRACE2. + */ +void tr2_list_env_vars_fl(const char *file, int line); + +/* + * Emit a "def_param" event for the given key/value pair IF we consider + * the key to be "interesting". + */ +void tr2_cfg_set_fl(const char *file, int line, const char *key, + const char *value); + +void tr2_cfg_free_patterns(void); + +void tr2_cfg_free_env_vars(void); + +#endif /* TR2_CFG_H */ diff --git a/trace2/tr2_cmd_name.c b/trace2/tr2_cmd_name.c new file mode 100644 index 0000000..dd31320 --- /dev/null +++ b/trace2/tr2_cmd_name.c @@ -0,0 +1,30 @@ +#include "cache.h" +#include "trace2/tr2_cmd_name.h" + +#define TR2_ENVVAR_PARENT_NAME "GIT_TRACE2_PARENT_NAME" + +static struct strbuf tr2cmdname_hierarchy = STRBUF_INIT; + +void tr2_cmd_name_append_hierarchy(const char *name) +{ + const char *parent_name = getenv(TR2_ENVVAR_PARENT_NAME); + + strbuf_reset(&tr2cmdname_hierarchy); + if (parent_name && *parent_name) { + strbuf_addstr(&tr2cmdname_hierarchy, parent_name); + strbuf_addch(&tr2cmdname_hierarchy, '/'); + } + strbuf_addstr(&tr2cmdname_hierarchy, name); + + setenv(TR2_ENVVAR_PARENT_NAME, tr2cmdname_hierarchy.buf, 1); +} + +const char *tr2_cmd_name_get_hierarchy(void) +{ + return tr2cmdname_hierarchy.buf; +} + +void tr2_cmd_name_release(void) +{ + strbuf_release(&tr2cmdname_hierarchy); +} diff --git a/trace2/tr2_cmd_name.h b/trace2/tr2_cmd_name.h new file mode 100644 index 0000000..ab70b67 --- /dev/null +++ b/trace2/tr2_cmd_name.h @@ -0,0 +1,24 @@ +#ifndef TR2_CMD_NAME_H +#define TR2_CMD_NAME_H + +/* + * Append the current command name to the list being maintained + * in the environment. + * + * The hierarchy for a top-level git command is just the current + * command name. For a child git process, the hierarchy includes the + * names of the parent processes. + * + * The hierarchy for the current process will be exported to the + * environment and inherited by child processes. + */ +void tr2_cmd_name_append_hierarchy(const char *name); + +/* + * Get the command name hierarchy for the current process. + */ +const char *tr2_cmd_name_get_hierarchy(void); + +void tr2_cmd_name_release(void); + +#endif /* TR2_CMD_NAME_H */ diff --git a/trace2/tr2_ctr.c b/trace2/tr2_ctr.c new file mode 100644 index 0000000..483ca7c --- /dev/null +++ b/trace2/tr2_ctr.c @@ -0,0 +1,101 @@ +#include "cache.h" +#include "thread-utils.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" +#include "trace2/tr2_ctr.h" + +/* + * A global counter block to aggregrate values from the partial sums + * from each thread. + */ +static struct tr2_counter_block final_counter_block; /* access under tr2tls_mutex */ + +/* + * Define metadata for each global counter. + * + * This array must match the "enum trace2_counter_id" and the values + * in "struct tr2_counter_block.counter[*]". + */ +static struct tr2_counter_metadata tr2_counter_metadata[TRACE2_NUMBER_OF_COUNTERS] = { + [TRACE2_COUNTER_ID_TEST1] = { + .category = "test", + .name = "test1", + .want_per_thread_events = 0, + }, + [TRACE2_COUNTER_ID_TEST2] = { + .category = "test", + .name = "test2", + .want_per_thread_events = 1, + }, + + /* Add additional metadata before here. */ +}; + +void tr2_counter_increment(enum trace2_counter_id cid, uint64_t value) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + struct tr2_counter *c = &ctx->counter_block.counter[cid]; + + c->value += value; + + ctx->used_any_counter = 1; + if (tr2_counter_metadata[cid].want_per_thread_events) + ctx->used_any_per_thread_counter = 1; +} + +void tr2_update_final_counters(void) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + enum trace2_counter_id cid; + + if (!ctx->used_any_counter) + return; + + /* + * Access `final_counter_block` requires holding `tr2tls_mutex`. + * We assume that our caller is holding the lock. + */ + + for (cid = 0; cid < TRACE2_NUMBER_OF_COUNTERS; cid++) { + struct tr2_counter *c_final = &final_counter_block.counter[cid]; + const struct tr2_counter *c = &ctx->counter_block.counter[cid]; + + c_final->value += c->value; + } +} + +void tr2_emit_per_thread_counters(tr2_tgt_evt_counter_t *fn_apply) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + enum trace2_counter_id cid; + + if (!ctx->used_any_per_thread_counter) + return; + + /* + * For each counter, if the counter wants per-thread events + * and this thread used it (the value is non-zero), emit it. + */ + for (cid = 0; cid < TRACE2_NUMBER_OF_COUNTERS; cid++) + if (tr2_counter_metadata[cid].want_per_thread_events && + ctx->counter_block.counter[cid].value) + fn_apply(&tr2_counter_metadata[cid], + &ctx->counter_block.counter[cid], + 0); +} + +void tr2_emit_final_counters(tr2_tgt_evt_counter_t *fn_apply) +{ + enum trace2_counter_id cid; + + /* + * Access `final_counter_block` requires holding `tr2tls_mutex`. + * We assume that our caller is holding the lock. + */ + + for (cid = 0; cid < TRACE2_NUMBER_OF_COUNTERS; cid++) + if (final_counter_block.counter[cid].value) + fn_apply(&tr2_counter_metadata[cid], + &final_counter_block.counter[cid], + 1); +} diff --git a/trace2/tr2_ctr.h b/trace2/tr2_ctr.h new file mode 100644 index 0000000..a2267ee --- /dev/null +++ b/trace2/tr2_ctr.h @@ -0,0 +1,104 @@ +#ifndef TR2_CTR_H +#define TR2_CTR_H + +#include "trace2.h" +#include "trace2/tr2_tgt.h" + +/* + * Define a mechanism to allow global "counters". + * + * Counters can be used count interesting activity that does not fit + * the "region and data" model, such as code called from many + * different regions and/or where you want to count a number of items, + * but don't have control of when the last item will be processed, + * such as counter the number of calls to `lstat()`. + * + * Counters differ from Trace2 "data" events. Data events are emitted + * immediately and are appropriate for documenting loop counters at + * the end of a region, for example. Counter values are accumulated + * during the program and final counter values are emitted at program + * exit. + * + * To make this model efficient, we define a compile-time fixed set of + * counters and counter ids using a fixed size "counter block" array + * in thread-local storage. This gives us constant time, lock-free + * access to each counter within each thread. This lets us avoid the + * complexities of dynamically allocating a counter and sharing that + * definition with other threads. + * + * Each thread uses the counter block in its thread-local storage to + * increment partial sums for each counter (without locking). When a + * thread exits, those partial sums are (under lock) added to the + * global final sum. + * + * Partial sums for each counter are optionally emitted when a thread + * exits. + * + * Final sums for each counter are emitted between the "exit" and + * "atexit" events. + * + * A parallel "counter metadata" table contains the "category" and + * "name" fields for each counter. This eliminates the need to + * include those args in the various counter APIs. + */ + +/* + * The definition of an individual counter as used by an individual + * thread (and later in aggregation). + */ +struct tr2_counter { + uint64_t value; +}; + +/* + * Metadata for a counter. + */ +struct tr2_counter_metadata { + const char *category; + const char *name; + + /* + * True if we should emit per-thread events for this counter + * when individual threads exit. + */ + unsigned int want_per_thread_events:1; +}; + +/* + * A compile-time fixed block of counters to insert into thread-local + * storage. This wrapper is used to avoid quirks of C and the usual + * need to pass an array size argument. + */ +struct tr2_counter_block { + struct tr2_counter counter[TRACE2_NUMBER_OF_COUNTERS]; +}; + +/* + * Private routines used by trace2.c to increment a counter for the + * current thread. + */ +void tr2_counter_increment(enum trace2_counter_id cid, uint64_t value); + +/* + * Add the current thread's counter data to the global totals. + * This is called during thread-exit. + * + * Caller must be holding the tr2tls_mutex. + */ +void tr2_update_final_counters(void); + +/* + * Emit per-thread counter data for the current thread. + * This is called during thread-exit. + */ +void tr2_emit_per_thread_counters(tr2_tgt_evt_counter_t *fn_apply); + +/* + * Emit global counter values. + * This is called during atexit handling. + * + * Caller must be holding the tr2tls_mutex. + */ +void tr2_emit_final_counters(tr2_tgt_evt_counter_t *fn_apply); + +#endif /* TR2_CTR_H */ diff --git a/trace2/tr2_dst.c b/trace2/tr2_dst.c new file mode 100644 index 0000000..8a21dd2 --- /dev/null +++ b/trace2/tr2_dst.c @@ -0,0 +1,394 @@ +#include "cache.h" +#include "sigchain.h" +#include "trace2/tr2_dst.h" +#include "trace2/tr2_sid.h" +#include "trace2/tr2_sysenv.h" + +/* + * How many attempts we will make at creating an automatically-named trace file. + */ +#define MAX_AUTO_ATTEMPTS 10 + +/* + * Sentinel file used to detect when we should discard new traces to avoid + * writing too many trace files to a directory. + */ +#define DISCARD_SENTINEL_NAME "git-trace2-discard" + +/* + * When set to zero, disables directory file count checks. Otherwise, controls + * how many files we can write to a directory before entering discard mode. + * This can be overridden via the TR2_SYSENV_MAX_FILES setting. + */ +static int tr2env_max_files = 0; + +static int tr2_dst_want_warning(void) +{ + static int tr2env_dst_debug = -1; + + if (tr2env_dst_debug == -1) { + const char *env_value = tr2_sysenv_get(TR2_SYSENV_DST_DEBUG); + if (!env_value || !*env_value) + tr2env_dst_debug = 0; + else + tr2env_dst_debug = atoi(env_value) > 0; + } + + return tr2env_dst_debug; +} + +void tr2_dst_trace_disable(struct tr2_dst *dst) +{ + if (dst->need_close) + close(dst->fd); + dst->fd = 0; + dst->initialized = 1; + dst->need_close = 0; +} + +/* + * Check to make sure we're not overloading the target directory with too many + * files. First get the threshold (if present) from the config or envvar. If + * it's zero or unset, disable this check. Next check for the presence of a + * sentinel file, then check file count. + * + * Returns 0 if tracing should proceed as normal. Returns 1 if the sentinel file + * already exists, which means tracing should be disabled. Returns -1 if there + * are too many files but there was no sentinel file, which means we have + * created and should write traces to the sentinel file. + * + * We expect that some trace processing system is gradually collecting files + * from the target directory; after it removes the sentinel file we'll start + * writing traces again. + */ +static int tr2_dst_too_many_files(struct tr2_dst *dst, const char *tgt_prefix) +{ + int file_count = 0, max_files = 0, ret = 0; + const char *max_files_var; + DIR *dirp; + struct strbuf path = STRBUF_INIT, sentinel_path = STRBUF_INIT; + struct stat statbuf; + + /* Get the config or envvar and decide if we should continue this check */ + max_files_var = tr2_sysenv_get(TR2_SYSENV_MAX_FILES); + if (max_files_var && *max_files_var && ((max_files = atoi(max_files_var)) >= 0)) + tr2env_max_files = max_files; + + if (!tr2env_max_files) { + ret = 0; + goto cleanup; + } + + strbuf_addstr(&path, tgt_prefix); + if (!is_dir_sep(path.buf[path.len - 1])) { + strbuf_addch(&path, '/'); + } + + /* check sentinel */ + strbuf_addbuf(&sentinel_path, &path); + strbuf_addstr(&sentinel_path, DISCARD_SENTINEL_NAME); + if (!stat(sentinel_path.buf, &statbuf)) { + ret = 1; + goto cleanup; + } + + /* check file count */ + dirp = opendir(path.buf); + while (file_count < tr2env_max_files && dirp && readdir(dirp)) + file_count++; + if (dirp) + closedir(dirp); + + if (file_count >= tr2env_max_files) { + dst->too_many_files = 1; + dst->fd = open(sentinel_path.buf, O_WRONLY | O_CREAT | O_EXCL, 0666); + ret = -1; + goto cleanup; + } + +cleanup: + strbuf_release(&path); + strbuf_release(&sentinel_path); + return ret; +} + +static int tr2_dst_try_auto_path(struct tr2_dst *dst, const char *tgt_prefix) +{ + int too_many_files; + const char *last_slash, *sid = tr2_sid_get(); + struct strbuf path = STRBUF_INIT; + size_t base_path_len; + unsigned attempt_count; + + last_slash = strrchr(sid, '/'); + if (last_slash) + sid = last_slash + 1; + + strbuf_addstr(&path, tgt_prefix); + if (!is_dir_sep(path.buf[path.len - 1])) + strbuf_addch(&path, '/'); + strbuf_addstr(&path, sid); + base_path_len = path.len; + + too_many_files = tr2_dst_too_many_files(dst, tgt_prefix); + if (!too_many_files) { + for (attempt_count = 0; attempt_count < MAX_AUTO_ATTEMPTS; attempt_count++) { + if (attempt_count > 0) { + strbuf_setlen(&path, base_path_len); + strbuf_addf(&path, ".%d", attempt_count); + } + + dst->fd = open(path.buf, O_WRONLY | O_CREAT | O_EXCL, 0666); + if (dst->fd != -1) + break; + } + } else if (too_many_files == 1) { + strbuf_release(&path); + if (tr2_dst_want_warning()) + warning("trace2: not opening %s trace file due to too " + "many files in target directory %s", + tr2_sysenv_display_name(dst->sysenv_var), + tgt_prefix); + return 0; + } + + if (dst->fd == -1) { + if (tr2_dst_want_warning()) + warning("trace2: could not open '%.*s' for '%s' tracing: %s", + (int) base_path_len, path.buf, + tr2_sysenv_display_name(dst->sysenv_var), + strerror(errno)); + + tr2_dst_trace_disable(dst); + strbuf_release(&path); + return 0; + } + + strbuf_release(&path); + + dst->need_close = 1; + dst->initialized = 1; + + return dst->fd; +} + +static int tr2_dst_try_path(struct tr2_dst *dst, const char *tgt_value) +{ + int fd = open(tgt_value, O_WRONLY | O_APPEND | O_CREAT, 0666); + if (fd == -1) { + if (tr2_dst_want_warning()) + warning("trace2: could not open '%s' for '%s' tracing: %s", + tgt_value, + tr2_sysenv_display_name(dst->sysenv_var), + strerror(errno)); + + tr2_dst_trace_disable(dst); + return 0; + } + + dst->fd = fd; + dst->need_close = 1; + dst->initialized = 1; + + return dst->fd; +} + +#ifndef NO_UNIX_SOCKETS +#define PREFIX_AF_UNIX "af_unix:" +#define PREFIX_AF_UNIX_STREAM "af_unix:stream:" +#define PREFIX_AF_UNIX_DGRAM "af_unix:dgram:" + +static int tr2_dst_try_uds_connect(const char *path, int sock_type, int *out_fd) +{ + int fd; + struct sockaddr_un sa; + + fd = socket(AF_UNIX, sock_type, 0); + if (fd == -1) + return -1; + + sa.sun_family = AF_UNIX; + strlcpy(sa.sun_path, path, sizeof(sa.sun_path)); + + if (connect(fd, (struct sockaddr *)&sa, sizeof(sa)) == -1) { + int saved_errno = errno; + close(fd); + errno = saved_errno; + return -1; + } + + *out_fd = fd; + return 0; +} + +#define TR2_DST_UDS_TRY_STREAM (1 << 0) +#define TR2_DST_UDS_TRY_DGRAM (1 << 1) + +static int tr2_dst_try_unix_domain_socket(struct tr2_dst *dst, + const char *tgt_value) +{ + unsigned int uds_try = 0; + int fd; + const char *path = NULL; + + /* + * Allow "af_unix:[<type>:]<absolute_path>" + * + * Trace2 always writes complete individual messages (without + * chunking), so we can talk to either DGRAM or STREAM type sockets. + * + * Allow the user to explicitly request the socket type. + * + * If they omit the socket type, try one and then the other. + */ + + if (skip_prefix(tgt_value, PREFIX_AF_UNIX_STREAM, &path)) + uds_try |= TR2_DST_UDS_TRY_STREAM; + + else if (skip_prefix(tgt_value, PREFIX_AF_UNIX_DGRAM, &path)) + uds_try |= TR2_DST_UDS_TRY_DGRAM; + + else if (skip_prefix(tgt_value, PREFIX_AF_UNIX, &path)) + uds_try |= TR2_DST_UDS_TRY_STREAM | TR2_DST_UDS_TRY_DGRAM; + + if (!path || !*path) { + if (tr2_dst_want_warning()) + warning("trace2: invalid AF_UNIX value '%s' for '%s' tracing", + tgt_value, + tr2_sysenv_display_name(dst->sysenv_var)); + + tr2_dst_trace_disable(dst); + return 0; + } + + if (!is_absolute_path(path) || + strlen(path) >= sizeof(((struct sockaddr_un *)0)->sun_path)) { + if (tr2_dst_want_warning()) + warning("trace2: invalid AF_UNIX path '%s' for '%s' tracing", + path, tr2_sysenv_display_name(dst->sysenv_var)); + + tr2_dst_trace_disable(dst); + return 0; + } + + if (uds_try & TR2_DST_UDS_TRY_STREAM) { + if (!tr2_dst_try_uds_connect(path, SOCK_STREAM, &fd)) + goto connected; + if (errno != EPROTOTYPE) + goto error; + } + if (uds_try & TR2_DST_UDS_TRY_DGRAM) { + if (!tr2_dst_try_uds_connect(path, SOCK_DGRAM, &fd)) + goto connected; + } + +error: + if (tr2_dst_want_warning()) + warning("trace2: could not connect to socket '%s' for '%s' tracing: %s", + path, tr2_sysenv_display_name(dst->sysenv_var), + strerror(errno)); + + tr2_dst_trace_disable(dst); + return 0; + +connected: + dst->fd = fd; + dst->need_close = 1; + dst->initialized = 1; + + return dst->fd; +} +#endif + +static void tr2_dst_malformed_warning(struct tr2_dst *dst, + const char *tgt_value) +{ + warning("trace2: unknown value for '%s': '%s'", + tr2_sysenv_display_name(dst->sysenv_var), tgt_value); +} + +int tr2_dst_get_trace_fd(struct tr2_dst *dst) +{ + const char *tgt_value; + + /* don't open twice */ + if (dst->initialized) + return dst->fd; + + dst->initialized = 1; + + tgt_value = tr2_sysenv_get(dst->sysenv_var); + + if (!tgt_value || !strcmp(tgt_value, "") || !strcmp(tgt_value, "0") || + !strcasecmp(tgt_value, "false")) { + dst->fd = 0; + return dst->fd; + } + + if (!strcmp(tgt_value, "1") || !strcasecmp(tgt_value, "true")) { + dst->fd = STDERR_FILENO; + return dst->fd; + } + + if (strlen(tgt_value) == 1 && isdigit(*tgt_value)) { + dst->fd = atoi(tgt_value); + return dst->fd; + } + + if (is_absolute_path(tgt_value)) { + if (is_directory(tgt_value)) + return tr2_dst_try_auto_path(dst, tgt_value); + else + return tr2_dst_try_path(dst, tgt_value); + } + +#ifndef NO_UNIX_SOCKETS + if (starts_with(tgt_value, PREFIX_AF_UNIX)) + return tr2_dst_try_unix_domain_socket(dst, tgt_value); +#endif + + /* Always warn about malformed values. */ + tr2_dst_malformed_warning(dst, tgt_value); + tr2_dst_trace_disable(dst); + return 0; +} + +int tr2_dst_trace_want(struct tr2_dst *dst) +{ + return !!tr2_dst_get_trace_fd(dst); +} + +void tr2_dst_write_line(struct tr2_dst *dst, struct strbuf *buf_line) +{ + int fd = tr2_dst_get_trace_fd(dst); + ssize_t bytes; + + strbuf_complete_line(buf_line); /* ensure final NL on buffer */ + + /* + * We do not use write_in_full() because we do not want + * a short-write to try again. We are using O_APPEND mode + * files and the kernel handles the atomic seek+write. If + * another thread or git process is concurrently writing to + * this fd or file, our remainder-write may not be contiguous + * with our initial write of this message. And that will + * confuse readers. So just don't bother. + * + * It is assumed that TRACE2 messages are short enough that + * the system can write them in 1 attempt and we won't see + * a short-write. + * + * If we get an IO error, just close the trace dst. + */ + sigchain_push(SIGPIPE, SIG_IGN); + bytes = write(fd, buf_line->buf, buf_line->len); + sigchain_pop(SIGPIPE); + if (bytes >= 0) + return; + + tr2_dst_trace_disable(dst); + if (tr2_dst_want_warning()) + warning("unable to write trace to '%s': %s", + tr2_sysenv_display_name(dst->sysenv_var), + strerror(errno)); +} diff --git a/trace2/tr2_dst.h b/trace2/tr2_dst.h new file mode 100644 index 0000000..b1a8c14 --- /dev/null +++ b/trace2/tr2_dst.h @@ -0,0 +1,38 @@ +#ifndef TR2_DST_H +#define TR2_DST_H + +struct strbuf; +#include "trace2/tr2_sysenv.h" + +struct tr2_dst { + enum tr2_sysenv_variable sysenv_var; + int fd; + unsigned int initialized : 1; + unsigned int need_close : 1; + unsigned int too_many_files : 1; +}; + +/* + * Disable TRACE2 on the destination. In TRACE2 a destination (DST) + * wraps a file descriptor; it is associated with a TARGET which + * defines the formatting. + */ +void tr2_dst_trace_disable(struct tr2_dst *dst); + +/* + * Return the file descriptor for the DST. + * If 0, the dst is closed or disabled. + */ +int tr2_dst_get_trace_fd(struct tr2_dst *dst); + +/* + * Return true if the DST is opened for writing. + */ +int tr2_dst_trace_want(struct tr2_dst *dst); + +/* + * Write a single line/message to the trace file. + */ +void tr2_dst_write_line(struct tr2_dst *dst, struct strbuf *buf_line); + +#endif /* TR2_DST_H */ diff --git a/trace2/tr2_sid.c b/trace2/tr2_sid.c new file mode 100644 index 0000000..dc6e75e --- /dev/null +++ b/trace2/tr2_sid.c @@ -0,0 +1,112 @@ +#include "cache.h" +#include "trace2/tr2_tbuf.h" +#include "trace2/tr2_sid.h" + +#define TR2_ENVVAR_PARENT_SID "GIT_TRACE2_PARENT_SID" + +static struct strbuf tr2sid_buf = STRBUF_INIT; +static int tr2sid_nr_git_parents; + +/* + * Compute the final component of the SID representing the current process. + * This should uniquely identify the process and be a valid filename (to + * allow writing trace2 data to per-process files). It should also be fixed + * length for possible use as a database key. + * + * "<yyyymmdd>T<hhmmss>.<fraction>Z-<host>-<process>" + * + * where <host> is a 9 character string: + * "H<first_8_chars_of_sha1_of_hostname>" + * "Localhost" when no hostname. + * + * where <process> is a 9 character string containing the least significant + * 32 bits in the process-id. + * "P<pid>" + * (This is an abribrary choice. On most systems pid_t is a 32 bit value, + * so limit doesn't matter. On larger systems, a truncated value is fine + * for our purposes here.) + */ +static void tr2_sid_append_my_sid_component(void) +{ + const struct git_hash_algo *algo = &hash_algos[GIT_HASH_SHA1]; + struct tr2_tbuf tb_now; + git_hash_ctx ctx; + pid_t pid = getpid(); + unsigned char hash[GIT_MAX_RAWSZ + 1]; + char hex[GIT_MAX_HEXSZ + 1]; + char hostname[HOST_NAME_MAX + 1]; + + tr2_tbuf_utc_datetime(&tb_now); + strbuf_addstr(&tr2sid_buf, tb_now.buf); + + strbuf_addch(&tr2sid_buf, '-'); + if (xgethostname(hostname, sizeof(hostname))) + strbuf_add(&tr2sid_buf, "Localhost", 9); + else { + algo->init_fn(&ctx); + algo->update_fn(&ctx, hostname, strlen(hostname)); + algo->final_fn(hash, &ctx); + hash_to_hex_algop_r(hex, hash, algo); + strbuf_addch(&tr2sid_buf, 'H'); + strbuf_add(&tr2sid_buf, hex, 8); + } + + strbuf_addf(&tr2sid_buf, "-P%08"PRIx32, (uint32_t)pid); +} + +/* + * Compute a "unique" session id (SID) for the current process. This allows + * all events from this process to have a single label (much like a PID). + * + * Export this into our environment so that all child processes inherit it. + * + * If we were started by another git instance, use our parent's SID as a + * prefix. (This lets us track parent/child relationships even if there + * is an intermediate shell process.) + * + * Additionally, count the number of nested git processes. + */ +static void tr2_sid_compute(void) +{ + const char *parent_sid; + + if (tr2sid_buf.len) + return; + + parent_sid = getenv(TR2_ENVVAR_PARENT_SID); + if (parent_sid && *parent_sid) { + const char *p; + for (p = parent_sid; *p; p++) + if (*p == '/') + tr2sid_nr_git_parents++; + + strbuf_addstr(&tr2sid_buf, parent_sid); + strbuf_addch(&tr2sid_buf, '/'); + tr2sid_nr_git_parents++; + } + + tr2_sid_append_my_sid_component(); + + setenv(TR2_ENVVAR_PARENT_SID, tr2sid_buf.buf, 1); +} + +const char *tr2_sid_get(void) +{ + if (!tr2sid_buf.len) + tr2_sid_compute(); + + return tr2sid_buf.buf; +} + +int tr2_sid_depth(void) +{ + if (!tr2sid_buf.len) + tr2_sid_compute(); + + return tr2sid_nr_git_parents; +} + +void tr2_sid_release(void) +{ + strbuf_release(&tr2sid_buf); +} diff --git a/trace2/tr2_sid.h b/trace2/tr2_sid.h new file mode 100644 index 0000000..9bef321 --- /dev/null +++ b/trace2/tr2_sid.h @@ -0,0 +1,18 @@ +#ifndef TR2_SID_H +#define TR2_SID_H + +/* + * Get our session id. Compute if necessary. + */ +const char *tr2_sid_get(void); + +/* + * Get our process depth. A top-level git process invoked from the + * command line will have depth=0. A child git process will have + * depth=1 and so on. + */ +int tr2_sid_depth(void); + +void tr2_sid_release(void); + +#endif /* TR2_SID_H */ diff --git a/trace2/tr2_sysenv.c b/trace2/tr2_sysenv.c new file mode 100644 index 0000000..a380dcf --- /dev/null +++ b/trace2/tr2_sysenv.c @@ -0,0 +1,132 @@ +#include "cache.h" +#include "config.h" +#include "dir.h" +#include "tr2_sysenv.h" + +/* + * Each entry represents a trace2 setting. + * See Documentation/technical/api-trace2.txt + */ +struct tr2_sysenv_entry { + const char *env_var_name; + const char *git_config_name; + + char *value; + unsigned int getenv_called : 1; +}; + +/* + * This table must match "enum tr2_sysenv_variable" in tr2_sysenv.h. + * + * The strings in this table are constant and must match the published + * config and environment variable names as described in the documentation. + * + * We do not define entries for the GIT_TRACE2_PARENT_* environment + * variables because they are transient and used to pass information + * from parent to child git processes, rather than settings. + */ +/* clang-format off */ +static struct tr2_sysenv_entry tr2_sysenv_settings[] = { + [TR2_SYSENV_CFG_PARAM] = { "GIT_TRACE2_CONFIG_PARAMS", + "trace2.configparams" }, + [TR2_SYSENV_ENV_VARS] = { "GIT_TRACE2_ENV_VARS", + "trace2.envvars" }, + + [TR2_SYSENV_DST_DEBUG] = { "GIT_TRACE2_DST_DEBUG", + "trace2.destinationdebug" }, + + [TR2_SYSENV_NORMAL] = { "GIT_TRACE2", + "trace2.normaltarget" }, + [TR2_SYSENV_NORMAL_BRIEF] = { "GIT_TRACE2_BRIEF", + "trace2.normalbrief" }, + + [TR2_SYSENV_EVENT] = { "GIT_TRACE2_EVENT", + "trace2.eventtarget" }, + [TR2_SYSENV_EVENT_BRIEF] = { "GIT_TRACE2_EVENT_BRIEF", + "trace2.eventbrief" }, + [TR2_SYSENV_EVENT_NESTING] = { "GIT_TRACE2_EVENT_NESTING", + "trace2.eventnesting" }, + + [TR2_SYSENV_PERF] = { "GIT_TRACE2_PERF", + "trace2.perftarget" }, + [TR2_SYSENV_PERF_BRIEF] = { "GIT_TRACE2_PERF_BRIEF", + "trace2.perfbrief" }, + + [TR2_SYSENV_MAX_FILES] = { "GIT_TRACE2_MAX_FILES", + "trace2.maxfiles" }, +}; +/* clang-format on */ + +static int tr2_sysenv_cb(const char *key, const char *value, void *d) +{ + int k; + + if (!starts_with(key, "trace2.")) + return 0; + + for (k = 0; k < ARRAY_SIZE(tr2_sysenv_settings); k++) { + if (!strcmp(key, tr2_sysenv_settings[k].git_config_name)) { + free(tr2_sysenv_settings[k].value); + tr2_sysenv_settings[k].value = xstrdup(value); + return 0; + } + } + + return 0; +} + +/* + * Load Trace2 settings from the system config (usually "/etc/gitconfig" + * unless we were built with a runtime-prefix). These are intended to + * define the default values for Trace2 as requested by the administrator. + * + * Then override with the Trace2 settings from the global config. + */ +void tr2_sysenv_load(void) +{ + if (ARRAY_SIZE(tr2_sysenv_settings) != TR2_SYSENV_MUST_BE_LAST) + BUG("tr2_sysenv_settings size is wrong"); + + read_very_early_config(tr2_sysenv_cb, NULL); +} + +/* + * Return the value for the requested Trace2 setting from these sources: + * the system config, the global config, and the environment. + */ +const char *tr2_sysenv_get(enum tr2_sysenv_variable var) +{ + if (var >= TR2_SYSENV_MUST_BE_LAST) + BUG("tr2_sysenv_get invalid var '%d'", var); + + if (!tr2_sysenv_settings[var].getenv_called) { + const char *v = getenv(tr2_sysenv_settings[var].env_var_name); + if (v && *v) { + free(tr2_sysenv_settings[var].value); + tr2_sysenv_settings[var].value = xstrdup(v); + } + tr2_sysenv_settings[var].getenv_called = 1; + } + + return tr2_sysenv_settings[var].value; +} + +/* + * Return a friendly name for this setting that is suitable for printing + * in an error messages. + */ +const char *tr2_sysenv_display_name(enum tr2_sysenv_variable var) +{ + if (var >= TR2_SYSENV_MUST_BE_LAST) + BUG("tr2_sysenv_get invalid var '%d'", var); + + return tr2_sysenv_settings[var].env_var_name; +} + +void tr2_sysenv_release(void) +{ + int k; + + for (k = 0; k < ARRAY_SIZE(tr2_sysenv_settings); k++) + free(tr2_sysenv_settings[k].value); +} diff --git a/trace2/tr2_sysenv.h b/trace2/tr2_sysenv.h new file mode 100644 index 0000000..3292ee1 --- /dev/null +++ b/trace2/tr2_sysenv.h @@ -0,0 +1,39 @@ +#ifndef TR2_SYSENV_H +#define TR2_SYSENV_H + +/* + * The Trace2 settings that can be loaded from /etc/gitconfig + * and/or user environment variables. + * + * Note that this set does not contain any of the transient + * environment variables used to pass information from parent + * to child git processes, such "GIT_TRACE2_PARENT_SID". + */ +enum tr2_sysenv_variable { + TR2_SYSENV_CFG_PARAM = 0, + TR2_SYSENV_ENV_VARS, + + TR2_SYSENV_DST_DEBUG, + + TR2_SYSENV_NORMAL, + TR2_SYSENV_NORMAL_BRIEF, + + TR2_SYSENV_EVENT, + TR2_SYSENV_EVENT_BRIEF, + TR2_SYSENV_EVENT_NESTING, + + TR2_SYSENV_PERF, + TR2_SYSENV_PERF_BRIEF, + + TR2_SYSENV_MAX_FILES, + + TR2_SYSENV_MUST_BE_LAST +}; + +void tr2_sysenv_load(void); + +const char *tr2_sysenv_get(enum tr2_sysenv_variable); +const char *tr2_sysenv_display_name(enum tr2_sysenv_variable var); +void tr2_sysenv_release(void); + +#endif /* TR2_SYSENV_H */ diff --git a/trace2/tr2_tbuf.c b/trace2/tr2_tbuf.c new file mode 100644 index 0000000..2498482 --- /dev/null +++ b/trace2/tr2_tbuf.c @@ -0,0 +1,47 @@ +#include "cache.h" +#include "tr2_tbuf.h" + +void tr2_tbuf_local_time(struct tr2_tbuf *tb) +{ + struct timeval tv; + struct tm tm; + time_t secs; + + gettimeofday(&tv, NULL); + secs = tv.tv_sec; + localtime_r(&secs, &tm); + + xsnprintf(tb->buf, sizeof(tb->buf), "%02d:%02d:%02d.%06ld", tm.tm_hour, + tm.tm_min, tm.tm_sec, (long)tv.tv_usec); +} + +void tr2_tbuf_utc_datetime_extended(struct tr2_tbuf *tb) +{ + struct timeval tv; + struct tm tm; + time_t secs; + + gettimeofday(&tv, NULL); + secs = tv.tv_sec; + gmtime_r(&secs, &tm); + + xsnprintf(tb->buf, sizeof(tb->buf), + "%4d-%02d-%02dT%02d:%02d:%02d.%06ldZ", tm.tm_year + 1900, + tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec, + (long)tv.tv_usec); +} + +void tr2_tbuf_utc_datetime(struct tr2_tbuf *tb) +{ + struct timeval tv; + struct tm tm; + time_t secs; + + gettimeofday(&tv, NULL); + secs = tv.tv_sec; + gmtime_r(&secs, &tm); + + xsnprintf(tb->buf, sizeof(tb->buf), "%4d%02d%02dT%02d%02d%02d.%06ldZ", + tm.tm_year + 1900, tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, + tm.tm_min, tm.tm_sec, (long)tv.tv_usec); +} diff --git a/trace2/tr2_tbuf.h b/trace2/tr2_tbuf.h new file mode 100644 index 0000000..fa853d8 --- /dev/null +++ b/trace2/tr2_tbuf.h @@ -0,0 +1,24 @@ +#ifndef TR2_TBUF_H +#define TR2_TBUF_H + +/* + * A simple wrapper around a fixed buffer to avoid C syntax + * quirks and the need to pass around an additional size_t + * argument. + */ +struct tr2_tbuf { + char buf[32]; +}; + +/* + * Fill buffer with formatted local time string. + */ +void tr2_tbuf_local_time(struct tr2_tbuf *tb); + +/* + * Fill buffer with formatted UTC datatime string. + */ +void tr2_tbuf_utc_datetime_extended(struct tr2_tbuf *tb); +void tr2_tbuf_utc_datetime(struct tr2_tbuf *tb); + +#endif /* TR2_TBUF_H */ diff --git a/trace2/tr2_tgt.h b/trace2/tr2_tgt.h new file mode 100644 index 0000000..bf8745c --- /dev/null +++ b/trace2/tr2_tgt.h @@ -0,0 +1,158 @@ +#ifndef TR2_TGT_H +#define TR2_TGT_H + +struct child_process; +struct repository; +struct json_writer; +struct tr2_timer_metadata; +struct tr2_timer; +struct tr2_counter_metadata; +struct tr2_counter; + +#define NS_TO_SEC(ns) ((double)(ns) / 1.0e9) + +/* + * Function prototypes for a TRACE2 "target" vtable. + */ + +typedef int(tr2_tgt_init_t)(void); +typedef void(tr2_tgt_term_t)(void); + +typedef void(tr2_tgt_evt_version_fl_t)(const char *file, int line); + +typedef void(tr2_tgt_evt_start_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + const char **argv); +typedef void(tr2_tgt_evt_exit_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, int code); +typedef void(tr2_tgt_evt_signal_t)(uint64_t us_elapsed_absolute, int signo); +typedef void(tr2_tgt_evt_atexit_t)(uint64_t us_elapsed_absolute, int code); + +typedef void(tr2_tgt_evt_error_va_fl_t)(const char *file, int line, + const char *fmt, va_list ap); + +typedef void(tr2_tgt_evt_command_path_fl_t)(const char *file, int line, + const char *command_path); +typedef void(tr2_tgt_evt_command_ancestry_fl_t)(const char *file, int line, + const char **parent_names); +typedef void(tr2_tgt_evt_command_name_fl_t)(const char *file, int line, + const char *name, + const char *hierarchy); +typedef void(tr2_tgt_evt_command_mode_fl_t)(const char *file, int line, + const char *mode); + +typedef void(tr2_tgt_evt_alias_fl_t)(const char *file, int line, + const char *alias, const char **argv); + +typedef void(tr2_tgt_evt_child_start_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + const struct child_process *cmd); +typedef void(tr2_tgt_evt_child_exit_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, + int pid, int code, + uint64_t us_elapsed_child); +typedef void(tr2_tgt_evt_child_ready_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + int cid, int pid, const char *ready, + uint64_t us_elapsed_child); + +typedef void(tr2_tgt_evt_thread_start_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute); +typedef void(tr2_tgt_evt_thread_exit_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_thread); + +typedef void(tr2_tgt_evt_exec_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, int exec_id, + const char *exe, const char **argv); +typedef void(tr2_tgt_evt_exec_result_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + int exec_id, int code); + +typedef void(tr2_tgt_evt_param_fl_t)(const char *file, int line, + const char *param, const char *value); + +typedef void(tr2_tgt_evt_repo_fl_t)(const char *file, int line, + const struct repository *repo); + +typedef void(tr2_tgt_evt_region_enter_printf_va_fl_t)( + const char *file, int line, uint64_t us_elapsed_absolute, + const char *category, const char *label, const struct repository *repo, + const char *fmt, va_list ap); +typedef void(tr2_tgt_evt_region_leave_printf_va_fl_t)( + const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, const char *label, + const struct repository *repo, const char *fmt, va_list ap); + +typedef void(tr2_tgt_evt_data_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, + const char *category, + const struct repository *repo, + const char *key, const char *value); +typedef void(tr2_tgt_evt_data_json_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, + const char *category, + const struct repository *repo, + const char *key, + const struct json_writer *value); + +typedef void(tr2_tgt_evt_printf_va_fl_t)(const char *file, int line, + uint64_t us_elapsed_absolute, + const char *fmt, va_list ap); + +typedef void(tr2_tgt_evt_timer_t)(const struct tr2_timer_metadata *meta, + const struct tr2_timer *timer, + int is_final_data); + +typedef void(tr2_tgt_evt_counter_t)(const struct tr2_counter_metadata *meta, + const struct tr2_counter *counter, + int is_final_data); + +/* + * "vtable" for a TRACE2 target. Use NULL if a target does not want + * to emit that message. + */ +/* clang-format off */ +struct tr2_tgt { + struct tr2_dst *pdst; + + tr2_tgt_init_t *pfn_init; + tr2_tgt_term_t *pfn_term; + + tr2_tgt_evt_version_fl_t *pfn_version_fl; + tr2_tgt_evt_start_fl_t *pfn_start_fl; + tr2_tgt_evt_exit_fl_t *pfn_exit_fl; + tr2_tgt_evt_signal_t *pfn_signal; + tr2_tgt_evt_atexit_t *pfn_atexit; + tr2_tgt_evt_error_va_fl_t *pfn_error_va_fl; + tr2_tgt_evt_command_path_fl_t *pfn_command_path_fl; + tr2_tgt_evt_command_ancestry_fl_t *pfn_command_ancestry_fl; + tr2_tgt_evt_command_name_fl_t *pfn_command_name_fl; + tr2_tgt_evt_command_mode_fl_t *pfn_command_mode_fl; + tr2_tgt_evt_alias_fl_t *pfn_alias_fl; + tr2_tgt_evt_child_start_fl_t *pfn_child_start_fl; + tr2_tgt_evt_child_exit_fl_t *pfn_child_exit_fl; + tr2_tgt_evt_child_ready_fl_t *pfn_child_ready_fl; + tr2_tgt_evt_thread_start_fl_t *pfn_thread_start_fl; + tr2_tgt_evt_thread_exit_fl_t *pfn_thread_exit_fl; + tr2_tgt_evt_exec_fl_t *pfn_exec_fl; + tr2_tgt_evt_exec_result_fl_t *pfn_exec_result_fl; + tr2_tgt_evt_param_fl_t *pfn_param_fl; + tr2_tgt_evt_repo_fl_t *pfn_repo_fl; + tr2_tgt_evt_region_enter_printf_va_fl_t *pfn_region_enter_printf_va_fl; + tr2_tgt_evt_region_leave_printf_va_fl_t *pfn_region_leave_printf_va_fl; + tr2_tgt_evt_data_fl_t *pfn_data_fl; + tr2_tgt_evt_data_json_fl_t *pfn_data_json_fl; + tr2_tgt_evt_printf_va_fl_t *pfn_printf_va_fl; + tr2_tgt_evt_timer_t *pfn_timer; + tr2_tgt_evt_counter_t *pfn_counter; +}; +/* clang-format on */ + +extern struct tr2_tgt tr2_tgt_event; +extern struct tr2_tgt tr2_tgt_normal; +extern struct tr2_tgt tr2_tgt_perf; + +#endif /* TR2_TGT_H */ diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c new file mode 100644 index 0000000..16f6332 --- /dev/null +++ b/trace2/tr2_tgt_event.c @@ -0,0 +1,696 @@ +#include "cache.h" +#include "config.h" +#include "json-writer.h" +#include "run-command.h" +#include "version.h" +#include "trace2/tr2_dst.h" +#include "trace2/tr2_tbuf.h" +#include "trace2/tr2_sid.h" +#include "trace2/tr2_sysenv.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" +#include "trace2/tr2_tmr.h" + +static struct tr2_dst tr2dst_event = { + .sysenv_var = TR2_SYSENV_EVENT, +}; + +/* + * The version number of the JSON data generated by the EVENT target in this + * source file. The version should be incremented if new event types are added, + * if existing fields are removed, or if there are significant changes in + * interpretation of existing events or fields. Smaller changes, such as adding + * a new field to an existing event, do not require an increment to the EVENT + * format version. + */ +#define TR2_EVENT_VERSION "3" + +/* + * Region nesting limit for messages written to the event target. + * + * The "region_enter" and "region_leave" messages (especially recursive + * messages such as those produced while diving the worktree or index) + * are primarily intended for the performance target during debugging. + * + * Some of the outer-most messages, however, may be of interest to the + * event target. Use the TR2_SYSENV_EVENT_NESTING setting to increase + * region details in the event target. + */ +static int tr2env_event_max_nesting_levels = 2; + +/* + * Use the TR2_SYSENV_EVENT_BRIEF to omit the <time>, <file>, and + * <line> fields from most events. + */ +static int tr2env_event_be_brief; + +static int fn_init(void) +{ + int want = tr2_dst_trace_want(&tr2dst_event); + int max_nesting; + int want_brief; + const char *nesting; + const char *brief; + + if (!want) + return want; + + nesting = tr2_sysenv_get(TR2_SYSENV_EVENT_NESTING); + if (nesting && *nesting && ((max_nesting = atoi(nesting)) > 0)) + tr2env_event_max_nesting_levels = max_nesting; + + brief = tr2_sysenv_get(TR2_SYSENV_EVENT_BRIEF); + if (brief && *brief && + ((want_brief = git_parse_maybe_bool(brief)) != -1)) + tr2env_event_be_brief = want_brief; + + return want; +} + +static void fn_term(void) +{ + tr2_dst_trace_disable(&tr2dst_event); +} + +/* + * Append common key-value pairs to the currently open JSON object. + * "event:"<event_name>" + * "sid":"<sid>" + * "thread":"<thread_name>" + * "time":"<time>" + * "file":"<filename>" + * "line":<line_number> + * "repo":<repo_id> + */ +static void event_fmt_prepare(const char *event_name, const char *file, + int line, const struct repository *repo, + struct json_writer *jw) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + struct tr2_tbuf tb_now; + + jw_object_string(jw, "event", event_name); + jw_object_string(jw, "sid", tr2_sid_get()); + jw_object_string(jw, "thread", ctx->thread_name); + + /* + * In brief mode, only emit <time> on these 2 event types. + */ + if (!tr2env_event_be_brief || !strcmp(event_name, "version") || + !strcmp(event_name, "atexit")) { + tr2_tbuf_utc_datetime_extended(&tb_now); + jw_object_string(jw, "time", tb_now.buf); + } + + if (!tr2env_event_be_brief && file && *file) { + jw_object_string(jw, "file", file); + jw_object_intmax(jw, "line", line); + } + + if (repo) + jw_object_intmax(jw, "repo", repo->trace2_repo_id); +} + +static void fn_too_many_files_fl(const char *file, int line) +{ + const char *event_name = "too_many_files"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_version_fl(const char *file, int line) +{ + const char *event_name = "version"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "evt", TR2_EVENT_VERSION); + jw_object_string(&jw, "exe", git_version_string); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); + + if (tr2dst_event.too_many_files) + fn_too_many_files_fl(file, line); +} + +static void fn_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, const char **argv) +{ + const char *event_name = "start"; + struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_inline_begin_array(&jw, "argv"); + jw_array_argv(&jw, argv); + jw_end(&jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int code) +{ + const char *event_name = "exit"; + struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_intmax(&jw, "code", code); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_signal(uint64_t us_elapsed_absolute, int signo) +{ + const char *event_name = "signal"; + struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_intmax(&jw, "signo", signo); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_atexit(uint64_t us_elapsed_absolute, int code) +{ + const char *event_name = "atexit"; + struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_intmax(&jw, "code", code); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void maybe_add_string_va(struct json_writer *jw, const char *field_name, + const char *fmt, va_list ap) +{ + if (fmt && *fmt) { + va_list copy_ap; + struct strbuf buf = STRBUF_INIT; + + va_copy(copy_ap, ap); + strbuf_vaddf(&buf, fmt, copy_ap); + va_end(copy_ap); + + jw_object_string(jw, field_name, buf.buf); + strbuf_release(&buf); + return; + } +} + +static void fn_error_va_fl(const char *file, int line, const char *fmt, + va_list ap) +{ + const char *event_name = "error"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + maybe_add_string_va(&jw, "msg", fmt, ap); + /* + * Also emit the format string as a field in case + * post-processors want to aggregate common error + * messages by type without argument fields (such + * as pathnames or branch names) cluttering it up. + */ + if (fmt && *fmt) + jw_object_string(&jw, "fmt", fmt); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_command_path_fl(const char *file, int line, const char *pathname) +{ + const char *event_name = "cmd_path"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "path", pathname); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_command_ancestry_fl(const char *file, int line, const char **parent_names) +{ + const char *event_name = "cmd_ancestry"; + const char *parent_name = NULL; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_inline_begin_array(&jw, "ancestry"); + + while ((parent_name = *parent_names++)) + jw_array_string(&jw, parent_name); + + jw_end(&jw); /* 'ancestry' array */ + jw_end(&jw); /* event object */ + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_command_name_fl(const char *file, int line, const char *name, + const char *hierarchy) +{ + const char *event_name = "cmd_name"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "name", name); + if (hierarchy && *hierarchy) + jw_object_string(&jw, "hierarchy", hierarchy); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_command_mode_fl(const char *file, int line, const char *mode) +{ + const char *event_name = "cmd_mode"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "name", mode); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_alias_fl(const char *file, int line, const char *alias, + const char **argv) +{ + const char *event_name = "alias"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "alias", alias); + jw_object_inline_begin_array(&jw, "argv"); + jw_array_argv(&jw, argv); + jw_end(&jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_child_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const struct child_process *cmd) +{ + const char *event_name = "child_start"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_intmax(&jw, "child_id", cmd->trace2_child_id); + if (cmd->trace2_hook_name) { + jw_object_string(&jw, "child_class", "hook"); + jw_object_string(&jw, "hook_name", cmd->trace2_hook_name); + } else { + const char *child_class = + cmd->trace2_child_class ? cmd->trace2_child_class : "?"; + jw_object_string(&jw, "child_class", child_class); + } + if (cmd->dir) + jw_object_string(&jw, "cd", cmd->dir); + jw_object_bool(&jw, "use_shell", cmd->use_shell); + jw_object_inline_begin_array(&jw, "argv"); + if (cmd->git_cmd) + jw_array_string(&jw, "git"); + jw_array_argv(&jw, cmd->args.v); + jw_end(&jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_child_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, int pid, + int code, uint64_t us_elapsed_child) +{ + const char *event_name = "child_exit"; + struct json_writer jw = JSON_WRITER_INIT; + double t_rel = (double)us_elapsed_child / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_intmax(&jw, "child_id", cid); + jw_object_intmax(&jw, "pid", pid); + jw_object_intmax(&jw, "code", code); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + + jw_release(&jw); +} + +static void fn_child_ready_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, int pid, + const char *ready, uint64_t us_elapsed_child) +{ + const char *event_name = "child_ready"; + struct json_writer jw = JSON_WRITER_INIT; + double t_rel = (double)us_elapsed_child / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_intmax(&jw, "child_id", cid); + jw_object_intmax(&jw, "pid", pid); + jw_object_string(&jw, "ready", ready); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + + jw_release(&jw); +} + +static void fn_thread_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute) +{ + const char *event_name = "thread_start"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_thread_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_thread) +{ + const char *event_name = "thread_exit"; + struct json_writer jw = JSON_WRITER_INIT; + double t_rel = (double)us_elapsed_thread / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int exec_id, const char *exe, const char **argv) +{ + const char *event_name = "exec"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_intmax(&jw, "exec_id", exec_id); + if (exe) + jw_object_string(&jw, "exe", exe); + jw_object_inline_begin_array(&jw, "argv"); + jw_array_argv(&jw, argv); + jw_end(&jw); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_exec_result_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int exec_id, + int code) +{ + const char *event_name = "exec_result"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_intmax(&jw, "exec_id", exec_id); + jw_object_intmax(&jw, "code", code); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_param_fl(const char *file, int line, const char *param, + const char *value) +{ + const char *event_name = "def_param"; + struct json_writer jw = JSON_WRITER_INIT; + enum config_scope scope = current_config_scope(); + const char *scope_name = config_scope_name(scope); + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, NULL, &jw); + jw_object_string(&jw, "scope", scope_name); + jw_object_string(&jw, "param", param); + jw_object_string(&jw, "value", value); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_repo_fl(const char *file, int line, + const struct repository *repo) +{ + const char *event_name = "def_repo"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_string(&jw, "worktree", repo->worktree); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_region_enter_printf_va_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const char *category, + const char *label, + const struct repository *repo, + const char *fmt, va_list ap) +{ + const char *event_name = "region_enter"; + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + if (ctx->nr_open_regions <= tr2env_event_max_nesting_levels) { + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_intmax(&jw, "nesting", ctx->nr_open_regions); + if (category) + jw_object_string(&jw, "category", category); + if (label) + jw_object_string(&jw, "label", label); + maybe_add_string_va(&jw, "msg", fmt, ap); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); + } +} + +static void fn_region_leave_printf_va_fl( + const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, const char *label, + const struct repository *repo, const char *fmt, va_list ap) +{ + const char *event_name = "region_leave"; + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + if (ctx->nr_open_regions <= tr2env_event_max_nesting_levels) { + struct json_writer jw = JSON_WRITER_INIT; + double t_rel = (double)us_elapsed_region / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_object_intmax(&jw, "nesting", ctx->nr_open_regions); + if (category) + jw_object_string(&jw, "category", category); + if (label) + jw_object_string(&jw, "label", label); + maybe_add_string_va(&jw, "msg", fmt, ap); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); + } +} + +static void fn_data_fl(const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, + const struct repository *repo, const char *key, + const char *value) +{ + const char *event_name = "data"; + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + if (ctx->nr_open_regions <= tr2env_event_max_nesting_levels) { + struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; + double t_rel = (double)us_elapsed_region / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_object_intmax(&jw, "nesting", ctx->nr_open_regions); + jw_object_string(&jw, "category", category); + jw_object_string(&jw, "key", key); + jw_object_string(&jw, "value", value); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); + } +} + +static void fn_data_json_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, + const struct repository *repo, const char *key, + const struct json_writer *value) +{ + const char *event_name = "data_json"; + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + if (ctx->nr_open_regions <= tr2env_event_max_nesting_levels) { + struct json_writer jw = JSON_WRITER_INIT; + double t_abs = (double)us_elapsed_absolute / 1000000.0; + double t_rel = (double)us_elapsed_region / 1000000.0; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, file, line, repo, &jw); + jw_object_double(&jw, "t_abs", 6, t_abs); + jw_object_double(&jw, "t_rel", 6, t_rel); + jw_object_intmax(&jw, "nesting", ctx->nr_open_regions); + jw_object_string(&jw, "category", category); + jw_object_string(&jw, "key", key); + jw_object_sub_jw(&jw, "value", value); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); + } +} + +static void fn_timer(const struct tr2_timer_metadata *meta, + const struct tr2_timer *timer, + int is_final_data) +{ + const char *event_name = is_final_data ? "timer" : "th_timer"; + struct json_writer jw = JSON_WRITER_INIT; + double t_total = NS_TO_SEC(timer->total_ns); + double t_min = NS_TO_SEC(timer->min_ns); + double t_max = NS_TO_SEC(timer->max_ns); + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw); + jw_object_string(&jw, "category", meta->category); + jw_object_string(&jw, "name", meta->name); + jw_object_intmax(&jw, "intervals", timer->interval_count); + jw_object_double(&jw, "t_total", 6, t_total); + jw_object_double(&jw, "t_min", 6, t_min); + jw_object_double(&jw, "t_max", 6, t_max); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +static void fn_counter(const struct tr2_counter_metadata *meta, + const struct tr2_counter *counter, + int is_final_data) +{ + const char *event_name = is_final_data ? "counter" : "th_counter"; + struct json_writer jw = JSON_WRITER_INIT; + + jw_object_begin(&jw, 0); + event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw); + jw_object_string(&jw, "category", meta->category); + jw_object_string(&jw, "name", meta->name); + jw_object_intmax(&jw, "count", counter->value); + jw_end(&jw); + + tr2_dst_write_line(&tr2dst_event, &jw.json); + jw_release(&jw); +} + +struct tr2_tgt tr2_tgt_event = { + .pdst = &tr2dst_event, + + .pfn_init = fn_init, + .pfn_term = fn_term, + + .pfn_version_fl = fn_version_fl, + .pfn_start_fl = fn_start_fl, + .pfn_exit_fl = fn_exit_fl, + .pfn_signal = fn_signal, + .pfn_atexit = fn_atexit, + .pfn_error_va_fl = fn_error_va_fl, + .pfn_command_path_fl = fn_command_path_fl, + .pfn_command_ancestry_fl = fn_command_ancestry_fl, + .pfn_command_name_fl = fn_command_name_fl, + .pfn_command_mode_fl = fn_command_mode_fl, + .pfn_alias_fl = fn_alias_fl, + .pfn_child_start_fl = fn_child_start_fl, + .pfn_child_exit_fl = fn_child_exit_fl, + .pfn_child_ready_fl = fn_child_ready_fl, + .pfn_thread_start_fl = fn_thread_start_fl, + .pfn_thread_exit_fl = fn_thread_exit_fl, + .pfn_exec_fl = fn_exec_fl, + .pfn_exec_result_fl = fn_exec_result_fl, + .pfn_param_fl = fn_param_fl, + .pfn_repo_fl = fn_repo_fl, + .pfn_region_enter_printf_va_fl = fn_region_enter_printf_va_fl, + .pfn_region_leave_printf_va_fl = fn_region_leave_printf_va_fl, + .pfn_data_fl = fn_data_fl, + .pfn_data_json_fl = fn_data_json_fl, + .pfn_printf_va_fl = NULL, + .pfn_timer = fn_timer, + .pfn_counter = fn_counter, +}; diff --git a/trace2/tr2_tgt_normal.c b/trace2/tr2_tgt_normal.c new file mode 100644 index 0000000..fbbef68 --- /dev/null +++ b/trace2/tr2_tgt_normal.c @@ -0,0 +1,402 @@ +#include "cache.h" +#include "config.h" +#include "run-command.h" +#include "quote.h" +#include "version.h" +#include "trace2/tr2_dst.h" +#include "trace2/tr2_sysenv.h" +#include "trace2/tr2_tbuf.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" +#include "trace2/tr2_tmr.h" + +static struct tr2_dst tr2dst_normal = { + .sysenv_var = TR2_SYSENV_NORMAL, +}; + +/* + * Use the TR2_SYSENV_NORMAL_BRIEF setting to omit the "<time> <file>:<line>" + * fields from each line written to the builtin normal target. + * + * Unit tests may want to use this to help with testing. + */ +static int tr2env_normal_be_brief; + +#define TR2FMT_NORMAL_FL_WIDTH (50) + +static int fn_init(void) +{ + int want = tr2_dst_trace_want(&tr2dst_normal); + int want_brief; + const char *brief; + + if (!want) + return want; + + brief = tr2_sysenv_get(TR2_SYSENV_NORMAL_BRIEF); + if (brief && *brief && + ((want_brief = git_parse_maybe_bool(brief)) != -1)) + tr2env_normal_be_brief = want_brief; + + return want; +} + +static void fn_term(void) +{ + tr2_dst_trace_disable(&tr2dst_normal); +} + +static void normal_fmt_prepare(const char *file, int line, struct strbuf *buf) +{ + strbuf_setlen(buf, 0); + + if (!tr2env_normal_be_brief) { + struct tr2_tbuf tb_now; + + tr2_tbuf_local_time(&tb_now); + strbuf_addstr(buf, tb_now.buf); + strbuf_addch(buf, ' '); + + if (file && *file) + strbuf_addf(buf, "%s:%d ", file, line); + while (buf->len < TR2FMT_NORMAL_FL_WIDTH) + strbuf_addch(buf, ' '); + } +} + +static void normal_io_write_fl(const char *file, int line, + const struct strbuf *buf_payload) +{ + struct strbuf buf_line = STRBUF_INIT; + + normal_fmt_prepare(file, line, &buf_line); + strbuf_addbuf(&buf_line, buf_payload); + tr2_dst_write_line(&tr2dst_normal, &buf_line); + strbuf_release(&buf_line); +} + +static void fn_version_fl(const char *file, int line) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "version %s", git_version_string); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, const char **argv) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, "start "); + sq_append_quote_argv_pretty(&buf_payload, argv); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int code) +{ + struct strbuf buf_payload = STRBUF_INIT; + double elapsed = (double)us_elapsed_absolute / 1000000.0; + + strbuf_addf(&buf_payload, "exit elapsed:%.6f code:%d", elapsed, code); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_signal(uint64_t us_elapsed_absolute, int signo) +{ + struct strbuf buf_payload = STRBUF_INIT; + double elapsed = (double)us_elapsed_absolute / 1000000.0; + + strbuf_addf(&buf_payload, "signal elapsed:%.6f code:%d", elapsed, + signo); + normal_io_write_fl(__FILE__, __LINE__, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_atexit(uint64_t us_elapsed_absolute, int code) +{ + struct strbuf buf_payload = STRBUF_INIT; + double elapsed = (double)us_elapsed_absolute / 1000000.0; + + strbuf_addf(&buf_payload, "atexit elapsed:%.6f code:%d", elapsed, code); + normal_io_write_fl(__FILE__, __LINE__, &buf_payload); + strbuf_release(&buf_payload); +} + +static void maybe_append_string_va(struct strbuf *buf, const char *fmt, + va_list ap) +{ + if (fmt && *fmt) { + va_list copy_ap; + + va_copy(copy_ap, ap); + strbuf_vaddf(buf, fmt, copy_ap); + va_end(copy_ap); + return; + } +} + +static void fn_error_va_fl(const char *file, int line, const char *fmt, + va_list ap) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, "error"); + if (fmt && *fmt) { + strbuf_addch(&buf_payload, ' '); + maybe_append_string_va(&buf_payload, fmt, ap); + } + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_path_fl(const char *file, int line, const char *pathname) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "cmd_path %s", pathname); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_ancestry_fl(const char *file, int line, const char **parent_names) +{ + const char *parent_name = NULL; + struct strbuf buf_payload = STRBUF_INIT; + + /* cmd_ancestry parent <- grandparent <- great-grandparent */ + strbuf_addstr(&buf_payload, "cmd_ancestry "); + while ((parent_name = *parent_names++)) { + strbuf_addstr(&buf_payload, parent_name); + /* if we'll write another one after this, add a delimiter */ + if (parent_names && *parent_names) + strbuf_addstr(&buf_payload, " <- "); + } + + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_name_fl(const char *file, int line, const char *name, + const char *hierarchy) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "cmd_name %s", name); + if (hierarchy && *hierarchy) + strbuf_addf(&buf_payload, " (%s)", hierarchy); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_mode_fl(const char *file, int line, const char *mode) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "cmd_mode %s", mode); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_alias_fl(const char *file, int line, const char *alias, + const char **argv) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "alias %s -> ", alias); + sq_append_quote_argv_pretty(&buf_payload, argv); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const struct child_process *cmd) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "child_start[%d]", cmd->trace2_child_id); + + if (cmd->dir) { + strbuf_addstr(&buf_payload, " cd "); + sq_quote_buf_pretty(&buf_payload, cmd->dir); + strbuf_addstr(&buf_payload, ";"); + } + + /* + * TODO if (cmd->env) { Consider dumping changes to environment. } + * See trace_add_env() in run-command.c as used by original trace.c + */ + + strbuf_addch(&buf_payload, ' '); + if (cmd->git_cmd) + strbuf_addstr(&buf_payload, "git "); + sq_append_quote_argv_pretty(&buf_payload, cmd->args.v); + + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, int pid, + int code, uint64_t us_elapsed_child) +{ + struct strbuf buf_payload = STRBUF_INIT; + double elapsed = (double)us_elapsed_child / 1000000.0; + + strbuf_addf(&buf_payload, "child_exit[%d] pid:%d code:%d elapsed:%.6f", + cid, pid, code, elapsed); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_ready_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, int pid, + const char *ready, uint64_t us_elapsed_child) +{ + struct strbuf buf_payload = STRBUF_INIT; + double elapsed = (double)us_elapsed_child / 1000000.0; + + strbuf_addf(&buf_payload, "child_ready[%d] pid:%d ready:%s elapsed:%.6f", + cid, pid, ready, elapsed); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int exec_id, const char *exe, const char **argv) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "exec[%d] ", exec_id); + if (exe) { + strbuf_addstr(&buf_payload, exe); + strbuf_addch(&buf_payload, ' '); + } + sq_append_quote_argv_pretty(&buf_payload, argv); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exec_result_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int exec_id, + int code) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "exec_result[%d] code:%d", exec_id, code); + if (code > 0) + strbuf_addf(&buf_payload, " err:%s", strerror(code)); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_param_fl(const char *file, int line, const char *param, + const char *value) +{ + struct strbuf buf_payload = STRBUF_INIT; + enum config_scope scope = current_config_scope(); + const char *scope_name = config_scope_name(scope); + + strbuf_addf(&buf_payload, "def_param scope:%s %s=%s", scope_name, param, + value); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_repo_fl(const char *file, int line, + const struct repository *repo) +{ + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, "worktree "); + sq_quote_buf_pretty(&buf_payload, repo->worktree); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_printf_va_fl(const char *file, int line, + uint64_t us_elapsed_absolute, const char *fmt, + va_list ap) +{ + struct strbuf buf_payload = STRBUF_INIT; + + maybe_append_string_va(&buf_payload, fmt, ap); + normal_io_write_fl(file, line, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_timer(const struct tr2_timer_metadata *meta, + const struct tr2_timer *timer, + int is_final_data) +{ + const char *event_name = is_final_data ? "timer" : "th_timer"; + struct strbuf buf_payload = STRBUF_INIT; + double t_total = NS_TO_SEC(timer->total_ns); + double t_min = NS_TO_SEC(timer->min_ns); + double t_max = NS_TO_SEC(timer->max_ns); + + strbuf_addf(&buf_payload, ("%s %s/%s" + " intervals:%"PRIu64 + " total:%8.6f min:%8.6f max:%8.6f"), + event_name, meta->category, meta->name, + timer->interval_count, + t_total, t_min, t_max); + + normal_io_write_fl(__FILE__, __LINE__, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_counter(const struct tr2_counter_metadata *meta, + const struct tr2_counter *counter, + int is_final_data) +{ + const char *event_name = is_final_data ? "counter" : "th_counter"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "%s %s/%s value:%"PRIu64, + event_name, meta->category, meta->name, + counter->value); + + normal_io_write_fl(__FILE__, __LINE__, &buf_payload); + strbuf_release(&buf_payload); +} + +struct tr2_tgt tr2_tgt_normal = { + .pdst = &tr2dst_normal, + + .pfn_init = fn_init, + .pfn_term = fn_term, + + .pfn_version_fl = fn_version_fl, + .pfn_start_fl = fn_start_fl, + .pfn_exit_fl = fn_exit_fl, + .pfn_signal = fn_signal, + .pfn_atexit = fn_atexit, + .pfn_error_va_fl = fn_error_va_fl, + .pfn_command_path_fl = fn_command_path_fl, + .pfn_command_ancestry_fl = fn_command_ancestry_fl, + .pfn_command_name_fl = fn_command_name_fl, + .pfn_command_mode_fl = fn_command_mode_fl, + .pfn_alias_fl = fn_alias_fl, + .pfn_child_start_fl = fn_child_start_fl, + .pfn_child_exit_fl = fn_child_exit_fl, + .pfn_child_ready_fl = fn_child_ready_fl, + .pfn_thread_start_fl = NULL, + .pfn_thread_exit_fl = NULL, + .pfn_exec_fl = fn_exec_fl, + .pfn_exec_result_fl = fn_exec_result_fl, + .pfn_param_fl = fn_param_fl, + .pfn_repo_fl = fn_repo_fl, + .pfn_region_enter_printf_va_fl = NULL, + .pfn_region_leave_printf_va_fl = NULL, + .pfn_data_fl = NULL, + .pfn_data_json_fl = NULL, + .pfn_printf_va_fl = fn_printf_va_fl, + .pfn_timer = fn_timer, + .pfn_counter = fn_counter, +}; diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c new file mode 100644 index 0000000..adae803 --- /dev/null +++ b/trace2/tr2_tgt_perf.c @@ -0,0 +1,630 @@ +#include "cache.h" +#include "config.h" +#include "run-command.h" +#include "quote.h" +#include "version.h" +#include "json-writer.h" +#include "trace2/tr2_dst.h" +#include "trace2/tr2_sid.h" +#include "trace2/tr2_sysenv.h" +#include "trace2/tr2_tbuf.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" +#include "trace2/tr2_tmr.h" + +static struct tr2_dst tr2dst_perf = { + .sysenv_var = TR2_SYSENV_PERF, +}; + +/* + * Use TR2_SYSENV_PERF_BRIEF to omit the "<time> <file>:<line>" + * fields from each line written to the builtin performance target. + * + * Unit tests may want to use this to help with testing. + */ +static int tr2env_perf_be_brief; + +#define TR2FMT_PERF_FL_WIDTH (28) +#define TR2FMT_PERF_MAX_EVENT_NAME (12) +#define TR2FMT_PERF_REPO_WIDTH (3) +#define TR2FMT_PERF_CATEGORY_WIDTH (12) + +#define TR2_INDENT (2) +#define TR2_INDENT_LENGTH(ctx) (((ctx)->nr_open_regions - 1) * TR2_INDENT) + +static int fn_init(void) +{ + int want = tr2_dst_trace_want(&tr2dst_perf); + int want_brief; + const char *brief; + + if (!want) + return want; + + brief = tr2_sysenv_get(TR2_SYSENV_PERF_BRIEF); + if (brief && *brief && + ((want_brief = git_parse_maybe_bool(brief)) != -1)) + tr2env_perf_be_brief = want_brief; + + return want; +} + +static void fn_term(void) +{ + tr2_dst_trace_disable(&tr2dst_perf); +} + +/* + * Format trace line prefix in human-readable classic format for + * the performance target: + * "[<time> [<file>:<line>] <bar>] <nr_parents> <bar> + * <thread_name> <bar> <event_name> <bar> [<repo>] <bar> + * [<elapsed_absolute>] [<elapsed_relative>] <bar> + * [<category>] <bar> [<dots>] " + */ +static void perf_fmt_prepare(const char *event_name, + struct tr2tls_thread_ctx *ctx, const char *file, + int line, const struct repository *repo, + uint64_t *p_us_elapsed_absolute, + uint64_t *p_us_elapsed_relative, + const char *category, struct strbuf *buf) +{ + int len; + + strbuf_setlen(buf, 0); + + if (!tr2env_perf_be_brief) { + struct tr2_tbuf tb_now; + size_t fl_end_col; + + tr2_tbuf_local_time(&tb_now); + strbuf_addstr(buf, tb_now.buf); + strbuf_addch(buf, ' '); + + fl_end_col = buf->len + TR2FMT_PERF_FL_WIDTH; + + if (file && *file) { + struct strbuf buf_fl = STRBUF_INIT; + + strbuf_addf(&buf_fl, "%s:%d", file, line); + + if (buf_fl.len <= TR2FMT_PERF_FL_WIDTH) + strbuf_addbuf(buf, &buf_fl); + else { + size_t avail = TR2FMT_PERF_FL_WIDTH - 3; + strbuf_addstr(buf, "..."); + strbuf_add(buf, + &buf_fl.buf[buf_fl.len - avail], + avail); + } + + strbuf_release(&buf_fl); + } + + while (buf->len < fl_end_col) + strbuf_addch(buf, ' '); + + strbuf_addstr(buf, " | "); + } + + strbuf_addf(buf, "d%d | ", tr2_sid_depth()); + strbuf_addf(buf, "%-*s | %-*s | ", TR2_MAX_THREAD_NAME, + ctx->thread_name, TR2FMT_PERF_MAX_EVENT_NAME, + event_name); + + len = buf->len + TR2FMT_PERF_REPO_WIDTH; + if (repo) + strbuf_addf(buf, "r%d ", repo->trace2_repo_id); + while (buf->len < len) + strbuf_addch(buf, ' '); + strbuf_addstr(buf, " | "); + + if (p_us_elapsed_absolute) + strbuf_addf(buf, "%9.6f | ", + ((double)(*p_us_elapsed_absolute)) / 1000000.0); + else + strbuf_addf(buf, "%9s | ", " "); + + if (p_us_elapsed_relative) + strbuf_addf(buf, "%9.6f | ", + ((double)(*p_us_elapsed_relative)) / 1000000.0); + else + strbuf_addf(buf, "%9s | ", " "); + + strbuf_addf(buf, "%-*.*s | ", TR2FMT_PERF_CATEGORY_WIDTH, + TR2FMT_PERF_CATEGORY_WIDTH, (category ? category : "")); + + if (ctx->nr_open_regions > 0) + strbuf_addchars(buf, '.', TR2_INDENT_LENGTH(ctx)); +} + +static void perf_io_write_fl(const char *file, int line, const char *event_name, + const struct repository *repo, + uint64_t *p_us_elapsed_absolute, + uint64_t *p_us_elapsed_relative, + const char *category, + const struct strbuf *buf_payload) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + struct strbuf buf_line = STRBUF_INIT; + + perf_fmt_prepare(event_name, ctx, file, line, repo, + p_us_elapsed_absolute, p_us_elapsed_relative, category, + &buf_line); + strbuf_addbuf(&buf_line, buf_payload); + tr2_dst_write_line(&tr2dst_perf, &buf_line); + strbuf_release(&buf_line); +} + +static void fn_version_fl(const char *file, int line) +{ + const char *event_name = "version"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, git_version_string); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, const char **argv) +{ + const char *event_name = "start"; + struct strbuf buf_payload = STRBUF_INIT; + + sq_append_quote_argv_pretty(&buf_payload, argv); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int code) +{ + const char *event_name = "exit"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "code:%d", code); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_signal(uint64_t us_elapsed_absolute, int signo) +{ + const char *event_name = "signal"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "signo:%d", signo); + + perf_io_write_fl(__FILE__, __LINE__, event_name, NULL, + &us_elapsed_absolute, NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_atexit(uint64_t us_elapsed_absolute, int code) +{ + const char *event_name = "atexit"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "code:%d", code); + + perf_io_write_fl(__FILE__, __LINE__, event_name, NULL, + &us_elapsed_absolute, NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void maybe_append_string_va(struct strbuf *buf, const char *fmt, + va_list ap) +{ + if (fmt && *fmt) { + va_list copy_ap; + + va_copy(copy_ap, ap); + strbuf_vaddf(buf, fmt, copy_ap); + va_end(copy_ap); + return; + } +} + +static void fn_error_va_fl(const char *file, int line, const char *fmt, + va_list ap) +{ + const char *event_name = "error"; + struct strbuf buf_payload = STRBUF_INIT; + + maybe_append_string_va(&buf_payload, fmt, ap); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_path_fl(const char *file, int line, const char *pathname) +{ + const char *event_name = "cmd_path"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, pathname); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_ancestry_fl(const char *file, int line, const char **parent_names) +{ + const char *event_name = "cmd_ancestry"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, "ancestry:["); + /* It's not an argv but the rules are basically the same. */ + sq_append_quote_argv_pretty(&buf_payload, parent_names); + strbuf_addch(&buf_payload, ']'); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_name_fl(const char *file, int line, const char *name, + const char *hierarchy) +{ + const char *event_name = "cmd_name"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, name); + if (hierarchy && *hierarchy) + strbuf_addf(&buf_payload, " (%s)", hierarchy); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_command_mode_fl(const char *file, int line, const char *mode) +{ + const char *event_name = "cmd_mode"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, mode); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_alias_fl(const char *file, int line, const char *alias, + const char **argv) +{ + const char *event_name = "alias"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "alias:%s argv:[", alias); + sq_append_quote_argv_pretty(&buf_payload, argv); + strbuf_addch(&buf_payload, ']'); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const struct child_process *cmd) +{ + const char *event_name = "child_start"; + struct strbuf buf_payload = STRBUF_INIT; + + if (cmd->trace2_hook_name) { + strbuf_addf(&buf_payload, "[ch%d] class:hook hook:%s", + cmd->trace2_child_id, cmd->trace2_hook_name); + } else { + const char *child_class = + cmd->trace2_child_class ? cmd->trace2_child_class : "?"; + strbuf_addf(&buf_payload, "[ch%d] class:%s", + cmd->trace2_child_id, child_class); + } + + if (cmd->dir) { + strbuf_addstr(&buf_payload, " cd:"); + sq_quote_buf_pretty(&buf_payload, cmd->dir); + } + + strbuf_addstr(&buf_payload, " argv:["); + if (cmd->git_cmd) { + strbuf_addstr(&buf_payload, "git"); + if (cmd->args.nr) + strbuf_addch(&buf_payload, ' '); + } + sq_append_quote_argv_pretty(&buf_payload, cmd->args.v); + strbuf_addch(&buf_payload, ']'); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, int pid, + int code, uint64_t us_elapsed_child) +{ + const char *event_name = "child_exit"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "[ch%d] pid:%d code:%d", cid, pid, code); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + &us_elapsed_child, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_child_ready_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int cid, int pid, + const char *ready, uint64_t us_elapsed_child) +{ + const char *event_name = "child_ready"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "[ch%d] pid:%d ready:%s", cid, pid, ready); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + &us_elapsed_child, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_thread_start_fl(const char *file, int line, + uint64_t us_elapsed_absolute) +{ + const char *event_name = "thread_start"; + struct strbuf buf_payload = STRBUF_INIT; + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_thread_exit_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_thread) +{ + const char *event_name = "thread_exit"; + struct strbuf buf_payload = STRBUF_INIT; + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + &us_elapsed_thread, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute, + int exec_id, const char *exe, const char **argv) +{ + const char *event_name = "exec"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "id:%d ", exec_id); + strbuf_addstr(&buf_payload, "argv:["); + if (exe) { + strbuf_addstr(&buf_payload, exe); + if (argv[0]) + strbuf_addch(&buf_payload, ' '); + } + sq_append_quote_argv_pretty(&buf_payload, argv); + strbuf_addch(&buf_payload, ']'); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_exec_result_fl(const char *file, int line, + uint64_t us_elapsed_absolute, int exec_id, + int code) +{ + const char *event_name = "exec_result"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "id:%d code:%d", exec_id, code); + if (code > 0) + strbuf_addf(&buf_payload, " err:%s", strerror(code)); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_param_fl(const char *file, int line, const char *param, + const char *value) +{ + const char *event_name = "def_param"; + struct strbuf buf_payload = STRBUF_INIT; + struct strbuf scope_payload = STRBUF_INIT; + enum config_scope scope = current_config_scope(); + const char *scope_name = config_scope_name(scope); + + strbuf_addf(&buf_payload, "%s:%s", param, value); + strbuf_addf(&scope_payload, "%s:%s", "scope", scope_name); + + perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, + scope_payload.buf, &buf_payload); + strbuf_release(&buf_payload); + strbuf_release(&scope_payload); +} + +static void fn_repo_fl(const char *file, int line, + const struct repository *repo) +{ + const char *event_name = "def_repo"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addstr(&buf_payload, "worktree:"); + sq_quote_buf_pretty(&buf_payload, repo->worktree); + + perf_io_write_fl(file, line, event_name, repo, NULL, NULL, NULL, + &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_region_enter_printf_va_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + const char *category, + const char *label, + const struct repository *repo, + const char *fmt, va_list ap) +{ + const char *event_name = "region_enter"; + struct strbuf buf_payload = STRBUF_INIT; + + if (label) + strbuf_addf(&buf_payload, "label:%s", label); + if (fmt && *fmt) { + strbuf_addch(&buf_payload, ' '); + maybe_append_string_va(&buf_payload, fmt, ap); + } + + perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute, + NULL, category, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_region_leave_printf_va_fl( + const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, const char *label, + const struct repository *repo, const char *fmt, va_list ap) +{ + const char *event_name = "region_leave"; + struct strbuf buf_payload = STRBUF_INIT; + + if (label) + strbuf_addf(&buf_payload, "label:%s", label); + if (fmt && *fmt) { + strbuf_addch(&buf_payload, ' ' ); + maybe_append_string_va(&buf_payload, fmt, ap); + } + + perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute, + &us_elapsed_region, category, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_data_fl(const char *file, int line, uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, + const struct repository *repo, const char *key, + const char *value) +{ + const char *event_name = "data"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "%s:%s", key, value); + + perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute, + &us_elapsed_region, category, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_data_json_fl(const char *file, int line, + uint64_t us_elapsed_absolute, + uint64_t us_elapsed_region, const char *category, + const struct repository *repo, const char *key, + const struct json_writer *value) +{ + const char *event_name = "data_json"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "%s:%s", key, value->json.buf); + + perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute, + &us_elapsed_region, category, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_printf_va_fl(const char *file, int line, + uint64_t us_elapsed_absolute, const char *fmt, + va_list ap) +{ + const char *event_name = "printf"; + struct strbuf buf_payload = STRBUF_INIT; + + maybe_append_string_va(&buf_payload, fmt, ap); + + perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute, + NULL, NULL, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_timer(const struct tr2_timer_metadata *meta, + const struct tr2_timer *timer, + int is_final_data) +{ + const char *event_name = is_final_data ? "timer" : "th_timer"; + struct strbuf buf_payload = STRBUF_INIT; + double t_total = NS_TO_SEC(timer->total_ns); + double t_min = NS_TO_SEC(timer->min_ns); + double t_max = NS_TO_SEC(timer->max_ns); + + strbuf_addf(&buf_payload, ("name:%s" + " intervals:%"PRIu64 + " total:%8.6f min:%8.6f max:%8.6f"), + meta->name, + timer->interval_count, + t_total, t_min, t_max); + + perf_io_write_fl(__FILE__, __LINE__, event_name, NULL, NULL, NULL, + meta->category, &buf_payload); + strbuf_release(&buf_payload); +} + +static void fn_counter(const struct tr2_counter_metadata *meta, + const struct tr2_counter *counter, + int is_final_data) +{ + const char *event_name = is_final_data ? "counter" : "th_counter"; + struct strbuf buf_payload = STRBUF_INIT; + + strbuf_addf(&buf_payload, "name:%s value:%"PRIu64, + meta->name, + counter->value); + + perf_io_write_fl(__FILE__, __LINE__, event_name, NULL, NULL, NULL, + meta->category, &buf_payload); + strbuf_release(&buf_payload); +} + +struct tr2_tgt tr2_tgt_perf = { + .pdst = &tr2dst_perf, + + .pfn_init = fn_init, + .pfn_term = fn_term, + + .pfn_version_fl = fn_version_fl, + .pfn_start_fl = fn_start_fl, + .pfn_exit_fl = fn_exit_fl, + .pfn_signal = fn_signal, + .pfn_atexit = fn_atexit, + .pfn_error_va_fl = fn_error_va_fl, + .pfn_command_path_fl = fn_command_path_fl, + .pfn_command_ancestry_fl = fn_command_ancestry_fl, + .pfn_command_name_fl = fn_command_name_fl, + .pfn_command_mode_fl = fn_command_mode_fl, + .pfn_alias_fl = fn_alias_fl, + .pfn_child_start_fl = fn_child_start_fl, + .pfn_child_exit_fl = fn_child_exit_fl, + .pfn_child_ready_fl = fn_child_ready_fl, + .pfn_thread_start_fl = fn_thread_start_fl, + .pfn_thread_exit_fl = fn_thread_exit_fl, + .pfn_exec_fl = fn_exec_fl, + .pfn_exec_result_fl = fn_exec_result_fl, + .pfn_param_fl = fn_param_fl, + .pfn_repo_fl = fn_repo_fl, + .pfn_region_enter_printf_va_fl = fn_region_enter_printf_va_fl, + .pfn_region_leave_printf_va_fl = fn_region_leave_printf_va_fl, + .pfn_data_fl = fn_data_fl, + .pfn_data_json_fl = fn_data_json_fl, + .pfn_printf_va_fl = fn_printf_va_fl, + .pfn_timer = fn_timer, + .pfn_counter = fn_counter, +}; diff --git a/trace2/tr2_tls.c b/trace2/tr2_tls.c new file mode 100644 index 0000000..04900bb --- /dev/null +++ b/trace2/tr2_tls.c @@ -0,0 +1,193 @@ +#include "cache.h" +#include "thread-utils.h" +#include "trace2/tr2_tls.h" + +/* + * Initialize size of the thread stack for nested regions. + * This is used to store nested region start times. Note that + * this stack is per-thread and not per-trace-key. + */ +#define TR2_REGION_NESTING_INITIAL_SIZE (100) + +static struct tr2tls_thread_ctx *tr2tls_thread_main; +static uint64_t tr2tls_us_start_process; + +static pthread_mutex_t tr2tls_mutex; +static pthread_key_t tr2tls_key; + +static int tr2_next_thread_id; /* modify under lock */ + +void tr2tls_start_process_clock(void) +{ + if (tr2tls_us_start_process) + return; + + /* + * Keep the absolute start time of the process (i.e. the main + * process) in a fixed variable since other threads need to + * access it. This allows them to do that without a lock on + * main thread's array data (because of reallocs). + */ + tr2tls_us_start_process = getnanotime() / 1000; +} + +struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_base_name, + uint64_t us_thread_start) +{ + struct tr2tls_thread_ctx *ctx = xcalloc(1, sizeof(*ctx)); + struct strbuf buf = STRBUF_INIT; + + /* + * Implicitly "tr2tls_push_self()" to capture the thread's start + * time in array_us_start[0]. For the main thread this gives us the + * application run time. + */ + ctx->alloc = TR2_REGION_NESTING_INITIAL_SIZE; + ctx->array_us_start = (uint64_t *)xcalloc(ctx->alloc, sizeof(uint64_t)); + ctx->array_us_start[ctx->nr_open_regions++] = us_thread_start; + + ctx->thread_id = tr2tls_locked_increment(&tr2_next_thread_id); + + strbuf_init(&buf, 0); + if (ctx->thread_id) + strbuf_addf(&buf, "th%02d:", ctx->thread_id); + strbuf_addstr(&buf, thread_base_name); + if (buf.len > TR2_MAX_THREAD_NAME) + strbuf_setlen(&buf, TR2_MAX_THREAD_NAME); + ctx->thread_name = strbuf_detach(&buf, NULL); + + pthread_setspecific(tr2tls_key, ctx); + + return ctx; +} + +struct tr2tls_thread_ctx *tr2tls_get_self(void) +{ + struct tr2tls_thread_ctx *ctx; + + if (!HAVE_THREADS) + return tr2tls_thread_main; + + ctx = pthread_getspecific(tr2tls_key); + + /* + * If the current thread's thread-proc did not call + * trace2_thread_start(), then the thread will not have any + * thread-local storage. Create it now and silently continue. + */ + if (!ctx) + ctx = tr2tls_create_self("unknown", getnanotime() / 1000); + + return ctx; +} + +int tr2tls_is_main_thread(void) +{ + if (!HAVE_THREADS) + return 1; + + return pthread_getspecific(tr2tls_key) == tr2tls_thread_main; +} + +void tr2tls_unset_self(void) +{ + struct tr2tls_thread_ctx *ctx; + + ctx = tr2tls_get_self(); + + pthread_setspecific(tr2tls_key, NULL); + + free((char *)ctx->thread_name); + free(ctx->array_us_start); + free(ctx); +} + +void tr2tls_push_self(uint64_t us_now) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + + ALLOC_GROW(ctx->array_us_start, ctx->nr_open_regions + 1, ctx->alloc); + ctx->array_us_start[ctx->nr_open_regions++] = us_now; +} + +void tr2tls_pop_self(void) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + + if (!ctx->nr_open_regions) + BUG("no open regions in thread '%s'", ctx->thread_name); + + ctx->nr_open_regions--; +} + +void tr2tls_pop_unwind_self(void) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + + while (ctx->nr_open_regions > 1) + tr2tls_pop_self(); +} + +uint64_t tr2tls_region_elasped_self(uint64_t us) +{ + struct tr2tls_thread_ctx *ctx; + uint64_t us_start; + + ctx = tr2tls_get_self(); + if (!ctx->nr_open_regions) + return 0; + + us_start = ctx->array_us_start[ctx->nr_open_regions - 1]; + + return us - us_start; +} + +uint64_t tr2tls_absolute_elapsed(uint64_t us) +{ + if (!tr2tls_thread_main) + return 0; + + return us - tr2tls_us_start_process; +} + +void tr2tls_init(void) +{ + tr2tls_start_process_clock(); + + pthread_key_create(&tr2tls_key, NULL); + init_recursive_mutex(&tr2tls_mutex); + + tr2tls_thread_main = + tr2tls_create_self("main", tr2tls_us_start_process); +} + +void tr2tls_release(void) +{ + tr2tls_unset_self(); + tr2tls_thread_main = NULL; + + pthread_mutex_destroy(&tr2tls_mutex); + pthread_key_delete(tr2tls_key); +} + +int tr2tls_locked_increment(int *p) +{ + int current_value; + + pthread_mutex_lock(&tr2tls_mutex); + current_value = *p; + *p = current_value + 1; + pthread_mutex_unlock(&tr2tls_mutex); + + return current_value; +} + +void tr2tls_lock(void) +{ + pthread_mutex_lock(&tr2tls_mutex); +} + +void tr2tls_unlock(void) +{ + pthread_mutex_unlock(&tr2tls_mutex); +} diff --git a/trace2/tr2_tls.h b/trace2/tr2_tls.h new file mode 100644 index 0000000..f904980 --- /dev/null +++ b/trace2/tr2_tls.h @@ -0,0 +1,124 @@ +#ifndef TR2_TLS_H +#define TR2_TLS_H + +#include "strbuf.h" +#include "trace2/tr2_ctr.h" +#include "trace2/tr2_tmr.h" + +/* + * Notice: the term "TLS" refers to "thread-local storage" in the + * Trace2 source files. This usage is borrowed from GCC and Windows. + * There is NO relation to "transport layer security". + */ + +/* + * Arbitry limit for thread names for column alignment. + */ +#define TR2_MAX_THREAD_NAME (24) + +struct tr2tls_thread_ctx { + const char *thread_name; + uint64_t *array_us_start; + size_t alloc; + size_t nr_open_regions; /* plays role of "nr" in ALLOC_GROW */ + int thread_id; + struct tr2_timer_block timer_block; + struct tr2_counter_block counter_block; + unsigned int used_any_timer:1; + unsigned int used_any_per_thread_timer:1; + unsigned int used_any_counter:1; + unsigned int used_any_per_thread_counter:1; +}; + +/* + * Create thread-local storage for the current thread. + * + * The first thread in the process will have: + * { .thread_id=0, .thread_name="main" } + * Subsequent threads are given a non-zero thread_id and a thread_name + * constructed from the id and a thread base name (which is usually just + * the name of the thread-proc function). For example: + * { .thread_id=10, .thread_name="th10:fsm-listen" } + * This helps to identify and distinguish messages from concurrent threads. + * The ctx.thread_name field is truncated if necessary to help with column + * alignment in printf-style messages. + * + * In this and all following functions the term "self" refers to the + * current thread. + */ +struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_base_name, + uint64_t us_thread_start); + +/* + * Get the thread-local storage pointer of the current thread. + */ +struct tr2tls_thread_ctx *tr2tls_get_self(void); + +/* + * return true if the current thread is the main thread. + */ +int tr2tls_is_main_thread(void); + +/* + * Free the current thread's thread-local storage. + */ +void tr2tls_unset_self(void); + +/* + * Begin a new nested region and remember the start time. + */ +void tr2tls_push_self(uint64_t us_now); + +/* + * End the innermost nested region. + */ +void tr2tls_pop_self(void); + +/* + * Pop any extra (above the first) open regions on the current + * thread and discard. During a thread-exit, we should only + * have region[0] that was pushed in trace2_thread_start() if + * the thread exits normally. + */ +void tr2tls_pop_unwind_self(void); + +/* + * Compute the elapsed time since the innermost region in the + * current thread started and the given time (usually now). + */ +uint64_t tr2tls_region_elasped_self(uint64_t us); + +/* + * Compute the elapsed time since the main thread started + * and the given time (usually now). This is assumed to + * be the absolute run time of the process. + */ +uint64_t tr2tls_absolute_elapsed(uint64_t us); + +/* + * Initialize thread-local storage for Trace2. + */ +void tr2tls_init(void); + +/* + * Free all Trace2 thread-local storage resources. + */ +void tr2tls_release(void); + +/* + * Protected increment of an integer. + */ +int tr2tls_locked_increment(int *p); + +/* + * Capture the process start time and do nothing else. + */ +void tr2tls_start_process_clock(void); + +/* + * Explicitly lock/unlock our mutex. + */ +void tr2tls_lock(void); +void tr2tls_unlock(void); + +#endif /* TR2_TLS_H */ diff --git a/trace2/tr2_tmr.c b/trace2/tr2_tmr.c new file mode 100644 index 0000000..786762d --- /dev/null +++ b/trace2/tr2_tmr.c @@ -0,0 +1,182 @@ +#include "cache.h" +#include "thread-utils.h" +#include "trace2/tr2_tgt.h" +#include "trace2/tr2_tls.h" +#include "trace2/tr2_tmr.h" + +#define MY_MAX(a, b) ((a) > (b) ? (a) : (b)) +#define MY_MIN(a, b) ((a) < (b) ? (a) : (b)) + +/* + * A global timer block to aggregate values from the partial sums from + * each thread. + */ +static struct tr2_timer_block final_timer_block; /* access under tr2tls_mutex */ + +/* + * Define metadata for each stopwatch timer. + * + * This array must match "enum trace2_timer_id" and the values + * in "struct tr2_timer_block.timer[*]". + */ +static struct tr2_timer_metadata tr2_timer_metadata[TRACE2_NUMBER_OF_TIMERS] = { + [TRACE2_TIMER_ID_TEST1] = { + .category = "test", + .name = "test1", + .want_per_thread_events = 0, + }, + [TRACE2_TIMER_ID_TEST2] = { + .category = "test", + .name = "test2", + .want_per_thread_events = 1, + }, + + /* Add additional metadata before here. */ +}; + +void tr2_start_timer(enum trace2_timer_id tid) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + struct tr2_timer *t = &ctx->timer_block.timer[tid]; + + t->recursion_count++; + if (t->recursion_count > 1) + return; /* ignore recursive starts */ + + t->start_ns = getnanotime(); +} + +void tr2_stop_timer(enum trace2_timer_id tid) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + struct tr2_timer *t = &ctx->timer_block.timer[tid]; + uint64_t ns_now; + uint64_t ns_interval; + + assert(t->recursion_count > 0); + + t->recursion_count--; + if (t->recursion_count) + return; /* still in recursive call(s) */ + + ns_now = getnanotime(); + ns_interval = ns_now - t->start_ns; + + t->total_ns += ns_interval; + + /* + * min_ns was initialized to zero (in the xcalloc()) rather + * than UINT_MAX when the block of timers was allocated, + * so we should always set both the min_ns and max_ns values + * the first time that the timer is used. + */ + if (!t->interval_count) { + t->min_ns = ns_interval; + t->max_ns = ns_interval; + } else { + t->min_ns = MY_MIN(ns_interval, t->min_ns); + t->max_ns = MY_MAX(ns_interval, t->max_ns); + } + + t->interval_count++; + + ctx->used_any_timer = 1; + if (tr2_timer_metadata[tid].want_per_thread_events) + ctx->used_any_per_thread_timer = 1; +} + +void tr2_update_final_timers(void) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + enum trace2_timer_id tid; + + if (!ctx->used_any_timer) + return; + + /* + * Accessing `final_timer_block` requires holding `tr2tls_mutex`. + * We assume that our caller is holding the lock. + */ + + for (tid = 0; tid < TRACE2_NUMBER_OF_TIMERS; tid++) { + struct tr2_timer *t_final = &final_timer_block.timer[tid]; + struct tr2_timer *t = &ctx->timer_block.timer[tid]; + + if (t->recursion_count) { + /* + * The current thread is exiting with + * timer[tid] still running. + * + * Technically, this is a bug, but I'm going + * to ignore it. + * + * I don't think it is worth calling die() + * for. I don't think it is worth killing the + * process for this bookkeeping error. We + * might want to call warning(), but I'm going + * to wait on that. + * + * The downside here is that total_ns won't + * include the current open interval (now - + * start_ns). I can live with that. + */ + } + + if (!t->interval_count) + continue; /* this timer was not used by this thread */ + + t_final->total_ns += t->total_ns; + + /* + * final_timer_block.timer[tid].min_ns was initialized to + * was initialized to zero rather than UINT_MAX, so we should + * always set both the min_ns and max_ns values the first time + * that we add a partial sum into it. + */ + if (!t_final->interval_count) { + t_final->min_ns = t->min_ns; + t_final->max_ns = t->max_ns; + } else { + t_final->min_ns = MY_MIN(t_final->min_ns, t->min_ns); + t_final->max_ns = MY_MAX(t_final->max_ns, t->max_ns); + } + + t_final->interval_count += t->interval_count; + } +} + +void tr2_emit_per_thread_timers(tr2_tgt_evt_timer_t *fn_apply) +{ + struct tr2tls_thread_ctx *ctx = tr2tls_get_self(); + enum trace2_timer_id tid; + + if (!ctx->used_any_per_thread_timer) + return; + + /* + * For each timer, if the timer wants per-thread events and + * this thread used it, emit it. + */ + for (tid = 0; tid < TRACE2_NUMBER_OF_TIMERS; tid++) + if (tr2_timer_metadata[tid].want_per_thread_events && + ctx->timer_block.timer[tid].interval_count) + fn_apply(&tr2_timer_metadata[tid], + &ctx->timer_block.timer[tid], + 0); +} + +void tr2_emit_final_timers(tr2_tgt_evt_timer_t *fn_apply) +{ + enum trace2_timer_id tid; + + /* + * Accessing `final_timer_block` requires holding `tr2tls_mutex`. + * We assume that our caller is holding the lock. + */ + + for (tid = 0; tid < TRACE2_NUMBER_OF_TIMERS; tid++) + if (final_timer_block.timer[tid].interval_count) + fn_apply(&tr2_timer_metadata[tid], + &final_timer_block.timer[tid], + 1); +} diff --git a/trace2/tr2_tmr.h b/trace2/tr2_tmr.h new file mode 100644 index 0000000..d575357 --- /dev/null +++ b/trace2/tr2_tmr.h @@ -0,0 +1,140 @@ +#ifndef TR2_TMR_H +#define TR2_TMR_H + +#include "trace2.h" +#include "trace2/tr2_tgt.h" + +/* + * Define a mechanism to allow "stopwatch" timers. + * + * Timers can be used to measure "interesting" activity that does not + * fit the "region" model, such as code called from many different + * regions (like zlib) and/or where data for individual calls are not + * interesting or are too numerous to be efficiently logged. + * + * Timer values are accumulated during program execution and emitted + * to the Trace2 logs at program exit. + * + * To make this model efficient, we define a compile-time fixed set of + * timers and timer ids using a "timer block" array in thread-local + * storage. This gives us constant time access to each timer within + * each thread, since we want start/stop operations to be as fast as + * possible. This lets us avoid the complexities of dynamically + * allocating a timer on the first use by a thread and/or possibly + * sharing that timer definition with other concurrent threads. + * However, this does require that we define time the set of timers at + * compile time. + * + * Each thread uses the timer block in its thread-local storage to + * compute partial sums for each timer (without locking). When a + * thread exits, those partial sums are (under lock) added to the + * global final sum. + * + * Using this "timer block" model costs ~48 bytes per timer per thread + * (we have about six uint64 fields per timer). This does increase + * the size of the thread-local storage block, but it is allocated (at + * thread create time) and not on the thread stack, so I'm not worried + * about the size. + * + * Partial sums for each timer are optionally emitted when a thread + * exits. + * + * Final sums for each timer are emitted between the "exit" and + * "atexit" events. + * + * A parallel "timer metadata" table contains the "category" and "name" + * fields for each timer. This eliminates the need to include those + * args in the various timer APIs. + */ + +/* + * The definition of an individual timer and used by an individual + * thread. + */ +struct tr2_timer { + /* + * Total elapsed time for this timer in this thread in nanoseconds. + */ + uint64_t total_ns; + + /* + * The maximum and minimum interval values observed for this + * timer in this thread. + */ + uint64_t min_ns; + uint64_t max_ns; + + /* + * The value of the clock when this timer was started in this + * thread. (Undefined when the timer is not active in this + * thread.) + */ + uint64_t start_ns; + + /* + * Number of times that this timer has been started and stopped + * in this thread. (Recursive starts are ignored.) + */ + uint64_t interval_count; + + /* + * Number of nested starts on the stack in this thread. (We + * ignore recursive starts and use this to track the recursive + * calls.) + */ + unsigned int recursion_count; +}; + +/* + * Metadata for a timer. + */ +struct tr2_timer_metadata { + const char *category; + const char *name; + + /* + * True if we should emit per-thread events for this timer + * when individual threads exit. + */ + unsigned int want_per_thread_events:1; +}; + +/* + * A compile-time fixed-size block of timers to insert into + * thread-local storage. This wrapper is used to avoid quirks + * of C and the usual need to pass an array size argument. + */ +struct tr2_timer_block { + struct tr2_timer timer[TRACE2_NUMBER_OF_TIMERS]; +}; + +/* + * Private routines used by trace2.c to actually start/stop an + * individual timer in the current thread. + */ +void tr2_start_timer(enum trace2_timer_id tid); +void tr2_stop_timer(enum trace2_timer_id tid); + +/* + * Add the current thread's timer data to the global totals. + * This is called during thread-exit. + * + * Caller must be holding the tr2tls_mutex. + */ +void tr2_update_final_timers(void); + +/* + * Emit per-thread timer data for the current thread. + * This is called during thread-exit. + */ +void tr2_emit_per_thread_timers(tr2_tgt_evt_timer_t *fn_apply); + +/* + * Emit global total timer values. + * This is called during atexit handling. + * + * Caller must be holding the tr2tls_mutex. + */ +void tr2_emit_final_timers(tr2_tgt_evt_timer_t *fn_apply); + +#endif /* TR2_TMR_H */ |