/** * 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: : ; a hit is escaped by * gstack-timing-ok: 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 = /(?:\/\/|\/\*|#|--|/g, '').trim(); return /[A-Za-z]{2}/.test(reason) ? { reason } : { missingReason: true }; } const identRe = (name: string) => new RegExp('(? { const vars = new Map(); 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): '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(/(? /^\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): '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 | '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 | 'all'> | { error: string } { const out = new Map | 'all'>(); const files = ctx.touched.filter(t => t.status !== 'D' && scansTiming(t.path)); if (!files.length) return out; const diff = spawnSync('git', ['diff', '--no-ext-diff', '--no-textconv', '--no-color', '--src-prefix=a/', '--dst-prefix=b/', '--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 }); if (diff.error || diff.status !== 0) return { error: 'git diff ' + (diff.error ? 'did not finish (' + diff.error.message + ')' : 'exited ' + diff.status + ': ' + (diff.stderr ?? '').trim().split('\n').pop()) }; let current: Set | 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); if (!(added instanceof Map)) return { id: 'timing', stage: 'preflight', status: 'incomplete', inputs: baseInputs(ctx), code: 'PREGATE_INCOMPLETE', detail: added.error + '; the added test lines were not read', fix: 'fix the git error and rerun gstack-pregate; an unread diff never passes' }; 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: 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 };