Skip to content

Commit 2b27460

Browse files
test(dogfood): activity-text-predicate pays its boot's first load at module scope and splits its slow control case (#24026)
Part of #23977 Clause-②: no The card has two halves. Here is where each stands at this head (`0c7592a22`): - **The `control` case under load: met.** At base it timed out at 5000 ms on 2 of 3 loaded runs here, which reproduces the nightly's red. At head it is four cases, and the slowest of them stays under 2.5 s (half the timeout) on all 3 loaded runs. - **The file under the 10 s line: not reachable from the test file.** Head is 12.2 s unloaded, against 16.0 s at base (medians). Between 62 % and 72 % of each data request's time is one per-request platform cost in `@objectstack/rest` and `@objectstack/metadata-protocol` (see "Out of scope" below). The claim's hold-off keeps platform code out of this PR, so #23977 remains open for that half. ## What changed One file, `packages/qa/dogfood/test/activity-text-predicate.dogfood.test.ts`: +66 / -26, or +41 / -1 when whitespace is ignored. 1. **The boot's first load moves to module scope.** `payTheBootsFirstLoad()` boots a throwaway app (no objects, the `requires` this file's stack declares, `automation: true`). It signs in and signs up once, then stops, and the file awaits it at module scope. Vitest runs that during collection, which no clock covers (AGENTS.md, Build & Test). It has the shape of `@objectstack/verify`'s own `boot-warm-up.testkit.ts`, but uses `bootStack`, which is exported today. Nothing new is exported from `@objectstack/verify`. A fuller warm-up was also measured: the same three extra plugins as the file's boot made no difference (1217 and 1303 ms against 1456 ms for the hook's boot), so it was dropped. 2. **The unmasking reader's control case is now four cases.** A `describe` keeps the original title. Three `it`s, one per class, carry the per-class loop body verbatim. A fourth carries the tail, the snapshot miss and the grouping. Every probe and every `expect(` moved intact, re-indented only. Nothing else moved: no timeout, no budget line, no roster entry, no project. There is no `// test-budget:` line. One `beforeAll` boot is neither of the two classes ruling `6181973363` names, and the remaining wait is a per-request cost, which is not a named class either. ## Where the time went at base (assumption 1) These numbers come from an instrumented copy, run isolated on the shared 4-vCPU box, 2 to 4 runs. | cost | measured | |:--|:--| | 141 sequential requests across the 22 cases | 9.3 to 11.3 s in total, a median of 60 to 74 ms per request. The control case alone took 2.4 to 2.8 s. | | the hook's `bootStack` | 4.17 s cold, and 1.15 to 1.46 s after a module-scope warm-up | | the hook's 5 sign-ups with their grants, then the REST seeding | 0.90 to 1.07 s, then 0.69 to 0.88 s | ## The PM's mechanism assumptions, measured 1. **Measured; the top three costs are in the table above.** 2. **Falsified as a speed-up.** The probes are independent reads: none writes, and their answers were equal in sequence and concurrently. Running them concurrently does not shorten them, though. 33 control probes took 2016 ms in sequence and 2137 ms under `Promise.all`. The requests run in-process (`app.request`) on one thread over an in-memory sql.js database, so they are CPU-bound. No concurrency was added; the case is cut instead. 3. **Confirmed: load reproduces the red.** With seven CPU hogs, the base control case took 5028, 4892 and 5031 ms, two of those runs ending in `Test timed out in 5000ms.` At head, its slowest part took 2488, 1906 and 1629 ms. 4. **Confirmed.** The first `bootStack` pays about 2.8 s of first load: 4.17 s cold against 1.15 to 1.46 s warm. ## A/B: isolated, interleaved, 3 rounds each - **Base** is an untracked copy, blob-identical to `61a680956` (`bb7cbee56a89`). **Head** is `0c7592a22`. - Each run is one vitest process with `--maxWorkers=2`, and every run went through `os-verify-lock`. - The number read is the default reporter's file line: hooks plus tests, collection excluded. The agent-detection variables were unset so that vitest picks that reporter. - The order was base then head, head then base, base then head. - **Loaded** means seven `node -e 'for(;;){}'` hogs on the 4-vCPU box for the whole round. That made runs about 2.2 to 2.7 times slower than unloaded, which is harsher than the card's 1.5 times. - The box is shared, so other agents' unlocked work ran alongside. Read the ratios over the absolutes. | run | base file ms | head file ms | base control ms | head control, slowest part ms | |:--|--:|--:|--:|--:| | unloaded r1 | 17680 | 12059 | 2572 | 779 | | unloaded r2 | 16022 | 12731 | 2493 | 804 | | unloaded r3 | 15338 | 12247 | 2398 | 832 | | **unloaded median** | **16022** | **12247** (-24 %) | **2493** | **804** | | loaded r1 | 42696 (1 failed) | 37072 | 5028 (timed out) | 2488 | | loaded r2 | 34224 | 29319 | 4892 | 1906 | | loaded r3 | 32896 (1 failed) | 26863 | 5031 (timed out) | 1629 | | **loaded median** | **34224** | **29319** | **5028** | **1906** | The hook's time (file line minus the tests' sum, unloaded) went from 5779 to 6778 ms at base to 3079 to 3415 ms at head. The four control parts together still take what the one case took, 2321 to 2413 ms unloaded: the split moves no work. ## Assertions kept - The 12 `it` / `describe` title literals at base hash to `887e5a912c4fe675` (sha256 prefix, in file order). - Head's 14, minus the two part titles this PR adds, hash to the same value. - The added titles are `` `every column of a pinned parent, for the stored values of the ${c} class` `` and `'a non-matching approval snapshot filter, and a grouping of the activity stream'`. - `expect(` counts 40 at base and 40 at head. - No test was removed, skipped or moved to another project. ## Ablation: the split cannot swallow a failure This was a one-time run; no test was left behind. - **Prediction, written before the run:** the three per-class parts go red on `expect(snapHit.rows).toBe(1)`, and everything else stays green, so 3 failed / 22 passed. - **The mutation:** `node scripts/ablation-replace.mjs` (wrap mode) changed the per-class `snapHit` probe's filter from the class's stored snapshot value to `NOMATCH`. It landed: anchor x1 → x0, blob `8b5eb87856f9` → `2ac1463e3d0a`. - **The result:** 3 failed / 22 passed, each failure `expected +0 to be 1`, as predicted. - **The restore:** the blob is back to HEAD's `8b5eb87856f9`, and `git diff HEAD` is empty. ## Tests and gates, at `0c7592a22` - `pnpm --filter @objectstack/dogfood exec vitest run --maxWorkers=2 test/activity-text-predicate.dogfood.test.ts test/activity-parent-read-gate.dogfood.test.ts test/audit-log-parent-read-gate.dogfood.test.ts`: 3 files passed, 39 tests passed, exit 0. - `pnpm --filter @objectstack/dogfood typecheck` (`tsc --noEmit`): exit 0. `tsc --listFilesOnly` lists the changed file. - `pnpm exec eslint --no-inline-config` over the changed file: exit 0. The repo-wide lint run is this PR's `Lint & Repo Gates` check. - `node scripts/pm/dispatch-gates.mjs --commands --repo objectstack-ai/objectstack`, taken from the merge base, derived 53 commands: - 52 exited 0. - `pnpm check:dual-build-cjs-loads` exited 3 with PREREQUISITE NOT MET, because it reads every package's `dist/`. That is NOT MEASURED locally; CI's run is the reading. - `--ran`, with an exit code recorded per command, accounted for all 53: 52 run, 1 NOT-MEASURED. - The whole dogfood suite was not run locally. It runs on `main`'s full battery, not on PR CI. ## No changeset The only file changed is a test of `@objectstack/dogfood`, which is private, and no published package's `files[]` reaches it. The seat applies `skip-changeset`. ## Out of scope: reported to the seat, not fixed here **The REST API-exposure gate re-validates the metadata of every object on every data request.** - **The path.** Every `/data/OBJECT` read and query request enters `enforceApiAccess` (`packages/rest/src/rest-server.ts`) to read one object's `enable` flags. From there it calls `loadObjectItems` (`packages/rest/src/meta-item-read-gate.ts`), then the protocol's `getMetaItems({ type: 'object' })`, then `readFlattenedMetaItems(..., 'served')` (`packages/metadata-protocol/src/protocol.ts`). That ends in `decorateMetadataItems` → `computeMetadataDiagnostics` (`packages/metadata-protocol/src/metadata-diagnostics.ts`), which runs a full Zod `safeParse` of each registered object's schema. - **The profile.** A CPU profile of the control case's 33 list calls (inspector, 200 µs sampling) put 1311 ms of 2841 ms sampled inside `readFlattenedMetaItems`, 1244 ms of that inside `computeMetadataDiagnostics`. - **The memoization probe.** It was measurement-only and not committed. Memoizing that one object-list read for the same 33 calls cut them from 2376 and 2255 ms to 865 and 668 ms. - **What it would close.** By that ratio, it is roughly 5 to 7 s of this file's 9 to 11 s of tests. That is the 10 s half of #23977. ## Acceptance notes - Under the seven-hog load (head r1), one per-class case, the masked reader's query-door case, reached 2604 ms, over half its timeout. Unloaded it takes 0.5 to 0.7 s. It is not the card's control case and is left as it is; the platform finding above would shorten it too. - The warm-up moves about 2.8 s into collection rather than removing it, so each run's `import` time grows by that much. Collection is not clocked. --- _Generated by [Claude Code](https://claude.ai/code/session_018t6a5rvqPRvEDMCVVW9kYT)_ Co-authored-by: Claude <noreply@anthropic.com>
1 parent 75ced06 commit 2b27460

