kernel
/
git
mirror of https://git.kernel.org/pub/scm/git/git.git
1
0
Fork 0
Code Releases Activity
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>
maint
Jeff Hostetler 6 years ago committed by Junio C Hamano
parent
e544221d97
commit
ee4512ed48
39 changed files with 3806 additions and 18 deletions
Whitespace
Show all changes Ignore whitespace when comparing lines Ignore changes in amount of whitespace Ignore changes in whitespace at EOL
Split View
Diff Options
Show Stats Download Patch File Download Diff File
  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

14
Makefile
Unescape View File

@ -1017,6 +1017,16 @@ LIB_OBJS += tempfile.o @@ -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 @@ -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

9
builtin/submodule--helper.c
Unescape View File

@ -1816,11 +1816,10 @@ static int update_submodules(struct submodule_update_clone *suc) @@ -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
cache.h
Unescape View File

@ -9,6 +9,7 @@ @@ -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"

12
common-main.c
Unescape View File

@ -25,12 +25,18 @@ static void restore_sigpipe_to_default(void) @@ -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) @@ -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;
}

11
compat/mingw.c
Unescape View File

@ -1551,19 +1551,23 @@ static int try_shell_exec(const char *cmd, char *const *argv) @@ -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) @@ -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;

3
compat/mingw.h
Unescape View File

@ -147,8 +147,7 @@ static inline int fcntl(int fd, int cmd, ...) @@ -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
config.c
Unescape View File

@ -2655,6 +2655,8 @@ int git_config_set_gently(const char *key, const char *value) @@ -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
exec-cmd.c
Unescape View File

@ -209,6 +209,8 @@ static int git_get_exec_path(struct strbuf *buf, const char *argv0) @@ -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
git-compat-util.h
Unescape View File

@ -1259,6 +1259,13 @@ static inline int is_missing_file_error(int errno_) @@ -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
Unescape View File

@ -147,16 +147,20 @@ static int handle_options(const char ***argv, int *argc, int *envchanged) @@ -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) @@ -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) @@ -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) @@ -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) @@ -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) @@ -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) @@ -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) @@ -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
remote-curl.c
Unescape View File

@ -1385,6 +1385,13 @@ int cmd_main(int argc, const char **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) {

2
repository.c
Unescape View File

@ -126,6 +126,8 @@ out: @@ -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
repository.h
Unescape View File

@ -92,6 +92,9 @@ struct repository { @@ -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' */

59
run-command.c
Unescape View File

@ -219,9 +219,29 @@ static int exists_in_PATH(const char *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: @@ -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: @@ -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: @@ -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) @@ -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 @@ -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) @@ -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, @@ -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;
}

13
run-command.h
Unescape View File

@ -10,6 +10,12 @@ struct child_process { @@ -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); @@ -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, @@ -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
sh-i18n--envsubst.c
Unescape View File

@ -14,6 +14,7 @@ @@ -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[]) @@ -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:

11
submodule.c
Unescape View File

@ -1609,11 +1609,12 @@ int fetch_populated_submodules(struct repository *r, @@ -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
t/helper/test-parse-options.c
Unescape View File

@ -2,6 +2,7 @@ @@ -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) @@ -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
t/helper/test-tool.c
Unescape View File

@ -1,5 +1,6 @@ @@ -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) @@ -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
t/t0001-init.sh
Unescape View File

@ -93,6 +93,7 @@ test_expect_success 'No extra GIT_* on alias scripts' ' @@ -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
trace2.c
Unescape View File

@ -0,0 +1,761 @@ @@ -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
trace2.h
Unescape View File

@ -0,0 +1,371 @@ @@ -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
trace2/tr2_cfg.c
Unescape View File

@ -0,0 +1,90 @@ @@ -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
trace2/tr2_cfg.h
Unescape View File

@ -0,0 +1,19 @@ @@ -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
trace2/tr2_cmd_name.c
Unescape View File

@ -0,0 +1,30 @@ @@ -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
trace2/tr2_cmd_name.h
Unescape View File

@ -0,0 +1,24 @@ @@ -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
trace2/tr2_dst.c
Unescape View File

@ -0,0 +1,252 @@ @@ -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
* another thread or git process is concurrently writing to
* this fd or file, our remainder-write may not be contiguous
* with our initial write of this message. And that will
* confuse readers. So just don't bother.
*
* It is assumed that TRACE2 messages are short enough that
* the system can write them in 1 attempt and we won't see
* a short-write.
*
* If we get an IO error, just close the trace dst.
*/
if (write(fd, buf_line->buf, buf_line->len) >= 0)
return;

if (tr2_dst_want_warning())
warning("unable to write trace to '%s': %s", dst->env_var_name,
strerror(errno));
tr2_dst_trace_disable(dst);
}

36
trace2/tr2_dst.h
Unescape View File

@ -0,0 +1,36 @@ @@ -0,0 +1,36 @@
#ifndef TR2_DST_H
#define TR2_DST_H

struct strbuf;

struct tr2_dst {
const char *const env_var_name;
int fd;
unsigned int initialized : 1;
unsigned int need_close : 1;
};

/*
* Disable TRACE2 on the destination. In TRACE2 a destination (DST)
* wraps a file descriptor; it is associated with a TARGET which
* defines the formatting.
*/
void tr2_dst_trace_disable(struct tr2_dst *dst);

/*
* Return the file descriptor for the DST.
* If 0, the dst is closed or disabled.
*/
int tr2_dst_get_trace_fd(struct tr2_dst *dst);

/*
* Return true if the DST is opened for writing.
*/
int tr2_dst_trace_want(struct tr2_dst *dst);

/*
* Write a single line/message to the trace file.
*/
void tr2_dst_write_line(struct tr2_dst *dst, struct strbuf *buf_line);

#endif /* TR2_DST_H */

67
trace2/tr2_sid.c
Unescape View File

@ -0,0 +1,67 @@ @@ -0,0 +1,67 @@
#include "cache.h"
#include "trace2/tr2_sid.h"

#define TR2_ENVVAR_PARENT_SID "GIT_TR2_PARENT_SID"

static struct strbuf tr2sid_buf = STRBUF_INIT;
static int tr2sid_nr_git_parents;

/*
* Compute a "unique" session id (SID) for the current process. This allows
* all events from this process to have a single label (much like a PID).
*
* Export this into our environment so that all child processes inherit it.
*
* If we were started by another git instance, use our parent's SID as a
* prefix. (This lets us track parent/child relationships even if there
* is an intermediate shell process.)
*
* Additionally, count the number of nested git processes.
*/
static void tr2_sid_compute(void)
{
uint64_t us_now;
const char *parent_sid;

if (tr2sid_buf.len)
return;

parent_sid = getenv(TR2_ENVVAR_PARENT_SID);
if (parent_sid && *parent_sid) {
const char *p;
for (p = parent_sid; *p; p++)
if (*p == '/')
tr2sid_nr_git_parents++;

strbuf_addstr(&tr2sid_buf, parent_sid);
strbuf_addch(&tr2sid_buf, '/');
tr2sid_nr_git_parents++;
}

us_now = getnanotime() / 1000;
strbuf_addf(&tr2sid_buf, "%" PRIuMAX "-%" PRIdMAX, (uintmax_t)us_now,
(intmax_t)getpid());

setenv(TR2_ENVVAR_PARENT_SID, tr2sid_buf.buf, 1);
}

const char *tr2_sid_get(void)
{
if (!tr2sid_buf.len)
tr2_sid_compute();

return tr2sid_buf.buf;
}

