[PATCH 0/8] WIP: trace2: a new trace facility

[PATCH 0/8] WIP: trace2: a new trace facility

[Jeff Hostetler via GitGitGadget]

This patch series contains a new trace2 facility that hopefully addresses
the recent trace- and structured-logging-related discussions. The intent is
to eventually replace the existing trace_ routines (or to route them to the
new trace2_ routines) as time permits.

This draft adds new trace2_ calls and leaves most of the original trace_
calls in place. Subsequent drafts will address this.

This version should be considered a replacement for my earlier structured
logging patch series [1].

It addresses Jonathan Nieder's, Ben Peart's, Peff's, and Junio's comments
[2,3,4,5] about merging the existing tracing routines, ease of use,
progressive logging rather than logging at the end of the program, hiding
all JSON details inside the trace2_ routines, and leaving an opening for
additional formats (protobuf or whatever).

It also adds a nested performance tracing feature similar to Duy's
suggestion in [6]. This version adds per-thread nesting and marks each event
with a thread name.

[1] 
https://public-inbox.org/git/20180713165621.52017-1-git@jeffhostetler.com/
[2] 
https://public-inbox.org/git/20180821044724.GA219616@aiede.svl.corp.google.com/
[3] 
https://public-inbox.org/git/13302a8c-a114-c3a7-65df-55f47f902126@gmail.com/
[4] 
https://public-inbox.org/git/20180814195456.GE28452@sigill.intra.peff.net/
[5] https://public-inbox.org/git/xmqqeff0zn53.fsf@gitster-ct.c.googlers.com/
[6] https://public-inbox.org/git/20180818144128.19361-2-pclouds@gmail.com/

Cc: gitster@pobox.comCc: peff@peff.netCc: peartben@gmail.comCc: 
jrnieder@gmail.comCc: pclouds@gmail.com

Jeff Hostetler (8):
  trace2: create new combined trace facility
  trace2: add trace2 to main
  trace2: demonstrate trace2 regions in wt-status
  trace2: demonstrate trace2 child process classification
  trace2: demonstrate instrumenting do_read_index
  trace2: demonstrate instrumenting threaded preload_index
  trace2: demonstrate setting sub-command parameter in checkout
  trace2: demonstrate use of regions in read_directory_recursive

 Makefile           |    1 +
 builtin/checkout.c |    5 +
 cache.h            |    1 +
 compat/mingw.h     |    3 +-
 dir.c              |    3 +
 editor.c           |    1 +
 git-compat-util.h  |    7 +
 git.c              |    9 +-
 pager.c            |    1 +
 preload-index.c    |   10 +
 read-cache.c       |    6 +
 repository.c       |    2 +
 run-command.c      |    8 +-
 run-command.h      |    5 +
 sub-process.c      |    1 +
 trace2.c           | 1592 ++++++++++++++++++++++++++++++++++++++++++++
 trace2.h           |  214 ++++++
 usage.c            |    5 +
 wt-status.c        |   14 +-
 19 files changed, 1882 insertions(+), 6 deletions(-)
 create mode 100644 trace2.c
 create mode 100644 trace2.h


base-commit: 2f743933341f276111103550fbf383a34dfcfd38
Published-As: https://github.com/gitgitgadget/git/releases/tags/pr-29%2Fjeffhostetler%2Fml-trace2-v0-v1
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-29/jeffhostetler/ml-trace2-v0-v1
Pull-Request: https://github.com/gitgitgadget/git/pull/29
-- 
gitgitgadget

[PATCH 1/8] trace2: create new combined trace facility

[Jeff Hostetler via GitGitGadget]

From: Jeff Hostetler <jeffhost@microsoft.com>

Create trace2 API allowing event-based tracing.  This will hopefully
eventually replace the existing trace API.

Create GIT_TR2 trace-key to replace GIT_TRACE, GIT_TR2_PERFORMANCE to
replace GIT_TRACE_PERFORMANCE, and a new trace-key GIT_TR2_EVENT to
generate JSON data for telemetry purposes.  Other structured formats
can easily be added later using this new existing model.

Define a higher-level event API that selectively writes to all of the
new GIT_TR2_* targets (depending on event type) without needing to call
different trace_printf*() or trace_performance_*() routines.

The API defines both fixed-field and printf-style functions.

The trace2 performance tracing includes thread-specific function
nesting and timings.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
---
 Makefile |    1 +
 cache.h  |    1 +
 trace2.c | 1592 ++++++++++++++++++++++++++++++++++++++++++++++++++++++
 trace2.h |  214 ++++++++
 4 files changed, 1808 insertions(+)
 create mode 100644 trace2.c
 create mode 100644 trace2.h

diff --git a/Makefile b/Makefile
index 5a969f5830..88ae7afdd4 100644
--- a/Makefile
+++ b/Makefile
@@ -974,6 +974,7 @@ LIB_OBJS += tag.o
 LIB_OBJS += tempfile.o
 LIB_OBJS += tmp-objdir.o
 LIB_OBJS += trace.o
+LIB_OBJS += trace2.o
 LIB_OBJS += trailer.o
 LIB_OBJS += transport.o
 LIB_OBJS += transport-helper.o
diff --git a/cache.h b/cache.h
index 4d014541ab..38f0cd2ba0 100644
--- a/cache.h
+++ b/cache.h
@@ -9,6 +9,7 @@
 #include "gettext.h"
 #include "convert.h"
 #include "trace.h"
+#include "trace2.h"
 #include "string-list.h"
 #include "pack-revindex.h"
 #include "hash.h"
