8f647a13

Report where a mutation run's time goes

## Why

Mutation checks routinely take hours in nix-ci and there was no way to find out why. The driver already measured each child's wall time (`Mutate.hs:runOneSuite`) but discarded it unless the child timed out; nothing was aggregated or reported. The coverage child measured its own in-process test time and wrote it as `baseline.json`, used only to derive per-mutation timeouts.

One wall-clock number per child would not have been enough anyway — see below.

## The three-way split, and why it is the whole point

Every child process pays three separate costs, and **which one dominates decides what would actually make the run faster**:

| cost | what it is | what to do if it dominates |
|---|---|---|
| **process startup** | exec, RTS init, `readAugmentedManifestFile`, `execTestDefM`, printing output | test several mutations per child |
| **suite setup** | `around`/`aroundAll` resources (tmp-postgres, webdriver), paid once per *child* rather than once per *suite* | share those resources across children |
| **test execution** | the leaf tests themselves | covering-test sets are too big, or the tests are slow |

Only the child can tell these apart, so it now writes its own numbers to a file the parent names with a new hidden `--mutation-timing-output`:

- `childTimingForestNanos` — `timedTime` of the `runSpecForestSynchronously` call
- `childTimingTestNanos` — `testSuiteStatSumTime` from `computeTestSuiteStats`
- `childTimingTestsRun` — leaves that ran (fewer than the covering-test count, under the child's fail-fast)

The parent subtracts: `startup = wall − forest`, `setup = forest − tests`, `tests = tests`. `childCosts` clamps the child's numbers to the parent's wall measurement first, so the parts **always sum to exactly the wall time** even if a child reports something impossible (there is a property test for this). A child that never wrote the file — killed on its timeout, or crashed first — is booked as `unattributed` rather than as three zeroes.

## What this immediately tells us

On the in-repo example project:

```
Timing report: mutation phase
  Wall clock                       4.21s
  Children                           328
  Sum of child wall time          16.57s
  Achieved parallelism        3.94× of 4

Where the child time goes
  process startup         15.94s   96.2%
  suite setup            486.8ms    2.9%
  test execution         140.9ms    0.9%
```

Coverage phase on the same project: **98.8% process startup**. On a toy project that is expected; on nix-ci, where suites spin up tmp-postgres, I would expect suite setup to take a large share instead. Either way the number now exists.

## Data flow

```
child (sydtest)                     parent (driver)                    output
──────────────────────────────────────────────────────────────────────────────
Single.hs         ─┐
SingleCoverage.hs ─┴─ ChildTiming ──> Mutate.hs / Coverage.hs ──> MutationPhaseTiming
                     (timing.json      (adds wall time, outcome,   CoveragePhaseTiming
                      in a temp dir)    covering-test count)              │
                                                                          v
                                                    summariseMutationPhase / ...Coverage
                                                                          │
                                              PhaseTimingSummary ─────────┤
                                                                          │
                              renderPhaseTimingSummary (terminal, limited)─┤─> stdout
                              renderPhaseTimingSummaryHtml ────────────────┴─> timing.html
```

### Where things live

- **`sydtest-mutation-runtime`**
  - `Test/Syd/Mutation/Timing.hs` — `ChildTiming`, what a child measures of itself.
  - `Test/Syd/Mutation/TimingReport.hs` — the recorded phase timings (`MutationPhaseTiming`, `CoveragePhaseTiming`), the pure aggregation (`summariseMutationPhase`, `summariseCoveragePhase` → `PhaseTimingSummary`), and the terminal renderer.
  - `Test/Syd/Mutation/TimingReport/Html.hs` — the same summary as a standalone page.
- **`sydtest`**
  - `OptParse.hs` — `--mutation-timing-output`, on both child settings records.
  - `MutationMode/Common.hs` — `childTimingOf`, `diffMonotonicNanos`.
  - `MutationMode/Single.hs`, `MutationMode/SingleCoverage.hs` — write the file.
- **`sydtest-mutation-driver`**
  - `Driver/Mutate.hs` — records a `MutationChildTiming` per child run, times the phase, writes both files.
  - `Driver/Coverage.hs` — same for coverage; also counts attempts so a flaky test shows up as such. `runCoverageMode` now takes a resolved job count and returns its timings for `Driver.hs:runCoverage` to accumulate across suites.
  - `Driver/Timing.hs` — `emitPhaseTimingReport`: writes the page, prints the abridged copy (only when the phase ran children, so the diff runner on an empty selection stays quiet).
  - `Driver/AssertScore.hs` — links the timing files through to `$out`, names `timing.html` alongside the report paths. Both are optional, so an older report directory does not crash a passing check.

## The page

Self-contained (inline CSS and JS, no external assets), so it opens straight from a Nix store path.

- Headline stacked bar for the phase, then a row per cost with an explanation of what to do about it.
- Grouped views: by suite, outcome, operator, module, and — only when more than one suite ran, since otherwise it repeats the per-child listing row for row — by mutation.
- **Per-child table with every child**, identity split into its own columns (operator, location, suite, outcome, tests run, mutation id). Sortable by any column; numeric columns carry the real nanoseconds in `data-v` so `9.0ms` does not sort after `1m02s`. Filter box with a live row count.
- Bars are stacked and shaded per cost, so a row shows both its size and its composition. Every share on the page is a share of the summed child wall time, so bars in different sections are comparable.
- Light and dark via `prefers-color-scheme`.

Verified in a real browser rather than by reading the markup: both phases screenshotted in light and dark, and the sort and filter driven headlessly (clicking `wall` gives 30s/20s/12s descending, clicking again reverses, filtering to `foo-test` leaves 2 of 3 rows with the count updating).

## How to look at it

```sh
nix build .#checks.x86_64-linux.mutation-sydtest-mutation-example.report.sydtest-mutation-example
xdg-open result/timing.html

nix build .#checks.x86_64-linux.mutation-sydtest-mutation-example.coverage
xdg-open result/<pkg>/augmented/timing.html
```

`timing.json` next to it is the machine-readable form, with every child's raw record.

## Notes for whoever picks this up

- **`.gitignore` had a blanket `*.html`**, which would have left the golden pages untracked and `sydtest-mutation`'s tests failing on missing goldens in a fresh clone. That rule is aimed at haddock and coverage output, so `**/test_resources/*.html` is now excepted. Worth knowing before adding more golden pages.
- **Version bumps**: `sydtest` 0.32.0.0 (breaking — both child settings records gained a field), `sydtest-mutation-driver` 0.3.0.0 (`runCoverageMode` signature), `sydtest-mutation-runtime` 0.1.2.0 (additions only). Changelogs written.
- **Two pre-existing flaky tests in `sydtest-test`** fail under machine load and tripped several of my `nix flake check` runs: `Test.Syd.TimingSpec.long diff timing is bounded` (a 120s wall-clock bound) and `Test.Syd.RunnerSpec.seeds the global pseudorandom generator so a FixedSeed run is reproducible`. Forcing the unmodified-`development` `sydtest-test` derivation to re-run failed 1 in 5 times too, so these are not from this change. The RunnerSpec one is a real latent bug — it asserts a *process-global* `StdGen` is undisturbed across two forest runs while the suite runs its tests in parallel, and `CoverageFailFastSpec` concurrently runs forests that reseed that same global generator. Worth fixing separately.
- The terminal renderer is always row-limited now (`renderPhaseTimingSummary :: Int -> ...`); its only consumer is the build log, and the full detail lives in the page.
- `TimingEntry` carries `timingEntryCells :: [(Text, Text)]` (name, value) so both renderers share one summary; the HTML header row is derived from the first entry's names via `entryColumnNames`, so there is no parallel-list invariant to keep in step.

## Possible next steps

The report exists to be acted on. Given what it says about startup cost, the obvious follow-ups are:

1. **Batch mutations per child** — one child process testing N mutations in sequence amortises exec + RTS init + `execTestDefM` across all of them. Biggest available win if startup keeps dominating.
2. **Share suite resources across children** — matters most for suites with an expensive `aroundAll` (tmp-postgres). The report will say when this is the lever.
3. **Trim covering-test sets** — only if `test execution` turns out to dominate on a real project.

## Feedback loops used

1. `stack build <package> --pedantic`
2. `stack test sydtest-mutation sydtest-mutation-driver-gen sydtest-test --pedantic --test-arguments "--ai-executor"`
3. `pre-commit run -a`
4. `nix flake check` — **passes** (`all checks passed!`)

## Tests

- `sydtest-mutation/test/Test/Syd/TimingReportSpec.hs`: `genValidSpec`/`jsonSpec` and file round-trips for every new type; unit tests for the stacked bar, duration formatting and the cost split (including the property that the split always sums to the wall time); golden terminal reports (full and abridged) and golden pages for both phases; a test that a module name containing `<script>&"'` comes out escaped rather than as markup.
- `sydtest-mutation-driver-gen/.../MutateSpec.hs`: a stand-in suite exe that writes a timing file, asserting `runMutationMode` records a child timing carrying the breakdown the child reported, with the right outcome and covering-test count, and writes `timing.html`.

Total

16m52s

Created 1 month ago Started 1 month ago Finished 1 month ago

Timeline