THIS IS A TEST INSTANCE ONLY! REPOSITORIES CAN BE DELETED AT ANY TIME!

Browse Source

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>
tags/v2.22.0-rc0
Jeff Hostetler Junio C Hamano 8 months ago
parent
commit
ee4512ed48
39 changed files with 3806 additions and 18 deletions
  1. +13
    -1
      Makefile
  2. +4
    -5
      builtin/submodule--helper.c
  3. +1
    -0
      cache.h
  4. +10
    -2
      common-main.c
  5. +10
    -1
      compat/mingw.c
  6. +1
    -2
      compat/mingw.h
  7. +2
    -0
      config.c
  8. +2
    -0
      exec-cmd.c
  9. +7
    -0
      git-compat-util.h
  10. +65
    -0
      git.c
  11. +7
    -0
      remote-curl.c
  12. +2
    -0
      repository.c
  13. +3
    -0
      repository.h
  14. +58
    -1
      run-command.c
  15. +12
    -1
      run-command.h
  16. +3
    -0
      sh-i18n--envsubst.c
  17. +6
    -5
      submodule.c
  18. +3
    -0
      t/helper/test-parse-options.c
  19. +3
    -0
      t/helper/test-tool.c
  20. +1
    -0
      t/t0001-init.sh
  21. +761
    -0
      trace2.c
  22. +371
    -0
      trace2.h
  23. +90
    -0
      trace2/tr2_cfg.c
  24. +19
    -0
      trace2/tr2_cfg.h
  25. +30
    -0
      trace2/tr2_cmd_name.c
  26. +24
    -0
      trace2/tr2_cmd_name.h
  27. +252
    -0
      trace2/tr2_dst.c
  28. +36
    -0
      trace2/tr2_dst.h
  29. +67
    -0
      trace2/tr2_sid.c
  30. +18
    -0
      trace2/tr2_sid.h
  31. +32
    -0
      trace2/tr2_tbuf.c
  32. +23
    -0
      trace2/tr2_tbuf.h
  33. +133
    -0
      trace2/tr2_tgt.h
  34. +588
    -0
      trace2/tr2_tgt_event.c
  35. +323
    -0
      trace2/tr2_tgt_normal.c
  36. +534
    -0
      trace2/tr2_tgt_perf.c
  37. +164
    -0
      trace2/tr2_tls.c
  38. +97
    -0
      trace2/tr2_tls.h
  39. +31
    -0
      usage.c

+ 13
- 1
Makefile View File

@@ -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

+ 4
- 5
builtin/submodule--helper.c View File

@@ -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.

+ 1
- 0
cache.h View File

@@ -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"

+ 10
- 2
common-main.c View File

@@ -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;
}

+ 10
- 1
compat/mingw.c View File

@@ -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;

+ 1
- 2
compat/mingw.h View File

@@ -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; }

+ 2
- 0
config.c View File

@@ -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);
}

/*

+ 2
- 0
exec-cmd.c View File

@@ -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;
}


+ 7
- 0
git-compat-util.h View File

@@ -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
- 0
git.c View File

@@ -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);


+ 7
- 0
remote-curl.c View File

@@ -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) {

+ 2
- 0
repository.c View File

@@ -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,

+ 3
- 0
repository.h View File

@@ -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' */

+ 58
- 1
run-command.c View File

@@ -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;
}

+ 12
- 1
run-command.h View File

@@ -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

+ 3
- 0
sh-i18n--envsubst.c View File

@@ -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:

+ 6
- 5
submodule.c View File

@@ -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:

+ 3
- 0
t/helper/test-parse-options.c View File

@@ -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) {

+ 3
- 0
t/helper/test-tool.c View File

@@ -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);
}
}

+ 1
- 0
t/t0001-init.sh View File

@@ -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

+ 761
- 0
trace2.c View File

@@ -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, 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_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);
}

#ifndef HAVE_VARIADIC_MACROS
void trace2_printf(const char *fmt, ...)
{
va_list ap;

va_start(ap, fmt);
trace2_printf_va_fl(NULL, 0, fmt, ap);
va_end(ap);
}
#endif

+ 371
- 0
trace2.h View File

@@ -0,0 +1,371 @@
#ifndef TRACE2_H
#define TRACE2_H

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.
*/

/*
* Initialize TRACE2 tracing facility if any of the builtin TRACE2
* targets are enabled in the environment. Emits a 'version' event.
*
* 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 true if trace2 is enabled.
*/
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.
*
* Write the exit-code that will be passed to exit() or returned
* from main().
*
* Use this prior to actually calling exit().
* See "#define exit()" in git-compat-util.h
*/
int 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 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))

/*
* Emit an 'alias' expansion event.
*/
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 "interesting" configuration
* settings.
*
* The environment variable "GIT_TR2_CONFIG_PARAMS" can be set to a
* list of patterns considered important. For example:
*
* GIT_TR2_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 a "def_param" event for the given config key/value pair IF
* we consider the key to be "interesting".
*
* 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))

/*
* Emit a 'child_start' event prior to spawning a child process.
*
* Before calling optionally set "cmd->trace2_child_class" to a string
* describing the type of the child process. For example, "editor" or
* "pager".
*/
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))

/*
* Emit a 'child_exit' event after the child process completes.
*/
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))

/*
* 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 the "exec_id".
*/
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 set up the trace2 TLS data for the thread.
*
* Thread names should be descriptive, like "preload_index".
* Thread names will be decorated with an instance number automatically.
*/
void trace2_thread_start_fl(const char *file, int line,
const char *thread_name);

