Commit cba4297
test(rest): give the import-template parity case a measured per-shape budget (#21481)
Fixes #21428
Clause-②: no
The parity case in `packages/rest/src/import-template-route.test.ts`,
"for every shape of default the engine reads", ran past vitest's default
5000ms twice on loaded Test Core shards. I measured where the time goes.
The engine boot costs 5-6ms. The loop over the 20 default shapes is 98%
of the case under every load I tried. So, as the triage ruling says for
the loop case, the case now has an explicit timeout with a stated,
measured budget: 1000ms per shape, which is 20000ms for the 20 shapes
today. The diff is this one test file (+31 / -1). No assertion changes.
## Premise check (done first, on `origin/main`)
- The case is at line 511 on `6210f887` and on `4c8363f4`, this branch's
base. The file was last changed at `88b484e0`. `premise_still_valid:
true`.
- The card said the cause was either a cold engine boot or an unbounded
per-shape loop. Measured: it is the loop. By the time this case runs, 25
cases have already run in the same worker, so its `boot()` is warm:
5-6ms idle. The cold first-use cost goes to the file's first case
instead (see Acceptance notes).
## Where the time goes
I added phase timers (`performance.now()`) to a throwaway copy of the
file. The copy was never committed and is deleted. Each run ran the
whole file, so the parity case ran after the 25 cases above it, as it
does in CI. The box has 4 vCPU and was shared with other jobs. The "busy
loops" are CPU-bound `node -e 'for(;;){}'` processes. Their PIDs were
recorded, and a trap killed them.
| load | whole case | boot | register + sync 20 objects | loop |
|:---|---:|---:|---:|---:|
| idle, 5 runs | 941-1085ms | 5-6ms | 14-15ms | 920-1063ms |
| 2 runs of the file at once, 3 rounds x 2 | 1105-1671ms | 5-7ms |
15-21ms | 1084-1642ms |
| 8 busy loops, 3 runs | 2232-2632ms | 9-10ms | 31-46ms | 2190-2576ms |
| 24 busy loops, 3 runs | 7654-8371ms | 36-44ms | 91-142ms | 7525-8165ms
|
Within the loop, each shape does three things, each about a third of the
loop: build the template through the real export route, parse the
workbook, and import one row through the real import door. Idle totals
were 312-337ms, 303-390ms and 289-344ms. `engine.find` was 4-5ms. The
slowest single shape took 71-100ms idle and 671-912ms at 24 busy loops.
All of that is the work the case asserts on, and boot plus schema sync
is 2% of the case. So moving the boot into a `beforeAll` would remove
about 6ms from a case that takes 7-8s under load. It would not fix this.
## The fix
- `const PARITY_MS_PER_SHAPE = 1_000;`, and the case's timeout is
`Object.keys(PARITY).length * PARITY_MS_PER_SHAPE`. The budget is per
shape because the loop is the cost. If someone adds a shape, the budget
grows with it and the headroom stays the same.
- The arithmetic, also in the comment above the constant: the slowest
per-shape cost measured is 419ms (8371ms / 20, at 24 busy loops). 1000ms
is about 2.4x that, and about 18x the slowest idle per-shape cost
(1085ms / 20 = 54ms). For 20 shapes that gives 20000ms.
- The comment block above the constant records the table above.
- The case's body, its title and all its assertions are byte-identical
to before. There is no skip, retry or quarantine, and vitest's global
timeouts are unchanged.
## Before / after: CI's budget, under load
This reproduces CI's signature on the unmodified file. The measurement
uses 24 busy loops on 4 vCPU and 4 interleaved pairs. Each pair runs
BEFORE first and then AFTER, with the same command and the same load.
Interleaving puts the shared box's drift on both sides.
- BEFORE is a byte-identical copy of the base file (`git hash-object`
`9412aad7`, the same as the `4c8363f4` blob), run beside the committed
file.
- AFTER is the committed file at `bc10b1eb`.
- Command, per leg: `vitest run --project local --maxWorkers=2
--reporter=verbose FILE`, run in `packages/rest`.
| N = 4 each | runs red | parity case | other cases |
|:---|---:|:---|:---|
| before (base file) | **4 / 4** | `Test timed out in 5000ms` at
5048-5160ms, every run | all 36 passed, every run |
| after (`bc10b1eb`) | **0 / 4** | passed, 7557-8166ms | all 36 passed,
every run |
When idle, the committed file at `bc10b1eb` runs 37 passed, and the
parity case takes 1064ms.
The case's own timings did not change, and they could not. The fix
changes the window and leaves the cost alone, because the cost is the
asserted work.
## Precedents read
- `a690c494`, which landed for #19631, removed an unbounded,
load-dependent draw from the clocked window.
- `80c29a14`, which landed for #20242, moved a one-time cold load out of
every clocked window to module scope. It argued against both a
`beforeAll` and a per-case timeout, on the grounds that "every budget
the cost is moved INTO can be exhausted by a heavier shard".
- Neither shape applies here. Nothing in this case's window is loading
or a one-time cost; it is the asserted loop itself. The same caveat
holds for this budget, though. It is 2.4x the heaviest load I could
reproduce, not a bound on every possible shard.
## Verification, at `bc10b1eb`
- Dependency closure built first: `pnpm turbo run build
--filter='@objectstack/rest^...' --concurrency=2`, 24 / 24 tasks.
- `pnpm --filter @objectstack/rest exec vitest run --maxWorkers=2
src/import-template-route.test.ts`: `Tests 37 passed (37)`.
- `pnpm --filter @objectstack/rest test`: `Test Files 256 passed (256)`,
`Tests 4848 passed | 322 skipped (5170)`.
- `pnpm --filter @objectstack/rest typecheck`: exit 0, and
`check:test-typecheck: OK`, 0 files / 0 errors. `tsconfig.json` excludes
`*.test.ts`. `tsc -p tsconfig.test.json --listFiles` includes this file,
so the typecheck does cover it.
- `node scripts/pm/dispatch-gates.mjs --commands --repo
objectstack-ai/objectstack`, with no paths, derived 54 commands for this
diff. All 54 ran and exited 0. `--ran` reports `54 derived famil(ies)
accounted for — 54 run, 0 NOT-MEASURED`. Two of them needed a
prerequisite first:
- `check-plugin-teardown-shape.mjs --self-test` refused on the shallow
clone, because its pinned fixture commit was missing. After fetching
that commit, it exited 0.
- `check:dual-build-cjs-loads` answered PREREQUISITE NOT MET because
there was no `dist/`. After `pnpm turbo run build
--filter='!@objectstack/docs'` (71 of 72 tasks were cache hits), it
exited 0.
- `pnpm lint` is a narrowing, with three pieces of evidence:
1. eslint's own config: `ESLint#isPathIgnored` answers `false` for the
one changed file. The computed config for it carries `parserOptions`
`ecmaVersion` / `sourceType` only, with no `project` and no
`projectService`.
2. `eslint --no-inline-config --format json` on the changed file reports
1 file, 0 errors and 0 warnings.
3. Invariance: type-aware linting is not enabled for any file, as
`eslint.config.mjs` itself states. The diff adds no export and touches
no other file, so it cannot change the verdict on any untouched file.
## Changeset
`skip-changeset`. The diff is one `*.test.ts` file.
`@objectstack/rest`'s `files[]` is `dist`, `README.md` and
`CHANGELOG.md`. After `pnpm --filter @objectstack/rest build`,
`PARITY_MS_PER_SHAPE` and the test-only strings `pty_list` and the
case's title have 0 hits across all three. The positive control
`answerImportTemplate` has 6 hits in `dist/`. No published byte changes.
## Acceptance notes
- The cold first-use cost of this file goes to its first case, "answers
an xlsx template without reading a single row". Its timings were 506ms
idle, 918-1020ms at 8 busy loops, and 2447-3117ms at 24 busy loops,
which is 49-62% of the 5000ms budget. It never went red in any run here,
so this is an observation. It is not filed.
- I could not read CI's per-case time for the two failing runs. The
job-log endpoint redirects to a host that this container's proxy refused
(CONNECT 403). The annotations read only carried the exit lines. So the
CI side is known only as "past 5000ms".
---
_Generated by [Claude
Code](https://claude.ai/code/session_016GiHYRmLSNWTfbX9gVQkpz)_
Co-authored-by: Claude <noreply@anthropic.com>1 parent 72217cd commit cba4297
1 file changed
Lines changed: 31 additions & 1 deletion
| Original file line number | Diff line number | Diff line change | |
|---|---|---|---|
| |||
507 | 507 | | |
508 | 508 | | |
509 | 509 | | |
| 510 | + | |
| 511 | + | |
| 512 | + | |
| 513 | + | |
| 514 | + | |
| 515 | + | |
| 516 | + | |
| 517 | + | |
| 518 | + | |
| 519 | + | |
| 520 | + | |
| 521 | + | |
| 522 | + | |
| 523 | + | |
| 524 | + | |
| 525 | + | |
| 526 | + | |
| 527 | + | |
| 528 | + | |
| 529 | + | |
| 530 | + | |
| 531 | + | |
| 532 | + | |
| 533 | + | |
| 534 | + | |
| 535 | + | |
| 536 | + | |
| 537 | + | |
| 538 | + | |
| 539 | + | |
510 | 540 | | |
511 | 541 | | |
512 | 542 | | |
| |||
546 | 576 | | |
547 | 577 | | |
548 | 578 | | |
549 | | - | |
| 579 | + | |
550 | 580 | | |
551 | 581 | | |
552 | 582 | | |
| |||
0 commit comments