[v2,7/8] test-lib: test_region looks for trace2 regions

Commit Message

Derrick Stolee Jan. 22, 2021, 1:03 p.m. UTC

From: Derrick Stolee <[e-mail]>

Most test cases can verify Git's behavior using input/output
expectations or changes to the .git directory. However, sometimes we
want to check that Git did or did not run a certain section of code.
This is particularly important for performance-only features that we
want to ensure have been enabled in certain cases.

Add a new 'test_region' function that checks if a trace2 region was
entered and left in a given trace2 event log.

There is one existing test (t0500-progress-display.sh) that performs
this check already, so use the helper function instead. Note that this
changes the expectations slightly. The old test (incorrectly) used two
patterns for the 'grep' invocation, but this performs an OR of the
patterns, not an AND. This means that as long as one region_enter event
was logged, the test would succeed, even if it was not due to the
progress category.

More uses will be added in a later change.

t6423-merge-rename-directories.sh also greps for region_enter lines, but
it verifies the number of such lines, which is not the same as an
existence check.

Signed-off-by: Derrick Stolee <[e-mail]>
---
 t/t0500-progress-display.sh |  3 +--
 t/test-lib-functions.sh     | 40 +++++++++++++++++++++++++++++++++++++
 2 files changed, 41 insertions(+), 2 deletions(-)

Comments

Junio C Hamano Jan. 22, 2021, 7:42 p.m. UTC | #1

"Derrick Stolee via GitGitGadget" <[e-mail]> writes:

> ... Note that this
> changes the expectations slightly. The old test (incorrectly) used two
> patterns for the 'grep' invocation, but this performs an OR of the
> patterns, not an AND. This means that as long as one region_enter event
> was logged, the test would succeed, even if it was not due to the
> progress category.

>  	# t0212/parse_events.perl intentionally omits regions and data.
> -	grep -e "region_enter" -e "\"category\":\"progress\"" trace.event &&
> -	grep -e "region_leave" -e "\"category\":\"progress\"" trace.event &&
> +	test_region progress "Working hard" trace.event &&

So we do want "region_enter" and the "category":"progress" on the
same line in the event file, but as long as "category":"progress"
exists, both will pass, regardless of enter/leave.  And ...

