mirror of
https://github.com/nexu-io/open-design.git
synced 2026-09-20 06:15:06 +08:00
ccfdc50929
* feat(analytics): measure first-call cache hit + is_followup_turn on run_finished
Instrumentation-first (telemetry before optimization) for the session-reuse
work: ship a v0.12.0 baseline that measures the cache-hit rate of the FIRST
model call of each turn, then compare it against the post-optimization release.
Why first-call: the existing run_finished usage scan is a REVERSE scan that
takes the LAST usage event of the turn. Within a turn, every call after the
first re-reads the growing prefix, so the last/aggregate cache-hit ratio is
high regardless of whether the session was reused — it masks the signal. The
session-reuse win shows up only on the OPENING call of a follow-up turn.
- scanRunEventsForUsageAnalytics now also forward-scans for the first usage
event and emits first_call_input_tokens / first_call_cache_read_input_tokens
/ first_call_cache_hit_ratio (anthropic vs openai cache accounting mirrored
from the existing last-call path). The group is gated on a real first-call
input so cache-only alias payloads don't emit a dangling cache_read.
- run_finished carries is_followup_turn (a prior completed assistant turn
exists) so first_call_cache_hit_ratio can be sliced to the turns where
session reuse actually applies.
- The first-call fields are reliable only for per-call-usage agents
(claude / opencode / codebuddy / pi). codex reports a single cumulative
turn.completed usage, so its first stream event is the whole-session
aggregate, not the opening call — gated out of the stream path here; its
per-call number must come from the rollout last_token_usage (follow-up).
* feat(analytics): recover codex first-call cache hit from the rollout
Completes the first-call cache-hit telemetry for codex. codex emits only a
cumulative `turn.completed` usage on the exec/json stream the daemon consumes,
so the stream cannot reveal the cache-hit of a turn's OPENING model call — the
number that moves when a session is reused. codex does record per-call usage in
its rollout JSONL (`token_count.info.last_token_usage`), so we read it there.
- codex-rollout-usage.ts: pure `extractCodexLastTurnFirstCallUsage` takes the
first `token_count` after the last `task_started` (the turn the daemon just
finished), skipping zero-input placeholder calls. Validated against real
codex 0.133.0 rollouts: a warm resume turn reads ~95-96% cache hit, a cold
open ~15-18% — the exact baseline-vs-optimized signal. `readCodexRolloutFirstCall`
locates the rollout best-effort (newest-first walk of
`$CODEX_HOME/sessions/**/rollout-*-<thread_id>.jsonl`) and never throws.
- json-event-stream.ts surfaces codex's `thread.started` thread_id on the same
`sessionId` status channel claude uses, so run_finished can find the rollout
(and a future native-resume path can reuse it). `codexSessionIdFromRunEvents`
recovers it from the stored run events.
- run_finished now resolves first-call usage per agent: codex from the rollout,
every other agent from the stream forward-scan, behind one `firstCallUsage`
object. CODEX_HOME comes from the drift-proof `spawnEnvForAgent('codex')`
resolver so it honors sandbox relocation.
* fix(analytics): default codex rollout home to ~/.codex when CODEX_HOME unset
End-to-end testing through a real daemon surfaced this: codex's first-call
fields were silently dropped on every non-sandboxed run. The daemon only sets
CODEX_HOME when sandbox mode relocates it; with sandbox off, `spawnEnvForAgent`
returns an empty CODEX_HOME, codex itself falls back to ~/.codex and writes the
rollout there — but readCodexRolloutFirstCall bailed on the empty value instead
of mirroring codex's `$CODEX_HOME || ~/.codex` resolution.
Verified against a real daemon-driven codex run: the emitted run_finished now
carries first_call_input_tokens / first_call_cache_read_input_tokens /
first_call_cache_hit_ratio alongside is_followup_turn. Adds hermetic tests for
the locate-and-read layer (plant a rollout under <home>/sessions/.../, read it
back by session id) which previously had only the pure extractor covered.
* fix(analytics): harden first-call telemetry per release-readiness review
Adversarial review of the first-call cache-hit telemetry before a release
cherry-pick surfaced four fixable items; all are read-only/additive and keep
the feature best-effort:
- Contain throws in the codex run_finished branch. spawnEnvForAgent /
agentCliEnvForAgent ran outside any local guard, so a throw there bubbled to
the outer run_finished `.catch` and would have dropped the ENTIRE completion
event for that run (not just the codex first-call fields). Wrap them so a
failure degrades to "no first-call fields".
- Match the anthropic first-call denominator to the last-call one: include
cache_creation_input_tokens in the effective-input sum. Previously first-call
omitted it, skewing the very cross-turn comparison the metric exists for.
Added a regression test with non-zero cache_creation.
- Bound the codex rollout locator. On a miss (session captured but file
relocated/deleted) it walked the user's entire codex history; cap the scan to
the newest few day-dirs since the run's own rollout is always recent.
- Declare first_call_* and is_followup_turn on RunFinishedProps in
packages/contracts so the analytics shape is typed at the boundary.
* refactor(analytics): share one cache-token extraction for first/last-call
Review follow-up: the first-call cache-creation extraction only matched two of
the aliases the last-call path accepts (it missed cache_write_input_tokens,
cache_creation_tokens, and nested cache_creation.input_tokens), so a provider
emitting one of those on the opening usage event would compute
first_call_cache_hit_ratio with too small a denominator and overstate the cache
hit — the exact baseline metric this PR adds.
Extract one `extractUsageCacheFields` helper carrying the full provider alias
matrix and route BOTH the last-call reverse scan and the first-call forward
scan through it, so the two effective-input denominators can never drift. Adds
a fixture using the nested `cache_creation.input_tokens` alias to lock it.
170 lines
6.5 KiB
TypeScript
170 lines
6.5 KiB
TypeScript
import { mkdtempSync, mkdirSync, writeFileSync } from 'node:fs';
|
||
import { tmpdir } from 'node:os';
|
||
import path from 'node:path';
|
||
import { describe, expect, it } from 'vitest';
|
||
|
||
import {
|
||
codexSessionIdFromRunEvents,
|
||
extractCodexLastTurnFirstCallUsage,
|
||
readCodexRolloutFirstCall,
|
||
} from '../src/codex-rollout-usage.js';
|
||
|
||
// Shapes mirror real codex 0.133.0 rollout JSONL (`~/.codex/sessions/**/rollout-*.jsonl`):
|
||
// each turn opens with a `task_started` event_msg, and every model call emits a
|
||
// `token_count` event_msg whose `info.last_token_usage` is that single call's
|
||
// usage (OpenAI-style: input_tokens INCLUDES the cached_input_tokens subset).
|
||
function taskStarted(): string {
|
||
return JSON.stringify({ type: 'event_msg', payload: { type: 'task_started' } });
|
||
}
|
||
function tokenCount(input: number | null, cached: number | null): string {
|
||
return JSON.stringify({
|
||
type: 'event_msg',
|
||
payload: {
|
||
type: 'token_count',
|
||
info:
|
||
input === null
|
||
? { last_token_usage: null }
|
||
: { last_token_usage: { input_tokens: input, cached_input_tokens: cached } },
|
||
},
|
||
});
|
||
}
|
||
|
||
describe('extractCodexLastTurnFirstCallUsage', () => {
|
||
it('reports the first call of the LAST turn, not the whole-session aggregate', () => {
|
||
// Real numbers from a 3-turn session: turn-1 is a cold open (18.5%), turn-2
|
||
// a warm resume (96.2%). The daemon just finished turn-3 (95%).
|
||
const rollout = [
|
||
taskStarted(),
|
||
tokenCount(13137, 2432), // turn-1 first call
|
||
tokenCount(13160, 2560), // within-turn-1 follow-up — must be ignored
|
||
taskStarted(),
|
||
tokenCount(13171, 12672), // turn-2 first call (the 96% spec number)
|
||
taskStarted(),
|
||
tokenCount(13342, 12672), // turn-3 first call — this is what we want
|
||
tokenCount(20000, 18000), // within-turn-3 follow-up — must be ignored
|
||
].join('\n');
|
||
|
||
const result = extractCodexLastTurnFirstCallUsage(rollout);
|
||
expect(result).toEqual({
|
||
first_call_input_tokens: 13342,
|
||
first_call_cache_read_input_tokens: 12672,
|
||
first_call_cache_hit_ratio: 12672 / 13342,
|
||
});
|
||
});
|
||
|
||
it('skips zero-input placeholder calls and uses the turn’s real first call', () => {
|
||
const rollout = [
|
||
taskStarted(),
|
||
tokenCount(0, 0), // interrupted/placeholder call — no usable ratio
|
||
tokenCount(40318, 15744), // the turn’s real opening call
|
||
].join('\n');
|
||
|
||
const result = extractCodexLastTurnFirstCallUsage(rollout);
|
||
expect(result?.first_call_input_tokens).toBe(40318);
|
||
expect(result?.first_call_cache_hit_ratio).toBeCloseTo(15744 / 40318);
|
||
});
|
||
|
||
it('treats a missing cached subset as a zero cache hit on a cold open', () => {
|
||
const rollout = [taskStarted(), tokenCount(15761, null)].join('\n');
|
||
const result = extractCodexLastTurnFirstCallUsage(rollout);
|
||
expect(result).toEqual({
|
||
first_call_input_tokens: 15761,
|
||
first_call_cache_read_input_tokens: 0,
|
||
first_call_cache_hit_ratio: 0,
|
||
});
|
||
});
|
||
|
||
it('returns null when the last turn produced no usable token_count yet', () => {
|
||
const rollout = [
|
||
taskStarted(),
|
||
tokenCount(13171, 12672),
|
||
taskStarted(), // a fresh turn opened but no call has landed
|
||
tokenCount(null, null),
|
||
].join('\n');
|
||
expect(extractCodexLastTurnFirstCallUsage(rollout)).toBeNull();
|
||
});
|
||
|
||
it('tolerates blank lines and non-JSON noise without throwing', () => {
|
||
const rollout = ['', 'not json', taskStarted(), ' ', tokenCount(13342, 12672)].join('\n');
|
||
const result = extractCodexLastTurnFirstCallUsage(rollout);
|
||
expect(result?.first_call_cache_hit_ratio).toBeCloseTo(12672 / 13342);
|
||
});
|
||
});
|
||
|
||
describe('codexSessionIdFromRunEvents', () => {
|
||
const statusEvent = (extra: Record<string, unknown>) => ({
|
||
event: 'agent',
|
||
data: { type: 'status', label: 'initializing', ...extra },
|
||
});
|
||
|
||
it('returns the thread id from the initializing status event', () => {
|
||
const events = [
|
||
statusEvent({ sessionId: '019eef4f-7409-7c82-bebe-30504eed3959' }),
|
||
{ event: 'agent', data: { type: 'status', label: 'thinking' } },
|
||
];
|
||
expect(codexSessionIdFromRunEvents(events)).toBe(
|
||
'019eef4f-7409-7c82-bebe-30504eed3959',
|
||
);
|
||
});
|
||
|
||
it('ignores status events without a session id and non-status events', () => {
|
||
const events = [
|
||
{ event: 'agent', data: { type: 'usage', usage: { input_tokens: 1 } } },
|
||
statusEvent({ label: 'thinking' }),
|
||
];
|
||
expect(codexSessionIdFromRunEvents(events)).toBeNull();
|
||
});
|
||
|
||
it('returns null for malformed input', () => {
|
||
expect(codexSessionIdFromRunEvents(null)).toBeNull();
|
||
expect(codexSessionIdFromRunEvents('nope')).toBeNull();
|
||
expect(codexSessionIdFromRunEvents([{ event: 'agent' }, 42])).toBeNull();
|
||
});
|
||
});
|
||
|
||
describe('readCodexRolloutFirstCall', () => {
|
||
// Plants a rollout under <home>/sessions/<y>/<m>/<d>/ exactly as codex names
|
||
// them, so the locate-and-read layer is covered (not just the pure extractor).
|
||
function plantRollout(sessionId: string, lines: string[]): string {
|
||
const home = mkdtempSync(path.join(tmpdir(), 'codex-home-'));
|
||
const dayDir = path.join(home, 'sessions', '2026', '06', '24');
|
||
mkdirSync(dayDir, { recursive: true });
|
||
writeFileSync(
|
||
path.join(dayDir, `rollout-2026-06-24T12-00-00-${sessionId}.jsonl`),
|
||
lines.join('\n'),
|
||
);
|
||
return home;
|
||
}
|
||
const rollout = (sid: string) => [
|
||
JSON.stringify({ type: 'event_msg', payload: { type: 'task_started' } }),
|
||
JSON.stringify({
|
||
type: 'event_msg',
|
||
payload: {
|
||
type: 'token_count',
|
||
info: { last_token_usage: { input_tokens: 13342, cached_input_tokens: 12672 } },
|
||
},
|
||
}),
|
||
];
|
||
|
||
it('locates the rollout by session id under CODEX_HOME and extracts first-call', async () => {
|
||
const sid = '019eef4f-7409-7c82-bebe-30504eed3959';
|
||
const home = plantRollout(sid, rollout(sid));
|
||
const result = await readCodexRolloutFirstCall({ codexHome: home, sessionId: sid });
|
||
expect(result?.first_call_input_tokens).toBe(13342);
|
||
expect(result?.first_call_cache_hit_ratio).toBeCloseTo(12672 / 13342);
|
||
});
|
||
|
||
it('returns null (never throws) when the session id has no matching rollout', async () => {
|
||
const home = plantRollout('some-other-session', rollout('some-other-session'));
|
||
await expect(
|
||
readCodexRolloutFirstCall({ codexHome: home, sessionId: 'missing-session' }),
|
||
).resolves.toBeNull();
|
||
});
|
||
|
||
it('returns null when no session id is given', async () => {
|
||
await expect(
|
||
readCodexRolloutFirstCall({ codexHome: '/nonexistent', sessionId: null }),
|
||
).resolves.toBeNull();
|
||
});
|
||
});
|