Balance coverage shards on Linux test times

scripts/ci-coverage-durations.json

@@ -0,0 +1,246 @@
+{
+  "source_run": 40801155956,
+  "source_jobs": [
+    123209371302,
+    123209371281
+  ],
+  "unit_seconds": 90.7,
+  "compile_seconds": 0.3,
+  "default_seconds": 1.0,
+  "targets": {
+    "api_retry_e2e": 0.12,
+    "api_timeout_e2e": 4.04,
+    "apply": 2.5,
+    "binary_fetch_error_classification_e2e": 0.0,
+    "blob_fetcher_edges_e2e": 0.06,
+    "child_deadline_guard": 0.08,
+    "cli": 4.7,
+    "cli_apply_silent": 0.01,
+    "cli_argv_non_utf8": 0.0,
+    "cli_config_fallback": 0.09,
+    "cli_get_silent": 0.01,
+    "cli_global_args": 0.12,
+    "cli_parse_apply": 0.0,
+    "cli_parse_get": 0.02,
+    "cli_parse_list": 0.04,
+    "cli_parse_main": 0.03,
+    "cli_parse_remove": 0.01,
+    "cli_parse_repair": 0.01,
+    "cli_parse_rollback": 0.0,
+    "cli_parse_scan": 0.05,
+    "cli_parse_vendor": 0.02,
+    "cli_parse_vex": 0.01,
+    "cli_path_flags_validated": 0.13,
+    "cli_remove_silent": 0.03,
+    "cli_scan_silent": 0.05,
+    "cli_sigpipe": 0.01,
+    "command_module_layering": 0.03,
+    "contract_gradle_codes": 0.36,
+    "contract_paid_required": 0.0,
+    "crawl_fd_limit_e2e": 0.15,
+    "crawler_cargo_e2e": 0.01,
+    "crawler_composer_e2e": 0.27,
+    "crawler_deno_e2e": 0.0,
+    "crawler_go_e2e": 0.01,
+    "crawler_gradle_e2e": 0.18,
+    "crawler_maven_e2e": 0.01,
+    "crawler_monorepo_gaps": 0.01,
+    "crawler_npm_e2e": 7.78,
+    "crawler_nuget_e2e": 0.04,
+    "crawler_python_e2e": 0.34,
+    "crawler_ruby_e2e": 0.28,
+    "crawlers_empty_paths_e2e": 0.02,
+    "docker_e2e_cargo": 0.0,
+    "docker_e2e_composer": 0.0,
+    "docker_e2e_deno": 0.0,
+    "docker_e2e_gem": 0.0,
+    "docker_e2e_golang": 0.0,
+    "docker_e2e_maven": 0.0,
+    "docker_e2e_npm": 0.0,
+    "docker_e2e_nuget": 0.0,
+    "docker_e2e_pypi": 0.0,
+    "docker_e2e_sbt": 0.0,
+    "docker_e2e_vendor_composer": 0.0,
+    "docker_e2e_vendor_gem": 0.0,
+    "docker_e2e_vendor_maven": 0.0,
+    "docker_e2e_vendor_nuget": 0.0,
+    "docker_e2e_vendor_pypi_pm": 0.0,
+    "e2e_bun_lockb": 0.01,
+    "e2e_cargo": 0.09,
+    "e2e_composer": 0.03,
+    "e2e_composer_vendor_dir_hints": 0.02,
+    "e2e_composer_version_identity": 0.04,
+    "e2e_embedded_vex": 0.04,
+    "e2e_gem": 0.02,
+    "e2e_golang": 0.02,
+    "e2e_golang_build": 1.7,
+    "e2e_golang_hosted_build": 3.26,
+    "e2e_golang_hosted_state": 0.09,
+    "e2e_golang_workspace_build": 3.12,
+    "e2e_gradle_agent_build": 0.01,
+    "e2e_gradle_discovery_build": 0.07,
+    "e2e_hosted_production": 0.0,
+    "e2e_maven": 0.02,
+    "e2e_npm": 0.0,
+    "e2e_nuget": 0.02,
+    "e2e_nuget_dotnet_build": 0.0,
+    "e2e_pypi": 0.0,
+    "e2e_pypi_bytecode": 0.15,
+    "e2e_pypi_multi_copy": 0.05,
+    "e2e_redirect_bun_build": 0.01,
+    "e2e_redirect_cargo_build": 0.66,
+    "e2e_redirect_cargo_shapes": 2.85,
+    "e2e_redirect_composer_build": 0.0,
+    "e2e_redirect_gem_build": 0.0,
+    "e2e_redirect_gem_stale_install": 0.71,
+    "e2e_redirect_gradle_build": 0.02,
+    "e2e_redirect_maven_build": 0.0,
+    "e2e_redirect_npm_build": 0.0,
+    "e2e_redirect_pnpm_build": 0.03,
+    "e2e_redirect_rush_sim": 0.0,
+    "e2e_redirect_uv_build": 0.0,
+    "e2e_redirect_vlt_build": 0.0,
+    "e2e_redirect_yarn_berry_build": 14.37,
+    "e2e_redirect_yarn_classic_build": 6.44,
+    "e2e_safety_cargo_build": 0.02,
+    "e2e_safety_cow": 0.08,
+    "e2e_safety_internals": 0.0,
+    "e2e_safety_lock": 1.01,
+    "e2e_safety_pnpm": 0.0,
+    "e2e_safety_vlt": 0.01,
+    "e2e_safety_yarn_pnp": 0.08,
+    "e2e_sbt": 0.16,
+    "e2e_sbt_build": 0.0,
+    "e2e_sbt_hosted": 0.1,
+    "e2e_sbt_vendor": 0.48,
+    "e2e_sbt_vendor_build": 0.0,
+    "e2e_scala_cli_vendor": 0.17,
+    "e2e_scan": 0.0,
+    "e2e_socket_yml_policy": 0.87,
+    "e2e_vendor_bun_build": 0.02,
+    "e2e_vendor_cargo_build": 0.74,
+    "e2e_vendor_composer_build": 0.01,
+    "e2e_vendor_composer_crlf": 0.05,
+    "e2e_vendor_gem_build": 0.0,
+    "e2e_vendor_golang_build": 1.03,
+    "e2e_vendor_gradle_build": 0.02,
+    "e2e_vendor_jvm_build": 0.03,
+    "e2e_vendor_maven_build": 0.0,
+    "e2e_vendor_npm_build": 1.24,
+    "e2e_vendor_pnpm_build": 12.61,
+    "e2e_vendor_pypi_build": 34.89,
+    "e2e_vendor_vlt_build": 0.0,
+    "e2e_vendor_yarn_berry_build": 2.22,
+    "e2e_vendor_yarn_classic_build": 0.95,
+    "e2e_vendor_yarn_classic_dev_flow": 1.81,
+    "e2e_vendored_production": 0.0,
+    "e2e_vex": 0.15,
+    "e2e_vex_build": 0.0,
+    "e2e_vex_lockfile": 11.21,
+    "e2e_vex_redirect": 0.41,
+    "e2e_vex_vendor": 0.14,
+    "e2e_vlt": 0.56,
+    "e2e_yarn4_pnpm_linker_build": 2.57,
+    "e2e_yarn4_workspaces_build": 2.08,
+    "e2e_yarn_legacy_cachekey_refusal_build": 0.71,
+    "ecosystem_dispatch_e2e": 0.21,
+    "fuzzy_match_e2e": 0.0,
+    "get": 0.68,
+    "global_probe_spawn_e2e": 0.02,
+    "global_scope_project_state": 0.24,
+    "gradle_agent_cli": 0.29,
+    "help_text_hygiene": 0.11,
+    "hosted_inventory": 0.06,
+    "hosted_memory_engine": 0.78,
+    "hosted_memory_parity": 0.26,
+    "hosted_memory_rollout": 0.22,
+    "hosted_superseding_pypi": 0.07,
+    "in_process_agent_reapply": 0.14,
+    "in_process_alternate_installers": 4.58,
+    "in_process_cargo_apply": 0.82,
+    "in_process_edge_cases": 0.17,
+    "in_process_gem_apply": 0.55,
+    "in_process_gem_multi_platform": 0.26,
+    "in_process_get": 0.11,
+    "in_process_get_corrupt_manifest": 0.0,
+    "in_process_get_hosted_ecosystems": 0.29,
+    "in_process_get_manifest_path": 0.06,
+    "in_process_get_modes": 0.13,
+    "in_process_get_update_count": 0.01,
+    "in_process_get_uuid_fallback": 0.01,
+    "in_process_pypi_apply": 8.43,
+    "in_process_pypi_multi_release": 9.6,
+    "in_process_python_envs": 0.22,
+    "in_process_redirect": 4.06,
+    "in_process_redirect_pdm": 0.47,
+    "in_process_redirect_pipenv": 0.67,
+    "in_process_redirect_pnpm": 1.81,
+    "in_process_redirect_poetry": 0.27,
+    "in_process_remote_ecosystems_apply": 1.04,
+    "in_process_remove_repair_lifecycle": 0.56,
+    "in_process_rollback_all_ecosystems": 0.57,
+    "in_process_rollback_hosted": 1.96,
+    "in_process_rollback_vendored": 0.19,
+    "in_process_scan": 0.19,
+    "in_process_scan_withdrawn": 0.35,
+    "in_process_target_ambiguity": 0.51,
+    "in_process_vendor": 5.58,
+    "in_process_vendor_bun_takeover": 0.42,
+    "in_process_vendor_npm_v1_takeover": 0.12,
+    "in_process_vendor_pnpm_parent_child": 0.17,
+    "in_process_vendor_pnpm_takeover": 0.19,
+    "in_process_vendor_pypi_takeover": 0.1,
+    "json_error_shape": 0.03,
+    "manifest_load_error_matrix": 0.16,
+    "manifest_path_ledger_root": 0.09,
+    "maven_sidecar_cli": 0.05,
+    "mode_migration_bun": 0.0,
+    "mode_migration_cargo": 0.78,
+    "mode_migration_composer": 0.31,
+    "mode_migration_npm": 3.45,
+    "mode_migration_pypi": 1.06,
+    "mode_migration_vlt": 0.01,
+    "output_helpers_e2e": 0.0,
+    "package_e2e": 0.01,
+    "pnpm_hosted": 0.02,
+    "poetry_hosted": 0.02,
+    "policy_pypi_names": 0.07,
+    "proxy_batch_e2e": 0.42,
+    "redirect_golden": 0.11,
+    "redirect_sbt_golden": 0.09,
+    "remedy_commands_parse": 0.17,
+    "remove": 0.78,
+    "remove_rollback_api_overrides": 0.01,
+    "repair": 1.54,
+    "rollback": 0.72,
+    "rollback_new_file_e2e": 0.01,
+    "scan": 4.26,
+    "scan_api_retry_e2e": 2.52,
+    "scan_get_mode_from_project_state": 0.17,
+    "scan_pnpm_relocated_store_cwd_e2e": 0.02,
+    "scan_requirements_lock_only": 0.66,
+    "scan_rollout_e2e": 0.56,
+    "scan_vendor_e2e": 0.49,
+    "scan_vendor_requirements_unwired": 0.07,
+    "self_update_e2e": 4.02,
+    "self_update_failures_e2e": 4.51,
+    "spawn_env_hygiene": 0.07,
+    "telemetry_helpers_e2e": 0.0,
+    "update": 4.75,
+    "update_state_env": 0.0,
+    "upstream_restore_golden": 1.45,
+    "user_patches": 0.15,
+    "uv_hosted": 0.0,
+    "vendor": 1.93,
+    "vendor_crash_safety_e2e": 0.09,
+    "vendor_eject": 0.14,
+    "vendor_eject_bun_lockb": 0.32,
+    "vendor_eject_fresh_checkout": 0.16,
+    "vendor_group_commit_e2e": 1.83,
+    "vendor_jvm_cli": 0.86,
+    "vendor_ledger_schema_e2e": 0.73,
+    "vendor_partial_staging_e2e": 0.09,
+    "vex": 0.06,
+    "vlt_locks": 3.16
+  }
+}