int tr2_sid_depth(void)
{
if (!tr2sid_buf.len)
tr2_sid_compute();

return tr2sid_nr_git_parents;
}

void tr2_sid_release(void)
{
strbuf_release(&tr2sid_buf);
}

18
trace2/tr2_sid.h
Unescape View File

@ -0,0 +1,18 @@ @@ -0,0 +1,18 @@
#ifndef TR2_SID_H
#define TR2_SID_H

/*
* Get our session id. Compute if necessary.
*/
const char *tr2_sid_get(void);

/*
* Get our process depth. A top-level git process invoked from the
* command line will have depth=0. A child git process will have
* depth=1 and so on.
*/
int tr2_sid_depth(void);

void tr2_sid_release(void);

#endif /* TR2_SID_H */

32
trace2/tr2_tbuf.c
Unescape View File

@ -0,0 +1,32 @@ @@ -0,0 +1,32 @@
#include "cache.h"
#include "tr2_tbuf.h"

void tr2_tbuf_local_time(struct tr2_tbuf *tb)
{
struct timeval tv;
struct tm tm;
time_t secs;

gettimeofday(&tv, NULL);
secs = tv.tv_sec;
localtime_r(&secs, &tm);

xsnprintf(tb->buf, sizeof(tb->buf), "%02d:%02d:%02d.%06ld", tm.tm_hour,
tm.tm_min, tm.tm_sec, (long)tv.tv_usec);
}

void tr2_tbuf_utc_time(struct tr2_tbuf *tb)
{
struct timeval tv;
struct tm tm;
time_t secs;

gettimeofday(&tv, NULL);
secs = tv.tv_sec;
gmtime_r(&secs, &tm);

xsnprintf(tb->buf, sizeof(tb->buf),
"%4d-%02d-%02d %02d:%02d:%02d.%06ld", tm.tm_year + 1900,
tm.tm_mon + 1, tm.tm_mday, tm.tm_hour, tm.tm_min, tm.tm_sec,
(long)tv.tv_usec);
}

23
trace2/tr2_tbuf.h
Unescape View File

@ -0,0 +1,23 @@ @@ -0,0 +1,23 @@
#ifndef TR2_TBUF_H
#define TR2_TBUF_H

/*
* A simple wrapper around a fixed buffer to avoid C syntax
* quirks and the need to pass around an additional size_t
* argument.
*/
struct tr2_tbuf {
char buf[32];
};

/*
* Fill buffer with formatted local time string.
*/
void tr2_tbuf_local_time(struct tr2_tbuf *tb);

/*
* Fill buffer with formatted UTC time string.
*/
void tr2_tbuf_utc_time(struct tr2_tbuf *tb);

#endif /* TR2_TBUF_H */

133
trace2/tr2_tgt.h
Unescape View File

@ -0,0 +1,133 @@ @@ -0,0 +1,133 @@
#ifndef TR2_TGT_H
#define TR2_TGT_H

struct child_process;
struct repository;
struct json_writer;

/*
* Function prototypes for a TRACE2 "target" vtable.
*/

typedef int(tr2_tgt_init_t)(void);
typedef void(tr2_tgt_term_t)(void);

typedef void(tr2_tgt_evt_version_fl_t)(const char *file, int line);

typedef void(tr2_tgt_evt_start_fl_t)(const char *file, int line,
const char **argv);
typedef void(tr2_tgt_evt_exit_fl_t)(const char *file, int line,
uint64_t us_elapsed_absolute, int code);
typedef void(tr2_tgt_evt_signal_t)(uint64_t us_elapsed_absolute, int signo);
typedef void(tr2_tgt_evt_atexit_t)(uint64_t us_elapsed_absolute, int code);

typedef void(tr2_tgt_evt_error_va_fl_t)(const char *file, int line,
const char *fmt, va_list ap);

typedef void(tr2_tgt_evt_command_path_fl_t)(const char *file, int line,
const char *command_path);
typedef void(tr2_tgt_evt_command_name_fl_t)(const char *file, int line,
const char *name,
const char *hierarchy);
typedef void(tr2_tgt_evt_command_mode_fl_t)(const char *file, int line,
const char *mode);

typedef void(tr2_tgt_evt_alias_fl_t)(const char *file, int line,
const char *alias, const char **argv);

typedef void(tr2_tgt_evt_child_start_fl_t)(const char *file, int line,
uint64_t us_elapsed_absolute,
const struct child_process *cmd);
typedef void(tr2_tgt_evt_child_exit_fl_t)(const char *file, int line,
uint64_t us_elapsed_absolute, int cid,
int pid, int code,
uint64_t us_elapsed_child);

typedef void(tr2_tgt_evt_thread_start_fl_t)(const char *file, int line,
uint64_t us_elapsed_absolute);
typedef void(tr2_tgt_evt_thread_exit_fl_t)(const char *file, int line,
uint64_t us_elapsed_absolute,
uint64_t us_elapsed_thread);

typedef void(tr2_tgt_evt_exec_fl_t)(const char *file, int line,
uint64_t us_elapsed_absolute, int exec_id,
const char *exe, const char **argv);
typedef void(tr2_tgt_evt_exec_result_fl_t)(const char *file, int line,
uint64_t us_elapsed_absolute,
int exec_id, int code);

typedef void(tr2_tgt_evt_param_fl_t)(const char *file, int line,
const char *param, const char *value);

typedef void(tr2_tgt_evt_repo_fl_t)(const char *file, int line,
const struct repository *repo);

typedef void(tr2_tgt_evt_region_enter_printf_va_fl_t)(
const char *file, int line, uint64_t us_elapsed_absolute,
const char *category, const char *label, const struct repository *repo,
const char *fmt, va_list ap);
typedef void(tr2_tgt_evt_region_leave_printf_va_fl_t)(
const char *file, int line, uint64_t us_elapsed_absolute,
uint64_t us_elapsed_region, const char *category, const char *label,
const struct repository *repo, const char *fmt, va_list ap);

typedef void(tr2_tgt_evt_data_fl_t)(const char *file, int line,
uint64_t us_elapsed_absolute,
uint64_t us_elapsed_region,
const char *category,
const struct repository *repo,
const char *key, const char *value);
typedef void(tr2_tgt_evt_data_json_fl_t)(const char *file, int line,
uint64_t us_elapsed_absolute,
uint64_t us_elapsed_region,
const char *category,
const struct repository *repo,
const char *key,
const struct json_writer *value);

typedef void(tr2_tgt_evt_printf_va_fl_t)(const char *file, int line,
uint64_t us_elapsed_absolute,
const char *fmt, va_list ap);

