From 8faf232267a2da1391a2367fa9ab8330da67e8cb Mon Sep 17 00:00:00 2001 From: Youngeun Kwon Date: Tue, 28 Jul 2026 12:15:03 -0700 Subject: [PATCH 01/10] feat(bench): record precise SWE rollout metrics Signed-off-by: Youngeun Kwon --- packages/opencode/src/bench/cli.ts | 43 ++++- packages/opencode/src/bench/metrics.ts | 169 ++++++++++++++++++ .../provider/sdk/nemo-gym/language-model.ts | 21 ++- packages/opencode/test/bench/metrics.test.ts | 129 +++++++++++++ 4 files changed, 355 insertions(+), 7 deletions(-) create mode 100644 packages/opencode/src/bench/metrics.ts create mode 100644 packages/opencode/test/bench/metrics.test.ts diff --git a/packages/opencode/src/bench/cli.ts b/packages/opencode/src/bench/cli.ts index c1374c03a383..243198450b5b 100644 --- a/packages/opencode/src/bench/cli.ts +++ b/packages/opencode/src/bench/cli.ts @@ -25,6 +25,12 @@ import os from "node:os" import { spawn } from "node:child_process" import { runDeepReset } from "./deep_reset" import { bootstrapRepoIfMissing } from "./bootstrap_repo" +import { + collectCompletionMetrics, + parseToolExecutionMetric, + updateNemoGymMetrics, + type ActionExecutionLatencyMetric, +} from "./metrics" // opencode's built-in anthropic system prompt — Bun bundles .txt as a string. // Used as the default when no --system-prompt override is passed. import PROMPT_ANTHROPIC from "../session/prompt/anthropic.txt" @@ -347,7 +353,12 @@ function runOpencode(args: { env: NodeJS.ProcessEnv opencodeBin: string agent: string -}): Promise<{ exitCode: number; stdout: string; stderr: string }> { +}): Promise<{ + exitCode: number + stdout: string + stderr: string + actionExecutionLatencies: ActionExecutionLatencyMetric[] +}> { // Use the same bun binary that's currently running — guaranteed to exist // and avoids PATH lookup quirks under Bun's posix_spawn. const bunPath = process.execPath @@ -401,12 +412,16 @@ function runOpencode(args: { } const MAX_KEEP = 256 * 1024 // keep only a bounded tail for error reporting let lineBuf = "" + const actionExecutionLatencies = new Map() child.stdout?.on("data", (b) => { lineBuf += b.toString("utf8") let idx: number while ((idx = lineBuf.indexOf("\n")) >= 0) { - const line = scrub(lineBuf.slice(0, idx)) + const rawLine = lineBuf.slice(0, idx) lineBuf = lineBuf.slice(idx + 1) + const actionMetric = parseToolExecutionMetric(rawLine) + if (actionMetric) actionExecutionLatencies.set(actionMetric.observation_id, actionMetric) + const line = scrub(rawLine) // Forward to our stdout so the gym log captures the event stream. process.stdout.write(line + "\n") stdout = (stdout + line + "\n").slice(-MAX_KEEP) @@ -417,10 +432,11 @@ function runOpencode(args: { stderr = (stderr + chunk).slice(-MAX_KEEP) process.stderr.write(chunk) }) - child.on("close", (code) => resolve({ exitCode: code ?? 0, stdout, stderr })) + const metrics = () => [...actionExecutionLatencies.values()].sort((a, b) => a.timestamp.localeCompare(b.timestamp)) + child.on("close", (code) => resolve({ exitCode: code ?? 0, stdout, stderr, actionExecutionLatencies: metrics() })) child.on("error", (err) => { stderr += String(err) - resolve({ exitCode: 999, stdout, stderr }) + resolve({ exitCode: 999, stdout, stderr, actionExecutionLatencies: metrics() }) }) }) } @@ -563,6 +579,24 @@ async function main() { const patch = await captureGitDiff(workspaceRoot) const benchRunTime = (Date.now() - startedAt) / 1000 + const completionMetrics = await collectCompletionMetrics(completionsDir, modelName) + const perTurnMetrics = { + response_latencies: completionMetrics.responseLatencies, + action_execution_latencies: result.actionExecutionLatencies, + token_usages: completionMetrics.tokenUsages, + } + const totalModelCallTime = completionMetrics.responseLatencies.reduce((total, metric) => total + metric.latency, 0) + const totalCommandExecTime = result.actionExecutionLatencies.reduce((total, metric) => total + metric.latency, 0) + + // OpenCode has no separate OpenHands-style runtime create/connect/init phases. + await updateNemoGymMetrics(process.env.NEMO_GYM_METRICS_FPATH, { + create_runtime_time: 0, + connect_to_runtime_time: 0, + initialize_runtime_time: 0, + total_model_call_time: totalModelCallTime, + total_command_exec_time: totalCommandExecTime, + per_turn_metrics: perTurnMetrics, + }) const error: string | null = result.exitCode === 0 ? null : `opencode_exit_${result.exitCode}` const outPath = await writeOutputJsonl(args.outputDir, instance.instance_id, { @@ -572,6 +606,7 @@ async function main() { metrics: { bench_run_time: benchRunTime, opencode_exit_code: result.exitCode, + ...perTurnMetrics, }, error, }) diff --git a/packages/opencode/src/bench/metrics.ts b/packages/opencode/src/bench/metrics.ts new file mode 100644 index 000000000000..38652842a83e --- /dev/null +++ b/packages/opencode/src/bench/metrics.ts @@ -0,0 +1,169 @@ +import { promises as fs } from "node:fs" + +export interface ResponseLatencyMetric { + model: string + latency: number + response_id: string + timestamp: string +} + +export interface ActionExecutionLatencyMetric { + observation_type: string + observation_id: string + latency: number + message: string + timestamp: string +} + +export interface TokenUsageMetric { + model: string + prompt_tokens: number + completion_tokens: number + cache_read_tokens: number + cache_write_tokens: number + context_window: number + per_turn_token: number + response_id: string +} + +export interface CompletionMetrics { + responseLatencies: ResponseLatencyMetric[] + tokenUsages: TokenUsageMetric[] +} + +interface CompletionDump { + response?: { + id?: unknown + model?: unknown + usage?: { + prompt_tokens?: unknown + completion_tokens?: unknown + prompt_tokens_details?: { + cached_tokens?: unknown + } | null + } + } + latency?: unknown + timestamp?: unknown +} + +function finiteNumber(value: unknown): number | undefined { + return typeof value === "number" && Number.isFinite(value) ? value : undefined +} + +function nonNegativeInteger(value: unknown): number { + const number = finiteNumber(value) + return number === undefined ? 0 : Math.max(0, Math.trunc(number)) +} + +function isoTimestamp(seconds: number): string { + return new Date(seconds * 1000).toISOString() +} + +export function parseToolExecutionMetric(line: string): ActionExecutionLatencyMetric | undefined { + let event: Record + try { + event = JSON.parse(line) + } catch { + return undefined + } + + const part = event.part + const state = part?.state + if ( + event.type !== "tool_use" || + part?.type !== "tool" || + (state?.status !== "completed" && state?.status !== "error") + ) { + return undefined + } + + const start = finiteNumber(state.time?.start) + const end = finiteNumber(state.time?.end) + const callID = typeof part.callID === "string" ? part.callID : typeof part.id === "string" ? part.id : undefined + if (start === undefined || end === undefined || end < start || !callID) return undefined + + const title = typeof state.title === "string" ? state.title : "" + const error = typeof state.error === "string" ? state.error : "" + return { + observation_type: typeof part.tool === "string" ? part.tool : "opencode_tool", + observation_id: callID, + latency: (end - start) / 1000, + message: title || error, + timestamp: new Date(end).toISOString(), + } +} + +export async function collectCompletionMetrics( + completionsDir: string, + fallbackModel: string, +): Promise { + const records: Array<{ + timestampSeconds: number + responseLatency: ResponseLatencyMetric + tokenUsage: TokenUsageMetric + }> = [] + + for (const name of await fs.readdir(completionsDir)) { + if (!name.endsWith(".json")) continue + + let dump: CompletionDump + try { + dump = JSON.parse(await fs.readFile(`${completionsDir}/${name}`, "utf8")) + } catch { + continue + } + + const latency = finiteNumber(dump.latency) + const timestampSeconds = finiteNumber(dump.timestamp) + const responseID = typeof dump.response?.id === "string" ? dump.response.id : "" + if (latency === undefined || latency < 0 || timestampSeconds === undefined || !responseID) continue + + const model = typeof dump.response?.model === "string" ? dump.response.model : fallbackModel + const promptTokens = nonNegativeInteger(dump.response?.usage?.prompt_tokens) + const completionTokens = nonNegativeInteger(dump.response?.usage?.completion_tokens) + const cacheReadTokens = nonNegativeInteger(dump.response?.usage?.prompt_tokens_details?.cached_tokens) + + records.push({ + timestampSeconds, + responseLatency: { + model, + latency, + response_id: responseID, + timestamp: isoTimestamp(timestampSeconds), + }, + tokenUsage: { + model, + prompt_tokens: promptTokens, + completion_tokens: completionTokens, + cache_read_tokens: cacheReadTokens, + cache_write_tokens: 0, + context_window: 0, + per_turn_token: promptTokens + completionTokens, + response_id: responseID, + }, + }) + } + + records.sort((a, b) => a.timestampSeconds - b.timestampSeconds) + return { + responseLatencies: records.map((record) => record.responseLatency), + tokenUsages: records.map((record) => record.tokenUsage), + } +} + +export async function updateNemoGymMetrics( + metricsPath: string | undefined, + update: Record, +): Promise { + if (!metricsPath) return + + let existing: Record = {} + try { + existing = JSON.parse(await fs.readFile(metricsPath, "utf8")) + } catch {} + + const tmpPath = `${metricsPath}.tmp.${process.pid}.${Date.now()}` + await fs.writeFile(tmpPath, JSON.stringify({ ...existing, ...update })) + await fs.rename(tmpPath, metricsPath) +} diff --git a/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts b/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts index 0a0f9e56c386..e0b8cd55ca2e 100644 --- a/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts +++ b/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts @@ -193,11 +193,14 @@ export class NemoGymLanguageModel implements LanguageModelV3 { async doGenerate(options: LanguageModelV3CallOptions) { const { warnings, loggedMessages, requestParams } = await this._buildRequestParams(options) const session = this._sessionFromHeaders(options.headers) + const requestStartedAt = Date.now() const { responseJson } = await this._postChat(requestParams) + const responseCompletedAt = Date.now() const choice = responseJson.choices[0] if (!choice) throw new Error("nemo-gym: empty choices in response") - const msg: ChatResponseChoice["message"] = choice.message ?? ({ role: "assistant" } as ChatResponseChoice["message"]) + const msg: ChatResponseChoice["message"] = + choice.message ?? ({ role: "assistant" } as ChatResponseChoice["message"]) const providerSpecificFields = this._extractProviderFields(msg) const providerMetadata = this._buildProviderMetadata(providerSpecificFields) @@ -223,6 +226,8 @@ export class NemoGymLanguageModel implements LanguageModelV3 { providerSpecificFields, requestParams, session, + requestStartedAt, + responseCompletedAt, }) return { @@ -249,7 +254,9 @@ export class NemoGymLanguageModel implements LanguageModelV3 { controller.enqueue({ type: "stream-start", warnings }) try { + const requestStartedAt = Date.now() const { responseJson } = await self._postChat(requestParams) + const responseCompletedAt = Date.now() const choice = responseJson.choices[0] if (!choice) throw new Error("nemo-gym: empty choices in response") @@ -317,6 +324,8 @@ export class NemoGymLanguageModel implements LanguageModelV3 { providerSpecificFields, requestParams, session, + requestStartedAt, + responseCompletedAt, }) controller.enqueue({ @@ -575,7 +584,10 @@ export class NemoGymLanguageModel implements LanguageModelV3 { return md } - private _mapFinishReason(raw: string | null): { unified: "stop" | "length" | "tool-calls" | "error" | "other"; raw: string | undefined } { + private _mapFinishReason(raw: string | null): { + unified: "stop" | "length" | "tool-calls" | "error" | "other" + raw: string | undefined + } { if (!raw) return { unified: "other", raw: undefined } switch (raw) { case "stop": @@ -612,6 +624,8 @@ export class NemoGymLanguageModel implements LanguageModelV3 { providerSpecificFields: Record requestParams: Record session: { sessionID: string; parentSessionID: string | undefined } + requestStartedAt: number + responseCompletedAt: number }) { const turn = this._nextTurn(args.session.sessionID) if (this.cfg.onCompletion) { @@ -645,7 +659,8 @@ export class NemoGymLanguageModel implements LanguageModelV3 { session_id: args.session.sessionID, parent_session_id: args.session.parentSessionID ?? null, turn, - timestamp: Date.now() / 1000, + latency: (args.responseCompletedAt - args.requestStartedAt) / 1000, + timestamp: args.responseCompletedAt / 1000, } const tmp = `${fpath}.tmp` await fs.writeFile(tmp, JSON.stringify(payload)) diff --git a/packages/opencode/test/bench/metrics.test.ts b/packages/opencode/test/bench/metrics.test.ts new file mode 100644 index 000000000000..9db494189170 --- /dev/null +++ b/packages/opencode/test/bench/metrics.test.ts @@ -0,0 +1,129 @@ +import { describe, expect, test } from "bun:test" +import fs from "node:fs/promises" +import os from "node:os" +import path from "node:path" +import { collectCompletionMetrics, parseToolExecutionMetric, updateNemoGymMetrics } from "../../src/bench/metrics" + +async function withTempDir(run: (directory: string) => Promise) { + const directory = await fs.mkdtemp(path.join(os.tmpdir(), "opencode-metrics-")) + try { + await run(directory) + } finally { + await fs.rm(directory, { recursive: true, force: true }) + } +} + +describe("bench metrics", () => { + test("extracts an exact completed tool span", () => { + const metric = parseToolExecutionMetric( + JSON.stringify({ + type: "tool_use", + part: { + type: "tool", + tool: "bash", + callID: "call-1", + state: { + status: "completed", + title: "Run focused tests", + time: { start: 1_000, end: 3_500 }, + }, + }, + }), + ) + + expect(metric).toEqual({ + observation_type: "bash", + observation_id: "call-1", + latency: 2.5, + message: "Run focused tests", + timestamp: "1970-01-01T00:00:03.500Z", + }) + expect(parseToolExecutionMetric("not json")).toBeUndefined() + }) + + test("collects and chronologically sorts completion timing and usage", async () => { + await withTempDir(async (directory) => { + const later = { + response: { + id: "response-2", + model: "model-b", + usage: { prompt_tokens: 20, completion_tokens: 4 }, + }, + latency: 2, + timestamp: 20, + } + const earlier = { + response: { + id: "response-1", + usage: { + prompt_tokens: 10, + completion_tokens: 3, + prompt_tokens_details: { cached_tokens: 2 }, + }, + }, + latency: 1.25, + timestamp: 10, + } + await fs.writeFile(path.join(directory, "later.json"), JSON.stringify(later)) + await fs.writeFile(path.join(directory, "earlier.json"), JSON.stringify(earlier)) + await fs.writeFile(path.join(directory, "incomplete.json"), JSON.stringify({ response: {} })) + + const metrics = await collectCompletionMetrics(directory, "fallback-model") + + expect(metrics.responseLatencies).toEqual([ + { + model: "fallback-model", + latency: 1.25, + response_id: "response-1", + timestamp: "1970-01-01T00:00:10.000Z", + }, + { + model: "model-b", + latency: 2, + response_id: "response-2", + timestamp: "1970-01-01T00:00:20.000Z", + }, + ]) + expect(metrics.tokenUsages).toEqual([ + { + model: "fallback-model", + prompt_tokens: 10, + completion_tokens: 3, + cache_read_tokens: 2, + cache_write_tokens: 0, + context_window: 0, + per_turn_token: 13, + response_id: "response-1", + }, + { + model: "model-b", + prompt_tokens: 20, + completion_tokens: 4, + cache_read_tokens: 0, + cache_write_tokens: 0, + context_window: 0, + per_turn_token: 24, + response_id: "response-2", + }, + ]) + }) + }) + + test("atomically merges the NeMo Gym metrics file", async () => { + await withTempDir(async (directory) => { + const metricsPath = path.join(directory, "nemo_gym_metrics.json") + await fs.writeFile(metricsPath, JSON.stringify({ ray_queue_time: 1.5 })) + + await updateNemoGymMetrics(metricsPath, { + total_model_call_time: 3.25, + create_runtime_time: 0, + }) + + expect(JSON.parse(await fs.readFile(metricsPath, "utf8"))).toEqual({ + ray_queue_time: 1.5, + total_model_call_time: 3.25, + create_runtime_time: 0, + }) + }) + }) +}) From a6e243856a6010e90870988d41c7b418734f67d3 Mon Sep 17 00:00:00 2001 From: Youngeun Kwon Date: Wed, 29 Jul 2026 01:48:40 -0700 Subject: [PATCH 02/10] fix(bench): order completion metrics by request start Signed-off-by: Youngeun Kwon --- packages/opencode/src/bench/metrics.ts | 10 ++++- packages/opencode/test/bench/metrics.test.ts | 40 ++++++++++---------- 2 files changed, 29 insertions(+), 21 deletions(-) diff --git a/packages/opencode/src/bench/metrics.ts b/packages/opencode/src/bench/metrics.ts index 38652842a83e..36b61d074137 100644 --- a/packages/opencode/src/bench/metrics.ts +++ b/packages/opencode/src/bench/metrics.ts @@ -99,6 +99,7 @@ export async function collectCompletionMetrics( fallbackModel: string, ): Promise { const records: Array<{ + startedAtSeconds: number timestampSeconds: number responseLatency: ResponseLatencyMetric tokenUsage: TokenUsageMetric @@ -125,6 +126,7 @@ export async function collectCompletionMetrics( const cacheReadTokens = nonNegativeInteger(dump.response?.usage?.prompt_tokens_details?.cached_tokens) records.push({ + startedAtSeconds: timestampSeconds - latency, timestampSeconds, responseLatency: { model, @@ -145,7 +147,13 @@ export async function collectCompletionMetrics( }) } - records.sort((a, b) => a.timestampSeconds - b.timestampSeconds) + // Subagent requests can overlap, so completion order is not turn-start order. + records.sort( + (a, b) => + a.startedAtSeconds - b.startedAtSeconds || + a.timestampSeconds - b.timestampSeconds || + a.responseLatency.response_id.localeCompare(b.responseLatency.response_id), + ) return { responseLatencies: records.map((record) => record.responseLatency), tokenUsages: records.map((record) => record.tokenUsage), diff --git a/packages/opencode/test/bench/metrics.test.ts b/packages/opencode/test/bench/metrics.test.ts index 9db494189170..c89d64d7ce10 100644 --- a/packages/opencode/test/bench/metrics.test.ts +++ b/packages/opencode/test/bench/metrics.test.ts @@ -41,18 +41,18 @@ describe("bench metrics", () => { expect(parseToolExecutionMetric("not json")).toBeUndefined() }) - test("collects and chronologically sorts completion timing and usage", async () => { + test("collects and sorts completion timing and usage by request start", async () => { await withTempDir(async (directory) => { - const later = { + const startsFirstButCompletesLater = { response: { id: "response-2", model: "model-b", usage: { prompt_tokens: 20, completion_tokens: 4 }, }, - latency: 2, + latency: 15, timestamp: 20, } - const earlier = { + const startsLaterButCompletesFirst = { response: { id: "response-1", usage: { @@ -64,27 +64,37 @@ describe("bench metrics", () => { latency: 1.25, timestamp: 10, } - await fs.writeFile(path.join(directory, "later.json"), JSON.stringify(later)) - await fs.writeFile(path.join(directory, "earlier.json"), JSON.stringify(earlier)) + await fs.writeFile(path.join(directory, "later.json"), JSON.stringify(startsFirstButCompletesLater)) + await fs.writeFile(path.join(directory, "earlier.json"), JSON.stringify(startsLaterButCompletesFirst)) await fs.writeFile(path.join(directory, "incomplete.json"), JSON.stringify({ response: {} })) const metrics = await collectCompletionMetrics(directory, "fallback-model") expect(metrics.responseLatencies).toEqual([ + { + model: "model-b", + latency: 15, + response_id: "response-2", + timestamp: "1970-01-01T00:00:20.000Z", + }, { model: "fallback-model", latency: 1.25, response_id: "response-1", timestamp: "1970-01-01T00:00:10.000Z", }, + ]) + expect(metrics.tokenUsages).toEqual([ { model: "model-b", - latency: 2, + prompt_tokens: 20, + completion_tokens: 4, + cache_read_tokens: 0, + cache_write_tokens: 0, + context_window: 0, + per_turn_token: 24, response_id: "response-2", - timestamp: "1970-01-01T00:00:20.000Z", }, - ]) - expect(metrics.tokenUsages).toEqual([ { model: "fallback-model", prompt_tokens: 10, @@ -95,16 +105,6 @@ describe("bench metrics", () => { per_turn_token: 13, response_id: "response-1", }, - { - model: "model-b", - prompt_tokens: 20, - completion_tokens: 4, - cache_read_tokens: 0, - cache_write_tokens: 0, - context_window: 0, - per_turn_token: 24, - response_id: "response-2", - }, ]) }) }) From d9115e5aea76d60ddb40f9702992d68a51423bb7 Mon Sep 17 00:00:00 2001 From: Youngeun Kwon Date: Wed, 29 Jul 2026 02:00:00 -0700 Subject: [PATCH 03/10] chore(bench): remove metrics tests Signed-off-by: Youngeun Kwon --- packages/opencode/test/bench/metrics.test.ts | 129 ------------------- 1 file changed, 129 deletions(-) delete mode 100644 packages/opencode/test/bench/metrics.test.ts diff --git a/packages/opencode/test/bench/metrics.test.ts b/packages/opencode/test/bench/metrics.test.ts deleted file mode 100644 index c89d64d7ce10..000000000000 --- a/packages/opencode/test/bench/metrics.test.ts +++ /dev/null @@ -1,129 +0,0 @@ -import { describe, expect, test } from "bun:test" -import fs from "node:fs/promises" -import os from "node:os" -import path from "node:path" -import { collectCompletionMetrics, parseToolExecutionMetric, updateNemoGymMetrics } from "../../src/bench/metrics" - -async function withTempDir(run: (directory: string) => Promise) { - const directory = await fs.mkdtemp(path.join(os.tmpdir(), "opencode-metrics-")) - try { - await run(directory) - } finally { - await fs.rm(directory, { recursive: true, force: true }) - } -} - -describe("bench metrics", () => { - test("extracts an exact completed tool span", () => { - const metric = parseToolExecutionMetric( - JSON.stringify({ - type: "tool_use", - part: { - type: "tool", - tool: "bash", - callID: "call-1", - state: { - status: "completed", - title: "Run focused tests", - time: { start: 1_000, end: 3_500 }, - }, - }, - }), - ) - - expect(metric).toEqual({ - observation_type: "bash", - observation_id: "call-1", - latency: 2.5, - message: "Run focused tests", - timestamp: "1970-01-01T00:00:03.500Z", - }) - expect(parseToolExecutionMetric("not json")).toBeUndefined() - }) - - test("collects and sorts completion timing and usage by request start", async () => { - await withTempDir(async (directory) => { - const startsFirstButCompletesLater = { - response: { - id: "response-2", - model: "model-b", - usage: { prompt_tokens: 20, completion_tokens: 4 }, - }, - latency: 15, - timestamp: 20, - } - const startsLaterButCompletesFirst = { - response: { - id: "response-1", - usage: { - prompt_tokens: 10, - completion_tokens: 3, - prompt_tokens_details: { cached_tokens: 2 }, - }, - }, - latency: 1.25, - timestamp: 10, - } - await fs.writeFile(path.join(directory, "later.json"), JSON.stringify(startsFirstButCompletesLater)) - await fs.writeFile(path.join(directory, "earlier.json"), JSON.stringify(startsLaterButCompletesFirst)) - await fs.writeFile(path.join(directory, "incomplete.json"), JSON.stringify({ response: {} })) - - const metrics = await collectCompletionMetrics(directory, "fallback-model") - - expect(metrics.responseLatencies).toEqual([ - { - model: "model-b", - latency: 15, - response_id: "response-2", - timestamp: "1970-01-01T00:00:20.000Z", - }, - { - model: "fallback-model", - latency: 1.25, - response_id: "response-1", - timestamp: "1970-01-01T00:00:10.000Z", - }, - ]) - expect(metrics.tokenUsages).toEqual([ - { - model: "model-b", - prompt_tokens: 20, - completion_tokens: 4, - cache_read_tokens: 0, - cache_write_tokens: 0, - context_window: 0, - per_turn_token: 24, - response_id: "response-2", - }, - { - model: "fallback-model", - prompt_tokens: 10, - completion_tokens: 3, - cache_read_tokens: 2, - cache_write_tokens: 0, - context_window: 0, - per_turn_token: 13, - response_id: "response-1", - }, - ]) - }) - }) - - test("atomically merges the NeMo Gym metrics file", async () => { - await withTempDir(async (directory) => { - const metricsPath = path.join(directory, "nemo_gym_metrics.json") - await fs.writeFile(metricsPath, JSON.stringify({ ray_queue_time: 1.5 })) - - await updateNemoGymMetrics(metricsPath, { - total_model_call_time: 3.25, - create_runtime_time: 0, - }) - - expect(JSON.parse(await fs.readFile(metricsPath, "utf8"))).toEqual({ - ray_queue_time: 1.5, - total_model_call_time: 3.25, - create_runtime_time: 0, - }) - }) - }) -}) From 59113b5c06cfe590b87d15c0050264f1655202b4 Mon Sep 17 00:00:00 2001 From: Youngeun Kwon Date: Mon, 3 Aug 2026 16:19:44 -0700 Subject: [PATCH 04/10] feat(bench): record precise parallel agent timing Signed-off-by: Youngeun Kwon --- packages/opencode/src/bench/metrics.ts | 63 +++++++++++++++++-- packages/opencode/src/cli/cmd/run.ts | 17 ++++- .../provider/sdk/nemo-gym/language-model.ts | 34 ++++++++-- 3 files changed, 104 insertions(+), 10 deletions(-) diff --git a/packages/opencode/src/bench/metrics.ts b/packages/opencode/src/bench/metrics.ts index 36b61d074137..82ce91ee9214 100644 --- a/packages/opencode/src/bench/metrics.ts +++ b/packages/opencode/src/bench/metrics.ts @@ -4,14 +4,22 @@ export interface ResponseLatencyMetric { model: string latency: number response_id: string + request_kind: "agent" | "title" | "subagent" + session_id: string + parent_session_id: string | null + session_turn: number + start_timestamp: string timestamp: string } export interface ActionExecutionLatencyMetric { observation_type: string observation_id: string + session_id: string + child_session_id?: string latency: number message: string + start_timestamp: string timestamp: string } @@ -19,6 +27,7 @@ export interface TokenUsageMetric { model: string prompt_tokens: number completion_tokens: number + reasoning_tokens?: number cache_read_tokens: number cache_write_tokens: number context_window: number @@ -38,12 +47,20 @@ interface CompletionDump { usage?: { prompt_tokens?: unknown completion_tokens?: unknown + completion_tokens_details?: { + reasoning_tokens?: unknown + } | null prompt_tokens_details?: { cached_tokens?: unknown } | null } } latency?: unknown + request_kind?: unknown + request_started_at?: unknown + session_id?: unknown + parent_session_id?: unknown + turn?: unknown timestamp?: unknown } @@ -56,6 +73,11 @@ function nonNegativeInteger(value: unknown): number { return number === undefined ? 0 : Math.max(0, Math.trunc(number)) } +function optionalNonNegativeInteger(value: unknown): number | undefined { + const number = finiteNumber(value) + return number === undefined || number < 0 ? undefined : Math.trunc(number) +} + function isoTimestamp(seconds: number): string { return new Date(seconds * 1000).toISOString() } @@ -78,18 +100,27 @@ export function parseToolExecutionMetric(line: string): ActionExecutionLatencyMe return undefined } - const start = finiteNumber(state.time?.start) + const recordedStart = finiteNumber(event.toolStart) const end = finiteNumber(state.time?.end) const callID = typeof part.callID === "string" ? part.callID : typeof part.id === "string" ? part.id : undefined - if (start === undefined || end === undefined || end < start || !callID) return undefined + if (recordedStart === undefined || end === undefined || end < recordedStart || !callID) return undefined const title = typeof state.title === "string" ? state.title : "" const error = typeof state.error === "string" ? state.error : "" + const metadata = + "metadata" in state && state.metadata && typeof state.metadata === "object" + ? (state.metadata as Record) + : undefined + const childSessionID = + part.tool === "task" && typeof metadata?.sessionId === "string" ? metadata.sessionId : undefined return { observation_type: typeof part.tool === "string" ? part.tool : "opencode_tool", observation_id: callID, - latency: (end - start) / 1000, + session_id: typeof event.sessionID === "string" ? event.sessionID : "", + ...(childSessionID ? { child_session_id: childSessionID } : {}), + latency: (end - recordedStart) / 1000, message: title || error, + start_timestamp: new Date(recordedStart).toISOString(), timestamp: new Date(end).toISOString(), } } @@ -116,28 +147,50 @@ export async function collectCompletionMetrics( } const latency = finiteNumber(dump.latency) + const requestStartedAtSeconds = finiteNumber(dump.request_started_at) const timestampSeconds = finiteNumber(dump.timestamp) const responseID = typeof dump.response?.id === "string" ? dump.response.id : "" - if (latency === undefined || latency < 0 || timestampSeconds === undefined || !responseID) continue + if ( + latency === undefined || + latency < 0 || + requestStartedAtSeconds === undefined || + timestampSeconds === undefined || + timestampSeconds < requestStartedAtSeconds || + !responseID + ) + continue const model = typeof dump.response?.model === "string" ? dump.response.model : fallbackModel + const requestKind = dump.request_kind === "title" || dump.request_kind === "subagent" ? dump.request_kind : "agent" + const sessionID = typeof dump.session_id === "string" ? dump.session_id : "" + const parentSessionID = typeof dump.parent_session_id === "string" ? dump.parent_session_id : null + const sessionTurn = nonNegativeInteger(dump.turn) const promptTokens = nonNegativeInteger(dump.response?.usage?.prompt_tokens) const completionTokens = nonNegativeInteger(dump.response?.usage?.completion_tokens) + const reasoningTokens = optionalNonNegativeInteger( + dump.response?.usage?.completion_tokens_details?.reasoning_tokens, + ) const cacheReadTokens = nonNegativeInteger(dump.response?.usage?.prompt_tokens_details?.cached_tokens) records.push({ - startedAtSeconds: timestampSeconds - latency, + startedAtSeconds: requestStartedAtSeconds, timestampSeconds, responseLatency: { model, latency, response_id: responseID, + request_kind: requestKind, + session_id: sessionID, + parent_session_id: parentSessionID, + session_turn: sessionTurn, + start_timestamp: isoTimestamp(requestStartedAtSeconds), timestamp: isoTimestamp(timestampSeconds), }, tokenUsage: { model, prompt_tokens: promptTokens, completion_tokens: completionTokens, + ...(reasoningTokens === undefined ? {} : { reasoning_tokens: reasoningTokens }), cache_read_tokens: cacheReadTokens, cache_write_tokens: 0, context_window: 0, diff --git a/packages/opencode/src/cli/cmd/run.ts b/packages/opencode/src/cli/cmd/run.ts index a05b273e4489..3a5136cd936d 100644 --- a/packages/opencode/src/cli/cmd/run.ts +++ b/packages/opencode/src/cli/cmd/run.ts @@ -440,6 +440,7 @@ export const RunCommand = effectCmd({ const events = await sdk.event.subscribe() let error: string | undefined + const toolStartTimes = new Map() async function loop() { const toggles = new Map() @@ -459,10 +460,24 @@ export const RunCommand = effectCmd({ if (event.type === "message.part.updated") { const part = event.properties.part + + if (part.type === "tool" && part.state.status === "running") { + const start = part.state.time.start + const key = `${part.sessionID}:${part.callID}` + const previous = toolStartTimes.get(key) + if (previous === undefined || start < previous) toolStartTimes.set(key, start) + } + + if (part.type === "tool" && (part.state.status === "completed" || part.state.status === "error")) { + const key = `${part.sessionID}:${part.callID}` + const toolStart = toolStartTimes.get(key) + toolStartTimes.delete(key) + if (emit("tool_use", { sessionID: part.sessionID, part, toolStart })) continue + } + if (part.sessionID !== sessionID) continue if (part.type === "tool" && (part.state.status === "completed" || part.state.status === "error")) { - if (emit("tool_use", { part })) continue if (part.state.status === "completed") { tool(part) continue diff --git a/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts b/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts index e0b8cd55ca2e..f3946519e2cd 100644 --- a/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts +++ b/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts @@ -75,6 +75,9 @@ interface ChatResponseUsage { prompt_tokens?: number | null completion_tokens?: number | null total_tokens?: number | null + completion_tokens_details?: { + reasoning_tokens?: number | null + } | null } interface ChatResponse { @@ -155,6 +158,17 @@ export class NemoGymLanguageModel implements LanguageModelV3 { // a Map keeps their dump filenames from clobbering the main session's. private readonly turnCounters: Map = new Map() + private _requestKind( + messages: ChatRequestMessage[], + parentSessionID: string | undefined, + ): "agent" | "title" | "subagent" { + if (parentSessionID) return "subagent" + const titlePrompt = "Generate a title for this conversation:" + return messages.some((message) => message.role === "user" && JSON.stringify(message.content).includes(titlePrompt)) + ? "title" + : "agent" + } + constructor(modelId: string, cfg: NemoGymLanguageModelConfig) { this.modelId = modelId this.provider = cfg.provider @@ -193,6 +207,7 @@ export class NemoGymLanguageModel implements LanguageModelV3 { async doGenerate(options: LanguageModelV3CallOptions) { const { warnings, loggedMessages, requestParams } = await this._buildRequestParams(options) const session = this._sessionFromHeaders(options.headers) + const turn = this._nextTurn(session.sessionID) const requestStartedAt = Date.now() const { responseJson } = await this._postChat(requestParams) const responseCompletedAt = Date.now() @@ -226,6 +241,7 @@ export class NemoGymLanguageModel implements LanguageModelV3 { providerSpecificFields, requestParams, session, + turn, requestStartedAt, responseCompletedAt, }) @@ -254,6 +270,7 @@ export class NemoGymLanguageModel implements LanguageModelV3 { controller.enqueue({ type: "stream-start", warnings }) try { + const turn = self._nextTurn(session.sessionID) const requestStartedAt = Date.now() const { responseJson } = await self._postChat(requestParams) const responseCompletedAt = Date.now() @@ -324,6 +341,7 @@ export class NemoGymLanguageModel implements LanguageModelV3 { providerSpecificFields, requestParams, session, + turn, requestStartedAt, responseCompletedAt, }) @@ -624,13 +642,19 @@ export class NemoGymLanguageModel implements LanguageModelV3 { providerSpecificFields: Record requestParams: Record session: { sessionID: string; parentSessionID: string | undefined } + turn: number requestStartedAt: number responseCompletedAt: number }) { - const turn = this._nextTurn(args.session.sessionID) if (this.cfg.onCompletion) { try { - await this.cfg.onCompletion({ turn, ...args }) + await this.cfg.onCompletion({ + turn: args.turn, + messages: args.messages, + response: args.response, + providerSpecificFields: args.providerSpecificFields, + requestParams: args.requestParams, + }) } catch (err) { console.warn(`[nemo-gym] onCompletion hook threw: ${String(err)}`) } @@ -640,7 +664,7 @@ export class NemoGymLanguageModel implements LanguageModelV3 { try { await fs.mkdir(this.cfg.completionsDir, { recursive: true }) - const turnStr = String(turn).padStart(4, "0") + const turnStr = String(args.turn).padStart(4, "0") const safeModel = this.modelId.replace(/\//g, "__") // sessionID is part of the filename so subagent dumps don't clobber the // main session's. Sanitized for filesystem safety. @@ -658,7 +682,9 @@ export class NemoGymLanguageModel implements LanguageModelV3 { kwargs, session_id: args.session.sessionID, parent_session_id: args.session.parentSessionID ?? null, - turn, + turn: args.turn, + request_kind: this._requestKind(args.messages, args.session.parentSessionID), + request_started_at: args.requestStartedAt / 1000, latency: (args.responseCompletedAt - args.requestStartedAt) / 1000, timestamp: args.responseCompletedAt / 1000, } From abda1840ea615f5889b90bfdacf5a7ee91e08ce3 Mon Sep 17 00:00:00 2001 From: Youngeun Kwon Date: Mon, 3 Aug 2026 17:54:36 -0700 Subject: [PATCH 05/10] feat(bench): record tool input and output Signed-off-by: Youngeun Kwon --- packages/opencode/src/bench/metrics.ts | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/packages/opencode/src/bench/metrics.ts b/packages/opencode/src/bench/metrics.ts index 82ce91ee9214..7c6922edb1c5 100644 --- a/packages/opencode/src/bench/metrics.ts +++ b/packages/opencode/src/bench/metrics.ts @@ -17,6 +17,8 @@ export interface ActionExecutionLatencyMetric { observation_id: string session_id: string child_session_id?: string + input?: Record + output?: string latency: number message: string start_timestamp: string @@ -113,11 +115,18 @@ export function parseToolExecutionMetric(line: string): ActionExecutionLatencyMe : undefined const childSessionID = part.tool === "task" && typeof metadata?.sessionId === "string" ? metadata.sessionId : undefined + const input = + state.input && typeof state.input === "object" && !Array.isArray(state.input) + ? (state.input as Record) + : undefined + const output = typeof state.output === "string" ? state.output : undefined return { observation_type: typeof part.tool === "string" ? part.tool : "opencode_tool", observation_id: callID, session_id: typeof event.sessionID === "string" ? event.sessionID : "", ...(childSessionID ? { child_session_id: childSessionID } : {}), + ...(input ? { input } : {}), + ...(output === undefined ? {} : { output }), latency: (end - recordedStart) / 1000, message: title || error, start_timestamp: new Date(recordedStart).toISOString(), From 9b79f6c1d2555c653e4b5dd49a08d2ddbd209731 Mon Sep 17 00:00:00 2001 From: Youngeun Kwon Date: Wed, 5 Aug 2026 11:58:10 -0700 Subject: [PATCH 06/10] feat(bench): capture NeMo Gym request timings Signed-off-by: Youngeun Kwon --- packages/opencode/src/bench/cli.ts | 5 +- packages/opencode/src/bench/metrics.ts | 19 ++++- .../provider/sdk/nemo-gym/language-model.ts | 72 +++++++++++++++++-- 3 files changed, 88 insertions(+), 8 deletions(-) diff --git a/packages/opencode/src/bench/cli.ts b/packages/opencode/src/bench/cli.ts index 243198450b5b..14bcbc4d164b 100644 --- a/packages/opencode/src/bench/cli.ts +++ b/packages/opencode/src/bench/cli.ts @@ -420,7 +420,10 @@ function runOpencode(args: { const rawLine = lineBuf.slice(0, idx) lineBuf = lineBuf.slice(idx + 1) const actionMetric = parseToolExecutionMetric(rawLine) - if (actionMetric) actionExecutionLatencies.set(actionMetric.observation_id, actionMetric) + if (actionMetric) { + const metricID = `${actionMetric.session_id}:${actionMetric.observation_id}` + actionExecutionLatencies.set(metricID, actionMetric) + } const line = scrub(rawLine) // Forward to our stdout so the gym log captures the event stream. process.stdout.write(line + "\n") diff --git a/packages/opencode/src/bench/metrics.ts b/packages/opencode/src/bench/metrics.ts index 7c6922edb1c5..873b43fc03a9 100644 --- a/packages/opencode/src/bench/metrics.ts +++ b/packages/opencode/src/bench/metrics.ts @@ -1,4 +1,7 @@ import { promises as fs } from "node:fs" +import path from "node:path" + +export type TimingBreakdown = Record export interface ResponseLatencyMetric { model: string @@ -10,6 +13,7 @@ export interface ResponseLatencyMetric { session_turn: number start_timestamp: string timestamp: string + timing_breakdown?: TimingBreakdown } export interface ActionExecutionLatencyMetric { @@ -64,6 +68,7 @@ interface CompletionDump { parent_session_id?: unknown turn?: unknown timestamp?: unknown + timing_breakdown?: unknown } function finiteNumber(value: unknown): number | undefined { @@ -84,6 +89,16 @@ function isoTimestamp(seconds: number): string { return new Date(seconds * 1000).toISOString() } +function timingBreakdown(value: unknown): TimingBreakdown | undefined { + if (!value || typeof value !== "object" || Array.isArray(value)) return undefined + + const entries = Object.entries(value).filter( + (entry): entry is [string, number | boolean] => + typeof entry[1] === "boolean" || (typeof entry[1] === "number" && Number.isFinite(entry[1])), + ) + return entries.length > 0 ? Object.fromEntries(entries) : undefined +} + export function parseToolExecutionMetric(line: string): ActionExecutionLatencyMetric | undefined { let event: Record try { @@ -150,7 +165,7 @@ export async function collectCompletionMetrics( let dump: CompletionDump try { - dump = JSON.parse(await fs.readFile(`${completionsDir}/${name}`, "utf8")) + dump = JSON.parse(await fs.readFile(path.join(completionsDir, name), "utf8")) } catch { continue } @@ -180,6 +195,7 @@ export async function collectCompletionMetrics( dump.response?.usage?.completion_tokens_details?.reasoning_tokens, ) const cacheReadTokens = nonNegativeInteger(dump.response?.usage?.prompt_tokens_details?.cached_tokens) + const requestTiming = timingBreakdown(dump.timing_breakdown) records.push({ startedAtSeconds: requestStartedAtSeconds, @@ -194,6 +210,7 @@ export async function collectCompletionMetrics( session_turn: sessionTurn, start_timestamp: isoTimestamp(requestStartedAtSeconds), timestamp: isoTimestamp(timestampSeconds), + ...(requestTiming ? { timing_breakdown: requestTiming } : {}), }, tokenUsage: { model, diff --git a/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts b/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts index f3946519e2cd..899b3dc0cf46 100644 --- a/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts +++ b/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts @@ -86,6 +86,7 @@ interface ChatResponse { created?: number choices: ChatResponseChoice[] usage?: ChatResponseUsage + nemo_gym_timing?: TimingBreakdown } // --------------------------------------------------------------------------- @@ -93,6 +94,21 @@ interface ChatResponse { // --------------------------------------------------------------------------- const TOKEN_ID_FIELDS = ["prompt_token_ids", "generation_token_ids", "generation_log_probs"] as const +type TimingBreakdown = Record + +function parseServerTiming(value: string | null): Record { + if (!value) return {} + + const timing: Record = {} + for (const metric of value.split(",")) { + const [rawName, ...parameters] = metric.split(";") + const duration = parameters.map((parameter) => parameter.trim().split("=", 2)).find(([key]) => key === "dur")?.[1] + const name = rawName?.trim() + const parsed = Number(duration) + if (name && duration !== undefined && Number.isFinite(parsed)) timing[name] = parsed + } + return timing +} export interface NemoGymLanguageModelConfig { /** Provider id used to namespace providerMetadata. Defaults to "nemo-gym". */ @@ -205,12 +221,18 @@ export class NemoGymLanguageModel implements LanguageModelV3 { // The streamText path in `session/llm.ts` only calls doStream. We still // implement doGenerate for completeness / future direct-use. async doGenerate(options: LanguageModelV3CallOptions) { + const requestBuildStartedAt = performance.now() const { warnings, loggedMessages, requestParams } = await this._buildRequestParams(options) + const timingBreakdown: TimingBreakdown = { + client_request_build_ms: performance.now() - requestBuildStartedAt, + } const session = this._sessionFromHeaders(options.headers) const turn = this._nextTurn(session.sessionID) const requestStartedAt = Date.now() - const { responseJson } = await this._postChat(requestParams) + const { responseJson, clientTiming } = await this._postChat(requestParams) const responseCompletedAt = Date.now() + Object.assign(timingBreakdown, clientTiming, responseJson.nemo_gym_timing) + const responseProcessingStartedAt = performance.now() const choice = responseJson.choices[0] if (!choice) throw new Error("nemo-gym: empty choices in response") @@ -234,6 +256,7 @@ export class NemoGymLanguageModel implements LanguageModelV3 { }) } } + timingBreakdown.client_response_processing_ms = performance.now() - responseProcessingStartedAt await this._dumpAndNotify({ messages: loggedMessages, @@ -244,6 +267,7 @@ export class NemoGymLanguageModel implements LanguageModelV3 { turn, requestStartedAt, responseCompletedAt, + timingBreakdown, }) return { @@ -258,7 +282,11 @@ export class NemoGymLanguageModel implements LanguageModelV3 { } async doStream(options: LanguageModelV3CallOptions) { + const requestBuildStartedAt = performance.now() const { warnings, loggedMessages, requestParams } = await this._buildRequestParams(options) + const timingBreakdown: TimingBreakdown = { + client_request_build_ms: performance.now() - requestBuildStartedAt, + } const session = this._sessionFromHeaders(options.headers) // Fire the HTTP call eagerly so any error surfaces synchronously when the @@ -272,8 +300,10 @@ export class NemoGymLanguageModel implements LanguageModelV3 { try { const turn = self._nextTurn(session.sessionID) const requestStartedAt = Date.now() - const { responseJson } = await self._postChat(requestParams) + const { responseJson, clientTiming } = await self._postChat(requestParams) const responseCompletedAt = Date.now() + Object.assign(timingBreakdown, clientTiming, responseJson.nemo_gym_timing) + const responseProcessingStartedAt = performance.now() const choice = responseJson.choices[0] if (!choice) throw new Error("nemo-gym: empty choices in response") @@ -335,6 +365,7 @@ export class NemoGymLanguageModel implements LanguageModelV3 { // Persist trajectory BEFORE finishing so a downstream tool crash // cannot lose this turn's token IDs. + timingBreakdown.client_response_processing_ms = performance.now() - responseProcessingStartedAt await self._dumpAndNotify({ messages: loggedMessages, response: responseJson, @@ -344,6 +375,7 @@ export class NemoGymLanguageModel implements LanguageModelV3 { turn, requestStartedAt, responseCompletedAt, + timingBreakdown, }) controller.enqueue({ @@ -511,7 +543,10 @@ export class NemoGymLanguageModel implements LanguageModelV3 { return { warnings, messages, loggedMessages, tools, toolChoice, requestParams } } - private async _postChat(params: Record): Promise<{ responseJson: ChatResponse }> { + private async _postChat(params: Record): Promise<{ + responseJson: ChatResponse + clientTiming: TimingBreakdown + }> { const url = this._urlFor("/v1/chat/completions") const headers: Record = { "Content-Type": "application/json", @@ -545,12 +580,18 @@ export class NemoGymLanguageModel implements LanguageModelV3 { // timeoutMs<=0 means "no timeout" — don't install the abort timer. const timer = timeoutMs > 0 ? setTimeout(() => ac.abort(), timeoutMs) : null try { + const serializeStartedAt = performance.now() + const requestBody = JSON.stringify(params) + const requestSerializedAt = performance.now() + const fetchStartedAt = performance.now() const res = await fetch(url, { method: "POST", headers, - body: JSON.stringify(params), + body: requestBody, signal: ac.signal, }) + const responseHeadersAt = performance.now() + const serverTiming = parseServerTiming(res.headers.get("server-timing")) if (timer) clearTimeout(timer) if (!res.ok) { const text = await res.text().catch(() => "") @@ -564,8 +605,25 @@ export class NemoGymLanguageModel implements LanguageModelV3 { if (k && v) this.cookies[k.trim()] = v.trim() } } - const responseJson = (await res.json()) as ChatResponse - return { responseJson } + const responseBodyStartedAt = performance.now() + const responseBody = await res.text() + const responseBodyReadAt = performance.now() + const responseJson = JSON.parse(responseBody) as ChatResponse + const responseParsedAt = performance.now() + return { + responseJson, + clientTiming: { + client_request_serialize_ms: requestSerializedAt - serializeStartedAt, + client_fetch_to_headers_ms: responseHeadersAt - fetchStartedAt, + client_response_body_read_ms: responseBodyReadAt - responseBodyStartedAt, + client_response_json_parse_ms: responseParsedAt - responseBodyReadAt, + client_http_total_ms: responseParsedAt - fetchStartedAt, + client_request_body_chars: requestBody.length, + client_response_body_chars: responseBody.length, + client_retry_count: attempt, + ...serverTiming, + }, + } } catch (err) { if (timer) clearTimeout(timer) lastErr = err @@ -645,6 +703,7 @@ export class NemoGymLanguageModel implements LanguageModelV3 { turn: number requestStartedAt: number responseCompletedAt: number + timingBreakdown: TimingBreakdown }) { if (this.cfg.onCompletion) { try { @@ -687,6 +746,7 @@ export class NemoGymLanguageModel implements LanguageModelV3 { request_started_at: args.requestStartedAt / 1000, latency: (args.responseCompletedAt - args.requestStartedAt) / 1000, timestamp: args.responseCompletedAt / 1000, + timing_breakdown: args.timingBreakdown, } const tmp = `${fpath}.tmp` await fs.writeFile(tmp, JSON.stringify(payload)) From 8ea3184a183ee9ea44098119e196411a4425fdab Mon Sep 17 00:00:00 2001 From: Youngeun Kwon Date: Wed, 5 Aug 2026 16:45:43 -0700 Subject: [PATCH 07/10] chore(bench): keep only NeMo-RL route timing --- packages/opencode/src/bench/metrics.ts | 23 +++--- .../provider/sdk/nemo-gym/language-model.ts | 75 +++---------------- 2 files changed, 20 insertions(+), 78 deletions(-) diff --git a/packages/opencode/src/bench/metrics.ts b/packages/opencode/src/bench/metrics.ts index 873b43fc03a9..5841a9ccdf16 100644 --- a/packages/opencode/src/bench/metrics.ts +++ b/packages/opencode/src/bench/metrics.ts @@ -1,7 +1,9 @@ import { promises as fs } from "node:fs" import path from "node:path" -export type TimingBreakdown = Record +export interface NemoRlTimingBreakdown { + nemo_rl_route_total_ms: number +} export interface ResponseLatencyMetric { model: string @@ -13,7 +15,7 @@ export interface ResponseLatencyMetric { session_turn: number start_timestamp: string timestamp: string - timing_breakdown?: TimingBreakdown + timing_breakdown?: NemoRlTimingBreakdown } export interface ActionExecutionLatencyMetric { @@ -60,6 +62,9 @@ interface CompletionDump { cached_tokens?: unknown } | null } + nemo_gym_timing?: { + nemo_rl_route_total_ms?: unknown + } } latency?: unknown request_kind?: unknown @@ -68,7 +73,6 @@ interface CompletionDump { parent_session_id?: unknown turn?: unknown timestamp?: unknown - timing_breakdown?: unknown } function finiteNumber(value: unknown): number | undefined { @@ -89,14 +93,9 @@ function isoTimestamp(seconds: number): string { return new Date(seconds * 1000).toISOString() } -function timingBreakdown(value: unknown): TimingBreakdown | undefined { - if (!value || typeof value !== "object" || Array.isArray(value)) return undefined - - const entries = Object.entries(value).filter( - (entry): entry is [string, number | boolean] => - typeof entry[1] === "boolean" || (typeof entry[1] === "number" && Number.isFinite(entry[1])), - ) - return entries.length > 0 ? Object.fromEntries(entries) : undefined +function nemoRlTimingBreakdown(value: unknown): NemoRlTimingBreakdown | undefined { + const routeTotalMs = finiteNumber(value) + return routeTotalMs === undefined ? undefined : { nemo_rl_route_total_ms: routeTotalMs } } export function parseToolExecutionMetric(line: string): ActionExecutionLatencyMetric | undefined { @@ -195,7 +194,7 @@ export async function collectCompletionMetrics( dump.response?.usage?.completion_tokens_details?.reasoning_tokens, ) const cacheReadTokens = nonNegativeInteger(dump.response?.usage?.prompt_tokens_details?.cached_tokens) - const requestTiming = timingBreakdown(dump.timing_breakdown) + const requestTiming = nemoRlTimingBreakdown(dump.response?.nemo_gym_timing?.nemo_rl_route_total_ms) records.push({ startedAtSeconds: requestStartedAtSeconds, diff --git a/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts b/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts index 899b3dc0cf46..367e0cfbe2bb 100644 --- a/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts +++ b/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts @@ -86,7 +86,9 @@ interface ChatResponse { created?: number choices: ChatResponseChoice[] usage?: ChatResponseUsage - nemo_gym_timing?: TimingBreakdown + nemo_gym_timing?: { + nemo_rl_route_total_ms?: number + } } // --------------------------------------------------------------------------- @@ -94,21 +96,6 @@ interface ChatResponse { // --------------------------------------------------------------------------- const TOKEN_ID_FIELDS = ["prompt_token_ids", "generation_token_ids", "generation_log_probs"] as const -type TimingBreakdown = Record - -function parseServerTiming(value: string | null): Record { - if (!value) return {} - - const timing: Record = {} - for (const metric of value.split(",")) { - const [rawName, ...parameters] = metric.split(";") - const duration = parameters.map((parameter) => parameter.trim().split("=", 2)).find(([key]) => key === "dur")?.[1] - const name = rawName?.trim() - const parsed = Number(duration) - if (name && duration !== undefined && Number.isFinite(parsed)) timing[name] = parsed - } - return timing -} export interface NemoGymLanguageModelConfig { /** Provider id used to namespace providerMetadata. Defaults to "nemo-gym". */ @@ -221,18 +208,12 @@ export class NemoGymLanguageModel implements LanguageModelV3 { // The streamText path in `session/llm.ts` only calls doStream. We still // implement doGenerate for completeness / future direct-use. async doGenerate(options: LanguageModelV3CallOptions) { - const requestBuildStartedAt = performance.now() const { warnings, loggedMessages, requestParams } = await this._buildRequestParams(options) - const timingBreakdown: TimingBreakdown = { - client_request_build_ms: performance.now() - requestBuildStartedAt, - } const session = this._sessionFromHeaders(options.headers) const turn = this._nextTurn(session.sessionID) const requestStartedAt = Date.now() - const { responseJson, clientTiming } = await this._postChat(requestParams) + const { responseJson } = await this._postChat(requestParams) const responseCompletedAt = Date.now() - Object.assign(timingBreakdown, clientTiming, responseJson.nemo_gym_timing) - const responseProcessingStartedAt = performance.now() const choice = responseJson.choices[0] if (!choice) throw new Error("nemo-gym: empty choices in response") @@ -256,7 +237,6 @@ export class NemoGymLanguageModel implements LanguageModelV3 { }) } } - timingBreakdown.client_response_processing_ms = performance.now() - responseProcessingStartedAt await this._dumpAndNotify({ messages: loggedMessages, @@ -267,7 +247,6 @@ export class NemoGymLanguageModel implements LanguageModelV3 { turn, requestStartedAt, responseCompletedAt, - timingBreakdown, }) return { @@ -282,11 +261,7 @@ export class NemoGymLanguageModel implements LanguageModelV3 { } async doStream(options: LanguageModelV3CallOptions) { - const requestBuildStartedAt = performance.now() const { warnings, loggedMessages, requestParams } = await this._buildRequestParams(options) - const timingBreakdown: TimingBreakdown = { - client_request_build_ms: performance.now() - requestBuildStartedAt, - } const session = this._sessionFromHeaders(options.headers) // Fire the HTTP call eagerly so any error surfaces synchronously when the @@ -300,10 +275,8 @@ export class NemoGymLanguageModel implements LanguageModelV3 { try { const turn = self._nextTurn(session.sessionID) const requestStartedAt = Date.now() - const { responseJson, clientTiming } = await self._postChat(requestParams) + const { responseJson } = await self._postChat(requestParams) const responseCompletedAt = Date.now() - Object.assign(timingBreakdown, clientTiming, responseJson.nemo_gym_timing) - const responseProcessingStartedAt = performance.now() const choice = responseJson.choices[0] if (!choice) throw new Error("nemo-gym: empty choices in response") @@ -365,7 +338,6 @@ export class NemoGymLanguageModel implements LanguageModelV3 { // Persist trajectory BEFORE finishing so a downstream tool crash // cannot lose this turn's token IDs. - timingBreakdown.client_response_processing_ms = performance.now() - responseProcessingStartedAt await self._dumpAndNotify({ messages: loggedMessages, response: responseJson, @@ -375,7 +347,6 @@ export class NemoGymLanguageModel implements LanguageModelV3 { turn, requestStartedAt, responseCompletedAt, - timingBreakdown, }) controller.enqueue({ @@ -543,10 +514,7 @@ export class NemoGymLanguageModel implements LanguageModelV3 { return { warnings, messages, loggedMessages, tools, toolChoice, requestParams } } - private async _postChat(params: Record): Promise<{ - responseJson: ChatResponse - clientTiming: TimingBreakdown - }> { + private async _postChat(params: Record): Promise<{ responseJson: ChatResponse }> { const url = this._urlFor("/v1/chat/completions") const headers: Record = { "Content-Type": "application/json", @@ -580,18 +548,12 @@ export class NemoGymLanguageModel implements LanguageModelV3 { // timeoutMs<=0 means "no timeout" — don't install the abort timer. const timer = timeoutMs > 0 ? setTimeout(() => ac.abort(), timeoutMs) : null try { - const serializeStartedAt = performance.now() - const requestBody = JSON.stringify(params) - const requestSerializedAt = performance.now() - const fetchStartedAt = performance.now() const res = await fetch(url, { method: "POST", headers, - body: requestBody, + body: JSON.stringify(params), signal: ac.signal, }) - const responseHeadersAt = performance.now() - const serverTiming = parseServerTiming(res.headers.get("server-timing")) if (timer) clearTimeout(timer) if (!res.ok) { const text = await res.text().catch(() => "") @@ -605,25 +567,8 @@ export class NemoGymLanguageModel implements LanguageModelV3 { if (k && v) this.cookies[k.trim()] = v.trim() } } - const responseBodyStartedAt = performance.now() - const responseBody = await res.text() - const responseBodyReadAt = performance.now() - const responseJson = JSON.parse(responseBody) as ChatResponse - const responseParsedAt = performance.now() - return { - responseJson, - clientTiming: { - client_request_serialize_ms: requestSerializedAt - serializeStartedAt, - client_fetch_to_headers_ms: responseHeadersAt - fetchStartedAt, - client_response_body_read_ms: responseBodyReadAt - responseBodyStartedAt, - client_response_json_parse_ms: responseParsedAt - responseBodyReadAt, - client_http_total_ms: responseParsedAt - fetchStartedAt, - client_request_body_chars: requestBody.length, - client_response_body_chars: responseBody.length, - client_retry_count: attempt, - ...serverTiming, - }, - } + const responseJson = (await res.json()) as ChatResponse + return { responseJson } } catch (err) { if (timer) clearTimeout(timer) lastErr = err @@ -703,7 +648,6 @@ export class NemoGymLanguageModel implements LanguageModelV3 { turn: number requestStartedAt: number responseCompletedAt: number - timingBreakdown: TimingBreakdown }) { if (this.cfg.onCompletion) { try { @@ -746,7 +690,6 @@ export class NemoGymLanguageModel implements LanguageModelV3 { request_started_at: args.requestStartedAt / 1000, latency: (args.responseCompletedAt - args.requestStartedAt) / 1000, timestamp: args.responseCompletedAt / 1000, - timing_breakdown: args.timingBreakdown, } const tmp = `${fpath}.tmp` await fs.writeFile(tmp, JSON.stringify(payload)) From 94e5c98a8ba034f7b30bb69d71dadb3b364e1ea9 Mon Sep 17 00:00:00 2001 From: Youngeun Kwon Date: Wed, 5 Aug 2026 23:30:37 -0700 Subject: [PATCH 08/10] chore(bench): remove inactive route timing plumbing --- packages/opencode/src/bench/metrics.ts | 16 ---------------- .../src/provider/sdk/nemo-gym/language-model.ts | 3 --- 2 files changed, 19 deletions(-) diff --git a/packages/opencode/src/bench/metrics.ts b/packages/opencode/src/bench/metrics.ts index 5841a9ccdf16..6c2c82289072 100644 --- a/packages/opencode/src/bench/metrics.ts +++ b/packages/opencode/src/bench/metrics.ts @@ -1,10 +1,6 @@ import { promises as fs } from "node:fs" import path from "node:path" -export interface NemoRlTimingBreakdown { - nemo_rl_route_total_ms: number -} - export interface ResponseLatencyMetric { model: string latency: number @@ -15,7 +11,6 @@ export interface ResponseLatencyMetric { session_turn: number start_timestamp: string timestamp: string - timing_breakdown?: NemoRlTimingBreakdown } export interface ActionExecutionLatencyMetric { @@ -62,9 +57,6 @@ interface CompletionDump { cached_tokens?: unknown } | null } - nemo_gym_timing?: { - nemo_rl_route_total_ms?: unknown - } } latency?: unknown request_kind?: unknown @@ -93,11 +85,6 @@ function isoTimestamp(seconds: number): string { return new Date(seconds * 1000).toISOString() } -function nemoRlTimingBreakdown(value: unknown): NemoRlTimingBreakdown | undefined { - const routeTotalMs = finiteNumber(value) - return routeTotalMs === undefined ? undefined : { nemo_rl_route_total_ms: routeTotalMs } -} - export function parseToolExecutionMetric(line: string): ActionExecutionLatencyMetric | undefined { let event: Record try { @@ -194,8 +181,6 @@ export async function collectCompletionMetrics( dump.response?.usage?.completion_tokens_details?.reasoning_tokens, ) const cacheReadTokens = nonNegativeInteger(dump.response?.usage?.prompt_tokens_details?.cached_tokens) - const requestTiming = nemoRlTimingBreakdown(dump.response?.nemo_gym_timing?.nemo_rl_route_total_ms) - records.push({ startedAtSeconds: requestStartedAtSeconds, timestampSeconds, @@ -209,7 +194,6 @@ export async function collectCompletionMetrics( session_turn: sessionTurn, start_timestamp: isoTimestamp(requestStartedAtSeconds), timestamp: isoTimestamp(timestampSeconds), - ...(requestTiming ? { timing_breakdown: requestTiming } : {}), }, tokenUsage: { model, diff --git a/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts b/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts index 367e0cfbe2bb..f3946519e2cd 100644 --- a/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts +++ b/packages/opencode/src/provider/sdk/nemo-gym/language-model.ts @@ -86,9 +86,6 @@ interface ChatResponse { created?: number choices: ChatResponseChoice[] usage?: ChatResponseUsage - nemo_gym_timing?: { - nemo_rl_route_total_ms?: number - } } // --------------------------------------------------------------------------- From 4ba0219978e9eff8832701551dd0087549f4cb1f Mon Sep 17 00:00:00 2001 From: Youngeun Kwon Date: Thu, 6 Aug 2026 17:36:12 -0700 Subject: [PATCH 09/10] refactor(bench): keep only trace-visible metrics --- packages/opencode/src/bench/cli.ts | 8 +------ packages/opencode/src/bench/metrics.ts | 31 +++++--------------------- packages/opencode/src/cli/cmd/run.ts | 13 +---------- 3 files changed, 7 insertions(+), 45 deletions(-) diff --git a/packages/opencode/src/bench/cli.ts b/packages/opencode/src/bench/cli.ts index 14bcbc4d164b..b8d78f4bcee0 100644 --- a/packages/opencode/src/bench/cli.ts +++ b/packages/opencode/src/bench/cli.ts @@ -582,23 +582,17 @@ async function main() { const patch = await captureGitDiff(workspaceRoot) const benchRunTime = (Date.now() - startedAt) / 1000 - const completionMetrics = await collectCompletionMetrics(completionsDir, modelName) + const completionMetrics = await collectCompletionMetrics(completionsDir) const perTurnMetrics = { response_latencies: completionMetrics.responseLatencies, action_execution_latencies: result.actionExecutionLatencies, token_usages: completionMetrics.tokenUsages, } - const totalModelCallTime = completionMetrics.responseLatencies.reduce((total, metric) => total + metric.latency, 0) - const totalCommandExecTime = result.actionExecutionLatencies.reduce((total, metric) => total + metric.latency, 0) - // OpenCode has no separate OpenHands-style runtime create/connect/init phases. await updateNemoGymMetrics(process.env.NEMO_GYM_METRICS_FPATH, { create_runtime_time: 0, connect_to_runtime_time: 0, initialize_runtime_time: 0, - total_model_call_time: totalModelCallTime, - total_command_exec_time: totalCommandExecTime, - per_turn_metrics: perTurnMetrics, }) const error: string | null = result.exitCode === 0 ? null : `opencode_exit_${result.exitCode}` diff --git a/packages/opencode/src/bench/metrics.ts b/packages/opencode/src/bench/metrics.ts index 6c2c82289072..147191e616b5 100644 --- a/packages/opencode/src/bench/metrics.ts +++ b/packages/opencode/src/bench/metrics.ts @@ -1,8 +1,7 @@ import { promises as fs } from "node:fs" import path from "node:path" -export interface ResponseLatencyMetric { - model: string +interface ResponseLatencyMetric { latency: number response_id: string request_kind: "agent" | "title" | "subagent" @@ -26,19 +25,14 @@ export interface ActionExecutionLatencyMetric { timestamp: string } -export interface TokenUsageMetric { - model: string +interface TokenUsageMetric { prompt_tokens: number completion_tokens: number reasoning_tokens?: number - cache_read_tokens: number - cache_write_tokens: number - context_window: number - per_turn_token: number response_id: string } -export interface CompletionMetrics { +interface CompletionMetrics { responseLatencies: ResponseLatencyMetric[] tokenUsages: TokenUsageMetric[] } @@ -46,16 +40,12 @@ export interface CompletionMetrics { interface CompletionDump { response?: { id?: unknown - model?: unknown usage?: { prompt_tokens?: unknown completion_tokens?: unknown completion_tokens_details?: { reasoning_tokens?: unknown } | null - prompt_tokens_details?: { - cached_tokens?: unknown - } | null } } latency?: unknown @@ -103,7 +93,7 @@ export function parseToolExecutionMetric(line: string): ActionExecutionLatencyMe return undefined } - const recordedStart = finiteNumber(event.toolStart) + const recordedStart = finiteNumber(state.time?.start) const end = finiteNumber(state.time?.end) const callID = typeof part.callID === "string" ? part.callID : typeof part.id === "string" ? part.id : undefined if (recordedStart === undefined || end === undefined || end < recordedStart || !callID) return undefined @@ -135,10 +125,7 @@ export function parseToolExecutionMetric(line: string): ActionExecutionLatencyMe } } -export async function collectCompletionMetrics( - completionsDir: string, - fallbackModel: string, -): Promise { +export async function collectCompletionMetrics(completionsDir: string): Promise { const records: Array<{ startedAtSeconds: number timestampSeconds: number @@ -170,7 +157,6 @@ export async function collectCompletionMetrics( ) continue - const model = typeof dump.response?.model === "string" ? dump.response.model : fallbackModel const requestKind = dump.request_kind === "title" || dump.request_kind === "subagent" ? dump.request_kind : "agent" const sessionID = typeof dump.session_id === "string" ? dump.session_id : "" const parentSessionID = typeof dump.parent_session_id === "string" ? dump.parent_session_id : null @@ -180,12 +166,10 @@ export async function collectCompletionMetrics( const reasoningTokens = optionalNonNegativeInteger( dump.response?.usage?.completion_tokens_details?.reasoning_tokens, ) - const cacheReadTokens = nonNegativeInteger(dump.response?.usage?.prompt_tokens_details?.cached_tokens) records.push({ startedAtSeconds: requestStartedAtSeconds, timestampSeconds, responseLatency: { - model, latency, response_id: responseID, request_kind: requestKind, @@ -196,14 +180,9 @@ export async function collectCompletionMetrics( timestamp: isoTimestamp(timestampSeconds), }, tokenUsage: { - model, prompt_tokens: promptTokens, completion_tokens: completionTokens, ...(reasoningTokens === undefined ? {} : { reasoning_tokens: reasoningTokens }), - cache_read_tokens: cacheReadTokens, - cache_write_tokens: 0, - context_window: 0, - per_turn_token: promptTokens + completionTokens, response_id: responseID, }, }) diff --git a/packages/opencode/src/cli/cmd/run.ts b/packages/opencode/src/cli/cmd/run.ts index 3a5136cd936d..d1067e02a8a1 100644 --- a/packages/opencode/src/cli/cmd/run.ts +++ b/packages/opencode/src/cli/cmd/run.ts @@ -440,7 +440,6 @@ export const RunCommand = effectCmd({ const events = await sdk.event.subscribe() let error: string | undefined - const toolStartTimes = new Map() async function loop() { const toggles = new Map() @@ -461,18 +460,8 @@ export const RunCommand = effectCmd({ if (event.type === "message.part.updated") { const part = event.properties.part - if (part.type === "tool" && part.state.status === "running") { - const start = part.state.time.start - const key = `${part.sessionID}:${part.callID}` - const previous = toolStartTimes.get(key) - if (previous === undefined || start < previous) toolStartTimes.set(key, start) - } - if (part.type === "tool" && (part.state.status === "completed" || part.state.status === "error")) { - const key = `${part.sessionID}:${part.callID}` - const toolStart = toolStartTimes.get(key) - toolStartTimes.delete(key) - if (emit("tool_use", { sessionID: part.sessionID, part, toolStart })) continue + if (emit("tool_use", { sessionID: part.sessionID, part })) continue } if (part.sessionID !== sessionID) continue From 45f5076f6c5b3af8456dc760ae3f1d0be9673270 Mon Sep 17 00:00:00 2001 From: Youngeun Kwon Date: Tue, 11 Aug 2026 09:28:58 -0700 Subject: [PATCH 10/10] fix(bench): measure OpenCode runtime initialization --- packages/opencode/src/bench/cli.ts | 9 ++++----- 1 file changed, 4 insertions(+), 5 deletions(-) diff --git a/packages/opencode/src/bench/cli.ts b/packages/opencode/src/bench/cli.ts index b8d78f4bcee0..4ab52dc08063 100644 --- a/packages/opencode/src/bench/cli.ts +++ b/packages/opencode/src/bench/cli.ts @@ -503,6 +503,7 @@ function detectOpencodeBin(): string { } async function main() { + const initializeStartedAt = Date.now() const args = parseArgs(process.argv.slice(2)) const instance = await readInstance(args.instanceDictPath, args.selectedId) // workspaceRoot is decided gym-side based on dataset_name; we use it verbatim. @@ -541,7 +542,6 @@ async function main() { maxTokens: forcedMaxTokens, }) - const startedAt = Date.now() const childEnv: NodeJS.ProcessEnv = { ...process.env, // Run-isolated opencode state. @@ -571,6 +571,8 @@ async function main() { } const opencodeBin = detectOpencodeBin() + const initializeRuntimeTime = (Date.now() - initializeStartedAt) / 1000 + const startedAt = Date.now() const result = await runOpencode({ workspaceRoot, modelName, @@ -588,11 +590,8 @@ async function main() { action_execution_latencies: result.actionExecutionLatencies, token_usages: completionMetrics.tokenUsages, } - // OpenCode has no separate OpenHands-style runtime create/connect/init phases. await updateNemoGymMetrics(process.env.NEMO_GYM_METRICS_FPATH, { - create_runtime_time: 0, - connect_to_runtime_time: 0, - initialize_runtime_time: 0, + initialize_runtime_time: initializeRuntimeTime, }) const error: string | null = result.exitCode === 0 ? null : `opencode_exit_${result.exitCode}`