git/trace2.c

802 lines
18 KiB
C
Raw Normal View History

#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_dst.h"
#include "trace2/tr2_sid.h"
#include "trace2/tr2_sysenv.h"
#include "trace2/tr2_tgt.h"
#include "trace2/tr2_tls.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
* the TR2 and TLS machinery.
*
* 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();
}
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();
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);
}
tr2: log parent process name It can be useful to tell who invoked Git - was it invoked manually by a user via CLI or script? By an IDE? In some cases - like 'repo' tool - we can influence the source code and set the GIT_TRACE2_PARENT_SID environment variable from the caller process. In 'repo''s case, that parent SID is manipulated to include the string "repo", which means we can positively identify when Git was invoked by 'repo' tool. However, identifying parents that way requires both that we know which tools invoke Git and that we have the ability to modify the source code of those tools. It cannot scale to keep up with the various IDEs and wrappers which use Git, most of which we don't know about. Learning which tools and wrappers invoke Git, and how, would give us insight to decide where to improve Git's usability and performance. Unfortunately, there's no cross-platform reliable way to gather the name of the parent process. If procfs is present, we can use that; otherwise we will need to discover the name another way. However, the process ID should be sufficient to look up the process name on most platforms, so that code may be shareable. Git for Windows gathers similar information and logs it as a "data_json" event. However, since "data_json" has a variable format, it is difficult to parse effectively in some languages; instead, let's pursue a dedicated "cmd_ancestry" event to record information about the ancestry of the current process and a consistent, parseable way. Git for Windows also gathers information about more than one generation of parent. In Linux further ancestry info can be gathered with procfs, but it's unwieldy to do so. In the interest of later moving Git for Windows ancestry logging to the 'cmd_ancestry' event, and in the interest of later adding more ancestry to the Linux implementation - or of adding this functionality to other platforms which have an easier time walking the process tree - let's make 'cmd_ancestry' accept an array of parentage. Signed-off-by: Emily Shaffer <emilyshaffer@google.com> Signed-off-by: Junio C Hamano <gitster@pobox.com>
2021-07-22 01:27:07 +00:00
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_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_name);
return;
}
us_now = getnanotime() / 1000;
us_elapsed_absolute = tr2tls_absolute_elapsed(us_now);
tr2tls_create_self(thread_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);
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);
}
const char *trace2_session_id(void)
{
return tr2_sid_get();
}