diff --git a/trace2.c b/trace2.c
new file mode 100644
index 0000000000..13d5c85366
--- /dev/null
+++ b/trace2.c
@@ -0,0 +1,1592 @@
+#include "cache.h"
+#include "config.h"
+#include "json-writer.h"
+#include "quote.h"
+#include "run-command.h"
+#include "sigchain.h"
+#include "thread-utils.h"
+#include "version.h"
+
+/*****************************************************************
+ * TODO remove this section header
+ *****************************************************************/
+
+static struct strbuf tr2sid_buf = STRBUF_INIT;
+static int tr2sid_nr_git_parents;
+
+/*
+ * Compute a "unique" session id (SID) for the current process.  All events
+ * from this process will have this label.  If we were started by another
+ * git instance, use our parent's SID as a prefix and count the number of
+ * nested git processes.  (This lets us track parent/child relationships
+ * even if there is an intermediate shell process.)
+ */
+static void tr2sid_compute(void)
+{
+	uint64_t us_now;
+	const char *parent_sid;
+
+	if (tr2sid_buf.len)
+		return;
+
+	parent_sid = getenv("SLOG_PARENT_SID");
+	if (parent_sid && *parent_sid) {
+		const char *p;
+		for (p = parent_sid; *p; p++)
+			if (*p == '/')
+				tr2sid_nr_git_parents++;
+
+		strbuf_addstr(&tr2sid_buf, parent_sid);
+		strbuf_addch(&tr2sid_buf, '/');
+		tr2sid_nr_git_parents++;
+	}
+
+	us_now = getnanotime() / 1000;
+	strbuf_addf(&tr2sid_buf, "%"PRIuMAX"-%"PRIdMAX,
+		    (uintmax_t)us_now, (intmax_t)getpid());
+
+	setenv("SLOG_PARENT_SID", tr2sid_buf.buf, 1);
+}
+
+/*****************************************************************
+ * TODO remove this section header
+ *****************************************************************/
+
+/*
+ * Each thread (including the main thread) has a stack of nested regions.
+ * This is used to indent messages and provide nested perf times.  The
+ * limit here is for simplicity.  Note that the region stack is per-thread
+ * and not per-trace_key.
+ */
+#define TR2_MAX_REGION_NESTING (100)
+#define TR2_INDENT (2)
+#define TR2_INDENT_LENGTH(ctx) (((ctx)->nr_open_regions - 1) * TR2_INDENT)
+
+#define TR2_MAX_THREAD_NAME (24)
+
+struct tr2tls_thread_ctx {
+	struct strbuf thread_name;
+	uint64_t us_start[TR2_MAX_REGION_NESTING];
+	int nr_open_regions;
+	int thread_id;
+};
+
+static struct tr2tls_thread_ctx *tr2tls_thread_main;
+
+static pthread_mutex_t tr2tls_mutex;
+static pthread_key_t tr2tls_key;
+static int tr2tls_initialized;
+
+static struct strbuf tr2_dots = STRBUF_INIT;
+
+static int tr2_next_child_id;
+static int tr2_next_thread_id;
+
+/*
+ * Create TLS data for the current thread.  This gives us a place to
+ * put per-thread data, such as thread start time, function nesting
+ * and a per-thread label for our messages.
+ *
+ * We assume the first thread is "main".  Other threads are given
+ * non-zero thread-ids to help distinguish messages from concurrent
+ * threads.
+ *
+ * Truncate the thread name if necessary to help with column alignment
+ * in printf-style messages.
+ */
+static struct tr2tls_thread_ctx *tr2tls_create_self(const char *thread_name)
+{
+	struct tr2tls_thread_ctx *ctx = xcalloc(1, sizeof(*ctx));
+
+	/*
+	 * Implicitly "tr2tls_push_self()" to capture the thread's start
+	 * time in us_start[0].  For the main thread this gives us the
+	 * application run time.
+	 */
+	ctx->us_start[ctx->nr_open_regions++] = getnanotime() / 1000;
+
+	pthread_mutex_lock(&tr2tls_mutex);
+	ctx->thread_id = tr2_next_thread_id++;
+	pthread_mutex_unlock(&tr2tls_mutex);
+
+	strbuf_init(&ctx->thread_name, 0);
+	if (ctx->thread_id)
+		strbuf_addf(&ctx->thread_name, "th%02d:", ctx->thread_id);
+	strbuf_addstr(&ctx->thread_name, thread_name);
+	if (ctx->thread_name.len > TR2_MAX_THREAD_NAME)
+		strbuf_setlen(&ctx->thread_name, TR2_MAX_THREAD_NAME);
+
+	pthread_setspecific(tr2tls_key, ctx);
+
+	return ctx;
+}
+
+static struct tr2tls_thread_ctx *tr2tls_get_self(void)
+{
+	struct tr2tls_thread_ctx * ctx = pthread_getspecific(tr2tls_key);
+
+	/*
+	 * If the thread-proc did not call trace2_thread_start(), we won't
+	 * have any TLS data associated with the current thread.  Fix it
+	 * here and silently continue.
+	 */
+	if (!ctx)
+		ctx = tr2tls_create_self("unknown");
+
+	return ctx;
+}
+
+static void tr2tls_unset_self(void)
+{
+	struct tr2tls_thread_ctx * ctx;
+
+	ctx = tr2tls_get_self();
+
+	pthread_setspecific(tr2tls_key, NULL);
+
+	free(ctx);
+}
+
+/*
+ * Begin a new nested region and remember the start time.
+ */
+static void tr2tls_push_self(void)
+{
+	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+
+	if (ctx->nr_open_regions == TR2_MAX_REGION_NESTING)
+		BUG("exceeded max region nesting '%d' in thread '%s'",
+		    ctx->nr_open_regions, ctx->thread_name.buf);
+
+	ctx->us_start[ctx->nr_open_regions++] = getnanotime() / 1000;
+}
+
+/*
+ * End the innermost nested region.
+ */
+static void tr2tls_pop_self(void)
+{
+	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+
+	if (!ctx->nr_open_regions)
+		BUG("no open regions in thread '%s'", ctx->thread_name.buf);
+
+	ctx->nr_open_regions--;
+}
+
+/*
+ * Compute elapsed time in innermost nested region.
+ */
+static uint64_t tr2tls_region_elapsed_self(void)
+{
+	struct tr2tls_thread_ctx *ctx;
+	uint64_t us_start;
+	uint64_t us_now;
+
+	ctx = tr2tls_get_self();
+	if (!ctx->nr_open_regions)
+		return 0;
+	
+	us_now = getnanotime() / 1000;
+	us_start = ctx->us_start[ctx->nr_open_regions - 1];
+
+	return us_now - us_start;
+}
+
+/*
+ * Compute the elapsed run time since the main thread started.
+ */
+static uint64_t tr2tls_elapsed_main(void)
+{
+	uint64_t us_start;
+	uint64_t us_now;
+	uint64_t us_elapsed;
+
+	if (!tr2tls_thread_main)
+		return 0;
+
+	us_now = getnanotime() / 1000;
+	us_start = tr2tls_thread_main->us_start[0];
+	us_elapsed = us_now - us_start;
+
+	return us_elapsed;
+}
+
+static void tr2tls_init(void)
+{
+	pthread_key_create(&tr2tls_key, NULL);
+	init_recursive_mutex(&tr2tls_mutex);
+
+	tr2tls_thread_main = tr2tls_create_self("main");
+	tr2tls_initialized = 1;
+}
+
+static void tr2tls_release(void)
+{
+	tr2tls_unset_self();
+	tr2tls_thread_main = NULL;
+
+	tr2tls_initialized = 0;
+
+	pthread_mutex_destroy(&tr2tls_mutex);
+	pthread_key_delete(tr2tls_key);
+}
+
+/*****************************************************************
+ * TODO remove this section header
+ *****************************************************************/
+
+static struct trace_key tr2key_default = { "GIT_TR2", 0, 0, 0 };
+static struct trace_key tr2key_perf    = { "GIT_TR2_PERFORMANCE", 0, 0, 0 };
+static struct trace_key tr2key_event   = { "GIT_TR2_EVENT", 0, 0, 0 };
+
+/*
+ * Region depth limit for messages written to the event target.
+ *
+ * The "region_enter" and "region_leave" messages (especially recursive
+ * messages such as those produced while diving the worktree or index)
+ * are primarily intended for the performance target during debugging.
+ *
+ * Some of the outer-most messages, however, may be of interest to the
+ * event target.  Set this environment variable to a larger integer for
+ * more detail in the event target.
+ */
+#define GIT_TR2_EVENT_DEPTH "GIT_TR2_EVENT_DEPTH"
+static int tr2env_event_depth_wanted = 2;
+
+/*
+ * Set this environment variable to true to omit the "<time> <file>:<line>"
+ * fields from each line written to the default and performance targets.
+ *
+ * Unit tests may want to use this to help with testing.
+ */
+#define GIT_TR2_BARE "GIT_TR2_BARE"
+static int tr2env_bare_wanted;
+
+static void tr2key_trace_disable(struct trace_key *key)
+{
+	if (key->need_close)
+		close(key->fd);
+	key->fd = 0;
+	key->initialized = 1;
+	key->need_close = 0;
+}
+
+static int tr2key_get_trace_fd(struct trace_key *key)
+{
+	const char *trace;
+
+	/* don't open twice */
+	if (key->initialized)
+		return key->fd;
+
+	trace = getenv(key->key);
+
+	if (!trace || !strcmp(trace, "") ||
+	    !strcmp(trace, "0") || !strcasecmp(trace, "false"))
+		key->fd = 0;
+	else if (!strcmp(trace, "1") || !strcasecmp(trace, "true"))
+		key->fd = STDERR_FILENO;
+	else if (strlen(trace) == 1 && isdigit(*trace))
+		key->fd = atoi(trace);
+	else if (is_absolute_path(trace)) {
+		int fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666);
+		if (fd == -1) {
+			warning("could not open '%s' for tracing: %s",
+				trace, strerror(errno));
+			tr2key_trace_disable(key);
+		} else {
+			key->fd = fd;
+			key->need_close = 1;
+		}
+	} else {
+		warning("unknown trace value for '%s': %s\n"
+			"         If you want to trace into a file, then please set %s\n"
+			"         to an absolute pathname (starting with /)",
+			key->key, trace, key->key);
+		tr2key_trace_disable(key);
+	}
+
+	key->initialized = 1;
+	return key->fd;
+}
+
+static int tr2key_trace_want(struct trace_key *key)
+{
+	return !!tr2key_get_trace_fd(key);
+}
+
+/*
+ * Force (rather than lazily) initialize any of the requested
+ * primary/builtin trace targets at startup (and before we've
+ * seen an actual trace event call) so we can see if we need
+ * to setup the TR2 and TLS machinery.
+ *
+ * Other ad hoc trace targets can just use compatibility mode
+ * and and printf-based messages.
+ */
+static int tr2key_want_builtins(void)
+{
+	int sum = 0;
+	int v;
+	char *p;
+
+	sum += tr2key_trace_want(&tr2key_default);
+	sum += tr2key_trace_want(&tr2key_perf);
+	sum += tr2key_trace_want(&tr2key_event);
+
+	p = getenv(GIT_TR2_EVENT_DEPTH);
+	if (p && ((v = atoi(p)) > 0))
+		tr2env_event_depth_wanted = v;
+
+	p = getenv(GIT_TR2_BARE);
+	if (p && *p && ((v = git_parse_maybe_bool(p)) != -1))
+		tr2env_bare_wanted = v;
+	
+	return sum;
+}
+
+static void tr2key_disable_builtins(void)
+{
+	tr2key_trace_disable(&tr2key_default);
+	tr2key_trace_disable(&tr2key_perf);
+	tr2key_trace_disable(&tr2key_event);
+}
+
+/*****************************************************************
+ * TODO remove this section header
+ *****************************************************************/
+
+/*
+ * A simple wrapper around a fixed buffer to avoid C syntax
+ * quirks and the need to pass around an additional size_t
+ * argument.
+ */
+struct tr2time_buf {
+	char buf[24];
+};
+
+static void tr2time_current_time(struct tr2time_buf *tb)
+{
+	struct timeval tv;
+	struct tm tm;
+	time_t secs;
+
+	gettimeofday(&tv, NULL);
+	secs = tv.tv_sec;
+	localtime_r(&secs, &tm);
+
+	xsnprintf(tb->buf, sizeof(tb->buf), "%02d:%02d:%02d.%06ld ",
+		  tm.tm_hour, tm.tm_min, tm.tm_sec, (long)tv.tv_usec);
+}
+
+/*****************************************************************
+ * TODO remove this section header
+ *****************************************************************/
+
+#define TR2FMT_MAX_EVENT_NAME (12)
+
+/*
+ * Format trace line prefix in human-readable classic format for
+ * the default target:
+ *     "<time> <file>:<line> <bar> <thread_name> <bar> <event_name> <bar> "
+ */
+static void tr2fmt_prepare_default(
+	const char *event_name,
+	struct tr2tls_thread_ctx *ctx,
+	const char *file, int line,
+	struct strbuf *buf)
+{
+	strbuf_setlen(buf,0);
+
+	if (!tr2env_bare_wanted) {
+		struct tr2time_buf tb_now;
+
+		tr2time_current_time(&tb_now);
+		strbuf_addstr(buf, tb_now.buf);
+
+		if (file && *file)
+			strbuf_addf(buf, "%s:%d ", file, line);
+		while (buf->len < 40)
+			strbuf_addch(buf, ' ');
+
+		strbuf_addstr(buf, "| ");
+	}
+
+	strbuf_addf(buf, "%-*s | %-*s | ",
+		    TR2_MAX_THREAD_NAME, ctx->thread_name.buf,
+		    TR2FMT_MAX_EVENT_NAME, event_name);
+}
+
+/*
+ * Format trace line prefix in human-readable classic format for
+ * the performance target:
+ *     "[<time>] [<file>:<line>] [<thread_name>] [<event_name>] <bar> <indent>"
+ */
+static void tr2fmt_prepare_perf(
+	const char *event_name,
+	struct tr2tls_thread_ctx *ctx,
+	const char *file, int line,
+	uint64_t *p_us_elapsed,
+	struct strbuf *buf)
+{
+	strbuf_setlen(buf,0);
+
+	if (!tr2env_bare_wanted) {
+
+		struct tr2time_buf tb_now;
+
+		tr2time_current_time(&tb_now);
+		strbuf_addstr(buf, tb_now.buf);
+
+		if (file && *file)
+			strbuf_addf(buf, "%s:%d ", file, line);
+		while (buf->len < 40)
+			strbuf_addch(buf, ' ');
+
+		strbuf_addstr(buf, "| ");
+	}
+
+	strbuf_addf(buf, "%-*s | %-*s | ",
+		    TR2_MAX_THREAD_NAME, ctx->thread_name.buf,
+		    TR2FMT_MAX_EVENT_NAME, event_name);
+
+	if (p_us_elapsed)
+		strbuf_addf(buf, "%9.6f | ",
+			    ((double)(*p_us_elapsed)) / 1000000.0);
+	else
+		strbuf_addf(buf, "%9s | ", " ");
+		
+	if (ctx->nr_open_regions > 0)
+		strbuf_addf(buf, "%.*s", TR2_INDENT_LENGTH(ctx), tr2_dots.buf);
+}
+
+/*
+ * Append common key-value pairs to the currently open JSON object.
+ *     "event:"<event_name>"
+ *      "sid":"<sid>"
+ *   "thread":"<thread_name>"
+ *     "file":"<filename>"
+ *     "line":<line_number>
+ */
+static void tr2fmt_prepare_json_trace_line(
+	const char *event_name,
+	const char *file, int line,
+	struct json_writer *jw)
+{
+	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+
+	jw_object_string(jw, "event", event_name);
+	jw_object_string(jw, "sid", tr2sid_buf.buf);
+	jw_object_string(jw, "thread", ctx->thread_name.buf);
+
+	if (file && *file) {
+		jw_object_string(jw, "file", file);
+		jw_object_intmax(jw, "line", line);
+	}
+}
+
+/*****************************************************************
+ * TODO remove this section header
+ *****************************************************************/
+
+static void tr2io_write_line(struct trace_key *key, struct strbuf *buf_line)
+{
+	strbuf_complete_line(buf_line); /* ensure final NL on buffer */
+
+	// TODO we don't really want short-writes to try again when
+	// TODO we are in append mode...
+
+	if (write_in_full(tr2key_get_trace_fd(key),
+			  buf_line->buf, buf_line->len) < 0) {
+		warning("unable to write trace for '%s': %s",
+			key->key, strerror(errno));
+		tr2key_trace_disable(key);
+	}
+}
+
+static void tr2io_write_default_fl(const char *file, int line,
+				   const char *event_name,
+				   const struct strbuf *buf_payload)
+{
+	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+	struct strbuf buf_line = STRBUF_INIT;
+
+	tr2fmt_prepare_default(event_name, ctx, file, line, &buf_line);
+
+	strbuf_addbuf(&buf_line, buf_payload);
+
+	tr2io_write_line(&tr2key_default, &buf_line);
+
+	strbuf_release(&buf_line);
+}
+
+static void tr2io_write_perf_fl(const char *file, int line,
+				const char *event_name,
+				uint64_t *p_us_elapsed,
+				const struct strbuf *buf_payload)
+{
+	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+	struct strbuf buf_line = STRBUF_INIT;
+
+	tr2fmt_prepare_perf(event_name, ctx, file, line,
+			    p_us_elapsed, &buf_line);
+
+	strbuf_addbuf(&buf_line, buf_payload);
+
+	tr2io_write_line(&tr2key_perf, &buf_line);
+
+	strbuf_release(&buf_line);
+}
+
+/*****************************************************************
+ * TODO remove this section header
+ *****************************************************************/
+
+/*
+ * Write 'version' event message to the builtin targets.
+ */
+static void tr2evt_version_fl(const char *file, int line)
+{
+	const char *event_name = "version";
+
+	if (tr2key_trace_want(&tr2key_default)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addf(&buf_payload, "%s", git_version_string);
+
+		tr2io_write_default_fl(file, line, event_name, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addf(&buf_payload, "%s", git_version_string);
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, NULL, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, file, line, &jw);
+		jw_object_string(&jw, "git", git_version_string);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+/*
+ * Write 'start' event message to the builtin targets.
+ */
+static void tr2evt_start_fl(const char *file, int line,
+			    const char **argv)
+{
+	const char *event_name = "start";
+
+	if (tr2key_trace_want(&tr2key_default)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		sq_quote_argv_pretty(&buf_payload, argv);
+
+		tr2io_write_default_fl(file, line, event_name, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		sq_quote_argv_pretty(&buf_payload, argv);
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, NULL, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, file, line, &jw);
+		jw_object_inline_begin_array(&jw, "argv");
+		jw_array_argv(&jw, argv);
+		jw_end(&jw);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+/*
+ * Write 'exit' event message to the builtin targets.
+ */
+static void tr2evt_exit_fl(const char *file, int line,
+			   int code, uint64_t us_elapsed)
+{
+	const char *event_name = "exit";
+
+	if (tr2key_trace_want(&tr2key_default)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+		double elapsed = (double)us_elapsed / 1000000.0;
+
+		strbuf_addf(&buf_payload, "elapsed:%.6f code:%d",
+			    elapsed, code);
+
+		tr2io_write_default_fl(file, line, event_name, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addf(&buf_payload, "code:%d", code);
+
+		tr2io_write_perf_fl(file, line, event_name,
+				    &us_elapsed, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+		double elapsed = (double)us_elapsed / 1000000.0;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, file, line, &jw);
+		jw_object_double(&jw, "elapsed", 6, elapsed);
+		jw_object_intmax(&jw, "code", code);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+/*
+ * Write 'signal' event message to the builtin targets.
+ */
+static void tr2evt_signal(int signo, uint64_t us_elapsed)
+{
+	const char *event_name = "signal";
+
+	if (tr2key_trace_want(&tr2key_default)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+		double elapsed = (double)us_elapsed / 1000000.0;
+
+		strbuf_addf(&buf_payload, "elapsed:%.6f signo:%d",
+			    elapsed, signo);
+
+		tr2io_write_default_fl(__FILE__, __LINE__,
+				       event_name, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addf(&buf_payload, "signo:%d", signo);
+
+		tr2io_write_perf_fl(__FILE__, __LINE__,
+				    event_name, &us_elapsed, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+		double elapsed = (double)us_elapsed / 1000000.0;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, __FILE__, __LINE__, &jw);
+		jw_object_double(&jw, "elapsed", 6, elapsed);
+		jw_object_intmax(&jw, "signo", signo);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+/*
+ * Write 'atexit' event message to the builtin targets.
+ */
+static void tr2evt_atexit(int code, uint64_t us_elapsed)
+{
+	const char *event_name = "atexit";
+
+	if (tr2key_trace_want(&tr2key_default)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+		double elapsed = (double)us_elapsed / 1000000.0;
+
+		strbuf_addf(&buf_payload, "elapsed:%.6f code:%d",
+			    elapsed, code);
+
+		tr2io_write_default_fl(__FILE__, __LINE__,
+				       event_name, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addf(&buf_payload, "code:%d", code);
+
+		tr2io_write_perf_fl(__FILE__, __LINE__,
+				    event_name, &us_elapsed, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+		double elapsed = (double)us_elapsed / 1000000.0;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, __FILE__, __LINE__, &jw);
+		jw_object_double(&jw, "elapsed", 6, elapsed);
+		jw_object_intmax(&jw, "code", code);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+static void tr2evt_error_va_fl(const char *file, int line,
+			       const char *fmt, va_list ap)
+{
+	const char *event_name = "error";
+
+	if (tr2key_trace_want(&tr2key_default)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_vaddf(&buf_payload, fmt, ap);
+
+		tr2io_write_default_fl(file, line, event_name, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_vaddf(&buf_payload, fmt, ap);
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, NULL, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+		struct strbuf buf_msg = STRBUF_INIT;
+
+		strbuf_vaddf(&buf_msg, fmt, ap);
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, file, line, &jw);
+		jw_object_string(&jw, "msg", buf_msg.buf);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+		strbuf_release(&buf_msg);
+	}
+}
+
+static void tr2evt_command_fl(const char *file, int line,
+			      const char *command_name)
+{
+	const char *event_name = "command";
+
+	if (tr2key_trace_want(&tr2key_default)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addstr(&buf_payload, command_name);
+
+		tr2io_write_default_fl(file, line, event_name, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addstr(&buf_payload, command_name);
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, NULL, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, file, line, &jw);
+		jw_object_string(&jw, "name", command_name);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+static void tr2evt_worktree_fl(const char *file, int line,
+			       const char *path)
+{
+	const char *event_name = "worktree";
+
+	if (tr2key_trace_want(&tr2key_default)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addstr(&buf_payload, path);
+
+		tr2io_write_default_fl(file, line, event_name, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addstr(&buf_payload, path);
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, NULL, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, file, line, &jw);
+		jw_object_string(&jw, "path", path);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+static void tr2evt_alias_fl(const char *file, int line,
+			    const char *alias, const char **argv)
+{
+	const char *event_name = "alias";
+
+	if (tr2key_trace_want(&tr2key_default)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addf(&buf_payload, "alias:%s argv:", alias);
+		sq_quote_argv_pretty(&buf_payload, argv);
+
+		tr2io_write_default_fl(file, line, event_name, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addf(&buf_payload, "alias:%s argv:", alias);
+		sq_quote_argv_pretty(&buf_payload, argv);
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, NULL, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, file, line, &jw);
+		jw_object_string(&jw, "alias", alias);
+		jw_object_inline_begin_array(&jw, "argv");
+		jw_array_argv(&jw, argv);
+		jw_end(&jw);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+static void tr2evt_param_fl(const char *file, int line,
+			    const char *param, const char *value)
+{
+	const char *event_name = "param";
+
+	if (tr2key_trace_want(&tr2key_default)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addf(&buf_payload, "%s:%s", param, value);
+
+		tr2io_write_default_fl(file, line, event_name, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addf(&buf_payload, "%s:%s", param, value);
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, NULL, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, file, line, &jw);
+		jw_object_string(&jw, "param", param);
+		jw_object_string(&jw, "value", value);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+/*
+ * Write a common 'child_start' message to the builtin targets.
+ */
+static void tr2evt_child_start_fl(const char *file, int line,
+				  int child_id, const char *child_class,
+				  const char **argv)
+{
+	const char *event_name = "child_start";
+
+	if (!child_class)
+		child_class = "?";
+
+	if (tr2key_trace_want(&tr2key_default)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addf(&buf_payload, "[ch%d] class:%s argv:",
+			    child_id, child_class);
+		sq_quote_argv_pretty(&buf_payload, argv);
+
+		tr2io_write_default_fl(file, line, event_name, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addf(&buf_payload, "[ch%d] class:%s argv:",
+			    child_id, child_class);
+		sq_quote_argv_pretty(&buf_payload, argv);
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, NULL, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, file, line, &jw);
+		jw_object_intmax(&jw, "child_id", child_id);
+		jw_object_string(&jw, "child_class", child_class);
+		jw_object_inline_begin_array(&jw, "argv");
+		jw_array_argv(&jw, argv);
+		jw_end(&jw);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+static void tr2evt_child_exit_fl(const char *file, int line,
+				 int child_id,
+				 int child_exit_code,
+				 uint64_t us_elapsed)
+{
+	const char *event_name = "child_exit";
+
+	if (tr2key_trace_want(&tr2key_default)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+		double elapsed = (double)us_elapsed / 1000000.0;
+
+		strbuf_addf(&buf_payload, "[ch%d] code:%d elapsed:%.6f",
+			    child_id, child_exit_code, elapsed);
+		
+		tr2io_write_default_fl(file, line, event_name, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addf(&buf_payload, "[ch%d] code:%d",
+			    child_id, child_exit_code);
+		
+		tr2io_write_perf_fl(file, line,
+				    event_name, &us_elapsed, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+		double elapsed = (double)us_elapsed / 1000000.0;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, file, line, &jw);
+		jw_object_intmax(&jw, "child_id", child_id);
+		jw_object_intmax(&jw, "code", child_exit_code);
+		jw_object_double(&jw, "elapsed", 6, elapsed);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+
+		jw_release(&jw);
+	}
+}
+
+static void tr2evt_thread_start_fl(const char *file, int line)
+{
+	const char *event_name = "thread_start";
+
+	/* Default target does not care about threads. */
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, NULL, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, file, line, &jw);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+static void tr2evt_thread_exit_fl(const char *file, int line,
+				  uint64_t us_elapsed)
+{
+	const char *event_name = "thread_exit";
+
+	/* Default target does not care about threads. */
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, &us_elapsed, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+		double elapsed = (double)us_elapsed / 1000000.0;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, file, line, &jw);
+		jw_object_double(&jw, "elapsed", 6, elapsed);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+static void tr2evt_region_enter_va_fl(const char *file, int line,
+				      const char *fmt, va_list ap)
+{
+	const char *event_name = "region_enter";
+
+	/* Default target does not care about nesting. */
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_vaddf(&buf_payload, fmt, ap);
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, NULL, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+		if (ctx->nr_open_regions <= tr2env_event_depth_wanted) {
+			struct json_writer jw = JSON_WRITER_INIT;
+			struct strbuf buf = STRBUF_INIT;
+
+			strbuf_vaddf(&buf, fmt, ap);
+
+			jw_object_begin(&jw, 0);
+			tr2fmt_prepare_json_trace_line(
+				event_name, file, line, &jw);
+			jw_object_intmax(&jw, "depth", ctx->nr_open_regions);
+			jw_object_string(&jw, "msg", buf.buf);
+			jw_end(&jw);
+
+			tr2io_write_line(&tr2key_event, &jw.json);
+			jw_release(&jw);
+			strbuf_release(&buf);
+		}
+	}
+}
+
+static void tr2evt_region_leave_va_fl(const char *file, int line,
+				      uint64_t us_elapsed,
+				      const char *fmt, va_list ap)
+{
+	const char *event_name = "region_leave";
+
+	/* Default target does not care about nesting. */
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_vaddf(&buf_payload, fmt, ap);
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, &us_elapsed, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+		if (ctx->nr_open_regions <= tr2env_event_depth_wanted) {
+			struct json_writer jw = JSON_WRITER_INIT;
+			struct strbuf buf = STRBUF_INIT;
+			double elapsed = (double)us_elapsed / 1000000.0;
+
+			strbuf_vaddf(&buf, fmt, ap);
+
+			jw_object_begin(&jw, 0);
+			tr2fmt_prepare_json_trace_line(
+				event_name, file, line, &jw);
+			jw_object_double(&jw, "elapsed", 6, elapsed);
+			jw_object_intmax(&jw, "depth", ctx->nr_open_regions);
+			jw_object_string(&jw, "msg", buf.buf);
+			jw_end(&jw);
+
+			tr2io_write_line(&tr2key_event, &jw.json);
+			jw_release(&jw);
+			strbuf_release(&buf);
+		}
+	}
+}
+
+static void tr2evt_printf_va_fl(const char *file, int line,
+				const char *fmt, va_list ap)
+{
+	const char *event_name = "printf";
+
+	if (tr2key_trace_want(&tr2key_default)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_vaddf(&buf_payload, fmt, ap);
+
+		tr2io_write_default_fl(file, line, event_name, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_vaddf(&buf_payload, fmt, ap);
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, NULL, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	/* Event target does not care about printf messages. */
+}
+
+static void tr2evt_data_fl(const char *file, int line,
+			   const char *category,
+			   const char *key,
+			   const char *value)
+{
+	const char *event_name = "data";
+
+	/* Default target does not care about data messages. */
+
+	if (tr2key_trace_want(&tr2key_perf)) {
+		struct strbuf buf_payload = STRBUF_INIT;
+
+		strbuf_addf(&buf_payload, "category:%s key:%s value:%s",
+			    category, key, value);
+
+		tr2io_write_perf_fl(file, line,
+				    event_name, NULL, &buf_payload);
+		strbuf_release(&buf_payload);
+	}
+
+	if (tr2key_trace_want(&tr2key_event)) {
+		struct json_writer jw = JSON_WRITER_INIT;
+
+		jw_object_begin(&jw, 0);
+		tr2fmt_prepare_json_trace_line(
+			event_name, file, line, &jw);
+		jw_object_string(&jw, "category", category);
+		jw_object_string(&jw, "key", key);
+		jw_object_string(&jw, "value", value);
+		jw_end(&jw);
+
+		tr2io_write_line(&tr2key_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+/*****************************************************************
+ * TODO remove this section header
+ *****************************************************************/
+
+static int tr2main_exit_code;
+
+/*
+ * Our atexit routine should run after everything has finished.
+ * The system should call it on the main thread.
+ *
+ * Note that events generated here might not actually appear if
+ * we are writing to fd 1 or 2 and our atexit routine runs after
+ * the pager's atexit routine (since it closes them to shutdown
+ * the pipes).
+ */
+static void tr2main_atexit_handler(void)
+{
+	assert(tr2tls_get_self() == tr2tls_thread_main);
+
+	/*
+	 * Pop any extra open regions on the main thread and discard.
+	 * Normally, we should only have the region[0] that was pushed
+	 * in trace2_start(), but there may be more if someone calls
+	 * die() for example.
+	 */
+	while (tr2tls_thread_main->nr_open_regions > 1)
+		tr2tls_pop_self();
+
+	/*
+	 * Issue single 'atexit' event with the elapsed time since
+	 * the main thread was started.
+	 */
+	tr2evt_atexit(tr2main_exit_code, tr2tls_elapsed_main());
+		
+	tr2key_disable_builtins();
+
+	tr2tls_release();
+
+	strbuf_release(&tr2sid_buf);
+	strbuf_release(&tr2_dots);
+}
+
+static void tr2main_signal_handler(int signo)
+{
+	tr2evt_signal(signo, tr2tls_elapsed_main());
+
+	sigchain_pop(signo);
+	raise(signo);
+}
+
+/*****************************************************************
+ * TODO remove this section header
+ *****************************************************************/
+
+void trace2_start_fl(const char *file, int line, const char **argv)
+{
+	if (!tr2key_want_builtins())
+		return;
+
+	tr2sid_compute();
+	strbuf_addchars(&tr2_dots, '.',
+			TR2_MAX_REGION_NESTING * TR2_INDENT);
+
+	atexit(tr2main_atexit_handler);
+	sigchain_push(SIGPIPE, tr2main_signal_handler);
+
+	tr2tls_init();
+
+	tr2evt_version_fl(file, line);
+	tr2evt_start_fl(file, line, argv);
+}
+
+int trace2_exit_fl(const char *file, int line, int code)
+{
+	code &= 0xff;
+
+	if (!tr2tls_initialized)
+		return code;
+
+	tr2main_exit_code = code;
+
+	tr2evt_exit_fl(file, line, code, tr2tls_elapsed_main());
+
+	return code;
+}
+
+void trace2_error_va_fl(const char *file, int line,
+			const char *fmt, va_list ap)
+{
+	if (!tr2tls_initialized)
+		return;
+
+	tr2evt_error_va_fl(file, line, fmt, ap);
+}
+
+void trace2_command_fl(const char *file, int line,
+		       const char *command_name)
+{
+	if (!tr2tls_initialized)
+		return;
+
+	tr2evt_command_fl(file, line, command_name);
+}
+
+void trace2_worktree_fl(const char *file, int line,
+			const char *path)
+{
+	if (!tr2tls_initialized)
+		return;
+
+	tr2evt_worktree_fl(file, line, path);
+}
+
+void trace2_alias_fl(const char *file, int line,
+		     const char *alias, const char **argv)
+{
+	if (!tr2tls_initialized)
+		return;
+
+	tr2evt_alias_fl(file, line, alias, argv);
+}
+
+void trace2_param_fl(const char *file, int line,
+		     const char *param, const char *value)
+{
+	if (!tr2tls_initialized)
+		return;
+
+	tr2evt_param_fl(file, line, param, value);
+}
+
+void trace2_child_start_fl(const char *file, int line,
+			   struct child_process *cmd)
+{
+	if (!tr2tls_initialized)
+		return;
+
+	pthread_mutex_lock(&tr2tls_mutex);
+	cmd->trace2_child_id = tr2_next_child_id++;
+	pthread_mutex_unlock(&tr2tls_mutex);
+
+	cmd->trace2_child_us_start = getnanotime() / 1000;
+
+	tr2evt_child_start_fl(file, line,
+			      cmd->trace2_child_id,
+			      cmd->trace2_child_class,
+			      cmd->argv);
+}
+
+void trace2_child_exit_fl(const char *file, int line,
+			  struct child_process *cmd,
+			  int child_exit_code)
+{
+	uint64_t us_elapsed;
+
+	if (!tr2tls_initialized)
+		return;
+
+	if (cmd->trace2_child_us_start)
+		us_elapsed = (getnanotime() / 1000) - cmd->trace2_child_us_start;
+	else
+		us_elapsed = 0;
+	
+	tr2evt_child_exit_fl(file, line,
+			     cmd->trace2_child_id,
+			     child_exit_code,
+			     us_elapsed);
+}
+
+void trace2_thread_start_fl(const char *file, int line,
+			    const char *thread_name)
+{
+	if (!tr2tls_initialized)
+		return;
+
+	tr2tls_create_self(thread_name);
+
+	tr2evt_thread_start_fl(file, line);
+}
+
+void trace2_thread_exit_fl(const char *file, int line)
+{
+	struct tr2tls_thread_ctx *ctx;
+
+	if (!tr2tls_initialized)
+		return;
+
+	/*
+	 * Pop any extra open regions on the current thread and discard.
+	 * Normally, we should only have the region[0] that was pushed
+	 * in trace2_thread_start() if the thread exits normally.
+	 */
+	ctx = tr2tls_get_self();
+	while (ctx->nr_open_regions > 1)
+		tr2tls_pop_self();
+
+	tr2evt_thread_exit_fl(file, line, tr2tls_region_elapsed_self());
+
+	tr2tls_unset_self();
+}
+
+void trace2_region_enter_va_fl(const char *file, int line,
+			       const char *fmt, va_list ap)
+{
+	if (!tr2tls_initialized)
+		return;
+
+	if (fmt && *fmt)
+		tr2evt_region_enter_va_fl(file, line, fmt, ap);
+
+	tr2tls_push_self();
+}
+
+void trace2_region_enter_fl(const char *file, int line,
+			    const char *fmt, ...)
+{
+	va_list ap;
+	va_start(ap, fmt);
+	trace2_region_enter_va_fl(file, line, fmt, ap);
+	va_end(ap);
+}
+
+#ifndef HAVE_VARIADIC_MACROS
+void trace2_region_enter(const char *fmt, ...)
+{
+	va_list ap;
+	va_start(ap, fmt);
+	trace2_region_enter_va_fl(NULL, 0, fmt, ap);
+	va_end(ap);
+}
+#endif
+
+void trace2_region_leave_va_fl(const char *file, int line,
+			       const char *fmt, va_list ap)
+{
+	uint64_t us_elapsed;
+
+	if (!tr2tls_initialized)
+		return;
+
+	/*
+	 * Get the elapsed time in the current region before we
+	 * pop it off the stack.  Pop the stack.  And then print
+	 * the perf message at the new (shallower) level so that
+	 * it lines up with the corresponding push/enter.
+	 */
+	us_elapsed = tr2tls_region_elapsed_self();
+	
+	tr2tls_pop_self();
+
+	if (fmt && *fmt)
+		tr2evt_region_leave_va_fl(file, line, us_elapsed, fmt, ap);
+}
+
+void trace2_region_leave_fl(const char *file, int line,
+			    const char *fmt, ...)
+{
+	va_list ap;
+	va_start(ap, fmt);
+	trace2_region_leave_va_fl(file, line, fmt, ap);
+	va_end(ap);
+}
+
+#ifndef HAVE_VARIADIC_MACROS
+void trace2_region_leave(const char *fmt, ...)
+{
+	va_list ap;
+	va_start(ap, fmt);
+	trace2_region_leave_va_fl(NULL, 0, fmt, ap);
+	va_end(ap);
+}
+#endif
+
+void trace2_printf_va_fl(const char *file, int line,
+			 const char *fmt, va_list ap)
+{
+	if (!tr2tls_initialized)
+		return;
+
+	tr2evt_printf_va_fl(file, line, fmt, ap);
+}
+
+void trace2_printf_fl(const char *file, int line,
+		      const char *fmt, ...)
+{
+	va_list ap;
+
+	va_start(ap, fmt);
+	trace2_printf_va_fl(file, line, fmt, ap);
+	va_end(ap);
+}
+
+#ifndef HAVE_VARIADIC_MACROS
+void trace2_printf(const char *fmt, ...)
+{
+	va_list ap;
+
+	va_start(ap, fmt);
+	trace2_printf_va_fl(NULL, 0, fmt, ap);
+	va_end(ap);
+}
+#endif
+
+void trace2_data_intmax_fl(const char *file, int line,
+			   const char *category,
+			   const char *key,
+			   intmax_t value)
+{
+	struct strbuf buf_string = STRBUF_INIT;
+
+	if (!tr2tls_initialized)
+		return;
+
+	strbuf_addf(&buf_string, "%"PRIdMAX, value);
+	tr2evt_data_fl(file, line, category, key, buf_string.buf);
+	strbuf_release(&buf_string);
+}
+
+void trace2_data_string_fl(const char *file, int line,
+			   const char *category,
+			   const char *key,
+			   const char *value)
+{
+	if (!tr2tls_initialized)
+		return;
+
+	tr2evt_data_fl(file, line, category, key, value);
+}
diff --git a/trace2.h b/trace2.h
new file mode 100644
index 0000000000..0ef08c1253
--- /dev/null
+++ b/trace2.h
@@ -0,0 +1,214 @@
+#ifndef TRACE2_H
+#define TRACE2_H
+
+/*
+ * Begin TRACE2 tracing (if any of the builtin TRACE2 targets are
+ * enabled in the environment).
+ *
+ * Emit a 'start' event.
+ */
+void trace2_start_fl(const char *file, int line,
+		     const char **argv);
+
+#define trace2_start(argv) trace2_start_fl(__FILE__, __LINE__, argv)
+
+/*
+ * Emit an 'exit' event.
+ *
+ * Write the exit-code that will be passed to exit() or returned
+ * from main().  Use this prior to actually calling exit().
+ * See "#define exit()" in git-compat-util.h
+ */
+int trace2_exit_fl(const char *file, int line, int code);
+
+#define trace2_exit(code) (trace2_exit_fl(__FILE__, __LINE__, (code)))
+
+/*
+ * Emit an 'error' event.
+ *
+ * Write an error message to the TRACE2 targets.
+ */
+void trace2_error_va_fl(const char *file, int line,
+			const char *fmt, va_list ap);
+
+#define trace2_error_va(fmt, ap) \
+	trace2_error_va_fl(__FILE__, __LINE__, (fmt), (ap))
+
+void trace2_command_fl(const char *file, int line,
+		       const char *command_name);
+
+#define trace2_command(n) \
+	trace2_command_fl(__FILE__, __LINE__, (n))
+
+/*
+ * Emit a 'worktree' event giving the absolute path of the worktree.
+ */
+void trace2_worktree_fl(const char *file, int line,
+			const char *path);
+
+#define trace2_worktree(path) \
+	trace2_worktree_fl(__FILE__, __LINE__, path)
+
+/*
+ * Emit an 'alias' expansion event.
+ */
+void trace2_alias_fl(const char *file, int line,
+		     const char *alias, const char **argv);
+
+#define trace2_alias(alias, argv) \
+	trace2_alias_fl(__FILE__, __LINE__, (alias), (argv))
+
+/*
+ * Emit a 'param' event.
+ *
+ * Write a (key, value) pair describing some aspect of the run
+ * such as an important configuration setting.
+ */ 
+void trace2_param_fl(const char *file, int line,
+		     const char *param, const char *value);
+
+#define trace2_param(param, value) \
+	trace2_param_fl(__FILE__, __LINE__, (param), (value))
+
+struct child_process;
+
+/*
+ * Emit a 'child_start' event prior to spawning a child process.
+ *
+ * Before calling optionally set cmd.trace2_child_class to a string
+ * describing the type of the child process.  For example, "editor"
+ * or "pager".
+ */
+void trace2_child_start_fl(const char *file, int line,
+			   struct child_process *cmd);
+
+#define trace2_child_start(cmd) \
+	trace2_child_start_fl(__FILE__, __LINE__, (cmd))
+
+/*
+ * Emit a 'child_exit' event after the child process completes. 
+ */
+void trace2_child_exit_fl(const char *file, int line,
+			  struct child_process *cmd,
+			  int child_exit_code);
+
+#define trace2_child_exit(cmd, code) \
+	trace2_child_exit_fl(__FILE__, __LINE__, (cmd), (code))
+
+/*
+ * Emit a 'thread_start' event.  This must be called from inside the
+ * thread-proc to set up TLS data for the thread.
+ *
+ * Thread names should be descriptive, like "preload_index".
+ * Thread names will be decorated with an instance number automatically.
+ */
+void trace2_thread_start_fl(const char *file, int line,
+			    const char *thread_name);
+
+#define trace2_thread_start(thread_name) \
+	trace2_thread_start_fl(__FILE__, __LINE__, (thread_name))
+
+/*
+ * Emit a 'thead_exit' event.  This must be called from inside the
+ * thread-proc to report thread-specific data and cleanup TLS data
+ * for the thread.
+ */
+void trace2_thread_exit_fl(const char *file, int line);
+
+#define trace2_thread_exit() trace2_thread_exit_fl(__FILE__, __LINE__)
+
+/*
+ * Emit a 'printf' event.
+ *
+ * Write an arbitrary formatted message to the TRACE2 targets.  These
+ * text messages should be considered as human-readable strings without
+ * any formatting guidelines.  Post-processors may choose to ignore
+ * them.
+ */
+void trace2_printf_va_fl(const char *file, int line,
+			 const char *fmt, va_list ap);
+
+#define trace2_printf_va(fmt, ap) \
+	trace2_printf_va_fl(__FILE__, __LINE__, (fmt), (ap))
+
+void trace2_printf_fl(const char *file, int line, const char *fmt, ...);
+
+#ifdef HAVE_VARIADIC_MACROS
+#define trace2_printf(...) \
+	trace2_printf_fl(__FILE__, __LINE__, __VA_ARGS__)
+#else
+__attribute__((format (printf, 1, 2)))
+void trace2_printf(const char *fmt, ...);
+#endif
+
+/*
+ * Emit a 'region_enter' event.
+ *
+ * Enter a new nesting level on the current thread and remember the
+ * current time.  This controls the indenting of subsequent thread
+ * events.
+ */
+void trace2_region_enter_va_fl(const char *file, int line,
+			       const char *fmt, va_list ap);
+
+#define trace2_region_enter_va(fmt, ap) \
+	trace2_region_enter_va_fl(__FILE__, __LINE__, (fmt), (ap))
+
+void trace2_region_enter_fl(const char *file, int line, const char *fmt, ...);
+
+#ifdef HAVE_VARIADIC_MACROS
+#define trace2_region_enter(...) \
+	trace2_region_enter_fl(__FILE__, __LINE__, __VA_ARGS__)
+#else
+__attribute__((format (printf, 1, 2)))
+void trace2_region_enter(const char *fmt, ...);
+#endif
+
+/*
+ * Emit a 'region_leave' event.
+ *
+ * Leave current nesting level and report the elapsed time spent
+ * in this nesting level.
+ */
+void trace2_region_leave_va_fl(const char *file, int line,
+			       const char *fmt, va_list ap);
+
+#define trace2_region_enter_va(fmt, ap) \
+	trace2_region_enter_va_fl(__FILE__, __LINE__, (fmt), (ap))
+
+void trace2_region_leave_fl(const char *file, int line, const char *fmt, ...);
+
+#ifdef HAVE_VARIADIC_MACROS
+#define trace2_region_leave(...) \
+	trace2_region_leave_fl(__FILE__, __LINE__, __VA_ARGS__)
+#else
+__attribute__((format (printf, 1, 2)))
+void trace2_region_leave(const char *fmt, ...);
+#endif
+
+/*
+ * Emit a 'data' event to report a <category>.<key> = <value> pair.
+ * This can be used to report global data, such as the size of the index,
+ * or by a thread to report TLS data, such as their assigned subset.
+ *
+ * On event-based TRACE2 targets, this generates a 'data' event suitable
+ * for post-processing.  On printf-based TRACE2 targets, this is converted
+ * into a fixed-format printf message.
+ */
+void trace2_data_intmax_fl(const char *file, int line,
+			   const char *category,
+			   const char *key,
+			   intmax_t value);
+
+#define trace2_data_intmax(c, k, v) \
+	trace2_data_intmax_fl(__FILE__, __LINE__, (c), (k), (v))
+
+void trace2_data_string_fl(const char *file, int line,
+			   const char *category,
+			   const char *key,
+			   const char *value);
+
+#define trace2_data_string(c, k, v) \
+	trace2_data_string_fl(__FILE__, __LINE__, (c), (k), (v))
+
+#endif /* TRACE2_H */
-- 
gitgitgadget

Re: [PATCH 1/8] trace2: create new combined trace facility

[Derrick Stolee]

On 8/31/2018 12:49 PM, Jeff Hostetler via GitGitGadget wrote:
> +	if (tr2key_trace_want(&tr2key_event)) {
> +		struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
> +		if (ctx->nr_open_regions <= tr2env_event_depth_wanted) {

This should also compare to TR2_MAX_REGION_NESTING to avoid memory 
bounds issues. It may even be worth sending a message that the depth 
went beyond the limits.

Thanks,

-Stolee

Re: [PATCH 1/8] trace2: create new combined trace facility

[Stefan Beller]

> Create GIT_TR2 trace-key to replace GIT_TRACE, GIT_TR2_PERFORMANCE to
> replace GIT_TRACE_PERFORMANCE, and a new trace-key GIT_TR2_EVENT to
> generate JSON data for telemetry purposes.  Other structured formats
> can easily be added later using this new existing model.

So the idea is to use the GIT_TR2 instead of GIT_TRACE and we
get the same output as well as a new form of structured logging here?
(Then GIT_TRACE could be retired, and we'd use the new API to add
more events, which are also more structured as the API allows for more
than just a string printed?)

> Define a higher-level event API that selectively writes to all of the
> new GIT_TR2_* targets (depending on event type) without needing to call
> different trace_printf*() or trace_performance_*() routines.
>
> The API defines both fixed-field and printf-style functions.
>
> The trace2 performance tracing includes thread-specific function
> nesting and timings.

So this only adds the new API, and we need to merge the TRACE
into the TRACE2 later?

> +++ b/trace2.c
> @@ -0,0 +1,1592 @@
[...]
> +
> +/*****************************************************************
> + * TODO remove this section header
> + *****************************************************************/

Yes, please.

> +/*
> + * Compute a "unique" session id (SID) for the current process.  All events
> + * from this process will have this label.  If we were started by another
> + * git instance, use our parent's SID as a prefix and count the number of
> + * nested git processes.  (This lets us track parent/child relationships
> + * even if there is an intermediate shell process.)

How does this work with threading. From this description we can have
two threads starting new child processes and they have the same ID
(<our id>-2)

> +
> +/*****************************************************************
> + * TODO remove this section header
> + *****************************************************************/

This looks like a reoccurring pattern. Did you have a tool
that needs these? Does the tool want to enforce some level of
documentation on each function?

> +
> +/*
> + * Each thread (including the main thread) has a stack of nested regions.
> + * This is used to indent messages and provide nested perf times.  The
> + * limit here is for simplicity.  Note that the region stack is per-thread
> + * and not per-trace_key.

What are the (nested) regions used for? I would imagine recursive
operations, e.g. unpacking trees? Where am I supposed to read
up on those?

> + */
> +#define TR2_MAX_REGION_NESTING (100)
> +#define TR2_INDENT (2)
> +#define TR2_INDENT_LENGTH(ctx) (((ctx)->nr_open_regions - 1) * TR2_INDENT)

In the structured part of the logging the indentation would not be
needed and we'd rather want to store the nesting level as an int,
this is solely for printing locally I'd assume.

> +#define TR2_MAX_THREAD_NAME (24)

This is the max length for a thread name including all the prefixes?


> +static void tr2tls_unset_self(void)
> +{
> +       struct tr2tls_thread_ctx * ctx;
> +
> +       ctx = tr2tls_get_self();
> +
> +       pthread_setspecific(tr2tls_key, NULL);

Would we also need to free tr2tls_key ?


> +/*****************************************************************
> + * TODO remove this section header
> + *****************************************************************/
> +
> +static void tr2io_write_line(struct trace_key *key, struct strbuf *buf_line)
> +{
> +       strbuf_complete_line(buf_line); /* ensure final NL on buffer */
> +
> +       // TODO we don't really want short-writes to try again when
> +       // TODO we are in append mode...

A different kind of TODO in a // comment?

Re: [PATCH 1/8] trace2: create new combined trace facility

[Junio C Hamano]

Stefan Beller <sbeller@google.com> writes:

>> The API defines both fixed-field and printf-style functions.
>>
>> The trace2 performance tracing includes thread-specific function
>> nesting and timings.
>
> So this only adds the new API, and we need to merge the TRACE
> into the TRACE2 later?

If this is a rhetorical question implying that it would be best if
the existing trace() were rewritten to be built on top of trace2()
while building this series, especially before adding new callsites
that directly use trace2(), I may share that feeling.  I haven't
studied this new round deeply enough to see how realistic it would
be, though.

Re: [PATCH 1/8] trace2: create new combined trace facility

[Jeff Hostetler]

On 9/4/2018 6:30 PM, Junio C Hamano wrote:
> Stefan Beller <sbeller@google.com> writes:
> 
>>> The API defines both fixed-field and printf-style functions.
>>>
>>> The trace2 performance tracing includes thread-specific function
>>> nesting and timings.
>>
>> So this only adds the new API, and we need to merge the TRACE
>> into the TRACE2 later?
> 
> If this is a rhetorical question implying that it would be best if
> the existing trace() were rewritten to be built on top of trace2()
> while building this series, especially before adding new callsites
> that directly use trace2(), I may share that feeling.  I haven't
> studied this new round deeply enough to see how realistic it would
> be, though.
> 
> 

I wanted to come up with a unified API that we liked and was
sufficient to handle the default-key, performance-key,
the new event-key (currently supporting JSON output), and any
other formats/variants that we want (protobufs, syslog, etc).

And hopefully get some agreement on it and see what else we want
from it.

And then look at converting the trace_printf() and trace_performance()
calls to trace2.  Clearly, I could just replace the existing printf
style calls to trace2_printf's, but I thought it would be better to
look at them and promote them to higher-level functions.  For example,
the trace_argv_printf() calls are generally used to dump the command
line arguments for the current process or spawned child processes.
I have trace2_start() and trace2_child_start() that captures the
argv and additional information about it.  (The "why" if you will.)
So the trace_argv_* forms can go away.

Likewise, all of the trace_performance() and trace_performance_since()
can be converted to trace2_region_enter/_leave calls.  And those forms
can be removed from trace.[ch].

The net-net is that trace.[ch] shrinks in a short sequence of commits
on top of my initial trace2 commit in a reroll of this patch series.
(and replacing some of the demonstration commits in V1)

Then I'll address the trace_printf_key() forms, since they write
to alternate stream.

Then I can delete trace.[ch].  And we can consider renaming
trace2_* functions and/or GIT_TR2_* env vars if we want.

I wanted to avoid rewriting trace.[ch] just to delete them later
in the same patch series.

Jeff

Re: [PATCH 1/8] trace2: create new combined trace facility

[Jeff Hostetler]

On 9/4/2018 6:12 PM, Stefan Beller wrote:
>> Create GIT_TR2 trace-key to replace GIT_TRACE, GIT_TR2_PERFORMANCE to
>> replace GIT_TRACE_PERFORMANCE, and a new trace-key GIT_TR2_EVENT to
>> generate JSON data for telemetry purposes.  Other structured formats
>> can easily be added later using this new existing model.
> 
> So the idea is to use the GIT_TR2 instead of GIT_TRACE and we
> get the same output as well as a new form of structured logging here?
> (Then GIT_TRACE could be retired, and we'd use the new API to add
> more events, which are also more structured as the API allows for more
> than just a string printed?)
> 
>> Define a higher-level event API that selectively writes to all of the
>> new GIT_TR2_* targets (depending on event type) without needing to call
>> different trace_printf*() or trace_performance_*() routines.
>>
>> The API defines both fixed-field and printf-style functions.
>>
>> The trace2 performance tracing includes thread-specific function
>> nesting and timings.
> 
> So this only adds the new API, and we need to merge the TRACE
> into the TRACE2 later?
> 
>> +++ b/trace2.c
>> @@ -0,0 +1,1592 @@
> [...]
>> +
>> +/*****************************************************************
>> + * TODO remove this section header
>> + *****************************************************************/
> 
> Yes, please.
> 
>> +/*
>> + * Compute a "unique" session id (SID) for the current process.  All events
>> + * from this process will have this label.  If we were started by another
>> + * git instance, use our parent's SID as a prefix and count the number of
>> + * nested git processes.  (This lets us track parent/child relationships
>> + * even if there is an intermediate shell process.)
> 
> How does this work with threading. From this description we can have
> two threads starting new child processes and they have the same ID
> (<our id>-2)

Threads are not involved here.

A git process computes its own unique session id.  It is constructed
from { [<inherited-parent-sid>], <current-time>, <current-pid> }.
So in the following example, fetch spawned rev-list and gc.  (I've
stripped out fields irrelevant to this discussion.)

"sid":"1536153920286494-12592",
"argv":["C:\\work\\gfw\\git.exe","--exec-path=.","fetch","gh"]

"sid":"1536153920286494-12592/1536153925520530-23024",
"argv":["git","rev-list","--objects","--stdin", ...]

"sid":"1536153920286494-12592/1536153926081533-23992",
"argv":["git","gc","--auto"]

So 2 child processes simultaneously spawned from 2 threads in the
top-level git command, would still have unique SIDs since their PIDs
are unique over the time interval of their execution.

In the above example, if rev-list spawned a child git process, that
child's SID would have 3 components (the prefix that it inherited
plus its own time and pid):
     1536153920286494-12592/1536153925520530-23024/<time>-<pid>

The above model works even if there is a shell command between the
top-level git command and the child git processes.

> 
>> +
>> +/*****************************************************************
>> + * TODO remove this section header
>> + *****************************************************************/
> 
> This looks like a reoccurring pattern. Did you have a tool
> that needs these? Does the tool want to enforce some level of
> documentation on each function?

No, this is just an <hr> that helps me see the different sections
as different sections in the editor and helps me group like items.
I might change that to a group-level comment that describes the
overall concept/purpose of the section.  Either way I'll get rid of
the stars.

> 
>> +
>> +/*
>> + * Each thread (including the main thread) has a stack of nested regions.
>> + * This is used to indent messages and provide nested perf times.  The
>> + * limit here is for simplicity.  Note that the region stack is per-thread
>> + * and not per-trace_key.
> 
> What are the (nested) regions used for? I would imagine recursive
> operations, e.g. unpacking trees? Where am I supposed to read
> up on those?

Unpacking trees would be a good usage. Duy did something similar in a
recent patch series.

Nested regions are intended for perf times.  The 8th patch in
this series demonstrates adding trace2_region_enter() and _leave()
calls inside read_directory_recursive().  The second column here
shows the elapsed time between the _enter and _leave.  (Again, I've
stripped out fields not currently relevant.)

| region_enter |           | status_untracked
| region_enter |           | ..read_directory_recursive:
| region_enter |           | ....read_directory_recursive:.github/
| region_leave |  0.000095 | ....read_directory_recursive:.github/
| region_enter |           | ....read_directory_recursive:block-sha1/
| region_leave |  0.000086 | ....read_directory_recursive:block-sha1/
| region_enter |           | ....read_directory_recursive:builtin/
| region_leave |  0.000716 | ....read_directory_recursive:builtin/
| region_enter |           | ....read_directory_recursive:ci/
| region_enter |           | ......read_directory_recursive:ci/util/
| region_leave |  0.000087 | ......read_directory_recursive:ci/util/
| region_leave |  0.000250 | ....read_directory_recursive:ci/
| region_enter |           | ....read_directory_recursive:compat/
| region_enter |           | 
......read_directory_recursive:compat/nedmalloc/
| region_leave |  0.000128 | 
......read_directory_recursive:compat/nedmalloc/
| region_enter |           | ......read_directory_recursive:compat/poll/
| region_leave |  0.000124 | ......read_directory_recursive:compat/poll/
| region_enter |           | ......read_directory_recursive:compat/regex/
| region_leave |  0.000129 | ......read_directory_recursive:compat/regex/
| region_leave |  0.017700 | ....read_directory_recursive:compat/
...
| region_leave |  0.053924 | ..read_directory_recursive:
| region_leave |  0.054127 | status_untracked

I include the read_directory_recursive() commit as an example of
how the API works.  I consider those particular calls as something
a developer would add while studying a problem, but not keep long term.
The calls in status_untracked() are probably keepers, since it would
compliment the existing warning about untracked file detection taking
too long.

The trace2_data_intmax() and trace2_data_string() routines work with
this nesting (are similarly ".." indented).  I don't have an example
in the V1 patch, but you might want to print the number of files touched
at each step in the recursion, for example.

> 
>> + */
>> +#define TR2_MAX_REGION_NESTING (100)
>> +#define TR2_INDENT (2)
>> +#define TR2_INDENT_LENGTH(ctx) (((ctx)->nr_open_regions - 1) * TR2_INDENT)
> 
> In the structured part of the logging the indentation would not be
> needed and we'd rather want to store the nesting level as an int,
> this is solely for printing locally I'd assume.
> 
>> +#define TR2_MAX_THREAD_NAME (24)
> 
> This is the max length for a thread name including all the prefixes?

A thread name does not have a SID-related prefix.  It is just a number
and a supplied label, such as the name of the thread-proc function.
I clip it for column alignment purposes.  For example, the 6th commit
in the patch series shows it being used in preload_index().  Again, this
is the perf view.

...
| main                     | region_enter |           | preload_index
| th01:preload_thread      | thread_start |           |
| th01:preload_thread      | printf       |           | preload {offset 
      0}{count     567}
| th02:preload_thread      | thread_start |           |
| th02:preload_thread      | printf       |           | preload {offset 
    567}{count     567}
| th03:preload_thread      | thread_start |           |
| th03:preload_thread      | printf       |           | preload {offset 
   1134}{count     567}
| th04:preload_thread      | thread_start |           |
| th04:preload_thread      | printf       |           | preload {offset 
   1701}{count     567}
| th05:preload_thread      | thread_start |           |
| th05:preload_thread      | printf       |           | preload {offset 
   2268}{count     567}
| th06:preload_thread      | thread_start |           |
| th06:preload_thread      | printf       |           | preload {offset 
   2835}{count     562}
| th03:preload_thread      | thread_exit  |  0.034892 |
| th06:preload_thread      | thread_exit  |  0.038585 |
| th04:preload_thread      | thread_exit  |  0.042468 |
| th02:preload_thread      | thread_exit  |  0.042601 |
| th01:preload_thread      | thread_exit  |  0.046107 |
| th05:preload_thread      | thread_exit  |  0.047696 |
| main                     | region_leave |  0.048093 | preload_index
...

This shows interleaved racy messages from each of the 6 threads started
in preload_index().  The thread_exit messages give the elapsed time of
each thread.

The thread_start/thread_exit events implicitly define a region (as
described earlier) so that region_enter, region_leave, and data events
will be ".." indented relative to the thread.  One could image building
a threaded version of status_untracked where read_directory_recursive
is spread across different threads.  The perf tracing here would let
us see timings for each thread.  Granted, the events are interleaved
and therefore racy, but you could post-process that thread-by-thread.

> 
> 
>> +static void tr2tls_unset_self(void)
>> +{
>> +       struct tr2tls_thread_ctx * ctx;
>> +
>> +       ctx = tr2tls_get_self();
>> +
>> +       pthread_setspecific(tr2tls_key, NULL);
> 
> Would we also need to free tr2tls_key ?

I free the ctx for each thread (including the main thread) after
disassociating it from the TLS slot when the thread is ending.

But the TLS slot (tr2tls_key) needs to remain until all the atexit
handler runs.  See tr2tls_release().

> 
> 
>> +/*****************************************************************
>> + * TODO remove this section header
>> + *****************************************************************/
>> +
>> +static void tr2io_write_line(struct trace_key *key, struct strbuf *buf_line)
>> +{
>> +       strbuf_complete_line(buf_line); /* ensure final NL on buffer */
>> +
>> +       // TODO we don't really want short-writes to try again when
>> +       // TODO we are in append mode...
> 
> A different kind of TODO in a // comment?
> 

Sorry, didn't want to forget to actually do it.   :-)

thanks for the review,
Jeff

[PATCH 2/8] trace2: add trace2 to main

[Jeff Hostetler via GitGitGadget]

From: Jeff Hostetler <jeffhost@microsoft.com>

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
---
 compat/mingw.h    | 3 +--
 git-compat-util.h | 7 +++++++
 git.c             | 9 ++++++++-
 repository.c      | 2 ++
 run-command.c     | 8 +++++++-
 run-command.h     | 5 +++++
 usage.c           | 5 +++++
 7 files changed, 35 insertions(+), 4 deletions(-)

diff --git a/compat/mingw.h b/compat/mingw.h
index 571019d0bd..606402faeb 100644
--- a/compat/mingw.h
+++ b/compat/mingw.h
@@ -144,8 +144,7 @@ static inline int fcntl(int fd, int cmd, ...)
 	errno = EINVAL;
 	return -1;
 }
-/* bash cannot reliably detect negative return codes as failure */
-#define exit(code) exit((code) & 0xff)
+
 #define sigemptyset(x) (void)0
 static inline int sigaddset(sigset_t *set, int signum)
 { return 0; }
diff --git a/git-compat-util.h b/git-compat-util.h
index 5f2e90932f..c0901d9ec6 100644
--- a/git-compat-util.h
+++ b/git-compat-util.h
@@ -1219,6 +1219,13 @@ static inline int is_missing_file_error(int errno_)
 
 extern int cmd_main(int, const char **);
 
+/*
+ * Intercept all calls to exit() and route them to trace2 to
+ * optionally emit a message before calling the real exit().
+ */
+int trace2_exit_fl(const char *file, int line, int code);
+#define exit(code) exit(trace2_exit_fl(__FILE__, __LINE__, (code)))
+
 /*
  * You can mark a stack variable with UNLEAK(var) to avoid it being
  * reported as a leak by tools like LSAN or valgrind. The argument
diff --git a/git.c b/git.c
index c27c38738b..cc56279a8c 100644
--- a/git.c
+++ b/git.c
@@ -331,6 +331,8 @@ static int handle_alias(int *argcp, const char ***argv)
 			argv_array_push(&child.args, alias_string + 1);
 			argv_array_pushv(&child.args, (*argv) + 1);
 
+			trace2_alias(alias_command, child.args.argv);
+
 			ret = run_command(&child);
 			if (ret >= 0)   /* normal exit */
 				exit(ret);
@@ -365,6 +367,8 @@ static int handle_alias(int *argcp, const char ***argv)
 		/* insert after command name */
 		memcpy(new_argv + count, *argv + 1, sizeof(char *) * *argcp);
 
+		trace2_alias(alias_command, new_argv);
+
 		*argv = new_argv;
 		*argcp += count - 1;
 
@@ -413,6 +417,7 @@ static int run_builtin(struct cmd_struct *p, int argc, const char **argv)
 		setup_work_tree();
 
 	trace_argv_printf(argv, "trace: built-in: git");
+	trace2_command(p->cmd);
 
 	validate_cache_entries(&the_index);
 	status = p->fn(argc, argv, prefix);
@@ -719,6 +724,8 @@ int cmd_main(int argc, const char **argv)
 			cmd = slash + 1;
 	}
 
+	trace2_start(argv);
+
 	trace_command_performance(argv);
 
 	/*
@@ -782,5 +789,5 @@ int cmd_main(int argc, const char **argv)
 	fprintf(stderr, _("failed to run command '%s': %s\n"),
 		cmd, strerror(errno));
 
-	return 1;
+	return trace2_exit(1);
 }
diff --git a/repository.c b/repository.c
index 5dd1486718..c169f61ccd 100644
--- a/repository.c
+++ b/repository.c
@@ -113,6 +113,8 @@ out:
 void repo_set_worktree(struct repository *repo, const char *path)
 {
 	repo->worktree = real_pathdup(path, 1);
+
+	trace2_worktree(repo->worktree);
 }
 
 static int read_and_verify_repository_format(struct repository_format *format,
diff --git a/run-command.c b/run-command.c
index 84b883c213..e833d9a277 100644
--- a/run-command.c
+++ b/run-command.c
@@ -706,6 +706,7 @@ fail_pipe:
 		cmd->err = fderr[0];
 	}
 
+	trace2_child_start(cmd);
 	trace_run_command(cmd);
 
 	fflush(NULL);
@@ -911,6 +912,8 @@ fail_pipe:
 #endif
 
 	if (cmd->pid < 0) {
+		trace2_child_exit(cmd, -1);
+
 		if (need_in)
 			close_pair(fdin);
 		else if (cmd->in)
@@ -949,13 +952,16 @@ fail_pipe:
 int finish_command(struct child_process *cmd)
 {
 	int ret = wait_or_whine(cmd->pid, cmd->argv[0], 0);
+	trace2_child_exit(cmd, ret);
 	child_process_clear(cmd);
 	return ret;
 }
 
 int finish_command_in_signal(struct child_process *cmd)
 {
-	return wait_or_whine(cmd->pid, cmd->argv[0], 1);
+	int ret = wait_or_whine(cmd->pid, cmd->argv[0], 1);
+	trace2_child_exit(cmd, ret);
+	return ret;
 }
 
 
diff --git a/run-command.h b/run-command.h
index 3932420ec8..a91206b08c 100644
--- a/run-command.h
+++ b/run-command.h
@@ -12,6 +12,11 @@ struct child_process {
 	struct argv_array args;
 	struct argv_array env_array;
 	pid_t pid;
+
+	int trace2_child_id;
+	uint64_t trace2_child_us_start;
+	const char *trace2_child_class;
+
 	/*
 	 * Using .in, .out, .err:
 	 * - Specify 0 for no redirections (child inherits stdin, stdout,
diff --git a/usage.c b/usage.c
index cc803336bd..1838c46d20 100644
--- a/usage.c
+++ b/usage.c
@@ -28,12 +28,17 @@ static NORETURN void usage_builtin(const char *err, va_list params)
 static NORETURN void die_builtin(const char *err, va_list params)
 {
 	vreportf("fatal: ", err, params);
+
+	trace2_error_va(err, params);
+
 	exit(128);
 }
 
 static void error_builtin(const char *err, va_list params)
 {
 	vreportf("error: ", err, params);
+
+	trace2_error_va(err, params);
 }
 
 static void warn_builtin(const char *warn, va_list params)
-- 
gitgitgadget

[PATCH 3/8] trace2: demonstrate trace2 regions in wt-status

[Jeff Hostetler via GitGitGadget]

From: Jeff Hostetler <jeffhost@microsoft.com>

Add trace2_region_enter() and trace2_region_leave() calls around the
various phases of a status scan.  This gives elapsed time for each
phase in the GIT_TR2_PERFORMANCE trace target.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
---
 wt-status.c | 14 ++++++++++++--
 1 file changed, 12 insertions(+), 2 deletions(-)

diff --git a/wt-status.c b/wt-status.c
index 5ffab61015..9e37a73c73 100644
--- a/wt-status.c
+++ b/wt-status.c
@@ -726,13 +726,23 @@ static void wt_status_collect_untracked(struct wt_status *s)
 
 void wt_status_collect(struct wt_status *s)
 {
+	trace2_region_enter("status_worktrees");
 	wt_status_collect_changes_worktree(s);
+	trace2_region_leave("status_worktrees");
 
-	if (s->is_initial)
+	if (s->is_initial) {
+		trace2_region_enter("status_initial");
 		wt_status_collect_changes_initial(s);
-	else
+		trace2_region_leave("status_initial");
+	} else {
+		trace2_region_enter("status_index");
 		wt_status_collect_changes_index(s);
+		trace2_region_leave("status_index");
+	}
+
+	trace2_region_enter("status_untracked");
 	wt_status_collect_untracked(s);
+	trace2_region_leave("status_untracked");
 }
 
 static void wt_longstatus_print_unmerged(struct wt_status *s)
-- 
gitgitgadget

[PATCH 4/8] trace2: demonstrate trace2 child process classification

[Jeff Hostetler via GitGitGadget]

From: Jeff Hostetler <jeffhost@microsoft.com>

Classify editory, pager, and sub-process child processes.
The former two can be used to identify interactive commands,
for example.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
---
 editor.c      | 1 +
 pager.c       | 1 +
 sub-process.c | 1 +
 3 files changed, 3 insertions(+)

diff --git a/editor.c b/editor.c
index 9a9b4e12d1..29707de198 100644
--- a/editor.c
+++ b/editor.c
@@ -66,6 +66,7 @@ int launch_editor(const char *path, struct strbuf *buffer, const char *const *en
 		p.argv = args;
 		p.env = env;
 		p.use_shell = 1;
+		p.trace2_child_class = "editor";
 		if (start_command(&p) < 0)
 			return error("unable to start editor '%s'", editor);
 
diff --git a/pager.c b/pager.c
index a768797fcf..4168460ae9 100644
--- a/pager.c
+++ b/pager.c
@@ -100,6 +100,7 @@ void prepare_pager_args(struct child_process *pager_process, const char *pager)
 	argv_array_push(&pager_process->args, pager);
 	pager_process->use_shell = 1;
 	setup_pager_env(&pager_process->env_array);
+	pager_process->trace2_child_class = "pager";
 }
 
 void setup_pager(void)
diff --git a/sub-process.c b/sub-process.c
index 8d2a1707cf..3f4af93555 100644
--- a/sub-process.c
+++ b/sub-process.c
@@ -88,6 +88,7 @@ int subprocess_start(struct hashmap *hashmap, struct subprocess_entry *entry, co
 	process->out = -1;
 	process->clean_on_exit = 1;
 	process->clean_on_exit_handler = subprocess_exit_handler;
+	process->trace2_child_class = "subprocess";
 
 	err = start_command(process);
 	if (err) {
-- 
gitgitgadget

[PATCH 5/8] trace2: demonstrate instrumenting do_read_index

[Jeff Hostetler via GitGitGadget]

From: Jeff Hostetler <jeffhost@microsoft.com>

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
---
 read-cache.c | 6 ++++++
 1 file changed, 6 insertions(+)

diff --git a/read-cache.c b/read-cache.c
index 7b1354d759..7a31ac4da8 100644
--- a/read-cache.c
+++ b/read-cache.c
@@ -1867,6 +1867,8 @@ static void tweak_split_index(struct index_state *istate)
 
 static void post_read_index_from(struct index_state *istate)
 {
+	trace2_data_intmax("index", "cache_nr", istate->cache_nr);
+
 	check_ce_order(istate);
 	tweak_untracked_cache(istate);
 	tweak_split_index(istate);
@@ -2012,7 +2014,9 @@ int read_index_from(struct index_state *istate, const char *path,
 	if (istate->initialized)
 		return istate->cache_nr;
 
+	trace2_region_enter("do_read_index");
 	ret = do_read_index(istate, path, 0);
+	trace2_region_leave("do_read_index");
 	trace_performance_since(start, "read cache %s", path);
 
 	split_index = istate->split_index;
@@ -2028,7 +2032,9 @@ int read_index_from(struct index_state *istate, const char *path,
 
 	base_oid_hex = oid_to_hex(&split_index->base_oid);
 	base_path = xstrfmt("%s/sharedindex.%s", gitdir, base_oid_hex);
+	trace2_region_enter("do_read_index");
 	ret = do_read_index(split_index->base, base_path, 1);
+	trace2_region_leave("do_read_index");
 	if (oidcmp(&split_index->base_oid, &split_index->base->oid))
 		die("broken index, expect %s in %s, got %s",
 		    base_oid_hex, base_path,
-- 
gitgitgadget

[PATCH 6/8] trace2: demonstrate instrumenting threaded preload_index

[Jeff Hostetler via GitGitGadget]

From: Jeff Hostetler <jeffhost@microsoft.com>

Add trace2_region_enter() and _leave() around the entire preload_index()
call.  Also add thread-specific events in the preload_thread() threadproc.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
---
 preload-index.c | 10 ++++++++++
 1 file changed, 10 insertions(+)

diff --git a/preload-index.c b/preload-index.c
index 71cd2437a3..2483d92c61 100644
--- a/preload-index.c
+++ b/preload-index.c
@@ -40,10 +40,14 @@ static void *preload_thread(void *_data)
 	struct cache_entry **cep = index->cache + p->offset;
 	struct cache_def cache = CACHE_DEF_INIT;
 
+	trace2_thread_start("preload_thread");
+
 	nr = p->nr;
 	if (nr + p->offset > index->cache_nr)
 		nr = index->cache_nr - p->offset;
 
+	trace2_printf("preload {offset %7d}{count %7d}", p->offset, nr);
+
 	do {
 		struct cache_entry *ce = *cep++;
 		struct stat st;
@@ -70,6 +74,9 @@ static void *preload_thread(void *_data)
 		mark_fsmonitor_valid(ce);
 	} while (--nr > 0);
 	cache_def_clear(&cache);
+
+	trace2_thread_exit();
+
 	return NULL;
 }
 
@@ -118,6 +125,9 @@ int read_index_preload(struct index_state *index,
 {
 	int retval = read_index(index);
 
+	trace2_region_enter("preload_index");
 	preload_index(index, pathspec);
+	trace2_region_leave("preload_index");
+
 	return retval;
 }
-- 
gitgitgadget

[PATCH 7/8] trace2: demonstrate setting sub-command parameter in checkout

[Jeff Hostetler via GitGitGadget]

From: Jeff Hostetler <jeffhost@microsoft.com>

Add trace2_param() events in checkout to report whether the command
is switching branches or just checking out a file.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
---
 builtin/checkout.c | 5 +++++
 1 file changed, 5 insertions(+)

diff --git a/builtin/checkout.c b/builtin/checkout.c
index 29ef50013d..0934587781 100644
--- a/builtin/checkout.c
+++ b/builtin/checkout.c
@@ -251,6 +251,8 @@ static int checkout_paths(const struct checkout_opts *opts,
 	int errs = 0;
 	struct lock_file lock_file = LOCK_INIT;
 
+	trace2_param("subcommand", (opts->patch_mode ? "patch" : "path"));
+
 	if (opts->track != BRANCH_TRACK_UNSPECIFIED)
 		die(_("'%s' cannot be used with updating paths"), "--track");
 
@@ -828,6 +830,9 @@ static int switch_branches(const struct checkout_opts *opts,
 	void *path_to_free;
 	struct object_id rev;
 	int flag, writeout_error = 0;
+
+	trace2_param("subcommand", "switch");
+
 	memset(&old_branch_info, 0, sizeof(old_branch_info));
 	old_branch_info.path = path_to_free = resolve_refdup("HEAD", 0, &rev, &flag);
 	if (old_branch_info.path)
-- 
gitgitgadget

[PATCH 8/8] trace2: demonstrate use of regions in read_directory_recursive

[Jeff Hostetler via GitGitGadget]

From: Jeff Hostetler <jeffhost@microsoft.com>

Add trace2_region_enter() and _leave() calls inside read_directory_recursive()
to show nesting and per-level timing.

TODO Drop this commit or ifdef the calls.  It generates too much data to
be in the production version.  It is included in this patch series for
illustration purposes only.  It is typical of what a developer might do
during a perf investigation.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
---
 dir.c | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/dir.c b/dir.c
index aceb0d4869..c7c0654da5 100644
--- a/dir.c
+++ b/dir.c
@@ -1951,6 +1951,8 @@ static enum path_treatment read_directory_recursive(struct dir_struct *dir,
 
 	strbuf_add(&path, base, baselen);
 
+	trace2_region_enter("read_directory_recursive:%.*s", baselen, base);
+
 	if (open_cached_dir(&cdir, dir, untracked, istate, &path, check_only))
 		goto out;
 
@@ -2042,6 +2044,7 @@ static enum path_treatment read_directory_recursive(struct dir_struct *dir,
 	close_cached_dir(&cdir);
  out:
 	strbuf_release(&path);
+	trace2_region_leave("read_directory_recursive:%.*s", baselen, base);
 
 	return dir_state;
 }
-- 
gitgitgadget

Re: [PATCH 0/8] WIP: trace2: a new trace facility

[Derrick Stolee]

On 8/31/2018 12:49 PM, Jeff Hostetler via GitGitGadget wrote:
> This patch series contains a new trace2 facility that hopefully addresses
> the recent trace- and structured-logging-related discussions. The intent is
> to eventually replace the existing trace_ routines (or to route them to the
> new trace2_ routines) as time permits.

I haven't been part of the recent discussions on these logging efforts, 
but I wanted to mention that I'm excited about the potential here. I 
want to use this new tracing model to trace how many commits are walked 
by graph algorithms like paint_down_to_common().

I'm playing with some efforts here, and found one issue when the API is 
used incorrectly (I'll respond to the patch with the issue).

Thanks,

-Stolee

[RFC PATCH 0/6] Use trace2 in commit-reach

[Derrick Stolee]

As promised, here is the direction I took when applying the trace2
feature to the walking code in commit-reach.c. Hence, this depends
on Jeff's trace2 patches and ds/reachable.

There are multiple benefits to the approach I take here:

1. If a user has performance problems, we can rerun the command
   with tracing on and get the region enter/leave notifications
   and the extra data like "num_walked".

2. While I was testing this series against real-world examples,
   I found a number I didn't expect. The numbers for
   can_all_from_reach_with_flags were much higher than I expected.
   Turns out the heuristic I wrote was not working correctly. With
   the trace2 library, I was able to add a "run_and_check_trace2"
   function in test-lib.sh so I could make the number of walked
   commits be a condition we check in the test. Then, the benefit
   we expect is demonstrated by the test suite when I fix the
   bug.

Thanks,
-Stolee

P.S. I'm sending this RFC from gmail because I'm having SMTP issues
with my work email.

Derrick Stolee (6):
  commit-reach: add trace2 telemetry and walk count
  comit-reach: use trace2 for commit_contains_tag_algo
  commit-reach: use trace2 in can_all_from_reach
  test-tool: start trace2 environment
  test-lib: add run_and_check_trace2
  commit-reach: fix first-parent heuristic

 commit-reach.c        | 32 ++++++++++++++++++++++++++++++--
 t/helper/test-tool.c  |  3 +++
 t/t6600-test-reach.sh |  6 ++++++
 t/test-lib.sh         | 14 ++++++++++++++
 4 files changed, 53 insertions(+), 2 deletions(-)

-- 
2.19.0-rc2

[RFC PATCH 1/6] commit-reach: add trace2 telemetry and walk count

[Derrick Stolee]

paint_down_to_common() is used by many Git commands, and sometimes
multiple times in a single call. It is important to measure
performance of this method, but the actual time it takes can vary
due to interactions outside Git's control (file system, CPU
contention, etc.). Instead, count how many times we execute the
while loop, which is consistent between runs.

Signed-off-by: Derrick Stolee <dstolee@microsoft.com>
---
 commit-reach.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/commit-reach.c b/commit-reach.c
index 86715c103c..ee374dce20 100644
--- a/commit-reach.c
+++ b/commit-reach.c
@@ -38,6 +38,9 @@ static struct commit_list *paint_down_to_common(struct commit *one, int n,
 	struct commit_list *result = NULL;
 	int i;
 	uint32_t last_gen = GENERATION_NUMBER_INFINITY;
+	uint32_t num_walked = 0;
+
+	trace2_region_enter("paint_down_to_common");
 
 	one->object.flags |= PARENT1;
 	if (!n) {
@@ -55,6 +58,7 @@ static struct commit_list *paint_down_to_common(struct commit *one, int n,
 		struct commit *commit = prio_queue_get(&queue);
 		struct commit_list *parents;
 		int flags;
+		num_walked++;
 
 		if (commit->generation > last_gen)
 			BUG("bad generation skip %8x > %8x at %s",
@@ -88,6 +92,10 @@ static struct commit_list *paint_down_to_common(struct commit *one, int n,
 	}
 
 	clear_prio_queue(&queue);
+
+	trace2_data_intmax("paint_down_to_common", "num_walked", num_walked);
+	trace2_region_leave("paint_down_to_common");
+
 	return result;
 }
 
-- 
2.19.0.rc2

[RFC PATCH 2/6] comit-reach: use trace2 for commit_contains_tag_algo

[Derrick Stolee]

Signed-off-by: Derrick Stolee <dstolee@microsoft.com>
---
 commit-reach.c | 12 +++++++++++-
 1 file changed, 11 insertions(+), 1 deletion(-)

diff --git a/commit-reach.c b/commit-reach.c
index ee374dce20..0fc3b1ac18 100644
--- a/commit-reach.c
+++ b/commit-reach.c
@@ -481,6 +481,7 @@ static enum contains_result contains_tag_algo(struct commit *candidate,
 	enum contains_result result;
 	uint32_t cutoff = GENERATION_NUMBER_INFINITY;
 	const struct commit_list *p;
+	uint32_t num_walked = 0;
 
 	for (p = want; p; p = p->next) {
 		struct commit *c = p->item;
@@ -493,12 +494,15 @@ static enum contains_result contains_tag_algo(struct commit *candidate,
 	if (result != CONTAINS_UNKNOWN)
 		return result;
 
+	trace2_region_enter("contains_tag_algo");
 	push_to_contains_stack(candidate, &contains_stack);
 	while (contains_stack.nr) {
 		struct contains_stack_entry *entry = &contains_stack.contains_stack[contains_stack.nr - 1];
 		struct commit *commit = entry->commit;
 		struct commit_list *parents = entry->parents;
 
+		num_walked++;
+
 		if (!parents) {
 			*contains_cache_at(cache, commit) = CONTAINS_NO;
 			contains_stack.nr--;
@@ -521,7 +525,13 @@ static enum contains_result contains_tag_algo(struct commit *candidate,
 		}
 	}
 	free(contains_stack.contains_stack);
-	return contains_test(candidate, want, cache, cutoff);
+
+	result = contains_test(candidate, want, cache, cutoff);
+
+	trace2_data_intmax("contains_tag_algo", "num_walked", num_walked);
+	trace2_region_leave("contains_tag_algo");
+
+	return result;
 }
 
 int commit_contains(struct ref_filter *filter, struct commit *commit,
-- 
2.19.0.rc2

[RFC PATCH 3/6] commit-reach: use trace2 in can_all_from_reach

[Derrick Stolee]

Signed-off-by: Derrick Stolee <dstolee@microsoft.com>
---
 commit-reach.c | 8 ++++++++
 1 file changed, 8 insertions(+)

diff --git a/commit-reach.c b/commit-reach.c
index 0fc3b1ac18..0a75644653 100644
--- a/commit-reach.c
+++ b/commit-reach.c
@@ -563,6 +563,7 @@ int can_all_from_reach_with_flag(struct object_array *from,
 	struct commit **list = NULL;
 	int i;
 	int result = 1;
+	uint32_t num_walked = 0;
 
 	ALLOC_ARRAY(list, from->nr);
 	for (i = 0; i < from->nr; i++) {
@@ -573,6 +574,8 @@ int can_all_from_reach_with_flag(struct object_array *from,
 			return 0;
 	}
 
+	trace2_region_enter("can_all_from_reach_with_flag");
+
 	QSORT(list, from->nr, compare_commits_by_gen);
 
 	for (i = 0; i < from->nr; i++) {
@@ -590,6 +593,8 @@ int can_all_from_reach_with_flag(struct object_array *from,
 				continue;
 			}
 
+			num_walked++;
+
 			for (parent = stack->item->parents; parent; parent = parent->next) {
 				if (parent->item->object.flags & (with_flag | RESULT))
 					stack->item->object.flags |= RESULT;
@@ -622,6 +627,9 @@ int can_all_from_reach_with_flag(struct object_array *from,
 		clear_commit_marks(list[i], RESULT);
 		clear_commit_marks(list[i], assign_flag);
 	}
+
+	trace2_data_intmax("can_all_from_reach_with_flag", "num_walked", num_walked);
+	trace2_region_leave("can_all_from_reach_with_flag");
 	return result;
 }
 
-- 
2.19.0.rc2

[RFC PATCH 4/6] test-tool: start trace2 environment

[Derrick Stolee]

Signed-off-by: Derrick Stolee <dstolee@microsoft.com>
---
 t/helper/test-tool.c | 3 +++
 1 file changed, 3 insertions(+)

diff --git a/t/helper/test-tool.c b/t/helper/test-tool.c
index 7566b0786a..f70d5d74f8 100644
--- a/t/helper/test-tool.c
+++ b/t/helper/test-tool.c
@@ -1,5 +1,6 @@
 #include "git-compat-util.h"
 #include "test-tool.h"
+#include "trace2.h"
 
 struct test_cmd {
 	const char *name;
@@ -55,6 +56,8 @@ int cmd_main(int argc, const char **argv)
 	if (argc < 2)
 		die("I need a test name!");
 
+	trace2_start(argv);
+
 	for (i = 0; i < ARRAY_SIZE(cmds); i++) {
 		if (!strcmp(cmds[i].name, argv[1])) {
 			argv++;
-- 
2.19.0.rc2

[RFC PATCH 5/6] test-lib: add run_and_check_trace2

[Derrick Stolee]

The trace2 facility allows tracing category-key-value triples that
we can use to communicate runtime information to a side channel.
One use is to track the number of commits that are walked by a
graph algorithm.

Add run_and_check_trace2 test function to run a given command with
GIT_TR2_PERFORMANCE running. Then, check the output for the
expected category-key-value triple.

Use this function in t6600-test-reach.sh to verify can_all_from_reach
only visits 11 commits in the example.

Signed-off-by: Derrick Stolee <dstolee@microsoft.com>
---
 t/t6600-test-reach.sh |  6 ++++++
 t/test-lib.sh         | 14 ++++++++++++++
 2 files changed, 20 insertions(+)

diff --git a/t/t6600-test-reach.sh b/t/t6600-test-reach.sh
index d139a00d1d..98ad25bb45 100755
--- a/t/t6600-test-reach.sh
+++ b/t/t6600-test-reach.sh
@@ -183,6 +183,12 @@ test_expect_success 'can_all_from_reach:hit' '
 	test_three_modes can_all_from_reach
 '
 
+test_expect_success 'can_all_from_reach:perf' '
+	cp commit-graph-full .git/objects/info/commit-graph &&
+	run_and_check_trace2 can_all_from_reach_with_flag num_walked 40 input \
+		"test-tool reach can_all_from_reach"
+'
+
 test_expect_success 'can_all_from_reach:miss' '
 	cat >input <<-\EOF &&
 	X:commit-2-10
diff --git a/t/test-lib.sh b/t/test-lib.sh
index 8bb0f4348e..9b9f68f324 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -1231,3 +1231,17 @@ test_lazy_prereq CURL '
 test_lazy_prereq SHA1 '
 	test $(git hash-object /dev/null) = e69de29bb2d1d6434b8b29ae775ad8c2e48c5391
 '
+
+# Useage: run_and_check_trace2 <category> <key> <value> <file> <command>
+# Run "command <file" with GIT_TR2_PERFORMANCE logging to a file and
+# check that file for a data output matching category.key = value.
+run_and_check_trace2 () {
+	CATEGORY=$1
+	KEY=$2
+	VALUE=$3
+	INPUT=$4
+	COMMAND=$5
+	# GIT_TR2_PERFORMANCE="$(pwd)/perf-log.txt"
+	GIT_TR2_PERFORMANCE="$(pwd)/perf-log.txt" $COMMAND <$INPUT &&
+	cat perf-log.txt | grep "category:$CATEGORY key:$KEY value:$VALUE"
+}
-- 
2.19.0.rc2

[RFC PATCH 6/6] commit-reach: fix first-parent heuristic

[Derrick Stolee]

The algorithm in can_all_from_reach_with_flags() performs a depth-
first-search, terminated by generation number, intending to use
a hueristic that "important" commits are found in the first-parent
history. This heuristic is valuable in scenarios like fetch
negotiation.

However, there is a problem! After the search finds a target commit,
it should pop all commits off the stack and mark them as "can reach".
This logic is incorrect, so the algorithm instead walks all reachable
commits above the generation-number cutoff.

The existing algorithm is still an improvement over the previous
algorithm, as the worst-case complexity went from quadratic to linear.
The performance measurement at the time was good, but not dramatic.

By fixing this heuristic, we can see in t6600-test-reach.sh that we
reduce the number of walked commits. This test will prevent a future
performance regression.

We can also re-run the performance tests from commit 4fbcca4e
"commit-reach: make can_all_from_reach... linear".

Performance was measured on the Linux repository using
'test-tool reach can_all_from_reach'. The input included rows seeded by
tag values. The "small" case included X-rows as v4.[0-9]* and Y-rows as
v3.[0-9]*. This mimics a (very large) fetch that says "I have all major
v3 releases and want all major v4 releases." The "large" case included
X-rows as "v4.*" and Y-rows as "v3.*". This adds all release-candidate
tags to the set, which does not greatly increase the number of objects
that are considered, but does increase the number of 'from' commits,
demonstrating the quadratic nature of the previous code.

Small Case:

4fbcca4e~1: 0.85 s
  4fbcca4e: 0.26 s (num_walked: 1,011,035)
      HEAD: 0.14 s (num_walked:     8,601)

Large Case:

4fbcca4e~1: 24.0 s
  4fbcca4e:  0.12 s (num_walked:  503,925)
      HEAD:  0.06 s (num_walked:  217,243)

Signed-off-by: Derrick Stolee <dstolee@microsoft.com>
---
 commit-reach.c        | 4 +++-
 t/t6600-test-reach.sh | 2 +-
 2 files changed, 4 insertions(+), 2 deletions(-)

diff --git a/commit-reach.c b/commit-reach.c
index 0a75644653..bd009260b0 100644
--- a/commit-reach.c
+++ b/commit-reach.c
@@ -588,8 +588,10 @@ int can_all_from_reach_with_flag(struct object_array *from,
 		while (stack) {
 			struct commit_list *parent;
 
-			if (stack->item->object.flags & with_flag) {
+			if (stack->item->object.flags & (with_flag | RESULT)) {
 				pop_commit(&stack);
+				if (stack)
+					stack->item->object.flags |= RESULT;
 				continue;
 			}
 
diff --git a/t/t6600-test-reach.sh b/t/t6600-test-reach.sh
index 98ad25bb45..5e231a5955 100755
--- a/t/t6600-test-reach.sh
+++ b/t/t6600-test-reach.sh
@@ -185,7 +185,7 @@ test_expect_success 'can_all_from_reach:hit' '
 
 test_expect_success 'can_all_from_reach:perf' '
 	cp commit-graph-full .git/objects/info/commit-graph &&
-	run_and_check_trace2 can_all_from_reach_with_flag num_walked 40 input \
+	run_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input \
 		"test-tool reach can_all_from_reach"
 '
 
-- 
2.19.0.rc2

Re: [RFC PATCH 6/6] commit-reach: fix first-parent heuristic

[Jonathan Nieder]

Hi,

Derrick Stolee wrote:

>  commit-reach.c        | 4 +++-
>  t/t6600-test-reach.sh | 2 +-
>  2 files changed, 4 insertions(+), 2 deletions(-)

I like this testing technique, and the test passes for me.

Except: if I put

	CC = cc -m32
	NO_OPENSSL = YesPlease
	NO_CURL = YesPlease

in config.mak (the first line to force 32-bit pointers, the others
to avoid some dependencies on libs that I don't have 32-bit versions
of), then the test fails for me:

 $ ./t6600-test-reach.sh -v -x -i
 [...]
 expecting success:
         cp commit-graph-full .git/objects/info/commit-graph &&
         run_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input \
                 "test-tool reach can_all_from_reach"

 ++ cp commit-graph-full .git/objects/info/commit-graph
 ++ run_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input 'test-tool reach can_all_from_r
 each'
 ++ CATEGORY=can_all_from_reach_with_flag
 ++ KEY=num_walked
 ++ VALUE=19
 ++ INPUT=input
 ++ COMMAND='test-tool reach can_all_from_reach'
 +++ pwd
 ++ GIT_TR2_PERFORMANCE='/usr/local/google/home/jrn/src/git/t/trash directory.t6600-test-reach/perf-log.t
 xt'
 ++ test-tool reach can_all_from_reach
 can_all_from_reach(X,Y):1
 ++ cat perf-log.txt
 ++ grep 'category:can_all_from_reach_with_flag key:num_walked value:19'
 error: last command exited with $?=1
 not ok 11 - can_all_from_reach:perf
 #
 #               cp commit-graph-full .git/objects/info/commit-graph &&
 #               run_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input \
 #                       "test-tool reach can_all_from_reach"
 #

When I cat perf-log.txt, I see

  ..category:can_all_from_reach_with_flag key:num_walked value:20

instead of the expected 19.

Known issue?

Thanks,
Jonathan

Re: [RFC PATCH 6/6] commit-reach: fix first-parent heuristic

[Derrick Stolee]

On 10/10/2018 9:50 PM, Jonathan Nieder wrote:
> Hi,
>
> Derrick Stolee wrote:
>
>>   commit-reach.c        | 4 +++-
>>   t/t6600-test-reach.sh | 2 +-
>>   2 files changed, 4 insertions(+), 2 deletions(-)
> I like this testing technique, and the test passes for me.
>
> Except: if I put
>
> 	CC = cc -m32
> 	NO_OPENSSL = YesPlease
> 	NO_CURL = YesPlease
>
> in config.mak (the first line to force 32-bit pointers, the others
> to avoid some dependencies on libs that I don't have 32-bit versions
> of), then the test fails for me:
>
>   $ ./t6600-test-reach.sh -v -x -i
>   [...]
>   expecting success:
>           cp commit-graph-full .git/objects/info/commit-graph &&
>           run_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input \
>                   "test-tool reach can_all_from_reach"
>
>   ++ cp commit-graph-full .git/objects/info/commit-graph
>   ++ run_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input 'test-tool reach can_all_from_r
>   each'
>   ++ CATEGORY=can_all_from_reach_with_flag
>   ++ KEY=num_walked
>   ++ VALUE=19
>   ++ INPUT=input
>   ++ COMMAND='test-tool reach can_all_from_reach'
>   +++ pwd
>   ++ GIT_TR2_PERFORMANCE='/usr/local/google/home/jrn/src/git/t/trash directory.t6600-test-reach/perf-log.t
>   xt'
>   ++ test-tool reach can_all_from_reach
>   can_all_from_reach(X,Y):1
>   ++ cat perf-log.txt
>   ++ grep 'category:can_all_from_reach_with_flag key:num_walked value:19'
>   error: last command exited with $?=1
>   not ok 11 - can_all_from_reach:perf
>   #
>   #               cp commit-graph-full .git/objects/info/commit-graph &&
>   #               run_and_check_trace2 can_all_from_reach_with_flag num_walked 19 input \
>   #                       "test-tool reach can_all_from_reach"
>   #
>
> When I cat perf-log.txt, I see
>
>    ..category:can_all_from_reach_with_flag key:num_walked value:20
>
> instead of the expected 19.
It is possible this is related to the sort-order problem reported and 
fixed by Rene [1]. I'll look into it in any case.

[1] 
https://public-inbox.org/git/dca35e44-a763-bcf0-f457-b8dab53815cf@web.de/

Re: [PATCH 0/8] WIP: trace2: a new trace facility

[Jonathan Nieder]

Hi,

Jeff Hostetler wrote:

> This patch series contains a new trace2 facility that hopefully addresses
> the recent trace- and structured-logging-related discussions. The intent is
> to eventually replace the existing trace_ routines (or to route them to the
> new trace2_ routines) as time permits.

I've been running with these patches since last October.  A few
thoughts:

I like the API.

The logs are a bit noisy and especially wide.  For my use, the
function name is not too important since we can get that from the file
and line number.  Should we have a way to omit some fields, or is that
for post-processing?

We don't find the JSON easy to parse and would prefer a binary format.

When I apply the patches, Git complains about whitespace problems
(trailing whitespace, etc).

Aside from that kind of easily correctible issue (trailing
whitespace), I'd be in favor of taking these patches pretty much as-is
and making improvements in tree.  Any objections to that, or do you
have other thoughts on where this should go?

If that sounds reasonable to you, I can send a clean version of these
based against current "master".  If I understand correctly, then

 https://github.com/jeffhostetler/git

branch

 gvfs-trace2-v4

contains some improvements, so as a next step I'd try to extract those
as incremental patches on top.  What do you think?

Thanks,
Jonathan

Re: [PATCH 0/8] WIP: trace2: a new trace facility

[Jeff Hostetler]

On 1/14/2019 8:05 PM, Jonathan Nieder wrote:
> Hi,
> 
> Jeff Hostetler wrote:
> 
>> This patch series contains a new trace2 facility that hopefully addresses
>> the recent trace- and structured-logging-related discussions. The intent is
>> to eventually replace the existing trace_ routines (or to route them to the
>> new trace2_ routines) as time permits.
> 
> I've been running with these patches since last October.  A few
> thoughts:
> 
> I like the API.

Great, thanks.  Hopefully you're getting some good/actionable data from
it.


> The logs are a bit noisy and especially wide.  For my use, the
> function name is not too important since we can get that from the file
> and line number.  Should we have a way to omit some fields, or is that
> for post-processing?

Yes, the events are a little wide and noisy, at least in this draft.

Part of this is to flesh out the trace2 API (which should be relatively
fixed) and make sure we have enough event types to emit useful
information.  This is independent of some of the detail events (like
region/data events within status or index reading/writing). Some of
those detail events might be kept if they're useful or temporary
demonstration events or events you could include in a private build for
a limited period of time.  So some of the noise might be those
demonstration events (stuff that you'd want for testing in a perf view,
but not need archived, for example).

Also, for the events that have a "category" field, I'd eventually
like to have a filter setting to include/omit them.  This is something
like the GIT_TRACE_<name> feature we currently have, but limited to
always writing to the same file.  I had this in an earlier version,
but haven't brought it over yet.

And yes, I have a post-processing step that filters fields and
generates a summary record for each process instance.  My previous
draft tried to do that summary inside the git.exe process and it was
suggested that we move that out, so this version emits the raw data
as it occurs and I get the summary after the fact.  This has turned
out nicely, even if the Trace2 stream is a little noisy.

There are some fields that I'd like to omit from my JSON stream that
I'm not using in my summary, such as the filename and line number.
These got carried along since the PERF view needed them.  I think they
make sense in the PERF view, but not so much in the EVENT view.
I'm filtering them out in my post-processing, but I think we could
just omit them.


> We don't find the JSON easy to parse and would prefer a binary format.

I'm going to have to push back a little on this one.  JSON is easy to
process in PERL, C#, various databases, and etc.  Processing a non-text
format in bash is just asking for pain and suffering.

Can you elaborate on the problems you're having with JSON?

When you say "binary" what kind of binary do you mean?  Is this BSON?
Or are you suggesting protocol buffers?  If the latter, is there a C
binding for that? (Every example I've seen talks about C++.)

In my gvfs-trace2-v4 branch, I've refactored the code and now have
a vtable-like mechanism that allows multiple Trace2 "targets" to be
defined.  See trace2/tr2_tgt_perf.c vs trace2/tr2_tgt_events.c.  The
former generates the GIT_TR2_PERF view and the latter generates the
JSON event view.

You could add a self-contained target vtable that generates a binary
view if you wanted.  (Just let it key off of a different GIT_TR2_
environment variable.)


> When I apply the patches, Git complains about whitespace problems
> (trailing whitespace, etc).
> 
> Aside from that kind of easily correctible issue (trailing
> whitespace), I'd be in favor of taking these patches pretty much as-is
> and making improvements in tree.  Any objections to that, or do you
> have other thoughts on where this should go?
> 
> If that sounds reasonable to you, I can send a clean version of these
> based against current "master".  If I understand correctly, then
> 
>   https://github.com/jeffhostetler/git
> 
> branch
> 
>   gvfs-trace2-v4
> 
> contains some improvements, so as a next step I'd try to extract those
> as incremental patches on top.  What do you think?
> 
> Thanks,
> Jonathan

The gvfs-trace2-v4 version has lots of improvements over the version
I last posted on the mailing list.  We should go with it.

I'm not surprised that there are merge conflicts, since mine is based
upon the recent GVFS release and has some gvfs-specific commits in it.

Let me rebase that branch onto the upstream/master and clean up the
mess and send out another patch set.

Hopefully, I can get that out tomorrow.

Jeff