History

Measure execute result size once per result object

Rhys Sullivan committed 2 months ago

Commit bb962c31 parent 4d4ad7c4 files · +232 −9Browse files

Unified · Split

4 files
  1. .changeset/dedupe-result-size-walk.md +7 −0
  2. packages/core/execution/src/engine.test.ts +137 −1
  3. packages/core/execution/src/engine.ts +27 −8
  4. packages/hosts/mcp/src/tool-server.test.ts +61 −0
.changeset/dedupe-result-size-walk.md+7−0
@@ -0,0 +1,7 @@
1+---
2+"@executor-js/execution": patch
3+---
4+
5+**Large execute results are measured once, not once per span**
6+
7+The result-size telemetry probe serializes the whole returned value to count its characters, and that cost grows with the payload. The same result object was walked again every time it was stamped onto another span: an operator-approved run measured it twice (inner and outer span), and every retried `resume` that replayed a settled outcome measured it again. The measurement is now computed once per result object and reused, so a large result pays one size walk no matter how many spans report it. Response text, structured content, and span attribute values are unchanged.
packages/core/execution/src/engine.test.ts+137−1
@@ -5,7 +5,7 @@ import { createExecutor, definePlugin } from "@executor-js/sdk"; · 4 unmodified lines
55 import { makeTestConfig } from "@executor-js/sdk/testing";
66 import type { CodeExecutor, ExecuteResult } from "@executor-js/codemode-core";
77
8−import { createExecutionEngine, formatPausedExecution } from "./engine";
8+import { createExecutionEngine, formatExecuteResult, formatPausedExecution } from "./engine";
99 import { FormElicitation } from "@executor-js/sdk/core";
1010
1111 // Regression for the hang reported as the executor-MCP "180s timeout" against
@@ -140,3 +140,139 @@ describe("formatPausedExecution approval terms", () => { · 128 unmodified lines
140140 expect((result.structured["interaction"] as Record<string, unknown>)["meta"]).toBeUndefined();
141141 });
142142 });
143+
144+// Pins the exact preview and structured shapes so the serialization dedupe in
145+// the engine cannot drift them: the preview stays pretty-printed (indent 2),
146+// truncation keeps its exact suffix, and structured carries the raw value.
147+describe("formatExecuteResult output identity", () => {
148+ const MAX_PREVIEW_CHARS = 30_000;
149+
150+ it("renders an object result as pretty-printed JSON and keeps the raw value in structured", () => {
151+ const value = { café: "naïve — ✓", emoji: "🎉", nested: { π: 3.14159 } };
152+ const formatted = formatExecuteResult({ result: value, logs: [] });
153+
154+ expect(formatted.text).toBe(JSON.stringify(value, null, 2));
155+ expect(formatted.structured).toEqual({ status: "completed", result: value, logs: [] });
156+ expect(formatted.structured["result"]).toBe(value);
157+ expect(formatted.isError).toBe(false);
158+ });
159+
160+ it("truncates a long preview with the exact suffix and untouched structured value", () => {
161+ const value = { data: "é🎉".repeat(12_000) };
162+ const pretty = JSON.stringify(value, null, 2);
163+ expect(pretty.length).toBeGreaterThan(MAX_PREVIEW_CHARS);
164+
165+ const formatted = formatExecuteResult({ result: value });
166+
167+ expect(formatted.text).toBe(
168+ `${pretty.slice(0, MAX_PREVIEW_CHARS)}\n... [truncated ${pretty.length - MAX_PREVIEW_CHARS} chars]`,
169+ );
170+ expect(formatted.structured["result"]).toBe(value);
171+ });
172+
173+ it("returns a string result verbatim", () => {
174+ const formatted = formatExecuteResult({ result: "plain — ✓", logs: ["l1", "l2"] });
175+
176+ expect(formatted.text).toBe("plain — ✓\n\nLogs:\nl1\nl2");
177+ expect(formatted.structured).toEqual({
178+ status: "completed",
179+ result: "plain — ✓",
180+ logs: ["l1", "l2"],
181+ });
182+ });
183+
184+ it("renders an error result with logs and truncation", () => {
185+ const formatted = formatExecuteResult({
186+ result: null,
187+ error: "boom",
188+ errorKind: "tool_error",
189+ logs: ["x".repeat(MAX_PREVIEW_CHARS)],
190+ });
191+
192+ const untruncated = `Error: boom\n\nLogs:\n${"x".repeat(MAX_PREVIEW_CHARS)}`;
193+ expect(formatted.text).toBe(
194+ `${untruncated.slice(0, MAX_PREVIEW_CHARS)}\n... [truncated ${untruncated.length - MAX_PREVIEW_CHARS} chars]`,
195+ );
196+ expect(formatted.isError).toBe(true);
197+ expect(formatted.structured).toEqual({
198+ status: "error",
199+ error: "boom",
200+ logs: ["x".repeat(MAX_PREVIEW_CHARS)],
201+ });
202+ });
203+});
204+
205+// The result-size span metric walks the whole result value with
206+// `JSON.stringify`. A `toJSON` probe inside the fixture counts full walks:
207+// every complete stringify of the value visits the probe exactly once.
208+describe("execute outcome measurement cost", () => {
209+ const instrumented = () => {
210+ let walks = 0;
211+ const probe = {
212+ toJSON: () => {
213+ walks += 1;
214+ return "probe";
215+ },
216+ };
217+ return { value: { data: [1, 2, 3], probe }, walks: () => walks };
218+ };
219+
220+ const executorFor = (result: ExecuteResult): CodeExecutor<FakeRuntimeError> => ({
221+ execute: () => Effect.succeed(result),
222+ });
223+
224+ it.effect("walks the result value once on the pausable path", () =>
225+ Effect.gen(function* () {
226+ const executor = yield* makeExecutor();
227+ const fixture = instrumented();
228+ const engine = createExecutionEngine({
229+ executor,
230+ codeExecutor: executorFor({ result: fixture.value, logs: [] }),
231+ });
232+
233+ const outcome = yield* engine.executeWithPause("noop");
234+
235+ expect(outcome.status).toBe("completed");
236+ expect(fixture.walks()).toBe(1);
237+ }),
238+ );
239+
240+ it.effect("walks the result value once even when autoApprove stamps two spans", () =>
241+ Effect.gen(function* () {
242+ const executor = yield* makeExecutor();
243+ const fixture = instrumented();
244+ const engine = createExecutionEngine({
245+ executor,
246+ codeExecutor: executorFor({ result: fixture.value, logs: [] }),
247+ });
248+
249+ // autoApprove runs the inline path (inner span annotation) and then
250+ // annotates the outer pausable span with the same result.
251+ const outcome = yield* engine.executeWithPause("noop", { autoApprove: true });
252+
253+ expect(outcome.status).toBe("completed");
254+ expect(fixture.walks()).toBe(1);
255+ }),
256+ );
257+
258+ it.effect("a completed execution plus its preview pays two walks total", () =>
259+ Effect.gen(function* () {
260+ const executor = yield* makeExecutor();
261+ const fixture = instrumented();
262+ const engine = createExecutionEngine({
263+ executor,
264+ codeExecutor: executorFor({ result: fixture.value, logs: [] }),
265+ });
266+
267+ const outcome = yield* engine.executeWithPause("noop");
268+ expect(outcome.status).toBe("completed");
269+ if (outcome.status !== "completed") return;
270+
271+ // One compact walk for the span size metric, one pretty walk for the
272+ // preview. They produce different strings (compact vs indent 2), so
273+ // neither can be derived from the other.
274+ formatExecuteResult(outcome.result);
275+ expect(fixture.walks()).toBe(2);
276+ }),
277+ );
278+});
packages/core/execution/src/engine.ts+27−8
@@ -80,6 +80,32 @@ const measureResultChars = (value: unknown): number => { · 79 unmodified lines
8080 }
8181 };
8282
83+/**
84+ * Outcome attributes are a pure function of an immutable `ExecuteResult`, but
85+ * the same result object is annotated more than once: the `autoApprove` path
86+ * stamps both the inner inline span and the outer pausable span, and resume
87+ * retries replay the settled result cached per execution id. The size probe
88+ * walks the whole result value (`JSON.stringify`), so its cost grows with the
89+ * payload — memoize the record per result object so each result is walked
90+ * once, no matter how many spans it is stamped onto.
91+ */
92+const executeOutcomeAttributesCache = new WeakMap<ExecuteResult, Record<string, unknown>>();
93+
94+const executeOutcomeAttributes = (result: ExecuteResult): Record<string, unknown> => {
95+ const cached = executeOutcomeAttributesCache.get(result);
96+ if (cached) return cached;
97+ const attributes = {
98+ "mcp.execute.result_chars": measureResultChars(result.result),
99+ "mcp.execute.log_chars": result.logs?.reduce((total, line) => total + line.length, 0) ?? 0,
100+ "mcp.execute.emitted": result.output?.length ?? 0,
101+ ...(result.error
102+ ? { "mcp.execute.outcome": "fail", "mcp.execute.error_kind": result.errorKind ?? "unknown" }
103+ : { "mcp.execute.outcome": "ok" }),
104+ };
105+ executeOutcomeAttributesCache.set(result, attributes);
106+ return attributes;
107+};
108+
83109 /**
84110 * Stamp the current `mcp.execute` / `mcp.execute.resume` span with how the
85111 * execution ended and how much data it sent back toward model context.
@@ -89,14 +115,7 @@ const measureResultChars = (value: unknown): number => { · 3 unmodified lines
89115 * or result content itself.
90116 */
91117 const annotateExecuteOutcome = (result: ExecuteResult) =>
92− Effect.annotateCurrentSpan({
93− "mcp.execute.result_chars": measureResultChars(result.result),
94− "mcp.execute.log_chars": result.logs?.reduce((total, line) => total + line.length, 0) ?? 0,
95− "mcp.execute.emitted": result.output?.length ?? 0,
96− ...(result.error
97− ? { "mcp.execute.outcome": "fail", "mcp.execute.error_kind": result.errorKind ?? "unknown" }
98− : { "mcp.execute.outcome": "ok" }),
99− });
118+ Effect.annotateCurrentSpan(executeOutcomeAttributes(result));
100119
101120 const annotateExecutionOutcome = (execution: ExecutionResult) =>
102121 execution.status === "paused"
packages/hosts/mcp/src/tool-server.test.ts+61−0
@@ -1973,3 +1973,64 @@ describe("MCP host server — hang-visibility tracing", () => { · 1972 unmodified lines
19731973 );
19741974 });
19751975 });
1976+
1977+// Pins that formatting a completed execution for MCP walks the result value
1978+// exactly once (`formatExecuteResult`'s pretty print), with or without emit()
1979+// output — the with-output and without-output branches are alternatives, never
1980+// stacked. A `toJSON` probe counts full `JSON.stringify` walks of the value.
1981+describe("formatMcpExecutionOutcome serialization cost", () => {
1982+ const instrumented = () => {
1983+ let walks = 0;
1984+ const probe = {
1985+ toJSON: () => {
1986+ walks += 1;
1987+ return "probe";
1988+ },
1989+ };
1990+ return { value: { data: [1, 2, 3], probe }, walks: () => walks };
1991+ };
1992+
1993+ it("stringifies the result value once for a plain completed outcome", () => {
1994+ const fixture = instrumented();
1995+ const outcome: ExecutionResult = {
1996+ status: "completed",
1997+ result: { result: fixture.value, logs: [] },
1998+ };
1999+
2000+ const result = formatMcpExecutionOutcome(outcome);
2001+
2002+ expect(fixture.walks()).toBe(1);
2003+ const first = result.content[0];
2004+ expectDefined(first);
2005+ expect(first).toEqual({
2006+ type: "text",
2007+ text: JSON.stringify(fixture.value, null, 2),
2008+ });
2009+ expectDefined(result.structuredContent);
2010+ expect(result.structuredContent["result"]).toBe(fixture.value);
2011+ // The identity probe above walked the value once more; discount it.
2012+ expect(fixture.walks()).toBe(2);
2013+ });
2014+
2015+ it("stringifies the result value once when emit() output is present", () => {
2016+ const fixture = instrumented();
2017+ const outcome: ExecutionResult = {
2018+ status: "completed",
2019+ result: {
2020+ result: fixture.value,
2021+ logs: [],
2022+ output: [{ type: "content", content: { type: "text", text: "emitted" } }],
2023+ },
2024+ };
2025+
2026+ const result = formatMcpExecutionOutcome(outcome);
2027+
2028+ expect(fixture.walks()).toBe(1);
2029+ expect(result.content[0]).toEqual({ type: "text", text: "emitted" });
2030+ const returned = result.content[1];
2031+ expectDefined(returned);
2032+ expect(returned.type).toBe("text");
2033+ if (returned.type !== "text") return;
2034+ expect(returned.text).toContain('"data"');
2035+ });
2036+});