diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 0f10886d..eae709ef 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -121,6 +121,15 @@ jobs: with: shared-key: test-macos save-if: false + # The same two changes as the shards below make; see there. + - name: Turn Spotlight indexing off + run: sudo mdutil -a -i off + - name: Put Xcode's git first on PATH + run: | + mkdir -p "$RUNNER_TEMP/xcode-git" + ln -s "$(dirname "$(xcrun -f git)")"/git* "$RUNNER_TEMP/xcode-git/" + echo "$RUNNER_TEMP/xcode-git" >> "$GITHUB_PATH" + "$RUNNER_TEMP/xcode-git/git" --version - run: cargo clippy --all-targets -- -D warnings - uses: taiki-e/install-action@nextest - run: cargo nextest run --profile macos-gate @@ -143,6 +152,20 @@ jobs: with: shared-key: test-macos save-if: ${{ matrix.shard == 1 }} + # The tests spend most of their time starting git (#894, + # docs/ci-performance.md). Spotlight indexes every repository they + # create, taking CPU from them on the 3-core runner. + - name: Turn Spotlight indexing off + run: sudo mdutil -a -i off + # Homebrew's git, first on the image's PATH, takes about 13 ms to run + # here and Xcode's about 9 ms. Xcode's git runs git-upload-pack and + # the rest only from beside itself, so they are linked here too. + - name: Put Xcode's git first on PATH + run: | + mkdir -p "$RUNNER_TEMP/xcode-git" + ln -s "$(dirname "$(xcrun -f git)")"/git* "$RUNNER_TEMP/xcode-git/" + echo "$RUNNER_TEMP/xcode-git" >> "$GITHUB_PATH" + "$RUNNER_TEMP/xcode-git/git" --version # nextest runs tests from every test binary in parallel, where cargo test # runs the binaries one after another; that matters on the slower macOS # runners. Without a lib target there are no doctests for it to miss. diff --git a/docs/ci-performance.md b/docs/ci-performance.md index 33726c46..685a49a6 100644 --- a/docs/ci-performance.md +++ b/docs/ci-performance.md @@ -179,3 +179,144 @@ value, `Git::checkout_location` reads each value with its own process again. Tha 17.2 s on the same host; concurrent host load and macOS runtime can differ. `an_ordinary_operation_inspects_ownership_in_few_git_processes` holds one ordinary operation to its 23 git processes. + +### After #857: the macOS breakdown + +Issue [#894](https://github.com/JacobStephens2/thirdshift/issues/894) asked +where the macOS shards' 3,900-4,250 seconds still go. Five passes of a +temporary diagnostic workflow on `macos-26` (3 vCPU Apple M1, macOS 26.6, +Homebrew git 2.56.0 first on `PATH`) measured it. It lived only on the +`issue-894-profile` branch: + +| Pass | Run | What it measured | +| --- | --- | --- | +| 1 | [39544139072](https://github.com/JacobStephens2/thirdshift/actions/runs/39544139072) | 23 of the 26 tests below, each alone; one `spec_run` partition at 3 and 6 threads | +| 2 | [39545174138](https://github.com/JacobStephens2/thirdshift/actions/runs/39545174138) | seven of them alone under dtrace; the same seven with git's fsync off and with Xcode's git; one process of each program | +| 3 | [39546189462](https://github.com/JacobStephens2/thirdshift/actions/runs/39546189462) | the four shards with Spotlight off and Xcode's git; the seven with Spotlight off | +| 4 | [39547327478](https://github.com/JacobStephens2/thirdshift/actions/runs/39547327478) | the four shards with each change alone | +| 5 | [39551482447](https://github.com/JacobStephens2/thirdshift/actions/runs/39551482447) | the other 19 tests alone under dtrace | + +The 26 tests are the 16 that [main CI run 39430050727](https://github.com/JacobStephens2/thirdshift/actions/runs/39430050727) +flagged over 60 seconds and ten more of the slowest in +[39536115478](https://github.com/JacobStephens2/thirdshift/actions/runs/39536115478), +12 of the 26 in `spec_run`. Pass 1 measured 23 of them. + +"Alone" means the test binary run directly, ` --exact +--test-threads 1`, from a Python driver that read wall time and the +`RUSAGE_CHILDREN` CPU time of the test and every process it reaped. Under +dtrace (SIP is off on the hosted image) the driver ran `sudo dtrace` with +`progenyof()` predicates: `proc:::exec-success` and +`proc:::exit` counted each program the test started and summed its lifetime; +`fsync` and `fcntl(F_FULLFSYNC | F_BARRIERFSYNC)` and `__semwait_signal` +(where `thread::sleep` waits) summed by program; `profile-997` sampled every +CPU, system-wide, by program. The same tests were then straced on x86_64 +Linux, whose git command lines, unlike dtrace's program names, say which +code ran each git. Over the 26 tests the two platforms' git counts agree +within 1% in total and within 12% for each Run test; the worktree unit test, +which drives git through its own scripts, ran 0.61 times as many on macOS. + +**The slowest tests are git processes.** Alone, each of pass 1's 23 tests +was on a CPU for 66-93% of its wall time (78% on average), so it waits +little: no fixed sleep or poll interval dominates. Under dtrace, git +processes were alive for 77-99% of each test's wall time, 88% summed over +all 26: + +| Test (alone) | Pass | Wall s | CPU s | macOS git processes | git alive s | Linux git processes | Launch recheck | Ownership inspection | Other git | +| --- | ---: | ---: | ---: | ---: | ---: | ---: | ---: | ---: | ---: | +| `spec_run security_findings_refusals_and_incomplete_reviews_hold_only_the_spec_self_merge` | 5 | 259.9 | 190.3 | 15,606 | 213.2 | 15,360 | 41% | 45% | 14% | +| `security_run unauthenticated_public_publishers_stage_single_fixes_and_specs_with_every_harness` | 5 | 234.1 | 168.2 | 15,112 | 189.6 | 14,800 | 42% | 43% | 15% | +| `spec_run security_review_on_a_spec_obeys_config_and_command_overrides` | 5 | 116.1 | 91.4 | 8,582 | 103.5 | 8,442 | 41% | 45% | 13% | +| `security_review repeated_fingerprints_reuse_private_records_and_preserve_day_shift_grades` | 5 | 116.0 | 82.3 | 6,020 | 93.5 | 5,923 | 42% | 44% | 14% | +| `spec_run without_a_limit_at_most_three_tickets_run_at_once` | 5 | 95.8 | 79.3 | 5,158 | 94.5 | 5,174 | 41% | 46% | 13% | +| `pickup_run pickup_wait_in_the_user_config_shortens_lengthens_or_disables_settling` | 2 | 89.7 | 67.3 | 4,946 | 79.4 | 4,781 | 38% | 39% | 23% | +| `spec_run a_review_required_spec_pr_stays_ready_without_an_attempt_or_another_round` | 5 | 89.0 | 67.4 | 4,208 | 80.5 | 4,143 | 41% | 45% | 13% | +| `architect_run base_carries_the_named_branch_to_the_dispatched_spec_run_whatever_is_checked_out` | 5 | 88.3 | 68.2 | 4,410 | 79.6 | 4,378 | 41% | 44% | 15% | +| `spec_run spec_delivery_rejects_late_retargeting_and_keeps_the_original_identity` | 2 | 83.9 | 69.0 | 7,630 | 77.0 | 7,495 | 41% | 45% | 14% | +| `spec_run successful_ticket_completion_with_an_invalid_spec_pr_starts_no_review` | 5 | 60.4 | 47.5 | 3,011 | 56.2 | 2,953 | 41% | 43% | 16% | +| `issue_number a_number_resolves_supported_origins_from_nested_directories` | 2 | 60.3 | 41.0 | 3,185 | 48.5 | 3,129 | 40% | 42% | 18% | +| `bin worktree::acquisition_tests::recovery_retains_changed_checkout_authority_during_removal` | 2 | 58.9 | 52.6 | 4,486 | 58.0 | 7,365 | 29% | 23% | 48% | +| `architect_run base_fix_reaches_each_tickets_run_of_the_dispatched_spec_run` | 5 | 55.0 | 43.7 | 3,036 | 50.2 | 2,987 | 42% | 45% | 14% | +| `spec_run repairs_exhausted_on_the_spec_pr_send_it_back_to_draft_and_exit_1` | 5 | 52.4 | 41.1 | 2,994 | 46.3 | 2,954 | 40% | 45% | 14% | +| `architect_run merge_merges_the_runs_pull_request_or_the_spec_pr` | 5 | 49.9 | 40.9 | 2,985 | 47.8 | 2,969 | 41% | 44% | 15% | +| `ci a_check_re_run_cannot_deliver_or_merge_without_readable_nonempty_checks` | 2 | 48.7 | 34.6 | 3,078 | 39.0 | 3,022 | 41% | 45% | 14% | +| `spec_run a_linear_spec_lands_each_ticket_in_order_then_opens_a_ready_spec_pr` | 2 | 47.3 | 32.8 | 1,900 | 36.5 | 1,872 | 41% | 45% | 14% | +| `spec_run independent_tickets_run_at_once_and_the_ticket_they_block_waits_for_both` | 5 | 46.2 | 38.0 | 2,948 | 43.6 | 2,913 | 41% | 46% | 13% | +| `ci a_repair_that_already_re_ran_ci_to_green_delivers_or_self_merges_the_unchanged_head` | 5 | 44.2 | 35.9 | 3,146 | 39.6 | 3,090 | 41% | 45% | 14% | +| `spec_run a_spec_pr_replaced_during_review_gets_its_checklist_on_the_delivered_identity` | 5 | 44.1 | 36.0 | 3,638 | 40.2 | 3,582 | 41% | 45% | 14% | +| `spec_run two_tickets_meeting_the_same_inherited_failure_share_one_base_fix` | 5 | 42.5 | 36.5 | 3,742 | 40.5 | 3,344 | 42% | 46% | 13% | +| `spec_run two_tickets_starting_together_in_one_launch_directory_both_get_their_worktrees` | 5 | 39.1 | 31.9 | 2,592 | 36.8 | 2,924 | 42% | 45% | 13% | +| `run_notification delivery_failures_name_the_stopped_stage_in_terminal_and_notification` | 5 | 36.0 | 27.3 | 2,896 | 30.3 | 2,848 | 41% | 45% | 14% | +| `architect_run base_fix_lets_the_dispatched_run_start_a_base_fix` | 5 | 36.0 | 30.0 | 2,976 | 33.4 | 2,928 | 41% | 44% | 15% | +| `security_run status_tracks_security_stages_and_nests_the_dispatched_fix` | 5 | 34.4 | 27.4 | 2,648 | 29.4 | 2,610 | 44% | 37% | 19% | +| `merge_run unblocked_or_unknown_review_decisions_allow_the_guarded_merge` | 2 | 30.6 | 24.8 | 2,680 | 28.3 | 2,636 | 41% | 44% | 15% | + +The last three columns split the Linux trace's git processes; summed over +the 26 tests they are 41%, 43% and 17%. +"Launch recheck" is `git rev-parse --git-common-dir`, mostly +`Directory::verify_repository`, which +[#858](https://github.com/JacobStephens2/thirdshift/issues/858) holds. +"Ownership inspection" is `worktree list --porcelain -z`, the combined +`rev-parse --show-toplevel …`, `rev-parse --symbolic-full-name HEAD` and the +branch `for-each-ref`. "Other git" is everything else, including git's own +subprocesses and the scenario's setup. Everything else the tests start is +small: the fake `gh`, `claude` and `codex` lived 1-3% of each test's wall +time, and shells under 2%, except in the worktree unit test, whose own +fake-git scripts ran 141 shells for 6 s, and +`spec_run without_a_limit_at_most_three_tickets_run_at_once`, 6 s of +shells in 96 s. + +What did not matter: + +- **fsync.** Git's fsyncs took under 0.1 s in each test. With + `core.fsync = none` the seven tests took 344 s against 346 s. +- **Sleeps and polls.** thirdshift's own `thread::sleep` totals (up to 60 s + in a Spec run test) are a parent waiting at the 100 ms poll while its child + Runs work. That overlaps their git time and adds no wall time. +- **More test threads.** One third of `spec_run` took 493 s at 3 threads and + 461 s at 6 (-6%): CPU use stayed at about 58% of three cores either way. + +What did: + +- **Each git process costs more on macOS.** One process of each program, + started 200 times in a scratch clone (pass 2), median: + + | Program | macOS ms | x86_64 Linux ms | + | --- | ---: | ---: | + | `/usr/bin/true` | 1.7 | 1.1 | + | `/bin/sh -c true` | 4.2 | 1.2 | + | Homebrew `git rev-parse --git-common-dir` | 13.2 | 2.4 | + | Xcode `git rev-parse --git-common-dir` | 9.1 | | + | `/usr/bin/git --version` (the `xcrun` shim) | 16.7 | | + | the fake `gh`, debug build | 3.7 | 3.7 | + | `thirdshift --version`, debug build | 7.7 | | + + Homebrew's git loads `pcre2` and `gettext` from `/opt/homebrew`, outside + the dyld shared cache. Under the shards' parallel load the gap grows. +- **Spotlight.** In the dtrace pass, `mdworker_shared`, `mds_stores` and + `mds` took 18-35% of all CPU samples in the first three tests after the + build, against git's 18-21%. They index the repositories the tests create. + +**The changes.** Both macOS jobs in CI now turn Spotlight indexing off +(`sudo mdutil -a -i off`) and put Xcode's git (`xcrun -f git`, 2.50.1 on +this image) first on `PATH`, with the `git-*` programs beside it. Summed +nextest time of the four shards, build excluded: + +| Runs | Shards 1 / 2 / 3 / 4 s | Sum s | +| --- | --- | ---: | +| `main`, five runs from [39511690293](https://github.com/JacobStephens2/thirdshift/actions/runs/39511690293) to [39536115478](https://github.com/JacobStephens2/thirdshift/actions/runs/39536115478) | 595-994 / 789-1,012 / 773-981 / 728-951 | 3,327-3,595 | +| Spotlight off (pass 4) | 800 / 835 / 852 / 722 | 3,209 | +| Xcode's git (pass 4) | 549 / 475 / 571 / 537 | 2,132 | +| Both (pass 3) | stopped early / stopped early / 341 / 555 | | + +Xcode's git alone took 38% off the mean of `main`'s five runs. Spotlight off +alone was 7% below that mean, inside the ±15% run-to-run noise; it is kept for +the CPU the samples show it freeing. In passes 3 and 4 two `security_run` +tests failed under Xcode's git: they run thirdshift with only a link to git on +`PATH`, and Xcode's git finds `git-upload-pack` only beside itself, not in +its exec path as Homebrew's and Linux's do. They now link it too. + +**What remains.** 83% of the git processes in the 26 tests are Worktree +ownership inspection and the launch-side recheck. Both are +read-only here; the macOS numbers above are on #858, which decides whether +inspection may recheck less often. Linux CI keeps Ubuntu's git, and a +macOS contributor's local run uses whichever git is first on their `PATH`. diff --git a/tests/security_run.rs b/tests/security_run.rs index 41d6624f..5213da60 100644 --- a/tests/security_run.rs +++ b/tests/security_run.rs @@ -2684,15 +2684,30 @@ fn another_pass_holds_the_security_run_and_its_skip_is_logged() { assert!(log.contains("Security run skipped: another Pass is already running")); } -#[test] -fn missing_node_fails_before_any_session_and_names_the_prerequisite() { - let scenario = Scenario::new(); +/// Link the git on `PATH` into the scenario's `bin`, for a test that runs +/// thirdshift with `bin` as its whole `PATH`. Over a local transport git runs +/// `git-upload-pack` and `git-receive-pack` by name. Linux's and Homebrew's +/// git find them in their exec path, but Xcode's finds them only beside +/// itself, so they are linked too wherever they are beside `git`. +fn link_git(scenario: &Scenario) { let git = std::process::Command::new("which") .arg("git") .output() .unwrap(); - let git = String::from_utf8(git.stdout).unwrap(); - std::os::unix::fs::symlink(git.trim(), scenario.path("bin/git")).unwrap(); + let git = std::path::PathBuf::from(String::from_utf8(git.stdout).unwrap().trim()); + std::os::unix::fs::symlink(&git, scenario.path("bin/git")).unwrap(); + for name in ["git-upload-pack", "git-receive-pack"] { + let program = git.with_file_name(name); + if program.exists() { + std::os::unix::fs::symlink(program, scenario.path("bin").join(name)).unwrap(); + } + } +} + +#[test] +fn missing_node_fails_before_any_session_and_names_the_prerequisite() { + let scenario = Scenario::new(); + link_git(&scenario); let path = scenario.path("bin"); let result = scenario.run_with_env(&["secure"], &[("PATH", path.to_str().unwrap())]); assert_eq!(result.code, Some(1), "{}", result.stderr); @@ -3482,12 +3497,7 @@ fn invalid_schema_pre_audit_github_response_has_dependency_cause() { #[test] fn an_unavailable_github_cli_has_a_safe_pre_audit_dependency_cause() { let scenario = Scenario::new(); - let git = std::process::Command::new("which") - .arg("git") - .output() - .unwrap(); - let git = String::from_utf8(git.stdout).unwrap(); - std::os::unix::fs::symlink(git.trim(), scenario.path("bin/git")).unwrap(); + link_git(&scenario); fs::remove_file(scenario.path("bin/gh")).unwrap(); let path = scenario.path("bin"); let resend = ResendStandIn::replying(200, r#"{"id":"1"}"#);