trace2: create new combined trace facility

Create a new unified tracing facility for git.  The eventual intent is to
replace the current trace_printf* and trace_performance* routines with a
unified set of git_trace2* routines.

In addition to the usual printf-style API, trace2 provides higer-level
event verbs with fixed-fields allowing structured data to be written.
This makes post-processing and analysis easier for external tools.

Trace2 defines 3 output targets.  These are set using the environment
variables "GIT_TR2", "GIT_TR2_PERF", and "GIT_TR2_EVENT".  These may be
set to "1" or to an absolute pathname (just like the current GIT_TRACE).

* GIT_TR2 is intended to be a replacement for GIT_TRACE and logs command
  summary data.

* GIT_TR2_PERF is intended as a replacement for GIT_TRACE_PERFORMANCE.
  It extends the output with columns for the command process, thread,
  repo, absolute and relative elapsed times.  It reports events for
  child process start/stop, thread start/stop, and per-thread function
  nesting.

* GIT_TR2_EVENT is a new structured format. It writes event data as a
  series of JSON records.

Calls to trace2 functions log to any of the 3 output targets enabled
without the need to call different trace_printf* or trace_performance*
routines.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
pull/608/head
Jeff Hostetler 4 years ago committed by Junio C Hamano
parent e544221d97
commit ee4512ed48
  1. 14
      Makefile
  2. 9
      builtin/submodule--helper.c
  3. 1
      cache.h
  4. 12
      common-main.c
  5. 11
      compat/mingw.c
  6. 3
      compat/mingw.h
  7. 2
      config.c
  8. 2
      exec-cmd.c
  9. 7
      git-compat-util.h
  10. 65
      git.c
  11. 7
      remote-curl.c
  12. 2
      repository.c
  13. 3
      repository.h
  14. 59
      run-command.c
  15. 13
      run-command.h
  16. 3
      sh-i18n--envsubst.c
  17. 11
      submodule.c
  18. 3
      t/helper/test-parse-options.c
  19. 3
      t/helper/test-tool.c
  20. 1
      t/t0001-init.sh
  21. 761
      trace2.c
  22. 371
      trace2.h
  23. 90
      trace2/tr2_cfg.c
  24. 19
      trace2/tr2_cfg.h
  25. 30
      trace2/tr2_cmd_name.c
  26. 24
      trace2/tr2_cmd_name.h
  27. 252
      trace2/tr2_dst.c
  28. 36
      trace2/tr2_dst.h
  29. 67
      trace2/tr2_sid.c
  30. 18
      trace2/tr2_sid.h
  31. 32
      trace2/tr2_tbuf.c
  32. 23
      trace2/tr2_tbuf.h
  33. 133
      trace2/tr2_tgt.h
  34. 588
      trace2/tr2_tgt_event.c
  35. 323
      trace2/tr2_tgt_normal.c
  36. 534
      trace2/tr2_tgt_perf.c
  37. 164
      trace2/tr2_tls.c
  38. 97
      trace2/tr2_tls.h
  39. 31
      usage.c

@ -1017,6 +1017,16 @@ LIB_OBJS += tempfile.o
LIB_OBJS += thread-utils.o
LIB_OBJS += tmp-objdir.o
LIB_OBJS += trace.o
LIB_OBJS += trace2.o
LIB_OBJS += trace2/tr2_cfg.o
LIB_OBJS += trace2/tr2_cmd_name.o
LIB_OBJS += trace2/tr2_dst.o
LIB_OBJS += trace2/tr2_sid.o
LIB_OBJS += trace2/tr2_tbuf.o
LIB_OBJS += trace2/tr2_tgt_event.o
LIB_OBJS += trace2/tr2_tgt_normal.o
LIB_OBJS += trace2/tr2_tgt_perf.o
LIB_OBJS += trace2/tr2_tls.o
LIB_OBJS += trailer.o
LIB_OBJS += transport.o
LIB_OBJS += transport-helper.o
@ -1596,7 +1606,9 @@ ifdef NO_INET_PTON
LIB_OBJS += compat/inet_pton.o
BASIC_CFLAGS += -DNO_INET_PTON
endif
ifndef NO_UNIX_SOCKETS
ifdef NO_UNIX_SOCKETS
BASIC_CFLAGS += -DNO_UNIX_SOCKETS
else
LIB_OBJS += unix-socket.o
PROGRAM_OBJS += credential-cache.o
PROGRAM_OBJS += credential-cache--daemon.o

