p7519: add trace logging during perf test

Add optional trace logging to allow us to better compare performance of
various fsmonitor providers and compare results with non-fsmonitor runs.

Currently, this includes Trace2 logging, but may be extended to include
other trace targets, such as GIT_TRACE_FSMONITOR if desired.

Using this logging helped me explain an odd behavior on MacOS where the
kernel was dropping events and causing the hook to Watchman to timeout.

Signed-off-by: Jeff Hostetler <jeffhost@microsoft.com>
Reviewed-by: Taylor Blau <me@ttaylorr.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>

diff --git a/t/perf/.gitignore b/t/perf/.gitignore
index 982eb8e3a949a74e5c26a952a33364c25f6f5b74..72f5d0d3148943e3fa21fe7958cd71eafb97c802 100644 (file)
--- a/t/perf/.gitignore
+++ b/t/perf/.gitignore
@@ -1,3 +1,4 @@
 /build/
 /test-results/
+/test-trace/
 /trash directory*/

diff --git a/t/perf/Makefile b/t/perf/Makefile
index fcb0e8865e49335d5a9afe3941bcea2c58f4bcd8..2465770a7825b4f360d649df3684c5339c8ce657 100644 (file)
--- a/t/perf/Makefile
+++ b/t/perf/Makefile
@@ -7,10 +7,10 @@ perf: pre-clean
        ./run
 
 pre-clean:
-       rm -rf test-results
+       rm -rf test-results test-trace
 
 clean:
-       rm -rf build "trash directory".* test-results
+       rm -rf build "trash directory".* test-results test-trace
 
 test-lint:
        $(MAKE) -C .. test-lint

diff --git a/t/perf/p7519-fsmonitor.sh b/t/perf/p7519-fsmonitor.sh
index 78e7d2c03f56187aa8a30e0f47cb843eaef1bdc7..aa0ea0e2ec8c2fc7486cb4a51b6d9c85233ea01e 100755 (executable)
--- a/t/perf/p7519-fsmonitor.sh
+++ b/t/perf/p7519-fsmonitor.sh
@@ -32,6 +32,8 @@ test_description="Test core.fsmonitor"
 #
 # GIT_PERF_7519_DROP_CACHE: if set, the OS caches are dropped between tests
 #
+# GIT_PERF_7519_TRACE: if set, enable trace logging during the test.
+#   Trace logs will be grouped by fsmonitor provider.
 
 test_perf_large_repo
 test_checkout_worktree
@@ -70,6 +72,32 @@ then
        fi
 fi
 
+trace_start() {
+       if test -n "$GIT_PERF_7519_TRACE"
+       then
+               name="$1"
+               TEST_TRACE_DIR="$TEST_OUTPUT_DIRECTORY/test-trace/p7519/"
+               echo "Writing trace logging to $TEST_TRACE_DIR"
+
+               mkdir -p "$TEST_TRACE_DIR"
+
+               # Start Trace2 logging and any other GIT_TRACE_* logs that you
+               # want for this named test case.
+
+               GIT_TRACE2_PERF="$TEST_TRACE_DIR/$name.trace2perf"
+               export GIT_TRACE2_PERF
+
+               >"$GIT_TRACE2_PERF"
+       fi
+}
+
+trace_stop() {
+       if test -n "$GIT_PERF_7519_TRACE"
+       then
+               unset GIT_TRACE2_PERF
+       fi
+}
+
 test_expect_success "one time repo setup" '
        # set untrackedCache depending on the environment
        if test -n "$GIT_PERF_7519_UNTRACKED_CACHE"
@@ -213,6 +241,7 @@ test_fsmonitor_suite() {
 # such as Watchman.
 #
 
+trace_start fsmonitor-watchman
 if test -n "$GIT_PERF_7519_FSMONITOR"; then
        for INTEGRATION_PATH in $GIT_PERF_7519_FSMONITOR; do
                test_expect_success "setup for fsmonitor $INTEGRATION_PATH" 'setup_for_fsmonitor'
@@ -231,11 +260,13 @@ then
        # preventing the removal of the trash directory
        watchman shutdown-server >/dev/null 2>&1
 fi
+trace_stop
 
 #
 # Run a full set of perf tests with the fsmonitor feature disabled.
 #
 
+trace_start fsmonitor-disabled
 test_expect_success "setup without fsmonitor" '
        unset INTEGRATION_SCRIPT &&
        git config --unset core.fsmonitor &&
@@ -243,5 +274,6 @@ test_expect_success "setup without fsmonitor" '
 '
 
 test_fsmonitor_suite
+trace_stop
 
 test_done