From 4080b7501efe1caa15bac18136465c56acb798e4 Mon Sep 17 00:00:00 2001 From: Colby McHenry Date: Tue, 4 Aug 2026 14:35:56 -0500 Subject: [PATCH] test(agent-eval): measure residual context occupancy, over multi-turn sessions (CG-7) The A/B arms reported cost, tokens, time and tool counts for one headless question. They could not report what issue #1500 actually measured: how much of the context window a tool's responses still occupy once the question is answered, which every later turn is then charged for. parse-run.mjs now measures that. Tokens are measured, not estimated: for each assistant request, input + cache_read + cache_creation is the exact token count of its whole prompt, so consecutive requests differ by exactly what was appended between them. That delta is priced against the characters in the gap, calibrated on gaps that are >=80% tool result. Explore output lands near 2.3 chars/token, so the usual bytes/4 estimate would have under-counted it by ~40%. Content also leaves the window, so residual is tracked apart from contributed: a compact_boundary clears the resident set, and a mid-run context drop is micro-compaction, which sheds the oldest tool results first and is applied FIFO. run-all.sh takes "Q1||Q2||Q3" and runs them as one resumed session, one segment file per turn; parse-run.mjs stitches the segments back together. bench-readme.sh now runs each README repo as a three-turn session (CG_TURNS=1 restores the single-question form). parse-bench-readme.mjs reports the arms' retrieval residual side by side -- codegraph's responses against the without-arm's Read/Grep/Bash -- in absolute tokens, share of context, and share of window, and says so explicitly when the rows it aggregated were single-turn. Two transcript traps are handled and documented at the call site: Claude Code emits one assistant event per content block, all carrying the same usage (summing per event double-counts every turn with both thinking and a tool_use), and the streamed output_tokens is a partial snapshot. Occupancy lives in parse-run.mjs and is imported by the aggregator rather than extracted to a module -- a new scripts/agent-eval/*.mjs scores into the self-query fixture's own corpus and moves its numbers. --- scripts/agent-eval/bench-readme.sh | 43 ++- scripts/agent-eval/parse-bench-readme.mjs | 141 ++++++--- scripts/agent-eval/parse-run.mjs | 348 +++++++++++++++++++--- scripts/agent-eval/run-all.sh | 73 ++++- 4 files changed, 499 insertions(+), 106 deletions(-) diff --git a/scripts/agent-eval/bench-readme.sh b/scripts/agent-eval/bench-readme.sh index 60a5330..67c01b6 100644 --- a/scripts/agent-eval/bench-readme.sh +++ b/scripts/agent-eval/bench-readme.sh @@ -1,28 +1,47 @@ #!/usr/bin/env bash # Re-run the README "Benchmark Results" A/B (with vs without codegraph) on the # current build: the 7 README repos, same queries, RUNS per arm (default 4). -# Output → /tmp/ab-readme//run/run-headless-{with,without}.jsonl +# Output → /tmp/ab-readme//run/run-headless-{with,without}[.tN].jsonl # Aggregate with parse-bench-readme.mjs. Repos must be cloned + indexed under # $CORPUS (default /tmp/codegraph-corpus) by the build under test. +# +# Each row is a THREE-TURN session: the README question, then two follow-ups +# that stay inside the same flow. Turns 2-3 are where residual context occupancy +# is actually charged — the first answer's tool output is still in the window, +# so the arms diverge on how much headroom each left behind. CG_TURNS=1 runs the +# README question alone (the original single-question A/B). set -uo pipefail H="$(cd "$(dirname "$0")" && pwd)" C="${CORPUS:-/tmp/codegraph-corpus}" RUNS="${RUNS:-4}" +TURNS="${CG_TURNS:-3}" ROWS=( -"vscode|How does the extension host communicate with the main process?" -"excalidraw|How does Excalidraw render and update canvas elements?" -"django|How does Django's ORM build and execute a query from a QuerySet?" -"tokio|How does tokio schedule and run async tasks on its runtime?" -"okhttp|How does OkHttp process a request through its interceptor chain?" -"gin|How does gin route requests through its middleware chain?" -"alamofire|How does Alamofire build, send, and validate a request?" +"vscode|How does the extension host communicate with the main process?|Where in that path would a message be dropped if the extension host crashes?|What would I need to change to add a new message type to that protocol?" +"excalidraw|How does Excalidraw render and update canvas elements?|Which part of that path decides whether a full re-render happens or an incremental one?|If I added a new element type, what in that render path would need to change?" +"django|How does Django's ORM build and execute a query from a QuerySet?|Where in that path is the SQL actually compiled into a string?|What would I change to add a new lookup type to that pipeline?" +"tokio|How does tokio schedule and run async tasks on its runtime?|Where does a task move between the local and the global queue in that path?|What in that path would I touch to add a per-task instrumentation hook?" +"okhttp|How does OkHttp process a request through its interceptor chain?|Where in that chain is the connection actually acquired?|What would I change to add a new interceptor stage before the cache?" +"gin|How does gin route requests through its middleware chain?|Where is the 404 / no-route case handled in that same chain?|What would I change to add a per-route middleware that runs before the global ones?" +"alamofire|How does Alamofire build, send, and validate a request?|Where does retry / interceptor logic hook into that path?|What would I change to add a new validation step to it?" ) -echo "### README A/B START $(date) RUNS=$RUNS" +echo "### README A/B START $(date) RUNS=$RUNS TURNS=$TURNS" for row in "${ROWS[@]}"; do - repo="${row%%|*}"; q="${row#*|}" - echo "===== $repo =====" + repo="${row%%|*}"; rest="${row#*|}" + # Take the first $TURNS questions and join them with "||" for run-all.sh. + q=""; n=0 + while [ "$n" -lt "$TURNS" ] && [ -n "$rest" ]; do + part="${rest%%|*}" + if [ "$rest" = "$part" ]; then rest=""; else rest="${rest#*|}"; fi + [ -n "$q" ] && q="$q||" + q="$q$part"; n=$((n + 1)) + done + echo "===== $repo ($n turns) =====" for run in $(seq 1 "$RUNS"); do - AGENT_EVAL_OUT="/tmp/ab-readme/$repo/run$run" bash "$H/run-all.sh" "$C/$repo" "$q" headless 2>&1 | grep -E "exit [0-9]" || echo " run$run: (no exit line)" + out="/tmp/ab-readme/$repo/run$run" + mkdir -p "$out" + AGENT_EVAL_OUT="$out" bash "$H/run-all.sh" "$C/$repo" "$q" headless > "$out/console.log" 2>&1 + grep -E "^exit [0-9]" "$out/console.log" | sed 's/^/ /' || echo " run$run: (no exit line)" + grep -E "codegraph +[0-9,]+ tok|→ file-access" "$out/console.log" | sed 's/^/ /' || true done done echo "### README A/B DONE $(date)" diff --git a/scripts/agent-eval/parse-bench-readme.mjs b/scripts/agent-eval/parse-bench-readme.mjs index f7c5ade..e0cf4af 100644 --- a/scripts/agent-eval/parse-bench-readme.mjs +++ b/scripts/agent-eval/parse-bench-readme.mjs @@ -1,71 +1,87 @@ #!/usr/bin/env node // Aggregate the README A/B (bench-readme.sh output): per repo, median of N runs -// per arm → time, tool calls, tokens, cost, and % saved. Plus an average row. +// per arm → time, tool calls, tokens, cost, % saved, and RESIDUAL CONTEXT +// OCCUPANCY. Plus an average row. // // Tokens = SUM of per-turn assistant `usage` (input + output + cache read + // cache creation) — the cumulative "total tokens processed". NOTE: `result.usage` -// is last-turn-only in current Claude Code, so it under-counts badly; don't use it. -// `total_cost_usd` and `duration_ms` are already cumulative. +// is last-turn-only in some Claude Code versions, so reading it alone can +// under-count badly; parseSession() sums per-segment and dedupes assistant +// events by message.id (Claude Code emits one event per content block, each +// carrying the same usage — summing per EVENT double-counts). +// +// The occupancy table answers the question "tokens processed" cannot: how much +// of the window each arm's tool output STILL OCCUPIES when the run ends. Under +// multi-turn rows that residual is charged against every following turn. // // Usage: node parse-bench-readme.mjs [/tmp/ab-readme] -import { readFileSync, existsSync, readdirSync } from 'fs'; +import { existsSync, readdirSync } from 'fs'; import { join } from 'path'; +import { parseSession } from './parse-run.mjs'; + const ROOT = process.argv[2] || '/tmp/ab-readme'; const REPOS = ['vscode', 'excalidraw', 'django', 'tokio', 'okhttp', 'gin', 'alamofire']; -function parse(file) { - if (!existsSync(file)) return null; - const L = readFileSync(file, 'utf8').split('\n').filter(Boolean); - let tools = 0, reads = 0, grep = 0, cg = 0, tokens = 0, r = null, raced = false; - for (const l of L) { let e; try { e = JSON.parse(l); } catch { continue; } - if (e.type === 'assistant') { - const u = e.message?.usage; - if (u) tokens += (u.input_tokens || 0) + (u.output_tokens || 0) + (u.cache_read_input_tokens || 0) + (u.cache_creation_input_tokens || 0); - for (const b of (e.message?.content || [])) if (b.type === 'tool_use') { - const n = b.name; - if (n === 'ToolSearch') continue; - tools++; - if (n === 'Read') reads++; - else if (n === 'Grep' || n === 'Glob') grep++; - else if (/codegraph/.test(n)) cg++; - } - } - // MCP cold-start race: the headless agent fired before `codegraph serve --mcp` - // finished registering its tools, so early calls returned "No such tool - // available" and the agent floundered into grep/Read. That measures CodeGraph's - // startup latency, NOT its steady-state value — flag the run so the aggregate - // can exclude it (an artifact of headless first-turn timing, not the tool). - if (e.type === 'user') for (const b of (Array.isArray(e.message?.content) ? e.message.content : [])) { - if (b.type === 'tool_result') { - const t = Array.isArray(b.content) ? b.content.map(c => c.text || '').join('') : (b.content || ''); - if (/No such tool available/.test(t)) raced = true; - } - } - if (e.type === 'result') r = e; - } - if (!r || r.subtype !== 'success') return null; - return { dur: r.duration_ms / 1000, tools, reads, grep, cg, tokens, cost: r.total_cost_usd || 0, raced }; +/** All segment files of one arm's session, in turn order (t1, t2, t3, …). */ +function segments(dir, label) { + const first = join(dir, `run-${label}.jsonl`); + if (!existsSync(first)) return null; + const rest = readdirSync(dir) + .map((f) => [f, new RegExp(`^run-${label}\\.t(\\d+)\\.jsonl$`).exec(f)]) + .filter(([, m]) => m) + .sort((a, b) => Number(a[1][1]) - Number(b[1][1])) + .map(([f]) => join(dir, f)); + return [first, ...rest]; } + +function parse(dir, label) { + const files = segments(dir, label); + if (!files) return null; + const s = parseSession(files); + if (!s.ok) return null; + const o = s.occupancy; + return { + dur: s.dur, tools: s.tools, reads: s.reads, grep: s.grep, cg: s.cg, + tokens: s.processed, cost: s.cost, raced: s.raced, turns: s.turns, + segments: files.length, + ctx: o.ctxFinal, + occCg: o.residual.codegraph, + occFile: o.residualFileAccess, + // The arm's own retrieval residual: codegraph in the with-arm, Read/Grep/Bash + // in the without-arm. Comparing these is the apples-to-apples pair. + occSelf: o.residual.codegraph + o.residualFileAccess, + occShareCtx: o.ctxFinal > 0 ? ((o.residual.codegraph + o.residualFileAccess) / o.ctxFinal) * 100 : 0, + occShareWin: ((o.residual.codegraph + o.residualFileAccess) / o.windowTokens) * 100, + window: o.windowTokens, + }; +} + const median = (arr) => { const v = [...arr].sort((a, b) => a - b); const n = v.length; return n === 0 ? 0 : n % 2 ? v[(n - 1) / 2] : (v[n / 2 - 1] + v[n / 2]) / 2; }; const fmtTime = (s) => s >= 60 ? `${Math.floor(s / 60)}m ${Math.round(s % 60)}s` : `${Math.round(s)}s`; const fmtTok = (t) => t >= 1e6 ? `${(t / 1e6).toFixed(1)}M` : `${Math.round(t / 1000)}k`; const pct = (w, wo) => wo > 0 ? Math.round((1 - w / wo) * 100) : 0; -console.log('repo n(w/wo) time WITH→WITHOUT tools W→WO tokens W→WO (saved) cost W→WO (saved)'); -const savings = { cost: [], tokens: [], time: [], tools: [] }; +// Exclude MCP-cold-start-raced WITH runs by default — they measure a startup +// race, not steady-state value. `CG_INCLUDE_RACED=1` keeps them (to see the raw +// distribution). The WITHOUT arm has no MCP, so it's never raced. +const includeRaced = process.env.CG_INCLUDE_RACED === '1'; +const rows = []; for (const repo of REPOS) { const dir = join(ROOT, repo); - const runDirs = existsSync(dir) ? readdirSync(dir).filter(d => /^run\d+$/.test(d)) : []; - // Exclude MCP-cold-start-raced WITH runs by default — they measure a startup - // race, not steady-state value. `CG_INCLUDE_RACED=1` keeps them (to see the raw - // distribution). The WITHOUT arm has no MCP, so it's never raced. - const includeRaced = process.env.CG_INCLUDE_RACED === '1'; + const runDirs = existsSync(dir) ? readdirSync(dir).filter(d => /^run\d+$/.test(d)).sort() : []; const W = [], WO = []; let racedExcluded = 0; for (const rd of runDirs) { - const w = parse(join(dir, rd, 'run-headless-with.jsonl')); + const w = parse(join(dir, rd), 'headless-with'); if (w) { if (w.raced && !includeRaced) racedExcluded++; else W.push(w); } - const wo = parse(join(dir, rd, 'run-headless-without.jsonl')); if (wo) WO.push(wo); + const wo = parse(join(dir, rd), 'headless-without'); if (wo) WO.push(wo); } + rows.push({ repo, W, WO, racedExcluded }); +} + +// ---- Table 1: the existing throughput view. -------------------------------- +console.log('repo n(w/wo) time WITH→WITHOUT tools W→WO tokens W→WO (saved) cost W→WO (saved)'); +const savings = { cost: [], tokens: [], time: [], tools: [] }; +for (const { repo, W, WO, racedExcluded } of rows) { if (!W.length || !WO.length) { console.log(`${repo.padEnd(11)} (incomplete: w=${W.length} wo=${WO.length})`); continue; } const m = (arr, k) => median(arr.map(x => x[k])); const wT = m(W, 'dur'), woT = m(WO, 'dur'), wTok = m(W, 'tokens'), woTok = m(WO, 'tokens'); @@ -82,3 +98,38 @@ for (const repo of REPOS) { } const avg = (a) => a.length ? Math.round(a.reduce((s, x) => s + x, 0) / a.length) : 0; console.log(`\nAVERAGE saved: cost ${avg(savings.cost)}% · tokens ${avg(savings.tokens)}% · time ${avg(savings.time)}% · tool calls ${avg(savings.tools)}%`); + +// ---- Table 2: residual context occupancy. ---------------------------------- +// WITH's retrieval residual is codegraph's tool output; WITHOUT's is Read + +// Grep/Glob + Bash. Same question, same window — so the pair is comparable. +const anyMulti = rows.some(({ W, WO }) => [...W, ...WO].some(r => r.segments > 1)); +console.log(`\n\nRESIDUAL CONTEXT OCCUPANCY — retrieval tokens still in the window at end of run`); +console.log(`(WITH = codegraph responses · WITHOUT = Read + Grep/Glob + Bash responses)`); +console.log(`${anyMulti ? 'multi-turn sessions' : 'SINGLE-TURN sessions — see the caveat below'}\n`); +console.log('repo turns final ctx W→WO residual W→WO % of ctx W→WO % of window W→WO'); +const occ = { resid: [], shareCtx: [] }; +for (const { repo, W, WO } of rows) { + if (!W.length || !WO.length) { console.log(`${repo.padEnd(11)} (incomplete)`); continue; } + const m = (arr, k) => median(arr.map(x => x[k])); + const wR = m(W, 'occSelf'), woR = m(WO, 'occSelf'); + const wCtx = m(W, 'ctx'), woCtx = m(WO, 'ctx'); + const wSc = m(W, 'occShareCtx'), woSc = m(WO, 'occShareCtx'); + const wSw = m(W, 'occShareWin'), woSw = m(WO, 'occShareWin'); + occ.resid.push(pct(wR, woR)); occ.shareCtx.push(pct(wSc, woSc)); + console.log( + `${repo.padEnd(11)} ${String(median(W.map(x => x.turns)) + '/' + median(WO.map(x => x.turns))).padEnd(7)} ` + + `${(fmtTok(wCtx) + '→' + fmtTok(woCtx)).padEnd(21)}` + + `${(fmtTok(wR) + '→' + fmtTok(woR) + ' (' + pct(wR, woR) + '%)').padEnd(22)}` + + `${(wSc.toFixed(1) + '%→' + woSc.toFixed(1) + '%').padEnd(18)}` + + `${wSw.toFixed(1)}%→${woSw.toFixed(1)}%` + ); +} +console.log(`\nAVERAGE: retrieval residual ${avg(occ.resid)}% lower with codegraph · share-of-context ${avg(occ.shareCtx)}% lower`); +if (!anyMulti) { + console.log( + `\nCAVEAT: every row above is a SINGLE-turn session, so the residual is measured at the\n` + + `moment the one question is answered. Occupancy is a cost that compounds over the turns\n` + + `that FOLLOW; a single-turn number does not settle it. Re-run with "||"-separated\n` + + `follow-ups (see run-all.sh) to measure the regime this metric is actually about.` + ); +} diff --git a/scripts/agent-eval/parse-run.mjs b/scripts/agent-eval/parse-run.mjs index 6d64d58..d227dc3 100644 --- a/scripts/agent-eval/parse-run.mjs +++ b/scripts/agent-eval/parse-run.mjs @@ -1,45 +1,321 @@ #!/usr/bin/env node -// Parse a Claude Code stream-json run log: tool-call sequence + token usage. +// Parse Claude Code stream-json run log(s): tool-call sequence, token usage, and +// RESIDUAL CONTEXT OCCUPANCY — how many tokens of the context window each tool +// family's responses still occupy when the run ends. +// +// Usage: parse-run.mjs [run.t2.jsonl ...] +// Multiple files = one multi-turn session's segments, IN ORDER (run-all.sh +// writes run-