|
32 | 32 | // was reachable from NO other file in `packages/cli` (which is why it was |
33 | 33 | // absent from the ledger in the first place), so this entry re-resolves |
34 | 34 | // exactly one file — the new test — and cannot move any existing suite. |
35 | | -// Measured again after: 135 files / 1470 tests, unchanged. |
| 35 | +// Measured again after: unchanged. ⚠️ The file/test COUNT that "unchanged" was |
| 36 | +// checked against is deliberately not repeated here. This file used to carry |
| 37 | +// this package's population in two separate sections; the two copies drifted |
| 38 | +// apart and neither said which was current, so the population is now stated |
| 39 | +// ONCE — with the commit it was measured on — in the suite-cost section below. |
36 | 40 | // |
37 | 41 | // ## Why the create-objectstack entry (#10557) |
38 | 42 | // |
|
62 | 66 | // suite cost in this repo — per-file module-graph re-execution under isolation, |
63 | 67 | // the proxy `scripts/partition-test-shards.mjs` weights by — predicted the |
64 | 68 | // cause would be import surface, which would have made a `test` block (`pool`, |
65 | | -// `isolate`) the lever. Measured on 2026-08-20, it is NOT that, and the |
66 | | -// measurement is recorded here because this file is where the next person |
67 | | -// looking for a lever will arrive. |
| 69 | +// `isolate`) the lever. It is NOT that, and the measurement is recorded here |
| 70 | +// because this file is where the next person looking for a lever will arrive. |
68 | 71 | // |
69 | | -// One machine, 4 cores, warm build, `npx vitest run --maxWorkers=2` per |
70 | | -// package, vitest 4.1.10. Both normalisers, because per-FILE cost alone cannot |
71 | | -// tell "expensive suite" from "more tests per file": |
| 72 | +// ⚠️ EVERY FIGURE BELOW COMES FROM ONE RUN ON ONE STATED COMMIT — 2f665a1af, |
| 73 | +// re-measured 2026-08-26 (#12499). The first version of this section carried a |
| 74 | +// DATE and no commit, and the population moved under it while the figures went |
| 75 | +// on reading as precise: 137 files / 1498 tests had become 185 / 2115, and 20 |
| 76 | +// spawner files had become 39, before anyone checked. A date says when someone |
| 77 | +// looked; a commit says WHAT they looked at, and only the second can be |
| 78 | +// re-checked. Whoever re-measures next: print your commit here, and keep these |
| 79 | +// counts in exactly one place in this file — a second copy is what rotted last |
| 80 | +// time, because the two drifted and neither said which was current. |
| 81 | +// |
| 82 | +// PROTOCOL. One machine, 4 cores, warm build, one `vitest run --maxWorkers=2` |
| 83 | +// per package, vitest 4.1.10 on node 22.22.2. ⚠️ Several agents share this |
| 84 | +// container, so every run below held the shared heavy-verify lock |
| 85 | +// (`scripts/pm/os-verify-lock.sh`): a suite timed beside a neighbour's build is |
| 86 | +// a reading about the box, not about the suite. |
| 87 | +// |
| 88 | +// Contention actually seen, so the absolutes can be discounted honestly: three |
| 89 | +// other agents were working this container. The `cli` run waited 4m01s for the |
| 90 | +// lock behind a neighbour's build and then held it 13m14s; the five peer runs |
| 91 | +// waited 7m03s and held 8m57s. The lock serialises LOCKED work only — a |
| 92 | +// neighbour's UNLOCKED gate script was seen at ~130% CPU partway through the |
| 93 | +// `cli` run — and 1-minute load averaged 4.36 (peak 6.97) on 4 cores across it. |
| 94 | +// ⛔ Also part of the protocol: each package was measured against a tree with |
| 95 | +// its own dependency closure BUILT. A package measured without one does not |
| 96 | +// report a cheap wall, it fails loudly — `example-showcase` did, first time. |
| 97 | +// |
| 98 | +// ⚠️ WHICH OF THESE TRAVEL TO ANOTHER BOX. #11707 re-ran this section's |
| 99 | +// absolutes elsewhere and they did NOT reproduce, while the ratio it cared |
| 100 | +// about did. So: every figure in SECONDS here is box-dependent and comparable |
| 101 | +// only inside this one run — the walls, s/file, s/test, the `Duration` split, |
| 102 | +// the per-spawn floors. What a reader on another box should expect to reproduce |
| 103 | +// are the RATIOS: tests/file, the top-20 concentration, the spawner share of |
| 104 | +// the file wall, this package's multiple over its peers, and the ratio between |
| 105 | +// the two spawn floors. |
| 106 | +// |
| 107 | +// Both normalisers, because per-FILE cost alone cannot tell "expensive suite" |
| 108 | +// from "more tests per file": |
72 | 109 | // |
73 | 110 | // package files tests tests/file wall s/file s/test |
74 | | -// @objectstack/cli 137 1498 10.9 495.81s 3.619 0.3310 |
75 | | -// @objectstack/spec 415 11045 26.6 325.31s 0.784 0.0295 |
76 | | -// …/service-automation 83 991 11.9 57.97s 0.698 0.0585 |
77 | | -// …/driver-turso 39 1003 25.7 38.50s 0.987 0.0384 |
78 | | -// @objectstack/client 23 314 13.7 23.75s 1.033 0.0756 |
79 | | -// …/example-showcase 21 342 16.3 31.15s 1.483 0.0911 |
| 111 | +// @objectstack/cli 185 2115 11.4 793.31s 4.288 0.3751 |
| 112 | +// @objectstack/spec 432 11460 26.5 358.46s 0.830 0.0313 |
| 113 | +// …/service-automation 91 1082 11.9 96.06s 1.056 0.0888 |
| 114 | +// …/driver-turso 39 1006 25.8 33.89s 0.869 0.0337 |
| 115 | +// @objectstack/client 25 346 13.8 18.74s 0.750 0.0542 |
| 116 | +// …/example-showcase 26 364 14.0 32.94s 1.267 0.0905 |
80 | 117 | // |
81 | | -// Normalising per TEST makes this package look worse, not better: it has the |
82 | | -// LOWEST tests-per-file of the six, so its 2.4-5.2x per-file cost becomes |
83 | | -// 3.6-11x per test. "It just has more tests per file" is falsified. |
| 118 | +// Normalising per TEST makes this package look WORSE, not better: it has the |
| 119 | +// LOWEST tests-per-file of the six, so its 3.4-5.7x per-file cost becomes |
| 120 | +// 4.1-12.0x per test. "It just has more tests per file" is falsified. ⚠️ Read |
| 121 | +// the SHAPE of that check, not only its answer: the multiple has to WIDEN when |
| 122 | +// the normaliser changes, and it does. |
84 | 123 | // |
85 | 124 | // The `Duration` split says where the cost is NOT: |
86 | 125 | // |
87 | | -// cli 495.81s (transform 29.47s, setup 0ms, import 192.91s, tests 774.95s) |
88 | | -// spec 325.31s (transform 13.79s, setup 0ms, import 63.90s, tests 456.36s) |
89 | | -// svc-auto 57.97s (transform 14.54s, setup 0ms, import 96.78s, tests 4.73s) |
90 | | -// turso 38.50s (transform 16.85s, setup 0ms, import 65.98s, tests 3.56s) |
91 | | -// client 23.75s (transform 18.31s, setup 0ms, import 39.72s, tests 2.25s) |
| 126 | +// cli 793.31s (transform 25.17s, setup 0ms, import 203.72s, tests 1353.09s) |
| 127 | +// spec 358.46s (transform 15.68s, setup 0ms, import 68.50s, tests 528.18s) |
| 128 | +// svc-auto 96.06s (transform 14.72s, setup 0ms, import 172.68s, tests 4.71s) |
| 129 | +// turso 33.89s (transform 14.13s, setup 0ms, import 56.93s, tests 3.62s) |
| 130 | +// client 18.74s (transform 10.91s, setup 0ms, import 30.15s, tests 2.38s) |
| 131 | +// showcase 32.94s (transform 16.68s, setup 0ms, import 48.76s, tests 12.78s) |
92 | 132 | // |
93 | | -// Per file this package's import cost is 1.41s and its transform cost 0.215s — |
94 | | -// MID-BAND and LOWEST respectively (client 1.73s/file import, turso 1.69s). |
95 | | -// The wide dependency closure in `package.json` is not what the test files |
96 | | -// import. `setup` is 0ms everywhere, so setupFiles cost is not it either. |
| 133 | +// Per file this package's import cost is 1.10s and its transform cost 0.136s — |
| 134 | +// SECOND-LOWEST of the six on BOTH; only `spec` is below it (0.16s import, |
| 135 | +// 0.036s transform), and the tops are `service-automation` at 1.90s import and |
| 136 | +// `example-showcase` at 0.642s transform. The wide dependency closure in |
| 137 | +// `package.json` is not what the test files import. `setup` is 0ms in all six, |
| 138 | +// so setupFiles cost is not it either — and that zero was checked against an |
| 139 | +// instrument that can say otherwise: the same reporter, pointed at a |
| 140 | +// deliberate 300ms setup file, reports it. |
97 | 141 | // |
98 | 142 | // The cost is test-body work, and it is concentrated, not uniform: median file |
99 | | -// 0.03s, 105 of 137 files under 2s, top 20 files = 87.7% of the wall. The 20 |
100 | | -// files that spawned the real CLI as a subprocess (all 20 of them |
101 | | -// `bin/run-dev.js` through `tsx` on that date, against a `mkdtemp` project) |
102 | | -// were 56.1% of the file wall (300.1s) while carrying 177 of 1498 tests — |
103 | | -// three have since moved to the built entry (#11707; last section of this |
104 | | -// header) and the split has not been re-measured. Each spawn re-executes the |
105 | | -// CLI's module graph in a COLD process, which is the standing theory after |
106 | | -// all — relocated out of vitest's worker, where neither its transform cache |
107 | | -// nor its module registry can reach it. Floor per spawn, doing nothing but |
108 | | -// printing a version: |
109 | | -// |
110 | | -// tsx bin/run-dev.js --version 6.5-6.8s (the source entry all 20 used) |
111 | | -// node bin/run.js --version 2.9-3.2s (the built entry) |
112 | | -// node -e 0 0.031s (process floor) |
| 143 | +// 0.05s, 129 of 185 files under 2s, top 20 files = 71.3% of the file wall |
| 144 | +// (965.3s of 1353.1s). "File wall" here is the sum of the per-module run |
| 145 | +// durations, which is the SAME quantity vitest prints as the `tests` term |
| 146 | +// above — said out loud so the two can be checked against each other instead of |
| 147 | +// drifting apart, which is how this section went stale the first time. |
| 148 | +// |
| 149 | +// The 39 files that spawn the real CLI as a subprocess (against a `mkdtemp` |
| 150 | +// project) are 89.4% of that file wall (1209.8s) while carrying 319 of the 2115 |
| 151 | +// tests — and they are the WHOLE of the top 20, all twenty of them. Each spawn |
| 152 | +// re-executes the CLI's module graph in a COLD process, which is the standing |
| 153 | +// theory after all — relocated out of vitest's worker, where neither its |
| 154 | +// transform cache nor its module registry can reach it. |
| 155 | +// |
| 156 | +// ⚠️ THE SPAWNER SET MOVED IN BOTH DIRECTIONS AT ONCE, which is why the two |
| 157 | +// shares here disagree with the 2026-08-20 pair in OPPOSITE directions: 20 |
| 158 | +// spawner files became 39, so the share of the wall they hold ROSE (56.1% -> |
| 159 | +// 89.4%) while the top-20 concentration FELL (87.7% -> 71.3%) — the same kind |
| 160 | +// of cost, spread across more files. Either number read alone tells the wrong |
| 161 | +// story; the pair is the finding. |
| 162 | +// |
| 163 | +// ⚠️ COUNTING THE SPAWNERS: match the entry BASENAME, not `bin/run-dev.js`. |
| 164 | +// Three of the 39 assemble the path from separate literals |
| 165 | +// (`join(…, '..', 'bin', 'run-dev.js')`) and a slash-joined pattern misses all |
| 166 | +// three — silently, since the answer it returns is still a plausible number. |
| 167 | +// Prose mentions do not count either: at least one file names the entry four |
| 168 | +// times while explicitly not spawning it. |
| 169 | +// |
| 170 | +// By entry point, after #11707 moved three files onto the built one: |
| 171 | +// |
| 172 | +// 35 files spawn `bin/run-dev.js` (source) 1169.2s 33.4s/file 311 tests |
| 173 | +// 4 files spawn `bin/run.js` (built) 40.6s 10.1s/file 8 tests |
| 174 | +// |
| 175 | +// ⛔ That is NOT a measurement of what the two entries cost. Those four are also |
| 176 | +// the smallest files here — 2.0 tests/file against 8.9 — and per TEST the |
| 177 | +// ordering REVERSES (5.1s vs 3.8s). File-level shares say where the wall sits, |
| 178 | +// not what one spawn costs. What a spawn costs is measured directly, one spawn |
| 179 | +// at a time, below. |
| 180 | +// |
| 181 | +// Floor per spawn, doing nothing but printing a version — 5 timed runs each |
| 182 | +// after one discarded warm-up, box idle inside the lock: |
| 183 | +// |
| 184 | +// tsx bin/run-dev.js --version 5.45-6.07s (the source entry, 35 files) |
| 185 | +// node bin/run.js --version 2.46-2.66s (the built entry, 4 files) |
| 186 | +// node -e 0 0.025-0.031s (process floor) |
| 187 | +// |
| 188 | +// ⚠️ The absolutes moved from the 2026-08-20 reading (6.5-6.8 / 2.9-3.2 / |
| 189 | +// 0.031); the RATIO did not — source-over-built was 2.18x then and 2.21x here (means of the five runs each). |
| 190 | +// That is the #11707 pattern exactly: carry the ratio to another box, never the |
| 191 | +// seconds. |
| 192 | +// |
| 193 | +// ⛔ The exit code is PART of this measurement, not a formality. A nonexistent |
| 194 | +// entry (`node bin/run-NOPE.js --version`, exit 1) returns in 0.030s — which |
| 195 | +// reads as a better floor than anything real. Timing alone cannot tell "fast" |
| 196 | +// from "never ran"; every row above was checked for exit 0. |
| 197 | +// |
| 198 | +// ⚠️ A port-selection change (#12441) was in flight on three of these spawner |
| 199 | +// files (`serve-node-env-production-default`, |
| 200 | +// `serve-app-anchored-optional-import`, `helpers/serve-process`) while this was |
| 201 | +// measured. It changes which PORT a spawned `serve` binds, not which ENTRY is |
| 202 | +// spawned, so the source-vs-built split above is unaffected by it; it can move |
| 203 | +// wall times slightly. Recorded so the next reader can tell drift from noise. |
113 | 204 | // |
114 | 205 | // ⚠️ Two levers were measured and both are rejected HERE, on this evidence: |
115 | 206 | // |
116 | | -// `test: { maxWorkers: 4 }` — real but not ours to take. 2->4 workers on an |
117 | | -// idle box is 495.81s -> 337.13s, but CPU is flat (user+sys 1291.3s -> |
118 | | -// 1256.2s) and per-file wall INFLATES (sum 535.1s -> 748.3s; longest file |
119 | | -// 74.3s -> 104.1s): the box is saturated, so this is packing, not work. In CI |
| 207 | +// `test: { maxWorkers: 4 }` — real but not ours to take. 2->4 workers on this |
| 208 | +// box is 793.31s -> 565.86s, but CPU is FLAT (user+sys 2028.5s -> 1971.2s) |
| 209 | +// and per-file wall INFLATES (sum 1353.1s -> 1969.8s; longest file 94.0s -> |
| 210 | +// 114.1s): the box is saturated, so this is packing, not work. Re-measured on |
| 211 | +// the commit above, and the 2026-08-20 verdict reproduced in every term. In CI |
120 | 212 | // the box is not this package's — `ci.yml` runs `turbo run test |
121 | 213 | // --concurrency=4` — so pinning a worker count here spends cores belonging to |
122 | 214 | // whatever else lands on the shard. Worker allocation is a property of the |
123 | 215 | // shard, decided in `ci.yml`, not of this config (#10149). |
124 | 216 | // |
125 | | -// `NODE_COMPILE_CACHE` for the spawned processes — measured 6.98/6.24/6.41/ |
126 | | -// 6.18s cached vs 6.39/6.72s uncached, i.e. inside noise for 42MB of cache. |
127 | | -// The per-spawn cost is module-graph EXECUTION, not compilation. |
| 217 | +// `NODE_COMPILE_CACHE` for the spawned processes — re-measured 5.15/5.34/ |
| 218 | +// 5.16/5.42s cached against 5.46/5.61/5.64/5.71s uncached, for 42MB of cache |
| 219 | +// (783 files). ⚠️ Unlike the 2026-08-20 reading, where the two sets |
| 220 | +// overlapped and the answer was "inside noise", these four-and-four do not |
| 221 | +// overlap: cached is consistently ~0.3s (~5%) faster. It is still not the |
| 222 | +// lever — that is an order of magnitude less than the 3.11s the built entry |
| 223 | +// already saves per spawn, and it buys 42MB to get it. The per-spawn cost is |
| 224 | +// module-graph EXECUTION, not compilation. |
128 | 225 | // |
129 | 226 | // So the work is real, the price is fair, and nothing contained in this package |
130 | 227 | // removes it without changing what the e2e tests assert. |
|
0 commit comments