#define trace2_thread_start(thread_name) \
trace2_thread_start_fl(__FILE__, __LINE__, (thread_name))

/*
* Emit a 'thread_exit' event. This must be called from inside the
* thread-proc to report thread-specific data and cleanup TLS data
* for the thread.
*/
void trace2_thread_exit_fl(const char *file, int line);

#define trace2_thread_exit() trace2_thread_exit_fl(__FILE__, __LINE__)

/*
* Emit a 'param' event.
*
* Write a "<param> = <value>" pair describing some aspect of the
* run such as an important configuration setting or command line
* option that significantly changes command behavior.
*/
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.
*/
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.
*
* Enter a new nesting level on the current thread and remember the
* current time. This controls the indenting of all subsequent events
* on this thread.
*/
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, ...);

#ifdef HAVE_VARIADIC_MACROS
#define trace2_region_enter_printf(category, label, repo, ...) \
trace2_region_enter_printf_fl(__FILE__, __LINE__, (category), (label), \
(repo), __VA_ARGS__)
#else
/* clang-format off */
__attribute__((format (region_enter_printf, 4, 5)))
void trace2_region_enter_printf(const char *category, const char *label,
const struct repository *repo, const char *fmt,
...);
/* clang-format on */
#endif

/*
* 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.
*/
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, ...);

#ifdef HAVE_VARIADIC_MACROS
#define trace2_region_leave_printf(category, label, repo, ...) \
trace2_region_leave_printf_fl(__FILE__, __LINE__, (category), (label), \
(repo), __VA_ARGS__)
#else
/* clang-format off */
__attribute__((format (region_leave_printf, 4, 5)))
void trace2_region_leave_printf(const char *category, const char *label,
const struct repository *repo, const char *fmt,
...);
/* clang-format on */
#endif

/*
* 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.
*
* 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, ...);

#ifdef HAVE_VARIADIC_MACROS
#define trace2_printf(...) trace2_printf_fl(__FILE__, __LINE__, __VA_ARGS__)
#else
/* clang-format off */
__attribute__((format (printf, 1, 2)))
void trace2_printf(const char *fmt, ...);
/* clang-format on */
#endif

#endif /* TRACE2_H */

+ 90
- 0
trace2/tr2_cfg.c View File

@@ -0,0 +1,90 @@
#include "cache.h"
#include "config.h"
#include "tr2_cfg.h"

#define TR2_ENVVAR_CFG_PARAM "GIT_TR2_CONFIG_PARAMS"

static struct strbuf **tr2_cfg_patterns;
static int tr2_cfg_count_patterns;
static int tr2_cfg_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 = getenv(TR2_ENVVAR_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;
}

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_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);
}

+ 19
- 0
trace2/tr2_cfg.h View File

@@ -0,0 +1,19 @@
#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);

/*
* 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);

#endif /* TR2_CFG_H */

+ 30
- 0
trace2/tr2_cmd_name.c View File

@@ -0,0 +1,30 @@
#include "cache.h"
#include "trace2/tr2_cmd_name.h"

#define TR2_ENVVAR_PARENT_NAME "GIT_TR2_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);
}

+ 24
- 0
trace2/tr2_cmd_name.h View File

@@ -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 */

+ 252
- 0
trace2/tr2_dst.c View File

@@ -0,0 +1,252 @@
#include "cache.h"
#include "trace2/tr2_dst.h"

/*
* If a Trace2 target cannot be opened for writing, we should issue a
* warning to stderr, but this is very annoying if the target is a pipe
* or socket and beyond the user's control -- especially since every
* git command (and sub-command) will print the message. So we silently
* eat these warnings and just discard the trace data.
*
* Enable the following environment variable to see these warnings.
*/
#define TR2_ENVVAR_DST_DEBUG "GIT_TR2_DST_DEBUG"

static int tr2_dst_want_warning(void)
{
static int tr2env_dst_debug = -1;

if (tr2env_dst_debug == -1) {
const char *env_value = getenv(TR2_ENVVAR_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;
}

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, dst->env_var_name, 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 errno;

sa.sun_family = AF_UNIX;
strlcpy(sa.sun_path, path, sizeof(sa.sun_path));

if (connect(fd, (struct sockaddr *)&sa, sizeof(sa)) == -1) {
int e = errno;
close(fd);
return e;
}

*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;
int e;
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, dst->env_var_name);

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, dst->env_var_name);

tr2_dst_trace_disable(dst);
return 0;
}

if (uds_try & TR2_DST_UDS_TRY_STREAM) {
e = tr2_dst_try_uds_connect(path, SOCK_STREAM, &fd);
if (!e)
goto connected;
if (e != EPROTOTYPE)
goto error;
}
if (uds_try & TR2_DST_UDS_TRY_DGRAM) {
e = tr2_dst_try_uds_connect(path, SOCK_DGRAM, &fd);
if (!e)
goto connected;
}

error:
if (tr2_dst_want_warning())
warning("trace2: could not connect to socket '%s' for '%s' tracing: %s",
path, dst->env_var_name, strerror(e));

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)
{
struct strbuf buf = STRBUF_INIT;

strbuf_addf(&buf, "trace2: unknown value for '%s': '%s'",
dst->env_var_name, tgt_value);
warning("%s", buf.buf);

strbuf_release(&buf);
}

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 = getenv(dst->env_var_name);

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))
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);

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
<