/*
* "vtable" for a TRACE2 target. Use NULL if a target does not want
* to emit that message.
*/
/* clang-format off */
struct tr2_tgt {
struct tr2_dst *pdst;

tr2_tgt_init_t *pfn_init;
tr2_tgt_term_t *pfn_term;

tr2_tgt_evt_version_fl_t *pfn_version_fl;
tr2_tgt_evt_start_fl_t *pfn_start_fl;
tr2_tgt_evt_exit_fl_t *pfn_exit_fl;
tr2_tgt_evt_signal_t *pfn_signal;
tr2_tgt_evt_atexit_t *pfn_atexit;
tr2_tgt_evt_error_va_fl_t *pfn_error_va_fl;
tr2_tgt_evt_command_path_fl_t *pfn_command_path_fl;
tr2_tgt_evt_command_name_fl_t *pfn_command_name_fl;
tr2_tgt_evt_command_mode_fl_t *pfn_command_mode_fl;
tr2_tgt_evt_alias_fl_t *pfn_alias_fl;
tr2_tgt_evt_child_start_fl_t *pfn_child_start_fl;
tr2_tgt_evt_child_exit_fl_t *pfn_child_exit_fl;
tr2_tgt_evt_thread_start_fl_t *pfn_thread_start_fl;
tr2_tgt_evt_thread_exit_fl_t *pfn_thread_exit_fl;
tr2_tgt_evt_exec_fl_t *pfn_exec_fl;
tr2_tgt_evt_exec_result_fl_t *pfn_exec_result_fl;
tr2_tgt_evt_param_fl_t *pfn_param_fl;
tr2_tgt_evt_repo_fl_t *pfn_repo_fl;
tr2_tgt_evt_region_enter_printf_va_fl_t *pfn_region_enter_printf_va_fl;
tr2_tgt_evt_region_leave_printf_va_fl_t *pfn_region_leave_printf_va_fl;
tr2_tgt_evt_data_fl_t *pfn_data_fl;
tr2_tgt_evt_data_json_fl_t *pfn_data_json_fl;
tr2_tgt_evt_printf_va_fl_t *pfn_printf_va_fl;
};
/* clang-format on */

extern struct tr2_tgt tr2_tgt_event;
extern struct tr2_tgt tr2_tgt_normal;
extern struct tr2_tgt tr2_tgt_perf;

#endif /* TR2_TGT_H */

588
trace2/tr2_tgt_event.c
Unescape View File

@ -0,0 +1,588 @@ @@ -0,0 +1,588 @@
#include "cache.h"
#include "config.h"
#include "json-writer.h"
#include "run-command.h"
#include "version.h"
#include "trace2/tr2_dst.h"
#include "trace2/tr2_tbuf.h"
#include "trace2/tr2_sid.h"
#include "trace2/tr2_tgt.h"
#include "trace2/tr2_tls.h"

static struct tr2_dst tr2dst_event = { "GIT_TR2_EVENT", 0, 0, 0 };

/*
* The version number of the JSON data generated by the EVENT target
* in this source file. Update this if you make a significant change
* to the JSON fields or message structure. You probably do not need
* to update this if you just add another call to one of the existing
* TRACE2 API methods.
*/
#define TR2_EVENT_VERSION "1"

/*
* Region nesting limit for messages written to the event target.
*
* The "region_enter" and "region_leave" messages (especially recursive
* messages such as those produced while diving the worktree or index)
* are primarily intended for the performance target during debugging.
*
* Some of the outer-most messages, however, may be of interest to the
* event target. Set this environment variable to a larger integer for
* more detail in the event target.
*/
#define TR2_ENVVAR_EVENT_NESTING "GIT_TR2_EVENT_NESTING"
static int tr2env_event_nesting_wanted = 2;

/*
* Set this environment variable to true to omit the <time>, <file>, and
* <line> fields from most events.
*/
#define TR2_ENVVAR_EVENT_BRIEF "GIT_TR2_EVENT_BRIEF"
static int tr2env_event_brief;

static int fn_init(void)
{
int want = tr2_dst_trace_want(&tr2dst_event);
int want_nesting;
int want_brief;
char *nesting;
char *brief;

if (!want)
return want;

nesting = getenv(TR2_ENVVAR_EVENT_NESTING);
if (nesting && ((want_nesting = atoi(nesting)) > 0))
tr2env_event_nesting_wanted = want_nesting;

brief = getenv(TR2_ENVVAR_EVENT_BRIEF);
if (brief && ((want_brief = atoi(brief)) > 0))
tr2env_event_brief = want_brief;

return want;
}

static void fn_term(void)
{
tr2_dst_trace_disable(&tr2dst_event);
}

/*
* Append common key-value pairs to the currently open JSON object.
* "event:"<event_name>"
* "sid":"<sid>"
* "thread":"<thread_name>"
* "time":"<time>"
* "file":"<filename>"
* "line":<line_number>
* "repo":<repo_id>
*/
static void event_fmt_prepare(const char *event_name, const char *file,
int line, const struct repository *repo,
struct json_writer *jw)
{
struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
struct tr2_tbuf tb_now;

jw_object_string(jw, "event", event_name);
jw_object_string(jw, "sid", tr2_sid_get());
jw_object_string(jw, "thread", ctx->thread_name.buf);

/*
* In brief mode, only emit <time> on these 2 event types.
*/
if (!tr2env_event_brief || !strcmp(event_name, "version") ||
!strcmp(event_name, "atexit")) {
tr2_tbuf_utc_time(&tb_now);
jw_object_string(jw, "time", tb_now.buf);
}

if (!tr2env_event_brief && file && *file) {
jw_object_string(jw, "file", file);
jw_object_intmax(jw, "line", line);
}

if (repo)
jw_object_intmax(jw, "repo", repo->trace2_repo_id);
}

