{"thread":{"id":"49264","subject":"[PATCH 0/8] WIP: trace2: a new trace facility","startedAt":"2018-08-31T16:49:57Z","lastAt":"2019-01-15T17:12:29Z","messageCount":26,"participants":["Jeff Hostetler via GitGitGadget","Derrick Stolee","Stefan Beller","Junio C Hamano","Jeff Hostetler","Jonathan Nieder"],"isPatch":true,"patchVersion":1,"patchTotal":8},"messages":[{"id":"357092","messageId":"pull.29.git.gitgitgadget@gmail.com","threadId":"49264","inReplyTo":null,"subject":"[PATCH 0/8] WIP: trace2: a new trace facility","fromName":"Jeff Hostetler via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2018-08-31T16:49:53Z","receivedAt":"2018-08-31T16:49:57Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"This patch series contains a new trace2 facility that hopefully addresses\nthe recent trace- and structured-logging-related discussions. The intent is\nto eventually replace the existing trace_ routines (or to route them to the\nnew trace2_ routines) as time permits.\n\nThis draft adds new trace2_ calls and leaves most of the original trace_\ncalls in place. Subsequent drafts will address this.\n\nThis version should be considered a replacement for my earlier structured\nlogging patch series [1].\n\nIt addresses Jonathan Nieder's, Ben Peart's, Peff's, and Junio's comments\n[2,3,4,5] about merging the existing tracing routines, ease of use,\nprogressive logging rather than logging at the end of the program, hiding\nall JSON details inside the trace2_ routines, and leaving an opening for\nadditional formats (protobuf or whatever).\n\nIt also adds a nested performance tracing feature similar to Duy's\nsuggestion in [6]. This version adds per-thread nesting and marks each event\nwith a thread name.\n\n[1] \nhttps://public-inbox.org/git/20180713165621.52017-1-git@jeffhostetler.com/\n[2] \nhttps://public-inbox.org/git/20180821044724.GA219616@aiede.svl.corp.google.com/\n[3] \nhttps://public-inbox.org/git/13302a8c-a114-c3a7-65df-55f47f902126@gmail.com/\n[4] \nhttps://public-inbox.org/git/20180814195456.GE28452@sigill.intra.peff.net/\n[5] https://public-inbox.org/git/xmqqeff0zn53.fsf@gitster-ct.c.googlers.com/\n[6] https://public-inbox.org/git/20180818144128.19361-2-pclouds@gmail.com/\n\nCc: gitster@pobox.comCc: peff@peff.netCc: peartben@gmail.comCc: \njrnieder@gmail.comCc: pclouds@gmail.com\n\nJeff Hostetler (8):\n  trace2: create new combined trace facility\n  trace2: add trace2 to main\n  trace2: demonstrate trace2 regions in wt-status\n  trace2: demonstrate trace2 child process classification\n  trace2: demonstrate instrumenting do_read_index\n  trace2: demonstrate instrumenting threaded preload_index\n  trace2: demonstrate setting sub-command parameter in checkout\n  trace2: demonstrate use of regions in read_directory_recursive\n\n Makefile           |    1 +\n builtin/checkout.c |    5 +\n cache.h            |    1 +\n compat/mingw.h     |    3 +-\n dir.c              |    3 +\n editor.c           |    1 +\n git-compat-util.h  |    7 +\n git.c              |    9 +-\n pager.c            |    1 +\n preload-index.c    |   10 +\n read-cache.c       |    6 +\n repository.c       |    2 +\n run-command.c      |    8 +-\n run-command.h      |    5 +\n sub-process.c      |    1 +\n trace2.c           | 1592 ++++++++++++++++++++++++++++++++++++++++++++\n trace2.h           |  214 ++++++\n usage.c            |    5 +\n wt-status.c        |   14 +-\n 19 files changed, 1882 insertions(+), 6 deletions(-)\n create mode 100644 trace2.c\n create mode 100644 trace2.h\n\n\nbase-commit: 2f743933341f276111103550fbf383a34dfcfd38\nPublished-As: https://github.com/gitgitgadget/git/releases/tags/pr-29%2Fjeffhostetler%2Fml-trace2-v0-v1\nFetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-29/jeffhostetler/ml-trace2-v0-v1\nPull-Request: https://github.com/gitgitgadget/git/pull/29\n-- \ngitgitgadget\n"},{"id":"357093","messageId":"2430ff0d46b4f7972084fb7e8cf74e75202840b5.1535734192.git.gitgitgadget@gmail.com","threadId":"49264","inReplyTo":"pull.29.git.gitgitgadget@gmail.com","subject":"[PATCH 2/8] trace2: add trace2 to main","fromName":"Jeff Hostetler via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2018-08-31T16:49:56Z","receivedAt":"2018-08-31T16:50:00Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler <jeffhost@microsoft.com>\n\nSigned-off-by: Jeff Hostetler <jeffhost@microsoft.com>\n---\n compat/mingw.h    | 3 +--\n git-compat-util.h | 7 +++++++\n git.c             | 9 ++++++++-\n repository.c      | 2 ++\n run-command.c     | 8 +++++++-\n run-command.h     | 5 +++++\n usage.c           | 5 +++++\n 7 files changed, 35 insertions(+), 4 deletions(-)\n\ndiff --git a/compat/mingw.h b/compat/mingw.h\nindex 571019d0bd..606402faeb 100644\n--- a/compat/mingw.h\n+++ b/compat/mingw.h\n@@ -144,8 +144,7 @@ static inline int fcntl(int fd, int cmd, ...)\n \terrno = EINVAL;\n \treturn -1;\n }\n-/* bash cannot reliably detect negative return codes as failure */\n-#define exit(code) exit((code) & 0xff)\n+\n #define sigemptyset(x) (void)0\n static inline int sigaddset(sigset_t *set, int signum)\n { return 0; }\ndiff --git a/git-compat-util.h b/git-compat-util.h\nindex 5f2e90932f..c0901d9ec6 100644\n--- a/git-compat-util.h\n+++ b/git-compat-util.h\n@@ -1219,6 +1219,13 @@ static inline int is_missing_file_error(int errno_)\n \n extern int cmd_main(int, const char **);\n \n+/*\n+ * Intercept all calls to exit() and route them to trace2 to\n+ * optionally emit a message before calling the real exit().\n+ */\n+int trace2_exit_fl(const char *file, int line, int code);\n+#define exit(code) exit(trace2_exit_fl(__FILE__, __LINE__, (code)))\n+\n /*\n  * You can mark a stack variable with UNLEAK(var) to avoid it being\n  * reported as a leak by tools like LSAN or valgrind. The argument\ndiff --git a/git.c b/git.c\nindex c27c38738b..cc56279a8c 100644\n--- a/git.c\n+++ b/git.c\n@@ -331,6 +331,8 @@ static int handle_alias(int *argcp, const char ***argv)\n \t\t\targv_array_push(&child.args, alias_string + 1);\n \t\t\targv_array_pushv(&child.args, (*argv) + 1);\n \n+\t\t\ttrace2_alias(alias_command, child.args.argv);\n+\n \t\t\tret = run_command(&child);\n \t\t\tif (ret >= 0)   /* normal exit */\n \t\t\t\texit(ret);\n@@ -365,6 +367,8 @@ static int handle_alias(int *argcp, const char ***argv)\n \t\t/* insert after command name */\n \t\tmemcpy(new_argv + count, *argv + 1, sizeof(char *) * *argcp);\n \n+\t\ttrace2_alias(alias_command, new_argv);\n+\n \t\t*argv = new_argv;\n \t\t*argcp += count - 1;\n \n@@ -413,6 +417,7 @@ static int run_builtin(struct cmd_struct *p, int argc, const char **argv)\n \t\tsetup_work_tree();\n \n \ttrace_argv_printf(argv, \"trace: built-in: git\");\n+\ttrace2_command(p->cmd);\n \n \tvalidate_cache_entries(&the_index);\n \tstatus = p->fn(argc, argv, prefix);\n@@ -719,6 +724,8 @@ int cmd_main(int argc, const char **argv)\n \t\t\tcmd = slash + 1;\n \t}\n \n+\ttrace2_start(argv);\n+\n \ttrace_command_performance(argv);\n \n \t/*\n@@ -782,5 +789,5 @@ int cmd_main(int argc, const char **argv)\n \tfprintf(stderr, _(\"failed to run command '%s': %s\\n\"),\n \t\tcmd, strerror(errno));\n \n-\treturn 1;\n+\treturn trace2_exit(1);\n }\ndiff --git a/repository.c b/repository.c\nindex 5dd1486718..c169f61ccd 100644\n--- a/repository.c\n+++ b/repository.c\n@@ -113,6 +113,8 @@ out:\n void repo_set_worktree(struct repository *repo, const char *path)\n {\n \trepo->worktree = real_pathdup(path, 1);\n+\n+\ttrace2_worktree(repo->worktree);\n }\n \n static int read_and_verify_repository_format(struct repository_format *format,\ndiff --git a/run-command.c b/run-command.c\nindex 84b883c213..e833d9a277 100644\n--- a/run-command.c\n+++ b/run-command.c\n@@ -706,6 +706,7 @@ fail_pipe:\n \t\tcmd->err = fderr[0];\n \t}\n \n+\ttrace2_child_start(cmd);\n \ttrace_run_command(cmd);\n \n \tfflush(NULL);\n@@ -911,6 +912,8 @@ fail_pipe:\n #endif\n \n \tif (cmd->pid < 0) {\n+\t\ttrace2_child_exit(cmd, -1);\n+\n \t\tif (need_in)\n \t\t\tclose_pair(fdin);\n \t\telse if (cmd->in)\n@@ -949,13 +952,16 @@ fail_pipe:\n int finish_command(struct child_process *cmd)\n {\n \tint ret = wait_or_whine(cmd->pid, cmd->argv[0], 0);\n+\ttrace2_child_exit(cmd, ret);\n \tchild_process_clear(cmd);\n \treturn ret;\n }\n \n int finish_command_in_signal(struct child_process *cmd)\n {\n-\treturn wait_or_whine(cmd->pid, cmd->argv[0], 1);\n+\tint ret = wait_or_whine(cmd->pid, cmd->argv[0], 1);\n+\ttrace2_child_exit(cmd, ret);\n+\treturn ret;\n }\n \n \ndiff --git a/run-command.h b/run-command.h\nindex 3932420ec8..a91206b08c 100644\n--- a/run-command.h\n+++ b/run-command.h\n@@ -12,6 +12,11 @@ struct child_process {\n \tstruct argv_array args;\n \tstruct argv_array env_array;\n \tpid_t pid;\n+\n+\tint trace2_child_id;\n+\tuint64_t trace2_child_us_start;\n+\tconst char *trace2_child_class;\n+\n \t/*\n \t * Using .in, .out, .err:\n \t * - Specify 0 for no redirections (child inherits stdin, stdout,\ndiff --git a/usage.c b/usage.c\nindex cc803336bd..1838c46d20 100644\n--- a/usage.c\n+++ b/usage.c\n@@ -28,12 +28,17 @@ static NORETURN void usage_builtin(const char *err, va_list params)\n static NORETURN void die_builtin(const char *err, va_list params)\n {\n \tvreportf(\"fatal: \", err, params);\n+\n+\ttrace2_error_va(err, params);\n+\n \texit(128);\n }\n \n static void error_builtin(const char *err, va_list params)\n {\n \tvreportf(\"error: \", err, params);\n+\n+\ttrace2_error_va(err, params);\n }\n \n static void warn_builtin(const char *warn, va_list params)\n-- \ngitgitgadget\n\n"},{"id":"357094","messageId":"82885700379efe6d6a83629cac4d943b99b393bf.1535734192.git.gitgitgadget@gmail.com","threadId":"49264","inReplyTo":"pull.29.git.gitgitgadget@gmail.com","subject":"[PATCH 1/8] trace2: create new combined trace facility","fromName":"Jeff Hostetler via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2018-08-31T16:49:55Z","receivedAt":"2018-08-31T16:50:01Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler <jeffhost@microsoft.com>\n\nCreate trace2 API allowing event-based tracing.  This will hopefully\neventually replace the existing trace API.\n\nCreate GIT_TR2 trace-key to replace GIT_TRACE, GIT_TR2_PERFORMANCE to\nreplace GIT_TRACE_PERFORMANCE, and a new trace-key GIT_TR2_EVENT to\ngenerate JSON data for telemetry purposes.  Other structured formats\ncan easily be added later using this new existing model.\n\nDefine a higher-level event API that selectively writes to all of the\nnew GIT_TR2_* targets (depending on event type) without needing to call\ndifferent trace_printf*() or trace_performance_*() routines.\n\nThe API defines both fixed-field and printf-style functions.\n\nThe trace2 performance tracing includes thread-specific function\nnesting and timings.\n\nSigned-off-by: Jeff Hostetler <jeffhost@microsoft.com>\n---\n Makefile |    1 +\n cache.h  |    1 +\n trace2.c | 1592 ++++++++++++++++++++++++++++++++++++++++++++++++++++++\n trace2.h |  214 ++++++++\n 4 files changed, 1808 insertions(+)\n create mode 100644 trace2.c\n create mode 100644 trace2.h\n\ndiff --git a/Makefile b/Makefile\nindex 5a969f5830..88ae7afdd4 100644\n--- a/Makefile\n+++ b/Makefile\n@@ -974,6 +974,7 @@ LIB_OBJS += tag.o\n LIB_OBJS += tempfile.o\n LIB_OBJS += tmp-objdir.o\n LIB_OBJS += trace.o\n+LIB_OBJS += trace2.o\n LIB_OBJS += trailer.o\n LIB_OBJS += transport.o\n LIB_OBJS += transport-helper.o\ndiff --git a/cache.h b/cache.h\nindex 4d014541ab..38f0cd2ba0 100644\n--- a/cache.h\n+++ b/cache.h\n@@ -9,6 +9,7 @@\n #include \"gettext.h\"\n #include \"convert.h\"\n #include \"trace.h\"\n+#include \"trace2.h\"\n #include \"string-list.h\"\n #include \"pack-revindex.h\"\n #include \"hash.h\"\ndiff --git a/trace2.c b/trace2.c\nnew file mode 100644\nindex 0000000000..13d5c85366\n--- /dev/null\n+++ b/trace2.c\n@@ -0,0 +1,1592 @@\n+#include \"cache.h\"\n+#include \"config.h\"\n+#include \"json-writer.h\"\n+#include \"quote.h\"\n+#include \"run-command.h\"\n+#include \"sigchain.h\"\n+#include \"thread-utils.h\"\n+#include \"version.h\"\n+\n+/*****************************************************************\n+ * TODO remove this section header\n+ *****************************************************************/\n+\n+static struct strbuf tr2sid_buf = STRBUF_INIT;\n+static int tr2sid_nr_git_parents;\n+\n+/*\n+ * Compute a \"unique\" session id (SID) for the current process.  All events\n+ * from this process will have this label.  If we were started by another\n+ * git instance, use our parent's SID as a prefix and count the number of\n+ * nested git processes.  (This lets us track parent/child relationships\n+ * even if there is an intermediate shell process.)\n+ */\n+static void tr2sid_compute(void)\n+{\n+\tuint64_t us_now;\n+\tconst char *parent_sid;\n+\n+\tif (tr2sid_buf.len)\n+\t\treturn;\n+\n+\tparent_sid = getenv(\"SLOG_PARENT_SID\");\n+\tif (parent_sid && *parent_sid) {\n+\t\tconst char *p;\n+\t\tfor (p = parent_sid; *p; p++)\n+\t\t\tif (*p == '/')\n+\t\t\t\ttr2sid_nr_git_parents++;\n+\n+\t\tstrbuf_addstr(&tr2sid_buf, parent_sid);\n+\t\tstrbuf_addch(&tr2sid_buf, '/');\n+\t\ttr2sid_nr_git_parents++;\n+\t}\n+\n+\tus_now = getnanotime() / 1000;\n+\tstrbuf_addf(&tr2sid_buf, \"%\"PRIuMAX\"-%\"PRIdMAX,\n+\t\t    (uintmax_t)us_now, (intmax_t)getpid());\n+\n+\tsetenv(\"SLOG_PARENT_SID\", tr2sid_buf.buf, 1);\n+}\n+\n+/*****************************************************************\n+ * TODO remove this section header\n+ *****************************************************************/\n+\n+/*\n+ * Each thread (including the main thread) has a stack of nested regions.\n+ * This is used to indent messages and provide nested perf times.  The\n+ * limit here is for simplicity.  Note that the region stack is per-thread\n+ * and not per-trace_key.\n+ */\n+#define TR2_MAX_REGION_NESTING (100)\n+#define TR2_INDENT (2)\n+#define TR2_INDENT_LENGTH(ctx) (((ctx)->nr_open_regions - 1) * TR2_INDENT)\n+\n+#define TR2_MAX_THREAD_NAME (24)\n+\n+struct tr2tls_thread_ctx {\n+\tstruct strbuf thread_name;\n+\tuint64_t us_start[TR2_MAX_REGION_NESTING];\n+\tint nr_open_regions;\n+\tint thread_id;\n+};\n+\n+static struct tr2tls_thread_ctx *tr2tls_thread_main;\n+\n+static pthread_mutex_t tr2tls_mutex;\n+static pthread_key_t tr2tls_key;\n+static int tr2tls_initialized;\n+\n+static struct strbuf tr2_dots = STRBUF_INIT;\n+\n+static int tr2_next_child_id;\n+static int tr2_next_thread_id;\n+\n+/*\n+ * Create TLS data for the current thread.  This gives us a place to\n+ * put per-thread data, such as thread start time, function nesting\n+ * and a per-thread label for our messages.\n+ *\n+ * We assume the first thread is \"main\".  Other threads are given\n+ * non-zero thread-ids to help distinguish messages from concurrent\n+ * threads.\n+ *\n+ * Truncate the thread name if necessary to help with column alignment\n+ * in printf-style messages.\n+ */\n+static struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name)\n+{\n+\tstruct tr2tls_thread_ctx *ctx = xcalloc(1, sizeof(*ctx));\n+\n+\t/*\n+\t * Implicitly \"tr2tls_push_self()\" to capture the thread's start\n+\t * time in us_start[0].  For the main thread this gives us the\n+\t * application run time.\n+\t */\n+\tctx->us_start[ctx->nr_open_regions++] = getnanotime() / 1000;\n+\n+\tpthread_mutex_lock(&tr2tls_mutex);\n+\tctx->thread_id = tr2_next_thread_id++;\n+\tpthread_mutex_unlock(&tr2tls_mutex);\n+\n+\tstrbuf_init(&ctx->thread_name, 0);\n+\tif (ctx->thread_id)\n+\t\tstrbuf_addf(&ctx->thread_name, \"th%02d:\", ctx->thread_id);\n+\tstrbuf_addstr(&ctx->thread_name, thread_name);\n+\tif (ctx->thread_name.len > TR2_MAX_THREAD_NAME)\n+\t\tstrbuf_setlen(&ctx->thread_name, TR2_MAX_THREAD_NAME);\n+\n+\tpthread_setspecific(tr2tls_key, ctx);\n+\n+\treturn ctx;\n+}\n+\n+static struct tr2tls_thread_ctx *tr2tls_get_self(void)\n+{\n+\tstruct tr2tls_thread_ctx * ctx = pthread_getspecific(tr2tls_key);\n+\n+\t/*\n+\t * If the thread-proc did not call trace2_thread_start(), we won't\n+\t * have any TLS data associated with the current thread.  Fix it\n+\t * here and silently continue.\n+\t */\n+\tif (!ctx)\n+\t\tctx = tr2tls_create_self(\"unknown\");\n+\n+\treturn ctx;\n+}\n+\n+static void tr2tls_unset_self(void)\n+{\n+\tstruct tr2tls_thread_ctx * ctx;\n+\n+\tctx = tr2tls_get_self();\n+\n+\tpthread_setspecific(tr2tls_key, NULL);\n+\n+\tfree(ctx);\n+}\n+\n+/*\n+ * Begin a new nested region and remember the start time.\n+ */\n+static void tr2tls_push_self(void)\n+{\n+\tstruct tr2tls_thread_ctx *ctx = tr2tls_get_self();\n+\n+\tif (ctx->nr_open_regions == TR2_MAX_REGION_NESTING)\n+\t\tBUG(\"exceeded max region nesting '%d' in thread '%s'\",\n+\t\t    ctx->nr_open_regions, ctx->thread_name.buf);\n+\n+\tctx->us_start[ctx->nr_open_regions++] = getnanotime() / 1000;\n+}\n+\n+/*\n+ * End the innermost nested region.\n+ */\n+static void tr2tls_pop_self(void)\n+{\n+\tstruct tr2tls_thread_ctx *ctx = tr2tls_get_self();\n+\n+\tif (!ctx->nr_open_regions)\n+\t\tBUG(\"no open regions in thread '%s'\", ctx->thread_name.buf);\n+\n+\tctx->nr_open_regions--;\n+}\n+\n+/*\n+ * Compute elapsed time in innermost nested region.\n+ */\n+static uint64_t tr2tls_region_elapsed_self(void)\n+{\n+\tstruct tr2tls_thread_ctx *ctx;\n+\tuint64_t us_start;\n+\tuint64_t us_now;\n+\n+\tctx = tr2tls_get_self();\n+\tif (!ctx->nr_open_regions)\n+\t\treturn 0;\n+\t\n+\tus_now = getnanotime() / 1000;\n+\tus_start = ctx->us_start[ctx->nr_open_regions - 1];\n+\n+\treturn us_now - us_start;\n+}\n+\n+/*\n+ * Compute the elapsed run time since the main thread started.\n+ */\n+static uint64_t tr2tls_elapsed_main(void)\n+{\n+\tuint64_t us_start;\n+\tuint64_t us_now;\n+\tuint64_t us_elapsed;\n+\n+\tif (!tr2tls_thread_main)\n+\t\treturn 0;\n+\n+\tus_now = getnanotime() / 1000;\n+\tus_start = tr2tls_thread_main->us_start[0];\n+\tus_elapsed = us_now - us_start;\n+\n+\treturn us_elapsed;\n+}\n+\n+static void tr2tls_init(void)\n+{\n+\tpthread_key_create(&tr2tls_key, NULL);\n+\tinit_recursive_mutex(&tr2tls_mutex);\n+\n+\ttr2tls_thread_main = tr2tls_create_self(\"main\");\n+\ttr2tls_initialized = 1;\n+}\n+\n+static void tr2tls_release(void)\n+{\n+\ttr2tls_unset_self();\n+\ttr2tls_thread_main = NULL;\n+\n+\ttr2tls_initialized = 0;\n+\n+\tpthread_mutex_destroy(&tr2tls_mutex);\n+\tpthread_key_delete(tr2tls_key);\n+}\n+\n+/*****************************************************************\n+ * TODO remove this section header\n+ *****************************************************************/\n+\n+static struct trace_key tr2key_default = { \"GIT_TR2\", 0, 0, 0 };\n+static struct trace_key tr2key_perf    = { \"GIT_TR2_PERFORMANCE\", 0, 0, 0 };\n+static struct trace_key tr2key_event   = { \"GIT_TR2_EVENT\", 0, 0, 0 };\n+\n+/*\n+ * Region depth limit for messages written to the event target.\n+ *\n+ * The \"region_enter\" and \"region_leave\" messages (especially recursive\n+ * messages such as those produced while diving the worktree or index)\n+ * are primarily intended for the performance target during debugging.\n+ *\n+ * Some of the outer-most messages, however, may be of interest to the\n+ * event target.  Set this environment variable to a larger integer for\n+ * more detail in the event target.\n+ */\n+#define GIT_TR2_EVENT_DEPTH \"GIT_TR2_EVENT_DEPTH\"\n+static int tr2env_event_depth_wanted = 2;\n+\n+/*\n+ * Set this environment variable to true to omit the \"<time> <file>:<line>\"\n+ * fields from each line written to the default and performance targets.\n+ *\n+ * Unit tests may want to use this to help with testing.\n+ */\n+#define GIT_TR2_BARE \"GIT_TR2_BARE\"\n+static int tr2env_bare_wanted;\n+\n+static void tr2key_trace_disable(struct trace_key *key)\n+{\n+\tif (key->need_close)\n+\t\tclose(key->fd);\n+\tkey->fd = 0;\n+\tkey->initialized = 1;\n+\tkey->need_close = 0;\n+}\n+\n+static int tr2key_get_trace_fd(struct trace_key *key)\n+{\n+\tconst char *trace;\n+\n+\t/* don't open twice */\n+\tif (key->initialized)\n+\t\treturn key->fd;\n+\n+\ttrace = getenv(key->key);\n+\n+\tif (!trace || !strcmp(trace, \"\") ||\n+\t    !strcmp(trace, \"0\") || !strcasecmp(trace, \"false\"))\n+\t\tkey->fd = 0;\n+\telse if (!strcmp(trace, \"1\") || !strcasecmp(trace, \"true\"))\n+\t\tkey->fd = STDERR_FILENO;\n+\telse if (strlen(trace) == 1 && isdigit(*trace))\n+\t\tkey->fd = atoi(trace);\n+\telse if (is_absolute_path(trace)) {\n+\t\tint fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666);\n+\t\tif (fd == -1) {\n+\t\t\twarning(\"could not open '%s' for tracing: %s\",\n+\t\t\t\ttrace, strerror(errno));\n+\t\t\ttr2key_trace_disable(key);\n+\t\t} else {\n+\t\t\tkey->fd = fd;\n+\t\t\tkey->need_close = 1;\n+\t\t}\n+\t} else {\n+\t\twarning(\"unknown trace value for '%s': %s\\n\"\n+\t\t\t\"         If you want to trace into a file, then please set %s\\n\"\n+\t\t\t\"         to an absolute pathname (starting with /)\",\n+\t\t\tkey->key, trace, key->key);\n+\t\ttr2key_trace_disable(key);\n+\t}\n+\n+\tkey->initialized = 1;\n+\treturn key->fd;\n+}\n+\n+static int tr2key_trace_want(struct trace_key *key)\n+{\n+\treturn !!tr2key_get_trace_fd(key);\n+}\n+\n+/*\n+ * Force (rather than lazily) initialize any of the requested\n+ * primary/builtin trace targets at startup (and before we've\n+ * seen an actual trace event call) so we can see if we need\n+ * to setup the TR2 and TLS machinery.\n+ *\n+ * Other ad hoc trace targets can just use compatibility mode\n+ * and and printf-based messages.\n+ */\n+static int tr2key_want_builtins(void)\n+{\n+\tint sum = 0;\n+\tint v;\n+\tchar *p;\n+\n+\tsum += tr2key_trace_want(&tr2key_default);\n+\tsum += tr2key_trace_want(&tr2key_perf);\n+\tsum += tr2key_trace_want(&tr2key_event);\n+\n+\tp = getenv(GIT_TR2_EVENT_DEPTH);\n+\tif (p && ((v = atoi(p)) > 0))\n+\t\ttr2env_event_depth_wanted = v;\n+\n+\tp = getenv(GIT_TR2_BARE);\n+\tif (p && *p && ((v = git_parse_maybe_bool(p)) != -1))\n+\t\ttr2env_bare_wanted = v;\n+\t\n+\treturn sum;\n+}\n+\n+static void tr2key_disable_builtins(void)\n+{\n+\ttr2key_trace_disable(&tr2key_default);\n+\ttr2key_trace_disable(&tr2key_perf);\n+\ttr2key_trace_disable(&tr2key_event);\n+}\n+\n+/*****************************************************************\n+ * TODO remove this section header\n+ *****************************************************************/\n+\n+/*\n+ * A simple wrapper around a fixed buffer to avoid C syntax\n+ * quirks and the need to pass around an additional size_t\n+ * argument.\n+ */\n+struct tr2time_buf {\n+\tchar buf[24];\n+};\n+\n+static void tr2time_current_time(struct tr2time_buf *tb)\n+{\n+\tstruct timeval tv;\n+\tstruct tm tm;\n+\ttime_t secs;\n+\n+\tgettimeofday(&tv, NULL);\n+\tsecs = tv.tv_sec;\n+\tlocaltime_r(&secs, &tm);\n+\n+\txsnprintf(tb->buf, sizeof(tb->buf), \"%02d:%02d:%02d.%06ld \",\n+\t\t  tm.tm_hour, tm.tm_min, tm.tm_sec, (long)tv.tv_usec);\n+}\n+\n+/*****************************************************************\n+ * TODO remove this section header\n+ *****************************************************************/\n+\n+#define TR2FMT_MAX_EVENT_NAME (12)\n+\n+/*\n+ * Format trace line prefix in human-readable classic format for\n+ * the default target:\n+ *     \"<time> <file>:<line> <bar> <thread_name> <bar> <event_name> <bar> \"\n+ */\n+static void tr2fmt_prepare_default(\n+\tconst char *event_name,\n+\tstruct tr2tls_thread_ctx *ctx,\n+\tconst char *file, int line,\n+\tstruct strbuf *buf)\n+{\n+\tstrbuf_setlen(buf,0);\n+\n+\tif (!tr2env_bare_wanted) {\n+\t\tstruct tr2time_buf tb_now;\n+\n+\t\ttr2time_current_time(&tb_now);\n+\t\tstrbuf_addstr(buf, tb_now.buf);\n+\n+\t\tif (file && *file)\n+\t\t\tstrbuf_addf(buf, \"%s:%d \", file, line);\n+\t\twhile (buf->len < 40)\n+\t\t\tstrbuf_addch(buf, ' ');\n+\n+\t\tstrbuf_addstr(buf, \"| \");\n+\t}\n+\n+\tstrbuf_addf(buf, \"%-*s | %-*s | \",\n+\t\t    TR2_MAX_THREAD_NAME, ctx->thread_name.buf,\n+\t\t    TR2FMT_MAX_EVENT_NAME, event_name);\n+}\n+\n+/*\n+ * Format trace line prefix in human-readable classic format for\n+ * the performance target:\n+ *     \"[<time>] [<file>:<line>] [<thread_name>] [<event_name>] <bar> <indent>\"\n+ */\n+static void tr2fmt_prepare_perf(\n+\tconst char *event_name,\n+\tstruct tr2tls_thread_ctx *ctx,\n+\tconst char *file, int line,\n+\tuint64_t *p_us_elapsed,\n+\tstruct strbuf *buf)\n+{\n+\tstrbuf_setlen(buf,0);\n+\n+\tif (!tr2env_bare_wanted) {\n+\n+\t\tstruct tr2time_buf tb_now;\n+\n+\t\ttr2time_current_time(&tb_now);\n+\t\tstrbuf_addstr(buf, tb_now.buf);\n+\n+\t\tif (file && *file)\n+\t\t\tstrbuf_addf(buf, \"%s:%d \", file, line);\n+\t\twhile (buf->len < 40)\n+\t\t\tstrbuf_addch(buf, ' ');\n+\n+\t\tstrbuf_addstr(buf, \"| \");\n+\t}\n+\n+\tstrbuf_addf(buf, \"%-*s | %-*s | \",\n+\t\t    TR2_MAX_THREAD_NAME, ctx->thread_name.buf,\n+\t\t    TR2FMT_MAX_EVENT_NAME, event_name);\n+\n+\tif (p_us_elapsed)\n+\t\tstrbuf_addf(buf, \"%9.6f | \",\n+\t\t\t    ((double)(*p_us_elapsed)) / 1000000.0);\n+\telse\n+\t\tstrbuf_addf(buf, \"%9s | \", \" \");\n+\t\t\n+\tif (ctx->nr_open_regions > 0)\n+\t\tstrbuf_addf(buf, \"%.*s\", TR2_INDENT_LENGTH(ctx), tr2_dots.buf);\n+}\n+\n+/*\n+ * Append common key-value pairs to the currently open JSON object.\n+ *     \"event:\"<event_name>\"\n+ *      \"sid\":\"<sid>\"\n+ *   \"thread\":\"<thread_name>\"\n+ *     \"file\":\"<filename>\"\n+ *     \"line\":<line_number>\n+ */\n+static void tr2fmt_prepare_json_trace_line(\n+\tconst char *event_name,\n+\tconst char *file, int line,\n+\tstruct json_writer *jw)\n+{\n+\tstruct tr2tls_thread_ctx *ctx = tr2tls_get_self();\n+\n+\tjw_object_string(jw, \"event\", event_name);\n+\tjw_object_string(jw, \"sid\", tr2sid_buf.buf);\n+\tjw_object_string(jw, \"thread\", ctx->thread_name.buf);\n+\n+\tif (file && *file) {\n+\t\tjw_object_string(jw, \"file\", file);\n+\t\tjw_object_intmax(jw, \"line\", line);\n+\t}\n+}\n+\n+/*****************************************************************\n+ * TODO remove this section header\n+ *****************************************************************/\n+\n+static void tr2io_write_line(struct trace_key *key, struct strbuf *buf_line)\n+{\n+\tstrbuf_complete_line(buf_line); /* ensure final NL on buffer */\n+\n+\t// TODO we don't really want short-writes to try again when\n+\t// TODO we are in append mode...\n+\n+\tif (write_in_full(tr2key_get_trace_fd(key),\n+\t\t\t  buf_line->buf, buf_line->len) < 0) {\n+\t\twarning(\"unable to write trace for '%s': %s\",\n+\t\t\tkey->key, strerror(errno));\n+\t\ttr2key_trace_disable(key);\n+\t}\n+}\n+\n+static void tr2io_write_default_fl(const char *file, int line,\n+\t\t\t\t   const char *event_name,\n+\t\t\t\t   const struct strbuf *buf_payload)\n+{\n+\tstruct tr2tls_thread_ctx *ctx = tr2tls_get_self();\n+\tstruct strbuf buf_line = STRBUF_INIT;\n+\n+\ttr2fmt_prepare_default(event_name, ctx, file, line, &buf_line);\n+\n+\tstrbuf_addbuf(&buf_line, buf_payload);\n+\n+\ttr2io_write_line(&tr2key_default, &buf_line);\n+\n+\tstrbuf_release(&buf_line);\n+}\n+\n+static void tr2io_write_perf_fl(const char *file, int line,\n+\t\t\t\tconst char *event_name,\n+\t\t\t\tuint64_t *p_us_elapsed,\n+\t\t\t\tconst struct strbuf *buf_payload)\n+{\n+\tstruct tr2tls_thread_ctx *ctx = tr2tls_get_self();\n+\tstruct strbuf buf_line = STRBUF_INIT;\n+\n+\ttr2fmt_prepare_perf(event_name, ctx, file, line,\n+\t\t\t    p_us_elapsed, &buf_line);\n+\n+\tstrbuf_addbuf(&buf_line, buf_payload);\n+\n+\ttr2io_write_line(&tr2key_perf, &buf_line);\n+\n+\tstrbuf_release(&buf_line);\n+}\n+\n+/*****************************************************************\n+ * TODO remove this section header\n+ *****************************************************************/\n+\n+/*\n+ * Write 'version' event message to the builtin targets.\n+ */\n+static void tr2evt_version_fl(const char *file, int line)\n+{\n+\tconst char *event_name = \"version\";\n+\n+\tif (tr2key_trace_want(&tr2key_default)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addf(&buf_payload, \"%s\", git_version_string);\n+\n+\t\ttr2io_write_default_fl(file, line, event_name, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addf(&buf_payload, \"%s\", git_version_string);\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, NULL, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, file, line, &jw);\n+\t\tjw_object_string(&jw, \"git\", git_version_string);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+/*\n+ * Write 'start' event message to the builtin targets.\n+ */\n+static void tr2evt_start_fl(const char *file, int line,\n+\t\t\t    const char **argv)\n+{\n+\tconst char *event_name = \"start\";\n+\n+\tif (tr2key_trace_want(&tr2key_default)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tsq_quote_argv_pretty(&buf_payload, argv);\n+\n+\t\ttr2io_write_default_fl(file, line, event_name, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tsq_quote_argv_pretty(&buf_payload, argv);\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, NULL, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, file, line, &jw);\n+\t\tjw_object_inline_begin_array(&jw, \"argv\");\n+\t\tjw_array_argv(&jw, argv);\n+\t\tjw_end(&jw);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+/*\n+ * Write 'exit' event message to the builtin targets.\n+ */\n+static void tr2evt_exit_fl(const char *file, int line,\n+\t\t\t   int code, uint64_t us_elapsed)\n+{\n+\tconst char *event_name = \"exit\";\n+\n+\tif (tr2key_trace_want(&tr2key_default)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\t\tdouble elapsed = (double)us_elapsed / 1000000.0;\n+\n+\t\tstrbuf_addf(&buf_payload, \"elapsed:%.6f code:%d\",\n+\t\t\t    elapsed, code);\n+\n+\t\ttr2io_write_default_fl(file, line, event_name, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addf(&buf_payload, \"code:%d\", code);\n+\n+\t\ttr2io_write_perf_fl(file, line, event_name,\n+\t\t\t\t    &us_elapsed, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\t\tdouble elapsed = (double)us_elapsed / 1000000.0;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, file, line, &jw);\n+\t\tjw_object_double(&jw, \"elapsed\", 6, elapsed);\n+\t\tjw_object_intmax(&jw, \"code\", code);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+/*\n+ * Write 'signal' event message to the builtin targets.\n+ */\n+static void tr2evt_signal(int signo, uint64_t us_elapsed)\n+{\n+\tconst char *event_name = \"signal\";\n+\n+\tif (tr2key_trace_want(&tr2key_default)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\t\tdouble elapsed = (double)us_elapsed / 1000000.0;\n+\n+\t\tstrbuf_addf(&buf_payload, \"elapsed:%.6f signo:%d\",\n+\t\t\t    elapsed, signo);\n+\n+\t\ttr2io_write_default_fl(__FILE__, __LINE__,\n+\t\t\t\t       event_name, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addf(&buf_payload, \"signo:%d\", signo);\n+\n+\t\ttr2io_write_perf_fl(__FILE__, __LINE__,\n+\t\t\t\t    event_name, &us_elapsed, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\t\tdouble elapsed = (double)us_elapsed / 1000000.0;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, __FILE__, __LINE__, &jw);\n+\t\tjw_object_double(&jw, \"elapsed\", 6, elapsed);\n+\t\tjw_object_intmax(&jw, \"signo\", signo);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+/*\n+ * Write 'atexit' event message to the builtin targets.\n+ */\n+static void tr2evt_atexit(int code, uint64_t us_elapsed)\n+{\n+\tconst char *event_name = \"atexit\";\n+\n+\tif (tr2key_trace_want(&tr2key_default)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\t\tdouble elapsed = (double)us_elapsed / 1000000.0;\n+\n+\t\tstrbuf_addf(&buf_payload, \"elapsed:%.6f code:%d\",\n+\t\t\t    elapsed, code);\n+\n+\t\ttr2io_write_default_fl(__FILE__, __LINE__,\n+\t\t\t\t       event_name, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addf(&buf_payload, \"code:%d\", code);\n+\n+\t\ttr2io_write_perf_fl(__FILE__, __LINE__,\n+\t\t\t\t    event_name, &us_elapsed, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\t\tdouble elapsed = (double)us_elapsed / 1000000.0;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, __FILE__, __LINE__, &jw);\n+\t\tjw_object_double(&jw, \"elapsed\", 6, elapsed);\n+\t\tjw_object_intmax(&jw, \"code\", code);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+static void tr2evt_error_va_fl(const char *file, int line,\n+\t\t\t       const char *fmt, va_list ap)\n+{\n+\tconst char *event_name = \"error\";\n+\n+\tif (tr2key_trace_want(&tr2key_default)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_vaddf(&buf_payload, fmt, ap);\n+\n+\t\ttr2io_write_default_fl(file, line, event_name, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_vaddf(&buf_payload, fmt, ap);\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, NULL, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\t\tstruct strbuf buf_msg = STRBUF_INIT;\n+\n+\t\tstrbuf_vaddf(&buf_msg, fmt, ap);\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, file, line, &jw);\n+\t\tjw_object_string(&jw, \"msg\", buf_msg.buf);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t\tstrbuf_release(&buf_msg);\n+\t}\n+}\n+\n+static void tr2evt_command_fl(const char *file, int line,\n+\t\t\t      const char *command_name)\n+{\n+\tconst char *event_name = \"command\";\n+\n+\tif (tr2key_trace_want(&tr2key_default)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addstr(&buf_payload, command_name);\n+\n+\t\ttr2io_write_default_fl(file, line, event_name, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addstr(&buf_payload, command_name);\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, NULL, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, file, line, &jw);\n+\t\tjw_object_string(&jw, \"name\", command_name);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+static void tr2evt_worktree_fl(const char *file, int line,\n+\t\t\t       const char *path)\n+{\n+\tconst char *event_name = \"worktree\";\n+\n+\tif (tr2key_trace_want(&tr2key_default)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addstr(&buf_payload, path);\n+\n+\t\ttr2io_write_default_fl(file, line, event_name, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addstr(&buf_payload, path);\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, NULL, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, file, line, &jw);\n+\t\tjw_object_string(&jw, \"path\", path);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+static void tr2evt_alias_fl(const char *file, int line,\n+\t\t\t    const char *alias, const char **argv)\n+{\n+\tconst char *event_name = \"alias\";\n+\n+\tif (tr2key_trace_want(&tr2key_default)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addf(&buf_payload, \"alias:%s argv:\", alias);\n+\t\tsq_quote_argv_pretty(&buf_payload, argv);\n+\n+\t\ttr2io_write_default_fl(file, line, event_name, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addf(&buf_payload, \"alias:%s argv:\", alias);\n+\t\tsq_quote_argv_pretty(&buf_payload, argv);\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, NULL, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, file, line, &jw);\n+\t\tjw_object_string(&jw, \"alias\", alias);\n+\t\tjw_object_inline_begin_array(&jw, \"argv\");\n+\t\tjw_array_argv(&jw, argv);\n+\t\tjw_end(&jw);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+static void tr2evt_param_fl(const char *file, int line,\n+\t\t\t    const char *param, const char *value)\n+{\n+\tconst char *event_name = \"param\";\n+\n+\tif (tr2key_trace_want(&tr2key_default)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addf(&buf_payload, \"%s:%s\", param, value);\n+\n+\t\ttr2io_write_default_fl(file, line, event_name, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addf(&buf_payload, \"%s:%s\", param, value);\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, NULL, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, file, line, &jw);\n+\t\tjw_object_string(&jw, \"param\", param);\n+\t\tjw_object_string(&jw, \"value\", value);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+/*\n+ * Write a common 'child_start' message to the builtin targets.\n+ */\n+static void tr2evt_child_start_fl(const char *file, int line,\n+\t\t\t\t  int child_id, const char *child_class,\n+\t\t\t\t  const char **argv)\n+{\n+\tconst char *event_name = \"child_start\";\n+\n+\tif (!child_class)\n+\t\tchild_class = \"?\";\n+\n+\tif (tr2key_trace_want(&tr2key_default)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addf(&buf_payload, \"[ch%d] class:%s argv:\",\n+\t\t\t    child_id, child_class);\n+\t\tsq_quote_argv_pretty(&buf_payload, argv);\n+\n+\t\ttr2io_write_default_fl(file, line, event_name, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addf(&buf_payload, \"[ch%d] class:%s argv:\",\n+\t\t\t    child_id, child_class);\n+\t\tsq_quote_argv_pretty(&buf_payload, argv);\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, NULL, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, file, line, &jw);\n+\t\tjw_object_intmax(&jw, \"child_id\", child_id);\n+\t\tjw_object_string(&jw, \"child_class\", child_class);\n+\t\tjw_object_inline_begin_array(&jw, \"argv\");\n+\t\tjw_array_argv(&jw, argv);\n+\t\tjw_end(&jw);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+static void tr2evt_child_exit_fl(const char *file, int line,\n+\t\t\t\t int child_id,\n+\t\t\t\t int child_exit_code,\n+\t\t\t\t uint64_t us_elapsed)\n+{\n+\tconst char *event_name = \"child_exit\";\n+\n+\tif (tr2key_trace_want(&tr2key_default)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\t\tdouble elapsed = (double)us_elapsed / 1000000.0;\n+\n+\t\tstrbuf_addf(&buf_payload, \"[ch%d] code:%d elapsed:%.6f\",\n+\t\t\t    child_id, child_exit_code, elapsed);\n+\t\t\n+\t\ttr2io_write_default_fl(file, line, event_name, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addf(&buf_payload, \"[ch%d] code:%d\",\n+\t\t\t    child_id, child_exit_code);\n+\t\t\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, &us_elapsed, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\t\tdouble elapsed = (double)us_elapsed / 1000000.0;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, file, line, &jw);\n+\t\tjw_object_intmax(&jw, \"child_id\", child_id);\n+\t\tjw_object_intmax(&jw, \"code\", child_exit_code);\n+\t\tjw_object_double(&jw, \"elapsed\", 6, elapsed);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+static void tr2evt_thread_start_fl(const char *file, int line)\n+{\n+\tconst char *event_name = \"thread_start\";\n+\n+\t/* Default target does not care about threads. */\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, NULL, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, file, line, &jw);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+static void tr2evt_thread_exit_fl(const char *file, int line,\n+\t\t\t\t  uint64_t us_elapsed)\n+{\n+\tconst char *event_name = \"thread_exit\";\n+\n+\t/* Default target does not care about threads. */\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, &us_elapsed, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\t\tdouble elapsed = (double)us_elapsed / 1000000.0;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, file, line, &jw);\n+\t\tjw_object_double(&jw, \"elapsed\", 6, elapsed);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+static void tr2evt_region_enter_va_fl(const char *file, int line,\n+\t\t\t\t      const char *fmt, va_list ap)\n+{\n+\tconst char *event_name = \"region_enter\";\n+\n+\t/* Default target does not care about nesting. */\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_vaddf(&buf_payload, fmt, ap);\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, NULL, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct tr2tls_thread_ctx *ctx = tr2tls_get_self();\n+\t\tif (ctx->nr_open_regions <= tr2env_event_depth_wanted) {\n+\t\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\t\t\tstruct strbuf buf = STRBUF_INIT;\n+\n+\t\t\tstrbuf_vaddf(&buf, fmt, ap);\n+\n+\t\t\tjw_object_begin(&jw, 0);\n+\t\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\t\tevent_name, file, line, &jw);\n+\t\t\tjw_object_intmax(&jw, \"depth\", ctx->nr_open_regions);\n+\t\t\tjw_object_string(&jw, \"msg\", buf.buf);\n+\t\t\tjw_end(&jw);\n+\n+\t\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\t\tjw_release(&jw);\n+\t\t\tstrbuf_release(&buf);\n+\t\t}\n+\t}\n+}\n+\n+static void tr2evt_region_leave_va_fl(const char *file, int line,\n+\t\t\t\t      uint64_t us_elapsed,\n+\t\t\t\t      const char *fmt, va_list ap)\n+{\n+\tconst char *event_name = \"region_leave\";\n+\n+\t/* Default target does not care about nesting. */\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_vaddf(&buf_payload, fmt, ap);\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, &us_elapsed, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct tr2tls_thread_ctx *ctx = tr2tls_get_self();\n+\t\tif (ctx->nr_open_regions <= tr2env_event_depth_wanted) {\n+\t\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\t\t\tstruct strbuf buf = STRBUF_INIT;\n+\t\t\tdouble elapsed = (double)us_elapsed / 1000000.0;\n+\n+\t\t\tstrbuf_vaddf(&buf, fmt, ap);\n+\n+\t\t\tjw_object_begin(&jw, 0);\n+\t\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\t\tevent_name, file, line, &jw);\n+\t\t\tjw_object_double(&jw, \"elapsed\", 6, elapsed);\n+\t\t\tjw_object_intmax(&jw, \"depth\", ctx->nr_open_regions);\n+\t\t\tjw_object_string(&jw, \"msg\", buf.buf);\n+\t\t\tjw_end(&jw);\n+\n+\t\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\t\tjw_release(&jw);\n+\t\t\tstrbuf_release(&buf);\n+\t\t}\n+\t}\n+}\n+\n+static void tr2evt_printf_va_fl(const char *file, int line,\n+\t\t\t\tconst char *fmt, va_list ap)\n+{\n+\tconst char *event_name = \"printf\";\n+\n+\tif (tr2key_trace_want(&tr2key_default)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_vaddf(&buf_payload, fmt, ap);\n+\n+\t\ttr2io_write_default_fl(file, line, event_name, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_vaddf(&buf_payload, fmt, ap);\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, NULL, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\t/* Event target does not care about printf messages. */\n+}\n+\n+static void tr2evt_data_fl(const char *file, int line,\n+\t\t\t   const char *category,\n+\t\t\t   const char *key,\n+\t\t\t   const char *value)\n+{\n+\tconst char *event_name = \"data\";\n+\n+\t/* Default target does not care about data messages. */\n+\n+\tif (tr2key_trace_want(&tr2key_perf)) {\n+\t\tstruct strbuf buf_payload = STRBUF_INIT;\n+\n+\t\tstrbuf_addf(&buf_payload, \"category:%s key:%s value:%s\",\n+\t\t\t    category, key, value);\n+\n+\t\ttr2io_write_perf_fl(file, line,\n+\t\t\t\t    event_name, NULL, &buf_payload);\n+\t\tstrbuf_release(&buf_payload);\n+\t}\n+\n+\tif (tr2key_trace_want(&tr2key_event)) {\n+\t\tstruct json_writer jw = JSON_WRITER_INIT;\n+\n+\t\tjw_object_begin(&jw, 0);\n+\t\ttr2fmt_prepare_json_trace_line(\n+\t\t\tevent_name, file, line, &jw);\n+\t\tjw_object_string(&jw, \"category\", category);\n+\t\tjw_object_string(&jw, \"key\", key);\n+\t\tjw_object_string(&jw, \"value\", value);\n+\t\tjw_end(&jw);\n+\n+\t\ttr2io_write_line(&tr2key_event, &jw.json);\n+\t\tjw_release(&jw);\n+\t}\n+}\n+\n+/*****************************************************************\n+ * TODO remove this section header\n+ *****************************************************************/\n+\n+static int tr2main_exit_code;\n+\n+/*\n+ * Our atexit routine should run after everything has finished.\n+ * The system should call it on the main thread.\n+ *\n+ * Note that events generated here might not actually appear if\n+ * we are writing to fd 1 or 2 and our atexit routine runs after\n+ * the pager's atexit routine (since it closes them to shutdown\n+ * the pipes).\n+ */\n+static void tr2main_atexit_handler(void)\n+{\n+\tassert(tr2tls_get_self() == tr2tls_thread_main);\n+\n+\t/*\n+\t * Pop any extra open regions on the main thread and discard.\n+\t * Normally, we should only have the region[0] that was pushed\n+\t * in trace2_start(), but there may be more if someone calls\n+\t * die() for example.\n+\t */\n+\twhile (tr2tls_thread_main->nr_open_regions > 1)\n+\t\ttr2tls_pop_self();\n+\n+\t/*\n+\t * Issue single 'atexit' event with the elapsed time since\n+\t * the main thread was started.\n+\t */\n+\ttr2evt_atexit(tr2main_exit_code, tr2tls_elapsed_main());\n+\t\t\n+\ttr2key_disable_builtins();\n+\n+\ttr2tls_release();\n+\n+\tstrbuf_release(&tr2sid_buf);\n+\tstrbuf_release(&tr2_dots);\n+}\n+\n+static void tr2main_signal_handler(int signo)\n+{\n+\ttr2evt_signal(signo, tr2tls_elapsed_main());\n+\n+\tsigchain_pop(signo);\n+\traise(signo);\n+}\n+\n+/*****************************************************************\n+ * TODO remove this section header\n+ *****************************************************************/\n+\n+void trace2_start_fl(const char *file, int line, const char **argv)\n+{\n+\tif (!tr2key_want_builtins())\n+\t\treturn;\n+\n+\ttr2sid_compute();\n+\tstrbuf_addchars(&tr2_dots, '.',\n+\t\t\tTR2_MAX_REGION_NESTING * TR2_INDENT);\n+\n+\tatexit(tr2main_atexit_handler);\n+\tsigchain_push(SIGPIPE, tr2main_signal_handler);\n+\n+\ttr2tls_init();\n+\n+\ttr2evt_version_fl(file, line);\n+\ttr2evt_start_fl(file, line, argv);\n+}\n+\n+int trace2_exit_fl(const char *file, int line, int code)\n+{\n+\tcode &= 0xff;\n+\n+\tif (!tr2tls_initialized)\n+\t\treturn code;\n+\n+\ttr2main_exit_code = code;\n+\n+\ttr2evt_exit_fl(file, line, code, tr2tls_elapsed_main());\n+\n+\treturn code;\n+}\n+\n+void trace2_error_va_fl(const char *file, int line,\n+\t\t\tconst char *fmt, va_list ap)\n+{\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\ttr2evt_error_va_fl(file, line, fmt, ap);\n+}\n+\n+void trace2_command_fl(const char *file, int line,\n+\t\t       const char *command_name)\n+{\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\ttr2evt_command_fl(file, line, command_name);\n+}\n+\n+void trace2_worktree_fl(const char *file, int line,\n+\t\t\tconst char *path)\n+{\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\ttr2evt_worktree_fl(file, line, path);\n+}\n+\n+void trace2_alias_fl(const char *file, int line,\n+\t\t     const char *alias, const char **argv)\n+{\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\ttr2evt_alias_fl(file, line, alias, argv);\n+}\n+\n+void trace2_param_fl(const char *file, int line,\n+\t\t     const char *param, const char *value)\n+{\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\ttr2evt_param_fl(file, line, param, value);\n+}\n+\n+void trace2_child_start_fl(const char *file, int line,\n+\t\t\t   struct child_process *cmd)\n+{\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\tpthread_mutex_lock(&tr2tls_mutex);\n+\tcmd->trace2_child_id = tr2_next_child_id++;\n+\tpthread_mutex_unlock(&tr2tls_mutex);\n+\n+\tcmd->trace2_child_us_start = getnanotime() / 1000;\n+\n+\ttr2evt_child_start_fl(file, line,\n+\t\t\t      cmd->trace2_child_id,\n+\t\t\t      cmd->trace2_child_class,\n+\t\t\t      cmd->argv);\n+}\n+\n+void trace2_child_exit_fl(const char *file, int line,\n+\t\t\t  struct child_process *cmd,\n+\t\t\t  int child_exit_code)\n+{\n+\tuint64_t us_elapsed;\n+\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\tif (cmd->trace2_child_us_start)\n+\t\tus_elapsed = (getnanotime() / 1000) - cmd->trace2_child_us_start;\n+\telse\n+\t\tus_elapsed = 0;\n+\t\n+\ttr2evt_child_exit_fl(file, line,\n+\t\t\t     cmd->trace2_child_id,\n+\t\t\t     child_exit_code,\n+\t\t\t     us_elapsed);\n+}\n+\n+void trace2_thread_start_fl(const char *file, int line,\n+\t\t\t    const char *thread_name)\n+{\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\ttr2tls_create_self(thread_name);\n+\n+\ttr2evt_thread_start_fl(file, line);\n+}\n+\n+void trace2_thread_exit_fl(const char *file, int line)\n+{\n+\tstruct tr2tls_thread_ctx *ctx;\n+\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\t/*\n+\t * Pop any extra open regions on the current thread and discard.\n+\t * Normally, we should only have the region[0] that was pushed\n+\t * in trace2_thread_start() if the thread exits normally.\n+\t */\n+\tctx = tr2tls_get_self();\n+\twhile (ctx->nr_open_regions > 1)\n+\t\ttr2tls_pop_self();\n+\n+\ttr2evt_thread_exit_fl(file, line, tr2tls_region_elapsed_self());\n+\n+\ttr2tls_unset_self();\n+}\n+\n+void trace2_region_enter_va_fl(const char *file, int line,\n+\t\t\t       const char *fmt, va_list ap)\n+{\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\tif (fmt && *fmt)\n+\t\ttr2evt_region_enter_va_fl(file, line, fmt, ap);\n+\n+\ttr2tls_push_self();\n+}\n+\n+void trace2_region_enter_fl(const char *file, int line,\n+\t\t\t    const char *fmt, ...)\n+{\n+\tva_list ap;\n+\tva_start(ap, fmt);\n+\ttrace2_region_enter_va_fl(file, line, fmt, ap);\n+\tva_end(ap);\n+}\n+\n+#ifndef HAVE_VARIADIC_MACROS\n+void trace2_region_enter(const char *fmt, ...)\n+{\n+\tva_list ap;\n+\tva_start(ap, fmt);\n+\ttrace2_region_enter_va_fl(NULL, 0, fmt, ap);\n+\tva_end(ap);\n+}\n+#endif\n+\n+void trace2_region_leave_va_fl(const char *file, int line,\n+\t\t\t       const char *fmt, va_list ap)\n+{\n+\tuint64_t us_elapsed;\n+\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\t/*\n+\t * Get the elapsed time in the current region before we\n+\t * pop it off the stack.  Pop the stack.  And then print\n+\t * the perf message at the new (shallower) level so that\n+\t * it lines up with the corresponding push/enter.\n+\t */\n+\tus_elapsed = tr2tls_region_elapsed_self();\n+\t\n+\ttr2tls_pop_self();\n+\n+\tif (fmt && *fmt)\n+\t\ttr2evt_region_leave_va_fl(file, line, us_elapsed, fmt, ap);\n+}\n+\n+void trace2_region_leave_fl(const char *file, int line,\n+\t\t\t    const char *fmt, ...)\n+{\n+\tva_list ap;\n+\tva_start(ap, fmt);\n+\ttrace2_region_leave_va_fl(file, line, fmt, ap);\n+\tva_end(ap);\n+}\n+\n+#ifndef HAVE_VARIADIC_MACROS\n+void trace2_region_leave(const char *fmt, ...)\n+{\n+\tva_list ap;\n+\tva_start(ap, fmt);\n+\ttrace2_region_leave_va_fl(NULL, 0, fmt, ap);\n+\tva_end(ap);\n+}\n+#endif\n+\n+void trace2_printf_va_fl(const char *file, int line,\n+\t\t\t const char *fmt, va_list ap)\n+{\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\ttr2evt_printf_va_fl(file, line, fmt, ap);\n+}\n+\n+void trace2_printf_fl(const char *file, int line,\n+\t\t      const char *fmt, ...)\n+{\n+\tva_list ap;\n+\n+\tva_start(ap, fmt);\n+\ttrace2_printf_va_fl(file, line, fmt, ap);\n+\tva_end(ap);\n+}\n+\n+#ifndef HAVE_VARIADIC_MACROS\n+void trace2_printf(const char *fmt, ...)\n+{\n+\tva_list ap;\n+\n+\tva_start(ap, fmt);\n+\ttrace2_printf_va_fl(NULL, 0, fmt, ap);\n+\tva_end(ap);\n+}\n+#endif\n+\n+void trace2_data_intmax_fl(const char *file, int line,\n+\t\t\t   const char *category,\n+\t\t\t   const char *key,\n+\t\t\t   intmax_t value)\n+{\n+\tstruct strbuf buf_string = STRBUF_INIT;\n+\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\tstrbuf_addf(&buf_string, \"%\"PRIdMAX, value);\n+\ttr2evt_data_fl(file, line, category, key, buf_string.buf);\n+\tstrbuf_release(&buf_string);\n+}\n+\n+void trace2_data_string_fl(const char *file, int line,\n+\t\t\t   const char *category,\n+\t\t\t   const char *key,\n+\t\t\t   const char *value)\n+{\n+\tif (!tr2tls_initialized)\n+\t\treturn;\n+\n+\ttr2evt_data_fl(file, line, category, key, value);\n+}\ndiff --git a/trace2.h b/trace2.h\nnew file mode 100644\nindex 0000000000..0ef08c1253\n--- /dev/null\n+++ b/trace2.h\n@@ -0,0 +1,214 @@\n+#ifndef TRACE2_H\n+#define TRACE2_H\n+\n+/*\n+ * Begin TRACE2 tracing (if any of the builtin TRACE2 targets are\n+ * enabled in the environment).\n+ *\n+ * Emit a 'start' event.\n+ */\n+void trace2_start_fl(const char *file, int line,\n+\t\t     const char **argv);\n+\n+#define trace2_start(argv) trace2_start_fl(__FILE__, __LINE__, argv)\n+\n+/*\n+ * Emit an 'exit' event.\n+ *\n+ * Write the exit-code that will be passed to exit() or returned\n+ * from main().  Use this prior to actually calling exit().\n+ * See \"#define exit()\" in git-compat-util.h\n+ */\n+int trace2_exit_fl(const char *file, int line, int code);\n+\n+#define trace2_exit(code) (trace2_exit_fl(__FILE__, __LINE__, (code)))\n+\n+/*\n+ * Emit an 'error' event.\n+ *\n+ * Write an error message to the TRACE2 targets.\n+ */\n+void trace2_error_va_fl(const char *file, int line,\n+\t\t\tconst char *fmt, va_list ap);\n+\n+#define trace2_error_va(fmt, ap) \\\n+\ttrace2_error_va_fl(__FILE__, __LINE__, (fmt), (ap))\n+\n+void trace2_command_fl(const char *file, int line,\n+\t\t       const char *command_name);\n+\n+#define trace2_command(n) \\\n+\ttrace2_command_fl(__FILE__, __LINE__, (n))\n+\n+/*\n+ * Emit a 'worktree' event giving the absolute path of the worktree.\n+ */\n+void trace2_worktree_fl(const char *file, int line,\n+\t\t\tconst char *path);\n+\n+#define trace2_worktree(path) \\\n+\ttrace2_worktree_fl(__FILE__, __LINE__, path)\n+\n+/*\n+ * Emit an 'alias' expansion event.\n+ */\n+void trace2_alias_fl(const char *file, int line,\n+\t\t     const char *alias, const char **argv);\n+\n+#define trace2_alias(alias, argv) \\\n+\ttrace2_alias_fl(__FILE__, __LINE__, (alias), (argv))\n+\n+/*\n+ * Emit a 'param' event.\n+ *\n+ * Write a (key, value) pair describing some aspect of the run\n+ * such as an important configuration setting.\n+ */ \n+void trace2_param_fl(const char *file, int line,\n+\t\t     const char *param, const char *value);\n+\n+#define trace2_param(param, value) \\\n+\ttrace2_param_fl(__FILE__, __LINE__, (param), (value))\n+\n+struct child_process;\n+\n+/*\n+ * Emit a 'child_start' event prior to spawning a child process.\n+ *\n+ * Before calling optionally set cmd.trace2_child_class to a string\n+ * describing the type of the child process.  For example, \"editor\"\n+ * or \"pager\".\n+ */\n+void trace2_child_start_fl(const char *file, int line,\n+\t\t\t   struct child_process *cmd);\n+\n+#define trace2_child_start(cmd) \\\n+\ttrace2_child_start_fl(__FILE__, __LINE__, (cmd))\n+\n+/*\n+ * Emit a 'child_exit' event after the child process completes. \n+ */\n+void trace2_child_exit_fl(const char *file, int line,\n+\t\t\t  struct child_process *cmd,\n+\t\t\t  int child_exit_code);\n+\n+#define trace2_child_exit(cmd, code) \\\n+\ttrace2_child_exit_fl(__FILE__, __LINE__, (cmd), (code))\n+\n+/*\n+ * Emit a 'thread_start' event.  This must be called from inside the\n+ * thread-proc to set up TLS data for the thread.\n+ *\n+ * Thread names should be descriptive, like \"preload_index\".\n+ * Thread names will be decorated with an instance number automatically.\n+ */\n+void trace2_thread_start_fl(const char *file, int line,\n+\t\t\t    const char *thread_name);\n+\n+#define trace2_thread_start(thread_name) \\\n+\ttrace2_thread_start_fl(__FILE__, __LINE__, (thread_name))\n+\n+/*\n+ * Emit a 'thead_exit' event.  This must be called from inside the\n+ * thread-proc to report thread-specific data and cleanup TLS data\n+ * for the thread.\n+ */\n+void trace2_thread_exit_fl(const char *file, int line);\n+\n+#define trace2_thread_exit() trace2_thread_exit_fl(__FILE__, __LINE__)\n+\n+/*\n+ * Emit a 'printf' event.\n+ *\n+ * Write an arbitrary formatted message to the TRACE2 targets.  These\n+ * text messages should be considered as human-readable strings without\n+ * any formatting guidelines.  Post-processors may choose to ignore\n+ * them.\n+ */\n+void trace2_printf_va_fl(const char *file, int line,\n+\t\t\t const char *fmt, va_list ap);\n+\n+#define trace2_printf_va(fmt, ap) \\\n+\ttrace2_printf_va_fl(__FILE__, __LINE__, (fmt), (ap))\n+\n+void trace2_printf_fl(const char *file, int line, const char *fmt, ...);\n+\n+#ifdef HAVE_VARIADIC_MACROS\n+#define trace2_printf(...) \\\n+\ttrace2_printf_fl(__FILE__, __LINE__, __VA_ARGS__)\n+#else\n+__attribute__((format (printf, 1, 2)))\n+void trace2_printf(const char *fmt, ...);\n+#endif\n+\n+/*\n+ * Emit a 'region_enter' event.\n+ *\n+ * Enter a new nesting level on the current thread and remember the\n+ * current time.  This controls the indenting of subsequent thread\n+ * events.\n+ */\n+void trace2_region_enter_va_fl(const char *file, int line,\n+\t\t\t       const char *fmt, va_list ap);\n+\n+#define trace2_region_enter_va(fmt, ap) \\\n+\ttrace2_region_enter_va_fl(__FILE__, __LINE__, (fmt), (ap))\n+\n+void trace2_region_enter_fl(const char *file, int line, const char *fmt, ...);\n+\n+#ifdef HAVE_VARIADIC_MACROS\n+#define trace2_region_enter(...) \\\n+\ttrace2_region_enter_fl(__FILE__, __LINE__, __VA_ARGS__)\n+#else\n+__attribute__((format (printf, 1, 2)))\n+void trace2_region_enter(const char *fmt, ...);\n+#endif\n+\n+/*\n+ * Emit a 'region_leave' event.\n+ *\n+ * Leave current nesting level and report the elapsed time spent\n+ * in this nesting level.\n+ */\n+void trace2_region_leave_va_fl(const char *file, int line,\n+\t\t\t       const char *fmt, va_list ap);\n+\n+#define trace2_region_enter_va(fmt, ap) \\\n+\ttrace2_region_enter_va_fl(__FILE__, __LINE__, (fmt), (ap))\n+\n+void trace2_region_leave_fl(const char *file, int line, const char *fmt, ...);\n+\n+#ifdef HAVE_VARIADIC_MACROS\n+#define trace2_region_leave(...) \\\n+\ttrace2_region_leave_fl(__FILE__, __LINE__, __VA_ARGS__)\n+#else\n+__attribute__((format (printf, 1, 2)))\n+void trace2_region_leave(const char *fmt, ...);\n+#endif\n+\n+/*\n+ * Emit a 'data' event to report a <category>.<key> = <value> pair.\n+ * This can be used to report global data, such as the size of the index,\n+ * or by a thread to report TLS data, such as their assigned subset.\n+ *\n+ * On event-based TRACE2 targets, this generates a 'data' event suitable\n+ * for post-processing.  On printf-based TRACE2 targets, this is converted\n+ * into a fixed-format printf message.\n+ */\n+void trace2_data_intmax_fl(const char *file, int line,\n+\t\t\t   const char *category,\n+\t\t\t   const char *key,\n+\t\t\t   intmax_t value);\n+\n+#define trace2_data_intmax(c, k, v) \\\n+\ttrace2_data_intmax_fl(__FILE__, __LINE__, (c), (k), (v))\n+\n+void trace2_data_string_fl(const char *file, int line,\n+\t\t\t   const char *category,\n+\t\t\t   const char *key,\n+\t\t\t   const char *value);\n+\n+#define trace2_data_string(c, k, v) \\\n+\ttrace2_data_string_fl(__FILE__, __LINE__, (c), (k), (v))\n+\n+#endif /* TRACE2_H */\n-- \ngitgitgadget\n\n"},{"id":"357095","messageId":"3ee8dcc8d356bfe18292dede717be509ca406b3d.1535734192.git.gitgitgadget@gmail.com","threadId":"49264","inReplyTo":"pull.29.git.gitgitgadget@gmail.com","subject":"[PATCH 4/8] trace2: demonstrate trace2 child process classification","fromName":"Jeff Hostetler via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2018-08-31T16:49:59Z","receivedAt":"2018-08-31T16:50:03Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler <jeffhost@microsoft.com>\n\nClassify editory, pager, and sub-process child processes.\nThe former two can be used to identify interactive commands,\nfor example.\n\nSigned-off-by: Jeff Hostetler <jeffhost@microsoft.com>\n---\n editor.c      | 1 +\n pager.c       | 1 +\n sub-process.c | 1 +\n 3 files changed, 3 insertions(+)\n\ndiff --git a/editor.c b/editor.c\nindex 9a9b4e12d1..29707de198 100644\n--- a/editor.c\n+++ b/editor.c\n@@ -66,6 +66,7 @@ int launch_editor(const char *path, struct strbuf *buffer, const char *const *en\n \t\tp.argv = args;\n \t\tp.env = env;\n \t\tp.use_shell = 1;\n+\t\tp.trace2_child_class = \"editor\";\n \t\tif (start_command(&p) < 0)\n \t\t\treturn error(\"unable to start editor '%s'\", editor);\n \ndiff --git a/pager.c b/pager.c\nindex a768797fcf..4168460ae9 100644\n--- a/pager.c\n+++ b/pager.c\n@@ -100,6 +100,7 @@ void prepare_pager_args(struct child_process *pager_process, const char *pager)\n \targv_array_push(&pager_process->args, pager);\n \tpager_process->use_shell = 1;\n \tsetup_pager_env(&pager_process->env_array);\n+\tpager_process->trace2_child_class = \"pager\";\n }\n \n void setup_pager(void)\ndiff --git a/sub-process.c b/sub-process.c\nindex 8d2a1707cf..3f4af93555 100644\n--- a/sub-process.c\n+++ b/sub-process.c\n@@ -88,6 +88,7 @@ int subprocess_start(struct hashmap *hashmap, struct subprocess_entry *entry, co\n \tprocess->out = -1;\n \tprocess->clean_on_exit = 1;\n \tprocess->clean_on_exit_handler = subprocess_exit_handler;\n+\tprocess->trace2_child_class = \"subprocess\";\n \n \terr = start_command(process);\n \tif (err) {\n-- \ngitgitgadget\n\n"},{"id":"357096","messageId":"45a88264dd20daddbe02af3cb6a785dbb49addfa.1535734192.git.gitgitgadget@gmail.com","threadId":"49264","inReplyTo":"pull.29.git.gitgitgadget@gmail.com","subject":"[PATCH 5/8] trace2: demonstrate instrumenting do_read_index","fromName":"Jeff Hostetler via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2018-08-31T16:50:00Z","receivedAt":"2018-08-31T16:50:04Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler <jeffhost@microsoft.com>\n\nSigned-off-by: Jeff Hostetler <jeffhost@microsoft.com>\n---\n read-cache.c | 6 ++++++\n 1 file changed, 6 insertions(+)\n\ndiff --git a/read-cache.c b/read-cache.c\nindex 7b1354d759..7a31ac4da8 100644\n--- a/read-cache.c\n+++ b/read-cache.c\n@@ -1867,6 +1867,8 @@ static void tweak_split_index(struct index_state *istate)\n \n static void post_read_index_from(struct index_state *istate)\n {\n+\ttrace2_data_intmax(\"index\", \"cache_nr\", istate->cache_nr);\n+\n \tcheck_ce_order(istate);\n \ttweak_untracked_cache(istate);\n \ttweak_split_index(istate);\n@@ -2012,7 +2014,9 @@ int read_index_from(struct index_state *istate, const char *path,\n \tif (istate->initialized)\n \t\treturn istate->cache_nr;\n \n+\ttrace2_region_enter(\"do_read_index\");\n \tret = do_read_index(istate, path, 0);\n+\ttrace2_region_leave(\"do_read_index\");\n \ttrace_performance_since(start, \"read cache %s\", path);\n \n \tsplit_index = istate->split_index;\n@@ -2028,7 +2032,9 @@ int read_index_from(struct index_state *istate, const char *path,\n \n \tbase_oid_hex = oid_to_hex(&split_index->base_oid);\n \tbase_path = xstrfmt(\"%s/sharedindex.%s\", gitdir, base_oid_hex);\n+\ttrace2_region_enter(\"do_read_index\");\n \tret = do_read_index(split_index->base, base_path, 1);\n+\ttrace2_region_leave(\"do_read_index\");\n \tif (oidcmp(&split_index->base_oid, &split_index->base->oid))\n \t\tdie(\"broken index, expect %s in %s, got %s\",\n \t\t    base_oid_hex, base_path,\n-- \ngitgitgadget\n\n"},{"id":"357097","messageId":"2db85146df849c2545e32ad32501c4fe5002bfa0.1535734192.git.gitgitgadget@gmail.com","threadId":"49264","inReplyTo":"pull.29.git.gitgitgadget@gmail.com","subject":"[PATCH 3/8] trace2: demonstrate trace2 regions in wt-status","fromName":"Jeff Hostetler via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2018-08-31T16:49:58Z","receivedAt":"2018-08-31T16:50:05Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler <jeffhost@microsoft.com>\n\nAdd trace2_region_enter() and trace2_region_leave() calls around the\nvarious phases of a status scan.  This gives elapsed time for each\nphase in the GIT_TR2_PERFORMANCE trace target.\n\nSigned-off-by: Jeff Hostetler <jeffhost@microsoft.com>\n---\n wt-status.c | 14 ++++++++++++--\n 1 file changed, 12 insertions(+), 2 deletions(-)\n\ndiff --git a/wt-status.c b/wt-status.c\nindex 5ffab61015..9e37a73c73 100644\n--- a/wt-status.c\n+++ b/wt-status.c\n@@ -726,13 +726,23 @@ static void wt_status_collect_untracked(struct wt_status *s)\n \n void wt_status_collect(struct wt_status *s)\n {\n+\ttrace2_region_enter(\"status_worktrees\");\n \twt_status_collect_changes_worktree(s);\n+\ttrace2_region_leave(\"status_worktrees\");\n \n-\tif (s->is_initial)\n+\tif (s->is_initial) {\n+\t\ttrace2_region_enter(\"status_initial\");\n \t\twt_status_collect_changes_initial(s);\n-\telse\n+\t\ttrace2_region_leave(\"status_initial\");\n+\t} else {\n+\t\ttrace2_region_enter(\"status_index\");\n \t\twt_status_collect_changes_index(s);\n+\t\ttrace2_region_leave(\"status_index\");\n+\t}\n+\n+\ttrace2_region_enter(\"status_untracked\");\n \twt_status_collect_untracked(s);\n+\ttrace2_region_leave(\"status_untracked\");\n }\n \n static void wt_longstatus_print_unmerged(struct wt_status *s)\n-- \ngitgitgadget\n\n"},{"id":"357098","messageId":"e3bde216b86fcb13da006937c8472823df9aa636.1535734192.git.gitgitgadget@gmail.com","threadId":"49264","inReplyTo":"pull.29.git.gitgitgadget@gmail.com","subject":"[PATCH 7/8] trace2: demonstrate setting sub-command parameter in checkout","fromName":"Jeff Hostetler via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2018-08-31T16:50:03Z","receivedAt":"2018-08-31T16:50:06Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler <jeffhost@microsoft.com>\n\nAdd trace2_param() events in checkout to report whether the command\nis switching branches or just checking out a file.\n\nSigned-off-by: Jeff Hostetler <jeffhost@microsoft.com>\n---\n builtin/checkout.c | 5 +++++\n 1 file changed, 5 insertions(+)\n\ndiff --git a/builtin/checkout.c b/builtin/checkout.c\nindex 29ef50013d..0934587781 100644\n--- a/builtin/checkout.c\n+++ b/builtin/checkout.c\n@@ -251,6 +251,8 @@ static int checkout_paths(const struct checkout_opts *opts,\n \tint errs = 0;\n \tstruct lock_file lock_file = LOCK_INIT;\n \n+\ttrace2_param(\"subcommand\", (opts->patch_mode ? \"patch\" : \"path\"));\n+\n \tif (opts->track != BRANCH_TRACK_UNSPECIFIED)\n \t\tdie(_(\"'%s' cannot be used with updating paths\"), \"--track\");\n \n@@ -828,6 +830,9 @@ static int switch_branches(const struct checkout_opts *opts,\n \tvoid *path_to_free;\n \tstruct object_id rev;\n \tint flag, writeout_error = 0;\n+\n+\ttrace2_param(\"subcommand\", \"switch\");\n+\n \tmemset(&old_branch_info, 0, sizeof(old_branch_info));\n \told_branch_info.path = path_to_free = resolve_refdup(\"HEAD\", 0, &rev, &flag);\n \tif (old_branch_info.path)\n-- \ngitgitgadget\n\n"},{"id":"357099","messageId":"cb64de09f3d857de448c27245693311bf7c7e5b0.1535734192.git.gitgitgadget@gmail.com","threadId":"49264","inReplyTo":"pull.29.git.gitgitgadget@gmail.com","subject":"[PATCH 8/8] trace2: demonstrate use of regions in read_directory_recursive","fromName":"Jeff Hostetler via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2018-08-31T16:50:05Z","receivedAt":"2018-08-31T16:50:07Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler <jeffhost@microsoft.com>\n\nAdd trace2_region_enter() and _leave() calls inside read_directory_recursive()\nto show nesting and per-level timing.\n\nTODO Drop this commit or ifdef the calls.  It generates too much data to\nbe in the production version.  It is included in this patch series for\nillustration purposes only.  It is typical of what a developer might do\nduring a perf investigation.\n\nSigned-off-by: Jeff Hostetler <jeffhost@microsoft.com>\n---\n dir.c | 3 +++\n 1 file changed, 3 insertions(+)\n\ndiff --git a/dir.c b/dir.c\nindex aceb0d4869..c7c0654da5 100644\n--- a/dir.c\n+++ b/dir.c\n@@ -1951,6 +1951,8 @@ static enum path_treatment read_directory_recursive(struct dir_struct *dir,\n \n \tstrbuf_add(&path, base, baselen);\n \n+\ttrace2_region_enter(\"read_directory_recursive:%.*s\", baselen, base);\n+\n \tif (open_cached_dir(&cdir, dir, untracked, istate, &path, check_only))\n \t\tgoto out;\n \n@@ -2042,6 +2044,7 @@ static enum path_treatment read_directory_recursive(struct dir_struct *dir,\n \tclose_cached_dir(&cdir);\n  out:\n \tstrbuf_release(&path);\n+\ttrace2_region_leave(\"read_directory_recursive:%.*s\", baselen, base);\n \n \treturn dir_state;\n }\n-- \ngitgitgadget\n"},{"id":"357100","messageId":"82b7680a2e3f85685950ac288534b8c6575bcd63.1535734192.git.gitgitgadget@gmail.com","threadId":"49264","inReplyTo":"pull.29.git.gitgitgadget@gmail.com","subject":"[PATCH 6/8] trace2: demonstrate instrumenting threaded preload_index","fromName":"Jeff Hostetler via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2018-08-31T16:50:02Z","receivedAt":"2018-08-31T16:50:08Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"From: Jeff Hostetler <jeffhost@microsoft.com>\n\nAdd trace2_region_enter() and _leave() around the entire preload_index()\ncall.  Also add thread-specific events in the preload_thread() threadproc.\n\nSigned-off-by: Jeff Hostetler <jeffhost@microsoft.com>\n---\n preload-index.c | 10 ++++++++++\n 1 file changed, 10 insertions(+)\n\ndiff --git a/preload-index.c b/preload-index.c\nindex 71cd2437a3..2483d92c61 100644\n--- a/preload-index.c\n+++ b/preload-index.c\n@@ -40,10 +40,14 @@ static void *preload_thread(void *_data)\n \tstruct cache_entry **cep = index->cache + p->offset;\n \tstruct cache_def cache = CACHE_DEF_INIT;\n \n+\ttrace2_thread_start(\"preload_thread\");\n+\n \tnr = p->nr;\n \tif (nr + p->offset > index->cache_nr)\n \t\tnr = index->cache_nr - p->offset;\n \n+\ttrace2_printf(\"preload {offset %7d}{count %7d}\", p->offset, nr);\n+\n \tdo {\n \t\tstruct cache_entry *ce = *cep++;\n \t\tstruct stat st;\n@@ -70,6 +74,9 @@ static void *preload_thread(void *_data)\n \t\tmark_fsmonitor_valid(ce);\n \t} while (--nr > 0);\n \tcache_def_clear(&cache);\n+\n+\ttrace2_thread_exit();\n+\n \treturn NULL;\n }\n \n@@ -118,6 +125,9 @@ int read_index_preload(struct index_state *index,\n {\n \tint retval = read_index(index);\n \n+\ttrace2_region_enter(\"preload_index\");\n \tpreload_index(index, pathspec);\n+\ttrace2_region_leave(\"preload_index\");\n+\n \treturn retval;\n }\n-- \ngitgitgadget\n\n"},{"id":"357103","messageId":"2ba9d81a-5578-a81c-a7d9-179864cb4277@gmail.com","threadId":"49264","inReplyTo":"pull.29.git.gitgitgadget@gmail.com","subject":"Re: [PATCH 0/8] WIP: trace2: a new trace facility","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2018-08-31T17:19:26Z","receivedAt":"2018-08-31T17:19:30Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"On 8/31/2018 12:49 PM, Jeff Hostetler via GitGitGadget wrote:\n> This patch series contains a new trace2 facility that hopefully addresses\n> the recent trace- and structured-logging-related discussions. The intent is\n> to eventually replace the existing trace_ routines (or to route them to the\n> new trace2_ routines) as time permits.\n\nI haven't been part of the recent discussions on these logging efforts, \nbut I wanted to mention that I'm excited about the potential here. I \nwant to use this new tracing model to trace how many commits are walked \nby graph algorithms like paint_down_to_common().\n\nI'm playing with some efforts here, and found one issue when the API is \nused incorrectly (I'll respond to the patch with the issue).\n\nThanks,\n\n-Stolee\n\n"},{"id":"357104","messageId":"e2e07731-6a13-d511-f568-5f81311f4904@gmail.com","threadId":"49264","inReplyTo":"82885700379efe6d6a83629cac4d943b99b393bf.1535734192.git.gitgitgadget@gmail.com","subject":"Re: [PATCH 1/8] trace2: create new combined trace facility","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2018-08-31T17:19:45Z","receivedAt":"2018-08-31T17:19:48Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"On 8/31/2018 12:49 PM, Jeff Hostetler via GitGitGadget wrote:\n> +\tif (tr2key_trace_want(&tr2key_event)) {\n> +\t\tstruct tr2tls_thread_ctx *ctx = tr2tls_get_self();\n> +\t\tif (ctx->nr_open_regions <= tr2env_event_depth_wanted) {\n\nThis should also compare to TR2_MAX_REGION_NESTING to avoid memory \nbounds issues. It may even be worth sending a message that the depth \nwent beyond the limits.\n\nThanks,\n\n-Stolee\n\n"},{"id":"357385","messageId":"CAGZ79kbUYDAKi-K2uHpkffPjMxGYtH=QUMhvfq4HTc5+a7-eBA@mail.gmail.com","threadId":"49264","inReplyTo":"82885700379efe6d6a83629cac4d943b99b393bf.1535734192.git.gitgitgadget@gmail.com","subject":"Re: [PATCH 1/8] trace2: create new combined trace facility","fromName":"Stefan Beller","fromEmail":"sbeller@google.com","sentAt":"2018-09-04T22:12:53Z","receivedAt":"2018-09-04T22:13:07Z","isPatch":true,"sender":{"key":"stefanbeller@gmail.com","avatar":"https://avatars.githubusercontent.com/u/455868?v=4"},"body":"> Create GIT_TR2 trace-key to replace GIT_TRACE, GIT_TR2_PERFORMANCE to\n> replace GIT_TRACE_PERFORMANCE, and a new trace-key GIT_TR2_EVENT to\n> generate JSON data for telemetry purposes.  Other structured formats\n> can easily be added later using this new existing model.\n\nSo the idea is to use the GIT_TR2 instead of GIT_TRACE and we\nget the same output as well as a new form of structured logging here?\n(Then GIT_TRACE could be retired, and we'd use the new API to add\nmore events, which are also more structured as the API allows for more\nthan just a string printed?)\n\n> Define a higher-level event API that selectively writes to all of the\n> new GIT_TR2_* targets (depending on event type) without needing to call\n> different trace_printf*() or trace_performance_*() routines.\n>\n> The API defines both fixed-field and printf-style functions.\n>\n> The trace2 performance tracing includes thread-specific function\n> nesting and timings.\n\nSo this only adds the new API, and we need to merge the TRACE\ninto the TRACE2 later?\n\n> +++ b/trace2.c\n> @@ -0,0 +1,1592 @@\n[...]\n> +\n> +/*****************************************************************\n> + * TODO remove this section header\n> + *****************************************************************/\n\nYes, please.\n\n> +/*\n> + * Compute a \"unique\" session id (SID) for the current process.  All events\n> + * from this process will have this label.  If we were started by another\n> + * git instance, use our parent's SID as a prefix and count the number of\n> + * nested git processes.  (This lets us track parent/child relationships\n> + * even if there is an intermediate shell process.)\n\nHow does this work with threading. From this description we can have\ntwo threads starting new child processes and they have the same ID\n(<our id>-2)\n\n> +\n> +/*****************************************************************\n> + * TODO remove this section header\n> + *****************************************************************/\n\nThis looks like a reoccurring pattern. Did you have a tool\nthat needs these? Does the tool want to enforce some level of\ndocumentation on each function?\n\n> +\n> +/*\n> + * Each thread (including the main thread) has a stack of nested regions.\n> + * This is used to indent messages and provide nested perf times.  The\n> + * limit here is for simplicity.  Note that the region stack is per-thread\n> + * and not per-trace_key.\n\nWhat are the (nested) regions used for? I would imagine recursive\noperations, e.g. unpacking trees? Where am I supposed to read\nup on those?\n\n> + */\n> +#define TR2_MAX_REGION_NESTING (100)\n> +#define TR2_INDENT (2)\n> +#define TR2_INDENT_LENGTH(ctx) (((ctx)->nr_open_regions - 1) * TR2_INDENT)\n\nIn the structured part of the logging the indentation would not be\nneeded and we'd rather want to store the nesting level as an int,\nthis is solely for printing locally I'd assume.\n\n> +#define TR2_MAX_THREAD_NAME (24)\n\nThis is the max length for a thread name including all the prefixes?\n\n\n> +static void tr2tls_unset_self(void)\n> +{\n> +       struct tr2tls_thread_ctx * ctx;\n> +\n> +       ctx = tr2tls_get_self();\n> +\n> +       pthread_setspecific(tr2tls_key, NULL);\n\nWould we also need to free tr2tls_key ?\n\n\n> +/*****************************************************************\n> + * TODO remove this section header\n> + *****************************************************************/\n> +\n> +static void tr2io_write_line(struct trace_key *key, struct strbuf *buf_line)\n> +{\n> +       strbuf_complete_line(buf_line); /* ensure final NL on buffer */\n> +\n> +       // TODO we don't really want short-writes to try again when\n> +       // TODO we are in append mode...\n\nA different kind of TODO in a // comment?\n"},{"id":"357387","messageId":"xmqqzhww6gl8.fsf@gitster-ct.c.googlers.com","threadId":"49264","inReplyTo":"CAGZ79kbUYDAKi-K2uHpkffPjMxGYtH=QUMhvfq4HTc5+a7-eBA@mail.gmail.com","subject":"Re: [PATCH 1/8] trace2: create new combined trace facility","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2018-09-04T22:30:27Z","receivedAt":"2018-09-04T22:30:31Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Stefan Beller <sbeller@google.com> writes:\n\n>> The API defines both fixed-field and printf-style functions.\n>>\n>> The trace2 performance tracing includes thread-specific function\n>> nesting and timings.\n>\n> So this only adds the new API, and we need to merge the TRACE\n> into the TRACE2 later?\n\nIf this is a rhetorical question implying that it would be best if\nthe existing trace() were rewritten to be built on top of trace2()\nwhile building this series, especially before adding new callsites\nthat directly use trace2(), I may share that feeling.  I haven't\nstudied this new round deeply enough to see how realistic it would\nbe, though.\n\n\n"},{"id":"357434","messageId":"dfdd9e8e-68f0-d36c-9479-79a9be08eeda@jeffhostetler.com","threadId":"49264","inReplyTo":"CAGZ79kbUYDAKi-K2uHpkffPjMxGYtH=QUMhvfq4HTc5+a7-eBA@mail.gmail.com","subject":"Re: [PATCH 1/8] trace2: create new combined trace facility","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2018-09-05T15:01:37Z","receivedAt":"2018-09-05T15:01:42Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 9/4/2018 6:12 PM, Stefan Beller wrote:\n>> Create GIT_TR2 trace-key to replace GIT_TRACE, GIT_TR2_PERFORMANCE to\n>> replace GIT_TRACE_PERFORMANCE, and a new trace-key GIT_TR2_EVENT to\n>> generate JSON data for telemetry purposes.  Other structured formats\n>> can easily be added later using this new existing model.\n> \n> So the idea is to use the GIT_TR2 instead of GIT_TRACE and we\n> get the same output as well as a new form of structured logging here?\n> (Then GIT_TRACE could be retired, and we'd use the new API to add\n> more events, which are also more structured as the API allows for more\n> than just a string printed?)\n> \n>> Define a higher-level event API that selectively writes to all of the\n>> new GIT_TR2_* targets (depending on event type) without needing to call\n>> different trace_printf*() or trace_performance_*() routines.\n>>\n>> The API defines both fixed-field and printf-style functions.\n>>\n>> The trace2 performance tracing includes thread-specific function\n>> nesting and timings.\n> \n> So this only adds the new API, and we need to merge the TRACE\n> into the TRACE2 later?\n> \n>> +++ b/trace2.c\n>> @@ -0,0 +1,1592 @@\n> [...]\n>> +\n>> +/*****************************************************************\n>> + * TODO remove this section header\n>> + *****************************************************************/\n> \n> Yes, please.\n> \n>> +/*\n>> + * Compute a \"unique\" session id (SID) for the current process.  All events\n>> + * from this process will have this label.  If we were started by another\n>> + * git instance, use our parent's SID as a prefix and count the number of\n>> + * nested git processes.  (This lets us track parent/child relationships\n>> + * even if there is an intermediate shell process.)\n> \n> How does this work with threading. From this description we can have\n> two threads starting new child processes and they have the same ID\n> (<our id>-2)\n\nThreads are not involved here.\n\nA git process computes its own unique session id.  It is constructed\nfrom { [<inherited-parent-sid>], <current-time>, <current-pid> }.\nSo in the following example, fetch spawned rev-list and gc.  (I've\nstripped out fields irrelevant to this discussion.)\n\n\"sid\":\"1536153920286494-12592\",\n\"argv\":[\"C:\\\\work\\\\gfw\\\\git.exe\",\"--exec-path=.\",\"fetch\",\"gh\"]\n\n\"sid\":\"1536153920286494-12592/1536153925520530-23024\",\n\"argv\":[\"git\",\"rev-list\",\"--objects\",\"--stdin\", ...]\n\n\"sid\":\"1536153920286494-12592/1536153926081533-23992\",\n\"argv\":[\"git\",\"gc\",\"--auto\"]\n\nSo 2 child processes simultaneously spawned from 2 threads in the\ntop-level git command, would still have unique SIDs since their PIDs\nare unique over the time interval of their execution.\n\nIn the above example, if rev-list spawned a child git process, that\nchild's SID would have 3 components (the prefix that it inherited\nplus its own time and pid):\n     1536153920286494-12592/1536153925520530-23024/<time>-<pid>\n\nThe above model works even if there is a shell command between the\ntop-level git command and the child git processes.\n\n> \n>> +\n>> +/*****************************************************************\n>> + * TODO remove this section header\n>> + *****************************************************************/\n> \n> This looks like a reoccurring pattern. Did you have a tool\n> that needs these? Does the tool want to enforce some level of\n> documentation on each function?\n\nNo, this is just an <hr> that helps me see the different sections\nas different sections in the editor and helps me group like items.\nI might change that to a group-level comment that describes the\noverall concept/purpose of the section.  Either way I'll get rid of\nthe stars.\n\n> \n>> +\n>> +/*\n>> + * Each thread (including the main thread) has a stack of nested regions.\n>> + * This is used to indent messages and provide nested perf times.  The\n>> + * limit here is for simplicity.  Note that the region stack is per-thread\n>> + * and not per-trace_key.\n> \n> What are the (nested) regions used for? I would imagine recursive\n> operations, e.g. unpacking trees? Where am I supposed to read\n> up on those?\n\nUnpacking trees would be a good usage. Duy did something similar in a\nrecent patch series.\n\nNested regions are intended for perf times.  The 8th patch in\nthis series demonstrates adding trace2_region_enter() and _leave()\ncalls inside read_directory_recursive().  The second column here\nshows the elapsed time between the _enter and _leave.  (Again, I've\nstripped out fields not currently relevant.)\n\n| region_enter |           | status_untracked\n| region_enter |           | ..read_directory_recursive:\n| region_enter |           | ....read_directory_recursive:.github/\n| region_leave |  0.000095 | ....read_directory_recursive:.github/\n| region_enter |           | ....read_directory_recursive:block-sha1/\n| region_leave |  0.000086 | ....read_directory_recursive:block-sha1/\n| region_enter |           | ....read_directory_recursive:builtin/\n| region_leave |  0.000716 | ....read_directory_recursive:builtin/\n| region_enter |           | ....read_directory_recursive:ci/\n| region_enter |           | ......read_directory_recursive:ci/util/\n| region_leave |  0.000087 | ......read_directory_recursive:ci/util/\n| region_leave |  0.000250 | ....read_directory_recursive:ci/\n| region_enter |           | ....read_directory_recursive:compat/\n| region_enter |           | \n......read_directory_recursive:compat/nedmalloc/\n| region_leave |  0.000128 | \n......read_directory_recursive:compat/nedmalloc/\n| region_enter |           | ......read_directory_recursive:compat/poll/\n| region_leave |  0.000124 | ......read_directory_recursive:compat/poll/\n| region_enter |           | ......read_directory_recursive:compat/regex/\n| region_leave |  0.000129 | ......read_directory_recursive:compat/regex/\n| region_leave |  0.017700 | ....read_directory_recursive:compat/\n...\n| region_leave |  0.053924 | ..read_directory_recursive:\n| region_leave |  0.054127 | status_untracked\n\nI include the read_directory_recursive() commit as an example of\nhow the API works.  I consider those particular calls as something\na developer would add while studying a problem, but not keep long term.\nThe calls in status_untracked() are probably keepers, since it would\ncompliment the existing warning about untracked file detection taking\ntoo long.\n\nThe trace2_data_intmax() and trace2_data_string() routines work with\nthis nesting (are similarly \"..\" indented).  I don't have an example\nin the V1 patch, but you might want to print the number of files touched\nat each step in the recursion, for example.\n\n> \n>> + */\n>> +#define TR2_MAX_REGION_NESTING (100)\n>> +#define TR2_INDENT (2)\n>> +#define TR2_INDENT_LENGTH(ctx) (((ctx)->nr_open_regions - 1) * TR2_INDENT)\n> \n> In the structured part of the logging the indentation would not be\n> needed and we'd rather want to store the nesting level as an int,\n> this is solely for printing locally I'd assume.\n> \n>> +#define TR2_MAX_THREAD_NAME (24)\n> \n> This is the max length for a thread name including all the prefixes?\n\nA thread name does not have a SID-related prefix.  It is just a number\nand a supplied label, such as the name of the thread-proc function.\nI clip it for column alignment purposes.  For example, the 6th commit\nin the patch series shows it being used in preload_index().  Again, this\nis the perf view.\n\n...\n| main                     | region_enter |           | preload_index\n| th01:preload_thread      | thread_start |           |\n| th01:preload_thread      | printf       |           | preload {offset \n      0}{count     567}\n| th02:preload_thread      | thread_start |           |\n| th02:preload_thread      | printf       |           | preload {offset \n    567}{count     567}\n| th03:preload_thread      | thread_start |           |\n| th03:preload_thread      | printf       |           | preload {offset \n   1134}{count     567}\n| th04:preload_thread      | thread_start |           |\n| th04:preload_thread      | printf       |           | preload {offset \n   1701}{count     567}\n| th05:preload_thread      | thread_start |           |\n| th05:preload_thread      | printf       |           | preload {offset \n   2268}{count     567}\n| th06:preload_thread      | thread_start |           |\n| th06:preload_thread      | printf       |           | preload {offset \n   2835}{count     562}\n| th03:preload_thread      | thread_exit  |  0.034892 |\n| th06:preload_thread      | thread_exit  |  0.038585 |\n| th04:preload_thread      | thread_exit  |  0.042468 |\n| th02:preload_thread      | thread_exit  |  0.042601 |\n| th01:preload_thread      | thread_exit  |  0.046107 |\n| th05:preload_thread      | thread_exit  |  0.047696 |\n| main                     | region_leave |  0.048093 | preload_index\n...\n\nThis shows interleaved racy messages from each of the 6 threads started\nin preload_index().  The thread_exit messages give the elapsed time of\neach thread.\n\nThe thread_start/thread_exit events implicitly define a region (as\ndescribed earlier) so that region_enter, region_leave, and data events\nwill be \"..\" indented relative to the thread.  One could image building\na threaded version of status_untracked where read_directory_recursive\nis spread across different threads.  The perf tracing here would let\nus see timings for each thread.  Granted, the events are interleaved\nand therefore racy, but you could post-process that thread-by-thread.\n\n> \n> \n>> +static void tr2tls_unset_self(void)\n>> +{\n>> +       struct tr2tls_thread_ctx * ctx;\n>> +\n>> +       ctx = tr2tls_get_self();\n>> +\n>> +       pthread_setspecific(tr2tls_key, NULL);\n> \n> Would we also need to free tr2tls_key ?\n\nI free the ctx for each thread (including the main thread) after\ndisassociating it from the TLS slot when the thread is ending.\n\nBut the TLS slot (tr2tls_key) needs to remain until all the atexit\nhandler runs.  See tr2tls_release().\n\n> \n> \n>> +/*****************************************************************\n>> + * TODO remove this section header\n>> + *****************************************************************/\n>> +\n>> +static void tr2io_write_line(struct trace_key *key, struct strbuf *buf_line)\n>> +{\n>> +       strbuf_complete_line(buf_line); /* ensure final NL on buffer */\n>> +\n>> +       // TODO we don't really want short-writes to try again when\n>> +       // TODO we are in append mode...\n> \n> A different kind of TODO in a // comment?\n> \n\nSorry, didn't want to forget to actually do it.   :-)\n\nthanks for the review,\nJeff\n"},{"id":"357440","messageId":"eb77f46b-8d04-a1c7-ae31-7ea5e2456cfd@jeffhostetler.com","threadId":"49264","inReplyTo":"xmqqzhww6gl8.fsf@gitster-ct.c.googlers.com","subject":"Re: [PATCH 1/8] trace2: create new combined trace facility","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2018-09-05T15:51:40Z","receivedAt":"2018-09-05T15:51:43Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 9/4/2018 6:30 PM, Junio C Hamano wrote:\n> Stefan Beller <sbeller@google.com> writes:\n> \n>>> The API defines both fixed-field and printf-style functions.\n>>>\n>>> The trace2 performance tracing includes thread-specific function\n>>> nesting and timings.\n>>\n>> So this only adds the new API, and we need to merge the TRACE\n>> into the TRACE2 later?\n> \n> If this is a rhetorical question implying that it would be best if\n> the existing trace() were rewritten to be built on top of trace2()\n> while building this series, especially before adding new callsites\n> that directly use trace2(), I may share that feeling.  I haven't\n> studied this new round deeply enough to see how realistic it would\n> be, though.\n> \n> \n\nI wanted to come up with a unified API that we liked and was\nsufficient to handle the default-key, performance-key,\nthe new event-key (currently supporting JSON output), and any\nother formats/variants that we want (protobufs, syslog, etc).\n\nAnd hopefully get some agreement on it and see what else we want\nfrom it.\n\nAnd then look at converting the trace_printf() and trace_performance()\ncalls to trace2.  Clearly, I could just replace the existing printf\nstyle calls to trace2_printf's, but I thought it would be better to\nlook at them and promote them to higher-level functions.  For example,\nthe trace_argv_printf() calls are generally used to dump the command\nline arguments for the current process or spawned child processes.\nI have trace2_start() and trace2_child_start() that captures the\nargv and additional information about it.  (The \"why\" if you will.)\nSo the trace_argv_* forms can go away.\n\nLikewise, all of the trace_performance() and trace_performance_since()\ncan be converted to trace2_region_enter/_leave calls.  And those forms\ncan be removed from trace.[ch].\n\nThe net-net is that trace.[ch] shrinks in a short sequence of commits\non top of my initial trace2 commit in a reroll of this patch series.\n(and replacing some of the demonstration commits in V1)\n\nThen I'll address the trace_printf_key() forms, since they write\nto alternate stream.\n\nThen I can delete trace.[ch].  And we can consider renaming\ntrace2_* functions and/or GIT_TR2_* env vars if we want.\n\nI wanted to avoid rewriting trace.[ch] just to delete them later\nin the same patch series.\n\nJeff\n"},{"id":"357535","messageId":"20180906151309.66712-1-dstolee@microsoft.com","threadId":"49264","inReplyTo":"2ba9d81a-5578-a81c-a7d9-179864cb4277@gmail.com","subject":"[RFC PATCH 0/6] Use trace2 in commit-reach","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2018-09-06T15:13:03Z","receivedAt":"2018-09-06T15:13:23Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"As promised, here is the direction I took when applying the trace2\nfeature to the walking code in commit-reach.c. Hence, this depends\non Jeff's trace2 patches and ds/reachable.\n\nThere are multiple benefits to the approach I take here:\n\n1. If a user has performance problems, we can rerun the command\n   with tracing on and get the region enter/leave notifications\n   and the extra data like \"num_walked\".\n\n2. While I was testing this series against real-world examples,\n   I found a number I didn't expect. The numbers for\n   can_all_from_reach_with_flags were much higher than I expected.\n   Turns out the heuristic I wrote was not working correctly. With\n   the trace2 library, I was able to add a \"run_and_check_trace2\"\n   function in test-lib.sh so I could make the number of walked\n   commits be a condition we check in the test. Then, the benefit\n   we expect is demonstrated by the test suite when I fix the\n   bug.\n\nThanks,\n-Stolee\n\nP.S. I'm sending this RFC from gmail because I'm having SMTP issues\nwith my work email.\n\nDerrick Stolee (6):\n  commit-reach: add trace2 telemetry and walk count\n  comit-reach: use trace2 for commit_contains_tag_algo\n  commit-reach: use trace2 in can_all_from_reach\n  test-tool: start trace2 environment\n  test-lib: add run_and_check_trace2\n  commit-reach: fix first-parent heuristic\n\n commit-reach.c        | 32 ++++++++++++++++++++++++++++++--\n t/helper/test-tool.c  |  3 +++\n t/t6600-test-reach.sh |  6 ++++++\n t/test-lib.sh         | 14 ++++++++++++++\n 4 files changed, 53 insertions(+), 2 deletions(-)\n\n-- \n2.19.0-rc2\n\n"},{"id":"357536","messageId":"20180906151309.66712-2-dstolee@microsoft.com","threadId":"49264","inReplyTo":"20180906151309.66712-1-dstolee@microsoft.com","subject":"[RFC PATCH 1/6] commit-reach: add trace2 telemetry and walk count","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2018-09-06T15:13:04Z","receivedAt":"2018-09-06T15:13:32Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"paint_down_to_common() is used by many Git commands, and sometimes\nmultiple times in a single call. It is important to measure\nperformance of this method, but the actual time it takes can vary\ndue to interactions outside Git's control (file system, CPU\ncontention, etc.). Instead, count how many times we execute the\nwhile loop, which is consistent between runs.\n\nSigned-off-by: Derrick Stolee <dstolee@microsoft.com>\n---\n commit-reach.c | 8 ++++++++\n 1 file changed, 8 insertions(+)\n\ndiff --git a/commit-reach.c b/commit-reach.c\nindex 86715c103c..ee374dce20 100644\n--- a/commit-reach.c\n+++ b/commit-reach.c\n@@ -38,6 +38,9 @@ static struct commit_list *paint_down_to_common(struct commit *one, int n,\n \tstruct commit_list *result = NULL;\n \tint i;\n \tuint32_t last_gen = GENERATION_NUMBER_INFINITY;\n+\tuint32_t num_walked = 0;\n+\n+\ttrace2_region_enter(\"paint_down_to_common\");\n \n \tone->object.flags |= PARENT1;\n \tif (!n) {\n@@ -55,6 +58,7 @@ static struct commit_list *paint_down_to_common(struct commit *one, int n,\n \t\tstruct commit *commit = prio_queue_get(&queue);\n \t\tstruct commit_list *parents;\n \t\tint flags;\n+\t\tnum_walked++;\n \n \t\tif (commit->generation > last_gen)\n \t\t\tBUG(\"bad generation skip %8x > %8x at %s\",\n@@ -88,6 +92,10 @@ static struct commit_list *paint_down_to_common(struct commit *one, int n,\n \t}\n \n \tclear_prio_queue(&queue);\n+\n+\ttrace2_data_intmax(\"paint_down_to_common\", \"num_walked\", num_walked);\n+\ttrace2_region_leave(\"paint_down_to_common\");\n+\n \treturn result;\n }\n \n-- \n2.19.0.rc2\n\n"},{"id":"357537","messageId":"20180906151309.66712-4-dstolee@microsoft.com","threadId":"49264","inReplyTo":"20180906151309.66712-1-dstolee@microsoft.com","subject":"[RFC PATCH 3/6] commit-reach: use trace2 in can_all_from_reach","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2018-09-06T15:13:06Z","receivedAt":"2018-09-06T15:13:49Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"Signed-off-by: Derrick Stolee <dstolee@microsoft.com>\n---\n commit-reach.c | 8 ++++++++\n 1 file changed, 8 insertions(+)\n\ndiff --git a/commit-reach.c b/commit-reach.c\nindex 0fc3b1ac18..0a75644653 100644\n--- a/commit-reach.c\n+++ b/commit-reach.c\n@@ -563,6 +563,7 @@ int can_all_from_reach_with_flag(struct object_array *from,\n \tstruct commit **list = NULL;\n \tint i;\n \tint result = 1;\n+\tuint32_t num_walked = 0;\n \n \tALLOC_ARRAY(list, from->nr);\n \tfor (i = 0; i < from->nr; i++) {\n@@ -573,6 +574,8 @@ int can_all_from_reach_with_flag(struct object_array *from,\n \t\t\treturn 0;\n \t}\n \n+\ttrace2_region_enter(\"can_all_from_reach_with_flag\");\n+\n \tQSORT(list, from->nr, compare_commits_by_gen);\n \n \tfor (i = 0; i < from->nr; i++) {\n@@ -590,6 +593,8 @@ int can_all_from_reach_with_flag(struct object_array *from,\n \t\t\t\tcontinue;\n \t\t\t}\n \n+\t\t\tnum_walked++;\n+\n \t\t\tfor (parent = stack->item->parents; parent; parent = parent->next) {\n \t\t\t\tif (parent->item->object.flags & (with_flag | RESULT))\n \t\t\t\t\tstack->item->object.flags |= RESULT;\n@@ -622,6 +627,9 @@ int can_all_from_reach_with_flag(struct object_array *from,\n \t\tclear_commit_marks(list[i], RESULT);\n \t\tclear_commit_marks(list[i], assign_flag);\n \t}\n+\n+\ttrace2_data_intmax(\"can_all_from_reach_with_flag\", \"num_walked\", num_walked);\n+\ttrace2_region_leave(\"can_all_from_reach_with_flag\");\n \treturn result;\n }\n \n-- \n2.19.0.rc2\n\n"},{"id":"357538","messageId":"20180906151309.66712-3-dstolee@microsoft.com","threadId":"49264","inReplyTo":"20180906151309.66712-1-dstolee@microsoft.com","subject":"[RFC PATCH 2/6] comit-reach: use trace2 for commit_contains_tag_algo","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2018-09-06T15:13:05Z","receivedAt":"2018-09-06T15:13:56Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"Signed-off-by: Derrick Stolee <dstolee@microsoft.com>\n---\n commit-reach.c | 12 +++++++++++-\n 1 file changed, 11 insertions(+), 1 deletion(-)\n\ndiff --git a/commit-reach.c b/commit-reach.c\nindex ee374dce20..0fc3b1ac18 100644\n--- a/commit-reach.c\n+++ b/commit-reach.c\n@@ -481,6 +481,7 @@ static enum contains_result contains_tag_algo(struct commit *candidate,\n \tenum contains_result result;\n \tuint32_t cutoff = GENERATION_NUMBER_INFINITY;\n \tconst struct commit_list *p;\n+\tuint32_t num_walked = 0;\n \n \tfor (p = want; p; p = p->next) {\n \t\tstruct commit *c = p->item;\n@@ -493,12 +494,15 @@ static enum contains_result contains_tag_algo(struct commit *candidate,\n \tif (result != CONTAINS_UNKNOWN)\n \t\treturn result;\n \n+\ttrace2_region_enter(\"contains_tag_algo\");\n \tpush_to_contains_stack(candidate, &contains_stack);\n \twhile (contains_stack.nr) {\n \t\tstruct contains_stack_entry *entry = &contains_stack.contains_stack[contains_stack.nr - 1];\n \t\tstruct commit *commit = entry->commit;\n \t\tstruct commit_list *parents = entry->parents;\n \n+\t\tnum_walked++;\n+\n \t\tif (!parents) {\n \t\t\t*contains_cache_at(cache, commit) = CONTAINS_NO;\n \t\t\tcontains_stack.nr--;\n@@ -521,7 +525,13 @@ static enum contains_result contains_tag_algo(struct commit *candidate,\n \t\t}\n \t}\n \tfree(contains_stack.contains_stack);\n-\treturn contains_test(candidate, want, cache, cutoff);\n+\n+\tresult = contains_test(candidate, want, cache, cutoff);\n+\n+\ttrace2_data_intmax(\"contains_tag_algo\", \"num_walked\", num_walked);\n+\ttrace2_region_leave(\"contains_tag_algo\");\n+\n+\treturn result;\n }\n \n int commit_contains(struct ref_filter *filter, struct commit *commit,\n-- \n2.19.0.rc2\n\n"},{"id":"357539","messageId":"20180906151309.66712-5-dstolee@microsoft.com","threadId":"49264","inReplyTo":"20180906151309.66712-1-dstolee@microsoft.com","subject":"[RFC PATCH 4/6] test-tool: start trace2 environment","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2018-09-06T15:13:07Z","receivedAt":"2018-09-06T15:13:59Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"Signed-off-by: Derrick Stolee <dstolee@microsoft.com>\n---\n t/helper/test-tool.c | 3 +++\n 1 file changed, 3 insertions(+)\n\ndiff --git a/t/helper/test-tool.c b/t/helper/test-tool.c\nindex 7566b0786a..f70d5d74f8 100644\n--- a/t/helper/test-tool.c\n+++ b/t/helper/test-tool.c\n@@ -1,5 +1,6 @@\n #include \"git-compat-util.h\"\n #include \"test-tool.h\"\n+#include \"trace2.h\"\n \n struct test_cmd {\n \tconst char *name;\n@@ -55,6 +56,8 @@ int cmd_main(int argc, const char **argv)\n \tif (argc < 2)\n \t\tdie(\"I need a test name!\");\n \n+\ttrace2_start(argv);\n+\n \tfor (i = 0; i < ARRAY_SIZE(cmds); i++) {\n \t\tif (!strcmp(cmds[i].name, argv[1])) {\n \t\t\targv++;\n-- \n2.19.0.rc2\n\n"},{"id":"357540","messageId":"20180906151309.66712-6-dstolee@microsoft.com","threadId":"49264","inReplyTo":"20180906151309.66712-1-dstolee@microsoft.com","subject":"[RFC PATCH 5/6] test-lib: add run_and_check_trace2","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2018-09-06T15:13:08Z","receivedAt":"2018-09-06T15:14:10Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"The trace2 facility allows tracing category-key-value triples that\nwe can use to communicate runtime information to a side channel.\nOne use is to track the number of commits that are walked by a\ngraph algorithm.\n\nAdd run_and_check_trace2 test function to run a given command with\nGIT_TR2_PERFORMANCE running. Then, check the output for the\nexpected category-key-value triple.\n\nUse this function in t6600-test-reach.sh to verify can_all_from_reach\nonly visits 11 commits in the example.\n\nSigned-off-by: Derrick Stolee <dstolee@microsoft.com>\n---\n t/t6600-test-reach.sh |  6 ++++++\n t/test-lib.sh         | 14 ++++++++++++++\n 2 files changed, 20 insertions(+)\n\ndiff --git a/t/t6600-test-reach.sh b/t/t6600-test-reach.sh\nindex d139a00d1d..98ad25bb45 100755\n--- a/t/t6600-test-reach.sh\n+++ b/t/t6600-test-reach.sh\n@@ -183,6 +183,12 @@ test_expect_success 'can_all_from_reach:hit' '\n \ttest_three_modes can_all_from_reach\n '\n \n+test_expect_success 'can_all_from_reach:perf' '\n+\tcp commit-graph-full .git/objects/info/commit-graph &&\n+\trun_and_check_trace2 can_all_from_reach_with_flag num_walked 40 input \\\n+\t\t\"test-tool reach can_all_from_reach\"\n+'\n+\n test_expect_success 'can_all_from_reach:miss' '\n \tcat >input <<-\\EOF &&\n \tX:commit-2-10\ndiff --git a/t/test-lib.sh b/t/test-lib.sh\nindex 8bb0f4348e..9b9f68f324 100644\n--- a/t/test-lib.sh\n+++ b/t/test-lib.sh\n@@ -1231,3 +1231,17 @@ test_lazy_prereq CURL '\n test_lazy_prereq SHA1 '\n \ttest $(git hash-object /dev/null) = e69de29bb2d1d6434b8b29ae775ad8c2e48c5391\n '\n+\n+# Useage: run_and_check_trace2 <category> <key> <value> <file> <command>\n+# Run \"command <file\" with GIT_TR2_PERFORMANCE logging to a file and\n+# check that file for a data output matching category.key = value.\n+run_and_check_trace2 () {\n+\tCATEGORY=$1\n+\tKEY=$2\n+\tVALUE=$3\n+\tINPUT=$4\n+\tCOMMAND=$5\n+\t# GIT_TR2_PERFORMANCE=\"$(pwd)/perf-log.txt\"\n+\tGIT_TR2_PERFORMANCE=\"$(pwd)/perf-log.txt\" $COMMAND <$INPUT &&\n+\tcat perf-log.txt | grep \"category:$CATEGORY key:$KEY value:$VALUE\"\n+}\n-- \n2.19.0.rc2\n\n"},{"id":"357541","messageId":"20180906151309.66712-7-dstolee@microsoft.com","threadId":"49264","inReplyTo":"20180906151309.66712-1-dstolee@microsoft.com","subject":"[RFC PATCH 6/6] commit-reach: fix first-parent heuristic","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2018-09-06T15:13:09Z","receivedAt":"2018-09-06T15:14:23Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"The algorithm in can_all_from_reach_with_flags() performs a depth-\nfirst-search, terminated by generation number, intending to use\na hueristic that \"important\" commits are found in the first-parent\nhistory. This heuristic is valuable in scenarios like fetch\nnegotiation.\n\nHowever, there is a problem! After the search finds a target commit,\nit should pop all commits off the stack and mark them as \"can reach\".\nThis logic is incorrect, so the algorithm instead walks all reachable\ncommits above the generation-number cutoff.\n\nThe existing algorithm is still an improvement over the previous\nalgorithm, as the worst-case complexity went from quadratic to linear.\nThe performance measurement at the time was good, but not dramatic.\n\nBy fixing this heuristic, we can see in t6600-test-reach.sh that we\nreduce the number of walked commits. This test will prevent a future\nperformance regression.\n\nWe can also re-run the performance tests from commit 4fbcca4e\n\"commit-reach: make can_all_from_reach... linear\".\n\nPerformance was measured on the Linux repository using\n'test-tool reach can_all_from_reach'. The input included rows seeded by\ntag values. The \"small\" case included X-rows as v4.[0-9]* and Y-rows as\nv3.[0-9]*. This mimics a (very large) fetch that says \"I have all major\nv3 releases and want all major v4 releases.\" The \"large\" case included\nX-rows as \"v4.*\" and Y-rows as \"v3.*\". This adds all release-candidate\ntags to the set, which does not greatly increase the number of objects\nthat are considered, but does increase the number of 'from' commits,\ndemonstrating the quadratic nature of the previous code.\n\nSmall Case:\n\n4fbcca4e~1: 0.85 s\n  4fbcca4e: 0.26 s (num_walked: 1,011,035)\n      HEAD: 0.14 s (num_walked:     8,601)\n\nLarge Case:\n\n4fbcca4e~1: 24.0 s\n  4fbcca4e:  0.12 s (num_walked:  503,925)\n      HEAD:  0.06 s (num_walked:  217,243)\n\nSigned-off-by: Derrick Stolee <dstolee@microsoft.com>\n---\n commit-reach.c        | 4 +++-\n t/t6600-test-reach.sh | 2 +-\n 2 files changed, 4 insertions(+), 2 deletions(-)\n\ndiff --git a/commit-reach.c b/commit-reach.c\nindex 0a75644653..bd009260b0 100644\n--- a/commit-reach.c\n+++ b/commit-reach.c\n@@ -588,8 +588,10 @@ int can_all_from_reach_with_flag(struct object_array *from,\n \t\twhile (stack) {\n \t\t\tstruct commit_list *parent;\n \n-\t\t\tif (stack->item->object.flags & with_flag) {\n+\t\t\tif (stack->item->object.flags & (with_flag | RESULT)) {\n \t\t\t\tpop_commit(&stack);\n+\t\t\t\tif (stack)\n+\t\t\t\t\tstack->item->object.flags |= RESULT;\n \t\t\t\tcontinue;\n \t\t\t}\n \ndiff --git a/t/t6600-test-reach.sh b/t/t6600-test-reach.sh\nindex 98ad25bb45..5e231a5955 100755\n--- a/t/t6600-test-reach.sh\n+++ b/t/t6600-test-reach.sh\n@@ -185,7 +185,7 @@ test_expect_success 'can_all_from_reach:hit' '\n \n test_expect_success 'can_all_from_reach:perf' '\n \tcp commit-graph-full .git/objects/info/commit-graph &&\n-\trun_and_check_trace2 can_all_from_reach_with_flag num_walked 40 input \\\n+\trun_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input \\\n \t\t\"test-tool reach can_all_from_reach\"\n '\n \n-- \n2.19.0.rc2\n\n"},{"id":"360127","messageId":"20181011015007.GA40329@aiede.svl.corp.google.com","threadId":"49264","inReplyTo":"20180906151309.66712-7-dstolee@microsoft.com","subject":"Re: [RFC PATCH 6/6] commit-reach: fix first-parent heuristic","fromName":"Jonathan Nieder","fromEmail":"jrnieder@gmail.com","sentAt":"2018-10-11T01:50:07Z","receivedAt":"2018-10-11T01:50:13Z","isPatch":true,"sender":{"key":"jrnieder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/281595?v=4"},"body":"Hi,\n\nDerrick Stolee wrote:\n\n>  commit-reach.c        | 4 +++-\n>  t/t6600-test-reach.sh | 2 +-\n>  2 files changed, 4 insertions(+), 2 deletions(-)\n\nI like this testing technique, and the test passes for me.\n\nExcept: if I put\n\n\tCC = cc -m32\n\tNO_OPENSSL = YesPlease\n\tNO_CURL = YesPlease\n\nin config.mak (the first line to force 32-bit pointers, the others\nto avoid some dependencies on libs that I don't have 32-bit versions\nof), then the test fails for me:\n\n $ ./t6600-test-reach.sh -v -x -i\n [...]\n expecting success:\n         cp commit-graph-full .git/objects/info/commit-graph &&\n         run_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input \\\n                 \"test-tool reach can_all_from_reach\"\n\n ++ cp commit-graph-full .git/objects/info/commit-graph\n ++ run_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input 'test-tool reach can_all_from_r\n each'\n ++ CATEGORY=can_all_from_reach_with_flag\n ++ KEY=num_walked\n ++ VALUE=19\n ++ INPUT=input\n ++ COMMAND='test-tool reach can_all_from_reach'\n +++ pwd\n ++ GIT_TR2_PERFORMANCE='/usr/local/google/home/jrn/src/git/t/trash directory.t6600-test-reach/perf-log.t\n xt'\n ++ test-tool reach can_all_from_reach\n can_all_from_reach(X,Y):1\n ++ cat perf-log.txt\n ++ grep 'category:can_all_from_reach_with_flag key:num_walked value:19'\n error: last command exited with $?=1\n not ok 11 - can_all_from_reach:perf\n #\n #               cp commit-graph-full .git/objects/info/commit-graph &&\n #               run_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input \\\n #                       \"test-tool reach can_all_from_reach\"\n #\n\nWhen I cat perf-log.txt, I see\n\n  ..category:can_all_from_reach_with_flag key:num_walked value:20\n\ninstead of the expected 19.\n\nKnown issue?\n\nThanks,\nJonathan\n"},{"id":"360171","messageId":"58d2959a-ffb1-13ba-26f1-84fc2953fcc3@gmail.com","threadId":"49264","inReplyTo":"20181011015007.GA40329@aiede.svl.corp.google.com","subject":"Re: [RFC PATCH 6/6] commit-reach: fix first-parent heuristic","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2018-10-11T11:00:29Z","receivedAt":"2018-10-11T11:00:34Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"On 10/10/2018 9:50 PM, Jonathan Nieder wrote:\n> Hi,\n>\n> Derrick Stolee wrote:\n>\n>>   commit-reach.c        | 4 +++-\n>>   t/t6600-test-reach.sh | 2 +-\n>>   2 files changed, 4 insertions(+), 2 deletions(-)\n> I like this testing technique, and the test passes for me.\n>\n> Except: if I put\n>\n> \tCC = cc -m32\n> \tNO_OPENSSL = YesPlease\n> \tNO_CURL = YesPlease\n>\n> in config.mak (the first line to force 32-bit pointers, the others\n> to avoid some dependencies on libs that I don't have 32-bit versions\n> of), then the test fails for me:\n>\n>   $ ./t6600-test-reach.sh -v -x -i\n>   [...]\n>   expecting success:\n>           cp commit-graph-full .git/objects/info/commit-graph &&\n>           run_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input \\\n>                   \"test-tool reach can_all_from_reach\"\n>\n>   ++ cp commit-graph-full .git/objects/info/commit-graph\n>   ++ run_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input 'test-tool reach can_all_from_r\n>   each'\n>   ++ CATEGORY=can_all_from_reach_with_flag\n>   ++ KEY=num_walked\n>   ++ VALUE=19\n>   ++ INPUT=input\n>   ++ COMMAND='test-tool reach can_all_from_reach'\n>   +++ pwd\n>   ++ GIT_TR2_PERFORMANCE='/usr/local/google/home/jrn/src/git/t/trash directory.t6600-test-reach/perf-log.t\n>   xt'\n>   ++ test-tool reach can_all_from_reach\n>   can_all_from_reach(X,Y):1\n>   ++ cat perf-log.txt\n>   ++ grep 'category:can_all_from_reach_with_flag key:num_walked value:19'\n>   error: last command exited with $?=1\n>   not ok 11 - can_all_from_reach:perf\n>   #\n>   #               cp commit-graph-full .git/objects/info/commit-graph &&\n>   #               run_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input \\\n>   #                       \"test-tool reach can_all_from_reach\"\n>   #\n>\n> When I cat perf-log.txt, I see\n>\n>    ..category:can_all_from_reach_with_flag key:num_walked value:20\n>\n> instead of the expected 19.\nIt is possible this is related to the sort-order problem reported and \nfixed by Rene [1]. I'll look into it in any case.\n\n[1] \nhttps://public-inbox.org/git/dca35e44-a763-bcf0-f457-b8dab53815cf@web.de/\n"},{"id":"366697","messageId":"20190115010528.GJ162110@google.com","threadId":"49264","inReplyTo":"pull.29.git.gitgitgadget@gmail.com","subject":"Re: [PATCH 0/8] WIP: trace2: a new trace facility","fromName":"Jonathan Nieder","fromEmail":"jrnieder@gmail.com","sentAt":"2019-01-15T01:05:28Z","receivedAt":"2019-01-15T01:05:33Z","isPatch":true,"sender":{"key":"jrnieder@gmail.com","avatar":"https://avatars.githubusercontent.com/u/281595?v=4"},"body":"Hi,\n\nJeff Hostetler wrote:\n\n> This patch series contains a new trace2 facility that hopefully addresses\n> the recent trace- and structured-logging-related discussions. The intent is\n> to eventually replace the existing trace_ routines (or to route them to the\n> new trace2_ routines) as time permits.\n\nI've been running with these patches since last October.  A few\nthoughts:\n\nI like the API.\n\nThe logs are a bit noisy and especially wide.  For my use, the\nfunction name is not too important since we can get that from the file\nand line number.  Should we have a way to omit some fields, or is that\nfor post-processing?\n\nWe don't find the JSON easy to parse and would prefer a binary format.\n\nWhen I apply the patches, Git complains about whitespace problems\n(trailing whitespace, etc).\n\nAside from that kind of easily correctible issue (trailing\nwhitespace), I'd be in favor of taking these patches pretty much as-is\nand making improvements in tree.  Any objections to that, or do you\nhave other thoughts on where this should go?\n\nIf that sounds reasonable to you, I can send a clean version of these\nbased against current \"master\".  If I understand correctly, then\n\n https://github.com/jeffhostetler/git\n\nbranch\n\n gvfs-trace2-v4\n\ncontains some improvements, so as a next step I'd try to extract those\nas incremental patches on top.  What do you think?\n\nThanks,\nJonathan\n"},{"id":"366724","messageId":"5df8db4b-c772-c202-5f58-58e9498f6bc0@jeffhostetler.com","threadId":"49264","inReplyTo":"20190115010528.GJ162110@google.com","subject":"Re: [PATCH 0/8] WIP: trace2: a new trace facility","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2019-01-15T17:03:55Z","receivedAt":"2019-01-15T17:12:29Z","isPatch":true,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 1/14/2019 8:05 PM, Jonathan Nieder wrote:\n> Hi,\n> \n> Jeff Hostetler wrote:\n> \n>> This patch series contains a new trace2 facility that hopefully addresses\n>> the recent trace- and structured-logging-related discussions. The intent is\n>> to eventually replace the existing trace_ routines (or to route them to the\n>> new trace2_ routines) as time permits.\n> \n> I've been running with these patches since last October.  A few\n> thoughts:\n> \n> I like the API.\n\nGreat, thanks.  Hopefully you're getting some good/actionable data from\nit.\n\n\n> The logs are a bit noisy and especially wide.  For my use, the\n> function name is not too important since we can get that from the file\n> and line number.  Should we have a way to omit some fields, or is that\n> for post-processing?\n\nYes, the events are a little wide and noisy, at least in this draft.\n\nPart of this is to flesh out the trace2 API (which should be relatively\nfixed) and make sure we have enough event types to emit useful\ninformation.  This is independent of some of the detail events (like\nregion/data events within status or index reading/writing). Some of\nthose detail events might be kept if they're useful or temporary\ndemonstration events or events you could include in a private build for\na limited period of time.  So some of the noise might be those\ndemonstration events (stuff that you'd want for testing in a perf view,\nbut not need archived, for example).\n\nAlso, for the events that have a \"category\" field, I'd eventually\nlike to have a filter setting to include/omit them.  This is something\nlike the GIT_TRACE_<name> feature we currently have, but limited to\nalways writing to the same file.  I had this in an earlier version,\nbut haven't brought it over yet.\n\nAnd yes, I have a post-processing step that filters fields and\ngenerates a summary record for each process instance.  My previous\ndraft tried to do that summary inside the git.exe process and it was\nsuggested that we move that out, so this version emits the raw data\nas it occurs and I get the summary after the fact.  This has turned\nout nicely, even if the Trace2 stream is a little noisy.\n\nThere are some fields that I'd like to omit from my JSON stream that\nI'm not using in my summary, such as the filename and line number.\nThese got carried along since the PERF view needed them.  I think they\nmake sense in the PERF view, but not so much in the EVENT view.\nI'm filtering them out in my post-processing, but I think we could\njust omit them.\n\n\n> We don't find the JSON easy to parse and would prefer a binary format.\n\nI'm going to have to push back a little on this one.  JSON is easy to\nprocess in PERL, C#, various databases, and etc.  Processing a non-text\nformat in bash is just asking for pain and suffering.\n\nCan you elaborate on the problems you're having with JSON?\n\nWhen you say \"binary\" what kind of binary do you mean?  Is this BSON?\nOr are you suggesting protocol buffers?  If the latter, is there a C\nbinding for that? (Every example I've seen talks about C++.)\n\nIn my gvfs-trace2-v4 branch, I've refactored the code and now have\na vtable-like mechanism that allows multiple Trace2 \"targets\" to be\ndefined.  See trace2/tr2_tgt_perf.c vs trace2/tr2_tgt_events.c.  The\nformer generates the GIT_TR2_PERF view and the latter generates the\nJSON event view.\n\nYou could add a self-contained target vtable that generates a binary\nview if you wanted.  (Just let it key off of a different GIT_TR2_\nenvironment variable.)\n\n\n> When I apply the patches, Git complains about whitespace problems\n> (trailing whitespace, etc).\n> \n> Aside from that kind of easily correctible issue (trailing\n> whitespace), I'd be in favor of taking these patches pretty much as-is\n> and making improvements in tree.  Any objections to that, or do you\n> have other thoughts on where this should go?\n> \n> If that sounds reasonable to you, I can send a clean version of these\n> based against current \"master\".  If I understand correctly, then\n> \n>   https://github.com/jeffhostetler/git\n> \n> branch\n> \n>   gvfs-trace2-v4\n> \n> contains some improvements, so as a next step I'd try to extract those\n> as incremental patches on top.  What do you think?\n> \n> Thanks,\n> Jonathan\n\nThe gvfs-trace2-v4 version has lots of improvements over the version\nI last posted on the mailing list.  We should go with it.\n\nI'm not surprised that there are merge conflicts, since mine is based\nupon the recent GVFS release and has some gvfs-specific commits in it.\n\nLet me rebase that branch onto the upstream/master and clean up the\nmess and send out another patch set.\n\nHopefully, I can get that out tomorrow.\n\nJeff\n"}]}