From e005ac1f889144ca07403ff25ff6cb5f7e8d8f75 Mon Sep 17 00:00:00 2001 From: Waleed Latif Date: Mon, 2 Nov 2026 16:10:57 -0800 Subject: [PATCH 1/2] improvement(sandbox): log per-phase timing for each sandbox execution --- .../sim/lib/execution/remote-sandbox/index.ts | 62 ++++++++++++++++--- .../execution/remote-sandbox/phase-timing.ts | 38 ++++++++++++ .../remote-sandbox/session-sandbox.test.ts | 27 ++++++++ .../lib/execution/remote-sandbox/session.ts | 6 ++ .../sim/lib/execution/remote-sandbox/types.ts | 3 + .../lib/function-execution/execute-request.ts | 11 ++++ 6 files changed, 140 insertions(+), 7 deletions(-) create mode 100644 apps/sim/lib/execution/remote-sandbox/phase-timing.ts diff --git a/apps/sim/lib/execution/remote-sandbox/index.ts b/apps/sim/lib/execution/remote-sandbox/index.ts index a16a464c294..265271b7b51 100644 --- a/apps/sim/lib/execution/remote-sandbox/index.ts +++ b/apps/sim/lib/execution/remote-sandbox/index.ts @@ -43,6 +43,10 @@ import { SANDBOX_OUTPUT_DIR_MAX_DEPTH, SANDBOX_OUTPUT_DIR_SENTINEL, } from '@/lib/execution/remote-sandbox/paths' +import { + createSandboxPhaseTimer, + type SandboxPhaseTimer, +} from '@/lib/execution/remote-sandbox/phase-timing' import { resolvePiSandboxLifetimeMs } from '@/lib/execution/remote-sandbox/pi-lifetime' import { resolveProvider } from '@/lib/execution/remote-sandbox/provider' import { @@ -116,13 +120,16 @@ async function leaseSandbox( selected: ResolvedSandbox | null, signal: AbortSignal, meterUsage: boolean | undefined, - session: SandboxSessionRequest | undefined + session: SandboxSessionRequest | undefined, + phases: SandboxPhaseTimer ): Promise { const provider = resolveProvider() const sessionCapable = Boolean(session && !meterUsage && provider.findSessionSandbox) if (session && sessionCapable) { + const endAccess = phases.start('access') await prepareSandboxSessionAccess(session.key, signal) + endAccess() return withSandboxSessionLock(session.key, signal, async (leaseSignal) => { const { created, status } = await ensureSessionSandbox({ provider, @@ -132,6 +139,7 @@ async function leaseSandbox( session, signal: leaseSignal, bootstrapTimeoutMs: remainingSandboxBudgetMs(signal), + phases, }) return { created, @@ -214,6 +222,16 @@ function raceSandboxAbort(operation: Promise, signal: AbortSignal): Promis }) } +/** Attaches the phase breakdown to whichever result the execution returns, after its release. */ +async function withPhaseTimings( + execute: (phases: SandboxPhaseTimer) => Promise +): Promise { + const phases = createSandboxPhaseTimer() + const result = await execute(phases) + result.phaseMs = phases.timings + return result +} + async function withSandboxExecutionBudget( timeoutMs: number, parentSignal: AbortSignal | undefined, @@ -864,7 +882,8 @@ async function acceptSessionOutputHistory( async function executeInSandboxWithinBudget( // The budget wrapper always injects the signal; the required-signal type states that // invariant instead of a cast hiding it. - req: SandboxExecutionRequest & { signal: AbortSignal } + req: SandboxExecutionRequest & { signal: AbortSignal }, + phases: SandboxPhaseTimer ): Promise { const { code, language, signal } = req const kind = req.sandboxKind ?? 'code' @@ -872,14 +891,17 @@ async function executeInSandboxWithinBudget( // Resolved before the sandbox is created so a selection that cannot be honored // fails without spending a provider create. + const endResolve = phases.start('resolve') const selected = await resolveWorkspaceSandbox({ kind, language, workspaceId: req.workspaceId, sandboxId: req.sandboxId, }) + endResolve() throwIfAborted(signal) + const endLease = phases.start('lease') const lease = await leaseSandbox( kind, { @@ -890,8 +912,10 @@ async function executeInSandboxWithinBudget( selected, signal, req.meterUsage, - req.session + req.session, + phases ) + endLease() const created = lease.created const sandbox = created.sandbox const sandboxId = sandbox.sandboxId @@ -906,6 +930,7 @@ async function executeInSandboxWithinBudget( // the finally below. Dependencies land before the inputs so user code and its // mounts always see a complete environment. // + const endPrepare = phases.start('prepare') if (lease.session && req.session) await recordSessionFileInput( req.session.key, @@ -926,6 +951,7 @@ async function executeInSandboxWithinBudget( signal, Boolean(lease.session) ) + endPrepare() const executionEnvironment = { ...selected?.envs, ...req.session?.envs, @@ -944,6 +970,7 @@ async function executeInSandboxWithinBudget( let execution: SandboxCodeResult try { + const endRun = phases.start('run') execution = await sandbox.runCode(code, { timeoutMs: codeBudgetMs(req, signal), javascriptPreload: buildJavaScriptRuntimeBindingsSource(req.runtimeBindings ?? []), @@ -951,6 +978,7 @@ async function executeInSandboxWithinBudget( signal, ...(hasExecutionEnvironment ? { envs: executionEnvironment } : {}), }) + endRun() } catch (error) { throwIfAborted(signal) throw error @@ -1009,11 +1037,13 @@ async function executeInSandboxWithinBudget( ...sessionField, } try { + const endCollect = phases.start('collect') const { exportedFiles, exportedFileContent, collectedFiles } = await collectExportedFiles( sandbox, req, { signal } ) + endCollect() throwIfAborted(signal) billableResult.exportedFileContent = exportedFileContent billableResult.exportedFiles = exportedFiles @@ -1044,6 +1074,7 @@ async function executeInSandboxWithinBudget( if (cost && billableOutputError) { attachTrustedSandboxOutputCost(billableOutputError, cost) } + const endRelease = phases.start('release') try { await privateInputFiles?.cleanup() await lease.release() @@ -1052,6 +1083,7 @@ async function executeInSandboxWithinBudget( providerId: created.providerId, sandboxId, }) + endRelease() } } } @@ -1061,12 +1093,14 @@ export function executeInSandbox(req: SandboxExecutionRequest): Promise executeInSandboxWithinBudget({ ...req, signal }) + (signal) => + withPhaseTimings((phases) => executeInSandboxWithinBudget({ ...req, signal }, phases)) ) } async function executeShellInSandboxWithinBudget( - req: SandboxShellExecutionRequest & { signal: AbortSignal } + req: SandboxShellExecutionRequest & { signal: AbortSignal }, + phases: SandboxPhaseTimer ): Promise { const { code, envs, signal } = req const kind = req.sandboxKind ?? 'shell' @@ -1074,21 +1108,26 @@ async function executeShellInSandboxWithinBudget( // No language is passed: a shell execution runs commands rather than a language // runtime, so whichever language the sandbox carries is the one it installs. + const endResolve = phases.start('resolve') const selected = await resolveWorkspaceSandbox({ kind, workspaceId: req.workspaceId, sandboxId: req.sandboxId, }) + endResolve() throwIfAborted(signal) + const endLease = phases.start('lease') const lease = await leaseSandbox( kind, { imageRef: selected?.imageRef, lifetimeMs: remainingSandboxBudgetMs(signal) }, selected, signal, req.meterUsage, - req.session + req.session, + phases ) + endLease() const created = lease.created const sandbox = created.sandbox const sandboxId = sandbox.sandboxId @@ -1102,6 +1141,7 @@ async function executeShellInSandboxWithinBudget( // Inside the try so a failed install or mount still releases the sandbox via // the finally below. The install shares the caller's budget rather than adding // to it — see the note in `executeInSandbox`. + const endPrepare = phases.start('prepare') if (lease.session && req.session) await recordSessionFileInput( req.session.key, @@ -1123,9 +1163,11 @@ async function executeShellInSandboxWithinBudget( signal, Boolean(lease.session) ) + endPrepare() let result: SandboxCommandResult try { + const endRun = phases.start('run') result = await sandbox.runCommand(code, { envs: { ...selected?.envs, @@ -1141,6 +1183,7 @@ async function executeShellInSandboxWithinBudget( rootUser: !lease.session, atMostOnce: true, }) + endRun() } catch (error) { throwIfAborted(signal) throw error @@ -1185,11 +1228,13 @@ async function executeShellInSandboxWithinBudget( ...sessionField, } try { + const endCollect = phases.start('collect') const { exportedFiles, exportedFileContent, collectedFiles } = await collectExportedFiles( sandbox, req, { signal } ) + endCollect() throwIfAborted(signal) billableResult.exportedFileContent = exportedFileContent billableResult.exportedFiles = exportedFiles @@ -1220,6 +1265,7 @@ async function executeShellInSandboxWithinBudget( if (cost && billableOutputError) { attachTrustedSandboxOutputCost(billableOutputError, cost) } + const endRelease = phases.start('release') try { await privateInputFiles?.cleanup() await lease.release() @@ -1228,6 +1274,7 @@ async function executeShellInSandboxWithinBudget( providerId: created.providerId, sandboxId, }) + endRelease() } } } @@ -1239,7 +1286,8 @@ export function executeShellInSandbox( req.timeoutMs, req.signal, Boolean(req.session && !req.meterUsage), - (signal) => executeShellInSandboxWithinBudget({ ...req, signal }) + (signal) => + withPhaseTimings((phases) => executeShellInSandboxWithinBudget({ ...req, signal }, phases)) ) } diff --git a/apps/sim/lib/execution/remote-sandbox/phase-timing.ts b/apps/sim/lib/execution/remote-sandbox/phase-timing.ts new file mode 100644 index 00000000000..8b17f8bf583 --- /dev/null +++ b/apps/sim/lib/execution/remote-sandbox/phase-timing.ts @@ -0,0 +1,38 @@ +/** + * Phases of one sandbox execution, in the order they run. `lease` spans the whole acquisition + * (session lock included); for a session, `lookup` and `cli` are the parts of it spent finding or + * creating the machine and verifying its deployment tooling. + */ +type SandboxPhase = + | 'resolve' + | 'access' + | 'lease' + | 'lookup' + | 'cli' + | 'prepare' + | 'run' + | 'collect' + | 'release' + +/** Wall-clock milliseconds per phase; a phase that did not finish is absent. */ +export type SandboxPhaseTimings = Partial> + +/** Accumulates per-phase wall time for one execution's log line. */ +export interface SandboxPhaseTimer { + readonly timings: SandboxPhaseTimings + /** Starts timing a phase; the returned function records its duration. */ + start(phase: SandboxPhase): () => void +} + +export function createSandboxPhaseTimer(): SandboxPhaseTimer { + const timings: SandboxPhaseTimings = {} + return { + timings, + start(phase) { + const startedAt = performance.now() + return () => { + timings[phase] = Math.round(performance.now() - startedAt) + } + }, + } +} diff --git a/apps/sim/lib/execution/remote-sandbox/session-sandbox.test.ts b/apps/sim/lib/execution/remote-sandbox/session-sandbox.test.ts index a38b777df7f..28502cf280b 100644 --- a/apps/sim/lib/execution/remote-sandbox/session-sandbox.test.ts +++ b/apps/sim/lib/execution/remote-sandbox/session-sandbox.test.ts @@ -821,6 +821,33 @@ describe('session sandbox lease', () => { expect(writes).toHaveBeenCalledTimes(firstWrites) }) + it('attributes a warm shell call’s wall time to the phase that spent it', async () => { + const { handle } = fakeSandbox('phase-timing') + const runCommand = handle.runCommand.bind(handle) + handle.runCommand = async (command, options) => { + await sleep(options.envs?.SIM_CLI_PATH ? 30 : 60) + return runCommand(command, options) + } + mockFindSessionSandbox.mockImplementation(async () => { + await sleep(40) + return handle + }) + + const result = await executeShellInSandbox({ + code: 'true', + envs: {}, + timeoutMs: 10_000, + session: { key: 'phase-timing', cli: CLI }, + }) + + const phases = result.phaseMs ?? {} + expect(result.sandboxSession).toBe('reused') + expect(phases.lookup).toBeGreaterThanOrEqual(38) + expect(phases.cli).toBeGreaterThanOrEqual(28) + expect(phases.run).toBeGreaterThanOrEqual(58) + expect(phases.lease).toBeGreaterThanOrEqual((phases.lookup ?? 0) + (phases.cli ?? 0)) + }) + it('pins shell CLI resolution ahead of caller environment paths', async () => { const { handle, calls } = fakeSandbox('shell-cli-path') mockFindSessionSandbox.mockResolvedValue(handle) diff --git a/apps/sim/lib/execution/remote-sandbox/session.ts b/apps/sim/lib/execution/remote-sandbox/session.ts index aba642ac799..cdd9cb01b10 100644 --- a/apps/sim/lib/execution/remote-sandbox/session.ts +++ b/apps/sim/lib/execution/remote-sandbox/session.ts @@ -3,6 +3,7 @@ import { getErrorMessage } from '@sim/utils/errors' import { createSandboxPricing } from '@/lib/billing/sandbox-pricing' import { mapSettledWithConcurrency } from '@/lib/core/utils/concurrency' import { type CreatedSandbox, createSelectedSandbox } from '@/lib/execution/remote-sandbox/create' +import type { SandboxPhaseTimer } from '@/lib/execution/remote-sandbox/phase-timing' import { resolveProvider } from '@/lib/execution/remote-sandbox/provider' import type { ResolvedSandbox } from '@/lib/execution/remote-sandbox/resolve' import { ensureSessionCli } from '@/lib/execution/remote-sandbox/session-cli' @@ -56,12 +57,14 @@ export async function ensureSessionSandbox(args: { session: SandboxSessionRequest signal: AbortSignal bootstrapTimeoutMs: number + phases?: SandboxPhaseTimer }): Promise { const { provider, kind, options, selected, session, signal } = args signal.throwIfAborted() if (!provider.findSessionSandbox) throw new Error('This deployment has no persistent workbench') const lifetimeMs = SESSION_SANDBOX_IDLE_MS + (options.lifetimeMs ?? 0) const requestedAtMs = Date.now() + const endLookup = args.phases?.start('lookup') const existing = await provider.findSessionSandbox(session.key, { ...(options.language ? { language: options.language } : {}), lifetimeMs, @@ -83,6 +86,7 @@ export async function ensureSessionSandbox(args: { true, provider ) + endLookup?.() // Before the abort check: a stopped caller still leaves this machine for the next call to // reuse, and a reused machine without history can never be certified. if (!existing) @@ -96,7 +100,9 @@ export async function ensureSessionSandbox(args: { await created.sandbox.extendLifetime?.(lifetimeMs) signal.throwIfAborted() if (session.cli) { + const endCli = args.phases?.start('cli') await ensureSessionCli(created.sandbox, session.cli, signal, args.bootstrapTimeoutMs) + endCli?.() } signal.throwIfAborted() return { created, status: existing ? 'reused' : 'created' } diff --git a/apps/sim/lib/execution/remote-sandbox/types.ts b/apps/sim/lib/execution/remote-sandbox/types.ts index 31dab9561ef..254b513d784 100644 --- a/apps/sim/lib/execution/remote-sandbox/types.ts +++ b/apps/sim/lib/execution/remote-sandbox/types.ts @@ -2,6 +2,7 @@ import type { CodePlaceholderRuntimeBinding } from '@/lib/execution/code-placeho import type { DurableSecretProvenance } from '@/lib/execution/durable-secret-provenance' import type { CodeLanguage } from '@/lib/execution/languages' import type { SandboxBuildError } from '@/lib/execution/remote-sandbox/build-errors' +import type { SandboxPhaseTimings } from '@/lib/execution/remote-sandbox/phase-timing' import type { SandboxSpec } from '@/lib/execution/remote-sandbox/spec' /** @@ -187,6 +188,8 @@ export interface SandboxExecutionResult { * is gone. */ sandboxSession?: 'created' | 'reused' + /** Wall time per execution phase, for the caller's log line; never part of a response. */ + phaseMs?: SandboxPhaseTimings } /** One harvested output file, carried as base64 with its decoded length. */ diff --git a/apps/sim/lib/function-execution/execute-request.ts b/apps/sim/lib/function-execution/execute-request.ts index cc99363f6e3..f0c4ba15b4d 100644 --- a/apps/sim/lib/function-execution/execute-request.ts +++ b/apps/sim/lib/function-execution/execute-request.ts @@ -2827,6 +2827,7 @@ export async function executeFunctionRequest( collectedFiles: shellCollectedFiles, cost: shellCost, sandboxSession: shellSandboxSession, + phaseMs: shellPhaseMs, } = await executeShellInSandbox({ code: resolvedCode, envs: shellEnvs, @@ -2851,6 +2852,8 @@ export async function executeFunctionRequest( sandboxId, succeeded: !shellError, executionTime, + sandboxSession: shellSandboxSession, + phaseMs: shellPhaseMs, }) if (shellError) { @@ -2981,6 +2984,7 @@ export async function executeFunctionRequest( collectedFiles: jsCollectedFiles, cost: sandboxCost, sandboxSession: jsSandboxSession, + phaseMs: jsPhaseMs, } = await executeInSandbox({ code: codeForE2B, language: CodeLanguage.JavaScript, @@ -3006,6 +3010,9 @@ export async function executeFunctionRequest( logger.info(`[${requestId}] E2B JS sandbox`, { sandboxId, succeeded: !e2bError, + executionTime, + sandboxSession: jsSandboxSession, + phaseMs: jsPhaseMs, }) if (e2bError) { @@ -3110,6 +3117,7 @@ export async function executeFunctionRequest( collectedFiles: pythonCollectedFiles, cost: sandboxCost, sandboxSession: pythonSandboxSession, + phaseMs: pythonPhaseMs, } = await executeInSandbox({ code: codeForE2B, language: CodeLanguage.Python, @@ -3134,6 +3142,9 @@ export async function executeFunctionRequest( logger.info(`[${requestId}] E2B Py sandbox`, { sandboxId, succeeded: !e2bError, + executionTime, + sandboxSession: pythonSandboxSession, + phaseMs: pythonPhaseMs, }) if (e2bError) { From c36b9a7366ec79bff189969a0256824497c19fef Mon Sep 17 00:00:00 2001 From: Waleed Latif Date: Mon, 2 Nov 2026 16:23:23 -0800 Subject: [PATCH 2/2] test(sandbox): time the unchanged-CLI warm path on a controlled clock --- .../execution/remote-sandbox/phase-timing.ts | 1 + .../remote-sandbox/session-sandbox.test.ts | 41 ++++++++++++------- 2 files changed, 28 insertions(+), 14 deletions(-) diff --git a/apps/sim/lib/execution/remote-sandbox/phase-timing.ts b/apps/sim/lib/execution/remote-sandbox/phase-timing.ts index 8b17f8bf583..ecc418075a2 100644 --- a/apps/sim/lib/execution/remote-sandbox/phase-timing.ts +++ b/apps/sim/lib/execution/remote-sandbox/phase-timing.ts @@ -24,6 +24,7 @@ export interface SandboxPhaseTimer { start(phase: SandboxPhase): () => void } +/** Creates a timer whose callbacks record rounded milliseconds; unfinished phases stay absent. */ export function createSandboxPhaseTimer(): SandboxPhaseTimer { const timings: SandboxPhaseTimings = {} return { diff --git a/apps/sim/lib/execution/remote-sandbox/session-sandbox.test.ts b/apps/sim/lib/execution/remote-sandbox/session-sandbox.test.ts index 28502cf280b..20562abee59 100644 --- a/apps/sim/lib/execution/remote-sandbox/session-sandbox.test.ts +++ b/apps/sim/lib/execution/remote-sandbox/session-sandbox.test.ts @@ -823,29 +823,42 @@ describe('session sandbox lease', () => { it('attributes a warm shell call’s wall time to the phase that spent it', async () => { const { handle } = fakeSandbox('phase-timing') + mockFindSessionSandbox.mockResolvedValue(handle) + const request = { + code: 'true', + envs: {}, + timeoutMs: 10_000, + session: { key: 'phase-timing', cli: CLI }, + } + await executeShellInSandbox(request) + + let nowMs = 0 + const clock = vi.spyOn(performance, 'now').mockImplementation(() => nowMs) + const writes = vi.fn(handle.writeFile.bind(handle)) + handle.writeFile = writes const runCommand = handle.runCommand.bind(handle) handle.runCommand = async (command, options) => { - await sleep(options.envs?.SIM_CLI_PATH ? 30 : 60) + nowMs += options.envs?.SIM_CLI_PATH ? 30 : 60 return runCommand(command, options) } mockFindSessionSandbox.mockImplementation(async () => { - await sleep(40) + nowMs += 40 return handle }) - const result = await executeShellInSandbox({ - code: 'true', - envs: {}, - timeoutMs: 10_000, - session: { key: 'phase-timing', cli: CLI }, - }) + try { + const result = await executeShellInSandbox(request) - const phases = result.phaseMs ?? {} - expect(result.sandboxSession).toBe('reused') - expect(phases.lookup).toBeGreaterThanOrEqual(38) - expect(phases.cli).toBeGreaterThanOrEqual(28) - expect(phases.run).toBeGreaterThanOrEqual(58) - expect(phases.lease).toBeGreaterThanOrEqual((phases.lookup ?? 0) + (phases.cli ?? 0)) + const phases = result.phaseMs ?? {} + expect(result.sandboxSession).toBe('reused') + expect(writes).not.toHaveBeenCalled() + expect(phases.lookup).toBe(40) + expect(phases.cli).toBe(30) + expect(phases.run).toBe(60) + expect(phases.lease).toBeGreaterThanOrEqual(70) + } finally { + clock.mockRestore() + } }) it('pins shell CLI resolution ahead of caller environment paths', async () => {