@ -1816,11 +1816,10 @@ static int update_submodules(struct submodule_update_clone *suc)
{
int i;
run_processes_parallel(suc->max_jobs,
update_clone_get_next_task,
update_clone_start_failure,
update_clone_task_finished,
suc);
run_processes_parallel_tr2(suc->max_jobs, update_clone_get_next_task,
update_clone_start_failure,
update_clone_task_finished, suc, "submodule",
"parallel/update");
/*
* We saved the output and put it out all at once now.

@ -9,6 +9,7 @@
#include "gettext.h"
#include "convert.h"
#include "trace.h"
#include "trace2.h"
#include "string-list.h"
#include "pack-revindex.h"
#include "hash.h"

@ -25,12 +25,18 @@ static void restore_sigpipe_to_default(void)
int main(int argc, const char **argv)
{
int result;
/*
* Always open file descriptors 0/1/2 to avoid clobbering files
* in die(). It also avoids messing up when the pipes are dup'ed
* onto stdin/stdout/stderr in the child processes we spawn.
*/
sanitize_stdfds();
restore_sigpipe_to_default();
trace2_initialize();
trace2_cmd_start(argv);
git_resolve_executable_dir(argv[0]);
@ -40,7 +46,9 @@ int main(int argc, const char **argv)
attr_start();
restore_sigpipe_to_default();
result = cmd_main(argc, argv);
trace2_cmd_exit(result);
return cmd_main(argc, argv);
return result;
}

@ -1551,19 +1551,23 @@ static int try_shell_exec(const char *cmd, char *const *argv)
return 0;
prog = path_lookup(interpr, 1);
if (prog) {
int exec_id;
int argc = 0;
const char **argv2;
while (argv[argc]) argc++;
ALLOC_ARRAY(argv2, argc + 1);
argv2[0] = (char *)cmd; /* full path to the script file */
memcpy(&argv2[1], &argv[1], sizeof(*argv) * argc);
exec_id = trace2_exec(prog, argv2);
pid = mingw_spawnv(prog, argv2, 1);
if (pid >= 0) {
int status;
if (waitpid(pid, &status, 0) < 0)
status = 255;
trace2_exec_result(exec_id, status);
exit(status);
}
trace2_exec_result(exec_id, -1);
pid = 1; /* indicate that we tried but failed */
free(prog);
free(argv2);
@ -1576,12 +1580,17 @@ int mingw_execv(const char *cmd, char *const *argv)
/* check if git_command is a shell script */
if (!try_shell_exec(cmd, argv)) {
int pid, status;
int exec_id;
exec_id = trace2_exec(cmd, (const char **)argv);
pid = mingw_spawnv(cmd, (const char **)argv, 0);
if (pid < 0)
if (pid < 0) {
trace2_exec_result(exec_id, -1);
return -1;
}
if (waitpid(pid, &status, 0) < 0)
status = 255;
trace2_exec_result(exec_id, status);
exit(status);
}
return -1;

@ -147,8 +147,7 @@ static inline int fcntl(int fd, int cmd, ...)
errno = EINVAL;
return -1;
}
/* bash cannot reliably detect negative return codes as failure */
#define exit(code) exit((code) & 0xff)
#define sigemptyset(x) (void)0
static inline int sigaddset(sigset_t *set, int signum)
{ return 0; }

