* [PATCH 0/8] WIP: trace2: a new trace facility @ 2018-08-31 16:49 Jeff Hostetler via GitGitGadget 2018-08-31 16:49 ` [PATCH 1/8] trace2: create new combined " Jeff Hostetler via GitGitGadget ` (9 more replies) 0 siblings, 10 replies; 26+ messages in thread From: Jeff Hostetler via GitGitGadget @ 2018-08-31 16:49 UTC (permalink / raw) To: git; +Cc: jeffhost, Junio C Hamano 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 ^ permalink raw reply [flat|nested] 26+ messages in thread
* [PATCH 1/8] trace2: create new combined trace facility 2018-08-31 16:49 [PATCH 0/8] WIP: trace2: a new trace facility Jeff Hostetler via GitGitGadget @ 2018-08-31 16:49 ` Jeff Hostetler via GitGitGadget 2018-08-31 17:19 ` Derrick Stolee 2018-09-04 22:12 ` Stefan Beller 2018-08-31 16:49 ` [PATCH 2/8] trace2: add trace2 to main Jeff Hostetler via GitGitGadget ` (8 subsequent siblings) 9 siblings, 2 replies; 26+ messages in thread From: Jeff Hostetler via GitGitGadget @ 2018-08-31 16:49 UTC (permalink / raw) To: git; +Cc: jeffhost, Junio C Hamano, Jeff Hostetler 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* Re: [PATCH 1/8] trace2: create new combined trace facility 2018-08-31 16:49 ` [PATCH 1/8] trace2: create new combined " Jeff Hostetler via GitGitGadget @ 2018-08-31 17:19 ` Derrick Stolee 2018-09-04 22:12 ` Stefan Beller 1 sibling, 0 replies; 26+ messages in thread From: Derrick Stolee @ 2018-08-31 17:19 UTC (permalink / raw) To: Jeff Hostetler via GitGitGadget, git; +Cc: jeffhost, Junio C Hamano 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 ^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [PATCH 1/8] trace2: create new combined trace facility 2018-08-31 16:49 ` [PATCH 1/8] trace2: create new combined " Jeff Hostetler via GitGitGadget 2018-08-31 17:19 ` Derrick Stolee @ 2018-09-04 22:12 ` Stefan Beller 2018-09-04 22:30 ` Junio C Hamano 2018-09-05 15:01 ` Jeff Hostetler 1 sibling, 2 replies; 26+ messages in thread From: Stefan Beller @ 2018-09-04 22:12 UTC (permalink / raw) To: gitgitgadget; +Cc: git, Junio C Hamano, Jeff Hostetler > 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? ^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [PATCH 1/8] trace2: create new combined trace facility 2018-09-04 22:12 ` Stefan Beller @ 2018-09-04 22:30 ` Junio C Hamano 2018-09-05 15:51 ` Jeff Hostetler 2018-09-05 15:01 ` Jeff Hostetler 1 sibling, 1 reply; 26+ messages in thread From: Junio C Hamano @ 2018-09-04 22:30 UTC (permalink / raw) To: Stefan Beller; +Cc: gitgitgadget, git, Jeff Hostetler 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. ^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [PATCH 1/8] trace2: create new combined trace facility 2018-09-04 22:30 ` Junio C Hamano @ 2018-09-05 15:51 ` Jeff Hostetler 0 siblings, 0 replies; 26+ messages in thread From: Jeff Hostetler @ 2018-09-05 15:51 UTC (permalink / raw) To: Junio C Hamano, Stefan Beller; +Cc: gitgitgadget, git, 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 ^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [PATCH 1/8] trace2: create new combined trace facility 2018-09-04 22:12 ` Stefan Beller 2018-09-04 22:30 ` Junio C Hamano @ 2018-09-05 15:01 ` Jeff Hostetler 1 sibling, 0 replies; 26+ messages in thread From: Jeff Hostetler @ 2018-09-05 15:01 UTC (permalink / raw) To: Stefan Beller, gitgitgadget; +Cc: git, Junio C Hamano, 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 ^ permalink raw reply [flat|nested] 26+ messages in thread
* [PATCH 2/8] trace2: add trace2 to main 2018-08-31 16:49 [PATCH 0/8] WIP: trace2: a new trace facility Jeff Hostetler via GitGitGadget 2018-08-31 16:49 ` [PATCH 1/8] trace2: create new combined " Jeff Hostetler via GitGitGadget @ 2018-08-31 16:49 ` Jeff Hostetler via GitGitGadget 2018-08-31 16:49 ` [PATCH 3/8] trace2: demonstrate trace2 regions in wt-status Jeff Hostetler via GitGitGadget ` (7 subsequent siblings) 9 siblings, 0 replies; 26+ messages in thread From: Jeff Hostetler via GitGitGadget @ 2018-08-31 16:49 UTC (permalink / raw) To: git; +Cc: jeffhost, Junio C Hamano, Jeff Hostetler 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* [PATCH 3/8] trace2: demonstrate trace2 regions in wt-status 2018-08-31 16:49 [PATCH 0/8] WIP: trace2: a new trace facility Jeff Hostetler via GitGitGadget 2018-08-31 16:49 ` [PATCH 1/8] trace2: create new combined " Jeff Hostetler via GitGitGadget 2018-08-31 16:49 ` [PATCH 2/8] trace2: add trace2 to main Jeff Hostetler via GitGitGadget @ 2018-08-31 16:49 ` Jeff Hostetler via GitGitGadget 2018-08-31 16:49 ` [PATCH 4/8] trace2: demonstrate trace2 child process classification Jeff Hostetler via GitGitGadget ` (6 subsequent siblings) 9 siblings, 0 replies; 26+ messages in thread From: Jeff Hostetler via GitGitGadget @ 2018-08-31 16:49 UTC (permalink / raw) To: git; +Cc: jeffhost, Junio C Hamano, Jeff Hostetler 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* [PATCH 4/8] trace2: demonstrate trace2 child process classification 2018-08-31 16:49 [PATCH 0/8] WIP: trace2: a new trace facility Jeff Hostetler via GitGitGadget ` (2 preceding siblings ...) 2018-08-31 16:49 ` [PATCH 3/8] trace2: demonstrate trace2 regions in wt-status Jeff Hostetler via GitGitGadget @ 2018-08-31 16:49 ` Jeff Hostetler via GitGitGadget 2018-08-31 16:50 ` [PATCH 5/8] trace2: demonstrate instrumenting do_read_index Jeff Hostetler via GitGitGadget ` (5 subsequent siblings) 9 siblings, 0 replies; 26+ messages in thread From: Jeff Hostetler via GitGitGadget @ 2018-08-31 16:49 UTC (permalink / raw) To: git; +Cc: jeffhost, Junio C Hamano, Jeff Hostetler 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* [PATCH 5/8] trace2: demonstrate instrumenting do_read_index 2018-08-31 16:49 [PATCH 0/8] WIP: trace2: a new trace facility Jeff Hostetler via GitGitGadget ` (3 preceding siblings ...) 2018-08-31 16:49 ` [PATCH 4/8] trace2: demonstrate trace2 child process classification Jeff Hostetler via GitGitGadget @ 2018-08-31 16:50 ` Jeff Hostetler via GitGitGadget 2018-08-31 16:50 ` [PATCH 6/8] trace2: demonstrate instrumenting threaded preload_index Jeff Hostetler via GitGitGadget ` (4 subsequent siblings) 9 siblings, 0 replies; 26+ messages in thread From: Jeff Hostetler via GitGitGadget @ 2018-08-31 16:50 UTC (permalink / raw) To: git; +Cc: jeffhost, Junio C Hamano, Jeff Hostetler 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* [PATCH 6/8] trace2: demonstrate instrumenting threaded preload_index 2018-08-31 16:49 [PATCH 0/8] WIP: trace2: a new trace facility Jeff Hostetler via GitGitGadget ` (4 preceding siblings ...) 2018-08-31 16:50 ` [PATCH 5/8] trace2: demonstrate instrumenting do_read_index Jeff Hostetler via GitGitGadget @ 2018-08-31 16:50 ` Jeff Hostetler via GitGitGadget 2018-08-31 16:50 ` [PATCH 7/8] trace2: demonstrate setting sub-command parameter in checkout Jeff Hostetler via GitGitGadget ` (3 subsequent siblings) 9 siblings, 0 replies; 26+ messages in thread From: Jeff Hostetler via GitGitGadget @ 2018-08-31 16:50 UTC (permalink / raw) To: git; +Cc: jeffhost, Junio C Hamano, Jeff Hostetler 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* [PATCH 7/8] trace2: demonstrate setting sub-command parameter in checkout 2018-08-31 16:49 [PATCH 0/8] WIP: trace2: a new trace facility Jeff Hostetler via GitGitGadget ` (5 preceding siblings ...) 2018-08-31 16:50 ` [PATCH 6/8] trace2: demonstrate instrumenting threaded preload_index Jeff Hostetler via GitGitGadget @ 2018-08-31 16:50 ` Jeff Hostetler via GitGitGadget 2018-08-31 16:50 ` [PATCH 8/8] trace2: demonstrate use of regions in read_directory_recursive Jeff Hostetler via GitGitGadget ` (2 subsequent siblings) 9 siblings, 0 replies; 26+ messages in thread From: Jeff Hostetler via GitGitGadget @ 2018-08-31 16:50 UTC (permalink / raw) To: git; +Cc: jeffhost, Junio C Hamano, Jeff Hostetler 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* [PATCH 8/8] trace2: demonstrate use of regions in read_directory_recursive 2018-08-31 16:49 [PATCH 0/8] WIP: trace2: a new trace facility Jeff Hostetler via GitGitGadget ` (6 preceding siblings ...) 2018-08-31 16:50 ` [PATCH 7/8] trace2: demonstrate setting sub-command parameter in checkout Jeff Hostetler via GitGitGadget @ 2018-08-31 16:50 ` Jeff Hostetler via GitGitGadget 2018-08-31 17:19 ` [PATCH 0/8] WIP: trace2: a new trace facility Derrick Stolee 2019-01-15 1:05 ` [PATCH 0/8] WIP: trace2: a new trace facility Jonathan Nieder 9 siblings, 0 replies; 26+ messages in thread From: Jeff Hostetler via GitGitGadget @ 2018-08-31 16:50 UTC (permalink / raw) To: git; +Cc: jeffhost, Junio C Hamano, Jeff Hostetler 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* Re: [PATCH 0/8] WIP: trace2: a new trace facility 2018-08-31 16:49 [PATCH 0/8] WIP: trace2: a new trace facility Jeff Hostetler via GitGitGadget ` (7 preceding siblings ...) 2018-08-31 16:50 ` [PATCH 8/8] trace2: demonstrate use of regions in read_directory_recursive Jeff Hostetler via GitGitGadget @ 2018-08-31 17:19 ` Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 0/6] Use trace2 in commit-reach Derrick Stolee 2019-01-15 1:05 ` [PATCH 0/8] WIP: trace2: a new trace facility Jonathan Nieder 9 siblings, 1 reply; 26+ messages in thread From: Derrick Stolee @ 2018-08-31 17:19 UTC (permalink / raw) To: Jeff Hostetler via GitGitGadget, git; +Cc: jeffhost, Junio C Hamano 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 ^ permalink raw reply [flat|nested] 26+ messages in thread
* [RFC PATCH 0/6] Use trace2 in commit-reach 2018-08-31 17:19 ` [PATCH 0/8] WIP: trace2: a new trace facility Derrick Stolee @ 2018-09-06 15:13 ` Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 1/6] commit-reach: add trace2 telemetry and walk count Derrick Stolee ` (5 more replies) 0 siblings, 6 replies; 26+ messages in thread From: Derrick Stolee @ 2018-09-06 15:13 UTC (permalink / raw) To: git; +Cc: git, stolee, gitster, 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 ^ permalink raw reply [flat|nested] 26+ messages in thread
* [RFC PATCH 1/6] commit-reach: add trace2 telemetry and walk count 2018-09-06 15:13 ` [RFC PATCH 0/6] Use trace2 in commit-reach Derrick Stolee @ 2018-09-06 15:13 ` Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 2/6] comit-reach: use trace2 for commit_contains_tag_algo Derrick Stolee ` (4 subsequent siblings) 5 siblings, 0 replies; 26+ messages in thread From: Derrick Stolee @ 2018-09-06 15:13 UTC (permalink / raw) To: git; +Cc: git, stolee, gitster, 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* [RFC PATCH 2/6] comit-reach: use trace2 for commit_contains_tag_algo 2018-09-06 15:13 ` [RFC PATCH 0/6] Use trace2 in commit-reach Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 1/6] commit-reach: add trace2 telemetry and walk count Derrick Stolee @ 2018-09-06 15:13 ` Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 3/6] commit-reach: use trace2 in can_all_from_reach Derrick Stolee ` (3 subsequent siblings) 5 siblings, 0 replies; 26+ messages in thread From: Derrick Stolee @ 2018-09-06 15:13 UTC (permalink / raw) To: git; +Cc: git, stolee, gitster, 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* [RFC PATCH 3/6] commit-reach: use trace2 in can_all_from_reach 2018-09-06 15:13 ` [RFC PATCH 0/6] Use trace2 in commit-reach Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 1/6] commit-reach: add trace2 telemetry and walk count Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 2/6] comit-reach: use trace2 for commit_contains_tag_algo Derrick Stolee @ 2018-09-06 15:13 ` Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 4/6] test-tool: start trace2 environment Derrick Stolee ` (2 subsequent siblings) 5 siblings, 0 replies; 26+ messages in thread From: Derrick Stolee @ 2018-09-06 15:13 UTC (permalink / raw) To: git; +Cc: git, stolee, gitster, 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* [RFC PATCH 4/6] test-tool: start trace2 environment 2018-09-06 15:13 ` [RFC PATCH 0/6] Use trace2 in commit-reach Derrick Stolee ` (2 preceding siblings ...) 2018-09-06 15:13 ` [RFC PATCH 3/6] commit-reach: use trace2 in can_all_from_reach Derrick Stolee @ 2018-09-06 15:13 ` Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 5/6] test-lib: add run_and_check_trace2 Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 6/6] commit-reach: fix first-parent heuristic Derrick Stolee 5 siblings, 0 replies; 26+ messages in thread From: Derrick Stolee @ 2018-09-06 15:13 UTC (permalink / raw) To: git; +Cc: git, stolee, gitster, 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* [RFC PATCH 5/6] test-lib: add run_and_check_trace2 2018-09-06 15:13 ` [RFC PATCH 0/6] Use trace2 in commit-reach Derrick Stolee ` (3 preceding siblings ...) 2018-09-06 15:13 ` [RFC PATCH 4/6] test-tool: start trace2 environment Derrick Stolee @ 2018-09-06 15:13 ` Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 6/6] commit-reach: fix first-parent heuristic Derrick Stolee 5 siblings, 0 replies; 26+ messages in thread From: Derrick Stolee @ 2018-09-06 15:13 UTC (permalink / raw) To: git; +Cc: git, stolee, gitster, 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* [RFC PATCH 6/6] commit-reach: fix first-parent heuristic 2018-09-06 15:13 ` [RFC PATCH 0/6] Use trace2 in commit-reach Derrick Stolee ` (4 preceding siblings ...) 2018-09-06 15:13 ` [RFC PATCH 5/6] test-lib: add run_and_check_trace2 Derrick Stolee @ 2018-09-06 15:13 ` Derrick Stolee 2018-10-11 1:50 ` Jonathan Nieder 5 siblings, 1 reply; 26+ messages in thread From: Derrick Stolee @ 2018-09-06 15:13 UTC (permalink / raw) To: git; +Cc: git, stolee, gitster, 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 ^ permalink raw reply related [flat|nested] 26+ messages in thread
* Re: [RFC PATCH 6/6] commit-reach: fix first-parent heuristic 2018-09-06 15:13 ` [RFC PATCH 6/6] commit-reach: fix first-parent heuristic Derrick Stolee @ 2018-10-11 1:50 ` Jonathan Nieder 2018-10-11 11:00 ` Derrick Stolee 0 siblings, 1 reply; 26+ messages in thread From: Jonathan Nieder @ 2018-10-11 1:50 UTC (permalink / raw) To: Derrick Stolee; +Cc: git, git, gitster, Derrick Stolee, Josh Steadmon 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 ^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [RFC PATCH 6/6] commit-reach: fix first-parent heuristic 2018-10-11 1:50 ` Jonathan Nieder @ 2018-10-11 11:00 ` Derrick Stolee 0 siblings, 0 replies; 26+ messages in thread From: Derrick Stolee @ 2018-10-11 11:00 UTC (permalink / raw) To: Jonathan Nieder; +Cc: git, git, gitster, Derrick Stolee, Josh Steadmon 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/ ^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [PATCH 0/8] WIP: trace2: a new trace facility 2018-08-31 16:49 [PATCH 0/8] WIP: trace2: a new trace facility Jeff Hostetler via GitGitGadget ` (8 preceding siblings ...) 2018-08-31 17:19 ` [PATCH 0/8] WIP: trace2: a new trace facility Derrick Stolee @ 2019-01-15 1:05 ` Jonathan Nieder 2019-01-15 17:03 ` Jeff Hostetler 9 siblings, 1 reply; 26+ messages in thread From: Jonathan Nieder @ 2019-01-15 1:05 UTC (permalink / raw) To: Jeff Hostetler via GitGitGadget Cc: git, jeffhost, Junio C Hamano, Derrick Stolee 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 ^ permalink raw reply [flat|nested] 26+ messages in thread
* Re: [PATCH 0/8] WIP: trace2: a new trace facility 2019-01-15 1:05 ` [PATCH 0/8] WIP: trace2: a new trace facility Jonathan Nieder @ 2019-01-15 17:03 ` Jeff Hostetler 0 siblings, 0 replies; 26+ messages in thread From: Jeff Hostetler @ 2019-01-15 17:03 UTC (permalink / raw) To: Jonathan Nieder, Jeff Hostetler via GitGitGadget Cc: git, jeffhost, Junio C Hamano, Derrick Stolee 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 ^ permalink raw reply [flat|nested] 26+ messages in thread
end of thread, other threads:[~2019-01-15 17:12 UTC | newest] Thread overview: 26+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2018-08-31 16:49 [PATCH 0/8] WIP: trace2: a new trace facility Jeff Hostetler via GitGitGadget 2018-08-31 16:49 ` [PATCH 1/8] trace2: create new combined " Jeff Hostetler via GitGitGadget 2018-08-31 17:19 ` Derrick Stolee 2018-09-04 22:12 ` Stefan Beller 2018-09-04 22:30 ` Junio C Hamano 2018-09-05 15:51 ` Jeff Hostetler 2018-09-05 15:01 ` Jeff Hostetler 2018-08-31 16:49 ` [PATCH 2/8] trace2: add trace2 to main Jeff Hostetler via GitGitGadget 2018-08-31 16:49 ` [PATCH 3/8] trace2: demonstrate trace2 regions in wt-status Jeff Hostetler via GitGitGadget 2018-08-31 16:49 ` [PATCH 4/8] trace2: demonstrate trace2 child process classification Jeff Hostetler via GitGitGadget 2018-08-31 16:50 ` [PATCH 5/8] trace2: demonstrate instrumenting do_read_index Jeff Hostetler via GitGitGadget 2018-08-31 16:50 ` [PATCH 6/8] trace2: demonstrate instrumenting threaded preload_index Jeff Hostetler via GitGitGadget 2018-08-31 16:50 ` [PATCH 7/8] trace2: demonstrate setting sub-command parameter in checkout Jeff Hostetler via GitGitGadget 2018-08-31 16:50 ` [PATCH 8/8] trace2: demonstrate use of regions in read_directory_recursive Jeff Hostetler via GitGitGadget 2018-08-31 17:19 ` [PATCH 0/8] WIP: trace2: a new trace facility Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 0/6] Use trace2 in commit-reach Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 1/6] commit-reach: add trace2 telemetry and walk count Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 2/6] comit-reach: use trace2 for commit_contains_tag_algo Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 3/6] commit-reach: use trace2 in can_all_from_reach Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 4/6] test-tool: start trace2 environment Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 5/6] test-lib: add run_and_check_trace2 Derrick Stolee 2018-09-06 15:13 ` [RFC PATCH 6/6] commit-reach: fix first-parent heuristic Derrick Stolee 2018-10-11 1:50 ` Jonathan Nieder 2018-10-11 11:00 ` Derrick Stolee 2019-01-15 1:05 ` [PATCH 0/8] WIP: trace2: a new trace facility Jonathan Nieder 2019-01-15 17:03 ` Jeff Hostetler
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.