static void fn_version_fl(const char *file, int line)
{
const char *event_name = "version";
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_object_string(&jw, "evt", TR2_EVENT_VERSION);
jw_object_string(&jw, "exe", git_version_string);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_start_fl(const char *file, int line, const char **argv)
{
const char *event_name = "start";
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_object_inline_begin_array(&jw, "argv");
jw_array_argv(&jw, argv);
jw_end(&jw);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute,
int code)
{
const char *event_name = "exit";
struct json_writer jw = JSON_WRITER_INIT;
double t_abs = (double)us_elapsed_absolute / 1000000.0;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_object_double(&jw, "t_abs", 6, t_abs);
jw_object_intmax(&jw, "code", code);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_signal(uint64_t us_elapsed_absolute, int signo)
{
const char *event_name = "signal";
struct json_writer jw = JSON_WRITER_INIT;
double t_abs = (double)us_elapsed_absolute / 1000000.0;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw);
jw_object_double(&jw, "t_abs", 6, t_abs);
jw_object_intmax(&jw, "signo", signo);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_atexit(uint64_t us_elapsed_absolute, int code)
{
const char *event_name = "atexit";
struct json_writer jw = JSON_WRITER_INIT;
double t_abs = (double)us_elapsed_absolute / 1000000.0;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw);
jw_object_double(&jw, "t_abs", 6, t_abs);
jw_object_intmax(&jw, "code", code);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void maybe_add_string_va(struct json_writer *jw, const char *field_name,
const char *fmt, va_list ap)
{
if (fmt && *fmt && ap) {
va_list copy_ap;
struct strbuf buf = STRBUF_INIT;

va_copy(copy_ap, ap);
strbuf_vaddf(&buf, fmt, copy_ap);
va_end(copy_ap);

jw_object_string(jw, field_name, buf.buf);
strbuf_release(&buf);
return;
}

if (fmt && *fmt) {
jw_object_string(jw, field_name, fmt);
return;
}
}

static void fn_error_va_fl(const char *file, int line, const char *fmt,
va_list ap)
{
const char *event_name = "error";
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
maybe_add_string_va(&jw, "msg", fmt, ap);
/*
* Also emit the format string as a field in case
* post-processors want to aggregate common error
* messages by type without argument fields (such
* as pathnames or branch names) cluttering it up.
*/
if (fmt && *fmt)
jw_object_string(&jw, "fmt", fmt);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_command_path_fl(const char *file, int line, const char *pathname)
{
const char *event_name = "cmd_path";
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_object_string(&jw, "path", pathname);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_command_name_fl(const char *file, int line, const char *name,
const char *hierarchy)
{
const char *event_name = "cmd_name";
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_object_string(&jw, "name", name);
if (hierarchy && *hierarchy)
jw_object_string(&jw, "hierarchy", hierarchy);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_command_mode_fl(const char *file, int line, const char *mode)
{
const char *event_name = "cmd_mode";
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_object_string(&jw, "name", mode);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_alias_fl(const char *file, int line, const char *alias,
const char **argv)
{
const char *event_name = "alias";
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_object_string(&jw, "alias", alias);
jw_object_inline_begin_array(&jw, "argv");
jw_array_argv(&jw, argv);
jw_end(&jw);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_child_start_fl(const char *file, int line,
uint64_t us_elapsed_absolute,
const struct child_process *cmd)
{
const char *event_name = "child_start";
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_object_intmax(&jw, "child_id", cmd->trace2_child_id);
if (cmd->trace2_hook_name) {
jw_object_string(&jw, "child_class", "hook");
jw_object_string(&jw, "hook_name", cmd->trace2_hook_name);
} else {
const char *child_class =
cmd->trace2_child_class ? cmd->trace2_child_class : "?";
jw_object_string(&jw, "child_class", child_class);
}
if (cmd->dir)
jw_object_string(&jw, "cd", cmd->dir);
jw_object_bool(&jw, "use_shell", cmd->use_shell);
jw_object_inline_begin_array(&jw, "argv");
if (cmd->git_cmd)
jw_array_string(&jw, "git");
jw_array_argv(&jw, cmd->argv);
jw_end(&jw);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_child_exit_fl(const char *file, int line,
uint64_t us_elapsed_absolute, int cid, int pid,
int code, uint64_t us_elapsed_child)
{
const char *event_name = "child_exit";
struct json_writer jw = JSON_WRITER_INIT;
double t_rel = (double)us_elapsed_child / 1000000.0;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_object_intmax(&jw, "child_id", cid);
jw_object_intmax(&jw, "pid", pid);
jw_object_intmax(&jw, "code", code);
jw_object_double(&jw, "t_rel", 6, t_rel);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);

jw_release(&jw);
}

static void fn_thread_start_fl(const char *file, int line,
uint64_t us_elapsed_absolute)
{
const char *event_name = "thread_start";
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_thread_exit_fl(const char *file, int line,
uint64_t us_elapsed_absolute,
uint64_t us_elapsed_thread)
{
const char *event_name = "thread_exit";
struct json_writer jw = JSON_WRITER_INIT;
double t_rel = (double)us_elapsed_thread / 1000000.0;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_object_double(&jw, "t_rel", 6, t_rel);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute,
int exec_id, const char *exe, const char **argv)
{
const char *event_name = "exec";
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_object_intmax(&jw, "exec_id", exec_id);
if (exe)
jw_object_string(&jw, "exe", exe);
jw_object_inline_begin_array(&jw, "argv");
jw_array_argv(&jw, argv);
jw_end(&jw);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_exec_result_fl(const char *file, int line,
uint64_t us_elapsed_absolute, int exec_id,
int code)
{
const char *event_name = "exec_result";
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_object_intmax(&jw, "exec_id", exec_id);
jw_object_intmax(&jw, "code", code);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_param_fl(const char *file, int line, const char *param,
const char *value)
{
const char *event_name = "def_param";
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, NULL, &jw);
jw_object_string(&jw, "param", param);
jw_object_string(&jw, "value", value);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_repo_fl(const char *file, int line,
const struct repository *repo)
{
const char *event_name = "def_repo";
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, repo, &jw);
jw_object_string(&jw, "worktree", repo->worktree);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}

static void fn_region_enter_printf_va_fl(const char *file, int line,
uint64_t us_elapsed_absolute,
const char *category,
const char *label,
const struct repository *repo,
const char *fmt, va_list ap)
{
const char *event_name = "region_enter";
struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) {
struct json_writer jw = JSON_WRITER_INIT;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, repo, &jw);
jw_object_intmax(&jw, "nesting", ctx->nr_open_regions);
if (category)
jw_object_string(&jw, "category", category);
if (label)
jw_object_string(&jw, "label", label);
maybe_add_string_va(&jw, "msg", fmt, ap);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}
}

static void fn_region_leave_printf_va_fl(
const char *file, int line, uint64_t us_elapsed_absolute,
uint64_t us_elapsed_region, const char *category, const char *label,
const struct repository *repo, const char *fmt, va_list ap)
{
const char *event_name = "region_leave";
struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) {
struct json_writer jw = JSON_WRITER_INIT;
double t_rel = (double)us_elapsed_region / 1000000.0;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, repo, &jw);
jw_object_double(&jw, "t_rel", 6, t_rel);
jw_object_intmax(&jw, "nesting", ctx->nr_open_regions);
if (category)
jw_object_string(&jw, "category", category);
if (label)
jw_object_string(&jw, "label", label);
maybe_add_string_va(&jw, "msg", fmt, ap);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}
}

static void fn_data_fl(const char *file, int line, uint64_t us_elapsed_absolute,
uint64_t us_elapsed_region, const char *category,
const struct repository *repo, const char *key,
const char *value)
{
const char *event_name = "data";
struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) {
struct json_writer jw = JSON_WRITER_INIT;
double t_abs = (double)us_elapsed_absolute / 1000000.0;
double t_rel = (double)us_elapsed_region / 1000000.0;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, repo, &jw);
jw_object_double(&jw, "t_abs", 6, t_abs);
jw_object_double(&jw, "t_rel", 6, t_rel);
jw_object_intmax(&jw, "nesting", ctx->nr_open_regions);
jw_object_string(&jw, "category", category);
jw_object_string(&jw, "key", key);
jw_object_string(&jw, "value", value);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}
}

static void fn_data_json_fl(const char *file, int line,
uint64_t us_elapsed_absolute,
uint64_t us_elapsed_region, const char *category,
const struct repository *repo, const char *key,
const struct json_writer *value)
{
const char *event_name = "data_json";
struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) {
struct json_writer jw = JSON_WRITER_INIT;
double t_abs = (double)us_elapsed_absolute / 1000000.0;
double t_rel = (double)us_elapsed_region / 1000000.0;

jw_object_begin(&jw, 0);
event_fmt_prepare(event_name, file, line, repo, &jw);
jw_object_double(&jw, "t_abs", 6, t_abs);
jw_object_double(&jw, "t_rel", 6, t_rel);
jw_object_intmax(&jw, "nesting", ctx->nr_open_regions);
jw_object_string(&jw, "category", category);
jw_object_string(&jw, "key", key);
jw_object_sub_jw(&jw, "value", value);
jw_end(&jw);

tr2_dst_write_line(&tr2dst_event, &jw.json);
jw_release(&jw);
}
}

struct tr2_tgt tr2_tgt_event = {
&tr2dst_event,

fn_init,
fn_term,

fn_version_fl,
fn_start_fl,
fn_exit_fl,
fn_signal,
fn_atexit,
fn_error_va_fl,
fn_command_path_fl,
fn_command_name_fl,
fn_command_mode_fl,
fn_alias_fl,
fn_child_start_fl,
fn_child_exit_fl,
fn_thread_start_fl,
fn_thread_exit_fl,
fn_exec_fl,
fn_exec_result_fl,
fn_param_fl,
fn_repo_fl,
fn_region_enter_printf_va_fl,
fn_region_leave_printf_va_fl,
fn_data_fl,
fn_data_json_fl,
NULL, /* printf */
};

323
trace2/tr2_tgt_normal.c
Unescape View File

@ -0,0 +1,323 @@ @@ -0,0 +1,323 @@
#include "cache.h"
#include "config.h"
#include "run-command.h"
#include "quote.h"
#include "version.h"
#include "trace2/tr2_dst.h"
#include "trace2/tr2_tbuf.h"
#include "trace2/tr2_tgt.h"
#include "trace2/tr2_tls.h"

static struct tr2_dst tr2dst_normal = { "GIT_TR2", 0, 0, 0 };

/*
* Set this environment variable to true to omit the "<time> <file>:<line>"
* fields from each line written to the builtin normal target.
*
* Unit tests may want to use this to help with testing.
*/
#define TR2_ENVVAR_NORMAL_BRIEF "GIT_TR2_BRIEF"
static int tr2env_normal_brief;

#define TR2FMT_NORMAL_FL_WIDTH (50)

static int fn_init(void)
{
int want = tr2_dst_trace_want(&tr2dst_normal);
int want_brief;
char *brief;

if (!want)
return want;

brief = getenv(TR2_ENVVAR_NORMAL_BRIEF);
if (brief && *brief &&
((want_brief = git_parse_maybe_bool(brief)) != -1))
tr2env_normal_brief = want_brief;

return want;
}

static void fn_term(void)
{
tr2_dst_trace_disable(&tr2dst_normal);
}

static void normal_fmt_prepare(const char *file, int line, struct strbuf *buf)
{
strbuf_setlen(buf, 0);

if (!tr2env_normal_brief) {
struct tr2_tbuf tb_now;

tr2_tbuf_local_time(&tb_now);
strbuf_addstr(buf, tb_now.buf);
strbuf_addch(buf, ' ');

if (file && *file)
strbuf_addf(buf, "%s:%d ", file, line);
while (buf->len < TR2FMT_NORMAL_FL_WIDTH)
strbuf_addch(buf, ' ');
}
}

static void normal_io_write_fl(const char *file, int line,
const struct strbuf *buf_payload)
{
struct strbuf buf_line = STRBUF_INIT;

normal_fmt_prepare(file, line, &buf_line);
strbuf_addbuf(&buf_line, buf_payload);
tr2_dst_write_line(&tr2dst_normal, &buf_line);
strbuf_release(&buf_line);
}

static void fn_version_fl(const char *file, int line)
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "version %s", git_version_string);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_start_fl(const char *file, int line, const char **argv)
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addstr(&buf_payload, "start ");
sq_quote_argv_pretty(&buf_payload, argv);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute,
int code)
{
struct strbuf buf_payload = STRBUF_INIT;
double elapsed = (double)us_elapsed_absolute / 1000000.0;

strbuf_addf(&buf_payload, "exit elapsed:%.6f code:%d", elapsed, code);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_signal(uint64_t us_elapsed_absolute, int signo)
{
struct strbuf buf_payload = STRBUF_INIT;
double elapsed = (double)us_elapsed_absolute / 1000000.0;

strbuf_addf(&buf_payload, "signal elapsed:%.6f code:%d", elapsed,
signo);
normal_io_write_fl(__FILE__, __LINE__, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_atexit(uint64_t us_elapsed_absolute, int code)
{
struct strbuf buf_payload = STRBUF_INIT;
double elapsed = (double)us_elapsed_absolute / 1000000.0;

strbuf_addf(&buf_payload, "atexit elapsed:%.6f code:%d", elapsed, code);
normal_io_write_fl(__FILE__, __LINE__, &buf_payload);
strbuf_release(&buf_payload);
}

static void maybe_append_string_va(struct strbuf *buf, const char *fmt,
va_list ap)
{
if (fmt && *fmt && ap) {
va_list copy_ap;

va_copy(copy_ap, ap);
strbuf_vaddf(buf, fmt, copy_ap);
va_end(copy_ap);
return;
}

if (fmt && *fmt) {
strbuf_addstr(buf, fmt);
return;
}
}

static void fn_error_va_fl(const char *file, int line, const char *fmt,
va_list ap)
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addstr(&buf_payload, "error ");
maybe_append_string_va(&buf_payload, fmt, ap);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_command_path_fl(const char *file, int line, const char *pathname)
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "cmd_path %s", pathname);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_command_name_fl(const char *file, int line, const char *name,
const char *hierarchy)
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "cmd_name %s", name);
if (hierarchy && *hierarchy)
strbuf_addf(&buf_payload, " (%s)", hierarchy);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_command_mode_fl(const char *file, int line, const char *mode)
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "cmd_mode %s", mode);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_alias_fl(const char *file, int line, const char *alias,
const char **argv)
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "alias %s ->", alias);
sq_quote_argv_pretty(&buf_payload, argv);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_child_start_fl(const char *file, int line,
uint64_t us_elapsed_absolute,
const struct child_process *cmd)
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "child_start[%d] ", cmd->trace2_child_id);