@ -2655,6 +2655,8 @@ int git_config_set_gently(const char *key, const char *value)
void git_config_set(const char *key, const char *value)
{
git_config_set_multivar(key, value, NULL, 0);
trace2_cmd_set_config(key, value);
}
/*

@ -209,6 +209,8 @@ static int git_get_exec_path(struct strbuf *buf, const char *argv0)
return -1;
}
trace2_cmd_path(buf->buf);
return 0;
}

@ -1259,6 +1259,13 @@ static inline int is_missing_file_error(int errno_)
extern int cmd_main(int, const char **);
/*
* Intercept all calls to exit() and route them to trace2 to
* optionally emit a message before calling the real exit().
*/
int trace2_cmd_exit_fl(const char *file, int line, int code);
#define exit(code) exit(trace2_cmd_exit_fl(__FILE__, __LINE__, (code)))
/*
* You can mark a stack variable with UNLEAK(var) to avoid it being
* reported as a leak by tools like LSAN or valgrind. The argument

65
git.c

@ -147,16 +147,20 @@ static int handle_options(const char ***argv, int *argc, int *envchanged)
git_set_exec_path(cmd + 1);
else {
puts(git_exec_path());
trace2_cmd_name("_query_");
exit(0);
}
} else if (!strcmp(cmd, "--html-path")) {
puts(system_path(GIT_HTML_PATH));
trace2_cmd_name("_query_");
exit(0);
} else if (!strcmp(cmd, "--man-path")) {
puts(system_path(GIT_MAN_PATH));
trace2_cmd_name("_query_");
exit(0);
} else if (!strcmp(cmd, "--info-path")) {
puts(system_path(GIT_INFO_PATH));
trace2_cmd_name("_query_");
exit(0);
} else if (!strcmp(cmd, "-p") || !strcmp(cmd, "--paginate")) {
use_pager = 1;
@ -285,6 +289,7 @@ static int handle_options(const char ***argv, int *argc, int *envchanged)
(*argv)++;
(*argc)--;
} else if (skip_prefix(cmd, "--list-cmds=", &cmd)) {
trace2_cmd_name("_query_");
if (!strcmp(cmd, "parseopt")) {
struct string_list list = STRING_LIST_INIT_DUP;
int i;
@ -332,9 +337,14 @@ static int handle_alias(int *argcp, const char ***argv)
commit_pager_choice();
child.use_shell = 1;
child.trace2_child_class = "shell_alias";
argv_array_push(&child.args, alias_string + 1);
argv_array_pushv(&child.args, (*argv) + 1);
trace2_cmd_alias(alias_command, child.args.argv);
trace2_cmd_list_config();
trace2_cmd_name("_run_shell_alias_");
ret = run_command(&child);
if (ret >= 0) /* normal exit */
exit(ret);
@ -369,6 +379,9 @@ static int handle_alias(int *argcp, const char ***argv)
/* insert after command name */
memcpy(new_argv + count, *argv + 1, sizeof(char *) * *argcp);
trace2_cmd_alias(alias_command, new_argv);
trace2_cmd_list_config();
*argv = new_argv;
*argcp += count - 1;
@ -417,6 +430,8 @@ static int run_builtin(struct cmd_struct *p, int argc, const char **argv)
setup_work_tree();
trace_argv_printf(argv, "trace: built-in: git");
trace2_cmd_name(p->cmd);
trace2_cmd_list_config();
validate_cache_entries(the_repository->index);
status = p->fn(argc, argv, prefix);
@ -666,7 +681,14 @@ static void execv_dashed_external(const char **argv)
cmd.clean_on_exit = 1;
cmd.wait_after_clean = 1;
cmd.silent_exec_failure = 1;
cmd.trace2_child_class = "dashed";
trace2_cmd_name("_run_dashed_");
/*
* The code in run_command() logs trace2 child_start/child_exit
* events, so we do not need to report exec/exec_result events here.
*/
trace_argv_printf(cmd.args.argv, "trace: exec:");
/*
@ -676,6 +698,12 @@ static void execv_dashed_external(const char **argv)
* the program.
*/
status = run_command(&cmd);
/*
* If the child process ran and we are now going to exit, emit a
* generic string as our trace2 command verb to indicate that we
* launched a dashed command.
*/
if (status >= 0)
exit(status);
else if (errno != ENOENT)
@ -701,6 +729,43 @@ static int run_argv(int *argcp, const char ***argv)
if (!done_alias)
handle_builtin(*argcp, *argv);
#if 0 // TODO In GFW, need to amend a7924b655e940b06cb547c235d6bed9767929673 to include trace2_ and _tr2 lines.
else if (get_builtin(**argv)) {
struct argv_array args = ARGV_ARRAY_INIT;
int i;
/*
* The current process is committed to launching a
* child process to run the command named in (**argv)
* and exiting. Log a generic string as the trace2
* command verb to indicate this. Note that the child
* process will log the actual verb when it runs.
*/
trace2_cmd_name("_run_git_alias_");
if (get_super_prefix())
die("%s doesn't support --super-prefix", **argv);
commit_pager_choice();
argv_array_push(&args, "git");
for (i = 0; i < *argcp; i++)
argv_array_push(&args, (*argv)[i]);
trace_argv_printf(args.argv, "trace: exec:");
/*
* if we fail because the command is not found, it is
* OK to return. Otherwise, we just pass along the status code.
*/
i = run_command_v_opt_tr2(args.argv, RUN_SILENT_EXEC_FAILURE |
RUN_CLEAN_ON_EXIT, "git_alias");
if (i >= 0 || errno != ENOENT)
exit(i);
die("could not execute builtin %s", **argv);
}
#endif // a7924b655e940b06cb547c235d6bed9767929673
/* .. then try the external ones */
execv_dashed_external(*argv);

