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, 588 insertions, 0 deletions

diff --git a/trace2/tr2_tgt_event.c b/trace2/tr2_tgt_event.c
new file mode 100644
index 0000000000..107cb5317d
--- /dev/null
+++ b/trace2/tr2_tgt_event.c
@@ -0,0 +1,588 @@
+#include "cache.h"
+#include "config.h"
+#include "json-writer.h"
+#include "run-command.h"
+#include "version.h"
+#include "trace2/tr2_dst.h"
+#include "trace2/tr2_tbuf.h"
+#include "trace2/tr2_sid.h"
+#include "trace2/tr2_tgt.h"
+#include "trace2/tr2_tls.h"
+
+static struct tr2_dst tr2dst_event = { "GIT_TR2_EVENT", 0, 0, 0 };
+
+/*
+ * The version number of the JSON data generated by the EVENT target
+ * in this source file.  Update this if you make a significant change
+ * to the JSON fields or message structure.  You probably do not need
+ * to update this if you just add another call to one of the existing
+ * TRACE2 API methods.
+ */
+#define TR2_EVENT_VERSION "1"
+
+/*
+ * Region nesting limit for messages written to the event target.
+ *
+ * The "region_enter" and "region_leave" messages (especially recursive
+ * messages such as those produced while diving the worktree or index)
+ * are primarily intended for the performance target during debugging.
+ *
+ * Some of the outer-most messages, however, may be of interest to the
+ * event target.  Set this environment variable to a larger integer for
+ * more detail in the event target.
+ */
+#define TR2_ENVVAR_EVENT_NESTING "GIT_TR2_EVENT_NESTING"
+static int tr2env_event_nesting_wanted = 2;
+
+/*
+ * Set this environment variable to true to omit the <time>, <file>, and
+ * <line> fields from most events.
+ */
+#define TR2_ENVVAR_EVENT_BRIEF "GIT_TR2_EVENT_BRIEF"
+static int tr2env_event_brief;
+
+static int fn_init(void)
+{
+	int want = tr2_dst_trace_want(&tr2dst_event);
+	int want_nesting;
+	int want_brief;
+	char *nesting;
+	char *brief;
+
+	if (!want)
+		return want;
+
+	nesting = getenv(TR2_ENVVAR_EVENT_NESTING);
+	if (nesting && ((want_nesting = atoi(nesting)) > 0))
+		tr2env_event_nesting_wanted = want_nesting;
+
+	brief = getenv(TR2_ENVVAR_EVENT_BRIEF);
+	if (brief && ((want_brief = atoi(brief)) > 0))
+		tr2env_event_brief = want_brief;
+
+	return want;
+}
+
+static void fn_term(void)
+{
+	tr2_dst_trace_disable(&tr2dst_event);
+}
+
+/*
+ * Append common key-value pairs to the currently open JSON object.
+ *     "event:"<event_name>"
+ *      "sid":"<sid>"
+ *   "thread":"<thread_name>"
+ *     "time":"<time>"
+ *     "file":"<filename>"
+ *     "line":<line_number>
+ *     "repo":<repo_id>
+ */
+static void event_fmt_prepare(const char *event_name, const char *file,
+			      int line, const struct repository *repo,
+			      struct json_writer *jw)
+{
+	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+	struct tr2_tbuf tb_now;
+
+	jw_object_string(jw, "event", event_name);
+	jw_object_string(jw, "sid", tr2_sid_get());
+	jw_object_string(jw, "thread", ctx->thread_name.buf);
+
+	/*
+	 * In brief mode, only emit <time> on these 2 event types.
+	 */
+	if (!tr2env_event_brief || !strcmp(event_name, "version") ||
+	    !strcmp(event_name, "atexit")) {
+		tr2_tbuf_utc_time(&tb_now);
+		jw_object_string(jw, "time", tb_now.buf);
+	}
+
+	if (!tr2env_event_brief && file && *file) {
+		jw_object_string(jw, "file", file);
+		jw_object_intmax(jw, "line", line);
+	}
+
+	if (repo)
+		jw_object_intmax(jw, "repo", repo->trace2_repo_id);
+}
+
+static void fn_version_fl(const char *file, int line)
+{
+	const char *event_name = "version";
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_string(&jw, "evt", TR2_EVENT_VERSION);
+	jw_object_string(&jw, "exe", git_version_string);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_start_fl(const char *file, int line, const char **argv)
+{
+	const char *event_name = "start";
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_inline_begin_array(&jw, "argv");
+	jw_array_argv(&jw, argv);
+	jw_end(&jw);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_exit_fl(const char *file, int line, uint64_t us_elapsed_absolute,
+		       int code)
+{
+	const char *event_name = "exit";
+	struct json_writer jw = JSON_WRITER_INIT;
+	double t_abs = (double)us_elapsed_absolute / 1000000.0;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_double(&jw, "t_abs", 6, t_abs);
+	jw_object_intmax(&jw, "code", code);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_signal(uint64_t us_elapsed_absolute, int signo)
+{
+	const char *event_name = "signal";
+	struct json_writer jw = JSON_WRITER_INIT;
+	double t_abs = (double)us_elapsed_absolute / 1000000.0;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw);
+	jw_object_double(&jw, "t_abs", 6, t_abs);
+	jw_object_intmax(&jw, "signo", signo);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_atexit(uint64_t us_elapsed_absolute, int code)
+{
+	const char *event_name = "atexit";
+	struct json_writer jw = JSON_WRITER_INIT;
+	double t_abs = (double)us_elapsed_absolute / 1000000.0;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, __FILE__, __LINE__, NULL, &jw);
+	jw_object_double(&jw, "t_abs", 6, t_abs);
+	jw_object_intmax(&jw, "code", code);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void maybe_add_string_va(struct json_writer *jw, const char *field_name,
+				const char *fmt, va_list ap)
+{
+	if (fmt && *fmt && ap) {
+		va_list copy_ap;
+		struct strbuf buf = STRBUF_INIT;
+
+		va_copy(copy_ap, ap);
+		strbuf_vaddf(&buf, fmt, copy_ap);
+		va_end(copy_ap);
+
+		jw_object_string(jw, field_name, buf.buf);
+		strbuf_release(&buf);
+		return;
+	}
+
+	if (fmt && *fmt) {
+		jw_object_string(jw, field_name, fmt);
+		return;
+	}
+}
+
+static void fn_error_va_fl(const char *file, int line, const char *fmt,
+			   va_list ap)
+{
+	const char *event_name = "error";
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	maybe_add_string_va(&jw, "msg", fmt, ap);
+	/*
+	 * Also emit the format string as a field in case
+	 * post-processors want to aggregate common error
+	 * messages by type without argument fields (such
+	 * as pathnames or branch names) cluttering it up.
+	 */
+	if (fmt && *fmt)
+		jw_object_string(&jw, "fmt", fmt);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_command_path_fl(const char *file, int line, const char *pathname)
+{
+	const char *event_name = "cmd_path";
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_string(&jw, "path", pathname);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_command_name_fl(const char *file, int line, const char *name,
+			       const char *hierarchy)
+{
+	const char *event_name = "cmd_name";
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_string(&jw, "name", name);
+	if (hierarchy && *hierarchy)
+		jw_object_string(&jw, "hierarchy", hierarchy);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_command_mode_fl(const char *file, int line, const char *mode)
+{
+	const char *event_name = "cmd_mode";
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_string(&jw, "name", mode);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_alias_fl(const char *file, int line, const char *alias,
+			const char **argv)
+{
+	const char *event_name = "alias";
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_string(&jw, "alias", alias);
+	jw_object_inline_begin_array(&jw, "argv");
+	jw_array_argv(&jw, argv);
+	jw_end(&jw);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_child_start_fl(const char *file, int line,
+			      uint64_t us_elapsed_absolute,
+			      const struct child_process *cmd)
+{
+	const char *event_name = "child_start";
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_intmax(&jw, "child_id", cmd->trace2_child_id);
+	if (cmd->trace2_hook_name) {
+		jw_object_string(&jw, "child_class", "hook");
+		jw_object_string(&jw, "hook_name", cmd->trace2_hook_name);
+	} else {
+		const char *child_class =
+			cmd->trace2_child_class ? cmd->trace2_child_class : "?";
+		jw_object_string(&jw, "child_class", child_class);
+	}
+	if (cmd->dir)
+		jw_object_string(&jw, "cd", cmd->dir);
+	jw_object_bool(&jw, "use_shell", cmd->use_shell);
+	jw_object_inline_begin_array(&jw, "argv");
+	if (cmd->git_cmd)
+		jw_array_string(&jw, "git");
+	jw_array_argv(&jw, cmd->argv);
+	jw_end(&jw);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_child_exit_fl(const char *file, int line,
+			     uint64_t us_elapsed_absolute, int cid, int pid,
+			     int code, uint64_t us_elapsed_child)
+{
+	const char *event_name = "child_exit";
+	struct json_writer jw = JSON_WRITER_INIT;
+	double t_rel = (double)us_elapsed_child / 1000000.0;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_intmax(&jw, "child_id", cid);
+	jw_object_intmax(&jw, "pid", pid);
+	jw_object_intmax(&jw, "code", code);
+	jw_object_double(&jw, "t_rel", 6, t_rel);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+
+	jw_release(&jw);
+}
+
+static void fn_thread_start_fl(const char *file, int line,
+			       uint64_t us_elapsed_absolute)
+{
+	const char *event_name = "thread_start";
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_thread_exit_fl(const char *file, int line,
+			      uint64_t us_elapsed_absolute,
+			      uint64_t us_elapsed_thread)
+{
+	const char *event_name = "thread_exit";
+	struct json_writer jw = JSON_WRITER_INIT;
+	double t_rel = (double)us_elapsed_thread / 1000000.0;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_double(&jw, "t_rel", 6, t_rel);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_exec_fl(const char *file, int line, uint64_t us_elapsed_absolute,
+		       int exec_id, const char *exe, const char **argv)
+{
+	const char *event_name = "exec";
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_intmax(&jw, "exec_id", exec_id);
+	if (exe)
+		jw_object_string(&jw, "exe", exe);
+	jw_object_inline_begin_array(&jw, "argv");
+	jw_array_argv(&jw, argv);
+	jw_end(&jw);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_exec_result_fl(const char *file, int line,
+			      uint64_t us_elapsed_absolute, int exec_id,
+			      int code)
+{
+	const char *event_name = "exec_result";
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_intmax(&jw, "exec_id", exec_id);
+	jw_object_intmax(&jw, "code", code);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_param_fl(const char *file, int line, const char *param,
+			const char *value)
+{
+	const char *event_name = "def_param";
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, NULL, &jw);
+	jw_object_string(&jw, "param", param);
+	jw_object_string(&jw, "value", value);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_repo_fl(const char *file, int line,
+		       const struct repository *repo)
+{
+	const char *event_name = "def_repo";
+	struct json_writer jw = JSON_WRITER_INIT;
+
+	jw_object_begin(&jw, 0);
+	event_fmt_prepare(event_name, file, line, repo, &jw);
+	jw_object_string(&jw, "worktree", repo->worktree);
+	jw_end(&jw);
+
+	tr2_dst_write_line(&tr2dst_event, &jw.json);
+	jw_release(&jw);
+}
+
+static void fn_region_enter_printf_va_fl(const char *file, int line,
+					 uint64_t us_elapsed_absolute,
+					 const char *category,
+					 const char *label,
+					 const struct repository *repo,
+					 const char *fmt, va_list ap)
+{
+	const char *event_name = "region_enter";
+	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+	if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) {
+		struct json_writer jw = JSON_WRITER_INIT;
+
+		jw_object_begin(&jw, 0);
+		event_fmt_prepare(event_name, file, line, repo, &jw);
+		jw_object_intmax(&jw, "nesting", ctx->nr_open_regions);
+		if (category)
+			jw_object_string(&jw, "category", category);
+		if (label)
+			jw_object_string(&jw, "label", label);
+		maybe_add_string_va(&jw, "msg", fmt, ap);
+		jw_end(&jw);
+
+		tr2_dst_write_line(&tr2dst_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+static void fn_region_leave_printf_va_fl(
+	const char *file, int line, uint64_t us_elapsed_absolute,
+	uint64_t us_elapsed_region, const char *category, const char *label,
+	const struct repository *repo, const char *fmt, va_list ap)
+{
+	const char *event_name = "region_leave";
+	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+	if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) {
+		struct json_writer jw = JSON_WRITER_INIT;
+		double t_rel = (double)us_elapsed_region / 1000000.0;
+
+		jw_object_begin(&jw, 0);
+		event_fmt_prepare(event_name, file, line, repo, &jw);
+		jw_object_double(&jw, "t_rel", 6, t_rel);
+		jw_object_intmax(&jw, "nesting", ctx->nr_open_regions);
+		if (category)
+			jw_object_string(&jw, "category", category);
+		if (label)
+			jw_object_string(&jw, "label", label);
+		maybe_add_string_va(&jw, "msg", fmt, ap);
+		jw_end(&jw);
+
+		tr2_dst_write_line(&tr2dst_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+static void fn_data_fl(const char *file, int line, uint64_t us_elapsed_absolute,
+		       uint64_t us_elapsed_region, const char *category,
+		       const struct repository *repo, const char *key,
+		       const char *value)
+{
+	const char *event_name = "data";
+	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+	if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) {
+		struct json_writer jw = JSON_WRITER_INIT;
+		double t_abs = (double)us_elapsed_absolute / 1000000.0;
+		double t_rel = (double)us_elapsed_region / 1000000.0;
+
+		jw_object_begin(&jw, 0);
+		event_fmt_prepare(event_name, file, line, repo, &jw);
+		jw_object_double(&jw, "t_abs", 6, t_abs);
+		jw_object_double(&jw, "t_rel", 6, t_rel);
+		jw_object_intmax(&jw, "nesting", ctx->nr_open_regions);
+		jw_object_string(&jw, "category", category);
+		jw_object_string(&jw, "key", key);
+		jw_object_string(&jw, "value", value);
+		jw_end(&jw);
+
+		tr2_dst_write_line(&tr2dst_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+static void fn_data_json_fl(const char *file, int line,
+			    uint64_t us_elapsed_absolute,
+			    uint64_t us_elapsed_region, const char *category,
+			    const struct repository *repo, const char *key,
+			    const struct json_writer *value)
+{
+	const char *event_name = "data_json";
+	struct tr2tls_thread_ctx *ctx = tr2tls_get_self();
+	if (ctx->nr_open_regions <= tr2env_event_nesting_wanted) {
+		struct json_writer jw = JSON_WRITER_INIT;
+		double t_abs = (double)us_elapsed_absolute / 1000000.0;
+		double t_rel = (double)us_elapsed_region / 1000000.0;
+
+		jw_object_begin(&jw, 0);
+		event_fmt_prepare(event_name, file, line, repo, &jw);
+		jw_object_double(&jw, "t_abs", 6, t_abs);
+		jw_object_double(&jw, "t_rel", 6, t_rel);
+		jw_object_intmax(&jw, "nesting", ctx->nr_open_regions);
+		jw_object_string(&jw, "category", category);
+		jw_object_string(&jw, "key", key);
+		jw_object_sub_jw(&jw, "value", value);
+		jw_end(&jw);
+
+		tr2_dst_write_line(&tr2dst_event, &jw.json);
+		jw_release(&jw);
+	}
+}
+
+struct tr2_tgt tr2_tgt_event = {
+	&tr2dst_event,
+
+	fn_init,
+	fn_term,
+
+	fn_version_fl,
+	fn_start_fl,
+	fn_exit_fl,
+	fn_signal,
+	fn_atexit,
+	fn_error_va_fl,
+	fn_command_path_fl,
+	fn_command_name_fl,
+	fn_command_mode_fl,
+	fn_alias_fl,
+	fn_child_start_fl,
+	fn_child_exit_fl,
+	fn_thread_start_fl,
+	fn_thread_exit_fl,
+	fn_exec_fl,
+	fn_exec_result_fl,
+	fn_param_fl,
+	fn_repo_fl,
+	fn_region_enter_printf_va_fl,
+	fn_region_leave_printf_va_fl,
+	fn_data_fl,
+	fn_data_json_fl,
+	NULL, /* printf */
+};