scripts/ci-test-shard.py

@@ -12,13 +12,21 @@
 
 Windows debug CI sets CI_TEST_TIMINGS to the checked-in runtime sample.
 Those shards balance measured test time plus linking work, with shard 1's
-unit tests reserved up front. Other runners retain the count-based split.
+unit tests reserved up front. Coverage shards do the same on their own
+Linux sample (scripts/ci-coverage-durations.json) unless CI_TEST_TIMINGS
+is set; setting it empty on the coverage step keeps the count split.
 
 CI_TEST_COVERAGE=1 runs the shard under cargo-llvm-cov for ci.yml's
 `coverage` job: `cargo llvm-cov --no-report` in place of `cargo test`, and
 no doctests, which cargo-llvm-cov leaves out without `--doctests`. A later
 `cargo llvm-cov report` exports the shard's profiles.
 
+Each test binary's `finished in` time is collected from cargo's output and
+printed at the end as one `ci-test-shard: timings {...}` JSON line, along
+with how long cargo took to reach its first test binary. The log tail is
+what log viewers and the log API return, so a fresh runtime sample can be
+read from any shard's log.
+
 Extra arguments after `SHARD COUNT` go to every `cargo` invocation.
 Each invocation runs with `--no-fail-fast`; the exit status is non-zero if
 any of them failed.
