feat(pregate): timing check flags elapsed-time bounds and sleep-then-assert in added test lines (W4)

lib/pregate/checks/timing.ts prints TIMING_ASSERTION: <file>:<line> <pattern>
and a TIMING_ASSERTIONS summary; gstack-timing-ok: <reason> in any comment
syntax on the line or the line above escapes one. It warns
(PREGATE_TIMING_ASSERTION): measured on gstack (9 of 47 test-touching
commits, 263 hits in the tree) and gbrain (37 of 95 commits; 31 of 38 sites
of the five timing-flake fixes), blocking would stop a fifth to two fifths
of test changes. Adds the /review checklist rule and the /investigate
timing-flake playbook.

Co-authored-by: capy-ai[bot] <230910855+capy-ai[bot]@users.noreply.github.com>
(cherry picked from commit a3b86b10b2)
This commit is contained in:
garrytan committed 2026-10-17 01:22:57 +00:00
1 parent 67f636a4d3
commit ed973840d3
14 files changed
+562 -3

No files matched your search

+1
View File
@@ -246,6 +246,7 @@ gstack_result_anchor() {
QUEUE_VERIFY_MISMATCH) printf '%s' 'queue-verify-mismatch' ;;
QUEUE_GATE_MISSING) printf '%s' 'queue-gate-missing' ;;
GATE_AHEAD_ATTEMPT_INVALID) printf '%s' 'gate-ahead-attempt-invalid' ;;
PREGATE_TIMING_ASSERTION) printf '%s' 'pregate-timing-assertion' ;;
*) return 1 ;;
esac
}
+54
View File
@@ -97,6 +97,12 @@ Two stages with separate clocks, both printed:
searched for the old value; a consumer the branch did not update fails with
`file:line`.
- `timing`: added or changed test lines that compare an elapsed wall-clock or
CPU time against a bound, or sleep and then assert, print
`TIMING_ASSERTION: <file>:<line> <pattern>` and a
`TIMING_ASSERTIONS: found=<n> escaped=<n> files=<n>` summary. It warns
(`PREGATE_TIMING_ASSERTION`); it does not block. See [timing](#timing).
- `guards`: each guard in `.gstack/pregate.json` whose `when` globs match a
touched file (renames included) runs its `command` in its own process, under
the verified launch Bun, with its own `timeout_s` (default `--timeout`). A
@@ -246,6 +252,54 @@ guard is a *command* with its own fix line. Older gstack refuses unknown keys
that reads them ships. The worked gbrain configuration is in
[gbrain worked configs](#gbrain-worked-configs).
<a id="timing"></a>
## Timing assertions
`timing` reads only the lines the branch added or changed in test code (test
files and files under `test/`, `tests/`, `spec/` or `__tests__/`; never
fixture trees). It reports three patterns:
| Pattern | Example |
|---|---|
| `wall-time-bound` | `expect(Date.now() - t0).toBeLessThan(400)`, `expect(elapsedMs).toBeLessThanOrEqual(2_000)`, `assert elapsed < 0.5` |
| `cpu-time-bound` | `expect(cpuMs(() => parse(x))).toBeLessThan(150)`, `assert time.process_time() - c0 < 0.2` |
| `sleep-then-assert` | `await Bun.sleep(50); expect(calls).toBe(1)` (a fixed sleep, not a polling loop) |
A comparison with `0`, a named bound (`timeoutMs`, `TTL_MS`), a timestamp
ordered against a bare `Date.now()` and a `while (… Date.now() < deadline)`
poll are not reported. Changing the bound of an existing assertion is a changed
line, so it is reported.
**Escape.** When the bound is the contract (a hang check with wide headroom, a
CPU-time bound on a pure function), put `gstack-timing-ok: <reason>` in a
comment, in any comment syntax (`//`, `#`, `/* */`, `--`), on the line or
the line above. The reason is required; an empty one is still reported with
`(gstack-timing-ok needs a reason)`. `--explain` lists every escape and its
reason.
**Warn, not block (measured 2026-10-16).** The detector was run over:
- gstack's own test tree: 263 hits in 123 of 1,566 test files (176
`wall-time-bound`, 87 `sleep-then-assert`), mostly real timing assertions,
most of them generous "does not hang" bounds.
- gstack's last 51 commits on main: 9 of the 47 that touched tests would have
been flagged (29 hits; #3190 alone has 7).
- gbrain's last 100 commits on master: 37 of the 95 that touched tests would
have been flagged (147 hits).
- The five gbrain timing-flake fixes (#6050, #6493, #6726, #6746, #6862): 31 of
38 fix sites were flagged before the fix. The misses are flakes with no
timing comparison on the line (an injected deadline in #6050, a
`Promise.race` with a sleep and a deadline parameter in #6862) and ratio or
percentile checks computed far from the clock read. The correct fix in
#6726 (wall clock to thread CPU time) is still a bound and is reported 21
times.
Blocking would stop about a fifth of gstack's and two fifths of gbrain's
test-touching commits, including correct fixes, so the check warns. A repo
that wants it stricter keeps the warning in its review rule (the /review
checklist has the same rule) and /investigate's flake playbook says what to do
with a timing flake: never raise the bound.
<a id="sealed"></a>
## Sealed output: the pre-push hook and `gstack-pregate sealed`
+14
View File
@@ -3537,3 +3537,17 @@ and the current one. Record the live attempt, or prepare a new one with
`gate-ahead --after <pr>` and run the gate there without editing tracked
files.
<a id="pregate-timing-assertion"></a>
### `PREGATE_TIMING_ASSERTION`
**Meaning.** A test line the branch added or changed compares an elapsed
wall-clock or CPU time against a bound, or sleeps for a fixed time and then
asserts. Under machine load such a test fails without a code change. The
`timing` check warns; it does not block (the measurement is in
[docs/pregate.md#timing](pregate.md#timing)).
**Fix.** Assert on the outcome instead: an injected clock, a forced deadline,
an event or a poll with a deadline. When the bound is the contract, add
`gstack-timing-ok: <reason>` in a comment on the line or the line above. Never
raise a bound to make a flake pass; /investigate's flake playbook covers the
diagnosis.
+24
View File
@@ -48,3 +48,27 @@ relaxation (review tag RH-15) and needs the owner's decision, not a merge.
`gh run list` comparison with the first-moved `headSha`, and a routing note
for the owner: `fix in this PR` | `rerun; cause outside the PR: <what>` |
`owner decision needed: <the relaxation and its P(fail | regression) before/after>`.
### Timing flakes (`TIMING_ASSERTION`)
When the failing line compares an elapsed time with a bound or sleeps and then
asserts (`gstack-pregate`'s `timing` check prints it as
`TIMING_ASSERTION: <file>:<line> <pattern>`):
1. **Same-load distributions.** Log the asserted value on every run and run the
file N ≥ 20 times on `origin/<base>` and on the PR head under the same load
(same machine, same concurrency, beside the same shard). Report min, p50,
p95, max and failures against the bound for both. A distribution that moved
on the PR head is a regression in the PR; the same distribution on both is a
test that depends on machine load.
2. **Forced probe.** Inject the delay the load causes (a sleep inside the
measured span behind a test-only hook, or a starved CPU) and show the
assertion failing every time.
3. **Fix the measurement, never the bound.** Assert on the outcome, an injected
clock, a forced deadline or a poll with a deadline instead of a fixed sleep;
a complexity bound measures thread CPU time against a same-run baseline.
When a bound stays the contract, the line carries
`gstack-timing-ok: <reason>`. Raising the bound is not a fix.
4. **Rerun only with outside-cause evidence:** the same-load distributions show
no PR regression and the failed run's load is on record (CI log, runner
metrics). Put both in `## Flake evidence`.
+24
View File
@@ -41,3 +41,27 @@ skip until the cause is named and probed.
`gh run list` comparison with the first-moved `headSha`, and a routing note
for the owner: `fix in this PR` | `rerun; cause outside the PR: <what>` |
`owner decision needed: <the relaxation and its P(fail | regression) before/after>`.
### Timing flakes (`TIMING_ASSERTION`)
When the failing line compares an elapsed time with a bound or sleeps and then
asserts (`gstack-pregate`'s `timing` check prints it as
`TIMING_ASSERTION: <file>:<line> <pattern>`):
1. **Same-load distributions.** Log the asserted value on every run and run the
file N ≥ 20 times on `origin/<base>` and on the PR head under the same load
(same machine, same concurrency, beside the same shard). Report min, p50,
p95, max and failures against the bound for both. A distribution that moved
on the PR head is a regression in the PR; the same distribution on both is a
test that depends on machine load.
2. **Forced probe.** Inject the delay the load causes (a sleep inside the
measured span behind a test-only hook, or a starved CPU) and show the
assertion failing every time.
3. **Fix the measurement, never the bound.** Assert on the outcome, an injected
clock, a forced deadline or a poll with a deadline instead of a fixed sleep;
a complexity bound measures thread CPU time against a same-run baseline.
When a bound stays the contract, the line carries
`gstack-timing-ok: <reason>`. Raising the bound is not a fix.
4. **Rerun only with outside-cause evidence:** the same-load distributions show
no PR regression and the failed run's load is on record (CI log, runner
metrics). Put both in `## Flake evidence`.
+225
View File
@@ -0,0 +1,225 @@
/**
* pregate check `timing` (tier 1, preflight; field list 2 W4): added or
* changed test lines that compare an elapsed wall-clock or CPU time against a
* bound, or that sleep and then assert. Each hit prints
* TIMING_ASSERTION: <file>:<line> <pattern>; a hit is escaped by
* gstack-timing-ok: <reason> in any comment syntax on the line or the line
* above (the reason is required). The check warns; see docs/pregate.md#timing
* for the measurement behind warn rather than block. Field incident: gbrain's
* master went red on a 461 ms run against a 400 ms bound, and five such flakes
* were fixed by hand in one week.
*/
import { spawnSync } from 'node:child_process';
import * as fs from 'node:fs';
import * as path from 'node:path';
import { baseInputs, sha256 } from '../context';
import { isTestFile } from '../import-graph';
import type { CheckDef, CheckResult, PregateContext } from '../types';
export type TimingPattern = 'wall-time-bound' | 'cpu-time-bound' | 'sleep-then-assert';
export interface TimingHit { file: string; line: number; pattern: TimingPattern; escape?: { reason: string } | { missingReason: true } }
const CODE_EXT = /\.(?:[cm]?[jt]sx?|py|rb|go|rs|java|kt|swift|exs?|php|cs)$/;
const TEST_DIR = /(?:^|\/)(?:test|tests|spec|__tests__)\//;
const FIXTURE_DIR = /(?:^|\/)(?:fixtures|__fixtures__|testdata)\//;
const WALL_SOURCE = /\b(?:Date\.now|performance\.now|process\.hrtime(?:\.bigint)?|Bun\.nanoseconds|time\.(?:time|monotonic|perf_counter)(?:_ns)?|System\.(?:nanoTime|currentTimeMillis)|Instant\.now|time\.Now|time\.Since|Process\.clock_gettime)\s*\(|\bnew Date\(\)\.getTime\(\)/;
const CPU_SOURCE = /\b(?:process\.cpuUsage|process\.resourceUsage|time\.(?:process_time|thread_time)(?:_ns)?|resource\.getrusage|\w*[cC]pu(?:Ms|Time|Usage|Nanos|Micros)\w*)\s*\(/;
const BOUND_NAME = /timeout|deadline|budget|limit|max|min|interval|delay|grace|ttl|cap\b|wait/i;
const ELAPSED_NAME = /^(?:ms|dt|secs?|seconds|nanos)$|^(?:elapsed|duration|took|latency|wall|cpu)|(?:Elapsed|Duration|Latency|Took|Ms|_ms|Millis|Nanos|_ns|Seconds|Secs)$/;
const ASSERT_CALL = /\bexpect\s*\(|\bassert\w*\b|\bt\.(?:ok|true|false|is)\s*\(|\.should\b/;
const SLEEP = /\b(?:await\s+(?:Bun\.sleep|sleep|delay|wait|setTimeoutPromise|timers\.setTimeout|scheduler\.wait)\s*\(|await\s+new\s+Promise\s*(?:<[^>]*>)?\s*\(\s*\(?\s*\w*\s*\)?\s*=>\s*setTimeout\s*\(|time\.sleep\s*\(|Thread\.sleep\s*\(|Bun\.sleepSync\s*\(|Atomics\.wait\s*\()/;
const ZERO_SLEEP = /^(?:await\s+)?(?:\w+(?:\.\w+)?\s*\(\s*0\s*\)|new\s+Promise[^;]*?setTimeout\s*\(\s*\w+\s*,\s*0\s*\))/;
const POLL = /\bwhile\b|\buntil\b|\bfor\s*\(|\bdo\s*\{/;
const ESCAPE = /(?:\/\/|\/\*|#|--|<!--|;|%|^\s*\*|^\s*')[^\n]*?\bgstack-timing-ok:([^\n]*)$/;
const ASSIGN = /^\s*(?:(?:const|let|var|val|final)\s+)?([A-Za-z_$][\w$]*)\s*(?::[^=]+)?(?<![=!<>])=(?!=)\s*(.+?);?\s*$/;
const ARITHMETIC = /^[\w$.()\s+\-*/!]+$/;
const NOT_ELAPSED = /mtime|ctime|birthtime|timestamp|stamp|At$|_at$/i;
/** Test code the check reads: test files and code under test directories, never fixture trees. */
export function scansTiming(rel: string): boolean {
return CODE_EXT.test(rel) && (isTestFile(rel) || TEST_DIR.test(rel)) && !FIXTURE_DIR.test(rel);
}
function escapeReason(line: string | undefined): TimingHit['escape'] | undefined {
const m = line === undefined ? null : ESCAPE.exec(line);
if (!m) return undefined;
const reason = m[1]!.replace(/\*\/|-->/g, '').trim();
return /[A-Za-z]{2}/.test(reason) ? { reason } : { missingReason: true };
}
const identRe = (name: string) => new RegExp('(?<![\\w$.])' + name.replace(/\$/g, '\\$') + '(?![\\w$])');
/** Variables holding a clock reading or an elapsed time: assigned a clock call, or arithmetic over clocks and such variables. */
function clockVariables(lines: readonly string[]): Map<string, 'wall' | 'cpu'> {
const vars = new Map<string, 'wall' | 'cpu'>();
for (let pass = 0; pass < 2; pass++) {
for (const line of lines) {
const m = ASSIGN.exec(line);
if (!m || vars.has(m[1]!)) continue;
const rhs = m[2]!.replace(/^await\s+/, '');
const leads = (re: RegExp) => { const r = re.exec(rhs); return !!r && r.index === 0; };
if (leads(CPU_SOURCE)) { vars.set(m[1]!, 'cpu'); continue; }
if (leads(WALL_SOURCE)) { vars.set(m[1]!, 'wall'); continue; }
if (!ARITHMETIC.test(rhs) || /[\w$]\s*\(/.test(rhs.replace(WALL_SOURCE, '0').replace(CPU_SOURCE, '0').replace(/\bMath\.\w+\s*\(/g, '('))) continue;
if (CPU_SOURCE.test(rhs)) { vars.set(m[1]!, 'cpu'); continue; }
if (WALL_SOURCE.test(rhs)) { vars.set(m[1]!, 'wall'); continue; }
for (const [name, kind] of vars) if (identRe(name).test(rhs)) { vars.set(m[1]!, kind); break; }
}
}
return vars;
}
/** The clock kind a code fragment measures, from a clock call, a clock variable or an elapsed-time name; null when it reads no time. */
function timeOperand(code: string, vars: Map<string, 'wall' | 'cpu'>): 'wall' | 'cpu' | null {
if (CPU_SOURCE.test(code)) return 'cpu';
if (WALL_SOURCE.test(code)) return 'wall';
let kind: 'wall' | 'cpu' | null = null;
for (const [, ident] of code.matchAll(/(?<![\w$])([A-Za-z_$][\w$]*)(?![\w$])/g)) {
const tracked = vars.get(ident!);
if (tracked) { if (tracked === 'cpu') return 'cpu'; kind = 'wall'; continue; }
if (/^[A-Z][A-Z0-9_]+$/.test(ident!) || BOUND_NAME.test(ident!) || NOT_ELAPSED.test(ident!) || !ELAPSED_NAME.test(ident!)) continue;
if (/cpu/i.test(ident!)) return 'cpu';
kind = 'wall';
}
return kind;
}
/** The text inside the parentheses opening at `open` (to the line's end when unbalanced). */
function parenArgs(line: string, open: number): string {
let depth = 0;
for (let i = open; i < line.length; i++) {
if (line[i] === '(') depth++;
else if (line[i] === ')' && --depth === 0) return line.slice(open + 1, i);
}
return line.slice(open + 1);
}
const isZero = (s: string) => /^\s*0(?:\.0+)?n?\s*$/.test(s);
const bareClock = (s: string) => /^\s*(?:Date\.now\(\)|performance\.now\(\)|new Date\(\)\.getTime\(\))\s*$/.test(s);
/** The clock kind of an asserted comparison between a time operand and a bound; a comparison with 0 is a sanity check, and a timestamp ordered against a bare now() is not an elapsed time. */
function boundKind(line: string, vars: Map<string, 'wall' | 'cpu'>): 'wall' | 'cpu' | null {
const code = line.replace(/'(?:[^'\\]|\\.)*'|"(?:[^"\\]|\\.)*"|`(?:[^`\\]|\\.)*`/g, "''").replace(/\s\/\/.*$|^\s*\/\/.*$|\s#\s.*$/, '');
for (const m of code.matchAll(/\.(?:toBeLessThan|toBeLessThanOrEqual|toBeGreaterThan|toBeGreaterThanOrEqual|toBeWithin)\s*\(/g)) {
const bound = parenArgs(code, m.index! + m[0].length - 1);
const open = code.lastIndexOf('expect(', m.index!);
if (open < 0 || isZero(bound)) continue;
const actual = parenArgs(code, open + 'expect'.length);
if (bareClock(bound) && !timeOperand(actual, vars)) continue;
const kind = timeOperand(actual, vars) ?? timeOperand(bound, vars);
if (kind) return kind;
}
for (const m of code.matchAll(/\b(?:assertLess|assertLessEqual|assertGreater|assertGreaterEqual)\s*\(/g)) {
const args = parenArgs(code, m.index! + m[0].length - 1);
if (isZero(args.split(',')[1] ?? '')) continue;
const kind = timeOperand(args, vars);
if (kind) return kind;
}
const asserted: string[] = [];
for (const m of code.matchAll(/\b(?:expect|assert(?:\.\w+)?|t\.(?:ok|true|false))\s*\(/g)) asserted.push(parenArgs(code, m.index! + m[0].length - 1));
const py = /^\s*assert\s+(.+)$/.exec(code);
if (py) asserted.push(py[1]!);
for (const segment of asserted) {
const clean = segment.replace(/=>/g, ' ');
for (const c of clean.matchAll(/([^<>=!&|,(]+?)\s*(<=?|>=?)\s*([^<>=&|,)]+)/g)) {
if (isZero(c[3]!) || isZero(c[1]!)) continue;
if (bareClock(c[3]!) && !timeOperand(c[1]!, vars)) continue;
const kind = timeOperand(c[1]!, vars) ?? timeOperand(c[3]!, vars);
if (kind) return kind;
}
}
return null;
}
/** True when the sleep sits outside a string literal and outside a polling loop. */
function fixedSleepAt(lines: readonly string[], i: number): boolean {
const line = lines[i]!;
const at = line.search(SLEEP);
if (at < 0) return false;
const before = line.slice(0, at);
if (((before.match(/'/g)?.length ?? 0) % 2) || ((before.match(/"/g)?.length ?? 0) % 2) || ((before.match(/`/g)?.length ?? 0) % 2)) return false;
if (ZERO_SLEEP.test(line.slice(at)) || POLL.test(line)) return false;
for (let k = i - 1; k >= 0 && k >= i - 2; k--) {
const prev = lines[k]!.trim();
if (!prev) continue;
if (POLL.test(prev) && /\{\s*$/.test(prev)) return false;
break;
}
return true;
}
/**
* Timing hits in one file's text. `added` holds the 1-based line numbers the
* branch added or changed; 'all' scans every line (the measurement mode).
*/
export function scanTiming(file: string, text: string, added: ReadonlySet<number> | 'all'): TimingHit[] {
const lines = text.split('\n');
const isAdded = (n: number) => added === 'all' || added.has(n);
const vars = clockVariables(lines);
const hits: TimingHit[] = [];
const escapeAt = (...ns: number[]) => {
for (const n of ns) { const e = escapeReason(lines[n - 1]); if (e) return e; }
return undefined;
};
for (let i = 0; i < lines.length; i++) {
const n = i + 1;
const line = lines[i]!;
const kind = boundKind(line, vars);
if (kind && isAdded(n)) { hits.push({ file, line: n, pattern: kind === 'cpu' ? 'cpu-time-bound' : 'wall-time-bound', escape: escapeAt(n, n - 1) }); continue; }
if (!fixedSleepAt(lines, i)) continue;
let seen = 0;
for (let j = i + 1; j < lines.length && seen < 3; j++) {
const next = lines[j]!.trim();
if (!next || /^(?:\/\/|#|\*|\/\*)/.test(next)) continue;
seen++;
if (SLEEP.test(next)) break;
if (!ASSERT_CALL.test(next)) continue;
if (isAdded(n) || isAdded(j + 1)) hits.push({ file, line: n, pattern: 'sleep-then-assert', escape: escapeAt(n, n - 1, j + 1, j) });
break;
}
}
return hits;
}
/** Added line numbers per test file, merge-base to the working tree; an untracked test file counts whole. */
export function addedTestLines(ctx: PregateContext): Map<string, Set<number> | 'all'> {
const out = new Map<string, Set<number> | 'all'>();
const files = ctx.touched.filter(t => t.status !== 'D' && scansTiming(t.path));
if (!files.length) return out;
const diff = spawnSync('git', ['diff', '--no-color', '--unified=0', '--diff-filter=ACMR', '-M', ctx.mergeBase, '--', ...files.map(t => t.path)], { cwd: ctx.repoRoot, encoding: 'utf8', timeout: 60_000, maxBuffer: 256 * 1024 * 1024, env: ctx.env });
let current: Set<number> | null = null;
for (const line of (diff.stdout ?? '').split('\n')) {
const header = /^\+\+\+ b\/(.+)$/.exec(line);
if (header) { current = new Set(); out.set(header[1]!, current); continue; }
const hunk = /^@@ -\d+(?:,\d+)? \+(\d+)(?:,(\d+))? @@/.exec(line);
if (hunk && current) { const start = Number(hunk[1]); const count = hunk[2] === undefined ? 1 : Number(hunk[2]); for (let k = 0; k < count; k++) current.add(start + k); }
}
for (const t of files) if (!out.has(t.path) && t.uncommitted && t.status === 'A') out.set(t.path, 'all');
return out;
}
function run(ctx: PregateContext): CheckResult {
const added = addedTestLines(ctx);
const hits: TimingHit[] = [];
for (const [file, lines] of added) {
let text: string;
try { text = fs.readFileSync(path.join(ctx.repoRoot, file), 'utf8'); } catch { continue; }
hits.push(...scanTiming(file, text, lines));
}
const inputs = baseInputs(ctx, { hits: sha256(hits.map(h => h.file + ':' + h.line + ':' + h.pattern + ':' + (h.escape && 'reason' in h.escape ? h.escape.reason : '')).join('\n')) });
const open = hits.filter(h => !h.escape || 'missingReason' in h.escape);
const escaped = hits.filter(h => h.escape && 'reason' in h.escape);
const summary = 'TIMING_ASSERTIONS: found=' + open.length + ' escaped=' + escaped.length + ' files=' + added.size;
for (const h of escaped) ctx.explain.push('timing: ' + h.file + ':' + h.line + ' ' + h.pattern + ' escaped: ' + (h.escape as { reason: string }).reason);
if (!open.length) return { id: 'timing', stage: 'preflight', status: 'pass', inputs, lines: escaped.length ? [summary] : undefined, detail: 'no timing assertion in the added lines of ' + added.size + ' test file(s)' + (escaped.length ? ' (' + escaped.length + ' escaped with gstack-timing-ok)' : '') };
const counts = (['wall-time-bound', 'cpu-time-bound', 'sleep-then-assert'] as const).map(p => [p, open.filter(h => h.pattern === p).length] as const).filter(([, c]) => c > 0);
return {
id: 'timing', stage: 'preflight', status: 'warn', inputs, code: 'PREGATE_TIMING_ASSERTION',
lines: [...open.map(h => 'TIMING_ASSERTION: ' + h.file + ':' + h.line + ' ' + h.pattern + (h.escape ? ' (gstack-timing-ok needs a reason)' : '')), summary],
detail: open.length + ' timing-dependent assertion(s) in added test lines (' + counts.map(([p, c]) => c + ' ' + p).join(', ') + ')' + (escaped.length ? '; ' + escaped.length + ' escaped' : ''),
fix: 'assert on the outcome, an injected clock or a forced deadline instead of elapsed time or a fixed sleep; when the bound is the contract, add gstack-timing-ok: <reason> in a comment on the line or the line above (docs/pregate.md#timing)',
};
}
export const timingCheck: CheckDef = { id: 'timing', stage: 'preflight', tier: 1, downgradable: true, needsRepoCommands: false, run };
+2 -1
View File
@@ -21,11 +21,12 @@ import { literalsCheck } from './checks/literals';
import { regenCheck } from './checks/regen';
import { secretsCheck } from './checks/secrets';
import { straysCheck } from './checks/strays';
import { timingCheck } from './checks/timing';
import { NON_DOWNGRADABLE } from './config';
import { withFingerprint } from './context';
import type { CheckDef, CheckResult, PregateContext, Stage } from './types';
export const CHECKS: readonly CheckDef[] = [regenCheck, secretsCheck, straysCheck, literalsCheck, guardsCheck, lanesCheck];
export const CHECKS: readonly CheckDef[] = [regenCheck, secretsCheck, straysCheck, literalsCheck, timingCheck, guardsCheck, lanesCheck];
export const CHECK_IDS = CHECKS.map(c => c.id);
export const PREGATE_OUT_REL = '.gstack/tmp/pregate.json';
export const PREGATE_TIER2 = ['ratchets', 'lint', 'links', 'hermetic', 'patches', 'integrator'] as const;
+6
View File
@@ -730,6 +730,12 @@ export const RESULT_CODES = {
summary: 'the gate-ahead attempt is unknown, already recorded, or its worktree no longer holds the gated commit',
fix: 'list attempts with gstack-ship-queue gate-ahead --list, then record the live one, or prepare a new attempt',
},
// Field list 2 W4 (pregate `timing`).
PREGATE_TIMING_ASSERTION: {
anchor: 'pregate-timing-assertion',
summary: 'an added or changed test line compares an elapsed wall-clock or CPU time against a bound, or sleeps and then asserts (a warning, not a block)',
fix: 'assert on the outcome, an injected clock or a forced deadline instead; when the bound is the contract, add `gstack-timing-ok: <reason>` in a comment on the line or the line above',
},
} as const satisfies Record<string, ResultCode>;
export type ResultCodeName = keyof typeof RESULT_CODES;
+4
View File
@@ -110,6 +110,10 @@ A gate is anything that would have made this change fail: a test, an assertion,
- Date-key lookups that assume "today" covers 24h — report at 8am PT only sees midnight→8am under today's key
- Mismatched time windows between related features — one uses hourly buckets, another uses daily keys for the same data
#### Timing-Dependent Tests
- An added or changed test line that compares an elapsed wall-clock or CPU time with a bound (`expect(Date.now() - t0).toBeLessThan(400)`, `assert elapsed < 0.5`) or sleeps a fixed time and then asserts, with no `gstack-timing-ok: <reason>` comment on the line or the line above. `gstack-pregate` prints these as `TIMING_ASSERTION: <file>:<line> <pattern>`; suggest asserting on the outcome, an injected clock, a forced deadline or a poll with a deadline
- A diff that raises an existing timing bound or adds a retry to make a flake pass: the bound is not the cause; route it to /investigate's flake recipe (timing flakes)
#### Type Coercion at Boundaries
- Values crossing Ruby→JSON→JS boundaries where type could change (numeric vs string) — hash/digest inputs must normalize types
- Hash/digest inputs that don't call `.to_s` or equivalent before serialization — `{ cores: 8 }` vs `{ cores: "8" }` produce different hashes
+1
View File
@@ -109,6 +109,7 @@
{ "file": "lib/pregate/checks/literals.ts", "movedFrom": "(new: pre-gate check, C8)" },
{ "file": "lib/pregate/checks/lanes.ts", "movedFrom": "(new: pre-gate check with the pipefail runner and requires-remote obligations, C8)" },
{ "file": "lib/pregate/checks/guards.ts", "movedFrom": "(new: pre-gate repo guards, field wave CD1)" },
{ "file": "lib/pregate/checks/timing.ts", "movedFrom": "(new: pre-gate timing-assertion check, field list 2 W4)" },
{ "file": "lib/pregate/runtime.ts", "movedFrom": "(new: the verified launch Bun for repo commands, field wave CD1)" },
{ "file": "lib/sealed-guard.ts", "movedFrom": "(new: the sealed-output guard shared by the pre-push hook and gstack-pregate sealed, field wave CD4)" },
{ "file": "lib/pregate/regate.ts", "movedFrom": "(new: the regate verdict from a fresh tree receipt plus migration collisions, field wave CD3)" },
+62
View File
@@ -0,0 +1,62 @@
import { expect, test } from 'bun:test';
import { cpuMs } from './helpers/cpu';
test('wall-clock bounds', async () => {
const t0 = Date.now();
run();
expect(Date.now() - t0).toBeLessThan(400); // HIT wall-time-bound
const started = performance.now();
const elapsed = performance.now() - started;
expect(elapsed).toBeLessThan(500); // HIT wall-time-bound
expect(result.elapsedMs).toBeLessThanOrEqual(2_000); // HIT wall-time-bound
expect(r.wall).toBeGreaterThan(1500); // HIT wall-time-bound
assert.ok(Date.now() - t0 < 1000); // HIT wall-time-bound
expect(input.deadlineAt - Date.now()).toBeLessThanOrEqual(1_500_000); // HIT wall-time-bound
});
test('CPU-time bounds', () => {
const ms = cpuMs(() => parse(input));
expect(ms).toBeLessThan(150); // HIT cpu-time-bound
expect(cpuMs(() => parse(input))).toBeLessThan(1000); // HIT cpu-time-bound
const usage = process.cpuUsage();
expect(process.cpuUsage(usage).user / 1000).toBeLessThan(200); // HIT cpu-time-bound
});
test('sleep then assert', async () => {
fire();
await Bun.sleep(50); // HIT sleep-then-assert
expect(calls).toBe(1);
await new Promise((r) => setTimeout(r, 100)); // HIT sleep-then-assert
expect(seen).toEqual(['a']);
});
test('not timing-dependent', async () => {
expect(result.elapsedMs).toBeGreaterThanOrEqual(0); // CLEAN
expect(entity.ttl_ms).toBeGreaterThan(1000); // CLEAN
expect(opts.timeoutMs).toBeLessThanOrEqual(60_000); // CLEAN
expect(CAPTURE_LONG_MS + 10_000).toBeLessThan(DEFAULT_SHARD_TIMEOUT_MS); // CLEAN
expect(lease.expiresAt).toBeGreaterThan(Date.now()); // CLEAN
expect(stats.reportMtimeMs).toBeLessThan(later); // CLEAN
expect(kept.length).toBeLessThan(items.length); // CLEAN
for (let i = 0; i < 4; i++) expect(step(i)).toBe('question'); // CLEAN
const log = path.join(dir, `run-${Date.now()}.log`);
expect(log.length).toBeGreaterThan(10); // CLEAN
expect(spawn(['bash', '-c', 'sleep 2; echo --timeout-ms 600']).status).toBe(0); // CLEAN
while (!fs.existsSync(ready) && Date.now() < deadline) await Bun.sleep(10); // CLEAN
expect(fs.existsSync(ready)).toBe(true);
await new Promise((r) => setTimeout(r, 0)); // CLEAN
expect(flushed).toBe(true);
const src = text.indexOf('await Bun.sleep(100)'); // CLEAN
expect(src).toBeGreaterThan(-1);
});
test('escapes', async () => {
// gstack-timing-ok: the 30 s cap is the product contract, measured at 2 s p99 under full suite load
expect(Date.now() - t0).toBeLessThan(30_000); // ESCAPED wall-time-bound
expect(Date.now() - t0).toBeLessThan(5_000); /* gstack-timing-ok: a hang check; the call returns in 40 ms */ // ESCAPED wall-time-bound
// gstack-timing-ok:
expect(Date.now() - t0).toBeLessThan(5_000); // UNREASONED wall-time-bound
await Bun.sleep(1100); // gstack-timing-ok: the mtime resolution is one second; the assert reads the file, not a race // ESCAPED sleep-then-assert
expect(stat.mtimeMs).not.toBe(before);
});
+25
View File
@@ -0,0 +1,25 @@
import time
def test_wall_bound():
t0 = time.monotonic()
run()
elapsed = time.monotonic() - t0
assert elapsed < 0.5 # HIT wall-time-bound
def test_cpu_bound():
c0 = time.process_time()
run()
assert time.process_time() - c0 < 0.2 # HIT cpu-time-bound
def test_sleep_then_assert():
fire()
time.sleep(0.1) # HIT sleep-then-assert
assert calls == 1
def test_escaped():
t0 = time.monotonic()
# gstack-timing-ok: the watchdog contract is two seconds and the call is a no-op
assert time.monotonic() - t0 < 2 # ESCAPED wall-time-bound
def test_clean():
assert len(rows) < 10 # CLEAN
+2 -2
View File
@@ -98,7 +98,7 @@ describe('gstack-pregate (bin)', () => {
const repo = fixture();
const help = runBin(repo, 'gstack-pregate', ['--help']);
expect(help.out).toContain('Exit codes: 0 ok · 1 fail · 2 usage · 3 refused or needs a flag');
expect(help.out).toContain('stage 1 mechanical preflight (regen, secrets, strays, literals, guards)');
expect(help.out).toContain('stage 1 mechanical preflight (regen, secrets, strays, literals, timing, guards)');
expect(help.out).toContain('stage 2 test execution (lanes)');
expect(runBin(repo, 'gstack-pregate', ['bogus']).status).toBe(EXIT.usage);
expect(pregate(repo, ['--only', 'hermetic']).status).toBe(EXIT.usage);
@@ -122,7 +122,7 @@ describe('gstack-pregate (bin)', () => {
const out = readOut(repo);
expect(out.schema_version).toBe(1);
expect(out.tree).toMatch(/^[0-9a-f]{40}$/);
expect(out.checks.map((c: any) => [c.id, c.status, c.stage])).toEqual([['regen', 'pass', 'preflight'], ['secrets', 'pass', 'preflight'], ['strays', 'pass', 'preflight'], ['literals', 'pass', 'preflight'], ['guards', 'pass', 'preflight'], ['lanes', 'pass', 'tests']]);
expect(out.checks.map((c: any) => [c.id, c.status, c.stage])).toEqual([['regen', 'pass', 'preflight'], ['secrets', 'pass', 'preflight'], ['strays', 'pass', 'preflight'], ['literals', 'pass', 'preflight'], ['timing', 'pass', 'preflight'], ['guards', 'pass', 'preflight'], ['lanes', 'pass', 'tests']]);
for (const c of out.checks) { expect(c.inputs.tree).toBe(out.tree); expect(typeof c.ms).toBe('number'); }
expect(check(repo, 'lanes').inputs.command).toMatch(/^[0-9a-f]{64}$/);
expect(out.verdict).toBe('pass');
+118
View File
@@ -0,0 +1,118 @@
/**
* pregate check `timing` (field list 2 W4): added or changed test lines
* that compare an elapsed wall-clock or CPU time against a bound, or sleep
* and then assert, print TIMING_ASSERTION lines and warn; a
* `gstack-timing-ok: <reason>` comment on the line or the line above
* escapes one. The fixture sources mark each line HIT, CLEAN, ESCAPED or
* UNREASONED with the expected pattern; they are .txt so this repo's own
* pregate never reads them as tests.
*/
import { afterEach, describe, expect, test } from 'bun:test';
import * as fs from 'node:fs';
import * as path from 'node:path';
import { EXIT } from '../lib/headless-artifacts';
import { scanTiming, scansTiming, type TimingHit } from '../lib/pregate/checks/timing';
import { CHECK_IDS } from '../lib/pregate/index';
import { validateConfig } from '../lib/pregate/config';
import { BASE_PREGATE, cleanup, commit, makeFixtureRepo, runBin, write, type FixtureRepo } from './helpers/pregate-fixture';
const FIXTURES = path.join(import.meta.dir, 'fixtures', 'pregate-timing');
const read = (name: string) => fs.readFileSync(path.join(FIXTURES, name), 'utf8');
/** Expected outcomes from the fixture's own markers: line → [marker, pattern]. */
function markers(text: string): Map<number, [string, string | undefined]> {
const out = new Map<number, [string, string | undefined]>();
text.split('\n').forEach((l, i) => { const m = /(?:\/\/|#) (HIT|CLEAN|ESCAPED|UNREASONED)(?: ([a-z-]+))?\s*$/.exec(l); if (m) out.set(i + 1, [m[1]!, m[2]]); });
return out;
}
function outcome(h: TimingHit | undefined): string {
if (!h) return 'CLEAN';
if (!h.escape) return 'HIT ' + h.pattern;
return ('reason' in h.escape ? 'ESCAPED ' : 'UNREASONED ') + h.pattern;
}
describe('timing detector over marked fixtures', () => {
for (const [file, as] of [['flaky.test.ts.txt', 'test/flaky.test.ts'], ['test_flaky.py.txt', 'tests/test_flaky.py']] as const) {
test(`${file}: every marked line gets its marked outcome and no unmarked line is flagged`, () => {
const text = read(file);
const hits = scanTiming(as, text, 'all');
const byLine = new Map(hits.map(h => [h.line, h]));
const expected = markers(text);
expect(expected.size).toBeGreaterThanOrEqual(5);
for (const [line, [marker, pattern]] of expected) expect(`${line}: ${outcome(byLine.get(line))}`).toBe(`${line}: ${pattern ? `${marker} ${pattern}` : marker}`);
expect(hits.filter(h => !expected.has(h.line)).map(h => `${h.line} ${h.pattern}`)).toEqual([]);
});
}
test('only added lines count: an unchanged bound is not reported, a changed one is', () => {
const text = read('flaky.test.ts.txt');
const line = text.split('\n').findIndex(l => l.includes('toBeLessThan(400)')) + 1;
expect(scanTiming('test/flaky.test.ts', text, new Set([1, 2, 3]))).toEqual([]);
expect(scanTiming('test/flaky.test.ts', text, new Set([line])).map(h => [h.line, h.pattern])).toEqual([[line, 'wall-time-bound']]);
});
test('a sleep-then-assert pair is reported when only its assertion changed', () => {
const text = read('flaky.test.ts.txt');
const lines = text.split('\n');
const sleep = lines.findIndex(l => l.includes('await Bun.sleep(50)')) + 1;
expect(scanTiming('test/flaky.test.ts', text, new Set([sleep + 1])).map(h => [h.line, h.pattern])).toEqual([[sleep, 'sleep-then-assert']]);
});
test('scope: test code only, never fixtures or product code', () => {
expect(scansTiming('test/x.test.ts')).toBe(true);
expect(scansTiming('test/helpers/poll.ts')).toBe(true);
expect(scansTiming('tests/test_x.py')).toBe(true);
expect(scansTiming('src/x.spec.js')).toBe(true);
expect(scansTiming('lib/retry.ts')).toBe(false);
expect(scansTiming('test/fixtures/pregate-timing/flaky.test.ts.txt')).toBe(false);
expect(scansTiming('test/fixtures/sample.test.ts')).toBe(false);
expect(scansTiming('docs/timing.md')).toBe(false);
});
});
const repos: FixtureRepo[] = [];
afterEach(() => { while (repos.length) cleanup(repos.pop()!); });
const pregate = (repo: FixtureRepo, args: string[]) => runBin(repo, 'gstack-pregate', ['--base', 'main', '--stage', 'preflight', '--only', 'timing', ...args]);
describe('gstack-pregate --only timing (real subprocess, fixture repo)', () => {
test('a branch adding a wall-clock bound warns with TIMING_ASSERTION file:line and still exits ok; the escape clears it', () => {
const repo = makeFixtureRepo(); repos.push(repo);
const body = "const test = require('node:test');\nconst assert = require('node:assert');\ntest('fast', () => {\n const t0 = Date.now();\n require('../lib/util.js').add(1, 2);\n assert.ok(Date.now() - t0 < 400);\n});\n";
commit(repo, { 'test/speed.test.js': body });
const r = pregate(repo, []);
expect(r.status).toBe(EXIT.ok);
expect(r.out).toMatch(/^preflight {2}timing {4}warn .*1 timing-dependent assertion\(s\) in added test lines \(1 wall-time-bound\) \(PREGATE_TIMING_ASSERTION\)/m);
expect(r.out).toContain('timing: TIMING_ASSERTION: test/speed.test.js:6 wall-time-bound');
expect(r.out).toContain('timing: TIMING_ASSERTIONS: found=1 escaped=0 files=1');
expect(r.out).toMatch(/^PREGATE: warn /m);
commit(repo, { 'test/speed.test.js': body.replace(' assert.ok(', ' // gstack-timing-ok: a hang check with 100x headroom\n assert.ok(') });
const ok = pregate(repo, ['--explain']);
expect(ok.status).toBe(EXIT.ok);
expect(ok.out).toMatch(/^preflight {2}timing {4}pass .*1 escaped with gstack-timing-ok/m);
expect(ok.out + ok.err).toContain('timing: test/speed.test.js:7 wall-time-bound escaped: a hang check with 100x headroom');
});
test('an escape without a reason is still reported, and an untouched existing bound is not', () => {
const repo = makeFixtureRepo(); repos.push(repo);
repo.git('checkout', '-q', 'main');
write(repo.work, 'test/old.test.js', "const assert = require('node:assert');\nconst t0 = Date.now();\nassert.ok(Date.now() - t0 < 400);\n");
repo.git('add', '-A'); repo.git('commit', '-q', '-m', 'old bound'); repo.git('push', '-q', 'origin', 'main');
repo.git('checkout', '-q', 'feature'); repo.git('merge', '-q', '--ff-only', 'main');
commit(repo, { 'test/old.test.js': "const assert = require('node:assert');\nconst t0 = Date.now();\nassert.ok(Date.now() - t0 < 400);\nassert.ok(true);\n", 'test/new.test.js': "const t0 = Date.now();\n// gstack-timing-ok:\nexpect(Date.now() - t0).toBeLessThan(400);\n" });
const r = pregate(repo, []);
expect(r.out).toContain('timing: TIMING_ASSERTION: test/new.test.js:3 wall-time-bound (gstack-timing-ok needs a reason)');
expect(r.out).not.toContain('test/old.test.js:3');
expect(r.out).toContain('TIMING_ASSERTIONS: found=1 escaped=0 files=2');
});
test('a docs-only branch passes and timing is a known, downgradable check id', () => {
const repo = makeFixtureRepo(); repos.push(repo);
commit(repo, { 'docs/README.md': '# docs\nmore\n' });
const r = pregate(repo, []);
expect(r.status).toBe(EXIT.ok);
expect(r.out).toMatch(/^preflight {2}timing {4}pass .*no timing assertion in the added lines of 0 test file\(s\)/m);
expect(CHECK_IDS).toContain('timing');
expect(validateConfig({ ...BASE_PREGATE, warn: ['timing'] }, CHECK_IDS)).toEqual([]);
});
});