From d95aa3425e6eac1146a36e84d462de7d3fcf6eed Mon Sep 17 00:00:00 2001 From: Jeffrey Montoya Date: Wed, 30 Sep 2026 11:35:49 -0400 Subject: [PATCH] feat(gateguard): measure hook latency in fresh processes --- docs/gateguard/evaluation.md | 89 ++++++++++++++++++++-------- scripts/dev/gateguard-eval.js | 80 ++++++++++++++++++++++--- tests/scripts/gateguard-eval.test.js | 45 ++++++++++++-- 3 files changed, 177 insertions(+), 37 deletions(-) diff --git a/docs/gateguard/evaluation.md b/docs/gateguard/evaluation.md index 080fe8aa3..10f799ae5 100644 --- a/docs/gateguard/evaluation.md +++ b/docs/gateguard/evaluation.md @@ -43,8 +43,15 @@ Metrics per hook: not ask. Asking fewer questions must not drop the ones that matter. - **Estimated denial tokens**: characters of all denial reasons divided by 4. - **Allows with a note**: how the working tree avoided a denial. -- **Hook latency p50/p95**: wall time of `run()` per step, in process. The - only non-deterministic metric. +- **Hook latency, fresh process**: `require()` of the hook plus `run()`, timed + inside a new Node process per step, which is how Claude Code runs a hook. + Node start-up itself is excluded; it is the same for every hook. See + [Latency](#latency). +- **run() latency, warm**: wall time of `run()` in the scenario's worker, after + the hook module is loaded. Modules the hook loads lazily count on the step + that first needs them. + +The latency rows are the only non-deterministic metrics. Each scenario runs in its own temp project (files, symlinks and hard links created from the fixture), with its own transcript, `GATEGUARD_STATE_DIR`, `HOME` and a @@ -57,30 +64,32 @@ relatively at that ref, into a temp tree that mirrors the repo layout. ## Results Working tree = branch `gateguard-full`; `upstream/main` = `c70874fa`; -`8438f040` = the pull request head before this round. Node 22, Linux. +`4b02f669` = the pull request head before this round. Node 22, Linux. ```text Corpus: 20 scenarios, 184 steps. ``` -| Metric | working tree | upstream/main | 8438f040 | +| Metric | working tree | upstream/main | 4b02f669 | | --- | ---: | ---: | ---: | | Steps | 184 | 184 | 184 | -| Denials | 132 | 157 | 131 | +| Denials | 132 | 157 | 132 | | Redundant denials | 0 | 38 | 0 | -| Must-deny bypasses | 0 | 8 | 1 | -| Expectation mismatches | 0 | 55 | 1 | +| Must-deny bypasses | 0 | 8 | 0 | +| Expectation mismatches | 0 | 55 | 0 | | Irrelevant questions asked | 2 | 187 | 2 | | Irrelevant questions in condensed denials | 2 | 111 | 2 | | Warranted questions not asked | 1 | 57 | 1 | -| Estimated denial tokens | 25633 | 27796 | 25455 | -| Allows with a credit note | 12 | 0 | 13 | +| Estimated denial tokens | 25633 | 27796 | 25633 | +| Allows with a credit note | 12 | 0 | 12 | | Allows with a sibling note | 11 | 0 | 11 | | Allows with a trivial-edit note | 5 | 0 | 5 | -| Hook latency p50 (ms) | 2.28 | 1.20 | 2.14 | -| Hook latency p95 (ms) | 7.81 | 2.93 | 7.48 | +| Hook latency p50, fresh process (ms) | 21.18 | 10.58 | 25.11 | +| Hook latency p95, fresh process (ms) | 30.34 | 16.67 | 38.24 | +| run() latency p50, warm (ms) | 2.03 | 1.03 | 2.01 | +| run() latency p95, warm (ms) | 10.56 | 2.58 | 7.03 | -| Scenario | Steps | Denials: working tree | Denials: upstream/main | Denials: 8438f040 | +| Scenario | Steps | Denials: working tree | Denials: upstream/main | Denials: 4b02f669 | | --- | ---: | ---: | ---: | ---: | | docs-heavy-session | 14 | 6 | 12 | 6 | | scaffold-module | 10 | 3 | 10 | 3 | @@ -94,7 +103,7 @@ Corpus: 20 scenarios, 184 steps. | subagent-edits | 6 | 3 | 1 | 3 | | first-shell-commands | 20 | 11 | 17 | 11 | | windows-paths | 8 | 5 | 7 | 5 | -| bypass-search-filters | 19 | 15 | 19 | 14 | +| bypass-search-filters | 19 | 15 | 19 | 15 | | bypass-turn-and-batch | 7 | 7 | 7 | 7 | | bypass-siblings | 11 | 11 | 11 | 11 | | cap-with-sensitive | 6 | 4 | 6 | 4 | @@ -129,12 +138,12 @@ Against `upstream/main`: after a comment-only one (the comment edit no longer spends the file's first touch). -Against `8438f040` (the pull request head before this round): one more -denial and one fewer credit. `bypass-search-filters` now includes a search -whose directory-qualified include (`rg -g 'src/**' sweep .`) keeps the target -in `lib/` out of the search; `8438f040` dropped that include and credited the -edit, its one must-deny bypass. The control that searches the target's own -directory is still credited. +Against `4b02f669` (the pull request head before this round): the same +decisions, questions and notes on every step; only latency changes (see +[Latency](#latency)). `bypass-search-filters` includes a search whose +directory-qualified include (`rg -g 'src/**' sweep .`) keeps the target in +`lib/` out of the search; it must be denied, and the control that searches +the target's own directory is credited. Four scenarios come from security reviews of this change. `bypass-comment-context` holds 21 must-deny steps: comment-looking edits that @@ -173,10 +182,12 @@ What the working tree still gets wrong, by the corpus's own labels: (`c-comment-continuation`) has no data words, so the condensed hint no longer mentions data schemas; the corpus labels that question as warranted (the 1 unasked one). -- Latency rises against `upstream/main` (p50 2.3 ms against 1.2 ms, p95 - 7.8 ms against 2.9 ms) with the added transcript scanning, path resolution - and the target's link-count check; both stay far below the 200 ms budget - for blocking hooks. Checking a comment-only edit +- Latency: a first touch costs more than on `upstream/main` because it reads + the transcript, matches the searches that name the target, reads the target + file and profiles the change (fresh-process p50 21.2 ms against 10.6 ms, + p95 30.3 ms against 16.7 ms on this corpus, where every step is a first + touch or a gate). Shell commands and repeat edits stay within about 1 to + 2.5 ms of `main`; see [Latency](#latency). Checking a comment-only edit reads and scans the target file, which costs up to about 50 ms for a 1 MiB file (the largest one read). @@ -185,14 +196,14 @@ What the working tree still gets wrong, by the corpus's own labels: ```bash git fetch upstream main node scripts/dev/gateguard-eval.js --markdown -node scripts/dev/gateguard-eval.js --markdown --baseline upstream/main --baseline 8438f040 +node scripts/dev/gateguard-eval.js --markdown --baseline upstream/main --baseline 4b02f669 node scripts/dev/gateguard-eval.js --json > gateguard-eval.json node scripts/dev/gateguard-eval.js --baseline upstream/main --sarif gateguard-eval.sarif node tests/hooks/gateguard-scenarios.test.js ``` `--baseline ` takes any ref and can be repeated (default -`upstream/main`); pass the pull request head (`8438f040` above) to compare +`upstream/main`); pass the pull request head (`4b02f669` above) to compare against it. `--corpus ` points at another scenario directory. The script exits non-zero when the working tree has a mismatch, a must-deny bypass, an explicit `allow` decision or a thrown error. @@ -201,6 +212,34 @@ mismatch, a must-deny bypass, an explicit `allow` decision or a thrown error. `warning`) with each hook's totals in the run properties. Timing is left out, so the file is identical across reruns of the same tree and corpus. +## Latency + +The fresh-process pass replays every scenario again, with a new state +directory and transcript, and runs each step with +`node -e `. Its decisions must match the worker's; +a step decided differently fails the run. `--no-cold` skips the pass. + +Per call type: 25 fresh processes each, p50 of `require()` plus p50 of +`run()` in ms, Node 22 on Linux, with a 20-search turn and a 50-function +target file: + +| Call | this branch | `4b02f669` | `main` | +| --- | ---: | ---: | ---: | +| Shell command, first of session | 10.2 | 19.2 | 8.7 | +| Shell command, routine gate already passed | 12.3 | 21.3 | 11.6 | +| Edit of a file already checked | 11.1 | 20.6 | 8.7 | +| First-touch edit, denied | 22.4 | 29.7 | 9.6 | +| First-touch edit, comment-only pass | 25.7 | 38.5 | 9.5 | + +Shell commands and repeat edits, most calls in a session, now load only the +modules they use and stay within about 1 to 2.5 ms of `main`. A first touch +reads the transcript, parses the turn's searches that name the target, reads +the target file and profiles the change; `main` does none of these. Each hook +call is a new Node process, so the code a call runs is also compiled on that +call, and that compilation, not the size of the files, is most of the +remaining difference. Node's module compile cache does not reduce it: it +caches top-level code, and the gate's functions are compiled on first call. + ## Corpus format One JSON file per scenario in `tests/fixtures/gateguard-scenarios/`: diff --git a/scripts/dev/gateguard-eval.js b/scripts/dev/gateguard-eval.js index f44598d52..b97693634 100644 --- a/scripts/dev/gateguard-eval.js +++ b/scripts/dev/gateguard-eval.js @@ -305,6 +305,59 @@ async function runCorpus(hookFile, scenarios) { } } +// --- cold latency --- +// see docs/gateguard/evaluation.md#latency + +const COLD_PROBE = [ + "const { performance } = require('perf_hooks');", + 'const started = performance.now();', + 'const hook = require(process.argv[1]);', + 'const result = hook.run(process.argv[2]);', + 'const ms = performance.now() - started;', + 'process.stdout.write(JSON.stringify({ ms, result: result === undefined ? null : result }));' +].join('\n'); + +/** Replay every scenario with one fresh Node process per step; returns per-step require+run latency and decisions. */ +function measureColdLatency(hookFile, scenarios) { + const workDir = fs.mkdtempSync(path.join(os.tmpdir(), 'gateguard-cold-')); + try { + const steps = []; + for (const scenario of scenarios) { + const prepared = prepareScenario(scenario, workDir); + if (prepared.skipped) continue; + for (const step of prepared.steps) { + if (step.records.length > 0) { + fs.appendFileSync(prepared.transcript, step.records.map(record => `${JSON.stringify(record)}\n`).join(''), 'utf8'); + } + const raw = JSON.stringify(step.payload); + const stdout = execFileSync(process.execPath, ['-e', COLD_PROBE, hookFile, raw], { + env: prepared.env, + encoding: 'utf8', + maxBuffer: 16 * 1024 * 1024, + stdio: ['ignore', 'pipe', 'ignore'] + }); + const { ms, result } = JSON.parse(stdout); + const output = hookOutput(result); + steps.push({ scenario: scenario.name, step: step.id, latencyMs: ms, decision: output.decision === 'deny' ? 'deny' : 'allow' }); + } + } + return steps; + } finally { + fs.rmSync(workDir, { recursive: true, force: true }); + } +} + +function coldSummary(coldSteps, warmSteps) { + const sorted = coldSteps.map(step => step.latencyMs).sort((a, b) => a - b); + const warmDecisions = new Map(warmSteps.map(step => [`${step.scenario}/${step.step}`, step.decision])); + const disagreements = coldSteps.filter(step => warmDecisions.get(`${step.scenario}/${step.step}`) !== step.decision).length; + return { + p50Ms: Number(percentile(sorted, 0.5).toFixed(3)), + p95Ms: Number(percentile(sorted, 0.95).toFixed(3)), + disagreements + }; +} + // --- question mapping --- function questionTextTable() { @@ -439,8 +492,10 @@ const METRIC_ROWS = [ ['Allows with a credit note', s => s.totals.allowsByKind.credit], ['Allows with a sibling note', s => s.totals.allowsByKind.sibling], ['Allows with a trivial-edit note', s => s.totals.allowsByKind.trivial], - ['Hook latency p50 (ms)', s => s.latency.p50Ms.toFixed(2)], - ['Hook latency p95 (ms)', s => s.latency.p95Ms.toFixed(2)] + ['Hook latency p50, fresh process (ms)', s => (s.cold ? s.cold.p50Ms.toFixed(2) : 'not run')], + ['Hook latency p95, fresh process (ms)', s => (s.cold ? s.cold.p95Ms.toFixed(2) : 'not run')], + ['run() latency p50, warm (ms)', s => s.latency.p50Ms.toFixed(2)], + ['run() latency p95, warm (ms)', s => s.latency.p95Ms.toFixed(2)] ]; function markdownTable(header, rows) { @@ -474,6 +529,10 @@ function renderMarkdown(report) { lines.push('', `${report.hooks[0].label} mismatches:`, ''); mismatched.forEach(step => lines.push(`- ${step.scenario} / ${step.step}: expected ${step.expect}, got ${step.decision} (${step.kind})`)); } + const cold = report.hooks[0].summary.cold; + if (cold && cold.disagreements > 0) { + lines.push('', `${report.hooks[0].label}: ${cold.disagreements} step(s) decided differently in a fresh process.`); + } return `${lines.join('\n')}\n`; } @@ -586,16 +645,18 @@ const USAGE = [ ' --corpus scenario directory (default tests/fixtures/gateguard-scenarios)', ' --markdown print markdown tables (default)', ' --json print the full report as JSON', - ' --sarif also write working-tree gate failures as SARIF 2.1.0' + ' --sarif also write working-tree gate failures as SARIF 2.1.0', + ' --no-cold skip the fresh-process latency pass (one Node process per step)' ].join('\n'); function parseArgs(argv) { - const options = { format: 'markdown', baselines: [], corpus: DEFAULT_CORPUS_DIR, sarif: null, help: false }; + const options = { format: 'markdown', baselines: [], corpus: DEFAULT_CORPUS_DIR, sarif: null, cold: true, help: false }; for (let i = 0; i < argv.length; i++) { const arg = argv[i]; if (arg === '--markdown') options.format = 'markdown'; else if (arg === '--json') options.format = 'json'; else if (arg === '--help' || arg === '-h') options.help = true; + else if (arg === '--no-cold') options.cold = false; else if ((arg === '--baseline' || arg === '--corpus' || arg === '--sarif') && i + 1 < argv.length) { if (arg === '--baseline') options.baselines.push(argv[++i]); else if (arg === '--sarif') options.sarif = path.resolve(argv[++i]); @@ -607,7 +668,7 @@ function parseArgs(argv) { } /** Evaluate the working-tree hook and each baseline ref over a corpus. */ -async function evaluate({ baselines = [DEFAULT_BASELINE], corpus = DEFAULT_CORPUS_DIR } = {}) { +async function evaluate({ baselines = [DEFAULT_BASELINE], corpus = DEFAULT_CORPUS_DIR, cold = false } = {}) { const scenarios = loadCorpus(corpus); const table = questionTextTable(); const hooks = [{ label: 'working tree', ref: null, file: path.join(REPO_ROOT, ...HOOK_RELATIVE_PATH.split('/')) }]; @@ -618,7 +679,9 @@ async function evaluate({ baselines = [DEFAULT_BASELINE], corpus = DEFAULT_CORPU }); const evaluated = []; for (const hook of hooks) { - evaluated.push({ label: hook.label, ref: hook.ref, summary: summarize(await runCorpus(hook.file, scenarios), table) }); + const summary = summarize(await runCorpus(hook.file, scenarios), table); + if (cold) summary.cold = coldSummary(measureColdLatency(hook.file, scenarios), summary.steps); + evaluated.push({ label: hook.label, ref: hook.ref, summary }); } return { corpus: { scenarios: scenarios.length, steps: scenarios.reduce((sum, scenario) => sum + scenario.steps.length, 0) }, @@ -640,7 +703,8 @@ async function main() { process.stdout.write(options.format === 'json' ? `${JSON.stringify(report, null, 2)}\n` : renderMarkdown(report)); if (options.sarif) fs.writeFileSync(options.sarif, renderSarif(report), 'utf8'); const working = report.hooks[0].summary.totals; - if (working.mustDenyBypasses > 0 || working.mismatches > 0 || working.explicitAllows > 0 || working.errors > 0) { + const coldDisagreements = report.hooks[0].summary.cold ? report.hooks[0].summary.cold.disagreements : 0; + if (working.mustDenyBypasses > 0 || working.mismatches > 0 || working.explicitAllows > 0 || working.errors > 0 || coldDisagreements > 0) { process.exitCode = 1; } } @@ -654,4 +718,4 @@ if (!isMainThread && workerData && workerData.gateguardEval) { }); } -module.exports = { loadCorpus, materializeHook, runCorpus, summarize, questionsAsked, renderMarkdown, renderSarif, parseArgs, evaluate }; +module.exports = { loadCorpus, materializeHook, runCorpus, measureColdLatency, summarize, questionsAsked, renderMarkdown, renderSarif, parseArgs, evaluate }; diff --git a/tests/scripts/gateguard-eval.test.js b/tests/scripts/gateguard-eval.test.js index 9935322a3..f8eaf5bbc 100644 --- a/tests/scripts/gateguard-eval.test.js +++ b/tests/scripts/gateguard-eval.test.js @@ -5,10 +5,11 @@ 'use strict'; const assert = require('assert'); +const fs = require('fs'); const os = require('os'); const path = require('path'); const { pathToFileURL } = require('url'); -const { parseArgs, renderSarif } = require('../../scripts/dev/gateguard-eval'); +const { parseArgs, renderSarif, loadCorpus, runCorpus, summarize, measureColdLatency } = require('../../scripts/dev/gateguard-eval'); let passed = 0; let failed = 0; @@ -164,6 +165,42 @@ test('output leaves out timing so reruns are byte-identical', () => { assert.strictEqual(renderSarif(slower), text); }); -console.log(`\nPassed: ${passed}`); -console.log(`Failed: ${failed}`); -process.exitCode = failed > 0 ? 1 : 0; +test('--no-cold turns off the fresh-process pass', () => { + assert.strictEqual(parseArgs([]).cold, true); + assert.strictEqual(parseArgs(['--no-cold']).cold, false); +}); + +async function coldTests() { + const corpusDir = fs.mkdtempSync(path.join(os.tmpdir(), 'gateguard-eval-corpus-')); + try { + fs.copyFileSync( + path.join(__dirname, '..', 'fixtures', 'gateguard-scenarios', '11-first-shell-commands.json'), + path.join(corpusDir, 'shell.json') + ); + const scenarios = loadCorpus(corpusDir); + const hookFile = path.join(__dirname, '..', '..', 'scripts', 'hooks', 'gateguard-fact-force.js'); + const warm = summarize(await runCorpus(hookFile, scenarios)); + const cold = measureColdLatency(hookFile, scenarios); + test('the fresh-process pass times every step', () => { + assert.strictEqual(cold.length, scenarios[0].steps.length); + assert.ok(cold.every(step => Number.isFinite(step.latencyMs) && step.latencyMs > 0)); + }); + test('fresh processes decide every step as the worker does', () => { + assert.deepStrictEqual(cold.map(step => step.decision), warm.steps.map(step => step.decision)); + }); + } finally { + fs.rmSync(corpusDir, { recursive: true, force: true }); + } +} + +coldTests().then(finish, error => { + console.log(` ✗ fresh-process pass failed: ${error.message}`); + failed++; + finish(); +}); + +function finish() { + console.log(`\nPassed: ${passed}`); + console.log(`Failed: ${failed}`); + process.exitCode = failed > 0 ? 1 : 0; +}