From 6b10ede06b908fddd09c6ce59aa3b29c9a8d479a Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Fri, 7 Sep 2018 11:46:51 -0400 Subject: [PATCH 1/9] t0051: test GIT_TRACE to a windows named pipe Create a test-tool helper to create the server side of a windows named pipe, wait for a client connection, and copy data written to the pipe to stdout. Create t0051 test to route GIT_TRACE output of a command to a named pipe using the above test-tool helper. Signed-off-by: Jeff Hostetler --- Makefile | 1 + t/helper/test-tool.c | 3 ++ t/helper/test-tool.h | 3 ++ t/helper/test-windows-named-pipe.c | 72 ++++++++++++++++++++++++++++++ t/t0051-windows-named-pipe.sh | 17 +++++++ 5 files changed, 96 insertions(+) create mode 100644 t/helper/test-windows-named-pipe.c create mode 100755 t/t0051-windows-named-pipe.sh diff --git a/Makefile b/Makefile index 31cbaf6022df08..d42c4e785a7568 100644 --- a/Makefile +++ b/Makefile @@ -741,6 +741,7 @@ TEST_BUILTINS_OBJS += test-submodule-config.o TEST_BUILTINS_OBJS += test-subprocess.o TEST_BUILTINS_OBJS += test-urlmatch-normalization.o TEST_BUILTINS_OBJS += test-wildmatch.o +TEST_BUILTINS_OBJS += test-windows-named-pipe.o TEST_BUILTINS_OBJS += test-write-cache.o TEST_PROGRAMS_NEED_X += test-dump-fsmonitor diff --git a/t/helper/test-tool.c b/t/helper/test-tool.c index 9d1b1255e0fc48..b8e11573732e4e 100644 --- a/t/helper/test-tool.c +++ b/t/helper/test-tool.c @@ -45,6 +45,9 @@ static struct test_cmd cmds[] = { { "subprocess", cmd__subprocess }, { "urlmatch-normalization", cmd__urlmatch_normalization }, { "wildmatch", cmd__wildmatch }, +#ifdef GIT_WINDOWS_NATIVE + { "windows-named-pipe", cmd__windows_named_pipe }, +#endif { "write-cache", cmd__write_cache }, }; diff --git a/t/helper/test-tool.h b/t/helper/test-tool.h index 376fe27d7a90cf..ea4bab00b2df74 100644 --- a/t/helper/test-tool.h +++ b/t/helper/test-tool.h @@ -41,6 +41,9 @@ int cmd__submodule_config(int argc, const char **argv); int cmd__subprocess(int argc, const char **argv); int cmd__urlmatch_normalization(int argc, const char **argv); int cmd__wildmatch(int argc, const char **argv); +#ifdef GIT_WINDOWS_NATIVE +int cmd__windows_named_pipe(int argc, const char **argv); +#endif int cmd__write_cache(int argc, const char **argv); #endif diff --git a/t/helper/test-windows-named-pipe.c b/t/helper/test-windows-named-pipe.c new file mode 100644 index 00000000000000..b4b752b01aaf55 --- /dev/null +++ b/t/helper/test-windows-named-pipe.c @@ -0,0 +1,72 @@ +#include "test-tool.h" +#include "git-compat-util.h" +#include "strbuf.h" + +#ifdef GIT_WINDOWS_NATIVE +static const char *usage_string = ""; + +#define TEST_BUFSIZE (4096) + +int cmd__windows_named_pipe(int argc, const char **argv) +{ + const char *filename; + struct strbuf pathname = STRBUF_INIT; + int err; + HANDLE h; + BOOL connected; + char buf[TEST_BUFSIZE + 1]; + + if (argc < 2) + goto print_usage; + filename = argv[1]; + if (strchr(filename, '/') || strchr(filename, '\\')) + goto print_usage; + strbuf_addf(&pathname, "//./pipe/%s", filename); + + /* + * Create a single instance of the server side of the named pipe. + * This will allow exactly one client instance to connect to it. + */ + h = CreateNamedPipeA( + pathname.buf, + PIPE_ACCESS_INBOUND | FILE_FLAG_FIRST_PIPE_INSTANCE, + PIPE_TYPE_MESSAGE | PIPE_READMODE_MESSAGE | PIPE_WAIT, + PIPE_UNLIMITED_INSTANCES, + TEST_BUFSIZE, TEST_BUFSIZE, 0, NULL); + if (h == INVALID_HANDLE_VALUE) { + err = err_win_to_posix(GetLastError()); + fprintf(stderr, "CreateNamedPipe failed: %s\n", + strerror(err)); + return err; + } + + connected = ConnectNamedPipe(h, NULL) + ? TRUE + : (GetLastError() == ERROR_PIPE_CONNECTED); + if (!connected) { + err = err_win_to_posix(GetLastError()); + fprintf(stderr, "ConnectNamedPipe failed: %s\n", + strerror(err)); + CloseHandle(h); + return err; + } + + while (1) { + DWORD nbr; + BOOL success = ReadFile(h, buf, TEST_BUFSIZE, &nbr, NULL); + if (!success || nbr == 0) + break; + buf[nbr] = 0; + + write(1, buf, nbr); + } + + DisconnectNamedPipe(h); + CloseHandle(h); + return 0; + +print_usage: + fprintf(stderr, "usage: %s %s\n", argv[0], usage_string); + return 1; +} +#endif diff --git a/t/t0051-windows-named-pipe.sh b/t/t0051-windows-named-pipe.sh new file mode 100755 index 00000000000000..e3c36341a0ae03 --- /dev/null +++ b/t/t0051-windows-named-pipe.sh @@ -0,0 +1,17 @@ +#!/bin/sh + +test_description='Windows named pipes' + +. ./test-lib.sh + +test_expect_failure MINGW 'o_append write to named pipe' ' + GIT_TRACE="$(pwd)/expect" git status >/dev/null 2>&1 && + { test-tool windows-named-pipe t0051 >actual 2>&1 & } && + pid=$! && + sleep 1 && + GIT_TRACE=//./pipe/t0051 git status >/dev/null 2>warning && + wait $pid && + test_cmp expect actual +' + +test_done From 09379ffddacf7c491a8fb42022123cc97a992c84 Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Thu, 6 Sep 2018 12:58:15 -0400 Subject: [PATCH 2/9] mingw: fix mingw_open_append to work with named pipes Signed-off-by: Jeff Hostetler --- compat/mingw.c | 38 ++++++++++++++++++++++++++++++++--- t/t0051-windows-named-pipe.sh | 2 +- 2 files changed, 36 insertions(+), 4 deletions(-) diff --git a/compat/mingw.c b/compat/mingw.c index 25ef94226f3d20..7f743e3f599018 100644 --- a/compat/mingw.c +++ b/compat/mingw.c @@ -557,6 +557,19 @@ int mingw_mkdir(const char *path, int mode) return ret; } +/* + * Calling CreateFile() using FILE_APPEND_DATA and without FILE_WRITE_DATA + * is documented in [1] as opening a writable file handle in append mode. + * (It is believed that) this is atomic since it is maintained by the + * kernel unlike the O_APPEND flag which is racily maintained by the CRT. + * + * [1] https://docs.microsoft.com/en-us/windows/desktop/fileio/file-access-rights-constants + * + * This trick does not appear to work for named pipes. Instead it creates + * a named pipe client handle that cannot be written to. Callers should + * just use the regular _wopen() for them. (And since client handle gets + * bound to a unique server handle, it isn't really an issue.) + */ static int mingw_open_append(wchar_t const *wfilename, int oflags, ...) { HANDLE handle; @@ -576,10 +589,12 @@ static int mingw_open_append(wchar_t const *wfilename, int oflags, ...) NULL, create, FILE_ATTRIBUTE_NORMAL, NULL); if (handle == INVALID_HANDLE_VALUE) return errno = err_win_to_posix(GetLastError()), -1; + /* * No O_APPEND here, because the CRT uses it only to reset the - * file pointer to EOF on write(); but that is not necessary - * for a file created with FILE_APPEND_DATA. + * file pointer to EOF before each write(); but that is not + * necessary (and may lead to races) for a file created with + * FILE_APPEND_DATA. */ fd = _open_osfhandle((intptr_t)handle, O_BINARY); if (fd < 0) @@ -587,6 +602,23 @@ static int mingw_open_append(wchar_t const *wfilename, int oflags, ...) return fd; } +#define IS_SBS(ch) (((ch) == '/') || ((ch) == '\\')) +/* + * Does the pathname map to the local named pipe filesystem? + * That is, does it have a "//./pipe/" prefix? + */ +static int mingw_is_local_named_pipe_path(const char *filename) +{ + return (IS_SBS(filename[0]) && + IS_SBS(filename[1]) && + filename[2] == '.' && + IS_SBS(filename[3]) && + !strncasecmp(filename+4, "pipe", 4) && + IS_SBS(filename[8]) && + filename[9]); +} +#undef IS_SBS + int mingw_open (const char *filename, int oflags, ...) { typedef int (*open_fn_t)(wchar_t const *wfilename, int oflags, ...); @@ -603,7 +635,7 @@ int mingw_open (const char *filename, int oflags, ...) if (filename && !strcmp(filename, "/dev/null")) filename = "nul"; - if (oflags & O_APPEND) + if ((oflags & O_APPEND) && !mingw_is_local_named_pipe_path(filename)) open_fn = mingw_open_append; else open_fn = _wopen; diff --git a/t/t0051-windows-named-pipe.sh b/t/t0051-windows-named-pipe.sh index e3c36341a0ae03..10ac92d22507ed 100755 --- a/t/t0051-windows-named-pipe.sh +++ b/t/t0051-windows-named-pipe.sh @@ -4,7 +4,7 @@ test_description='Windows named pipes' . ./test-lib.sh -test_expect_failure MINGW 'o_append write to named pipe' ' +test_expect_success MINGW 'o_append write to named pipe' ' GIT_TRACE="$(pwd)/expect" git status >/dev/null 2>&1 && { test-tool windows-named-pipe t0051 >actual 2>&1 & } && pid=$! && From 312ccaa06b65beaba2046b55b0df7d137181f24d Mon Sep 17 00:00:00 2001 From: Jeff Hostetler Date: Thu, 30 Aug 2018 12:53:37 -0400 Subject: [PATCH 3/9] 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 --- Makefile | 9 + cache.h | 1 + common-main.c | 5 +- compat/mingw.c | 2 + compat/mingw.h | 3 +- config.c | 2 + exec-cmd.c | 10 +- git-compat-util.h | 7 + git.c | 45 ++- remote-curl.c | 7 + repository.c | 2 + repository.h | 3 + run-command.c | 32 +- run-command.h | 10 +- sh-i18n--envsubst.c | 3 + t/helper/test-tool.c | 3 + trace2.c | 743 ++++++++++++++++++++++++++++++++++++++++ trace2.h | 353 +++++++++++++++++++ trace2/tr2_cfg.c | 92 +++++ trace2/tr2_cfg.h | 23 ++ trace2/tr2_dst.c | 87 +++++ trace2/tr2_dst.h | 34 ++ trace2/tr2_sid.c | 69 ++++ trace2/tr2_sid.h | 22 ++ trace2/tr2_tbuf.c | 17 + trace2/tr2_tbuf.h | 19 + trace2/tr2_tgt.h | 119 +++++++ trace2/tr2_tgt_event.c | 531 ++++++++++++++++++++++++++++ trace2/tr2_tgt_normal.c | 320 +++++++++++++++++ trace2/tr2_tgt_perf.c | 530 ++++++++++++++++++++++++++++ trace2/tr2_tls.c | 170 +++++++++ trace2/tr2_tls.h | 99 ++++++ usage.c | 31 ++ 33 files changed, 3391 insertions(+), 12 deletions(-) create mode 100644 trace2.c create mode 100644 trace2.h create mode 100644 trace2/tr2_cfg.c create mode 100644 trace2/tr2_cfg.h create mode 100644 trace2/tr2_dst.c create mode 100644 trace2/tr2_dst.h create mode 100644 trace2/tr2_sid.c create mode 100644 trace2/tr2_sid.h create mode 100644 trace2/tr2_tbuf.c create mode 100644 trace2/tr2_tbuf.h create mode 100644 trace2/tr2_tgt.h create mode 100644 trace2/tr2_tgt_event.c create mode 100644 trace2/tr2_tgt_normal.c create mode 100644 trace2/tr2_tgt_perf.c create mode 100644 trace2/tr2_tls.c create mode 100644 trace2/tr2_tls.h diff --git a/Makefile b/Makefile index d42c4e785a7568..74319a98b88c05 100644 --- a/Makefile +++ b/Makefile @@ -981,6 +981,15 @@ LIB_OBJS += tag.o LIB_OBJS += tempfile.o LIB_OBJS += tmp-objdir.o LIB_OBJS += trace.o +LIB_OBJS += trace2.o +LIB_OBJS += trace2/tr2_cfg.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 diff --git a/cache.h b/cache.h index ee6f6ee2b97dd5..1912a8ea8d1c5f 100644 --- a/cache.h +++ b/cache.h @@ -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" diff --git a/common-main.c b/common-main.c index 3728f66b4cce80..bfea45c18d82f3 100644 --- a/common-main.c +++ b/common-main.c @@ -31,6 +31,9 @@ int main(int argc, const char **argv) * onto stdin/stdout/stderr in the child processes we spawn. */ sanitize_stdfds(); + restore_sigpipe_to_default(); + + trace2_initialize(argv); git_resolve_executable_dir(argv[0]); @@ -40,7 +43,5 @@ int main(int argc, const char **argv) attr_start(); - restore_sigpipe_to_default(); - return cmd_main(argc, argv); } diff --git a/compat/mingw.c b/compat/mingw.c index 7f743e3f599018..ac4c1beecf05a3 100644 --- a/compat/mingw.c +++ b/compat/mingw.c @@ -1971,6 +1971,7 @@ static int try_shell_exec(const char *cmd, char *const *argv) int status; if (waitpid(pid, &status, 0) < 0) status = 255; + trace2_exec_result(status); exit(status); } pid = 1; /* indicate that we tried but failed */ @@ -1991,6 +1992,7 @@ int mingw_execv(const char *cmd, char *const *argv) return -1; if (waitpid(pid, &status, 0) < 0) status = 255; + trace2_exec_result(status); exit(status); } return -1; diff --git a/compat/mingw.h b/compat/mingw.h index 0614b4c81fa3dc..b2f823b099eec2 100644 --- a/compat/mingw.h +++ b/compat/mingw.h @@ -146,8 +146,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; } diff --git a/config.c b/config.c index b55d15913faeb2..4c0b1e2c5c4ee4 100644 --- a/config.c +++ b/config.c @@ -2682,6 +2682,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); } /* diff --git a/exec-cmd.c b/exec-cmd.c index 4f81f443105f07..640003564e611c 100644 --- a/exec-cmd.c +++ b/exec-cmd.c @@ -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; } @@ -328,16 +330,22 @@ const char **prepare_git_cmd(struct argv_array *out, const char **argv) int execv_git_cmd(const char **argv) { struct argv_array nargv = ARGV_ARRAY_INIT; + int err; prepare_git_cmd(&nargv, argv); trace_argv_printf(nargv.argv, "trace: exec:"); + trace2_exec("git", (const char **)nargv.argv); /* execvp() can only ever return if it fails */ sane_execvp("git", (char **)nargv.argv); - trace_printf("trace: exec failed: %s\n", strerror(errno)); + err = errno; + trace_printf("trace: exec failed: %s\n", strerror(err)); + trace2_exec_result(err); argv_array_clear(&nargv); + + errno = err; return -1; } diff --git a/git-compat-util.h b/git-compat-util.h index 4a742687ae1cf9..a44007398d26ed 100644 --- a/git-compat-util.h +++ b/git-compat-util.h @@ -1296,6 +1296,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 diff --git a/git.c b/git.c index be8f1b0eeb8ecd..2924710db52e79 100644 --- a/git.c +++ b/git.c @@ -147,16 +147,20 @@ static int handle_options(const char ***argv, int *argc, int *envchanged) git_set_exec_path(cmd + 1); else { puts(git_exec_path()); + trace2_cmd_verb("_query_"); exit(0); } } else if (!strcmp(cmd, "--html-path")) { puts(system_path(GIT_HTML_PATH)); + trace2_cmd_verb("_query_"); exit(0); } else if (!strcmp(cmd, "--man-path")) { puts(system_path(GIT_MAN_PATH)); + trace2_cmd_verb("_query_"); exit(0); } else if (!strcmp(cmd, "--info-path")) { puts(system_path(GIT_INFO_PATH)); + trace2_cmd_verb("_query_"); exit(0); } else if (!strcmp(cmd, "-p") || !strcmp(cmd, "--paginate")) { use_pager = 1; @@ -285,6 +289,7 @@ static int handle_options(const char ***argv, int *argc, int *envchanged) (*argv)++; (*argc)--; } else if (skip_prefix(cmd, "--list-cmds=", &cmd)) { + trace2_cmd_verb("_query_"); if (!strcmp(cmd, "parseopt")) { struct string_list list = STRING_LIST_INIT_DUP; int i; @@ -329,9 +334,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_verb("_run_shell_alias_"); + ret = run_command(&child); if (ret >= 0) /* normal exit */ exit(ret); @@ -366,6 +376,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; @@ -475,6 +488,8 @@ static int run_builtin(struct cmd_struct *p, int argc, const char **argv) die("pre-command hook aborted command"); trace_argv_printf(argv, "trace: built-in: git"); + trace2_cmd_verb(p->cmd); + trace2_cmd_list_config(); validate_cache_entries(&the_index); exit_code = status = p->fn(argc, argv, prefix); @@ -732,23 +747,34 @@ 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"; if (run_pre_command_hook(cmd.args.argv)) die("pre-command hook aborted command"); trace_argv_printf(cmd.args.argv, "trace: exec:"); + trace2_exec(NULL, cmd.args.argv); /* * If we fail because the command is not found, it is * OK to return. Otherwise, we just pass along the status code, * or our usual generic code if we were not even able to exec * the program. + * + * 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. */ exit_code = status = run_command(&cmd); - if (status >= 0) + trace2_exec_result(status); + if (status >= 0) { + trace2_cmd_verb("_run_dashed_"); exit(status); - else if (errno != ENOENT) + } + else if (errno != ENOENT) { + trace2_cmd_verb("_run_dashed_"); exit(128); + } run_post_command_hook(); } @@ -773,6 +799,15 @@ static int run_argv(int *argcp, const char ***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_verb("_run_git_alias_"); + if (get_super_prefix()) die("%s doesn't support --super-prefix", **argv); @@ -788,8 +823,8 @@ static int run_argv(int *argcp, const char ***argv) * 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(args.argv, RUN_SILENT_EXEC_FAILURE | - RUN_CLEAN_ON_EXIT); + 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); @@ -900,5 +935,5 @@ int cmd_main(int argc, const char **argv) fprintf(stderr, _("failed to run command '%s': %s\n"), cmd, strerror(errno)); - return 1; + return trace2_cmd_exit(1); } diff --git a/remote-curl.c b/remote-curl.c index fb28309e850518..2b56d6e5e7be73 100644 --- a/remote-curl.c +++ b/remote-curl.c @@ -1339,6 +1339,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_verb("remote-curl"); + remote = remote_get(argv[1]); if (argc > 2) { diff --git a/repository.c b/repository.c index 5dd148671811b3..a84055ed1d9e3d 100644 --- a/repository.c +++ b/repository.c @@ -113,6 +113,8 @@ static int repo_init_gitdir(struct repository *repo, const char *gitdir) 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, diff --git a/repository.h b/repository.h index 9f16c42c1ed04a..97b03846ba544a 100644 --- a/repository.h +++ b/repository.h @@ -90,6 +90,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' */ diff --git a/run-command.c b/run-command.c index a0c9dea4d3d339..1c5a6c224ecf43 100644 --- a/run-command.c +++ b/run-command.c @@ -707,6 +707,7 @@ int start_command(struct child_process *cmd) cmd->err = fderr[0]; } + trace2_child_start(cmd); trace_run_command(cmd); fflush(NULL); @@ -912,6 +913,8 @@ int start_command(struct child_process *cmd) #endif if (cmd->pid < 0) { + trace2_child_exit(cmd, -1); + if (need_in) close_pair(fdin); else if (cmd->in) @@ -950,13 +953,16 @@ int start_command(struct child_process *cmd) 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; } @@ -978,7 +984,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; @@ -990,6 +1007,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); } @@ -1824,6 +1842,15 @@ int run_processes_parallel(int n, int output_timeout = 100; int spawn_cap = 4; struct parallel_processes pp; + /* + * TODO Currently all callers of run_processes_parallel() + * are in the submodule code, so hard-coding the category + * is OK for now. Later, pass in category to this function. + */ + const char *category = "submodule"; + + trace2_region_enter_printf(category, "run_pp", NULL, + "max:%d", ((n < 1) ? online_cpus() : n)); pp_init(&pp, n, get_next_task, start_failure, task_finished, pp_cb); while (1) { @@ -1853,5 +1880,8 @@ int run_processes_parallel(int n, } pp_cleanup(&pp); + + trace2_region_leave(category, "run_pp", NULL); + return 0; } diff --git a/run-command.h b/run-command.h index e9c72b73a83358..e71ddd65afe5e1 100644 --- a/run-command.h +++ b/run-command.h @@ -12,6 +12,11 @@ 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; + /* * Using .in, .out, .err: * - Specify 0 for no redirections (child inherits stdin, stdout, @@ -77,12 +82,15 @@ extern int run_hook_argv(const char *const *env, const char *name, #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 diff --git a/sh-i18n--envsubst.c b/sh-i18n--envsubst.c index 09c6b445b96312..2296ba1a2d6361 100644 --- a/sh-i18n--envsubst.c +++ b/sh-i18n--envsubst.c @@ -14,6 +14,7 @@ */ #include "git-compat-util.h" +#include "trace2.h" /* Substitution of environment variables in shell format strings. Copyright (C) 2003-2007 Free Software Foundation, Inc. @@ -67,6 +68,8 @@ cmd_main (int argc, const char *argv[]) /* Default values for command line options. */ /* unsigned short int show_variables = 0; */ + trace2_cmd_verb("sh-i18n--envsubst"); + switch (argc) { case 1: diff --git a/t/helper/test-tool.c b/t/helper/test-tool.c index b8e11573732e4e..ae43a27f6420c0 100644 --- a/t/helper/test-tool.c +++ b/t/helper/test-tool.c @@ -1,5 +1,6 @@ #include "git-compat-util.h" #include "test-tool.h" +#include "trace2.h" struct test_cmd { const char *name; @@ -63,6 +64,8 @@ int cmd_main(int argc, const char **argv) if (!strcmp(cmds[i].name, argv[1])) { argv++; argc--; + trace2_cmd_verb(cmds[i].name); + trace2_cmd_list_config(); return cmds[i].fn(argc, argv); } } diff --git a/trace2.c b/trace2.c new file mode 100644 index 00000000000000..c9844bc742e597 --- /dev/null +++ b/trace2.c @@ -0,0 +1,743 @@ +#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_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_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 will try to write an event to *each* + * of the enabled targets. + */ +static struct tr2_tgt *tr2_tgt_builtins[] = +{ + &tr2_tgt_normal, + &tr2_tgt_perf, + &tr2_tgt_event, + NULL +}; + +#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]) + +#define for_each_wanted_builtin(j, tgt_j) \ + for_each_builtin(j, tgt_j) \ + if (tr2_dst_trace_want(tgt_j->pdst)) + +/* + * 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(); + } +} + +/***************************************************************** + * TODO remove this section header + *****************************************************************/ + +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_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); +} + +/***************************************************************** + * TODO remove this section header + *****************************************************************/ + +void trace2_initialize_fl(const char *file, int line, const char **argv) +{ + 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' and 'start' messages 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); + 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_verb_fl(const char *file, int line, const char *command_verb) +{ + struct tr2_tgt *tgt_j; + int j; + + if (!trace2_enabled) + return; + + for_each_wanted_builtin(j, tgt_j) { + if (tgt_j->pfn_command_verb_fl) + tgt_j->pfn_command_verb_fl(file, line, command_verb); + } +} + +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, + child_exit_code, us_elapsed_child); + } +} + +void trace2_exec_fl(const char *file, int line, + const char *exe, const char **argv) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + + if (!trace2_enabled) + return; + + us_now = getnanotime() / 1000; + us_elapsed_absolute = tr2tls_absolute_elapsed(us_now); + + for_each_wanted_builtin(j, tgt_j) { + if (tgt_j->pfn_exec_fl) + tgt_j->pfn_exec_fl(file, line, us_elapsed_absolute, + exe, argv); + } +} + +void trace2_exec_result_fl(const char *file, int line, int code) +{ + struct tr2_tgt *tgt_j; + int j; + uint64_t us_now; + uint64_t us_elapsed_absolute; + + if (!trace2_enabled) + return; + + 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, + 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 + * 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 + * 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_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 diff --git a/trace2.h b/trace2.h new file mode 100644 index 00000000000000..8cb75a57305307 --- /dev/null +++ b/trace2.h @@ -0,0 +1,353 @@ +#ifndef TRACE2_H +#define TRACE2_H + +struct child_process; +struct repository; + +/* + * 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 'version' and + * 'start' events. + * + * Cleanup/Termination is handled automatically by a registered + * atexit() routine. + */ +void trace2_initialize_fl(const char *file, int line, const char **argv); + +#define trace2_initialize(argv) trace2_initialize_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_verb' event with the canonical name of the (usually) + * builtin command. This gives post-processors a simple field + * to identify the command verb without having to parse the argv. + */ +void trace2_cmd_verb_fl(const char *file, int line, const char *command_verb); + +#define trace2_cmd_verb(v) \ + trace2_cmd_verb_fl(__FILE__, __LINE__, (v)) + +/* + * 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. + */ +void 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(). + */ +void trace2_exec_result_fl(const char *file, int line, int code); + +#define trace2_exec_result(code) \ + trace2_exec_result_fl(__FILE__, __LINE__, (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 " = " 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 .