@@ -30,13 +38,31 @@
 import json
 import os
 from pathlib import Path
+import re
 import subprocess
 import sys
+import threading
+import time
+
+# The Linux runtime sample coverage shards balance on (the Windows one,
+# scripts/ci-test-durations.json, doesn't model them: #1768).
+COVERAGE_TIMINGS = Path(__file__).with_name("ci-coverage-durations.json")
 
 # Shard 1's share of the integration targets, relative to every other
 # shard's 1.0 (it also carries the unit tests and doctests).
 FIRST_SHARD_WEIGHT = 0.5
 
+# cargo's `Running tests/x.rs (target/debug/deps/x-0123456789abcdef)` and
+# `test result: ... finished in 1.23s` lines. The binary name, not the source
+# path, is the target name (tests/apply/main.rs is `apply`); unit-test
+# binaries are recorded as `unit:<crate>`. ANSI colour is stripped first.
+ANSI = re.compile(r"\x1b\[[0-9;]*m")
+RUNNING = re.compile(r"^\s*Running (unittests )?\S+ \(.*?([^/\\]+)-[0-9a-f]{16}(?:\.exe)?\)\s*$")
+RESULT = re.compile(r"^test result: .*finished in ([0-9.]+)s\s*$")
+
+# How long run() keeps reading cargo's pipe after cargo exits.
+DRAIN_SECONDS = 10
+
 
 def integration_targets(metadata):
     """Sorted, de-duplicated names of the workspace's integration tests."""