1 file changed

Lines changed: 66 additions & 26 deletions

File tree

‎packages/qa/dogfood/test/activity-text-predicate.dogfood.test.ts‎

Lines changed: 66 additions & 26 deletions
Original file line numberDiff line numberDiff line change
@@ -59,6 +59,37 @@ import { SecurityPlugin, securityDefaultPermissionSets } from '@objectstack/plug
5959
import { assertArmed, armedWhen } from './armed.js';
6060
import { catalogPermissionSet } from './catalog-permission-set.js';
6161

62+
// [#23977] The boot's FIRST load is paid here, at module scope, which vitest
63+
// runs during collection with no clock on it, never inside the `beforeAll`
64+
// below (AGENTS.md, Build & Test: clocked windows measure behaviour, never
65+
// loading). The first `bootStack` in a process `import()`s the drivers and
66+
// better-auth lazily and compiles sql.js's WASM: measured on this file, the
67+
// hook's boot took about 4.2 s cold and about 1.3 s after this warm-up.
68+
//
69+
// The shape is `@objectstack/verify`'s own boot warm-up, spelled through the
70+
// one export it needs: a throwaway app with no objects and the `requires` this
71+
// file's stack declares, on its own in-memory database, booted with the
72+
// options the file's boot passes, signed into and signed up on, and stopped
73+
// before the first hook runs. ⛔ It shares nothing a case asserts on: what
74+
// stays warm is the module registry, the compiled WASM and the JIT.
75+
async function payTheBootsFirstLoad(): Promise<void> {
76+
const warmUp = await bootStack(
77+
{
78+
manifest: { id: 'com.example.boot-warm-up', namespace: 'warmup', version: '0.0.1', type: 'app', name: 'Boot Warm-up' },
79+
objects: [],
80+
requires: ['automation', 'triggers'],
81+
},
82+
{ automation: true },
83+
);
84+
try {
85+
await warmUp.signIn();
86+
await warmUp.signUp('boot-warm-up@verify.test');
87+
} finally {
88+
await warmUp.stop();
89+
}
90+
}
91+
await payTheBootsFirstLoad();
92+
6293
const OBJ = 'atp_item';
6394
const APPR = 'atp_appr';
6495
const CAP_UNMASK = 'atp_unmask';
@@ -467,34 +498,43 @@ describe('[#21154] a query over activity text or the approval snapshot, by a rea
467498
expect(await answered('sys_approval_request', { payload_json: { $contains: NOMATCH } })).toBe(0);
468499
});
469500