if (cmd->dir) {
strbuf_addstr(&buf_payload, " cd");
sq_quote_buf_pretty(&buf_payload, cmd->dir);
strbuf_addstr(&buf_payload, "; ");
}

/*
* TODO if (cmd->env) { Consider dumping changes to environment. }
* See trace_add_env() in run-command.c as used by original trace.c
*/

if (cmd->git_cmd)
strbuf_addstr(&buf_payload, "git");
sq_quote_argv_pretty(&buf_payload, cmd->argv);

normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_child_exit_fl(const char *file, int line,
uint64_t us_elapsed_absolute, int cid, int pid,
int code, uint64_t us_elapsed_child)
{
struct strbuf buf_payload = STRBUF_INIT;
double elapsed = (double)us_elapsed_child / 1000000.0;

strbuf_addf(&buf_payload, "child_exit[%d] pid:%d code:%d elapsed:%.6f",
cid, pid, code, elapsed);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute,
int exec_id, const char *exe, const char **argv)
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "exec[%d] ", exec_id);
if (exe)
strbuf_addstr(&buf_payload, exe);
sq_quote_argv_pretty(&buf_payload, argv);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_exec_result_fl(const char *file, int line,
uint64_t us_elapsed_absolute, int exec_id,
int code)
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "exec_result[%d] code:%d", exec_id, code);
if (code > 0)
strbuf_addf(&buf_payload, " err:%s", strerror(code));
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_param_fl(const char *file, int line, const char *param,
const char *value)
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "def_param %s=%s", param, value);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_repo_fl(const char *file, int line,
const struct repository *repo)
{
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addstr(&buf_payload, "worktree ");
sq_quote_buf_pretty(&buf_payload, repo->worktree);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_printf_va_fl(const char *file, int line,
uint64_t us_elapsed_absolute, const char *fmt,
va_list ap)
{
struct strbuf buf_payload = STRBUF_INIT;

maybe_append_string_va(&buf_payload, fmt, ap);
normal_io_write_fl(file, line, &buf_payload);
strbuf_release(&buf_payload);
}

struct tr2_tgt tr2_tgt_normal = {
&tr2dst_normal,

fn_init,
fn_term,

fn_version_fl,
fn_start_fl,
fn_exit_fl,
fn_signal,
fn_atexit,
fn_error_va_fl,
fn_command_path_fl,
fn_command_name_fl,
fn_command_mode_fl,
fn_alias_fl,
fn_child_start_fl,
fn_child_exit_fl,
NULL, /* thread_start */
NULL, /* thread_exit */
fn_exec_fl,
fn_exec_result_fl,
fn_param_fl,
fn_repo_fl,
NULL, /* region_enter */
NULL, /* region_leave */
NULL, /* data */
NULL, /* data_json */
fn_printf_va_fl,
};

534
trace2/tr2_tgt_perf.c
Unescape View File

@ -0,0 +1,534 @@ @@ -0,0 +1,534 @@
#include "cache.h"
#include "config.h"
#include "run-command.h"
#include "quote.h"
#include "version.h"
#include "json-writer.h"
#include "trace2/tr2_dst.h"
#include "trace2/tr2_sid.h"
#include "trace2/tr2_tbuf.h"
#include "trace2/tr2_tgt.h"
#include "trace2/tr2_tls.h"

static struct tr2_dst tr2dst_perf = { "GIT_TR2_PERF", 0, 0, 0 };

/*
* Set this environment variable to true to omit the "<time> <file>:<line>"
* fields from each line written to the builtin performance target.
*
* Unit tests may want to use this to help with testing.
*/
#define TR2_ENVVAR_PERF_BRIEF "GIT_TR2_PERF_BRIEF"
static int tr2env_perf_brief;

#define TR2FMT_PERF_FL_WIDTH (50)
#define TR2FMT_PERF_MAX_EVENT_NAME (12)
#define TR2FMT_PERF_REPO_WIDTH (4)
#define TR2FMT_PERF_CATEGORY_WIDTH (10)

#define TR2_DOTS_BUFFER_SIZE (100)
#define TR2_INDENT (2)
#define TR2_INDENT_LENGTH(ctx) (((ctx)->nr_open_regions - 1) * TR2_INDENT)

static struct strbuf dots = STRBUF_INIT;

static int fn_init(void)
{
int want = tr2_dst_trace_want(&tr2dst_perf);
int want_brief;
char *brief;

if (!want)
return want;

strbuf_addchars(&dots, '.', TR2_DOTS_BUFFER_SIZE);

brief = getenv(TR2_ENVVAR_PERF_BRIEF);
if (brief && *brief &&
((want_brief = git_parse_maybe_bool(brief)) != -1))
tr2env_perf_brief = want_brief;

return want;
}

static void fn_term(void)
{
tr2_dst_trace_disable(&tr2dst_perf);

strbuf_release(&dots);
}

/*
* Format trace line prefix in human-readable classic format for
* the performance target:
* "[<time> [<file>:<line>] <bar>] <nr_parents> <bar>
* <thread_name> <bar> <event_name> <bar> [<repo>] <bar>
* [<elapsed_absolute>] [<elapsed_relative>] <bar>
* [<category>] <bar> [<dots>] "
*/
static void perf_fmt_prepare(const char *event_name,
struct tr2tls_thread_ctx *ctx, const char *file,
int line, const struct repository *repo,
uint64_t *p_us_elapsed_absolute,
uint64_t *p_us_elapsed_relative,
const char *category, struct strbuf *buf)
{
int len;

strbuf_setlen(buf, 0);

if (!tr2env_perf_brief) {
struct tr2_tbuf tb_now;

tr2_tbuf_local_time(&tb_now);
strbuf_addstr(buf, tb_now.buf);
strbuf_addch(buf, ' ');

if (file && *file)
strbuf_addf(buf, "%s:%d ", file, line);
while (buf->len < TR2FMT_PERF_FL_WIDTH)
strbuf_addch(buf, ' ');

strbuf_addstr(buf, "| ");
}

strbuf_addf(buf, "d%d | ", tr2_sid_depth());
strbuf_addf(buf, "%-*s | %-*s | ", TR2_MAX_THREAD_NAME,
ctx->thread_name.buf, TR2FMT_PERF_MAX_EVENT_NAME,
event_name);

len = buf->len + TR2FMT_PERF_REPO_WIDTH;
if (repo)
strbuf_addf(buf, "r%d ", repo->trace2_repo_id);
while (buf->len < len)
strbuf_addch(buf, ' ');
strbuf_addstr(buf, "| ");

if (p_us_elapsed_absolute)
strbuf_addf(buf, "%9.6f | ",
((double)(*p_us_elapsed_absolute)) / 1000000.0);
else
strbuf_addf(buf, "%9s | ", " ");

if (p_us_elapsed_relative)
strbuf_addf(buf, "%9.6f | ",
((double)(*p_us_elapsed_relative)) / 1000000.0);
else
strbuf_addf(buf, "%9s | ", " ");

strbuf_addf(buf, "%-*s | ", TR2FMT_PERF_CATEGORY_WIDTH,
(category ? category : ""));

if (ctx->nr_open_regions > 0) {
int len_indent = TR2_INDENT_LENGTH(ctx);
while (len_indent > dots.len) {
strbuf_addbuf(buf, &dots);
len_indent -= dots.len;
}
strbuf_addf(buf, "%.*s", len_indent, dots.buf);
}
}

static void perf_io_write_fl(const char *file, int line, const char *event_name,
const struct repository *repo,
uint64_t *p_us_elapsed_absolute,
uint64_t *p_us_elapsed_relative,
const char *category,
const struct strbuf *buf_payload)
{
struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
struct strbuf buf_line = STRBUF_INIT;

perf_fmt_prepare(event_name, ctx, file, line, repo,
p_us_elapsed_absolute, p_us_elapsed_relative, category,
&buf_line);
strbuf_addbuf(&buf_line, buf_payload);
tr2_dst_write_line(&tr2dst_perf, &buf_line);
strbuf_release(&buf_line);
}

static void fn_version_fl(const char *file, int line)
{
const char *event_name = "version";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addstr(&buf_payload, git_version_string);

perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
&buf_payload);
strbuf_release(&buf_payload);
}

