]> git.ipfire.org Git - thirdparty/git.git/blame - t/t0211-trace2-perf.sh
t0211: test URL redacting in PERF format
[thirdparty/git.git] / t / t0211-trace2-perf.sh
CommitLineData
a15860dc
JH
1#!/bin/sh
2
3test_description='test trace2 facility (perf target)'
0033ab3f 4
c73e7f80 5TEST_PASSES_SANITIZE_LEAK=false
a15860dc
JH
6. ./test-lib.sh
7
bce9db6d 8# Turn off any inherited trace2 settings for this test.
e4b75d6a
SG
9sane_unset GIT_TRACE2 GIT_TRACE2_PERF GIT_TRACE2_EVENT
10sane_unset GIT_TRACE2_PERF_BRIEF
11sane_unset GIT_TRACE2_CONFIG_PARAMS
bce9db6d 12
a15860dc
JH
13# Add t/helper directory to PATH so that we can use a relative
14# path to run nested instances of test-tool.exe (see 004child).
15# This helps with HEREDOC comparisons later.
16TTDIR="$GIT_BUILD_DIR/t/helper/" && export TTDIR
17PATH="$TTDIR:$PATH" && export PATH
18
19# Warning: use of 'test_cmp' may run test-tool.exe and/or git.exe
20# Warning: to do the actual diff/comparison, so the HEREDOCs here
21# Warning: only cover our actual calls to test-tool and/or git.
22# Warning: So you may see extra lines in artifact files when
23# Warning: interactively debugging.
24
a15860dc
JH
25V=$(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#
e4b75d6a 32# Defer setting GIT_TRACE2_PERF until the actual command we want to
a15860dc
JH
33# test because hidden git and test-tool commands in the test
34# harness can contaminate our output.
35
36# Enable "brief" feature which turns off the prefix:
37# "<clock> <file>:<line> | <nr_parents> | "
e4b75d6a 38GIT_TRACE2_PERF_BRIEF=1 && export GIT_TRACE2_PERF_BRIEF
a15860dc
JH
39
40# Repeat some of the t0210 tests using the perf target stream instead of
41# the normal stream.
42#
43# Tokens here of the form _FIELD_ have been replaced in the observed output.
44
45# Verb 001return
46#
47# Implicit return from cmd_<verb> function propagates <code>.
48
49test_expect_success 'perf stream, return code 0' '
50 test_when_finished "rm trace.perf actual expect" &&
e4b75d6a 51 GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 0 &&
a15860dc
JH
52 perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
53 cat >expect <<-EOF &&
54 d0|main|version|||||$V
39f43177 55 d0|main|start||_T_ABS_|||_EXE_ trace2 001return 0
a15860dc
JH
56 d0|main|cmd_name|||||trace2 (trace2)
57 d0|main|exit||_T_ABS_|||code:0
58 d0|main|atexit||_T_ABS_|||code:0
59 EOF
60 test_cmp expect actual
61'
62
63test_expect_success 'perf stream, return code 1' '
64 test_when_finished "rm trace.perf actual expect" &&
e4b75d6a 65 test_must_fail env GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 1 &&
a15860dc
JH
66 perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
67 cat >expect <<-EOF &&
68 d0|main|version|||||$V
39f43177 69 d0|main|start||_T_ABS_|||_EXE_ trace2 001return 1
a15860dc
JH
70 d0|main|cmd_name|||||trace2 (trace2)
71 d0|main|exit||_T_ABS_|||code:1
72 d0|main|atexit||_T_ABS_|||code:1
73 EOF
74 test_cmp expect actual
75'
76
77# Verb 003error
78#
79# To the above, add multiple 'error <msg>' events
80
81test_expect_success 'perf stream, error event' '
82 test_when_finished "rm trace.perf actual expect" &&
e4b75d6a 83 GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 003error "hello world" "this is a test" &&
a15860dc
JH
84 perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
85 cat >expect <<-EOF &&
86 d0|main|version|||||$V
39f43177 87 d0|main|start||_T_ABS_|||_EXE_ trace2 003error '\''hello world'\'' '\''this is a test'\''
a15860dc
JH
88 d0|main|cmd_name|||||trace2 (trace2)
89 d0|main|error|||||hello world
90 d0|main|error|||||this is a test
91 d0|main|exit||_T_ABS_|||code:0
92 d0|main|atexit||_T_ABS_|||code:0
93 EOF
94 test_cmp expect actual
95'
96
97# Verb 004child
98#
99# Test nested spawning of child processes.
100#
101# Conceptually, this looks like:
102# P1: TT trace2 004child
103# P2: |--- TT trace2 004child
104# P3: |--- TT trace2 001return 0
105#
106# Which should generate events:
107# P1: version
108# P1: start
109# P1: cmd_name
110# P1: child_start
111# P2: version
112# P2: start
113# P2: cmd_name
114# P2: child_start
115# P3: version
116# P3: start
117# P3: cmd_name
118# P3: exit
119# P3: atexit
120# P2: child_exit
121# P2: exit
122# P2: atexit
123# P1: child_exit
124# P1: exit
125# P1: atexit
126
127test_expect_success 'perf stream, child processes' '
128 test_when_finished "rm trace.perf actual expect" &&
e4b75d6a 129 GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 004child test-tool trace2 004child test-tool trace2 001return 0 &&
a15860dc
JH
130 perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
131 cat >expect <<-EOF &&
132 d0|main|version|||||$V
39f43177 133 d0|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 004child test-tool trace2 001return 0
a15860dc 134 d0|main|cmd_name|||||trace2 (trace2)
742ed633 135 d0|main|child_start||_T_ABS_|||[ch0] class:? argv:[test-tool trace2 004child test-tool trace2 001return 0]
a15860dc 136 d1|main|version|||||$V
39f43177 137 d1|main|start||_T_ABS_|||_EXE_ trace2 004child test-tool trace2 001return 0
a15860dc 138 d1|main|cmd_name|||||trace2 (trace2/trace2)
742ed633 139 d1|main|child_start||_T_ABS_|||[ch0] class:? argv:[test-tool trace2 001return 0]
a15860dc 140 d2|main|version|||||$V
39f43177 141 d2|main|start||_T_ABS_|||_EXE_ trace2 001return 0
a15860dc
JH
142 d2|main|cmd_name|||||trace2 (trace2/trace2/trace2)
143 d2|main|exit||_T_ABS_|||code:0
144 d2|main|atexit||_T_ABS_|||code:0
145 d1|main|child_exit||_T_ABS_|_T_REL_||[ch0] pid:_PID_ code:0
146 d1|main|exit||_T_ABS_|||code:0
147 d1|main|atexit||_T_ABS_|||code:0
148 d0|main|child_exit||_T_ABS_|_T_REL_||[ch0] pid:_PID_ code:0
149 d0|main|exit||_T_ABS_|||code:0
150 d0|main|atexit||_T_ABS_|||code:0
151 EOF
152 test_cmp expect actual
153'
154
e4b75d6a 155sane_unset GIT_TRACE2_PERF_BRIEF
bce9db6d
JH
156
157# Now test without environment variables and get all Trace2 settings
158# from the global config.
159
160test_expect_success 'using global config, perf stream, return code 0' '
161 test_when_finished "rm trace.perf actual expect" &&
162 test_config_global trace2.perfBrief 1 &&
163 test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&
164 test-tool trace2 001return 0 &&
165 perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
166 cat >expect <<-EOF &&
167 d0|main|version|||||$V
168 d0|main|start||_T_ABS_|||_EXE_ trace2 001return 0
169 d0|main|cmd_name|||||trace2 (trace2)
170 d0|main|exit||_T_ABS_|||code:0
171 d0|main|atexit||_T_ABS_|||code:0
172 EOF
173 test_cmp expect actual
174'
175
8ad57564
JH
176# Exercise the stopwatch timers in a loop and confirm that we have
177# as many start/stop intervals as expected. We cannot really test the
178# actual (total, min, max) timer values, so we have to assume that they
179# are good, but we can verify the interval count.
180#
181# The timer "test/test1" should only emit a global summary "timer" event.
182# The timer "test/test2" should emit per-thread "th_timer" events and a
183# global summary "timer" event.
184
185have_timer_event () {
186 thread=$1 event=$2 category=$3 name=$4 intervals=$5 file=$6 &&
187
188 pattern="d0|${thread}|${event}||||${category}|name:${name} intervals:${intervals}" &&
189
190 grep "${pattern}" ${file}
191}
192
193test_expect_success 'stopwatch timer test/test1' '
194 test_when_finished "rm trace.perf actual" &&
195 test_config_global trace2.perfBrief 1 &&
196 test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&
197
198 # Use the timer "test1" 5 times from "main".
199 test-tool trace2 100timer 5 10 &&
200
201 perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
202
203 have_timer_event "main" "timer" "test" "test1" 5 actual
204'
205
e48a21df 206test_expect_success PTHREADS 'stopwatch timer test/test2' '
8ad57564
JH
207 test_when_finished "rm trace.perf actual" &&
208 test_config_global trace2.perfBrief 1 &&
209 test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&
210
211 # Use the timer "test2" 5 times each in 3 threads.
212 test-tool trace2 101timer 5 10 3 &&
213
214 perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
215
216 # So we should have 3 per-thread events of 5 each.
217 have_timer_event "th01:ut_101" "th_timer" "test" "test2" 5 actual &&
218 have_timer_event "th02:ut_101" "th_timer" "test" "test2" 5 actual &&
219 have_timer_event "th03:ut_101" "th_timer" "test" "test2" 5 actual &&
220
221 # And we should have 15 total uses.
222 have_timer_event "main" "timer" "test" "test2" 15 actual
223'
224
81071626
JH
225# Exercise the global counters and confirm that we get the expected values.
226#
227# The counter "test/test1" should only emit a global summary "counter" event.
228# The counter "test/test2" could emit per-thread "th_counter" events and a
229# global summary "counter" event.
230
231have_counter_event () {
232 thread=$1 event=$2 category=$3 name=$4 value=$5 file=$6 &&
233
234 pattern="d0|${thread}|${event}||||${category}|name:${name} value:${value}" &&
235
236 grep "${patern}" ${file}
237}
238
239test_expect_success 'global counter test/test1' '
240 test_when_finished "rm trace.perf actual" &&
241 test_config_global trace2.perfBrief 1 &&
242 test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&
243
244 # Use the counter "test1" and add n integers.
245 test-tool trace2 200counter 1 2 3 4 5 &&
246
247 perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
248
249 have_counter_event "main" "counter" "test" "test1" 15 actual
250'
251
e48a21df 252test_expect_success PTHREADS 'global counter test/test2' '
81071626
JH
253 test_when_finished "rm trace.perf actual" &&
254 test_config_global trace2.perfBrief 1 &&
255 test_config_global trace2.perfTarget "$(pwd)/trace.perf" &&
256
257 # Add 2 integers to the counter "test2" in each of 3 threads.
258 test-tool trace2 201counter 7 13 3 &&
259
260 perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <trace.perf >actual &&
261
262 # So we should have 3 per-thread events of 5 each.
263 have_counter_event "th01:ut_201" "th_counter" "test" "test2" 20 actual &&
264 have_counter_event "th02:ut_201" "th_counter" "test" "test2" 20 actual &&
265 have_counter_event "th03:ut_201" "th_counter" "test" "test2" 20 actual &&
266
267 # And we should have a single event with the total across all threads.
268 have_counter_event "main" "counter" "test" "test2" 60 actual
269'
270
c73e7f80
JH
271test_expect_success 'unsafe URLs are redacted by default' '
272 test_when_finished \
273 "rm -r actual trace.perf unredacted.perf clone clone2" &&
274
275 test_config_global \
276 "url.$(pwd).insteadOf" https://user:pwd@example.com/ &&
277 test_config_global trace2.configParams "core.*,remote.*.url" &&
278
279 GIT_TRACE2_PERF="$(pwd)/trace.perf" \
280 git clone https://user:pwd@example.com/ clone &&
281 ! grep user:pwd trace.perf &&
282
283 GIT_TRACE2_REDACT=0 GIT_TRACE2_PERF="$(pwd)/unredacted.perf" \
284 git clone https://user:pwd@example.com/ clone2 &&
285 perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" <unredacted.perf >actual &&
286 grep "d0|main|start|.* clone https://user:pwd@example.com" actual &&
287 grep "d0|main|def_param|.*|remote.origin.url:https://user:pwd@example.com" actual
288'
289
a15860dc 290test_done