WIP: trace2: a new trace facility

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/[email protected]/
[2]
https://public-inbox.org/git/[email protected]/
[3]
https://public-inbox.org/git/[email protected]/
[4]
https://public-inbox.org/git/[email protected]/
[5] https://public-inbox.org/git/[email protected]/
[6] https://public-inbox.org/git/[email protected]/

Cc: [email protected]: [email protected]: [email protected]:
[email protected]: [email protected]

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

From: Jeff Hostetler <[email protected]>

---
 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(-)

index 571019d0bd..606402faeb 100644
@@ -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; }

index 5f2e90932f..c0901d9ec6 100644
@@ -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

index c27c38738b..cc56279a8c 100644
@@ -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);
 }

index 5dd1486718..c169f61ccd 100644
@@ -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,

index 84b883c213..e833d9a277 100644
@@ -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;
 }
 
 

index 3932420ec8..a91206b08c 100644
@@ -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,

index cc803336bd..1838c46d20 100644
@@ -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

From: Jeff Hostetler <[email protected]>

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.

---
 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

index 5a969f5830..88ae7afdd4 100644
@@ -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

index 4d014541ab..38f0cd2ba0 100644
@@ -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"

gitgitgadget

From: Jeff Hostetler <[email protected]>

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

---
 editor.c      | 1 +
 pager.c       | 1 +
 sub-process.c | 1 +
 3 files changed, 3 insertions(+)

index 9a9b4e12d1..29707de198 100644
@@ -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);
 

index a768797fcf..4168460ae9 100644
@@ -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)

index 8d2a1707cf..3f4af93555 100644
@@ -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

From: Jeff Hostetler <[email protected]>

---
 read-cache.c | 6 ++++++
 1 file changed, 6 insertions(+)

index 7b1354d759..7a31ac4da8 100644
@@ -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

From: Jeff Hostetler <[email protected]>

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.

---
 wt-status.c | 14 ++++++++++++--
 1 file changed, 12 insertions(+), 2 deletions(-)

index 5ffab61015..9e37a73c73 100644
@@ -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

From: Jeff Hostetler <[email protected]>

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

---
 builtin/checkout.c | 5 +++++
 1 file changed, 5 insertions(+)

index 29ef50013d..0934587781 100644
@@ -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

From: Jeff Hostetler <[email protected]>

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.

---
 dir.c | 3 +++
 1 file changed, 3 insertions(+)

index aceb0d4869..c7c0654da5 100644
@@ -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

From: Jeff Hostetler <[email protected]>

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

---
 preload-index.c | 10 ++++++++++
 1 file changed, 10 insertions(+)

index 71cd2437a3..2483d92c61 100644
@@ -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

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

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?)

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

[...]

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)

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

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.

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.

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.

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.

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.

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().

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

thanks for the review,
Jeff

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

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

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.

---
 commit-reach.c | 8 ++++++++
 1 file changed, 8 insertions(+)

index 86715c103c..ee374dce20 100644
@@ -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

---
 commit-reach.c | 8 ++++++++
 1 file changed, 8 insertions(+)

index 0fc3b1ac18..0a75644653 100644
@@ -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

---
 commit-reach.c | 12 +++++++++++-
 1 file changed, 11 insertions(+), 1 deletion(-)

index ee374dce20..0fc3b1ac18 100644
@@ -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

---
 t/helper/test-tool.c | 3 +++
 1 file changed, 3 insertions(+)

index 7566b0786a..f70d5d74f8 100644
@@ -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

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.

---
 t/t6600-test-reach.sh |  6 ++++++
 t/test-lib.sh         | 14 ++++++++++++++
 2 files changed, 20 insertions(+)

index d139a00d1d..98ad25bb45 100755
@@ -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

index 8bb0f4348e..9b9f68f324 100644
@@ -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

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)

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

index 0a75644653..bd009260b0 100644
@@ -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;
 			}
 

index 98ad25bb45..5e231a5955 100755
@@ -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

Hi,

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

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/[email protected]/

Hi,

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

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

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.

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.)

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