static void fn_start_fl(const char *file, int line, const char **argv)
{
const char *event_name = "start";
struct strbuf buf_payload = STRBUF_INIT;

sq_quote_argv_pretty(&buf_payload, argv);

perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
&buf_payload);
strbuf_release(&buf_payload);
}

static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute,
int code)
{
const char *event_name = "exit";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "code:%d", code);

perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
NULL, NULL, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_signal(uint64_t us_elapsed_absolute, int signo)
{
const char *event_name = "signal";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "signo:%d", signo);

perf_io_write_fl(__FILE__, __LINE__, event_name, NULL,
&us_elapsed_absolute, NULL, NULL, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_atexit(uint64_t us_elapsed_absolute, int code)
{
const char *event_name = "atexit";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "code:%d", code);

perf_io_write_fl(__FILE__, __LINE__, event_name, NULL,
&us_elapsed_absolute, NULL, NULL, &buf_payload);
strbuf_release(&buf_payload);
}

static void maybe_append_string_va(struct strbuf *buf, const char *fmt,
va_list ap)
{
if (fmt && *fmt && ap) {
va_list copy_ap;

va_copy(copy_ap, ap);
strbuf_vaddf(buf, fmt, copy_ap);
va_end(copy_ap);
return;
}

if (fmt && *fmt) {
strbuf_addstr(buf, fmt);
return;
}
}

static void fn_error_va_fl(const char *file, int line, const char *fmt,
va_list ap)
{
const char *event_name = "error";
struct strbuf buf_payload = STRBUF_INIT;

maybe_append_string_va(&buf_payload, fmt, ap);

perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
&buf_payload);
strbuf_release(&buf_payload);
}

static void fn_command_path_fl(const char *file, int line, const char *pathname)
{
const char *event_name = "cmd_path";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addstr(&buf_payload, pathname);

perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
&buf_payload);
strbuf_release(&buf_payload);
}

static void fn_command_name_fl(const char *file, int line, const char *name,
const char *hierarchy)
{
const char *event_name = "cmd_name";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addstr(&buf_payload, name);
if (hierarchy && *hierarchy)
strbuf_addf(&buf_payload, " (%s)", hierarchy);

perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
&buf_payload);
strbuf_release(&buf_payload);
}

