#!/bin/sh test_description='test trace2 facility (perf target)' TEST_PASSES_SANITIZE_LEAK=false . ./test-lib.sh # Turn off any inherited trace2 settings for this test. sane_unset GIT_TRACE2 GIT_TRACE2_PERF GIT_TRACE2_EVENT sane_unset GIT_TRACE2_PERF_BRIEF sane_unset GIT_TRACE2_CONFIG_PARAMS # 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. 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_TRACE2_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: # " : | | " GIT_TRACE2_PERF_BRIEF=1 && export GIT_TRACE2_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_ function propagates . test_expect_success 'perf stream, return code 0' ' test_when_finished "rm trace.perf actual expect" && GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 0 && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && cat >expect <<-EOF && d0|main|version|||||$V d0|main|start||_T_ABS_|||_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_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 001return 1 && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && cat >expect <<-EOF && d0|main|version|||||$V d0|main|start||_T_ABS_|||_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 ' events test_expect_success 'perf stream, error event' ' test_when_finished "rm trace.perf actual expect" && GIT_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 003error "hello world" "this is a test" && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && cat >expect <<-EOF && d0|main|version|||||$V d0|main|start||_T_ABS_|||_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_TRACE2_PERF="$(pwd)/trace.perf" test-tool trace2 004child test-tool trace2 004child test-tool trace2 001return 0 && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && cat >expect <<-EOF && d0|main|version|||||$V d0|main|start||_T_ABS_|||_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||_T_ABS_|||_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||_T_ABS_|||_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 ' sane_unset GIT_TRACE2_PERF_BRIEF # Now test without environment variables and get all Trace2 settings # from the global config. test_expect_success 'using global config, perf stream, return code 0' ' test_when_finished "rm trace.perf actual expect" && test_config_global trace2.perfBrief 1 && test_config_global trace2.perfTarget "$(pwd)/trace.perf" && test-tool trace2 001return 0 && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && cat >expect <<-EOF && d0|main|version|||||$V d0|main|start||_T_ABS_|||_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 ' # Exercise the stopwatch timers in a loop and confirm that we have # as many start/stop intervals as expected. We cannot really test the # actual (total, min, max) timer values, so we have to assume that they # are good, but we can verify the interval count. # # The timer "test/test1" should only emit a global summary "timer" event. # The timer "test/test2" should emit per-thread "th_timer" events and a # global summary "timer" event. have_timer_event () { thread=$1 event=$2 category=$3 name=$4 intervals=$5 file=$6 && pattern="d0|${thread}|${event}||||${category}|name:${name} intervals:${intervals}" && grep "${pattern}" ${file} } test_expect_success 'stopwatch timer test/test1' ' test_when_finished "rm trace.perf actual" && test_config_global trace2.perfBrief 1 && test_config_global trace2.perfTarget "$(pwd)/trace.perf" && # Use the timer "test1" 5 times from "main". test-tool trace2 100timer 5 10 && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && have_timer_event "main" "timer" "test" "test1" 5 actual ' test_expect_success PTHREADS 'stopwatch timer test/test2' ' test_when_finished "rm trace.perf actual" && test_config_global trace2.perfBrief 1 && test_config_global trace2.perfTarget "$(pwd)/trace.perf" && # Use the timer "test2" 5 times each in 3 threads. test-tool trace2 101timer 5 10 3 && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && # So we should have 3 per-thread events of 5 each. have_timer_event "th01:ut_101" "th_timer" "test" "test2" 5 actual && have_timer_event "th02:ut_101" "th_timer" "test" "test2" 5 actual && have_timer_event "th03:ut_101" "th_timer" "test" "test2" 5 actual && # And we should have 15 total uses. have_timer_event "main" "timer" "test" "test2" 15 actual ' # Exercise the global counters and confirm that we get the expected values. # # The counter "test/test1" should only emit a global summary "counter" event. # The counter "test/test2" could emit per-thread "th_counter" events and a # global summary "counter" event. have_counter_event () { thread=$1 event=$2 category=$3 name=$4 value=$5 file=$6 && pattern="d0|${thread}|${event}||||${category}|name:${name} value:${value}" && grep "${pattern}" ${file} } test_expect_success 'global counter test/test1' ' test_when_finished "rm trace.perf actual" && test_config_global trace2.perfBrief 1 && test_config_global trace2.perfTarget "$(pwd)/trace.perf" && # Use the counter "test1" and add n integers. test-tool trace2 200counter 1 2 3 4 5 && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && have_counter_event "main" "counter" "test" "test1" 15 actual ' test_expect_success PTHREADS 'global counter test/test2' ' test_when_finished "rm trace.perf actual" && test_config_global trace2.perfBrief 1 && test_config_global trace2.perfTarget "$(pwd)/trace.perf" && # Add 2 integers to the counter "test2" in each of 3 threads. test-tool trace2 201counter 7 13 3 && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && # So we should have 3 per-thread events of 5 each. have_counter_event "th01:ut_201" "th_counter" "test" "test2" 20 actual && have_counter_event "th02:ut_201" "th_counter" "test" "test2" 20 actual && have_counter_event "th03:ut_201" "th_counter" "test" "test2" 20 actual && # And we should have a single event with the total across all threads. have_counter_event "main" "counter" "test" "test2" 60 actual ' test_expect_success 'unsafe URLs are redacted by default' ' test_when_finished \ "rm -r actual trace.perf unredacted.perf clone clone2" && test_config_global \ "url.$(pwd).insteadOf" https://user:pwd@example.com/ && test_config_global trace2.configParams "core.*,remote.*.url" && GIT_TRACE2_PERF="$(pwd)/trace.perf" \ git clone https://user:pwd@example.com/ clone && ! grep user:pwd trace.perf && GIT_TRACE2_REDACT=0 GIT_TRACE2_PERF="$(pwd)/unredacted.perf" \ git clone https://user:pwd@example.com/ clone2 && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && grep "d0|main|start|.* clone https://user:pwd@example.com" actual && grep "d0|main|def_param|.*|remote.origin.url:https://user:pwd@example.com" actual ' # Confirm that the requested command produces a "cmd_name" and a # set of "def_param" events. # try_simple () { test_when_finished "rm prop.perf actual" && cmd=$1 && cmd_name=$2 && test_config_global "trace2.configParams" "cfg.prop.*" && test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" && test_config_global "cfg.prop.foo" "red" && ENV_PROP_FOO=blue \ GIT_TRACE2_PERF="$(pwd)/prop.perf" \ $cmd && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && grep "d0|main|cmd_name|.*|$cmd_name" actual && grep "d0|main|def_param|.*|cfg.prop.foo:red" actual && grep "d0|main|def_param|.*|ENV_PROP_FOO:blue" actual } # Representative mainstream builtin Git command dispatched # in run_builtin() in git.c # test_expect_success 'expect def_params for normal builtin command' ' try_simple "git version" "version" ' # Representative query command dispatched in handle_options() # in git.c # test_expect_success 'expect def_params for query command' ' try_simple "git --man-path" "_query_" ' # remote-curl.c does not use the builtin setup in git.c, so confirm # that executables built from remote-curl.c emit def_params. # # Also tests the dashed-command handling where "git foo" silently # spawns "git-foo". Make sure that both commands should emit # def_params. # # Pass bogus arguments to remote-https and allow the command to fail # because we don't actually have a remote to fetch from. We just want # to see the run-dashed code run an executable built from # remote-curl.c rather than git.c. Confirm that we get def_param # events from both layers. # test_expect_success LIBCURL \ 'expect def_params for remote-curl and _run_dashed_' ' test_when_finished "rm prop.perf actual" && test_config_global "trace2.configParams" "cfg.prop.*" && test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" && test_config_global "cfg.prop.foo" "red" && test_might_fail env \ ENV_PROP_FOO=blue \ GIT_TRACE2_PERF="$(pwd)/prop.perf" \ git remote-http x y && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && grep "d0|main|cmd_name|.*|_run_dashed_" actual && grep "d0|main|def_param|.*|cfg.prop.foo:red" actual && grep "d0|main|def_param|.*|ENV_PROP_FOO:blue" actual && grep "d1|main|cmd_name|.*|remote-curl" actual && grep "d1|main|def_param|.*|cfg.prop.foo:red" actual && grep "d1|main|def_param|.*|ENV_PROP_FOO:blue" actual ' # Similarly, `git-http-fetch` is not built from git.c so do a # trivial fetch so that the main git.c run-dashed code spawns # an executable built from http-fetch.c. Confirm that we get # def_param events from both layers. # test_expect_success LIBCURL \ 'expect def_params for http-fetch and _run_dashed_' ' test_when_finished "rm prop.perf actual" && test_config_global "trace2.configParams" "cfg.prop.*" && test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" && test_config_global "cfg.prop.foo" "red" && test_might_fail env \ ENV_PROP_FOO=blue \ GIT_TRACE2_PERF="$(pwd)/prop.perf" \ git http-fetch --stdin file:/// <<-EOF && EOF perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && grep "d0|main|cmd_name|.*|_run_dashed_" actual && grep "d0|main|def_param|.*|cfg.prop.foo:red" actual && grep "d0|main|def_param|.*|ENV_PROP_FOO:blue" actual && grep "d1|main|cmd_name|.*|http-fetch" actual && grep "d1|main|def_param|.*|cfg.prop.foo:red" actual && grep "d1|main|def_param|.*|ENV_PROP_FOO:blue" actual ' # Historically, alias expansion explicitly emitted the def_param # events (independent of whether the command was a builtin, a Git # command or arbitrary shell command) so that it wasn't dependent # upon the unpeeling of the alias. Let's make sure that we preserve # the net effect. # test_expect_success 'expect def_params during git alias expansion' ' test_when_finished "rm prop.perf actual" && test_config_global "trace2.configParams" "cfg.prop.*" && test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" && test_config_global "cfg.prop.foo" "red" && test_config_global "alias.xxx" "version" && ENV_PROP_FOO=blue \ GIT_TRACE2_PERF="$(pwd)/prop.perf" \ git xxx && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && # "git xxx" is first mapped to "git-xxx" and the child will fail. grep "d0|main|cmd_name|.*|_run_dashed_ (_run_dashed_)" actual && # We unpeel that and substitute "version" into "xxx" (giving # "git version") and update the cmd_name event. grep "d0|main|cmd_name|.*|_run_git_alias_ (_run_dashed_/_run_git_alias_)" actual && # These def_param events could be associated with either of the # above cmd_name events. It does not matter. grep "d0|main|def_param|.*|cfg.prop.foo:red" actual && grep "d0|main|def_param|.*|ENV_PROP_FOO:blue" actual && # The "git version" child sees a different cmd_name hierarchy. # Also test the def_param (only for completeness). grep "d1|main|cmd_name|.*|version (_run_dashed_/_run_git_alias_/version)" actual && grep "d1|main|def_param|.*|cfg.prop.foo:red" actual && grep "d1|main|def_param|.*|ENV_PROP_FOO:blue" actual ' test_expect_success 'expect def_params during shell alias expansion' ' test_when_finished "rm prop.perf actual" && test_config_global "trace2.configParams" "cfg.prop.*" && test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" && test_config_global "cfg.prop.foo" "red" && test_config_global "alias.xxx" "!git version" && ENV_PROP_FOO=blue \ GIT_TRACE2_PERF="$(pwd)/prop.perf" \ git xxx && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && # "git xxx" is first mapped to "git-xxx" and the child will fail. grep "d0|main|cmd_name|.*|_run_dashed_ (_run_dashed_)" actual && # We unpeel that and substitute "git version" for "git xxx" (as a # shell command. Another cmd_name event is emitted as we unpeel. grep "d0|main|cmd_name|.*|_run_shell_alias_ (_run_dashed_/_run_shell_alias_)" actual && # These def_param events could be associated with either of the # above cmd_name events. It does not matter. grep "d0|main|def_param|.*|cfg.prop.foo:red" actual && grep "d0|main|def_param|.*|ENV_PROP_FOO:blue" actual && # We get the following only because we used a git command for the # shell command. In general, it could have been a shell script and # we would see nothing. # # The child knows the cmd_name hierarchy so it includes it. grep "d1|main|cmd_name|.*|version (_run_dashed_/_run_shell_alias_/version)" actual && grep "d1|main|def_param|.*|cfg.prop.foo:red" actual && grep "d1|main|def_param|.*|ENV_PROP_FOO:blue" actual ' test_expect_success 'expect def_params during nested git alias expansion' ' test_when_finished "rm prop.perf actual" && test_config_global "trace2.configParams" "cfg.prop.*" && test_config_global "trace2.envvars" "ENV_PROP_FOO,ENV_PROP_BAR" && test_config_global "cfg.prop.foo" "red" && test_config_global "alias.xxx" "yyy" && test_config_global "alias.yyy" "version" && ENV_PROP_FOO=blue \ GIT_TRACE2_PERF="$(pwd)/prop.perf" \ git xxx && perl "$TEST_DIRECTORY/t0211/scrub_perf.perl" actual && # "git xxx" is first mapped to "git-xxx" and try to spawn "git-xxx" # and the child will fail. grep "d0|main|cmd_name|.*|_run_dashed_ (_run_dashed_)" actual && grep "d0|main|child_start|.*|.* class:dashed argv:\[git-xxx\]" actual && # We unpeel that and substitute "yyy" into "xxx" (giving "git yyy") # and spawn "git-yyy" and the child will fail. grep "d0|main|alias|.*|alias:xxx argv:\[yyy\]" actual && grep "d0|main|cmd_name|.*|_run_dashed_ (_run_dashed_/_run_dashed_)" actual && grep "d0|main|child_start|.*|.* class:dashed argv:\[git-yyy\]" actual && # We unpeel that and substitute "version" into "xxx" (giving # "git version") and update the cmd_name event. grep "d0|main|alias|.*|alias:yyy argv:\[version\]" actual && grep "d0|main|cmd_name|.*|_run_git_alias_ (_run_dashed_/_run_dashed_/_run_git_alias_)" actual && # These def_param events could be associated with any of the # above cmd_name events. It does not matter. grep "d0|main|def_param|.*|cfg.prop.foo:red" actual >actual.matches && grep "d0|main|def_param|.*|ENV_PROP_FOO:blue" actual && # However, we do not want them repeated each time we unpeel. test_line_count = 1 actual.matches && # The "git version" child sees a different cmd_name hierarchy. # Also test the def_param (only for completeness). grep "d1|main|cmd_name|.*|version (_run_dashed_/_run_dashed_/_run_git_alias_/version)" actual && grep "d1|main|def_param|.*|cfg.prop.foo:red" actual && grep "d1|main|def_param|.*|ENV_PROP_FOO:blue" actual ' test_done