summaryrefslogtreecommitdiff
path: root/trace2/tr2_tgt_event.c
diff options
context:
space:
mode:
authorJeff Hostetler <jeffhost@microsoft.com>2019-02-22 22:25:01 (GMT)
committerJunio C Hamano <gitster@pobox.com>2019-02-22 23:27:59 (GMT)
commitee4512ed481a126dadd33334186e0e759d7f2f47 (patch)
tree4bc0418115d44b1833c1d24d2ac1c92f067b7ad3 /trace2/tr2_tgt_event.c
parente544221d97a57a9be7ba18a0df52a15b4cc76f97 (diff)
downloadgit-ee4512ed481a126dadd33334186e0e759d7f2f47.zip
git-ee4512ed481a126dadd33334186e0e759d7f2f47.tar.gz
git-ee4512ed481a126dadd33334186e0e759d7f2f47.tar.bz2
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>
Diffstat (limited to 'trace2/tr2_tgt_event.c')
-rw-r--r--trace2/tr2_tgt_event.c588
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 0000000..107cb53
--- /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 */
+};