diff --git a/apps/framework/harness/run-eval.ts b/apps/framework/harness/run-eval.ts index aa0c306a..aeda9798 100644 --- a/apps/framework/harness/run-eval.ts +++ b/apps/framework/harness/run-eval.ts @@ -373,6 +373,10 @@ async function runOne( stepCount?: number; toolCallCount: number; agentRunDurationMs: number; + agentRunStartedAt: number; + agentPromptAt?: number; + agentRunEndedAt: number; + scoringEndedAt: number; cliVersion?: string; } > { @@ -456,6 +460,7 @@ async function runOne( timeoutSec: TIMEOUT_SEC, sessionArchivePath: sessionArchivePath(expName, ev.id, runIndex), }); + const agentRunEndedAt = Date.now(); await session.ensureReady?.(); // Exports the workspace so scorers can run host tooling (vite/vitest) against it. // Withheld tests are copied in lazily, only if the scorer asks to run Vitest. @@ -481,6 +486,7 @@ async function runOne( return vitestRun(hostWorkspace); }, }); + const scoringEndedAt = Date.now(); // Runs after scoring so the scorer sees what the agent actually saw, not rehydrated content. await rehydrateTruncatedDocsResults(session.sandbox, run.toolCalls); @@ -503,6 +509,10 @@ async function runOne( stepCount: run.stepCount, toolCallCount: run.toolCalls.length, agentRunDurationMs: run.durationMs, + agentRunStartedAt: run.startedAt, + agentPromptAt: run.promptAt, + agentRunEndedAt, + scoringEndedAt, cliVersion: marker?.cliVersion ?? ev.metadata.cliVersion, }; } @@ -543,12 +553,14 @@ async function runOne( timeoutSec: TIMEOUT_SEC, sessionArchivePath: sessionArchivePath(expName, ev.id, runIndex), }); + const agentRunEndedAt = Date.now(); const last = await (scorer as ToolScorer)({ ...session.scoringContext, toolCalls: run.toolCalls, transcript: run.transcript, agentReport: run.agentReport, }); + const scoringEndedAt = Date.now(); // Runs after scoring so the scorer sees what the agent actually saw, not rehydrated content. if (cliSandbox) @@ -568,6 +580,10 @@ async function runOne( stepCount: run.stepCount, toolCallCount: run.toolCalls.length, agentRunDurationMs: run.durationMs, + agentRunStartedAt: run.startedAt, + agentPromptAt: run.promptAt, + agentRunEndedAt, + scoringEndedAt, // No sandbox in tools mode, so no marker to read; only the frontmatter pin applies. cliVersion: ev.metadata.cliVersion, }; diff --git a/apps/framework/scripts/upload-braintrust.test.ts b/apps/framework/scripts/upload-braintrust.test.ts index ef6cb4ec..38ee128b 100644 --- a/apps/framework/scripts/upload-braintrust.test.ts +++ b/apps/framework/scripts/upload-braintrust.test.ts @@ -128,7 +128,7 @@ function recorder(node: RecordedSpan): SpanSink { } describe('logTranscript', () => { - it('logs back-to-back LLM spans per request, with tool calls as siblings under task', () => { + it('logs back-to-back LLM spans per request, with teardown and score after task', () => { const root: RecordedSpan = { children: [] }; const ms = (s: number) => (100 + s) * 1000; logTranscript(recorder(root), { @@ -138,7 +138,9 @@ describe('logTranscript', () => { passed: true, modelId: 'm', startTime: 100, - endTime: 170, + endTime: 150, + agentEndTime: 140, + scoringEndTime: 150, toolLabels: [], transcript: [ { @@ -230,7 +232,98 @@ describe('logTranscript', () => { input: [prompt, first, skillResult, second, bashResult], } ), - span('passed', 70, 70), + span('teardown', 38, 40), + span('passed', 40, 50), + ]); + }); + + it.each([ + ['recorded prompt', 102, 102], + ['prompt before run start', 98, 100], + ['prompt after first event', 109, 108], + ])('starts task and the first LLM span at the %s', (_, promptTime, at) => { + const root: RecordedSpan = { children: [] }; + logTranscript(recorder(root), { + prompt: 'go', + agentReport: '', + checks: [], + passed: true, + modelId: 'm', + startTime: 100, + endTime: 120, + promptTime, + agentEndTime: 110, + scoringEndTime: 120, + toolLabels: [], + transcript: [ + { type: 'message', role: 'assistant', content: 'a', ts: 108_000 }, + ], + }); + expect( + root.children.map(({ name, start, end }) => [name, start, end]) + ).toEqual([ + ['setup', 100, at], + ['task', at, 108], + ['teardown', 108, 110], + ['passed', 110, 120], + ]); + expect(root.children[1]?.children[0]).toMatchObject({ + name: 'm', + start: at, + end: 108, + }); + }); + + it('ends setup at a leading non-assistant message and starts task there', () => { + const root: RecordedSpan = { children: [] }; + logTranscript(recorder(root), { + prompt: '', + agentReport: '', + checks: [], + passed: false, + startTime: 100, + endTime: 120, + agentEndTime: 110, + scoringEndTime: 120, + toolLabels: [], + transcript: [ + { type: 'message', role: 'system', content: 'init', ts: 103_000 }, + { type: 'message', role: 'assistant', content: 'a', ts: 108_000 }, + ], + }); + expect( + root.children.map(({ name, start, end }) => [name, start, end]) + ).toEqual([ + ['setup', 100, 103], + ['task', 103, 108], + ['teardown', 108, 110], + ['passed', 110, 120], + ]); + expect(root.children[1]?.children.map((c) => c.name)).toEqual([ + 'system', + 'assistant', + ]); + }); + + it('keeps a zero-length score at the run end for results without recorded times', () => { + const root: RecordedSpan = { children: [] }; + logTranscript(recorder(root), { + prompt: '', + agentReport: '', + checks: [], + passed: true, + startTime: 100, + endTime: 170, + toolLabels: [], + transcript: [ + { type: 'message', role: 'assistant', content: 'a', ts: 104_000 }, + ], + }); + expect( + root.children.map(({ name, start, end }) => [name, start, end]) + ).toEqual([ + ['task', 100, 104], + ['passed', 170, 170], ]); }); }); diff --git a/apps/framework/scripts/upload-braintrust.ts b/apps/framework/scripts/upload-braintrust.ts index b0e99576..68859234 100644 --- a/apps/framework/scripts/upload-braintrust.ts +++ b/apps/framework/scripts/upload-braintrust.ts @@ -84,6 +84,11 @@ interface PendingRow { /** Unix seconds. */ startTime?: number; endTime?: number; + /** When the CLI recorded the prompt; absent on older results. */ + promptTime?: number; + /** When `agent.run()` returned and scoring began; absent on older results. */ + agentEndTime?: number; + scoringEndTime?: number; } function git(...args: string[]): string | undefined { @@ -267,11 +272,11 @@ async function collectRows( const durationMs = result.agentRunDurationMs ?? (typeof result.durationMs === 'number' ? result.durationMs : undefined); - // Results record duration but no start time, so derive it from file mtime. const { mtimeMs } = await stat(absolutePath); if (mtimeMs < SINCE) { continue; } + // Older results record only a duration, so derive the window from mtime. const endTime = durationMs ? mtimeMs / 1000 : undefined; const transcript = transcriptSchema.parse(result.transcript); const sessionArchivePath = join( @@ -323,11 +328,19 @@ async function collectRows( ? { tool_call_count: result.toolCallCount } : {}), }, + promptTime: sec(result.agentPromptAt), + agentEndTime: sec(result.agentRunEndedAt), + scoringEndTime: sec(result.scoringEndedAt), ...runWindow( transcript, - endTime && durationMs - ? { startTime: endTime - durationMs / 1000, endTime } - : {} + result.agentRunStartedAt && result.scoringEndedAt + ? { + startTime: result.agentRunStartedAt / 1000, + endTime: result.scoringEndedAt / 1000, + } + : endTime && durationMs + ? { startTime: endTime - durationMs / 1000, endTime } + : {} ), }; @@ -339,8 +352,10 @@ async function collectRows( } /** - * Widens the mtime-derived window to cover transcript timestamps, since mtime - * lands after scoring and the agent clock can drift from the host's. + * Widens the run window to cover transcript timestamps, since the mtime + * fallback lands after scoring. Transcript times come from the sandbox clock, + * which Docker shares with the host (<300ms apart on Docker Desktop), so skew + * is absorbed by widening and clamping rather than corrected. */ function runWindow( transcript: TranscriptPart[], @@ -385,15 +400,21 @@ export interface SpanSink { * generation time as a gap. Their Codex translator does what we do. * https://github.com/braintrustdata/braintrust-coding-agent-plugins/blob/c0346dcdb16ae9f136b3abf83efb6458191f9300/bt-daemon/src/translate/codex.rs#L929-L932 * - * task 0s → 38s - * ├─ llm (text + Skill) 0s → 4s - * ├─ Skill 4s → 5s - * ├─ llm (Bash only) 5s → 8s - * ├─ Bash 8s → 31s - * └─ llm (text) 31s → 38s + * eval 0s → 50s + * ├─ setup 0s → 2s CLI boot until it records the prompt + * ├─ task 2s → 38s + * │ ├─ llm (text + Skill) 2s → 4s + * │ ├─ Skill 4s → 5s + * │ ├─ llm (Bash only) 5s → 8s + * │ ├─ Bash 8s → 31s + * │ └─ llm (text) 31s → 38s + * ├─ teardown 38s → 40s CLI exit until `agent.run()` returns + * └─ passed (score) 40s → 50s workspace export, checks, judges * - * Parts without a `requestId` each get their own LLM span. Transcripts without - * timestamps collapse every span to the run start. + * Without a prompt time or a leading non-assistant message there is no setup + * span, and the first LLM span starts at the run start. Parts without a + * `requestId` each get their own LLM span. Transcripts without timestamps + * collapse every span to the run start. */ export function logTranscript( parent: SpanSink, @@ -409,16 +430,42 @@ export function logTranscript( | 'toolLabels' | 'startTime' | 'endTime' + | 'promptTime' + | 'agentEndTime' + | 'scoringEndTime' > ): void { - const sec = (ms: number | undefined) => (ms ? ms / 1000 : undefined); + const [first] = row.transcript; + const promptTime = + row.promptTime ?? + (first?.type === 'message' && first.role !== 'assistant' + ? sec(first.ts) + : undefined); + const firstTime = sec(row.transcript.find((part) => part.ts)?.ts); + // The prompt time is on the sandbox clock, so keep it inside the run. + const setupEnd = + promptTime === undefined + ? undefined + : Math.min( + Math.max(row.startTime ?? promptTime, promptTime), + firstTime ?? Infinity + ); + if (row.startTime !== undefined && setupEnd !== undefined) { + const setup = parent.startSpan({ + name: 'setup', + type: 'task', + startTime: row.startTime, + }); + setup.end({ endTime: setupEnd }); + } + const taskStart = setupEnd ?? row.startTime; const task = parent.startSpan({ name: 'task', type: 'task', - startTime: row.startTime, + startTime: taskStart, }); task.log({ input: row.prompt, output: row.agentReport }); - let latestTime = row.startTime; + let latestTime = taskStart; let toolIndex = 0; // Seeded with the prompt, which the transcript omits. const history: Record[] = row.prompt @@ -548,17 +595,31 @@ export function logTranscript( } task.end({ endTime: latestTime }); - const scoredAt = row.endTime ?? latestTime; + const agentEnd = latest(latestTime, row.agentEndTime); + if (row.agentEndTime !== undefined) { + const teardown = parent.startSpan({ + name: 'teardown', + type: 'task', + startTime: latestTime, + }); + teardown.end({ endTime: agentEnd }); + } + const scoreStart = + row.agentEndTime === undefined ? (row.endTime ?? latestTime) : agentEnd; const scorer = parent.startSpan({ name: 'passed', type: 'score', - startTime: scoredAt, + startTime: scoreStart, }); scorer.log({ output: row.checks, scores: { passed: row.passed ? 1 : 0 }, }); - scorer.end({ endTime: scoredAt }); + scorer.end({ endTime: latest(scoreStart, row.scoringEndTime) }); +} + +function sec(ms: number | undefined) { + return ms ? ms / 1000 : undefined; } function latest(a: number | undefined, b: number | undefined) { diff --git a/packages/core/src/agents/claude-code/parser.test.ts b/packages/core/src/agents/claude-code/parser.test.ts index 7dd0e95d..9db0115c 100644 --- a/packages/core/src/agents/claude-code/parser.test.ts +++ b/packages/core/src/agents/claude-code/parser.test.ts @@ -1,5 +1,9 @@ import { describe, expect, it } from 'vitest'; -import { claudeCodeParser, sessionRequestUsage } from './parser.js'; +import { + claudeCodeParser, + sessionPromptAt, + sessionRequestUsage, +} from './parser.js'; import { adaptTranscript } from '../../parsers/adapt.js'; /** A representative Claude Code `--print` JSONL session. */ @@ -277,3 +281,16 @@ describe('sessionRequestUsage', () => { ); }); }); + +describe('sessionPromptAt', () => { + it('returns the first user record time, skipping queue records', () => { + const jsonl = [ + { type: 'queue-operation', timestamp: '2026-09-30T20:31:32.391Z' }, + { type: 'user', timestamp: '2026-09-30T20:31:34.374Z' }, + { type: 'user', timestamp: '2026-09-30T20:31:40.000Z' }, + ] + .map((r) => JSON.stringify(r)) + .join('\n'); + expect(sessionPromptAt(jsonl)).toBe(Date.parse('2026-09-30T20:31:34.374Z')); + }); +}); diff --git a/packages/core/src/agents/claude-code/parser.ts b/packages/core/src/agents/claude-code/parser.ts index cac6a784..b07f26c0 100644 --- a/packages/core/src/agents/claude-code/parser.ts +++ b/packages/core/src/agents/claude-code/parser.ts @@ -225,6 +225,14 @@ export function sessionRequestUsage(jsonl: string): Map { return byRequest; } +/** When the session recorded its first user record, in epoch ms. */ +export function sessionPromptAt(jsonl: string): number | undefined { + const prompt = parseJsonlRecords(jsonl).records.find( + (record) => record.type === 'user' && typeof record.timestamp === 'string' + ); + return prompt ? Date.parse(String(prompt.timestamp)) : undefined; +} + function recordToEvents(data: Record): TranscriptEvent[] { const events: TranscriptEvent[] = []; const timestamp = diff --git a/packages/core/src/agents/claude-code/runner.ts b/packages/core/src/agents/claude-code/runner.ts index 9246aed0..dd37dbf6 100644 --- a/packages/core/src/agents/claude-code/runner.ts +++ b/packages/core/src/agents/claude-code/runner.ts @@ -8,7 +8,7 @@ import type { Model as AnthropicModel } from '@anthropic-ai/sdk/resources/messag import type { McpServerConfig } from '../../index.js'; import { isRecord, parseJsonlRecords } from '../../json.js'; import type { AgentRunner } from '../types.js'; -import { sessionRequestUsage } from './parser.js'; +import { sessionPromptAt, sessionRequestUsage } from './parser.js'; import { npmGlobalBin, npmInstallGlobal, @@ -38,6 +38,7 @@ export const claudeCodeRunner: AgentRunner = { const request = event.requestId && usage.get(event.requestId); if (request) event.usage = request; } + return { promptAt: sessionPromptAt(session.stdout) }; }, async install(sandbox, version) { diff --git a/packages/core/src/agents/codex/parser.test.ts b/packages/core/src/agents/codex/parser.test.ts index d975a6e8..416098b0 100644 --- a/packages/core/src/agents/codex/parser.test.ts +++ b/packages/core/src/agents/codex/parser.test.ts @@ -472,6 +472,24 @@ describe('enrichFromRollout', () => { ['', 't3', 'r2'], ]); }); + + it('returns the first user message time as the prompt time', () => { + const line = (timestamp: string, role: string) => + JSON.stringify({ + timestamp, + type: 'response_item', + payload: { type: 'message', role }, + }); + const rollout = [ + line('2026-10-01T17:43:08.454Z', 'developer'), + line('2026-10-01T17:43:08.454Z', 'user'), + line('2026-10-01T17:43:08.473Z', 'user'), + line('2026-10-01T17:43:18.250Z', 'assistant'), + ].join('\n'); + expect(enrichFromRollout([], rollout)).toBe( + Date.parse('2026-10-01T17:43:08.454Z') + ); + }); }); describe('enrichFromRollout tool pairing', () => { diff --git a/packages/core/src/agents/codex/parser.ts b/packages/core/src/agents/codex/parser.ts index 2319093a..d9e8842b 100644 --- a/packages/core/src/agents/codex/parser.ts +++ b/packages/core/src/agents/codex/parser.ts @@ -274,11 +274,13 @@ const ROLLOUT_TOOL_ITEMS = new Set([ * rollout: reasoning → message → function_call(c1) → token_usage_record(r1) * → function_call_output(c1) * events: message → tool_call → tool_result, each tagged requestId r1 + * + * Returns when the rollout recorded the first user message, in epoch ms. */ export function enrichFromRollout( events: TranscriptEvent[], rollout: string -): void { +): number | undefined { interface Request { id?: string; usage?: RequestUsage; @@ -291,6 +293,7 @@ export function enrichFromRollout( const toolItems: Record[] = []; const requests: { at?: string; request: Request }[] = []; let open: Request | undefined; + let promptAt: number | undefined; for (const record of parseJsonlRecords(rollout).records) { const at = str(record.timestamp); @@ -310,7 +313,10 @@ export function enrichFromRollout( if (callId) callEnds.set(callId, at); continue; } - if (payload.type === 'message' && payload.role !== 'assistant') continue; + if (payload.type === 'message' && payload.role !== 'assistant') { + if (payload.role === 'user' && at) promptAt ??= Date.parse(at); + continue; + } open ??= {}; if (payload.type === 'message') messages.push({ at, request: open }); if (callId) callStarts.set(callId, { at, request: open }); @@ -377,6 +383,7 @@ export function enrichFromRollout( const next = events.findIndex((e) => at && e.timestamp && e.timestamp > at); events.splice(next === -1 ? events.length : next, 0, silent); } + return promptAt; } /** diff --git a/packages/core/src/agents/codex/runner.ts b/packages/core/src/agents/codex/runner.ts index 7fabe2bd..0986fceb 100644 --- a/packages/core/src/agents/codex/runner.ts +++ b/packages/core/src/agents/codex/runner.ts @@ -108,10 +108,10 @@ export const codexRunner: AgentRunner = { `cat "$(ls -t "$HOME"/.codex/sessions/*/*/*/rollout-*.jsonl 2>/dev/null | head -1)"` ); if (!rollout.ok) return; - enrichFromRollout(events, rollout.stdout); + const promptAt = enrichFromRollout(events, rollout.stdout); // The --json stream has no per-response boundary, but the rollout logs one // token_count event per model response. - return { stepCount: countModelResponses(rollout.stdout) }; + return { stepCount: countModelResponses(rollout.stdout), promptAt }; }, deriveStopReason(raw, command) { diff --git a/packages/core/src/agents/engine.test.ts b/packages/core/src/agents/engine.test.ts index 85395f2f..1415763c 100644 --- a/packages/core/src/agents/engine.test.ts +++ b/packages/core/src/agents/engine.test.ts @@ -12,7 +12,7 @@ import { join } from 'node:path'; import { afterEach, beforeEach, describe, expect, it } from 'vitest'; import type { CommandResult } from '../index.js'; import type { AgentTranscriptParser } from '../parsers/types.js'; -import { createCliAgent } from './engine.js'; +import { createCliAgent, taskDurationMs } from './engine.js'; import { USER_PROMPT_PATH } from './shared.js'; import type { AgentRunner } from './types.js'; @@ -168,3 +168,69 @@ describe('createCliAgent session archive', () => { expect(existsSync(sessionArchivePath)).toBe(false); }); }); + +describe('taskDurationMs', () => { + const transcript = [ + { + type: 'message' as const, + role: 'assistant' as const, + content: 'a', + ts: 1_500, + }, + { + type: 'tool_call' as const, + name: 'Bash', + input: {}, + ts: 2_000, + resultTs: 9_000, + }, + { + type: 'message' as const, + role: 'assistant' as const, + content: 'b', + ts: 8_000, + }, + ]; + + it('spans the prompt to the latest event, including tool results', () => { + expect(taskDurationMs(transcript, 1_000)).toBe(8_000); + }); + + it('is undefined without a prompt time or event times', () => { + expect(taskDurationMs(transcript, undefined)).toBeUndefined(); + expect( + taskDurationMs( + [{ type: 'message', role: 'assistant', content: 'a' }], + 1_000 + ) + ).toBeUndefined(); + }); + + it('reports 0 for a run whose task time is unknown', async () => { + process.env[API_KEY_ENV_VAR] = 'k'; + const runner: AgentRunner = { + id: 'claude-code', + displayName: 'Fake CLI', + apiKeyEnvVar: API_KEY_ENV_VAR, + cliPackage: 'fake-cli', + defaultCliVersion: '1.0.0', + defaultModel: 'fake-model', + install: async () => {}, + exec: async () => ({ command: ok, raw: 'x' }), + }; + const run = await createCliAgent(runner, parser, { + model: 'fake-model', + }).run({ + systemPrompt: '', + userPrompt: 'the task', + timeoutSec: 1, + sandbox: { + workspace: '/w', + exec: async () => ok, + readFile: async () => '', + copyToHost: async () => {}, + }, + }); + expect(run.durationMs).toBe(0); + }); +}); diff --git a/packages/core/src/agents/engine.ts b/packages/core/src/agents/engine.ts index 742570c6..acf73d61 100644 --- a/packages/core/src/agents/engine.ts +++ b/packages/core/src/agents/engine.ts @@ -21,7 +21,7 @@ import { rmSync } from 'node:fs'; import { basename, dirname } from 'node:path'; -import type { AgentHarness, AgentRunResult } from '../index.js'; +import type { AgentHarness, AgentRunResult, TranscriptPart } from '../index.js'; import type { ModelProvider, ReasoningEffortLevel } from '../eval-metadata.js'; import { adaptTranscript } from '../parsers/adapt.js'; import type { AgentTranscriptParser } from '../parsers/types.js'; @@ -121,8 +121,6 @@ export function createCliAgent( reasoningEffort: options.reasoningEffort, timeoutSec: args.timeoutSec, }); - const durationMs = Date.now() - start; - const { events } = raw ? parser.parseTranscript(raw, { mcpServerNames: Object.keys(args.mcpServers ?? {}), @@ -176,12 +174,31 @@ export function createCliAgent( stepCount: (enriched ? enriched.stepCount : undefined) ?? runner.extractStepCount?.(raw), - durationMs, + // 0 when the task's time is unknown or it never ran. + durationMs: taskDurationMs(adapted.transcript, enriched?.promptAt) ?? 0, + startedAt: start, + promptAt: enriched ? enriched.promptAt : undefined, }; }, }; } +/** + * Time from the prompt to the last transcript event, the same window as the + * `task` span. Both ends come from the sandbox clock. + */ +export function taskDurationMs( + transcript: TranscriptPart[], + promptAt: number | undefined +): number | undefined { + const times = transcript.flatMap((part) => [ + part.ts ?? 0, + part.type === 'tool_call' ? (part.resultTs ?? 0) : 0, + ]); + const lastAt = Math.max(0, ...times); + return promptAt && lastAt > promptAt ? lastAt - promptAt : undefined; +} + function requireApiKey(runner: AgentRunner): string { return requireEnv( runner.apiKeyEnvVar, diff --git a/packages/core/src/agents/grok/parser.test.ts b/packages/core/src/agents/grok/parser.test.ts index 725e44b7..279a57ae 100644 --- a/packages/core/src/agents/grok/parser.test.ts +++ b/packages/core/src/agents/grok/parser.test.ts @@ -463,4 +463,17 @@ describe('grok request timing and usage', () => { outputTokens: 1, }); }); + + it('returns the first user prompt time', () => { + const update = (ms: number, sessionUpdate: string) => + JSON.stringify({ + params: { _meta: { agentTimestampMs: ms }, update: { sessionUpdate } }, + }); + const updates = [ + update(1000, 'user_message_chunk'), + update(1100, 'user_message_chunk'), + update(4000, 'agent_message_chunk'), + ].join('\n'); + expect(enrichFromUpdates([], updates)).toBe(1000); + }); }); diff --git a/packages/core/src/agents/grok/parser.ts b/packages/core/src/agents/grok/parser.ts index b7b223a8..e5ef9e64 100644 --- a/packages/core/src/agents/grok/parser.ts +++ b/packages/core/src/agents/grok/parser.ts @@ -245,15 +245,17 @@ function stepUsage(usage: unknown): RequestUsage | undefined { * Fills in event times from the session's `updates.jsonl`, which the stdout * stream lacks. Tool calls match by `toolCallId`. Assistant messages pair by * position with runs of `agent_message_chunk`, and take the run's last time. + * Returns when the first user prompt was recorded, in epoch ms. */ export function enrichFromUpdates( events: TranscriptEvent[], updates: string -): void { +): number | undefined { const callStarts = new Map(); const callEnds = new Map(); const messageEnds: number[] = []; let inMessage = false; + let promptAt: number | undefined; for (const record of parseJsonlRecords(updates).records) { const params = isRecord(record.params) ? record.params : {}; const meta = isRecord(params._meta) ? params._meta : {}; @@ -261,6 +263,7 @@ export function enrichFromUpdates( const at = Number(meta.agentTimestampMs) || undefined; const kind = update.sessionUpdate; const id = str(update.toolCallId); + if (kind === 'user_message_chunk') promptAt ??= at; if (kind === 'agent_message_chunk') { if (!inMessage) messageEnds.push(0); if (at) messageEnds[messageEnds.length - 1] = at; @@ -289,10 +292,11 @@ export function enrichFromUpdates( const messages = events.filter( (e) => e.type === 'message' && e.role === 'assistant' ); - if (messages.length !== messageEnds.length) return; + if (messages.length !== messageEnds.length) return promptAt; messages.forEach((event, i) => { event.timestamp = iso(messageEnds[i]) ?? event.timestamp; }); + return promptAt; } export const grokParser: AgentTranscriptParser = { diff --git a/packages/core/src/agents/grok/runner.ts b/packages/core/src/agents/grok/runner.ts index 38e5275a..b0e8c728 100644 --- a/packages/core/src/agents/grok/runner.ts +++ b/packages/core/src/agents/grok/runner.ts @@ -60,7 +60,8 @@ export const grokRunner: AgentRunner = { const updates = await sandbox.exec( `cat ${this.sessionDir}/*/*/updates.jsonl` ); - if (updates.ok) enrichFromUpdates(events, updates.stdout); + if (!updates.ok) return; + return { promptAt: enrichFromUpdates(events, updates.stdout) }; }, async install(sandbox, version, apiKey) { diff --git a/packages/core/src/agents/opencode/runner.ts b/packages/core/src/agents/opencode/runner.ts index e1b68369..1ac0c01e 100644 --- a/packages/core/src/agents/opencode/runner.ts +++ b/packages/core/src/agents/opencode/runner.ts @@ -111,6 +111,19 @@ export function createOpencodeRunner( ); }, + // stdout has no user message record, so read its time from the session db. + async enrichEvents(sandbox) { + const script = `const { DatabaseSync } = require('node:sqlite'); +const db = new DatabaseSync(process.env.HOME + '/.local/share/opencode/opencode.db'); +const row = db.prepare("select min(json_extract(data, '$.time.created')) as t from message where json_extract(data, '$.role') = 'user'").get(); +console.log(row?.t ?? '');`; + const out = await sandbox.exec( + `node --no-warnings -e ${shellQuote(script)}` + ); + if (!out.ok) return; + return { promptAt: Number(out.stdout.trim()) || undefined }; + }, + async exec({ sandbox, model, diff --git a/packages/core/src/agents/types.ts b/packages/core/src/agents/types.ts index de42c50f..c518ab76 100644 --- a/packages/core/src/agents/types.ts +++ b/packages/core/src/agents/types.ts @@ -121,12 +121,13 @@ export interface AgentRunner { sessionDir?: string; /** * Fills in event `timestamp`, `requestId`, and `usage` from the CLI's session - * files, since stdout lacks them. Returns `stepCount` if the files have it. + * files, since stdout lacks them. Returns `stepCount` if the files have it, + * and `promptAt`, the epoch ms the CLI recorded the user prompt. */ enrichEvents?( sandbox: AgentSandbox, events: TranscriptEvent[] - ): Promise<{ stepCount?: number } | void>; + ): Promise<{ stepCount?: number; promptAt?: number } | void>; } /** diff --git a/packages/core/src/eval-metadata.ts b/packages/core/src/eval-metadata.ts index d3078052..e2eca869 100644 --- a/packages/core/src/eval-metadata.ts +++ b/packages/core/src/eval-metadata.ts @@ -422,8 +422,15 @@ const evalResultShape = { // stepCount 5, toolCallCount 3 stepCount: z.number().optional(), toolCallCount: z.number().optional(), - // Wall-clock time of the agent run only. Sandbox boot and scoring are excluded. + // Agent time only, from the prompt to the last transcript event (the `task` + // span). 0 when that time is unknown or the task never ran. agentRunDurationMs: z.number().optional(), + // Host epoch ms. The run ends when `agent.run()` returns; scoring starts then. + agentRunStartedAt: z.number().optional(), + // When the CLI recorded the prompt, from its session files (sandbox clock). + agentPromptAt: z.number().optional(), + agentRunEndedAt: z.number().optional(), + scoringEndedAt: z.number().optional(), sandboxUsage: sandboxUsageSchema.optional(), }; diff --git a/packages/core/src/index.ts b/packages/core/src/index.ts index d11edfbf..77af9646 100644 --- a/packages/core/src/index.ts +++ b/packages/core/src/index.ts @@ -455,7 +455,12 @@ export type AgentRunResult = { stoppedReason: string; usage?: AgentUsage; stepCount?: number; + /** Task time, prompt to last transcript event; see `agentRunDurationMs`. */ durationMs: number; + /** Host epoch ms the agent process or model loop started. */ + startedAt: number; + /** Epoch ms the CLI recorded the user prompt, from its session files. */ + promptAt?: number; }; export type AgentHarness = { @@ -882,6 +887,7 @@ export function aiSdkAgent(options: { usage, stepCount: result.steps.length, durationMs: Date.now() - start, + startedAt: start, }; } finally { await closeMcpHandles(mcpHandles);