@matheusbsbs / matheus-bagliano / commits / a15860dca3

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>

Jeff Hostetler committed Feb 22, 2019 at 14:25 UTC a15860dca3f194bb87e2d6028264791a4cec031d
10 files changed +1175
Makefile
+1
@@ -773,6 +773,7 @@ TEST_BUILTINS_OBJS += test-string-list.o
773 TEST_BUILTINS_OBJS += test-submodule-config.o
774 TEST_BUILTINS_OBJS += test-submodule-nested-repo-config.o
775 TEST_BUILTINS_OBJS += test-subprocess.o
776 +TEST_BUILTINS_OBJS += test-trace2.o
777 TEST_BUILTINS_OBJS += test-urlmatch-normalization.o
778 TEST_BUILTINS_OBJS += test-xml-encode.o
779 TEST_BUILTINS_OBJS += test-wildmatch.o
t/helper/test-tool.c
+1
@@ -52,6 +52,7 @@ static struct test_cmd cmds[] = {
52 { "submodule-config", cmd__submodule_config },
53 { "submodule-nested-repo-config", cmd__submodule_nested_repo_config },
54 { "subprocess", cmd__subprocess },
55 + { "trace2", cmd__trace2 },
56 { "urlmatch-normalization", cmd__urlmatch_normalization },
57 { "xml-encode", cmd__xml_encode },
58 { "wildmatch", cmd__wildmatch },
t/helper/test-tool.h
+1
@@ -48,6 +48,7 @@ int cmd__string_list(int argc, const char **argv);
48 int cmd__submodule_config(int argc, const char **argv);
49 int cmd__submodule_nested_repo_config(int argc, const char **argv);
50 int cmd__subprocess(int argc, const char **argv);
51 +int cmd__trace2(int argc, const char **argv);
52 int cmd__urlmatch_normalization(int argc, const char **argv);
53 int cmd__xml_encode(int argc, const char **argv);
54 int cmd__wildmatch(int argc, const char **argv);
t/helper/test-trace2.c new
+273
@@ -0,0 +1,273 @@
1 +#include "test-tool.h"
2 +#include "cache.h"
3 +#include "argv-array.h"
4 +#include "run-command.h"
5 +#include "exec-cmd.h"
6 +#include "config.h"
7 +
8 +typedef int(fn_unit_test)(int argc, const char **argv);
9 +
10 +struct unit_test {
11 + fn_unit_test *ut_fn;
12 + const char *ut_name;
13 + const char *ut_usage;
14 +};
15 +
16 +#define MyOk 0
17 +#define MyError 1
18 +
19 +static int get_i(int *p_value, const char *data)
20 +{
21 + char *endptr;
22 +
23 + if (!data || !*data)
24 + return MyError;
25 +
26 + *p_value = strtol(data, &endptr, 10);
27 + if (*endptr || errno == ERANGE)
28 + return MyError;
29 +
30 + return MyOk;
31 +}
32 +
33 +/*
34 + * Cause process to exit with the requested value via "return".
35 + *
36 + * Rely on test-tool.c:cmd_main() to call trace2_cmd_exit()
37 + * with our result.
38 + *
39 + * Test harness can confirm:
40 + * [] the process-exit value.
41 + * [] the "code" field in the "exit" trace2 event.
42 + * [] the "code" field in the "atexit" trace2 event.
43 + * [] the "name" field in the "cmd_name" trace2 event.
44 + * [] "def_param" events for all of the "interesting" pre-defined
45 + * config settings.
46 + */
47 +static int ut_001return(int argc, const char **argv)
48 +{
49 + int rc;
50 +
51 + if (get_i(&rc, argv[0]))
52 + die("expect <exit_code>");
53 +
54 + return rc;
55 +}
56 +
57 +/*
58 + * Cause the process to exit with the requested value via "exit()".
59 + *
60 + * Test harness can confirm:
61 + * [] the "code" field in the "exit" trace2 event.
62 + * [] the "code" field in the "atexit" trace2 event.
63 + * [] the "name" field in the "cmd_name" trace2 event.
64 + * [] "def_param" events for all of the "interesting" pre-defined
65 + * config settings.
66 + */
67 +static int ut_002exit(int argc, const char **argv)
68 +{
69 + int rc;
70 +
71 + if (get_i(&rc, argv[0]))
72 + die("expect <exit_code>");
73 +
74 + exit(rc);
75 +}
76 +
77 +/*
78 + * Send an "error" event with each value in argv. Normally, git only issues
79 + * a single "error" event immediately before issuing an "exit" event (such
80 + * as in die() or BUG()), but multiple "error" events are allowed.
81 + *
82 + * Test harness can confirm:
83 + * [] a trace2 "error" event for each value in argv.
84 + * [] the "name" field in the "cmd_name" trace2 event.
85 + * [] (optional) the file:line in the "exit" event refers to this function.
86 + */
87 +static int ut_003error(int argc, const char **argv)
88 +{
89 + int k;
90 +
91 + if (!argv[0] || !*argv[0])
92 + die("expect <error_message>");
93 +
94 + for (k = 0; k < argc; k++)
95 + error("%s", argv[k]);
96 +
97 + return 0;
98 +}
99 +
100 +/*
101 + * Run a child process and wait for it to finish and exit with its return code.
102 + * test-tool trace2 004child [<child-command-line>]
103 + *
104 + * For example:
105 + * test-tool trace2 004child git version
106 + * test-tool trace2 004child test-tool trace2 001return 0
107 + * test-tool trace2 004child test-tool trace2 004child test-tool trace2 004child
108 + * test-tool trace2 004child git -c alias.xyz=version xyz
109 + *
110 + * Test harness can confirm:
111 + * [] the "name" field in the "cmd_name" trace2 event.
112 + * [] that the outer process has a single component SID (or depth "d0" in
113 + * the PERF stream).
114 + * [] that "child_start" and "child_exit" events are generated for the child.
115 + * [] if the child process is an instrumented executable:
116 + * [] that "version", "start", ..., "exit", and "atexit" events are
117 + * generated by the child process.
118 + * [] that the child process events have a multiple component SID (or
119 + * depth "dN+1" in the PERF stream).
120 + * [] that the child exit code is propagated to the parent process "exit"
121 + * and "atexit" events..
122 + * [] (optional) that the "t_abs" field in the child process "atexit" event
123 + * is less than the "t_rel" field in the "child_exit" event of the parent
124 + * process.
125 + * [] if the child process is like the alias example above,
126 + * [] (optional) the child process attempts to run "git-xyx" as a dashed
127 + * command.
128 + * [] the child process emits an "alias" event with "xyz" => "version"
129 + * [] the child process runs "git version" as a child process.
130 + * [] the child process has a 3 component SID (or depth "d2" in the PERF
131 + * stream).
132 + */
133 +static int ut_004child(int argc, const char **argv)
134 +{
135 + int result;
136 +
137 + /*
138 + * Allow empty <child_command_line> so we can do arbitrarily deep
139 + * command nesting and let the last one be null.
140 + */
141 + if (!argc)
142 + return 0;
143 +
144 + result = run_command_v_opt(argv, 0);
145 + exit(result);
146 +}
147 +
148 +/*
149 + * Exec a git command. This may either create a child process (Windows)
150 + * or replace the existing process.
151 + * test-tool trace2 005exec <git_command_args>
152 + *
153 + * For example:
154 + * test-tool trace2 005exec version
155 + *
156 + * Test harness can confirm (on Windows):
157 + * [] the "name" field in the "cmd_name" trace2 event.
158 + * [] that the outer process has a single component SID (or depth "d0" in
159 + * the PERF stream).
160 + * [] that "exec" and "exec_result" events are generated for the child
161 + * process (since the Windows compatibility layer fakes an exec() with
162 + * a CreateProcess(), WaitForSingleObject(), and exit()).
163 + * [] that the child process has multiple component SID (or depth "dN+1"
164 + * in the PERF stream).
165 + *
166 + * Test harness can confirm (on platforms with a real exec() function):
167 + * [] TODO talk about process replacement and how it affects SID.
168 + */
169 +static int ut_005exec(int argc, const char **argv)
170 +{
171 + int result;
172 +
173 + if (!argc)
174 + return 0;
175 +
176 + result = execv_git_cmd(argv);
177 + return result;
178 +}
179 +
180 +static int ut_006data(int argc, const char **argv)
181 +{
182 + const char *usage_error =
183 + "expect <cat0> <k0> <v0> [<cat1> <k1> <v1> [...]]";
184 +
185 + if (argc % 3 != 0)
186 + die("%s", usage_error);
187 +
188 + while (argc) {
189 + if (!argv[0] || !*argv[0] || !argv[1] || !*argv[1] ||
190 + !argv[2] || !*argv[2])
191 + die("%s", usage_error);
192 +
193 + trace2_data_string(argv[0], the_repository, argv[1], argv[2]);
194 + argv += 3;
195 + argc -= 3;
196 + }
197 +
198 + return 0;
199 +}
200 +
201 +/*
202 + * Usage:
203 + * test-tool trace2 <ut_name_1> <ut_usage_1>
204 + * test-tool trace2 <ut_name_2> <ut_usage_2>
205 + * ...
206 + */
207 +#define USAGE_PREFIX "test-tool trace2"
208 +
209 +/* clang-format off */
210 +static struct unit_test ut_table[] = {
211 + { ut_001return, "001return", "<exit_code>" },
212 + { ut_002exit, "002exit", "<exit_code>" },
213 + { ut_003error, "003error", "<error_message>+" },
214 + { ut_004child, "004child", "[<child_command_line>]" },
215 + { ut_005exec, "005exec", "<git_command_args>" },
216 + { ut_006data, "006data", "[<category> <key> <value>]+" },
217 +};
218 +/* clang-format on */
219 +
220 +/* clang-format off */
221 +#define for_each_ut(k, ut_k) \
222 + for (k = 0, ut_k = &ut_table[k]; \
223 + k < ARRAY_SIZE(ut_table); \
224 + k++, ut_k = &ut_table[k])
225 +/* clang-format on */
226 +
227 +static int print_usage(void)
228 +{
229 + int k;
230 + struct unit_test *ut_k;
231 +
232 + fprintf(stderr, "usage:\n");
233 + for_each_ut (k, ut_k)
234 + fprintf(stderr, "\t%s %s %s\n", USAGE_PREFIX, ut_k->ut_name,
235 + ut_k->ut_usage);
236 +
237 + return 129;
238 +}
239 +
240 +/*
241 + * Issue various trace2 events for testing.
242 + *
243 + * We assume that these trace2 routines has already been called:
244 + * [] trace2_initialize() [common-main.c:main()]
245 + * [] trace2_cmd_start() [common-main.c:main()]
246 + * [] trace2_cmd_name() [test-tool.c:cmd_main()]
247 + * [] tracd2_cmd_list_config() [test-tool.c:cmd_main()]
248 + * So that:
249 + * [] the various trace2 streams are open.
250 + * [] the process SID has been created.
251 + * [] the "version" event has been generated.
252 + * [] the "start" event has been generated.
253 + * [] the "cmd_name" event has been generated.
254 + * [] this writes various "def_param" events for interesting config values.
255 + *
256 + * We further assume that if we return (rather than exit()), trace2_cmd_exit()
257 + * will be called by test-tool.c:cmd_main().
258 + */
259 +int cmd__trace2(int argc, const char **argv)
260 +{
261 + int k;
262 + struct unit_test *ut_k;
263 +
264 + argc--; /* skip over "trace2" arg */
265 + argv++;
266 +
267 + if (argc)
268 + for_each_ut (k, ut_k)
269 + if (!strcmp(argv[0], ut_k->ut_name))
270 + return ut_k->ut_fn(argc - 1, argv + 1);
271 +
272 + return print_usage();
273 +}
t/t0210-trace2-normal.sh new
+135
@@ -0,0 +1,135 @@
1 +#!/bin/sh
2 +
3 +test_description='test trace2 facility (normal target)'
4 +. ./test-lib.sh
5 +
6 +# Add t/helper directory to PATH so that we can use a relative
7 +# path to run nested instances of test-tool.exe (see 004child).
8 +# This helps with HEREDOC comparisons later.
9 +TTDIR="$GIT_BUILD_DIR/t/helper/" && export TTDIR
10 +PATH="$TTDIR:$PATH" && export PATH
11 +
12 +# Warning: use of 'test_cmp' may run test-tool.exe and/or git.exe
13 +# Warning: to do the actual diff/comparison, so the HEREDOCs here
14 +# Warning: only cover our actual calls to test-tool and/or git.
15 +# Warning: So you may see extra lines in artifact files when
16 +# Warning: interactively debugging.
17 +
18 +# Turn off any inherited trace2 settings for this test.
19 +unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT
20 +unset GIT_TR2_BRIEF
21 +unset GIT_TR2_CONFIG_PARAMS
22 +
23 +V=$(git version | sed -e 's/^git version //') && export V
24 +
25 +# There are multiple trace2 targets: normal, perf, and event.
26 +# Trace2 events will/can be written to each active target (subject
27 +# to whatever filtering that target decides to do).
28 +# This script tests the normal target in isolation.
29 +#
30 +# Defer setting GIT_TR2 until the actual command line we want to test
31 +# because hidden git and test-tool commands run by the test harness
32 +# can contaminate our output.
33 +
34 +# Enable "brief" feature which turns off "<clock> <file>:<line> " prefix.
35 +GIT_TR2_BRIEF=1 && export GIT_TR2_BRIEF
36 +
37 +# Basic tests of the trace2 normal stream. Since this stream is used
38 +# primarily with printf-style debugging/tracing, we do limited testing
39 +# here.
40 +#
41 +# We do confirm the following API features:
42 +# [] the 'version <v>' event
43 +# [] the 'start <argv>' event
44 +# [] the 'cmd_name <name>' event
45 +# [] the 'exit <time> code:<code>' event
46 +# [] the 'atexit <time> code:<code>' event
47 +#
48 +# Fields of the form _FIELD_ are tokens that have been replaced (such
49 +# as the elapsed time).
50 +
51 +# Verb 001return
52 +#
53 +# Implicit return from cmd_<verb> function propagates <code>.
54 +
55 +test_expect_success 'normal stream, return code 0' '
56 + test_when_finished "rm trace.normal actual expect" &&
57 + GIT_TR2="$(pwd)/trace.normal" test-tool trace2 001return 0 &&
58 + perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
59 + cat >expect <<-EOF &&
60 + version $V
61 + start _EXE_ trace2 001return 0
62 + cmd_name trace2 (trace2)
63 + exit elapsed:_TIME_ code:0
64 + atexit elapsed:_TIME_ code:0
65 + EOF
66 + test_cmp expect actual
67 +'
68 +
69 +test_expect_success 'normal stream, return code 1' '
70 + test_when_finished "rm trace.normal actual expect" &&
71 + test_must_fail env GIT_TR2="$(pwd)/trace.normal" test-tool trace2 001return 1 &&
72 + perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
73 + cat >expect <<-EOF &&
74 + version $V
75 + start _EXE_ trace2 001return 1
76 + cmd_name trace2 (trace2)
77 + exit elapsed:_TIME_ code:1
78 + atexit elapsed:_TIME_ code:1
79 + EOF
80 + test_cmp expect actual
81 +'
82 +
83 +# Verb 002exit
84 +#
85 +# Explicit exit(code) from within cmd_<verb> propagates <code>.
86 +
87 +test_expect_success 'normal stream, exit code 0' '
88 + test_when_finished "rm trace.normal actual expect" &&
89 + GIT_TR2="$(pwd)/trace.normal" test-tool trace2 002exit 0 &&
90 + perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
91 + cat >expect <<-EOF &&
92 + version $V
93 + start _EXE_ trace2 002exit 0
94 + cmd_name trace2 (trace2)
95 + exit elapsed:_TIME_ code:0
96 + atexit elapsed:_TIME_ code:0
97 + EOF
98 + test_cmp expect actual
99 +'
100 +
101 +test_expect_success 'normal stream, exit code 1' '
102 + test_when_finished "rm trace.normal actual expect" &&
103 + test_must_fail env GIT_TR2="$(pwd)/trace.normal" test-tool trace2 002exit 1 &&
104 + perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
105 + cat >expect <<-EOF &&
106 + version $V
107 + start _EXE_ trace2 002exit 1
108 + cmd_name trace2 (trace2)
109 + exit elapsed:_TIME_ code:1
110 + atexit elapsed:_TIME_ code:1
111 + EOF
112 + test_cmp expect actual
113 +'
114 +
115 +# Verb 003error
116 +#
117 +# To the above, add multiple 'error <msg>' events
118 +
119 +test_expect_success 'normal stream, error event' '
120 + test_when_finished "rm trace.normal actual expect" &&
121 + GIT_TR2="$(pwd)/trace.normal" test-tool trace2 003error "hello world" "this is a test" &&
122 + perl "$TEST_DIRECTORY/t0210/scrub_normal.perl" <trace.normal >actual &&
123 + cat >expect <<-EOF &&
124 + version $V
125 + start _EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
126 + cmd_name trace2 (trace2)
127 + error hello world
128 + error this is a test
129 + exit elapsed:_TIME_ code:0
130 + atexit elapsed:_TIME_ code:0
131 + EOF
132 + test_cmp expect actual
133 +'
134 +
135 +test_done
t/t0210/scrub_normal.perl new
+48
@@ -0,0 +1,48 @@
1 +#!/usr/bin/perl
2 +#
3 +# Scrub the variable fields from the normal trace2 output to
4 +# make testing easier.
5 +
6 +use strict;
7 +use warnings;
8 +
9 +my $float = '[0-9]*\.[0-9]+([eE][-+]?[0-9]+)?';
10 +
11 +# This code assumes that the trace2 data was written with bare
12 +# turned on (which omits the "<clock> <file>:<line>" prefix.
13 +
14 +while (<>) {
15 + # Various messages include an elapsed time in the middle
16 + # of the message. Replace the time with a placeholder to
17 + # simplify our HEREDOC in the test script.
18 + s/elapsed:$float/elapsed:_TIME_/g;
19 +
20 + my $line = $_;
21 +
22 + # we expect:
23 + # start <argv0> [<argv1> [<argv2> [...]]]
24 + #
25 + # where argv0 might be a relative or absolute path, with
26 + # or without quotes, and platform dependent. Replace argv0
27 + # with a token for HEREDOC matching in the test script.
28 +
29 + if ($line =~ m/^start/) {
30 + $line =~ /^start\s+(.*)/;
31 + my $argv = $1;
32 + $argv =~ m/(\'[^\']*\'|[^ ]+)\s+(.*)/;
33 + my $argv_0 = $1;
34 + my $argv_rest = $2;
35 +
36 + print "start _EXE_ $argv_rest\n";
37 + }
38 + elsif ($line =~ m/^cmd_path/) {
39 + # Likewise, the 'cmd_path' message breaks out argv[0].
40 + #
41 + # This line is only emitted when RUNTIME_PREFIX is defined,
42 + # so just omit it for testing purposes.
43 + # print "cmd_path _EXE_\n";
44 + }
45 + else {
46 + print "$line";
47 + }
48 +}
t/t0211-trace2-perf.sh new
+153
@@ -0,0 +1,153 @@
1 +#!/bin/sh
2 +
3 +test_description='test trace2 facility (perf target)'
4 +. ./test-lib.sh
5 +
6 +# Add t/helper directory to PATH so that we can use a relative
7 +# path to run nested instances of test-tool.exe (see 004child).
8 +# This helps with HEREDOC comparisons later.
9 +TTDIR="$GIT_BUILD_DIR/t/helper/" && export TTDIR
10 +PATH="$TTDIR:$PATH" && export PATH
11 +
12 +# Warning: use of 'test_cmp' may run test-tool.exe and/or git.exe
13 +# Warning: to do the actual diff/comparison, so the HEREDOCs here
14 +# Warning: only cover our actual calls to test-tool and/or git.
15 +# Warning: So you may see extra lines in artifact files when
16 +# Warning: interactively debugging.
17 +
18 +# Turn off any inherited trace2 settings for this test.
19 +unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT
20 +unset GIT_TR2_PERF_BRIEF
21 +unset GIT_TR2_CONFIG_PARAMS
22 +
23 +V=$(git version | sed -e 's/^git version //') && export V
24 +
25 +# There are multiple trace2 targets: normal, perf, and event.
26 +# Trace2 events will/can be written to each active target (subject
27 +# to whatever filtering that target decides to do).
28 +# Test each target independently.
29 +#
30 +# Defer setting GIT_TR2_PERF until the actual command we want to
31 +# test because hidden git and test-tool commands in the test
32 +# harness can contaminate our output.
33 +
34 +# Enable "brief" feature which turns off the prefix:
35 +# "<clock> <file>:<line> | <nr_parents> | "
36 +GIT_TR2_PERF_BRIEF=1 && export GIT_TR2_PERF_BRIEF
37 +
38 +# Repeat some of the t0210 tests using the perf target stream instead of
39 +# the normal stream.
40 +#
41 +# Tokens here of the form _FIELD_ have been replaced in the observed output.
42 +
43 +# Verb 001return
44 +#
45 +# Implicit return from cmd_<verb> function propagates <code>.
46 +
47 +test_expect_success 'perf stream, return code 0' '
48 + test_when_finished "rm trace.perf actual expect" &&
49 + GIT_TR2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 0 &&
50 + perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
51 + cat >expect <<-EOF &&
52 + d0|main|version|||||$V
53 + d0|main|start|||||_EXE_ trace2 001return 0
54 + d0|main|cmd_name|||||trace2 (trace2)
55 + d0|main|exit||_T_ABS_|||code:0
56 + d0|main|atexit||_T_ABS_|||code:0
57 + EOF
58 + test_cmp expect actual
59 +'
60 +
61 +test_expect_success 'perf stream, return code 1' '
62 + test_when_finished "rm trace.perf actual expect" &&
63 + test_must_fail env GIT_TR2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 1 &&
64 + perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
65 + cat >expect <<-EOF &&
66 + d0|main|version|||||$V
67 + d0|main|start|||||_EXE_ trace2 001return 1
68 + d0|main|cmd_name|||||trace2 (trace2)
69 + d0|main|exit||_T_ABS_|||code:1
70 + d0|main|atexit||_T_ABS_|||code:1
71 + EOF
72 + test_cmp expect actual
73 +'
74 +
75 +# Verb 003error
76 +#
77 +# To the above, add multiple 'error <msg>' events
78 +
79 +test_expect_success 'perf stream, error event' '
80 + test_when_finished "rm trace.perf actual expect" &&
81 + GIT_TR2_PERF="$(pwd)/trace.perf" test-tool trace2 003error "hello world" "this is a test" &&
82 + perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
83 + cat >expect <<-EOF &&
84 + d0|main|version|||||$V
85 + d0|main|start|||||_EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
86 + d0|main|cmd_name|||||trace2 (trace2)
87 + d0|main|error|||||hello world
88 + d0|main|error|||||this is a test
89 + d0|main|exit||_T_ABS_|||code:0
90 + d0|main|atexit||_T_ABS_|||code:0
91 + EOF
92 + test_cmp expect actual
93 +'
94 +
95 +# Verb 004child
96 +#
97 +# Test nested spawning of child processes.
98 +#
99 +# Conceptually, this looks like:
100 +# P1: TT trace2 004child
101 +# P2: |--- TT trace2 004child
102 +# P3: |--- TT trace2 001return 0
103 +#
104 +# Which should generate events:
105 +# P1: version
106 +# P1: start
107 +# P1: cmd_name
108 +# P1: child_start
109 +# P2: version
110 +# P2: start
111 +# P2: cmd_name
112 +# P2: child_start
113 +# P3: version
114 +# P3: start
115 +# P3: cmd_name
116 +# P3: exit
117 +# P3: atexit
118 +# P2: child_exit
119 +# P2: exit
120 +# P2: atexit
121 +# P1: child_exit
122 +# P1: exit
123 +# P1: atexit
124 +
125 +test_expect_success 'perf stream, child processes' '
126 + test_when_finished "rm trace.perf actual expect" &&
127 + GIT_TR2_PERF="$(pwd)/trace.perf" test-tool trace2 004child test-tool trace2 004child test-tool trace2 001return 0 &&
128 + perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
129 + cat >expect <<-EOF &&
130 + d0|main|version|||||$V
131 + d0|main|start|||||_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0
132 + d0|main|cmd_name|||||trace2 (trace2)
133 + d0|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 004child test-tool trace2 001return 0
134 + d1|main|version|||||$V
135 + d1|main|start|||||_EXE_ trace2 004child test-tool trace2 001return 0
136 + d1|main|cmd_name|||||trace2 (trace2/trace2)
137 + d1|main|child_start||_T_ABS_|||[ch0] class:? argv: test-tool trace2 001return 0
138 + d2|main|version|||||$V
139 + d2|main|start|||||_EXE_ trace2 001return 0
140 + d2|main|cmd_name|||||trace2 (trace2/trace2/trace2)
141 + d2|main|exit||_T_ABS_|||code:0
142 + d2|main|atexit||_T_ABS_|||code:0
143 + d1|main|child_exit||_T_ABS_|_T_REL_||[ch0] pid:_PID_ code:0
144 + d1|main|exit||_T_ABS_|||code:0
145 + d1|main|atexit||_T_ABS_|||code:0
146 + d0|main|child_exit||_T_ABS_|_T_REL_||[ch0] pid:_PID_ code:0
147 + d0|main|exit||_T_ABS_|||code:0
148 + d0|main|atexit||_T_ABS_|||code:0
149 + EOF
150 + test_cmp expect actual
151 +'
152 +
153 +test_done
t/t0211/scrub_perf.perl new
+76
@@ -0,0 +1,76 @@
1 +#!/usr/bin/perl
2 +#
3 +# Scrub the variable fields from the perf trace2 output to
4 +# make testing easier.
5 +
6 +use strict;
7 +use warnings;
8 +
9 +my $qpath = '\'[^\']*\'|[^ ]*';
10 +
11 +my $col_depth=0;
12 +my $col_thread=1;
13 +my $col_event=2;
14 +my $col_repo=3;
15 +my $col_t_abs=4;
16 +my $col_t_rel=5;
17 +my $col_category=6;
18 +my $col_rest=7;
19 +
20 +# This code assumes that the trace2 data was written with bare
21 +# turned on (which omits the "<clock> <file>:<line> | <parents>"
22 +# prefix.
23 +
24 +while (<>) {
25 + my @tokens = split /\|/;
26 +
27 + foreach my $col (@tokens) { $col =~ s/^\s+|\s+$//g; }
28 +
29 + if ($tokens[$col_event] =~ m/^start/) {
30 + # The 'start' message lists the contents of argv in $col_rest.
31 + # On some platforms (Windows), argv[0] is *sometimes* a canonical
32 + # absolute path to the EXE rather than the value passed in the
33 + # shell script. Replace it with a placeholder to simplify our
34 + # HEREDOC in the test script.
35 + my $argv0;
36 + my $argvRest;
37 + $tokens[$col_rest] =~ s/^($qpath)\W*(.*)/_EXE_ $2/;
38 + }
39 + elsif ($tokens[$col_event] =~ m/cmd_path/) {
40 + # Likewise, the 'cmd_path' message breaks out argv[0].
41 + #
42 + # This line is only emitted when RUNTIME_PREFIX is defined,
43 + # so just omit it for testing purposes.
44 + # $tokens[$col_rest] = "_EXE_";
45 + goto SKIP_LINE;
46 + }
47 + elsif ($tokens[$col_event] =~ m/child_exit/) {
48 + $tokens[$col_rest] =~ s/ pid:\d* / pid:_PID_ /;
49 + }
50 + elsif ($tokens[$col_event] =~ m/data/) {
51 + if ($tokens[$col_category] =~ m/process/) {
52 + # 'data' and 'data_json' events containing 'process'
53 + # category data are assumed to be platform-specific
54 + # and highly variable. Just omit them.
55 + goto SKIP_LINE;
56 + }
57 + }
58 +
59 + # t_abs and t_rel are either blank or a float. Replace the float
60 + # with a constant for matching the HEREDOC in the test script.
61 + if ($tokens[$col_t_abs] =~ m/\d/) {
62 + $tokens[$col_t_abs] = "_T_ABS_";
63 + }
64 + if ($tokens[$col_t_rel] =~ m/\d/) {
65 + $tokens[$col_t_rel] = "_T_REL_";
66 + }
67 +
68 + my $out;
69 +
70 + $out = join('|', @tokens);
71 + print "$out\n";
72 +
73 + SKIP_LINE:
74 +}
75 +
76 +
t/t0212-trace2-event.sh new
+236
@@ -0,0 +1,236 @@
1 +#!/bin/sh
2 +
3 +test_description='test trace2 facility'
4 +. ./test-lib.sh
5 +
6 +perl -MJSON::PP -e 0 >/dev/null 2>&1 && test_set_prereq JSON_PP
7 +
8 +# Add t/helper directory to PATH so that we can use a relative
9 +# path to run nested instances of test-tool.exe (see 004child).
10 +# This helps with HEREDOC comparisons later.
11 +TTDIR="$GIT_BUILD_DIR/t/helper/" && export TTDIR
12 +PATH="$TTDIR:$PATH" && export PATH
13 +
14 +# Warning: use of 'test_cmp' may run test-tool.exe and/or git.exe
15 +# Warning: to do the actual diff/comparison, so the HEREDOCs here
16 +# Warning: only cover our actual calls to test-tool and/or git.
17 +# Warning: So you may see extra lines in artifact files when
18 +# Warning: interactively debugging.
19 +
20 +# Turn off any inherited trace2 settings for this test.
21 +unset GIT_TR2 GIT_TR2_PERF GIT_TR2_EVENT
22 +unset GIT_TR2_BARE
23 +unset GIT_TR2_CONFIG_PARAMS
24 +
25 +V=$(git version | sed -e 's/^git version //') && export V
26 +
27 +# There are multiple trace2 targets: normal, perf, and event.
28 +# Trace2 events will/can be written to each active target (subject
29 +# to whatever filtering that target decides to do).
30 +# Test each target independently.
31 +#
32 +# Defer setting GIT_TR2_PERF until the actual command we want to
33 +# test because hidden git and test-tool commands in the test
34 +# harness can contaminate our output.
35 +
36 +# We don't bother repeating the 001return and 002exit tests, since they
37 +# have coverage in the normal and perf targets.
38 +
39 +# Verb 003error
40 +#
41 +# To the above, add multiple 'error <msg>' events
42 +
43 +test_expect_success JSON_PP 'event stream, error event' '
44 + test_when_finished "rm trace.event actual expect" &&
45 + GIT_TR2_EVENT="$(pwd)/trace.event" test-tool trace2 003error "hello world" "this is a test" &&
46 + perl "$TEST_DIRECTORY/t0212/parse_events.perl" <trace.event >actual &&
47 + sed -e "s/^|//" >expect <<-EOF &&
48 + |VAR1 = {
49 + | "_SID0_":{
50 + | "argv":[
51 + | "_EXE_",
52 + | "trace2",
53 + | "003error",
54 + | "hello world",
55 + | "this is a test"
56 + | ],
57 + | "errors":[
58 + | "%s",
59 + | "%s"
60 + | ],
61 + | "exit_code":0,
62 + | "hierarchy":"trace2",
63 + | "name":"trace2",
64 + | "version":"$V"
65 + | }
66 + |};
67 + EOF
68 + test_cmp expect actual
69 +'
70 +
71 +# Verb 004child
72 +#
73 +# Test nested spawning of child processes.
74 +#
75 +# Conceptually, this looks like:
76 +# P1: TT trace2 004child
77 +# P2: |--- TT trace2 004child
78 +# P3: |--- TT trace2 001return 0
79 +
80 +test_expect_success JSON_PP 'event stream, return code 0' '
81 + test_when_finished "rm trace.event actual expect" &&
82 + GIT_TR2_EVENT="$(pwd)/trace.event" test-tool trace2 004child test-tool trace2 004child test-tool trace2 001return 0 &&
83 + perl "$TEST_DIRECTORY/t0212/parse_events.perl" <trace.event >actual &&
84 + sed -e "s/^|//" >expect <<-EOF &&
85 + |VAR1 = {
86 + | "_SID0_":{
87 + | "argv":[
88 + | "_EXE_",
89 + | "trace2",
90 + | "004child",
91 + | "test-tool",
92 + | "trace2",
93 + | "004child",
94 + | "test-tool",
95 + | "trace2",
96 + | "001return",
97 + | "0"
98 + | ],
99 + | "child":{
100 + | "0":{
101 + | "child_argv":[
102 + | "_EXE_",
103 + | "trace2",
104 + | "004child",
105 + | "test-tool",
106 + | "trace2",
107 + | "001return",
108 + | "0"
109 + | ],
110 + | "child_class":"?",
111 + | "child_code":0,
112 + | "use_shell":0
113 + | }
114 + | },
115 + | "exit_code":0,
116 + | "hierarchy":"trace2",
117 + | "name":"trace2",
118 + | "version":"$V"
119 + | },
120 + | "_SID0_/_SID1_":{
121 + | "argv":[
122 + | "_EXE_",
123 + | "trace2",
124 + | "004child",
125 + | "test-tool",
126 + | "trace2",
127 + | "001return",
128 + | "0"
129 + | ],
130 + | "child":{
131 + | "0":{
132 + | "child_argv":[
133 + | "_EXE_",
134 + | "trace2",
135 + | "001return",
136 + | "0"
137 + | ],
138 + | "child_class":"?",
139 + | "child_code":0,
140 + | "use_shell":0
141 + | }
142 + | },
143 + | "exit_code":0,
144 + | "hierarchy":"trace2/trace2",
145 + | "name":"trace2",
146 + | "version":"$V"
147 + | },
148 + | "_SID0_/_SID1_/_SID2_":{
149 + | "argv":[
150 + | "_EXE_",
151 + | "trace2",
152 + | "001return",
153 + | "0"
154 + | ],
155 + | "exit_code":0,
156 + | "hierarchy":"trace2/trace2/trace2",
157 + | "name":"trace2",
158 + | "version":"$V"
159 + | }
160 + |};
161 + EOF
162 + test_cmp expect actual
163 +'
164 +
165 +# Test listing of all "interesting" config settings.
166 +
167 +test_expect_success JSON_PP 'event stream, list config' '
168 + test_when_finished "rm trace.event actual expect" &&
169 + git config --local t0212.abc 1 &&
170 + git config --local t0212.def "hello world" &&
171 + GIT_TR2_EVENT="$(pwd)/trace.event" GIT_TR2_CONFIG_PARAMS="t0212.*" test-tool trace2 001return 0 &&
172 + perl "$TEST_DIRECTORY/t0212/parse_events.perl" <trace.event >actual &&
173 + sed -e "s/^|//" >expect <<-EOF &&
174 + |VAR1 = {
175 + | "_SID0_":{
176 + | "argv":[
177 + | "_EXE_",
178 + | "trace2",
179 + | "001return",
180 + | "0"
181 + | ],
182 + | "exit_code":0,
183 + | "hierarchy":"trace2",
184 + | "name":"trace2",
185 + | "params":[
186 + | {
187 + | "param":"t0212.abc",
188 + | "value":"1"
189 + | },
190 + | {
191 + | "param":"t0212.def",
192 + | "value":"hello world"
193 + | }
194 + | ],
195 + | "version":"$V"
196 + | }
197 + |};
198 + EOF
199 + test_cmp expect actual
200 +'
201 +
202 +test_expect_success JSON_PP 'basic trace2_data' '
203 + test_when_finished "rm trace.event actual expect" &&
204 + GIT_TR2_EVENT="$(pwd)/trace.event" test-tool trace2 006data test_category k1 v1 test_category k2 v2 &&
205 + perl "$TEST_DIRECTORY/t0212/parse_events.perl" <trace.event >actual &&
206 + sed -e "s/^|//" >expect <<-EOF &&
207 + |VAR1 = {
208 + | "_SID0_":{
209 + | "argv":[
210 + | "_EXE_",
211 + | "trace2",
212 + | "006data",
213 + | "test_category",
214 + | "k1",
215 + | "v1",
216 + | "test_category",
217 + | "k2",
218 + | "v2"
219 + | ],
220 + | "data":{
221 + | "test_category":{
222 + | "k1":"v1",
223 + | "k2":"v2"
224 + | }
225 + | },
226 + | "exit_code":0,
227 + | "hierarchy":"trace2",
228 + | "name":"trace2",
229 + | "version":"$V"
230 + | }
231 + |};
232 + EOF
233 + test_cmp expect actual
234 +'
235 +
236 +test_done
t/t0212/parse_events.perl new
+251
@@ -0,0 +1,251 @@
1 +#!/usr/bin/perl
2 +#
3 +# Parse event stream and convert individual events into a summary
4 +# record for the process.
5 +#
6 +# Git.exe generates one or more "event" records for each API method,
7 +# such as "start <argv>" and "exit <code>", during the life of the git
8 +# process. Additionally, the input may contain interleaved events
9 +# from multiple concurrent git processes and/or multiple threads from
10 +# within a git process.
11 +#
12 +# Accumulate events for each process (based on its unique SID) in a
13 +# dictionary and emit process summary records.
14 +#
15 +# Convert some of the variable fields (such as elapsed time) into
16 +# placeholders (or omit them) to make HEREDOC comparisons easier in
17 +# the test scripts.
18 +#
19 +# We may also omit fields not (currently) useful for testing purposes.
20 +
21 +use strict;
22 +use warnings;
23 +use JSON::PP;
24 +use Data::Dumper;
25 +use Getopt::Long;
26 +
27 +# The version of the trace2 event target format that we understand.
28 +# This is reported in the 'version' event in the 'evt' field.
29 +# It comes from the GIT_TR2_EVENT_VERSION macro in trace2/tr2_tgt_event.c
30 +my $evt_version = '1';
31 +
32 +my $show_children = 1;
33 +my $show_exec = 1;
34 +my $show_threads = 1;
35 +
36 +# A hack to generate test HEREDOC data for pasting into the test script.
37 +# Usage:
38 +# cd "t/trash directory.t0212-trace2-event"
39 +# $TT trace ... >trace.event
40 +# VV=$(../../git.exe version | sed -e 's/^git version //')
41 +# perl ../t0212/parse_events.perl --HEREDOC --VERSION=$VV <trace.event >heredoc
42 +# Then paste heredoc into your new test.
43 +
44 +my $gen_heredoc = 0;
45 +my $gen_version = '';
46 +
47 +GetOptions("children!" => \$show_children,
48 + "exec!" => \$show_exec,
49 + "threads!" => \$show_threads,
50 + "HEREDOC!" => \$gen_heredoc,
51 + "VERSION=s" => \$gen_version )
52 + or die("Error in command line arguments\n");
53 +
54 +
55 +# SIDs contains timestamps and PIDs of the process and its parents.
56 +# This makes it difficult to match up in a HEREDOC in the test script.
57 +# Build a map from actual SIDs to predictable constant values and yet
58 +# keep the parent/child relationships. For example:
59 +# {..., "sid":"1539706952458276-8652", ...}
60 +# {..., "sid":"1539706952458276-8652/1539706952649493-15452", ...}
61 +# becomes:
62 +# {..., "sid":"_SID1_", ...}
63 +# {..., "sid":"_SID1_/_SID2_", ...}
64 +my $sid_map;
65 +my $sid_count = 0;
66 +
67 +my $processes;
68 +
69 +while (<>) {
70 + my $line = decode_json( $_ );
71 +
72 + my $sid = "";
73 + my $sid_sep = "";
74 +
75 + my $raw_sid = $line->{'sid'};
76 + my @raw_sid_parts = split /\//, $raw_sid;
77 + foreach my $raw_sid_k (@raw_sid_parts) {
78 + if (!exists $sid_map->{$raw_sid_k}) {
79 + $sid_map->{$raw_sid_k} = '_SID' . $sid_count . '_';
80 + $sid_count++;
81 + }
82 + $sid = $sid . $sid_sep . $sid_map->{$raw_sid_k};
83 + $sid_sep = '/';
84 + }
85 +
86 + my $event = $line->{'event'};
87 +
88 + if ($event eq 'version') {
89 + $processes->{$sid}->{'version'} = $line->{'exe'};
90 + if ($gen_heredoc == 1 && $gen_version eq $line->{'exe'}) {
91 + # If we are generating data FOR the test script, replace
92 + # the reported git.exe version with a reference to an
93 + # environment variable. When our output is pasted into
94 + # the test script, it will then be expanded in future
95 + # test runs to the THEN current version of git.exe.
96 + # We assume that the test script uses env var $V.
97 + $processes->{$sid}->{'version'} = "\$V";
98 + }
99 + }
100 +
101 + elsif ($event eq 'start') {
102 + $processes->{$sid}->{'argv'} = $line->{'argv'};
103 + $processes->{$sid}->{'argv'}[0] = "_EXE_";
104 + }
105 +
106 + elsif ($event eq 'exit') {
107 + $processes->{$sid}->{'exit_code'} = $line->{'code'};
108 + }
109 +
110 + elsif ($event eq 'atexit') {
111 + $processes->{$sid}->{'exit_code'} = $line->{'code'};
112 + }
113 +
114 + elsif ($event eq 'error') {
115 + # For HEREDOC purposes, use the error message format string if
116 + # available, rather than the formatted message (which probably
117 + # has an absolute pathname).
118 + if (exists $line->{'fmt'}) {
119 + push( @{$processes->{$sid}->{'errors'}}, $line->{'fmt'} );
120 + }
121 + elsif (exists $line->{'msg'}) {
122 + push( @{$processes->{$sid}->{'errors'}}, $line->{'msg'} );
123 + }
124 + }
125 +
126 + elsif ($event eq 'cmd_path') {
127 + ## $processes->{$sid}->{'path'} = $line->{'path'};
128 + #
129 + # Like in the 'start' event, we need to replace the value of
130 + # argv[0] with a token for HEREDOC purposes. However, the
131 + # event is only emitted when RUNTIME_PREFIX is defined, so
132 + # just omit it for testing purposes.
133 + # $processes->{$sid}->{'path'} = "_EXE_";
134 + }
135 +
136 + elsif ($event eq 'cmd_name') {
137 + $processes->{$sid}->{'name'} = $line->{'name'};
138 + $processes->{$sid}->{'hierarchy'} = $line->{'hierarchy'};
139 + }
140 +
141 + elsif ($event eq 'alias') {
142 + $processes->{$sid}->{'alias'}->{'key'} = $line->{'alias'};
143 + $processes->{$sid}->{'alias'}->{'argv'} = $line->{'argv'};
144 + }
145 +
146 + elsif ($event eq 'def_param') {
147 + my $kv;
148 + $kv->{'param'} = $line->{'param'};
149 + $kv->{'value'} = $line->{'value'};
150 + push( @{$processes->{$sid}->{'params'}}, $kv );
151 + }
152 +
153 + elsif ($event eq 'child_start') {
154 + if ($show_children == 1) {
155 + $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'child_class'} = $line->{'child_class'};
156 + $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'child_argv'} = $line->{'argv'};
157 + $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'child_argv'}[0] = "_EXE_";
158 + $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'use_shell'} = $line->{'use_shell'} ? 1 : 0;
159 + }
160 + }
161 +
162 + elsif ($event eq 'child_exit') {
163 + if ($show_children == 1) {
164 + $processes->{$sid}->{'child'}->{$line->{'child_id'}}->{'child_code'} = $line->{'code'};
165 + }
166 + }
167 +
168 + # TODO decide what information we want to test from thread events.
169 +
170 + elsif ($event eq 'thread_start') {
171 + if ($show_threads == 1) {
172 + }
173 + }
174 +
175 + elsif ($event eq 'thread_exit') {
176 + if ($show_threads == 1) {
177 + }
178 + }
179 +
180 + # TODO decide what information we want to test from exec events.
181 +
182 + elsif ($event eq 'exec') {
183 + if ($show_exec == 1) {
184 + }
185 + }
186 +
187 + elsif ($event eq 'exec_result') {
188 + if ($show_exec == 1) {
189 + }
190 + }
191 +
192 + elsif ($event eq 'def_param') {
193 + # Accumulate parameter key/value pairs by key rather than in an array
194 + # so that we get overwrite (last one wins) effects.
195 + $processes->{$sid}->{'params'}->{$line->{'param'}} = $line->{'value'};
196 + }
197 +
198 + elsif ($event eq 'def_repo') {
199 + # $processes->{$sid}->{'repos'}->{$line->{'repo'}} = $line->{'worktree'};
200 + $processes->{$sid}->{'repos'}->{$line->{'repo'}} = "_WORKTREE_";
201 + }
202 +
203 + # A series of potentially nested and threaded region and data events
204 + # is fundamentally incompatibile with the type of summary record we
205 + # are building in this script. Since they are intended for
206 + # perf-trace-like analysis rather than a result summary, we ignore
207 + # most of them here.
208 +
209 + # elsif ($event eq 'region_enter') {
210 + # }
211 + # elsif ($event eq 'region_leave') {
212 + # }
213 +
214 + elsif ($event eq 'data') {
215 + my $cat = $line->{'category'};
216 + if ($cat eq 'test_category') {
217 +
218 + my $key = $line->{'key'};
219 + my $value = $line->{'value'};
220 + $processes->{$sid}->{'data'}->{$cat}->{$key} = $value;
221 + }
222 + }
223 +
224 + # This trace2 target does not emit 'printf' events.
225 + #
226 + # elsif ($event eq 'printf') {
227 + # }
228 +}
229 +
230 +# Dump the resulting hash into something that we can compare against
231 +# in the test script. These options make Dumper output look a little
232 +# bit like JSON. Also convert variable references of the form "$VAR*"
233 +# so that the matching HEREDOC doesn't need to escape it.
234 +
235 +$Data::Dumper::Sortkeys = 1;
236 +$Data::Dumper::Indent = 1;
237 +$Data::Dumper::Purity = 1;
238 +$Data::Dumper::Pair = ':';
239 +
240 +my $out = Dumper($processes);
241 +$out =~ s/'/"/g;
242 +$out =~ s/\$VAR/VAR/g;
243 +
244 +# Finally, if we're running this script to generate (manually confirmed)
245 +# data to add to the test script, guard the indentation.
246 +
247 +if ($gen_heredoc == 1) {
248 + $out =~ s/^/\t\|/gms;
249 +}
250 +
251 +print $out;