@ -1385,6 +1385,13 @@ int cmd_main(int argc, const char **argv)
string_list_init(&options.deepen_not, 1);
string_list_init(&options.push_options, 1);
/*
* Just report "remote-curl" here (folding all the various aliases
* ("git-remote-http", "git-remote-https", and etc.) here since they
* are all just copies of the same actual executable.
*/
trace2_cmd_name("remote-curl");
remote = remote_get(argv[1]);
if (argc > 2) {

@ -126,6 +126,8 @@ out:
void repo_set_worktree(struct repository *repo, const char *path)
{
repo->worktree = real_pathdup(path, 1);
trace2_def_repo(repo);
}
static int read_and_verify_repository_format(struct repository_format *format,

@ -92,6 +92,9 @@ struct repository {
/* Repository's current hash algorithm, as serialized on disk. */
const struct git_hash_algo *hash_algo;
/* A unique-id for tracing purposes. */
int trace2_repo_id;
/* Configurations */
/* Indicate if a repository has a different 'commondir' from 'gitdir' */

@ -219,9 +219,29 @@ static int exists_in_PATH(const char *file)
int sane_execvp(const char *file, char * const argv[])
{
#ifndef GIT_WINDOWS_NATIVE
/*
* execvp() doesn't return, so we all we can do is tell trace2
* what we are about to do and let it leave a hint in the log
* (unless of course the execvp() fails).
*
* we skip this for Windows because the compat layer already
* has to emulate the execvp() call anyway.
*/
int exec_id = trace2_exec(file, (const char **)argv);
#endif
if (!execvp(file, argv))
return 0; /* cannot happen ;-) */
#ifndef GIT_WINDOWS_NATIVE
{
int ec = errno;
trace2_exec_result(exec_id, ec);
errno = ec;
}
#endif
/*
* When a command can't be found because one of the directories
* listed in $PATH is unsearchable, execvp reports EACCES, but
@ -712,6 +732,7 @@ fail_pipe:
cmd->err = fderr[0];
}
trace2_child_start(cmd);
trace_run_command(cmd);
fflush(NULL);
@ -926,6 +947,8 @@ end_of_spawn:
#endif
if (cmd->pid < 0) {
trace2_child_exit(cmd, -1);
if (need_in)
close_pair(fdin);
else if (cmd->in)
@ -964,13 +987,16 @@ end_of_spawn:
int finish_command(struct child_process *cmd)
{
int ret = wait_or_whine(cmd->pid, cmd->argv[0], 0);
trace2_child_exit(cmd, ret);
child_process_clear(cmd);
return ret;
}
int finish_command_in_signal(struct child_process *cmd)
{
return wait_or_whine(cmd->pid, cmd->argv[0], 1);
int ret = wait_or_whine(cmd->pid, cmd->argv[0], 1);
trace2_child_exit(cmd, ret);
return ret;
}
@ -992,7 +1018,18 @@ int run_command_v_opt(const char **argv, int opt)
return run_command_v_opt_cd_env(argv, opt, NULL, NULL);
}
int run_command_v_opt_tr2(const char **argv, int opt, const char *tr2_class)
{
return run_command_v_opt_cd_env_tr2(argv, opt, NULL, NULL, tr2_class);
}
int run_command_v_opt_cd_env(const char **argv, int opt, const char *dir, const char *const *env)
{
return run_command_v_opt_cd_env_tr2(argv, opt, dir, env, NULL);
}
int run_command_v_opt_cd_env_tr2(const char **argv, int opt, const char *dir,
const char *const *env, const char *tr2_class)
{
struct child_process cmd = CHILD_PROCESS_INIT;
cmd.argv = argv;
@ -1004,6 +1041,7 @@ int run_command_v_opt_cd_env(const char **argv, int opt, const char *dir, const
cmd.clean_on_exit = opt & RUN_CLEAN_ON_EXIT ? 1 : 0;
cmd.dir = dir;
cmd.env = env;
cmd.trace2_child_class = tr2_class;
return run_command(&cmd);
}
@ -1319,6 +1357,7 @@ int run_hook_ve(const char *const *env, const char *name, va_list args)
hook.env = env;
hook.no_stdin = 1;
hook.stdout_to_stderr = 1;
hook.trace2_hook_name = name;
return run_command(&hook);
}
@ -1807,3 +1846,21 @@ int run_processes_parallel(int n,
pp_cleanup(&pp);
return 0;
}
int run_processes_parallel_tr2(int n, get_next_task_fn get_next_task,
start_failure_fn start_failure,
task_finished_fn task_finished, void *pp_cb,
const char *tr2_category, const char *tr2_label)
{
int result;
trace2_region_enter_printf(tr2_category, tr2_label, NULL, "max:%d",
((n < 1) ? online_cpus() : n));
result = run_processes_parallel(n, get_next_task, start_failure,
task_finished, pp_cb);
trace2_region_leave(tr2_category, tr2_label, NULL);
return result;
}

@ -10,6 +10,12 @@ struct child_process {
struct argv_array args;
struct argv_array env_array;
pid_t pid;
int trace2_child_id;
uint64_t trace2_child_us_start;
const char *trace2_child_class;
const char *trace2_hook_name;
/*
* Using .in, .out, .err:
* - Specify 0 for no redirections (child inherits stdin, stdout,
@ -73,12 +79,14 @@ extern int run_hook_ve(const char *const *env, const char *name, va_list args);
#define RUN_USING_SHELL 16
#define RUN_CLEAN_ON_EXIT 32
int run_command_v_opt(const char **argv, int opt);
int run_command_v_opt_tr2(const char **argv, int opt, const char *tr2_class);
/*
* env (the environment) is to be formatted like environ: "VAR=VALUE".
* To unset an environment variable use just "VAR".
*/
int run_command_v_opt_cd_env(const char **argv, int opt, const char *dir, const char *const *env);
int run_command_v_opt_cd_env_tr2(const char **argv, int opt, const char *dir,
const char *const *env, const char *tr2_class);
/**
* Execute the given command, sending "in" to its stdin, and capturing its
@ -220,5 +228,8 @@ int run_processes_parallel(int n,
start_failure_fn,
task_finished_fn,
void *pp_cb);
int run_processes_parallel_tr2(int n, get_next_task_fn, start_failure_fn,
task_finished_fn, void *pp_cb,
const char *tr2_category, const char *tr2_label);
#endif

@ -14,6 +14,7 @@
*/
#include "git-compat-util.h"
#include "trace2.h"
/* Substitution of environment variables in shell format strings.
Copyright (C) 2003-2007 Free Software Foundation, Inc.
@ -67,6 +68,8 @@ cmd_main (int argc, const char *argv[])
/* Default values for command line options. */
/* unsigned short int show_variables = 0; */
trace2_cmd_name("sh-i18n--envsubst");
switch (argc)
{
case 1:

@ -1609,11 +1609,12 @@ int fetch_populated_submodules(struct repository *r,
calculate_changed_submodule_paths(r, &spf.changed_submodule_names);
string_list_sort(&spf.changed_submodule_names);
run_processes_parallel(max_parallel_jobs,
get_next_submodule,
fetch_start_failure,
fetch_finish,
&spf);
run_processes_parallel_tr2(max_parallel_jobs,
get_next_submodule,
fetch_start_failure,
fetch_finish,
&spf,
"submodule", "parallel/fetch");
argv_array_clear(&spf.args);
out:

@ -2,6 +2,7 @@
#include "cache.h"
#include "parse-options.h"
#include "string-list.h"
#include "trace2.h"
static int boolean = 0;
static int integer = 0;
@ -153,6 +154,8 @@ int cmd__parse_options(int argc, const char **argv)
int i;
int ret = 0;
trace2_cmd_name("_parse_");
argc = parse_options(argc, (const char **)argv, prefix, options, usage, 0);
if (length_cb.called) {

@ -1,5 +1,6 @@
#include "git-compat-util.h"
#include "test-tool.h"
#include "trace2.h"
struct test_cmd {
const char *name;
@ -82,6 +83,8 @@ int cmd_main(int argc, const char **argv)
if (!strcmp(cmds[i].name, argv[1])) {
argv++;
argc--;
trace2_cmd_name(cmds[i].name);
trace2_cmd_list_config();
return cmds[i].fn(argc, argv);
}
}

@ -93,6 +93,7 @@ test_expect_success 'No extra GIT_* on alias scripts' '
sed -n \
-e "/^GIT_PREFIX=/d" \
-e "/^GIT_TEXTDOMAINDIR=/d" \
-e "/^GIT_TR2_PARENT/d" \
-e "/^GIT_/s/=.*//p" |
sort
EOF

@ -0,0 +1,761 @@
#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_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();
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_fl(const char *file, int line)
{
struct tr2_tgt *tgt_j;
int j;
if (trace2_enabled)
return;
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;
if (!trace2_enabled)
return;
for_each_wanted_builtin (j, tgt_j)
if (tgt_j->pfn_start_fl)
tgt_j->pfn_start_fl(file, line, argv);
}
int 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;
code &= 0xff;
if (!trace2_enabled)
return code;
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);
return 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_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_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);
}
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);
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)
{
trace2_region_enter_printf_va_fl(file, line, category, label, repo,
NULL, NULL);
}
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);
}
#ifndef HAVE_VARIADIC_MACROS
void trace2_region_enter_printf(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(NULL, 0, category, label, repo, fmt,
ap);
va_end(ap);
}
#endif
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)
{
trace2_region_leave_printf_va_fl(file, line, category, label, repo,
NULL, NULL);
}
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);
}
#ifndef HAVE_VARIADIC_MACROS
void trace2_region_leave_printf(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(NULL, 0, category, label, repo, fmt,
ap);
va_end(ap);
}
#endif
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