From a15860dca3f194bb87e2d6028264791a4cec031d Mon Sep 17 00:00:00 2001
From: Jeff Hostetler <jeffhost@microsoft.com>
Date: Fri, 22 Feb 2019 14:25:10 -0800
Subject: [PATCH] trace2: t/helper/test-trace2, t0210.sh, t0211.sh, t0212.sh

Create unit tests for Trace2.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 Makefile                  |   1 +
 t/helper/test-tool.c      |   1 +
 t/helper/test-tool.h      |   1 +
 t/helper/test-trace2.c    | 273 ++++++++++++++++++++++++++++++++++++++++++++++
 t/t0210-trace2-normal.sh  | 135 +++++++++++++++++++++++
 t/t0210/scrub_normal.perl |  48 ++++++++
 t/t0211-trace2-perf.sh    | 153 ++++++++++++++++++++++++++
 t/t0211/scrub_perf.perl   |  76 +++++++++++++
 t/t0212-trace2-event.sh   | 236 +++++++++++++++++++++++++++++++++++++++
 t/t0212/parse_events.perl | 251 ++++++++++++++++++++++++++++++++++++++++++
 10 files changed, 1175 insertions(+)
 create mode 100644 t/helper/test-trace2.c
 create mode 100755 t/t0210-trace2-normal.sh
 create mode 100644 t/t0210/scrub_normal.perl
 create mode 100755 t/t0211-trace2-perf.sh
 create mode 100644 t/t0211/scrub_perf.perl
 create mode 100755 t/t0212-trace2-event.sh
 create mode 100644 t/t0212/parse_events.perl

diff --git a/Makefile b/Makefile
index 29fec13c9b..148668368b 100644
--- a/Makefile
+++ b/Makefile
@@ -773,6 +773,7 @@ TEST_BUILTINS_OBJS += test-string-list.o
 TEST_BUILTINS_OBJS += test-submodule-config.o
 TEST_BUILTINS_OBJS += test-submodule-nested-repo-config.o
 TEST_BUILTINS_OBJS += test-subprocess.o
+TEST_BUILTINS_OBJS += test-trace2.o
 TEST_BUILTINS_OBJS += test-urlmatch-normalization.o
 TEST_BUILTINS_OBJS += test-xml-encode.o
 TEST_BUILTINS_OBJS += test-wildmatch.o