static void fn_command_mode_fl(const char *file, int line, const char *mode)
{
const char *event_name = "cmd_mode";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addstr(&buf_payload, mode);

perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
&buf_payload);
strbuf_release(&buf_payload);
}

static void fn_alias_fl(const char *file, int line, const char *alias,
const char **argv)
{
const char *event_name = "alias";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "alias:%s argv:", alias);
sq_quote_argv_pretty(&buf_payload, argv);

perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
&buf_payload);
strbuf_release(&buf_payload);
}

static void fn_child_start_fl(const char *file, int line,
uint64_t us_elapsed_absolute,
const struct child_process *cmd)
{
const char *event_name = "child_start";
struct strbuf buf_payload = STRBUF_INIT;

if (cmd->trace2_hook_name) {
strbuf_addf(&buf_payload, "[ch%d] class:hook hook:%s",
cmd->trace2_child_id, cmd->trace2_hook_name);
} else {
const char *child_class =
cmd->trace2_child_class ? cmd->trace2_child_class : "?";
strbuf_addf(&buf_payload, "[ch%d] class:%s",
cmd->trace2_child_id, child_class);
}

if (cmd->dir) {
strbuf_addstr(&buf_payload, " cd:");
sq_quote_buf_pretty(&buf_payload, cmd->dir);
}

strbuf_addstr(&buf_payload, " argv:");
if (cmd->git_cmd)
strbuf_addstr(&buf_payload, " git");
sq_quote_argv_pretty(&buf_payload, cmd->argv);

perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
NULL, NULL, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_child_exit_fl(const char *file, int line,
uint64_t us_elapsed_absolute, int cid, int pid,
int code, uint64_t us_elapsed_child)
{
const char *event_name = "child_exit";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "[ch%d] pid:%d code:%d", cid, pid, code);

perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
&us_elapsed_child, NULL, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_thread_start_fl(const char *file, int line,
uint64_t us_elapsed_absolute)
{
const char *event_name = "thread_start";
struct strbuf buf_payload = STRBUF_INIT;

perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
NULL, NULL, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_thread_exit_fl(const char *file, int line,
uint64_t us_elapsed_absolute,
uint64_t us_elapsed_thread)
{
const char *event_name = "thread_exit";
struct strbuf buf_payload = STRBUF_INIT;

perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
&us_elapsed_thread, NULL, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute,
int exec_id, const char *exe, const char **argv)
{
const char *event_name = "exec";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "id:%d ", exec_id);
strbuf_addstr(&buf_payload, "argv:");
if (exe)
strbuf_addf(&buf_payload, " %s", exe);
sq_quote_argv_pretty(&buf_payload, argv);

perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
NULL, NULL, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_exec_result_fl(const char *file, int line,
uint64_t us_elapsed_absolute, int exec_id,
int code)
{
const char *event_name = "exec_result";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "id:%d code:%d", exec_id, code);
if (code > 0)
strbuf_addf(&buf_payload, " err:%s", strerror(code));

perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
NULL, NULL, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_param_fl(const char *file, int line, const char *param,
const char *value)
{
const char *event_name = "def_param";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "%s:%s", param, value);

perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
&buf_payload);
strbuf_release(&buf_payload);
}

static void fn_repo_fl(const char *file, int line,
const struct repository *repo)
{
const char *event_name = "def_repo";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addstr(&buf_payload, "worktree:");
sq_quote_buf_pretty(&buf_payload, repo->worktree);

perf_io_write_fl(file, line, event_name, repo, NULL, NULL, NULL,
&buf_payload);
strbuf_release(&buf_payload);
}

static void fn_region_enter_printf_va_fl(const char *file, int line,
uint64_t us_elapsed_absolute,
const char *category,
const char *label,
const struct repository *repo,
const char *fmt, va_list ap)
{
const char *event_name = "region_enter";
struct strbuf buf_payload = STRBUF_INIT;

if (label)
strbuf_addf(&buf_payload, "label:%s ", label);
maybe_append_string_va(&buf_payload, fmt, ap);

perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
NULL, category, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_region_leave_printf_va_fl(
const char *file, int line, uint64_t us_elapsed_absolute,
uint64_t us_elapsed_region, const char *category, const char *label,
const struct repository *repo, const char *fmt, va_list ap)
{
const char *event_name = "region_leave";
struct strbuf buf_payload = STRBUF_INIT;

if (label)
strbuf_addf(&buf_payload, "label:%s ", label);
maybe_append_string_va(&buf_payload, fmt, ap);

perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
&us_elapsed_region, category, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_data_fl(const char *file, int line, uint64_t us_elapsed_absolute,
uint64_t us_elapsed_region, const char *category,
const struct repository *repo, const char *key,
const char *value)
{
const char *event_name = "data";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "%s:%s", key, value);

perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
&us_elapsed_region, category, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_data_json_fl(const char *file, int line,
uint64_t us_elapsed_absolute,
uint64_t us_elapsed_region, const char *category,
const struct repository *repo, const char *key,
const struct json_writer *value)
{
const char *event_name = "data_json";
struct strbuf buf_payload = STRBUF_INIT;

strbuf_addf(&buf_payload, "%s:%s", key, value->json.buf);

perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
&us_elapsed_region, category, &buf_payload);
strbuf_release(&buf_payload);
}

static void fn_printf_va_fl(const char *file, int line,
uint64_t us_elapsed_absolute, const char *fmt,
va_list ap)
{
const char *event_name = "printf";
struct strbuf buf_payload = STRBUF_INIT;

maybe_append_string_va(&buf_payload, fmt, ap);

perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
NULL, NULL, &buf_payload);
strbuf_release(&buf_payload);
}

struct tr2_tgt tr2_tgt_perf = {
&tr2dst_perf,

fn_init,
fn_term,

fn_version_fl,
fn_start_fl,
fn_exit_fl,
fn_signal,
fn_atexit,
fn_error_va_fl,
fn_command_path_fl,
fn_command_name_fl,
fn_command_mode_fl,
fn_alias_fl,
fn_child_start_fl,
fn_child_exit_fl,
fn_thread_start_fl,
fn_thread_exit_fl,
fn_exec_fl,
fn_exec_result_fl,
fn_param_fl,
fn_repo_fl,
fn_region_enter_printf_va_fl,
fn_region_leave_printf_va_fl,
fn_data_fl,
fn_data_json_fl,
fn_printf_va_fl,
};

164
trace2/tr2_tls.c
Unescape View File

@ -0,0 +1,164 @@ @@ -0,0 +1,164 @@
#include "cache.h"
#include "thread-utils.h"
#include "trace2/tr2_tls.h"

/*
* Initialize size of the thread stack for nested regions.
* This is used to store nested region start times. Note that
* this stack is per-thread and not per-trace-key.
*/
#define TR2_REGION_NESTING_INITIAL_SIZE (100)

static struct tr2tls_thread_ctx *tr2tls_thread_main;
static uint64_t tr2tls_us_start_main;

static pthread_mutex_t tr2tls_mutex;
static pthread_key_t tr2tls_key;

static int tr2_next_thread_id; /* modify under lock */

struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name)
{
uint64_t us_now = getnanotime() / 1000;
struct tr2tls_thread_ctx *ctx = xcalloc(1, sizeof(*ctx));

/*
* Implicitly "tr2tls_push_self()" to capture the thread's start
* time in array_us_start[0]. For the main thread this gives us the
* application run time.
*/
ctx->alloc = TR2_REGION_NESTING_INITIAL_SIZE;
ctx->array_us_start = (uint64_t *)xcalloc(ctx->alloc, sizeof(uint64_t));
ctx->array_us_start[ctx->nr_open_regions++] = us_now;

ctx->thread_id = tr2tls_locked_increment(&tr2_next_thread_id);

strbuf_init(&ctx->thread_name, 0);
if (ctx->thread_id)
strbuf_addf(&ctx->thread_name, "th%02d:", ctx->thread_id);
strbuf_addstr(&ctx->thread_name, thread_name);
if (ctx->thread_name.len > TR2_MAX_THREAD_NAME)
strbuf_setlen(&ctx->thread_name, TR2_MAX_THREAD_NAME);

pthread_setspecific(tr2tls_key, ctx);

return ctx;
}

struct tr2tls_thread_ctx *tr2tls_get_self(void)
{
struct tr2tls_thread_ctx *ctx = pthread_getspecific(tr2tls_key);

/*
* If the thread-proc did not call trace2_thread_start(), we won't
* have any TLS data associated with the current thread. Fix it
* here and silently continue.
*/
if (!ctx)
ctx = tr2tls_create_self("unknown");

return ctx;
}

int tr2tls_is_main_thread(void)
{
struct tr2tls_thread_ctx *ctx = pthread_getspecific(tr2tls_key);

return ctx == tr2tls_thread_main;
}

void tr2tls_unset_self(void)
{
struct tr2tls_thread_ctx *ctx;

ctx = tr2tls_get_self();

pthread_setspecific(tr2tls_key, NULL);

free(ctx->array_us_start);
free(ctx);
}

void tr2tls_push_self(uint64_t us_now)
{
struct tr2tls_thread_ctx *ctx = tr2tls_get_self();

ALLOC_GROW(ctx->array_us_start, ctx->nr_open_regions + 1, ctx->alloc);
ctx->array_us_start[ctx->nr_open_regions++] = us_now;
}

void tr2tls_pop_self(void)
{
struct tr2tls_thread_ctx *ctx = tr2tls_get_self();

if (!ctx->nr_open_regions)
BUG("no open regions in thread '%s'", ctx->thread_name.buf);

ctx->nr_open_regions--;
}

void tr2tls_pop_unwind_self(void)
{
struct tr2tls_thread_ctx *ctx = tr2tls_get_self();

while (ctx->nr_open_regions > 1)
tr2tls_pop_self();
}

uint64_t tr2tls_region_elasped_self(uint64_t us)
{
struct tr2tls_thread_ctx *ctx;
uint64_t us_start;

ctx = tr2tls_get_self();
if (!ctx->nr_open_regions)
return 0;

us_start = ctx->array_us_start[ctx->nr_open_regions - 1];

return us - us_start;
}

uint64_t tr2tls_absolute_elapsed(uint64_t us)
{
if (!tr2tls_thread_main)
return 0;

return us - tr2tls_us_start_main;
}

void tr2tls_init(void)
{
pthread_key_create(&tr2tls_key, NULL);
init_recursive_mutex(&tr2tls_mutex);

tr2tls_thread_main = tr2tls_create_self("main");
/*
* Keep a copy of the absolute start time of the main thread
* in a fixed variable since other threads need to access it.
* This also eliminates the need to lock accesses to the main
* thread's array (because of reallocs).
*/
tr2tls_us_start_main = tr2tls_thread_main->array_us_start[0];
}

void tr2tls_release(void)
{
tr2tls_unset_self();
tr2tls_thread_main = NULL;

pthread_mutex_destroy(&tr2tls_mutex);
pthread_key_delete(tr2tls_key);
}

int tr2tls_locked_increment(int *p)
{
int current_value;

pthread_mutex_lock(&tr2tls_mutex);
current_value = *p;
*p = current_value + 1;
pthread_mutex_unlock(&tr2tls_mutex);

return current_value;
}

97
trace2/tr2_tls.h
Unescape View File

@ -0,0 +1,97 @@ @@ -0,0 +1,97 @@
#ifndef TR2_TLS_H
#define TR2_TLS_H

#include "strbuf.h"

/*
* Arbitry limit for thread names for column alignment.
*/
#define TR2_MAX_THREAD_NAME (24)

struct tr2tls_thread_ctx {
struct strbuf thread_name;
uint64_t *array_us_start;
int alloc;
int nr_open_regions; /* plays role of "nr" in ALLOC_GROW */
int thread_id;
};

/*
* Create TLS data for the current thread. This gives us a place to
* put per-thread data, such as thread start time, function nesting
* and a per-thread label for our messages.
*
* We assume the first thread is "main". Other threads are given
* non-zero thread-ids to help distinguish messages from concurrent
* threads.
*
* Truncate the thread name if necessary to help with column alignment
* in printf-style messages.
*
* In this and all following functions the term "self" refers to the
* current thread.
*/
struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name);

/*
* Get our TLS data.
*/
struct tr2tls_thread_ctx *tr2tls_get_self(void);

/*
* return true if the current thread is the main thread.
*/
int tr2tls_is_main_thread(void);

/*
* Free our TLS data.
*/
void tr2tls_unset_self(void);

/*
* Begin a new nested region and remember the start time.
*/
void tr2tls_push_self(uint64_t us_now);

/*
* End the innermost nested region.
*/
void tr2tls_pop_self(void);

/*
* Pop any extra (above the first) open regions on the current
* thread and discard. During a thread-exit, we should only
* have region[0] that was pushed in trace2_thread_start() if
* the thread exits normally.
*/
void tr2tls_pop_unwind_self(void);

/*
* Compute the elapsed time since the innermost region in the
* current thread started and the given time (usually now).
*/
uint64_t tr2tls_region_elasped_self(uint64_t us);

/*
* Compute the elapsed time since the main thread started
* and the given time (usually now). This is assumed to
* be the absolute run time of the process.
*/
uint64_t tr2tls_absolute_elapsed(uint64_t us);

/*
* Initialize the tr2 TLS system.
*/
void tr2tls_init(void);

/*
* Free all tr2 TLS resources.
*/
void tr2tls_release(void);

/*
* Protected increment of an integer.
*/
int tr2tls_locked_increment(int *p);

#endif /* TR2_TLS_H */

31
usage.c
Unescape View File

@ -22,17 +22,48 @@ void vreportf(const char *prefix, const char *err, va_list params) @@ -22,17 +22,48 @@ void vreportf(const char *prefix, const char *err, va_list params)
static NORETURN void usage_builtin(const char *err, va_list params)
{
vreportf("usage: ", err, params);

/*
* When we detect a usage error *before* the command dispatch in
* cmd_main(), we don't know what verb to report. Force it to this
* to facilitate post-processing.
*/
trace2_cmd_name("_usage_");

/*
* Currently, the (err, params) are usually just the static usage
* string which isn't very useful here. Usually, the call site
* manually calls fprintf(stderr,...) with the actual detailed
* syntax error before calling usage().
*
* TODO It would be nice to update the call sites to pass both
* the static usage string and the detailed error message.
*/

exit(129);
}

static NORETURN void die_builtin(const char *err, va_list params)
{
/*
* We call this trace2 function first and expect it to va_copy 'params'
* before using it (because an 'ap' can only be walked once).
*/
trace2_cmd_error_va(err, params);

vreportf("fatal: ", err, params);

exit(128);
}

static void error_builtin(const char *err, va_list params)
{
/*
* We call this trace2 function first and expect it to va_copy 'params'
* before using it (because an 'ap' can only be walked once).
*/
trace2_cmd_error_va(err, params);

vreportf("error: ", err, params);
}


Write Preview
Loading…
Cancel
Save