@@ -90,6 +116,45 @@ def invocations(shard, count, names, extra=(), timings=None, coverage=False):
     return runs
 
 
+def run(args, timings):
+    """Run `args`, echoing its merged output byte for byte, and add each test
+    binary's `finished in` seconds to `timings`. Returns the exit status and
+    when the first test binary started (None if none did)."""
+    first = None
+
+    def forward(pipe):
+        nonlocal first
+        current = None
+        echo = True
+        for raw in pipe:
+            # Keep draining after a failed write (say `tee` died): a reader
+            # that stops would leave cargo blocked on a full pipe.
+            if echo:
+                try:
+                    sys.stdout.buffer.write(raw)
+                    sys.stdout.buffer.flush()
+                except (OSError, ValueError):
+                    echo = False
+            line = ANSI.sub("", raw.decode("utf-8", "replace"))
+            if m := RUNNING.match(line):
+                current = ("unit:" if m[1] else "") + m[2]
+                first = first or time.monotonic()
+            elif current and (m := RESULT.match(line)):
+                timings[current] = timings.get(current, 0.0) + float(m[1])
+                current = None
+
+    proc = subprocess.Popen(args, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
+    reader = threading.Thread(target=forward, args=(proc.stdout,), daemon=True)
+    reader.start()
+    status = proc.wait()
+    # A process a test left behind (a build daemon, say) can hold the pipe
+    # open after cargo exits; don't wait for it past a short drain.
+    reader.join(timeout=DRAIN_SECONDS)
+    if not reader.is_alive():
+        proc.stdout.close()
+    return status, first
+
+
 def main(argv):
     if len(argv) < 2:
         print(__doc__, file=sys.stderr)
@@ -99,16 +164,26 @@ def main(argv):
         ["cargo", "metadata", "--no-deps", "--format-version", "1"],
         check=True, capture_output=True, text=True).stdout)
     names = integration_targets(metadata)
-    timing_path = os.environ.get("CI_TEST_TIMINGS")
-    timings = json.loads(Path(timing_path).read_text(encoding="utf-8")) if timing_path else None
     coverage = os.environ.get("CI_TEST_COVERAGE") == "1"
+    timing_path = os.environ.get("CI_TEST_TIMINGS", COVERAGE_TIMINGS if coverage else None)
+    timings = json.loads(Path(timing_path).read_text(encoding="utf-8")) if timing_path else None
     print(f"ci-test-shard: shard {shard}/{count}: "
           f"{len(partition(names, count, timings)[shard - 1])} of {len(names)} integration targets", flush=True)
     status = 0
+    measured = {}
+    build = 0.0
     for args in invocations(shard, count, names, argv[2:], timings, coverage):
         print("+ " + " ".join(args), flush=True)
-        if subprocess.run(args).returncode != 0:
+        start = time.monotonic()
+        code, first = run(args, measured)
+        if code != 0:
             status = 1
+        # Build time of this invocation: start to its first test binary.
+        # (The doctest run prints no `Running` line and isn't counted.)
+        if first is not None:
+            build += first - start
+    measured = {"_build_seconds": build, **dict(sorted(measured.items(), key=lambda kv: (-kv[1], kv[0])))}
+    print("ci-test-shard: timings " + json.dumps({k: round(v, 2) for k, v in measured.items()}), flush=True)
     return status