diff --git a/t/helper/test-tool.c b/t/helper/test-tool.c
index d13fd94430..53c06932c4 100644
--- a/t/helper/test-tool.c
+++ b/t/helper/test-tool.c
@@ -52,6 +52,7 @@ static struct test_cmd cmds[] = {
 	{ "submodule-config", cmd__submodule_config },
 	{ "submodule-nested-repo-config", cmd__submodule_nested_repo_config },
 	{ "subprocess", cmd__subprocess },
+	{ "trace2", cmd__trace2 },
 	{ "urlmatch-normalization", cmd__urlmatch_normalization },
 	{ "xml-encode", cmd__xml_encode },
 	{ "wildmatch", cmd__wildmatch },
diff --git a/t/helper/test-tool.h b/t/helper/test-tool.h
index 25abed1cf2..ffab4d19d7 100644
--- a/t/helper/test-tool.h
+++ b/t/helper/test-tool.h
@@ -48,6 +48,7 @@ int cmd__string_list(int argc, const char **argv);
 int cmd__submodule_config(int argc, const char **argv);
 int cmd__submodule_nested_repo_config(int argc, const char **argv);
 int cmd__subprocess(int argc, const char **argv);
+int cmd__trace2(int argc, const char **argv);
 int cmd__urlmatch_normalization(int argc, const char **argv);
 int cmd__xml_encode(int argc, const char **argv);
 int cmd__wildmatch(int argc, const char **argv);
diff --git a/t/helper/test-trace2.c b/t/helper/test-trace2.c
new file mode 100644
index 0000000000..197819c872
--- /dev/null
+++ b/t/helper/test-trace2.c
@@ -0,0 +1,273 @@
+#include "test-tool.h"
+#include "cache.h"
+#include "argv-array.h"
+#include "run-command.h"
+#include "exec-cmd.h"
+#include "config.h"
+
+typedef int(fn_unit_test)(int argc, const char **argv);
+
+struct unit_test {
+	fn_unit_test *ut_fn;
+	const char *ut_name;
+	const char *ut_usage;
+};
+
+#define MyOk 0
+#define MyError 1
+
+static int get_i(int *p_value, const char *data)
+{
+	char *endptr;
+
+	if (!data || !*data)
+		return MyError;
+
+	*p_value = strtol(data, &endptr, 10);
+	if (*endptr || errno == ERANGE)
+		return MyError;
+
+	return MyOk;
+}
+
+/*
+ * Cause process to exit with the requested value via "return".
+ *
+ * Rely on test-tool.c:cmd_main() to call trace2_cmd_exit()
+ * with our result.
+ *
+ * Test harness can confirm:
+ * [] the process-exit value.
+ * [] the "code" field in the "exit" trace2 event.
+ * [] the "code" field in the "atexit" trace2 event.
+ * [] the "name" field in the "cmd_name" trace2 event.
+ * [] "def_param" events for all of the "interesting" pre-defined
+ * config settings.
+ */
+static int ut_001return(int argc, const char **argv)
+{
+	int rc;
+
+	if (get_i(&rc, argv[0]))
+		die("expect <exit_code>");
+
+	return rc;
+}
+
+/*
+ * Cause the process to exit with the requested value via "exit()".
+ *
+ * Test harness can confirm:
+ * [] the "code" field in the "exit" trace2 event.
+ * [] the "code" field in the "atexit" trace2 event.
+ * [] the "name" field in the "cmd_name" trace2 event.
+ * [] "def_param" events for all of the "interesting" pre-defined
+ * config settings.
+ */
+static int ut_002exit(int argc, const char **argv)
+{
+	int rc;
+
+	if (get_i(&rc, argv[0]))
+		die("expect <exit_code>");
+
+	exit(rc);
+}
+
+/*
+ * Send an "error" event with each value in argv.  Normally, git only issues
+ * a single "error" event immediately before issuing an "exit" event (such
+ * as in die() or BUG()), but multiple "error" events are allowed.
+ *
+ * Test harness can confirm:
+ * [] a trace2 "error" event for each value in argv.
+ * [] the "name" field in the "cmd_name" trace2 event.
+ * [] (optional) the file:line in the "exit" event refers to this function.
+ */
+static int ut_003error(int argc, const char **argv)
+{
+	int k;
+
+	if (!argv[0] || !*argv[0])
+		die("expect <error_message>");
+
+	for (k = 0; k < argc; k++)
+		error("%s", argv[k]);
+
+	return 0;
+}
+
+/*
+ * Run a child process and wait for it to finish and exit with its return code.
+ * test-tool trace2 004child [<child-command-line>]
+ *
+ * For example:
+ * test-tool trace2 004child git version
+ * test-tool trace2 004child test-tool trace2 001return 0
+ * test-tool trace2 004child test-tool trace2 004child test-tool trace2 004child
+ * test-tool trace2 004child git -c alias.xyz=version xyz
+ *
+ * Test harness can confirm:
+ * [] the "name" field in the "cmd_name" trace2 event.
+ * [] that the outer process has a single component SID (or depth "d0" in
+ *    the PERF stream).
+ * [] that "child_start" and "child_exit" events are generated for the child.
+ * [] if the child process is an instrumented executable:
+ *    [] that "version", "start", ..., "exit", and "atexit" events are
+ *       generated by the child process.
+ *    [] that the child process events have a multiple component SID (or
+ *       depth "dN+1" in the PERF stream).
+ * [] that the child exit code is propagated to the parent process "exit"
+ *    and "atexit" events..
+ * [] (optional) that the "t_abs" field in the child process "atexit" event
+ *    is less than the "t_rel" field in the "child_exit" event of the parent
+ *    process.
+ * [] if the child process is like the alias example above,
+ *    [] (optional) the child process attempts to run "git-xyx" as a dashed
+ *       command.
+ *    [] the child process emits an "alias" event with "xyz" => "version"
+ *    [] the child process runs "git version" as a child process.
+ *    [] the child process has a 3 component SID (or depth "d2" in the PERF
+ *       stream).
+ */
+static int ut_004child(int argc, const char **argv)
+{
+	int result;
+
+	/*
+	 * Allow empty <child_command_line> so we can do arbitrarily deep
+	 * command nesting and let the last one be null.
+	 */
+	if (!argc)
+		return 0;
+
+	result = run_command_v_opt(argv, 0);
+	exit(result);
+}
+
+/*
+ * Exec a git command.  This may either create a child process (Windows)
+ * or replace the existing process.
+ * test-tool trace2 005exec <git_command_args>
+ *
+ * For example:
+ * test-tool trace2 005exec version
+ *
+ * Test harness can confirm (on Windows):
+ * [] the "name" field in the "cmd_name" trace2 event.
+ * [] that the outer process has a single component SID (or depth "d0" in
+ *    the PERF stream).
+ * [] that "exec" and "exec_result" events are generated for the child
+ *    process (since the Windows compatibility layer fakes an exec() with
+ *    a CreateProcess(), WaitForSingleObject(), and exit()).
+ * [] that the child process has multiple component SID (or depth "dN+1"
+ *    in the PERF stream).
+ *
+ * Test harness can confirm (on platforms with a real exec() function):
+ * [] TODO talk about process replacement and how it affects SID.
+ */
+static int ut_005exec(int argc, const char **argv)
+{
+	int result;
+
+	if (!argc)
+		return 0;
+
+	result = execv_git_cmd(argv);
+	return result;
+}
+
+static int ut_006data(int argc, const char **argv)
+{
+	const char *usage_error =
+		"expect <cat0> <k0> <v0> [<cat1> <k1> <v1> [...]]";
+
+	if (argc % 3 != 0)
+		die("%s", usage_error);
+
+	while (argc) {
+		if (!argv[0] || !*argv[0] || !argv[1] || !*argv[1] ||
+		    !argv[2] || !*argv[2])
+			die("%s", usage_error);
+
+		trace2_data_string(argv[0], the_repository, argv[1], argv[2]);
+		argv += 3;
+		argc -= 3;
+	}
+
+	return 0;
+}
+
+/*
+ * Usage:
+ *     test-tool trace2 <ut_name_1> <ut_usage_1>
+ *     test-tool trace2 <ut_name_2> <ut_usage_2>
+ *     ...
+ */
+#define USAGE_PREFIX "test-tool trace2"
+
+/* clang-format off */
+static struct unit_test ut_table[] = {
+	{ ut_001return,   "001return", "<exit_code>" },
+	{ ut_002exit,     "002exit",   "<exit_code>" },
+	{ ut_003error,    "003error",  "<error_message>+" },
+	{ ut_004child,    "004child",  "[<child_command_line>]" },
+	{ ut_005exec,     "005exec",   "<git_command_args>" },
+	{ ut_006data,     "006data",   "[<category> <key> <value>]+" },
+};
+/* clang-format on */
+
+/* clang-format off */
+#define for_each_ut(k, ut_k)			\
+	for (k = 0, ut_k = &ut_table[k];	\
+	     k < ARRAY_SIZE(ut_table);		\
+	     k++, ut_k = &ut_table[k])
+/* clang-format on */
+
+static int print_usage(void)
+{
+	int k;
+	struct unit_test *ut_k;
+
+	fprintf(stderr, "usage:\n");
+	for_each_ut (k, ut_k)
+		fprintf(stderr, "\t%s %s %s\n", USAGE_PREFIX, ut_k->ut_name,
+			ut_k->ut_usage);
+
+	return 129;
+}
+
+/*
+ * Issue various trace2 events for testing.
+ *
+ * We assume that these trace2 routines has already been called:
+ *    [] trace2_initialize()      [common-main.c:main()]
+ *    [] trace2_cmd_start()       [common-main.c:main()]
+ *    [] trace2_cmd_name()        [test-tool.c:cmd_main()]
+ *    [] tracd2_cmd_list_config() [test-tool.c:cmd_main()]
+ * So that:
+ *    [] the various trace2 streams are open.
+ *    [] the process SID has been created.
+ *    [] the "version" event has been generated.
+ *    [] the "start" event has been generated.
+ *    [] the "cmd_name" event has been generated.
+ *    [] this writes various "def_param" events for interesting config values.
+ *
+ * We further assume that if we return (rather than exit()), trace2_cmd_exit()
+ * will be called by test-tool.c:cmd_main().
+ */
+int cmd__trace2(int argc, const char **argv)
+{
+	int k;
+	struct unit_test *ut_k;
+
+	argc--; /* skip over "trace2" arg */
+	argv++;
+
+	if (argc)
+		for_each_ut (k, ut_k)
+			if (!strcmp(argv[0], ut_k->ut_name))
+				return ut_k->ut_fn(argc - 1, argv + 1);
+
+	return print_usage();
+}
diff --git a/t/t0210-trace2-normal.sh b/t/t0210-trace2-normal.sh
new file mode 100755
index 0000000000..03a0aedb1d
--- /dev/null
+++ b/t/t0210-trace2-normal.sh
@@ -0,0 +1,135 @@
+#!/bin/sh
+
+test_description='test trace2 facility (normal target)'
+. ./test-lib.sh
+
+# Add t/helper directory to PATH so that we can use a relative
+# path to run nested instances of test-tool.exe (see 004child).
+# This helps with HEREDOC comparisons later.
+TTDIR="$GIT_BUILD_DIR/t/helper/" && export TTDIR
+PATH="$TTDIR:$PATH" && export PATH
+
+# Warning: use of 'test_cmp' may run test-tool.exe and/or git.exe
+# Warning: to do the actual diff/comparison, so the HEREDOCs here
+# Warning: only cover our actual calls to test-tool and/or git.
+# Warning: So you may see extra lines in artifact files when
+# Warning: interactively debugging.
+
+# Turn off any inherited trace2 settings for this test.
+unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT
+unset GIT_TR2_BRIEF
+unset GIT_TR2_CONFIG_PARAMS
+
+V=$(git version | sed -e 's/^git version //') && export V
+
+# There are multiple trace2 targets: normal, perf, and event.
+# Trace2 events will/can be written to each active target (subject
+# to whatever filtering that target decides to do).
+# This script tests the normal target in isolation.
+#
+# Defer setting GIT_TR2 until the actual command line we want to test
+# because hidden git and test-tool commands run by the test harness
+# can contaminate our output.
+
+# Enable "brief" feature which turns off "<clock> <file>:<line> " prefix.
+GIT_TR2_BRIEF=1 && export GIT_TR2_BRIEF
+
+# Basic tests of the trace2 normal stream.  Since this stream is used
+# primarily with printf-style debugging/tracing, we do limited testing
+# here.
+#
+# We do confirm the following API features:
+# [] the 'version <v>' event
+# [] the 'start <argv>' event
+# [] the 'cmd_name <name>' event
+# [] the 'exit <time> code:<code>' event
+# [] the 'atexit <time> code:<code>' event
+#
+# Fields of the form _FIELD_ are tokens that have been replaced (such
+# as the elapsed time).
+
+# Verb 001return
+#
+# Implicit return from cmd_<verb> function propagates <code>.
+
+test_expect_success 'normal stream, return code 0' '
+	test_when_finished "rm trace.normal actual expect" &&
+	GIT_TR2="$(pwd)/trace.normal" test-tool trace2 001return 0 &&
+	perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
+	cat >expect <<-EOF &&
+		version $V
+		start _EXE_ trace2 001return 0
+		cmd_name trace2 (trace2)
+		exit elapsed:_TIME_ code:0
+		atexit elapsed:_TIME_ code:0
+	EOF
+	test_cmp expect actual
+'
+
+test_expect_success 'normal stream, return code 1' '
+	test_when_finished "rm trace.normal actual expect" &&
+	test_must_fail env GIT_TR2="$(pwd)/trace.normal" test-tool trace2 001return 1 &&
+	perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
+	cat >expect <<-EOF &&
+		version $V
+		start _EXE_ trace2 001return 1
+		cmd_name trace2 (trace2)
+		exit elapsed:_TIME_ code:1
+		atexit elapsed:_TIME_ code:1
+	EOF
+	test_cmp expect actual
+'
+
+# Verb 002exit
+#
+# Explicit exit(code) from within cmd_<verb> propagates <code>.
+
+test_expect_success 'normal stream, exit code 0' '
+	test_when_finished "rm trace.normal actual expect" &&
+	GIT_TR2="$(pwd)/trace.normal" test-tool trace2 002exit 0 &&
+	perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
+	cat >expect <<-EOF &&
+		version $V
+		start _EXE_ trace2 002exit 0
+		cmd_name trace2 (trace2)
+		exit elapsed:_TIME_ code:0
+		atexit elapsed:_TIME_ code:0
+	EOF
+	test_cmp expect actual
+'
+
+test_expect_success 'normal stream, exit code 1' '
+	test_when_finished "rm trace.normal actual expect" &&
+	test_must_fail env GIT_TR2="$(pwd)/trace.normal" test-tool trace2 002exit 1 &&
+	perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
+	cat >expect <<-EOF &&
+		version $V
+		start _EXE_ trace2 002exit 1
+		cmd_name trace2 (trace2)
+		exit elapsed:_TIME_ code:1
+		atexit elapsed:_TIME_ code:1
+	EOF
+	test_cmp expect actual
+'
+
+# Verb 003error
+#
+# To the above, add multiple 'error <msg>' events
+
+test_expect_success 'normal stream, error event' '
+	test_when_finished "rm trace.normal actual expect" &&
+	GIT_TR2="$(pwd)/trace.normal" test-tool trace2 003error "hello world" "this is a test" &&
+	perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
+	cat >expect <<-EOF &&
+		version $V
+		start _EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
+		cmd_name trace2 (trace2)
+		error hello world
+		error this is a test
+		exit elapsed:_TIME_ code:0
+		atexit elapsed:_TIME_ code:0
+	EOF
+	test_cmp expect actual
+'
+
+test_done
diff --git a/t/t0210/scrub_normal.perl b/t/t0210/scrub_normal.perl
new file mode 100644
index 0000000000..c65d1a815e
--- /dev/null
+++ b/t/t0210/scrub_normal.perl
@@ -0,0 +1,48 @@
+#!/usr/bin/perl
+#
+# Scrub the variable fields from the normal trace2 output to
+# make testing easier.
+
+use strict;
+use warnings;
+
+my $float = '[0-9]*\.[0-9]+([eE][-+]?[0-9]+)?';
+
+# This code assumes that the trace2 data was written with bare
+# turned on (which omits the "<clock> <file>:<line>" prefix.
+
+while (<>) {
+    # Various messages include an elapsed time in the middle
+    # of the message.  Replace the time with a placeholder to
+    # simplify our HEREDOC in the test script.
+    s/elapsed:$float/elapsed:_TIME_/g;
+
+    my $line = $_;
+
+    # we expect:
+    #    start <argv0> [<argv1> [<argv2> [...]]]
+    #
+    # where argv0 might be a relative or absolute path, with
+    # or without quotes, and platform dependent.  Replace argv0
+    # with a token for HEREDOC matching in the test script.
+
+    if ($line =~ m/^start/) {
+	$line =~ /^start\s+(.*)/;
+	my $argv = $1;
+	$argv =~ m/(\'[^\']*\'|[^ ]+)\s+(.*)/;
+	my $argv_0 = $1;
+	my $argv_rest = $2;
+
+	print "start _EXE_ $argv_rest\n";
+    }
+    elsif ($line =~ m/^cmd_path/) {
+	# Likewise, the 'cmd_path' message breaks out argv[0].
+	#
+	# This line is only emitted when RUNTIME_PREFIX is defined,
+	# so just omit it for testing purposes.
+	# print "cmd_path _EXE_\n";
+    }
+    else {
+	print "$line";
+    }
+}
diff --git a/t/t0211-trace2-perf.sh b/t/t0211-trace2-perf.sh
new file mode 100755
index 0000000000..953e2f7847
--- /dev/null
+++ b/t/t0211-trace2-perf.sh
@@ -0,0 +1,153 @@
+#!/bin/sh
+
+test_description='test trace2 facility (perf target)'
+. ./test-lib.sh
+
+# Add t/helper directory to PATH so that we can use a relative
+# path to run nested instances of test-tool.exe (see 004child).
+# This helps with HEREDOC comparisons later.
+TTDIR="$GIT_BUILD_DIR/t/helper/" && export TTDIR
+PATH="$TTDIR:$PATH" && export PATH
+
+# Warning: use of 'test_cmp' may run test-tool.exe and/or git.exe
+# Warning: to do the actual diff/comparison, so the HEREDOCs here
+# Warning: only cover our actual calls to test-tool and/or git.
+# Warning: So you may see extra lines in artifact files when
+# Warning: interactively debugging.
+
+# Turn off any inherited trace2 settings for this test.
+unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT
+unset GIT_TR2_PERF_BRIEF
+unset GIT_TR2_CONFIG_PARAMS
+
+V=$(git version | sed -e 's/^git version //') && export V
+
+# There are multiple trace2 targets: normal, perf, and event.
+# Trace2 events will/can be written to each active target (subject
+# to whatever filtering that target decides to do).
+# Test each target independently.
+#
+# Defer setting GIT_TR2_PERF until the actual command we want to
+# test because hidden git and test-tool commands in the test
+# harness can contaminate our output.
+
+# Enable "brief" feature which turns off the prefix:
+#     "<clock> <file>:<line> | <nr_parents> | "
+GIT_TR2_PERF_BRIEF=1 && export GIT_TR2_PERF_BRIEF
+
+# Repeat some of the t0210 tests using the perf target stream instead of
+# the normal stream.
+#
+# Tokens here of the form _FIELD_ have been replaced in the observed output.
+
+# Verb 001return
+#
+# Implicit return from cmd_<verb> function propagates <code>.
+
+test_expect_success 'perf stream, return code 0' '
+	test_when_finished "rm trace.perf actual expect" &&
+	GIT_TR2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 0 &&
+	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
+	cat >expect <<-EOF &&
+		d0|main|version|||||$V
+		d0|main|start|||||_EXE_ trace2 001return 0
+		d0|main|cmd_name|||||trace2 (trace2)
+		d0|main|exit||_T_ABS_|||code:0
+		d0|main|atexit||_T_ABS_|||code:0
+	EOF
+	test_cmp expect actual
+'
+
+test_expect_success 'perf stream, return code 1' '
+	test_when_finished "rm trace.perf actual expect" &&
+	test_must_fail env GIT_TR2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 1 &&
+	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
+	cat >expect <<-EOF &&
+		d0|main|version|||||$V
+		d0|main|start|||||_EXE_ trace2 001return 1
+		d0|main|cmd_name|||||trace2 (trace2)
+		d0|main|exit||_T_ABS_|||code:1
+		d0|main|atexit||_T_ABS_|||code:1
+	EOF
+	test_cmp expect actual
+'
+
+# Verb 003error
+#
+# To the above, add multiple 'error <msg>' events
+
+test_expect_success 'perf stream, error event' '
+	test_when_finished "rm trace.perf actual expect" &&
+	GIT_TR2_PERF="$(pwd)/trace.perf" test-tool trace2 003error "hello world" "this is a test" &&
+	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
+	cat >expect <<-EOF &&
+		d0|main|version|||||$V
+		d0|main|start|||||_EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
+		d0|main|cmd_name|||||trace2 (trace2)
+		d0|main|error|||||hello world
+		d0|main|error|||||this is a test
+		d0|main|exit||_T_ABS_|||code:0
+		d0|main|atexit||_T_ABS_|||code:0
+	EOF
+	test_cmp expect actual
+'
+
+# Verb 004child
+#
+# Test nested spawning of child processes.
+#
+# Conceptually, this looks like:
+#    P1: TT trace2 004child
+#    P2: |--- TT trace2 004child
+#    P3:      |--- TT trace2 001return 0
+#
+# Which should generate events:
+#    P1: version
+#    P1: start
+#    P1: cmd_name
+#    P1: child_start
+#        P2: version
+#        P2: start
+#        P2: cmd_name
+#        P2: child_start
+#            P3: version
+#            P3: start
+#            P3: cmd_name
+#            P3: exit
+#            P3: atexit
+#        P2: child_exit
+#        P2: exit
+#        P2: atexit
+#    P1: child_exit
+#    P1: exit
+#    P1: atexit
+
+test_expect_success 'perf stream, child processes' '
+	test_when_finished "rm trace.perf actual expect" &&
+	GIT_TR2_PERF="$(pwd)/trace.perf" test-tool trace2 004child test-tool trace2 004child test-tool trace2 001return 0 &&
+	perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
+	cat >expect <<-EOF &&
+		d0|main|version|||||$V
+		d0|main|start|||||_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0
+		d0|main|cmd_name|||||trace2 (trace2)
+		d0|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 004child test-tool trace2 001return 0
+		d1|main|version|||||$V
+		d1|main|start|||||_EXE_ trace2 004child test-tool trace2 001return 0
+		d1|main|cmd_name|||||trace2 (trace2/trace2)
+		d1|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 001return 0
+		d2|main|version|||||$V
+		d2|main|start|||||_EXE_ trace2 001return 0
+		d2|main|cmd_name|||||trace2 (trace2/trace2/trace2)
+		d2|main|exit||_T_ABS_|||code:0
+		d2|main|atexit||_T_ABS_|||code:0
+		d1|main|child_exit||_T_ABS_|_T_REL_||[ch0] pid:_PID_ code:0
+		d1|main|exit||_T_ABS_|||code:0
+		d1|main|atexit||_T_ABS_|||code:0
+		d0|main|child_exit||_T_ABS_|_T_REL_||[ch0] pid:_PID_ code:0
+		d0|main|exit||_T_ABS_|||code:0
+		d0|main|atexit||_T_ABS_|||code:0
+	EOF
+	test_cmp expect actual
+'
+
+test_done
diff --git a/t/t0211/scrub_perf.perl b/t/t0211/scrub_perf.perl
new file mode 100644
index 0000000000..351af7844e
--- /dev/null
+++ b/t/t0211/scrub_perf.perl
@@ -0,0 +1,76 @@
+#!/usr/bin/perl
+#
+# Scrub the variable fields from the perf trace2 output to
+# make testing easier.
+
+use strict;
+use warnings;
+
+my $qpath = '\'[^\']*\'|[^ ]*';
+
+my $col_depth=0;
+my $col_thread=1;
+my $col_event=2;
+my $col_repo=3;
+my $col_t_abs=4;
+my $col_t_rel=5;
+my $col_category=6;
+my $col_rest=7;
+
+# This code assumes that the trace2 data was written with bare
+# turned on (which omits the "<clock> <file>:<line> | <parents>"
+# prefix.
+
+while (<>) {
+    my @tokens = split /\|/;
+
+    foreach my $col (@tokens) { $col =~ s/^\s+|\s+$//g; }
+
+    if ($tokens[$col_event] =~ m/^start/) {
+	# The 'start' message lists the contents of argv in $col_rest.
+	# On some platforms (Windows), argv[0] is *sometimes* a canonical
+	# absolute path to the EXE rather than the value passed in the
+	# shell script.  Replace it with a placeholder to simplify our
+	# HEREDOC in the test script.
+	my $argv0;
+	my $argvRest;
+	$tokens[$col_rest] =~ s/^($qpath)\W*(.*)/_EXE_ $2/;
+    }
+    elsif ($tokens[$col_event] =~ m/cmd_path/) {
+	# Likewise, the 'cmd_path' message breaks out argv[0].
+	#
+	# This line is only emitted when RUNTIME_PREFIX is defined,
+	# so just omit it for testing purposes.
+	# $tokens[$col_rest] = "_EXE_";
+	goto SKIP_LINE;
+    }
+    elsif ($tokens[$col_event] =~ m/child_exit/) {
+	$tokens[$col_rest] =~ s/ pid:\d* / pid:_PID_ /;
+    }
+    elsif ($tokens[$col_event] =~ m/data/) {
+	if ($tokens[$col_category] =~ m/process/) {
+	    # 'data' and 'data_json' events containing 'process'
+	    # category data are assumed to be platform-specific
+	    # and highly variable.  Just omit them.
+	    goto SKIP_LINE;
+	}
+    }
+
+    # t_abs and t_rel are either blank or a float.  Replace the float
+    # with a constant for matching the HEREDOC in the test script.
+    if ($tokens[$col_t_abs] =~ m/\d/) {
+	$tokens[$col_t_abs] = "_T_ABS_";
+    }
+    if ($tokens[$col_t_rel] =~ m/\d/) {
+	$tokens[$col_t_rel] = "_T_REL_";
+    }
+
+    my $out;
+
+    $out = join('|', @tokens);
+    print "$out\n";
+
+  SKIP_LINE:
+}
+
+
diff --git a/t/t0212-trace2-event.sh b/t/t0212-trace2-event.sh
new file mode 100755
index 0000000000..028b6c5671
--- /dev/null
+++ b/t/t0212-trace2-event.sh
@@ -0,0 +1,236 @@
+#!/bin/sh
+
+test_description='test trace2 facility'
+. ./test-lib.sh
+
+perl -MJSON::PP -e 0 >/dev/null 2>&1 && test_set_prereq JSON_PP
+
+# Add t/helper directory to PATH so that we can use a relative
+# path to run nested instances of test-tool.exe (see 004child).
+# This helps with HEREDOC comparisons later.
+TTDIR="$GIT_BUILD_DIR/t/helper/" && export TTDIR
+PATH="$TTDIR:$PATH" && export PATH
+
+# Warning: use of 'test_cmp' may run test-tool.exe and/or git.exe
+# Warning: to do the actual diff/comparison, so the HEREDOCs here
+# Warning: only cover our actual calls to test-tool and/or git.
+# Warning: So you may see extra lines in artifact files when
+# Warning: interactively debugging.
+
+# Turn off any inherited trace2 settings for this test.
+unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT
+unset GIT_TR2_BARE
+unset GIT_TR2_CONFIG_PARAMS
+
+V=$(git version | sed -e 's/^git version //') && export V
+
+# There are multiple trace2 targets: normal, perf, and event.
+# Trace2 events will/can be written to each active target (subject
+# to whatever filtering that target decides to do).
+# Test each target independently.
+#
+# Defer setting GIT_TR2_PERF until the actual command we want to
+# test because hidden git and test-tool commands in the test
+# harness can contaminate our output.
+
+# We don't bother repeating the 001return and 002exit tests, since they
+# have coverage in the normal and perf targets.
+
+# Verb 003error
+#
+# To the above, add multiple 'error <msg>' events
+
+test_expect_success JSON_PP 'event stream, error event' '
+	test_when_finished "rm trace.event actual expect" &&
+	GIT_TR2_EVENT="$(pwd)/trace.event" test-tool trace2 003error "hello world" "this is a test" &&
+	perl "$TEST_DIRECTORY/t0212/parse_events.perl" <trace.event >actual &&
+	sed -e "s/^|//" >expect <<-EOF &&
+	|VAR1 = {
+	|  "_SID0_":{
+	|    "argv":[
+	|      "_EXE_",
+	|      "trace2",
+	|      "003error",
+	|      "hello world",
+	|      "this is a test"
+	|    ],
+	|    "errors":[
+	|      "%s",
+	|      "%s"
+	|    ],
+	|    "exit_code":0,
+	|    "hierarchy":"trace2",
+	|    "name":"trace2",
+	|    "version":"$V"
+	|  }
+	|};
+	EOF
+	test_cmp expect actual
+'
+
+# Verb 004child
+#
+# Test nested spawning of child processes.
+#
+# Conceptually, this looks like:
+#    P1: TT trace2 004child
+#    P2: |--- TT trace2 004child
+#    P3:      |--- TT trace2 001return 0
+
+test_expect_success JSON_PP 'event stream, return code 0' '
+	test_when_finished "rm trace.event actual expect" &&
+	GIT_TR2_EVENT="$(pwd)/trace.event" test-tool trace2 004child test-tool trace2 004child test-tool trace2 001return 0 &&
+	perl "$TEST_DIRECTORY/t0212/parse_events.perl" <trace.event >actual &&
+	sed -e "s/^|//" >expect <<-EOF &&
+	|VAR1 = {
+	|  "_SID0_":{
+	|    "argv":[
+	|      "_EXE_",
+	|      "trace2",
+	|      "004child",
+	|      "test-tool",
+	|      "trace2",
+	|      "004child",
+	|      "test-tool",
+	|      "trace2",
+	|      "001return",
+	|      "0"
+	|    ],
+	|    "child":{
+	|      "0":{
+	|        "child_argv":[
+	|          "_EXE_",
+	|          "trace2",
+	|          "004child",
+	|          "test-tool",
+	|          "trace2",
+	|          "001return",
+	|          "0"
+	|        ],
+	|        "child_class":"?",
+	|        "child_code":0,
+	|        "use_shell":0
+	|      }
+	|    },
+	|    "exit_code":0,
+	|    "hierarchy":"trace2",
+	|    "name":"trace2",
+	|    "version":"$V"
+	|  },
+	|  "_SID0_/_SID1_":{
+	|    "argv":[
+	|      "_EXE_",
+	|      "trace2",
+	|      "004child",
+	|      "test-tool",
+	|      "trace2",
+	|      "001return",
+	|      "0"
+	|    ],
+	|    "child":{
+	|      "0":{
+	|        "child_argv":[
+	|          "_EXE_",
+	|          "trace2",
+	|          "001return",
+	|          "0"
+	|        ],
+	|        "child_class":"?",
+	|        "child_code":0,
+	|        "use_shell":0
+	|      }
+	|    },
+	|    "exit_code":0,
+	|    "hierarchy":"trace2/trace2",
+	|    "name":"trace2",
+	|    "version":"$V"
+	|  },
+	|  "_SID0_/_SID1_/_SID2_":{
+	|    "argv":[
+	|      "_EXE_",
+	|      "trace2",
+	|      "001return",
+	|      "0"
+	|    ],
+	|    "exit_code":0,
+	|    "hierarchy":"trace2/trace2/trace2",
+	|    "name":"trace2",
+	|    "version":"$V"
+	|  }
+	|};
+	EOF
+	test_cmp expect actual
+'
+
+# Test listing of all "interesting" config settings.
+
+test_expect_success JSON_PP 'event stream, list config' '
+	test_when_finished "rm trace.event actual expect" &&
+	git config --local t0212.abc 1 &&
+	git config --local t0212.def "hello world" &&
+	GIT_TR2_EVENT="$(pwd)/trace.event" GIT_TR2_CONFIG_PARAMS="t0212.*" test-tool trace2 001return 0 &&
+	perl "$TEST_DIRECTORY/t0212/parse_events.perl" <trace.event >actual &&
+	sed -e "s/^|//" >expect <<-EOF &&
+	|VAR1 = {
+	|  "_SID0_":{
+	|    "argv":[
+	|      "_EXE_",
+	|      "trace2",
+	|      "001return",
+	|      "0"
+	|    ],
+	|    "exit_code":0,
+	|    "hierarchy":"trace2",
+	|    "name":"trace2",
+	|    "params":[
+	|      {
+	|        "param":"t0212.abc",
+	|        "value":"1"
+	|      },
+	|      {
+	|        "param":"t0212.def",
+	|        "value":"hello world"
+	|      }
+	|    ],
+	|    "version":"$V"
+	|  }
+	|};
+	EOF
+	test_cmp expect actual
+'
+
+test_expect_success JSON_PP 'basic trace2_data' '
+	test_when_finished "rm trace.event actual expect" &&
+	GIT_TR2_EVENT="$(pwd)/trace.event" test-tool trace2 006data test_category k1 v1 test_category k2 v2 &&
+	perl "$TEST_DIRECTORY/t0212/parse_events.perl" <trace.event >actual &&
+	sed -e "s/^|//" >expect <<-EOF &&
+	|VAR1 = {
+	|  "_SID0_":{
+	|    "argv":[
+	|      "_EXE_",
+	|      "trace2",
+	|      "006data",
+	|      "test_category",
+	|      "k1",
+	|      "v1",
+	|      "test_category",
+	|      "k2",
+	|      "v2"
+	|    ],
+	|    "data":{
+	|      "test_category":{
+	|        "k1":"v1",
+	|        "k2":"v2"
+	|      }
+	|    },
+	|    "exit_code":0,
+	|    "hierarchy":"trace2",
+	|    "name":"trace2",
+	|    "version":"$V"
+	|  }
+	|};
+	EOF
+	test_cmp expect actual
+'
+
+test_done
diff --git a/t/t0212/parse_events.perl b/t/t0212/parse_events.perl
new file mode 100644
index 0000000000..a2776ba216
--- /dev/null
+++ b/t/t0212/parse_events.perl
@@ -0,0 +1,251 @@
+#!/usr/bin/perl
+#
+# Parse event stream and convert individual events into a summary
+# record for the process.
+#
+# Git.exe generates one or more "event" records for each API method,
+# such as "start <argv>" and "exit <code>", during the life of the git
+# process.  Additionally, the input may contain interleaved events
+# from multiple concurrent git processes and/or multiple threads from
+# within a git process.
+#
+# Accumulate events for each process (based on its unique SID) in a
+# dictionary and emit process summary records.
+#
+# Convert some of the variable fields (such as elapsed time) into
+# placeholders (or omit them) to make HEREDOC comparisons easier in
+# the test scripts.
+#
+# We may also omit fields not (currently) useful for testing purposes.
+
+use strict;
+use warnings;
+use JSON::PP;
+use Data::Dumper;
+use Getopt::Long;
+
+# The version of the trace2 event target format that we understand.
+# This is reported in the 'version' event in the 'evt' field.
+# It comes from the GIT_TR2_EVENT_VERSION macro in trace2/tr2_tgt_event.c
+my $evt_version = '1';
+
+my $show_children = 1;
+my $show_exec     = 1;
+my $show_threads  = 1;
+
+# A hack to generate test HEREDOC data for pasting into the test script.
+# Usage:
+#    cd "t/trash directory.t0212-trace2-event"
+#    $TT trace ... >trace.event
+#    VV=$(../../git.exe version | sed -e 's/^git version //')
+#    perl ../t0212/parse_events.perl --HEREDOC --VERSION=$VV <trace.event >heredoc
+# Then paste heredoc into your new test.
+
+my $gen_heredoc = 0;
+my $gen_version = '';
+
+GetOptions("children!" => \$show_children,
+	   "exec!"     => \$show_exec,
+	   "threads!"  => \$show_threads,
+	   "HEREDOC!"  => \$gen_heredoc,
+	   "VERSION=s" => \$gen_version    )
+    or die("Error in command line arguments\n");
+
+
+# SIDs contains timestamps and PIDs of the process and its parents.
+# This makes it difficult to match up in a HEREDOC in the test script.
+# Build a map from actual SIDs to predictable constant values and yet
+# keep the parent/child relationships.  For example:
+# {..., "sid":"1539706952458276-8652", ...}
+# {..., "sid":"1539706952458276-8652/1539706952649493-15452", ...}
+# becomes:
+# {..., "sid":"_SID1_", ...}
+# {..., "sid":"_SID1_/_SID2_", ...}
+my $sid_map;
+my $sid_count = 0;
+
+my $processes;
+
+while (<>) {
+    my $line = decode_json( $_ );
+
+    my $sid = "";
+    my $sid_sep = "";
+
+    my $raw_sid = $line->{'sid'};
+    my @raw_sid_parts = split /\//, $raw_sid;
+    foreach my $raw_sid_k (@raw_sid_parts) {
+	if (!exists $sid_map->{$raw_sid_k}) {
+	    $sid_map->{$raw_sid_k} = '_SID' . $sid_count . '_';
+	    $sid_count++;
+	}
+	$sid = $sid . $sid_sep . $sid_map->{$raw_sid_k};
+	$sid_sep = '/';
+    }
+    
+    my $event = $line->{'event'};
+
+    if ($event eq 'version') {
+	$processes->{$sid}->{'version'} = $line->{'exe'};
+	if ($gen_heredoc == 1 && $gen_version eq $line->{'exe'}) {
+	    # If we are generating data FOR the test script, replace
+	    # the reported git.exe version with a reference to an
+	    # environment variable.  When our output is pasted into
+	    # the test script, it will then be expanded in future
+	    # test runs to the THEN current version of git.exe.
+	    # We assume that the test script uses env var $V.
+	    $processes->{$sid}->{'version'} = "\$V";
+	}
+    }
+
+    elsif ($event eq 'start') {
+	$processes->{$sid}->{'argv'} = $line->{'argv'};
+	$processes->{$sid}->{'argv'}[0] = "_EXE_";
+    }
+
+    elsif ($event eq 'exit') {
+	$processes->{$sid}->{'exit_code'} = $line->{'code'};
+    }
+
+    elsif ($event eq 'atexit') {
+	$processes->{$sid}->{'exit_code'} = $line->{'code'};
+    }
+
+    elsif ($event eq 'error') {
+	# For HEREDOC purposes, use the error message format string if
+	# available, rather than the formatted message (which probably
+	# has an absolute pathname).
+	if (exists $line->{'fmt'}) {
+	    push( @{$processes->{$sid}->{'errors'}}, $line->{'fmt'} );
+	}
+	elsif (exists $line->{'msg'}) {
+	    push( @{$processes->{$sid}->{'errors'}}, $line->{'msg'} );
+	}
+    }
+
+    elsif ($event eq 'cmd_path') {
+	## $processes->{$sid}->{'path'} = $line->{'path'};
+	#
+	# Like in the 'start' event, we need to replace the value of
+	# argv[0] with a token for HEREDOC purposes.  However, the
+	# event is only emitted when RUNTIME_PREFIX is defined, so
+	# just omit it for testing purposes.
+	# $processes->{$sid}->{'path'} = "_EXE_";
+    }
+    
+    elsif ($event eq 'cmd_name') {
+	$processes->{$sid}->{'name'} = $line->{'name'};
+	$processes->{$sid}->{'hierarchy'} = $line->{'hierarchy'};
+    }
+
+    elsif ($event eq 'alias') {
+	$processes->{$sid}->{'alias'}->{'key'} = $line->{'alias'};
+	$processes->{$sid}->{'alias'}->{'argv'} = $line->{'argv'};
+    }
+
+    elsif ($event eq 'def_param') {
+	my $kv;
+	$kv->{'param'} = $line->{'param'};
+	$kv->{'value'} = $line->{'value'};
+	push( @{$processes->{$sid}->{'params'}}, $kv );
+    }
+
+    elsif ($event eq 'child_start') {
+	if ($show_children == 1) {
+	    $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'child_class'} = $line->{'child_class'};
+	    $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'child_argv'} = $line->{'argv'};
+	    $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'child_argv'}[0] = "_EXE_";
+	    $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'use_shell'} = $line->{'use_shell'} ? 1 : 0;
+	}
+    }
+
+    elsif ($event eq 'child_exit') {
+	if ($show_children == 1) {
+	    $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'child_code'} = $line->{'code'};
+	}
+    }
+
+    # TODO decide what information we want to test from thread events.
+
+    elsif ($event eq 'thread_start') {
+	if ($show_threads == 1) {
+	}
+    }
+
+    elsif ($event eq 'thread_exit') {
+	if ($show_threads == 1) {
+	}
+    }
+
+    # TODO decide what information we want to test from exec events.
+
+    elsif ($event eq 'exec') {
+	if ($show_exec == 1) {
+	}
+    }
+
+    elsif ($event eq 'exec_result') {
+	if ($show_exec == 1) {
+	}
+    }
+
+    elsif ($event eq 'def_param') {
+	# Accumulate parameter key/value pairs by key rather than in an array
+	# so that we get overwrite (last one wins) effects.
+	$processes->{$sid}->{'params'}->{$line->{'param'}} = $line->{'value'};
+    }
+
+    elsif ($event eq 'def_repo') {
+	# $processes->{$sid}->{'repos'}->{$line->{'repo'}} = $line->{'worktree'};
+	$processes->{$sid}->{'repos'}->{$line->{'repo'}} = "_WORKTREE_";
+    }
+
+    # A series of potentially nested and threaded region and data events
+    # is fundamentally incompatibile with the type of summary record we
+    # are building in this script.  Since they are intended for
+    # perf-trace-like analysis rather than a result summary, we ignore
+    # most of them here.
+
+    # elsif ($event eq 'region_enter') {
+    # }
+    # elsif ($event eq 'region_leave') {
+    # }
+
+    elsif ($event eq 'data') {
+	my $cat = $line->{'category'};
+	if ($cat eq 'test_category') {
+	    
+	    my $key = $line->{'key'};
+	    my $value = $line->{'value'};
+	    $processes->{$sid}->{'data'}->{$cat}->{$key} = $value;
+	}
+    }
+
+    # This trace2 target does not emit 'printf' events.
+    #
+    # elsif ($event eq 'printf') {
+    # }
+}
+
+# Dump the resulting hash into something that we can compare against
+# in the test script.  These options make Dumper output look a little
+# bit like JSON.  Also convert variable references of the form "$VAR*"
+# so that the matching HEREDOC doesn't need to escape it.
+
+$Data::Dumper::Sortkeys = 1;
+$Data::Dumper::Indent = 1;
+$Data::Dumper::Purity = 1;
+$Data::Dumper::Pair = ':';
+
+my $out = Dumper($processes);
+$out =~ s/'/"/g;
+$out =~ s/\$VAR/VAR/g;
+
+# Finally, if we're running this script to generate (manually confirmed)
+# data to add to the test script, guard the indentation.
+
+if ($gen_heredoc == 1) {
+    $out =~ s/^/\t\|/gms;
+}
+
+print $out;
-- 
2.11.4.GIT