feat(gateguard): measure hook latency in fresh processes

This commit is contained in:
Jeffrey Montoya
2026-09-30 11:35:49 -04:00
parent eab92ed21d
commit d95aa3425e
3 changed files with 177 additions and 37 deletions
+64 -25
View File
@@ -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 <ref>` 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 <dir>` 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 <probe> <hook> <payload>`. 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/`:
+72 -8
View File
@@ -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 <dir> scenario directory (default tests/fixtures/gateguard-scenarios)',
' --markdown print markdown tables (default)',
' --json print the full report as JSON',
' --sarif <file> also write working-tree gate failures as SARIF 2.1.0'
' --sarif <file> 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 };
+41 -4
View File
@@ -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;
}