> +test_region () {
> +	local expect_exit=0
> +	if test "$1" = "!"
> +	then
> +		expect_exit=1
> +		shift
> +	fi
> +
> +	grep -e "\"region_enter\".*\"category\":\"$1\",\"label\":\"$2\"" "$3"

... this makes sure there is enter/category on a line (and
leave/category on a line with another check).  Makes sense.

But...

	test_region '!' '\(unmatching capture)' 'two' 'three'

would try to use an invalid regexp and cause grep to exit with 2,
which would mean ...

> +	exitcode=$?
> +
> +	if test $exitcode != $expect_exit

... this will not trigger and we return "success" (i.e. "failed as
expected")?

	Clarification.  The point is *NOT* that the grep pattern is
	not robust against funnies in $1 and $2---after all, these
	strings are under our control.  The point is what should
	happen when "grep" exits with an error when asked to ensure
	that there is no region detected.

> +	then
> +		return 1
> +	fi
> +
> +	grep -e "\"region_leave\".*\"category\":\"$1\",\"label\":\"$2\"" "$3"

The same comment on "what about an error from grep" applies to this
one.

It might be easier to read to avoid having to say too many
backslash-quoted double quotes:

	grep -e	'"region_leave".*"category":"'"$1"'","label":"'"$2"\" "$3"

This comment applies to the earlier "grep", too.

> +	exitcode=$?
> +
> +	if test $exitcode != $expect_exit
> +	then
> +		return 1
> +	fi
> +}

Derrick Stolee Jan. 23, 2021, 6:36 p.m. UTC | #2

On 1/22/2021 2:42 PM, Junio C Hamano wrote:
> "Derrick Stolee via GitGitGadget" <[e-mail]> writes:
>> +	grep -e "\"region_enter\".*\"category\":\"$1\",\"label\":\"$2\"" "$3"
> 
> ... this makes sure there is enter/category on a line (and
> leave/category on a line with another check).  Makes sense.
> 
> But...
> 
> 	test_region '!' '\(unmatching capture)' 'two' 'three'
> 
> would try to use an invalid regexp and cause grep to exit with 2,
> which would mean ...
> 
>> +	exitcode=$?
>> +
>> +	if test $exitcode != $expect_exit
> 
> ... this will not trigger and we return "success" (i.e. "failed as
> expected")?

Am I misunderstanding something here? If exitcode is 2, then this
will always trigger and return 1, signaling a failure. That would
propagate to the parent test and cause the test to fail. That seems
like the correct intention, but I'm not 100% confident about that.

> 	Clarification.  The point is *NOT* that the grep pattern is
> 	not robust against funnies in $1 and $2---after all, these
> 	strings are under our control.  The point is what should
> 	happen when "grep" exits with an error when asked to ensure
> 	that there is no region detected.

I'll be more robust to these in the next version. We'll expect
exit code equal to zero or _not_ equal to zero, depending on the
presence of '!'. This has the downside of returning success for
bad input strings when '!' is specified.

Basically, the approach I'm taking for v3 is here:

	if [test $expect_exit = 1] && [test $exitcode = 0]
	then
		return 1
	elif [test $expect_exit = 0] && [test $exitcode != 0]
	then
		return 1
	fi

>> +	grep -e "\"region_leave\".*\"category\":\"$1\",\"label\":\"$2\"" "$3"
> 
> The same comment on "what about an error from grep" applies to this
> one.
> 
> It might be easier to read to avoid having to say too many
> backslash-quoted double quotes:
> 
> 	grep -e	'"region_leave".*"category":"'"$1"'","label":"'"$2"\" "$3"
> 
> This comment applies to the earlier "grep", too.

Thanks. This does look a bit cleaner.

-Stolee

Junio C Hamano Jan. 23, 2021, 6:50 p.m. UTC | #3

Derrick Stolee <[e-mail]> writes:

>>> +	if test $exitcode != $expect_exit
>> 
>> ... this will not trigger and we return "success" (i.e. "failed as
>> expected")?
>
> Am I misunderstanding something here? If exitcode is 2, then this
> will always trigger and return 1, signaling a failure.

Are, please disregard.  Yes, the above does the right thing already.

Patch

diff --git a/t/t0500-progress-display.sh b/t/t0500-progress-display.sh
index 1ed1df351cb..84cce345e7d 100755
--- a/t/t0500-progress-display.sh
+++ b/t/t0500-progress-display.sh
@@ -303,8 +303,7 @@  test_expect_success 'progress generates traces' '
 		"Working hard" <in 2>stderr &&
 
 	# t0212/parse_events.perl intentionally omits regions and data.
-	grep -e "region_enter" -e "\"category\":\"progress\"" trace.event &&
-	grep -e "region_leave" -e "\"category\":\"progress\"" trace.event &&
+	test_region progress "Working hard" trace.event &&
 	grep "\"key\":\"total_objects\",\"value\":\"40\"" trace.event &&
 	grep "\"key\":\"total_bytes\",\"value\":\"409600\"" trace.event
 '
diff --git a/t/test-lib-functions.sh b/t/test-lib-functions.sh
index 999982fe4a9..1170f7108ac 100644
--- a/t/test-lib-functions.sh
+++ b/t/test-lib-functions.sh
@@ -1655,3 +1655,43 @@  test_subcommand () {
 		grep "\[$expr\]"
 	fi
 }
+
+# Check that the given command was invoked as part of the
+# trace2-format trace on stdin.
+#
+#	test_region [!] <category> <label> git <command> <args>...
+#
+# For example, to look for trace2_region_enter("index", "do_read_index", repo)
+# in an invocation of "git checkout HEAD~1", run
+#
+#	GIT_TRACE2_EVENT="$(pwd)/trace.txt" GIT_TRACE2_EVENT_NESTING=10 \
+#		git checkout HEAD~1 &&
+#	test_region index do_read_index <trace.txt
+#
+# If the first parameter passed is !, this instead checks that
+# the given region was not entered.
+#
+test_region () {
+	local expect_exit=0
+	if test "$1" = "!"
+	then
+		expect_exit=1
+		shift
+	fi
+
+	grep -e "\"region_enter\".*\"category\":\"$1\",\"label\":\"$2\"" "$3"
+	exitcode=$?
+
+	if test $exitcode != $expect_exit
+	then
+		return 1
+	fi
+
+	grep -e "\"region_leave\".*\"category\":\"$1\",\"label\":\"$2\"" "$3"
+	exitcode=$?
+
+	if test $exitcode != $expect_exit
+	then
+		return 1
+	fi
+}