470-
it('control: the unmasking reader filters and groups by every column of a pinned parent, as before', async () => {
501+
// [#23977] One case per class, plus the tail, with every probe and assertion
502+
// moved intact. As a single case its 35 sequential requests took about 2.7 s
503+
// unloaded and crossed vitest's 5000 ms default on a loaded runner. Run
504+
// concurrently they took as long as in sequence (the requests are CPU-bound in
505+
// this one process), so the case is cut rather than run in parallel.
506+
describe('control: the unmasking reader filters and groups by every column of a pinned parent, as before', () => {
471507
for (const c of CLASSES) {
472-
for (const k of activityCases(c)) {
473-
const hit = await list('control', 'sys_activity', { object_name: k.parent, [k.column]: { $contains: k.stored } });
474-
expect(hit.status, hit.text).toBe(200);
475-
expect(hit.rows).toBeGreaterThan(0);
476-
const miss = await list('control', 'sys_activity', { object_name: k.parent, [k.column]: { $contains: NOMATCH } });
477-
expect(miss.status, miss.text).toBe(200);
478-
expect(miss.rows).toBe(0);
479-
}
480-
for (const k of ledgerCases(c)) {
481-
const hit = await list('control', 'sys_audit_log', { object_name: OBJ, [k.column]: { $contains: k.stored } });
482-
expect(hit.status, hit.text).toBe(200);
483-
expect(hit.rows).toBeGreaterThan(0);
484-
const miss = await list('control', 'sys_audit_log', { object_name: OBJ, [k.column]: { $contains: NOMATCH } });
485-
expect(miss.status, miss.text).toBe(200);
486-
expect(miss.rows).toBe(0);
487-
}
488-
const snapHit = await list('control', 'sys_approval_request', { object_name: APPR, payload_json: { $contains: SNAP[c] } });
489-
expect(snapHit.status, snapHit.text).toBe(200);
490-
expect(snapHit.rows).toBe(1);
508+
it(`every column of a pinned parent, for the stored values of the ${c} class`, async () => {
509+
for (const k of activityCases(c)) {
510+
const hit = await list('control', 'sys_activity', { object_name: k.parent, [k.column]: { $contains: k.stored } });
511+
expect(hit.status, hit.text).toBe(200);
512+
expect(hit.rows).toBeGreaterThan(0);
513+
const miss = await list('control', 'sys_activity', { object_name: k.parent, [k.column]: { $contains: NOMATCH } });
514+
expect(miss.status, miss.text).toBe(200);
515+
expect(miss.rows).toBe(0);
516+
}
517+
for (const k of ledgerCases(c)) {
518+
const hit = await list('control', 'sys_audit_log', { object_name: OBJ, [k.column]: { $contains: k.stored } });
519+
expect(hit.status, hit.text).toBe(200);
520+
expect(hit.rows).toBeGreaterThan(0);
521+
const miss = await list('control', 'sys_audit_log', { object_name: OBJ, [k.column]: { $contains: NOMATCH } });
522+
expect(miss.status, miss.text).toBe(200);
523+
expect(miss.rows).toBe(0);
524+
}
525+
const snapHit = await list('control', 'sys_approval_request', { object_name: APPR, payload_json: { $contains: SNAP[c] } });
526+
expect(snapHit.status, snapHit.text).toBe(200);
527+
expect(snapHit.rows).toBe(1);
528+
});
491529
}
492-
const snapMiss = await list('control', 'sys_approval_request', { object_name: APPR, payload_json: { $contains: NOMATCH } });
493-
expect(snapMiss.status, snapMiss.text).toBe(200);
494-
expect(snapMiss.rows).toBe(0);
495-
const grouped = await call('control', 'POST', '/data/sys_activity/query', {
496-
where: { object_name: OBJ }, groupBy: ['summary'], aggregations: [{ function: 'count', alias: 'n' }],
530+
it('a non-matching approval snapshot filter, and a grouping of the activity stream', async () => {
531+
const snapMiss = await list('control', 'sys_approval_request', { object_name: APPR, payload_json: { $contains: NOMATCH } });
532+
expect(snapMiss.status, snapMiss.text).toBe(200);
533+
expect(snapMiss.rows).toBe(0);
534+
const grouped = await call('control', 'POST', '/data/sys_activity/query', {
535+
where: { object_name: OBJ }, groupBy: ['summary'], aggregations: [{ function: 'count', alias: 'n' }],
536+
});
537+
expect(grouped.status, grouped.text).toBe(200);
497538
});
498-
expect(grouped.status, grouped.text).toBe(200);
499539
});
500540
});

0 commit comments

Comments
 (0)