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`.