trace2: create new combined trace facility

Create a new unified tracing facility for git.  The eventual intent is to
replace the current trace_printf* and trace_performance* routines with a
unified set of git_trace2* routines.

In addition to the usual printf-style API, trace2 provides higer-level
event verbs with fixed-fields allowing structured data to be written.
This makes post-processing and analysis easier for external tools.

Trace2 defines 3 output targets.  These are set using the environment
variables "GIT_TR2", "GIT_TR2_PERF", and "GIT_TR2_EVENT".  These may be
set to "1" or to an absolute pathname (just like the current GIT_TRACE).

* GIT_TR2 is intended to be a replacement for GIT_TRACE and logs command
  summary data.

* GIT_TR2_PERF is intended as a replacement for GIT_TRACE_PERFORMANCE.
  It extends the output with columns for the command process, thread,
  repo, absolute and relative elapsed times.  It reports events for
  child process start/stop, thread start/stop, and per-thread function
  nesting.

* GIT_TR2_EVENT is a new structured format. It writes event data as a
  series of JSON records.

Calls to trace2 functions log to any of the 3 output targets enabled
without the need to call different trace_printf* or trace_performance*
routines.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>

1 files changed, 534 insertions, 0 deletions

diff --git a/trace2/tr2_tgt_perf.c b/trace2/tr2_tgt_perf.c
new file mode 100644
index 0000000000..f0746fcf86
--- /dev/null
+++ b/trace2/tr2_tgt_perf.c
@@ -0,0 +1,534 @@
+#include "cache.h"
+#include "config.h"
+#include "run-command.h"
+#include "quote.h"
+#include "version.h"
+#include "json-writer.h"
+#include "trace2/tr2_dst.h"
+#include "trace2/tr2_sid.h"
+#include "trace2/tr2_tbuf.h"
+#include "trace2/tr2_tgt.h"
+#include "trace2/tr2_tls.h"
+
+static struct tr2_dst tr2dst_perf = { "GIT_TR2_PERF", 0, 0, 0 };
+
+/*
+ * Set this environment variable to true to omit the "<time> <file>:<line>"
+ * fields from each line written to the builtin performance target.
+ *
+ * Unit tests may want to use this to help with testing.
+ */
+#define TR2_ENVVAR_PERF_BRIEF "GIT_TR2_PERF_BRIEF"
+static int tr2env_perf_brief;
+
+#define TR2FMT_PERF_FL_WIDTH (50)
+#define TR2FMT_PERF_MAX_EVENT_NAME (12)
+#define TR2FMT_PERF_REPO_WIDTH (4)
+#define TR2FMT_PERF_CATEGORY_WIDTH (10)
+
+#define TR2_DOTS_BUFFER_SIZE (100)
+#define TR2_INDENT (2)
+#define TR2_INDENT_LENGTH(ctx) (((ctx)->nr_open_regions - 1) * TR2_INDENT)
+
+static struct strbuf dots = STRBUF_INIT;
+
+static int fn_init(void)
+{
+	int want = tr2_dst_trace_want(&tr2dst_perf);
+	int want_brief;
+	char *brief;
+
+	if (!want)
+		return want;
+
+	strbuf_addchars(&dots, '.', TR2_DOTS_BUFFER_SIZE);
+
+	brief = getenv(TR2_ENVVAR_PERF_BRIEF);
+	if (brief && *brief &&
+	    ((want_brief = git_parse_maybe_bool(brief)) != -1))
+		tr2env_perf_brief = want_brief;
+
+	return want;
+}
+
+static void fn_term(void)
+{
+	tr2_dst_trace_disable(&tr2dst_perf);
+
+	strbuf_release(&dots);
+}
+
+/*
+ * Format trace line prefix in human-readable classic format for
+ * the performance target:
+ *     "[<time> [<file>:<line>] <bar>] <nr_parents> <bar>
+ *         <thread_name> <bar> <event_name> <bar> [<repo>] <bar>
+ *         [<elapsed_absolute>] [<elapsed_relative>] <bar>
+ *         [<category>] <bar> [<dots>] "
+ */
+static void perf_fmt_prepare(const char *event_name,
+			     struct tr2tls_thread_ctx *ctx, const char *file,
+			     int line, const struct repository *repo,
+			     uint64_t *p_us_elapsed_absolute,
+			     uint64_t *p_us_elapsed_relative,
+			     const char *category, struct strbuf *buf)
+{
+	int len;
+
+	strbuf_setlen(buf, 0);
+
+	if (!tr2env_perf_brief) {
+		struct tr2_tbuf tb_now;
+
+		tr2_tbuf_local_time(&tb_now);
+		strbuf_addstr(buf, tb_now.buf);
+		strbuf_addch(buf, ' ');
+
+		if (file && *file)
+			strbuf_addf(buf, "%s:%d ", file, line);
+		while (buf->len < TR2FMT_PERF_FL_WIDTH)
+			strbuf_addch(buf, ' ');
+
+		strbuf_addstr(buf, "| ");
+	}
+
+	strbuf_addf(buf, "d%d | ", tr2_sid_depth());
+	strbuf_addf(buf, "%-*s | %-*s | ", TR2_MAX_THREAD_NAME,
+		    ctx->thread_name.buf, TR2FMT_PERF_MAX_EVENT_NAME,
+		    event_name);
+
+	len = buf->len + TR2FMT_PERF_REPO_WIDTH;
+	if (repo)
+		strbuf_addf(buf, "r%d ", repo->trace2_repo_id);
+	while (buf->len < len)
+		strbuf_addch(buf, ' ');
+	strbuf_addstr(buf, "| ");
+
+	if (p_us_elapsed_absolute)
+		strbuf_addf(buf, "%9.6f | ",
+			    ((double)(*p_us_elapsed_absolute)) / 1000000.0);
+	else
+		strbuf_addf(buf, "%9s | ", " ");
+
+	if (p_us_elapsed_relative)
+		strbuf_addf(buf, "%9.6f | ",
+			    ((double)(*p_us_elapsed_relative)) / 1000000.0);
+	else
+		strbuf_addf(buf, "%9s | ", " ");
+
+	strbuf_addf(buf, "%-*s | ", TR2FMT_PERF_CATEGORY_WIDTH,
+		    (category ? category : ""));
+
+	if (ctx->nr_open_regions > 0) {
+		int len_indent = TR2_INDENT_LENGTH(ctx);
+		while (len_indent > dots.len) {
+			strbuf_addbuf(buf, &dots);
+			len_indent -= dots.len;
+		}
+		strbuf_addf(buf, "%.*s", len_indent, dots.buf);
+	}
+}
+
+static void perf_io_write_fl(const char *file, int line, const char *event_name,
+			     const struct repository *repo,
+			     uint64_t *p_us_elapsed_absolute,
+			     uint64_t *p_us_elapsed_relative,
+			     const char *category,
+			     const struct strbuf *buf_payload)
+{
+	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+	struct strbuf buf_line = STRBUF_INIT;
+
+	perf_fmt_prepare(event_name, ctx, file, line, repo,
+			 p_us_elapsed_absolute, p_us_elapsed_relative, category,
+			 &buf_line);
+	strbuf_addbuf(&buf_line, buf_payload);
+	tr2_dst_write_line(&tr2dst_perf, &buf_line);
+	strbuf_release(&buf_line);
+}
+
+static void fn_version_fl(const char *file, int line)
+{
+	const char *event_name = "version";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addstr(&buf_payload, git_version_string);
+
+	perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
+			 &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_start_fl(const char *file, int line, const char **argv)
+{
+	const char *event_name = "start";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	sq_quote_argv_pretty(&buf_payload, argv);
+
+	perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
+			 &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute,
+		       int code)
+{
+	const char *event_name = "exit";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addf(&buf_payload, "code:%d", code);
+
+	perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
+			 NULL, NULL, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_signal(uint64_t us_elapsed_absolute, int signo)
+{
+	const char *event_name = "signal";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addf(&buf_payload, "signo:%d", signo);
+
+	perf_io_write_fl(__FILE__, __LINE__, event_name, NULL,
+			 &us_elapsed_absolute, NULL, NULL, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_atexit(uint64_t us_elapsed_absolute, int code)
+{
+	const char *event_name = "atexit";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addf(&buf_payload, "code:%d", code);
+
+	perf_io_write_fl(__FILE__, __LINE__, event_name, NULL,
+			 &us_elapsed_absolute, NULL, NULL, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void maybe_append_string_va(struct strbuf *buf, const char *fmt,
+				   va_list ap)
+{
+	if (fmt && *fmt && ap) {
+		va_list copy_ap;
+
+		va_copy(copy_ap, ap);
+		strbuf_vaddf(buf, fmt, copy_ap);
+		va_end(copy_ap);
+		return;
+	}
+
+	if (fmt && *fmt) {
+		strbuf_addstr(buf, fmt);
+		return;
+	}
+}
+
+static void fn_error_va_fl(const char *file, int line, const char *fmt,
+			   va_list ap)
+{
+	const char *event_name = "error";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	maybe_append_string_va(&buf_payload, fmt, ap);
+
+	perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
+			 &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_command_path_fl(const char *file, int line, const char *pathname)
+{
+	const char *event_name = "cmd_path";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addstr(&buf_payload, pathname);
+
+	perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
+			 &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_command_name_fl(const char *file, int line, const char *name,
+			       const char *hierarchy)
+{
+	const char *event_name = "cmd_name";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addstr(&buf_payload, name);
+	if (hierarchy && *hierarchy)
+		strbuf_addf(&buf_payload, " (%s)", hierarchy);
+
+	perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
+			 &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_command_mode_fl(const char *file, int line, const char *mode)
+{
+	const char *event_name = "cmd_mode";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addstr(&buf_payload, mode);
+
+	perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
+			 &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_alias_fl(const char *file, int line, const char *alias,
+			const char **argv)
+{
+	const char *event_name = "alias";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addf(&buf_payload, "alias:%s argv:", alias);
+	sq_quote_argv_pretty(&buf_payload, argv);
+
+	perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
+			 &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_child_start_fl(const char *file, int line,
+			      uint64_t us_elapsed_absolute,
+			      const struct child_process *cmd)
+{
+	const char *event_name = "child_start";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	if (cmd->trace2_hook_name) {
+		strbuf_addf(&buf_payload, "[ch%d] class:hook hook:%s",
+			    cmd->trace2_child_id, cmd->trace2_hook_name);
+	} else {
+		const char *child_class =
+			cmd->trace2_child_class ? cmd->trace2_child_class : "?";
+		strbuf_addf(&buf_payload, "[ch%d] class:%s",
+			    cmd->trace2_child_id, child_class);
+	}
+
+	if (cmd->dir) {
+		strbuf_addstr(&buf_payload, " cd:");
+		sq_quote_buf_pretty(&buf_payload, cmd->dir);
+	}
+
+	strbuf_addstr(&buf_payload, " argv:");
+	if (cmd->git_cmd)
+		strbuf_addstr(&buf_payload, " git");
+	sq_quote_argv_pretty(&buf_payload, cmd->argv);
+
+	perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
+			 NULL, NULL, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_child_exit_fl(const char *file, int line,
+			     uint64_t us_elapsed_absolute, int cid, int pid,
+			     int code, uint64_t us_elapsed_child)
+{
+	const char *event_name = "child_exit";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addf(&buf_payload, "[ch%d] pid:%d code:%d", cid, pid, code);
+
+	perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
+			 &us_elapsed_child, NULL, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_thread_start_fl(const char *file, int line,
+			       uint64_t us_elapsed_absolute)
+{
+	const char *event_name = "thread_start";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
+			 NULL, NULL, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_thread_exit_fl(const char *file, int line,
+			      uint64_t us_elapsed_absolute,
+			      uint64_t us_elapsed_thread)
+{
+	const char *event_name = "thread_exit";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
+			 &us_elapsed_thread, NULL, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute,
+		       int exec_id, const char *exe, const char **argv)
+{
+	const char *event_name = "exec";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addf(&buf_payload, "id:%d ", exec_id);
+	strbuf_addstr(&buf_payload, "argv:");
+	if (exe)
+		strbuf_addf(&buf_payload, " %s", exe);
+	sq_quote_argv_pretty(&buf_payload, argv);
+
+	perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
+			 NULL, NULL, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_exec_result_fl(const char *file, int line,
+			      uint64_t us_elapsed_absolute, int exec_id,
+			      int code)
+{
+	const char *event_name = "exec_result";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addf(&buf_payload, "id:%d code:%d", exec_id, code);
+	if (code > 0)
+		strbuf_addf(&buf_payload, " err:%s", strerror(code));
+
+	perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
+			 NULL, NULL, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_param_fl(const char *file, int line, const char *param,
+			const char *value)
+{
+	const char *event_name = "def_param";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addf(&buf_payload, "%s:%s", param, value);
+
+	perf_io_write_fl(file, line, event_name, NULL, NULL, NULL, NULL,
+			 &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_repo_fl(const char *file, int line,
+		       const struct repository *repo)
+{
+	const char *event_name = "def_repo";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addstr(&buf_payload, "worktree:");
+	sq_quote_buf_pretty(&buf_payload, repo->worktree);
+
+	perf_io_write_fl(file, line, event_name, repo, NULL, NULL, NULL,
+			 &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_region_enter_printf_va_fl(const char *file, int line,
+					 uint64_t us_elapsed_absolute,
+					 const char *category,
+					 const char *label,
+					 const struct repository *repo,
+					 const char *fmt, va_list ap)
+{
+	const char *event_name = "region_enter";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	if (label)
+		strbuf_addf(&buf_payload, "label:%s ", label);
+	maybe_append_string_va(&buf_payload, fmt, ap);
+
+	perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
+			 NULL, category, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_region_leave_printf_va_fl(
+	const char *file, int line, uint64_t us_elapsed_absolute,
+	uint64_t us_elapsed_region, const char *category, const char *label,
+	const struct repository *repo, const char *fmt, va_list ap)
+{
+	const char *event_name = "region_leave";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	if (label)
+		strbuf_addf(&buf_payload, "label:%s ", label);
+	maybe_append_string_va(&buf_payload, fmt, ap);
+
+	perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
+			 &us_elapsed_region, category, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_data_fl(const char *file, int line, uint64_t us_elapsed_absolute,
+		       uint64_t us_elapsed_region, const char *category,
+		       const struct repository *repo, const char *key,
+		       const char *value)
+{
+	const char *event_name = "data";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addf(&buf_payload, "%s:%s", key, value);
+
+	perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
+			 &us_elapsed_region, category, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_data_json_fl(const char *file, int line,
+			    uint64_t us_elapsed_absolute,
+			    uint64_t us_elapsed_region, const char *category,
+			    const struct repository *repo, const char *key,
+			    const struct json_writer *value)
+{
+	const char *event_name = "data_json";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	strbuf_addf(&buf_payload, "%s:%s", key, value->json.buf);
+
+	perf_io_write_fl(file, line, event_name, repo, &us_elapsed_absolute,
+			 &us_elapsed_region, category, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+static void fn_printf_va_fl(const char *file, int line,
+			    uint64_t us_elapsed_absolute, const char *fmt,
+			    va_list ap)
+{
+	const char *event_name = "printf";
+	struct strbuf buf_payload = STRBUF_INIT;
+
+	maybe_append_string_va(&buf_payload, fmt, ap);
+
+	perf_io_write_fl(file, line, event_name, NULL, &us_elapsed_absolute,
+			 NULL, NULL, &buf_payload);
+	strbuf_release(&buf_payload);
+}
+
+struct tr2_tgt tr2_tgt_perf = {
+	&tr2dst_perf,
+
+	fn_init,
+	fn_term,
+
+	fn_version_fl,
+	fn_start_fl,
+	fn_exit_fl,
+	fn_signal,
+	fn_atexit,
+	fn_error_va_fl,
+	fn_command_path_fl,
+	fn_command_name_fl,
+	fn_command_mode_fl,
+	fn_alias_fl,
+	fn_child_start_fl,
+	fn_child_exit_fl,
+	fn_thread_start_fl,
+	fn_thread_exit_fl,
+	fn_exec_fl,
+	fn_exec_result_fl,
+	fn_param_fl,
+	fn_repo_fl,
+	fn_region_enter_printf_va_fl,
+	fn_region_leave_printf_va_fl,
+	fn_data_fl,
+	fn_data_json_fl,
+	fn_printf_va_fl,
+};