Skip to content

Commit cba7d8a

Browse files
test(example-todo): boot the loop-body kernel once per file under a measured budget (#31312)
<!-- claude-projects-attribution: {"github_login":"marchtian"} --> _Requested by **田騏** · [project thread](https://claude.ai/code/project/chan_01VmuUhXU9SSUzqJYyXSmYSi?thread=cmsg_01VmuUhXU9SSUzqJYyXSmYSiWpz18m9kVbxeipdp31C27T)_ Fixes #31298 This is also the fix for the queue-flake anchor #31294 (same file, same case); the anchor can be closed with this PR. Clause-②: no — test-only; no accept set, schema or export changes Metadata-protocol: none ## 维护者速读 - 改了什么:`examples/app-todo/test/loop-body-iteration.test.ts` 不再每条用例各启动一个完整的 todo kernel,改为整个文件在 `beforeAll` 里启动一次(带 30 秒实测预算),每条用例前清空 `todo_task` 行和捕获的通知。五条用例的断言一字未改。只改这一个测试文件。 - 为什么改:启动约占每条用例耗时的 80%。在负载高的 Test Core 分片上,第一条用例(启动 + 一次执行)三次被 vitest 默认 5 秒截断(5011 / 5015 / 5033 ms),把与它无关的 PR 踢出合并队列(#31249、#31258),#31279 也因此红了两次。 - #31298 的假设已实测排除:去掉 #31230 加的三个源码别名,本文件耗时不变(这个文件的导入链根本不经过那三个包),所以 `vitest.config.ts` 不改。 - 风险与回滚:只改测试文件,不发布(skip-changeset)。隔离已验证:4 种乱序和 5 条单跑都绿;去掉每例前的清空则 5 条里 4 条红。回滚即 revert。 - 两分钟验证:`pnpm --filter @objectstack/example-todo exec vitest run test/loop-body-iteration.test.ts`,预期 5/5 通过。 - 需要你做的:无,席位落地。 ## What changes - `examples/app-todo/test/loop-body-iteration.test.ts` only. - `bootTodoKernel()` runs once per file in `beforeAll`, under an explicit 30 000 ms budget (`BOOT_BUDGET_MS`) with the measurement written beside it. It used to run inside each of the five cases, under vitest's 5 s per-test default. - `beforeEach` gives each case the state a fresh boot leaves: every `todo_task` row is deleted through the driver (so no hook or flow observes the reset), and the captured `messaging.emit()` list is emptied. - CONTROL removes the fixture flow it registers (`unregisterFlow`) in a `finally`, so no case leaves a registration behind. - `afterAll` disconnects the one driver. This replaces the per-case `afterEach` driver list. - Every assertion is unchanged. The doc block says why the suite shares one kernel and how each case still gets a clean state. ## Why The three failing Test Core jobs all cut off the same case, the file's first: | job | ESCALATION | EVERY | other 3 | package Duration | |---|---|---|---|---| | 128565270519 (#31279) | 5011 ms, timed out | 1356 ms | 344–502 ms | 50.13 s | | 128519296820 (queue 42410962891, #31249) | 5033 ms, timed out | 4620 ms | 563–746 ms | 78.25 s | | 128555004931 (queue 42422774934, #31258) | 5015 ms, timed out | 1691 ms | 416–508 ms | 53.55 s | Each log shows the case past kernel bootstrap and object registration when the timeout hit. `afterEach` then closed the driver under it and printed `Acquire connection error: Error: aborted` three times. That is slowness, not an assertion failure. Locally, idle, a case took 90–330 ms, and boot was about 80% of it. Boot phases measured inside the first case: `kernel.use` 3 ms, `bootstrap` 31–42 ms, sqlite-wasm `connect` 35 ms, `syncSchemas` 52–82 ms, Default Organization 45–87 ms, registering the flows 32–44 ms. The `execute` itself took 22–25 ms. So each case put a whole kernel boot under the 5 s per-test line, and on a shard running about 20x slower than an idle box (one warm case took 4620 ms), the first one crossed it. ### #31298's hypothesis, measured: the #31230 aliases are not the cost #31298 asked for cold and warm timings with and without the package-wide source aliases in `examples/app-todo/vitest.config.ts` (`@objectstack/runtime`, `@objectstack/plugin-auth`, `@objectstack/mcp`). Measured on this container (4 cores), whole example suite, test file from `main` `7c523aa1`. "Cold" means `node_modules/.vite` removed first. "Load" means 8 CPU-bound processes running beside the suite. The numbers are the five case times of this file, in ms: | variant | cold | warm | load (two runs) | suite wall idle / load | |---|---|---|---|---| | A: `main` (aliases on) | 296,112,224,190,189 | 306,89,219,169,162 / 300,123,242,171,162 | 880,332,379,375,272 / 608,234,345,272,238 | 15.4 s / 37.2–37.5 s | | B: aliases removed | 507,106,257,206,183 | 338,124,234,178,171 / 268,106,225,173,157 | 831,243,429,359,312 / 691,343,466,340,277 | 15.0–15.4 s / 34.7–37.9 s | | C: aliases on, `mcp-actions.test.ts` excluded | 266,77,203,166,165 | 283,118,216,186,173 | 852,285,384,332,308 / 813,376,425,379,264 | 9.7 s / 22.7–22.9 s | A and B are the same within noise. That fits the import graph: none of the `dist/` of `core`, `objectql`, `driver-sql`, `driver-sqlite-wasm` or `service-automation`, which are all this file imports from the platform, imports any of the three aliased packages (0 files). Narrowing the aliases would not change this file. So `vitest.config.ts` is not touched. What #31230 did change is the package's load. Its `mcp-actions.test.ts` joined the suite and adds about 6 s of idle wall and about 15 s under load (A against C), running in parallel with this file on the same shard. That makes the shard busier. It does not explain the cliff by itself: this file's own case times are the same in A and C. ## Tests After the fix, on this container, JSON reporter, case times in ms: - Idle, whole suite: 48, 34, 29, 11, 18. Under 8 CPU hogs: 132, 97, 56, 29, 36. Before the fix the same runs gave 296–880 for the first case. - File alone, idle: `tests 273–275ms` for the file, boot included. It was `tests 850–874ms` before. - Isolation: `--sequence.shuffle` with seeds 1, 7, 42 and 1234: 5/5 passed in each order (for example CONTROL, CONTAINMENT, ESCALATION, EVERY, REMINDER). Each case alone (`-t ESCALATION`, `-t EVERY`, `-t CONTAINMENT`, `-t REMINDER`, `-t CONTROL`): 1 passed, 4 skipped, each time. - Reverse check: with the `beforeEach` reset removed, 4 of 5 cases fail. So the reset is what keeps the shared kernel's cases independent, and it works. - Sibling files that also boot a kernel: in the same three failing jobs their slowest single case was 2060 ms (task-recurrence `daily`), then 2019 ms and 1888 ms, and task-completion GATES 1763 ms. Locally idle they take 700–1118 ms. None is at the 5 s line, so they are not changed here (see Acceptance notes). - The whole example suite, 5 runs in a row on `877170f8`: `pnpm --filter @objectstack/example-todo exec vitest run`, each exit 0 with `Test Files 9 passed (9)`, `Tests 249 passed (249)`. ## Acceptance notes - The boot budget is per-file (`beforeAll`, 30 s), not per case. Each case now runs no boot and stays under 150 ms locally even under load, far inside the 5 s default, so the cases keep vitest's default. - Sibling files in `examples/app-todo/test` that boot a kernel per case: `task-recurrence.test.ts` (4 end-to-end cases, slowest 2060 ms in CI), `task-completion-trigger.test.ts` (slowest 1763 ms), `derived-flag-removal.test.ts` (slowest 1079 ms). Not at the cliff in any of the three failing jobs, so not touched. If one of them is ever cut off, the same one-kernel-per-file shape applies. - `mcp-actions.test.ts` (from #31230) adds about 6 s of idle suite wall to this package (15.4 s against 9.7 s without it). Its cost is the same with and without the aliases. Not a defect; noted as the package's load. ## Verification All on `877170f8` (this branch with `origin/main` merged in, no rebase): - `node scripts/pm/dispatch-gates.mjs --commands --repo objectstack-ai/objectstack` derived 37 commands. Every one ran with exit 0. Before the run, `pnpm exec turbo run build --filter='./packages/**' --concurrency=2` built every package, because `check:dual-build-cjs-loads` reads built output and exited 3 (prerequisite not met) without it. `--ran`: "37 derived famil(ies) accounted for — 37 run, 0 NOT-MEASURED". - `pnpm lint`: exit 0. - `pnpm --filter @objectstack/example-todo typecheck`: exit 0. The program includes `test/loop-body-iteration.test.ts`, counted with `--listFiles`. - Not run locally: `test:repo` (the vitest `repo` project), because this diff does not touch it. Test Core runs it on this PR. ## Human Minimum - [x] 1. Schemas start as Zod; `packages/spec` holds no runtime logic. (Not touched.) - [x] 2. Every name I added uses the casing for its kind. - [x] 3. No formatter ran; `pnpm lint` passes. - [x] 4. One issue, one branch off an up-to-date `main`, one pull request. - [x] 5. A change that publishes carries a changeset, and both declaration lines are filled in here and in the changeset. (Test-only in a private example package; nothing publishes: `skip-changeset`.) - [x] 6. `packages/spec` touched: its generated artifacts are regenerated and committed. (Not touched.) - [x] 7. No hand edits to `content/docs/references/`, `packages/*/CHANGELOG.md` or `content/docs/releases/`. - [x] 8. Title, body and comments are in English. - [x] The *Before Submitting* list in CONTRIBUTING.md is done. --- _Generated by [Claude Code](https://claude.ai/code/session_017ihL2etWp2cPA9ARe5c6hN)_ 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-authored-by: Claude <noreply@anthropic.com>
1 parent f8c3ecc commit cba7d8a

1 file changed

Lines changed: 53 additions & 18 deletions

File tree

‎examples/app-todo/test/loop-body-iteration.test.ts‎

Lines changed: 53 additions & 18 deletions
Original file line numberDiff line numberDiff line change
@@ -34,9 +34,20 @@
3434
* real flow by deleting `config.body` and re-wiring the flat edges, still dies
3535
* at `update_priority`. Without it a green suite could not distinguish "the
3636
* loop body ran" from "nothing in this harness can fail".
37+
*
38+
* ONE KERNEL PER FILE, CLEAN STATE PER CASE. The boot is ~80% of a case's wall
39+
* (measured locally: ~250 ms of boot against ~25 ms of `execute`), and booting
40+
* it inside every case put a whole kernel under vitest's 5 s per-test default:
41+
* on loaded Test Core shards the first case was cut off at 5011–5033 ms. So the
42+
* kernel boots once in `beforeAll`, under its own measured budget (below), and
43+
* `beforeEach` gives every case the state a fresh boot would: no `todo_task`
44+
* rows (deleted through the driver, so no hook or flow observes the reset) and
45+
* no captured notices. The only registration a case adds — CONTROL's fixture
46+
* flow — is removed in its own `finally`. Each case still passes alone and in
47+
* shuffled order.
3748
*/
3849

39-
import { describe, it, expect, afterEach } from 'vitest';
50+
import { describe, it, expect, beforeAll, beforeEach, afterAll } from 'vitest';
4051
import { ObjectKernel } from '@objectstack/core';
4152
import { ObjectQLPlugin } from '@objectstack/objectql';
4253
import { SqliteWasmDriver } from '@objectstack/driver-sqlite-wasm';
@@ -55,13 +66,6 @@ interface CapturedEmit {
5566
source?: { object: string; id: string };
5667
}
5768

58-
const openDrivers: Array<{ disconnect?: () => Promise<void> }> = [];
59-
afterEach(async () => {
60-
while (openDrivers.length) {
61-
try { await openDrivers.pop()?.disconnect?.(); } catch { /* noop */ }
62-
}
63-
});
64-
6569
/** `n` whole days before today, as a `Field.date` string (UTC); negative = future. */
6670
function daysAgoIso(n: number): string {
6771
const d = new Date();
@@ -74,11 +78,14 @@ function daysAgoIso(n: number): string {
7478
* A real kernel with the app's real `todo_task` over in-process sqlite-wasm,
7579
* the real automation engine, and a capturing `messaging` service.
7680
*/
77-
async function bootTodoKernel(): Promise<{
81+
interface TodoKernel {
7882
automation: AutomationEngine & Record<string, any>;
7983
data: any;
84+
driver: any;
8085
emits: CapturedEmit[];
81-
}> {
86+
}
87+
88+
async function bootTodoKernel(): Promise<TodoKernel> {
8289
const emits: CapturedEmit[] = [];
8390
const messaging = {
8491
async emit(input: CapturedEmit) {
@@ -107,7 +114,6 @@ async function bootTodoKernel(): Promise<{
107114
const driver: any = new SqliteWasmDriver({ filename: ':memory:' });
108115
await driver.connect();
109116
objectql.registerDriver(driver, true);
110-
openDrivers.push(driver);
111117
objectql.registry.registerObject(Task, 'todo', 'todo');
112118
await objectql.syncSchemas();
113119
// A real `single` install's Default Organization: the system writes below
@@ -116,9 +122,33 @@ async function bootTodoKernel(): Promise<{
116122

117123
automation.registerFlow(OverdueEscalationFlow.name, OverdueEscalationFlow);
118124
automation.registerFlow(TaskReminderFlow.name, TaskReminderFlow);
119-
return { automation, data, emits };
125+
return { automation, data, driver, emits };
120126
}
121127

128+
/**
129+
* The boot budget is measured, not vitest's 10 s hook default. Locally one boot
130+
* (kernel, sqlite-wasm connect, schema sync, Default Organization, flows) took
131+
* 230–330 ms idle and ~650 ms with 8 CPU-bound processes beside the suite on 4
132+
* cores. On Test Core shards the old first case — this boot plus one
133+
* `execute` — was cut off at 5011, 5015 and 5033 ms (jobs 128519296820,
134+
* 128555004931, 128565270519), and one warm case took 4620 ms, so the shard's
135+
* slowdown has reached ~20x the idle reading. 30 s is 6x the 5 s the shards
136+
* already exceeded.
137+
*/
138+
const BOOT_BUDGET_MS = 30_000;
139+
140+
let k: TodoKernel;
141+
beforeAll(async () => { k = await bootTodoKernel(); }, BOOT_BUDGET_MS);
142+
afterAll(async () => { await k?.driver.disconnect?.(); });
143+
144+
/** The state a fresh boot leaves: no task rows, no captured notices. */
145+
beforeEach(async () => {
146+
for (const row of await k.driver.find('todo_task', { where: {} })) {
147+
await k.driver.delete('todo_task', row.id);
148+
}
149+
k.emits.length = 0;
150+
});
151+
122152
const SYSTEM = { context: { isSystem: true } };
123153

124154
/** Seed one task `days` days past due, and return its id. */
@@ -132,7 +162,7 @@ async function seedOverdueTask(data: any, subject: string, days: number, owner =
132162

133163
describe('#19206 — the loop body runs and binds `currentTask`', () => {
134164
it('ESCALATION: the run reaches `notify_owner` and the notice renders the real day count', async () => {
135-
const { automation, data, emits } = await bootTodoKernel();
165+
const { automation, data, emits } = k;
136166
const id = await seedOverdueTask(data, 'Renew the domain', 5);
137167

138168
const result: any = await automation.execute('todo_overdue_escalation');
@@ -158,7 +188,7 @@ describe('#19206 — the loop body runs and binds `currentTask`', () => {
158188
});
159189

160190
it('EVERY item is processed, and each one carries its own values', async () => {
161-
const { automation, data, emits } = await bootTodoKernel();
191+
const { automation, data, emits } = k;
162192
await seedOverdueTask(data, 'Alpha', 4, 'usr_a');
163193
await seedOverdueTask(data, 'Bravo', 9, 'usr_b');
164194
await seedOverdueTask(data, 'Charlie', 12, 'usr_c');
@@ -184,7 +214,7 @@ describe('#19206 — the loop body runs and binds `currentTask`', () => {
184214
});
185215

186216
it('CONTAINMENT: one un-notifiable row does not end the sweep', async () => {
187-
const { automation, data, emits } = await bootTodoKernel();
217+
const { automation, data, emits } = k;
188218
await seedOverdueTask(data, 'Alpha', 4, 'usr_a');
189219
// `notify` refuses an empty resolved recipient set (`notify-node.ts`), so
190220
// this row's iteration fails INSIDE the body's `try_catch`.
@@ -200,7 +230,7 @@ describe('#19206 — the loop body runs and binds `currentTask`', () => {
200230
});
201231

202232
it('REMINDER: the second loop in the file binds its iterator too', async () => {
203-
const { automation, data, emits } = await bootTodoKernel();
233+
const { automation, data, emits } = k;
204234
await data.insert('todo_task', {
205235
subject: 'Pay the invoice', status: 'not_started', priority: 'high',
206236
due_date: daysAgoIso(-1), owner: 'usr_test_owner',
@@ -216,7 +246,7 @@ describe('#19206 — the loop body runs and binds `currentTask`', () => {
216246
});
217247

218248
it('CONTROL: the pre-fix body-less shape still dies at `update_priority`', async () => {
219-
const { automation, data, emits } = await bootTodoKernel();
249+
const { automation, data, emits } = k;
220250
await seedOverdueTask(data, 'Renew the domain', 5);
221251

222252
// The pre-#19206 shape, rebuilt from the real flow so it cannot drift: the
@@ -237,7 +267,12 @@ describe('#19206 — the loop body runs and binds `currentTask`', () => {
237267
];
238268
automation.registerFlow(legacy.name, legacy);
239269

240-
const result: any = await automation.execute(legacy.name);
270+
let result: any;
271+
try {
272+
result = await automation.execute(legacy.name);
273+
} finally {
274+
automation.unregisterFlow(legacy.name);
275+
}
241276
expect(result.success).toBe(false);
242277
// Loud rather than catastrophic: the filter operand reads `currentTask`,
243278
// which the body-less shape never binds, and the operand envelope fails the

0 commit comments

Comments
 (0)