diff --git a/packages/adapter-utils/src/index.ts b/packages/adapter-utils/src/index.ts index dc5db8865f0..6de4a666e54 100644 --- a/packages/adapter-utils/src/index.ts +++ b/packages/adapter-utils/src/index.ts @@ -65,7 +65,7 @@ export { redactCommandText, } from "./command-redaction.js"; export { buildSandboxNpmInstallCommand } from "./sandbox-install-command.js"; -export { createRuntimeProgressReporter } from "./runtime-progress.js"; +export { createRuntimeProgressReporter, createSyncStageTimer } from "./runtime-progress.js"; export type { RuntimeProgressSink, RuntimeProgressPhase, @@ -76,6 +76,9 @@ export type { RuntimeStatusPhase, RuntimeStatusSink, RuntimeStatusUpdate, + SandboxSyncTransport, + SyncStageTimer, + SyncStageTimerOptions, } from "./runtime-progress.js"; export { inferOpenAiCompatibleBiller } from "./billing.js"; // Keep the root adapter-utils entry browser-safe because the UI imports it. diff --git a/packages/adapter-utils/src/runtime-progress.test.ts b/packages/adapter-utils/src/runtime-progress.test.ts index 24048404e73..80c2b4d92f5 100644 --- a/packages/adapter-utils/src/runtime-progress.test.ts +++ b/packages/adapter-utils/src/runtime-progress.test.ts @@ -1,5 +1,5 @@ import { describe, expect, it } from "vitest"; -import { createRuntimeProgressReporter } from "./runtime-progress.js"; +import { createRuntimeProgressReporter, createSyncStageTimer } from "./runtime-progress.js"; const MB = 1024 * 1024; @@ -279,3 +279,110 @@ describe("createRuntimeProgressReporter", () => { expect(failLines.at(-1)).toContain("failed at 20%"); }); }); + +describe("createSyncStageTimer", () => { + it("emits a per-stage + total duration line with the phase, artifact and transport tag", async () => { + const clock = makeClock(); + const lines: string[] = []; + const timer = createSyncStageTimer({ + sink: (line) => { + lines.push(line); + }, + phase: "git_sync", + artifact: "git history", + now: clock.now, + }); + + await timer.time("tar", async () => { + clock.advance(12); + }); + await timer.time("upload", async () => { + clock.advance(340); + }); + await timer.time("extract", async () => { + clock.advance(88); + }); + await timer.finish(); + + expect(lines).toEqual([ + "[paperclip] sync git_sync git history: tar 12ms, upload 340ms, extract 88ms (total 440ms) [transport=fallback]\n", + ]); + }); + + it("defaults the transport tag to fallback and honors an explicit native tag", async () => { + const clock = makeClock(); + const native: string[] = []; + const timer = createSyncStageTimer({ + sink: (line) => { + native.push(line); + }, + phase: "config_sync", + artifact: "workspace", + transport: "native", + now: clock.now, + }); + await timer.time("upload", async () => { + clock.advance(5); + }); + await timer.finish(); + expect(native).toEqual([ + "[paperclip] sync config_sync workspace: upload 5ms (total 5ms) [transport=native]\n", + ]); + }); + + it("returns the timed function's result and records duration even when it throws", async () => { + const clock = makeClock(); + const lines: string[] = []; + const timer = createSyncStageTimer({ + sink: (line) => { + lines.push(line); + }, + phase: "config_sync", + artifact: "skills", + now: clock.now, + }); + + const value = await timer.time("tar", async () => { + clock.advance(7); + return 42; + }); + expect(value).toBe(42); + + await expect( + timer.time("upload", async () => { + clock.advance(3); + throw new Error("upload boom"); + }), + ).rejects.toThrow("upload boom"); + + await timer.finish(); + expect(lines).toEqual([ + "[paperclip] sync config_sync skills: tar 7ms, upload 3ms (total 10ms) [transport=fallback]\n", + ]); + }); + + it("is idempotent on finish and a no-op with no sink or no timed stage", async () => { + const lines: string[] = []; + const timer = createSyncStageTimer({ + sink: (line) => { + lines.push(line); + }, + phase: "git_sync", + artifact: "git history", + now: makeClock().now, + }); + // No stage timed → nothing to report. + await timer.finish(); + await timer.finish(); + expect(lines).toEqual([]); + + // Disabled sink → never throws, emits nothing. + const disabled = createSyncStageTimer({ + sink: undefined, + phase: "git_sync", + artifact: "git history", + }); + await disabled.time("tar", async () => {}); + await expect(disabled.finish()).resolves.toBeUndefined(); + }); +}); diff --git a/packages/adapter-utils/src/runtime-progress.ts b/packages/adapter-utils/src/runtime-progress.ts index e217927675b..90b2c2db75a 100644 --- a/packages/adapter-utils/src/runtime-progress.ts +++ b/packages/adapter-utils/src/runtime-progress.ts @@ -39,6 +39,75 @@ export interface RuntimeStatusUpdate { export type RuntimeStatusSink = (update: RuntimeStatusUpdate) => void | Promise; +/** + * Which transport carried a sync artifact's bytes. Phase 0 (PAP-2952) always + * records the base64-shell `"fallback"`; later phases populate `"native"` once + * the sandbox seam gains a direct upload verb. Placeholder tag on the timer line + * so Phase 6 can compare fallback-vs-native durations from the same log shape. + */ +export type SandboxSyncTransport = "native" | "fallback"; + +export interface SyncStageTimerOptions { + /** Where the aggregated duration line is written (the run log). Undefined = disabled. */ + sink: RuntimeProgressSink | undefined; + /** Reused status-phase label, e.g. "git_sync" / "config_sync". */ + phase: RuntimeStatusPhase; + /** Per-artifact label, e.g. "git history", "workspace", or an asset key. */ + artifact: string; + /** Transport tag placeholder; defaults to "fallback" (see {@link SandboxSyncTransport}). */ + transport?: SandboxSyncTransport; + /** Injectable clock for deterministic tests. Default `Date.now`. */ + now?: () => number; +} + +export interface SyncStageTimer { + /** + * Run `fn`, recording its wall-clock duration under `stage`. Returns `fn`'s + * result and re-throws its error; the duration is recorded either way so a + * failing stage still contributes to the breakdown. + */ + time(stage: string, fn: () => Promise): Promise; + /** + * Emit the aggregated per-stage + total duration line for this artifact. + * Idempotent; a no-op when no sink was provided or no stage was timed. + */ + finish(): Promise; +} + +/** + * Duration instrumentation for a single sync artifact's tar → upload → extract + * seams. Each stage is wrapped with `time()`; `finish()` emits one legible line + * carrying the per-stage durations, the total, and the transport tag — the + * measurement baseline Phase 6 compares before/after. + */ +export function createSyncStageTimer(options: SyncStageTimerOptions): SyncStageTimer { + const now = options.now ?? Date.now; + const transport: SandboxSyncTransport = options.transport ?? "fallback"; + const stages: { stage: string; durationMs: number }[] = []; + let finished = false; + + return { + async time(stage, fn) { + const startedAt = now(); + try { + return await fn(); + } finally { + stages.push({ stage, durationMs: Math.max(0, Math.round(now() - startedAt)) }); + } + }, + async finish() { + if (finished) return; + finished = true; + if (!options.sink || stages.length === 0) return; + const totalMs = stages.reduce((sum, entry) => sum + entry.durationMs, 0); + const breakdown = stages.map((entry) => `${entry.stage} ${entry.durationMs}ms`).join(", "); + await options.sink( + `[paperclip] sync ${options.phase} ${options.artifact}: ${breakdown} (total ${totalMs}ms) [transport=${transport}]\n`, + ); + }, + }; +} + export interface RuntimeProgressReporterOptions { sink: RuntimeProgressSink; phase: RuntimeProgressPhase; diff --git a/packages/adapter-utils/src/sandbox-managed-runtime.test.ts b/packages/adapter-utils/src/sandbox-managed-runtime.test.ts index e2f7237a928..b4ea62773c8 100644 --- a/packages/adapter-utils/src/sandbox-managed-runtime.test.ts +++ b/packages/adapter-utils/src/sandbox-managed-runtime.test.ts @@ -225,6 +225,7 @@ describe("sandbox managed runtime", () => { }, }; const runtimeStatuses: Array<{ phase: string; message: string }> = []; + const progressLines: string[] = []; const prepared = await prepareSandboxManagedRuntime({ spec: { @@ -238,6 +239,9 @@ describe("sandbox managed runtime", () => { adapterKey: "test-adapter", client, workspaceLocalDir: localWorkspaceDir, + onProgress: (line) => { + progressLines.push(line); + }, onRuntimeProgress: async (status) => { runtimeStatuses.push({ phase: status.phase, message: status.message }); }, @@ -300,6 +304,15 @@ describe("sandbox managed runtime", () => { status.phase === "export" && /^Exporting git history from sandbox: 100% \(\d+\.\d\/\d+\.\d MB\)$/.test(status.message) ))).toBe(true); + + // Sync-duration timers cover the git and workspace-overlay phases too + // (PAP-2952 Phase 0): one tar → upload → extract breakdown per artifact. + expect(progressLines.some((line) => + /^\[paperclip\] sync git_sync git history: tar \d+ms, upload \d+ms, extract \d+ms \(total \d+ms\) \[transport=fallback\]\n$/.test(line), + )).toBe(true); + expect(progressLines.some((line) => + /^\[paperclip\] sync config_sync workspace: tar \d+ms, upload \d+ms, extract \d+ms \(total \d+ms\) \[transport=fallback\]\n$/.test(line), + )).toBe(true); }); it("repairs stale host index deletions when the sandbox restores a clean git worktree", async () => { @@ -757,6 +770,18 @@ describe("sandbox managed runtime", () => { const uploadAssetLines = lines.filter((line) => line.includes("Syncing skills to sandbox")); expect(uploadWorkspaceLines.length).toBeGreaterThan(0); expect(uploadAssetLines.length).toBeGreaterThan(0); + + // Per-artifact sync-duration timer lines (PAP-2952 Phase 0): tar → upload → + // extract breakdown + total, tagged with the placeholder transport, one per + // synced artifact (workspace + the skills asset here). + const workspaceTimer = lines.find((line) => + /^\[paperclip\] sync config_sync workspace: tar \d+ms, upload \d+ms, extract \d+ms \(total \d+ms\) \[transport=fallback\]\n$/.test(line), + ); + const assetTimer = lines.find((line) => + /^\[paperclip\] sync config_sync skills: tar \d+ms, upload \d+ms, extract \d+ms \(total \d+ms\) \[transport=fallback\]\n$/.test(line), + ); + expect(workspaceTimer).toBeDefined(); + expect(assetTimer).toBeDefined(); // 100 reported increments must be throttled to at most ~one line per 10% step. expect(uploadWorkspaceLines.length).toBeLessThanOrEqual(11); // Reaches 100% and shows the MB breakdown. diff --git a/packages/adapter-utils/src/sandbox-managed-runtime.ts b/packages/adapter-utils/src/sandbox-managed-runtime.ts index ccce1d13120..7cbf2808280 100644 --- a/packages/adapter-utils/src/sandbox-managed-runtime.ts +++ b/packages/adapter-utils/src/sandbox-managed-runtime.ts @@ -18,11 +18,13 @@ import { import { captureDirectorySnapshot, mergeDirectoryWithBaseline } from "./workspace-restore-merge.js"; import { createRuntimeProgressReporter, + createSyncStageTimer, type RuntimeProgressDirection, type RuntimeProgressPhase, type RuntimeProgressSink, type RuntimeStatusPhase, type RuntimeStatusSink, + type SandboxSyncTransport, } from "./runtime-progress.js"; import { isRelativePathOrDescendant, shouldExcludePath } from "./exclude-patterns.js"; @@ -494,7 +496,13 @@ export async function prepareSandboxManagedRuntime(input: { // child task wires it into writeFile/readFile. onProgress?: RuntimeProgressSink; onRuntimeProgress?: RuntimeStatusSink; + // Placeholder transport tag for the sync-duration instrumentation. Phase 0 + // (PAP-2952) always records the base64-shell "fallback"; later phases set + // "native" once the seam gains a direct upload verb. Only labels the timer + // lines — it does not change transport behavior. + syncTransport?: SandboxSyncTransport; }): Promise { + const syncTransport: SandboxSyncTransport = input.syncTransport ?? "fallback"; const workspaceRemoteDir = input.workspaceRemoteDir ?? input.spec.remoteCwd; const runtimeRootDir = path.posix.join(workspaceRemoteDir, ".paperclip-runtime", input.adapterKey); const gitSnapshot = await readGitWorkspaceSnapshot(input.workspaceLocalDir); @@ -525,17 +533,25 @@ export async function prepareSandboxManagedRuntime(input: { ]); if (gitSnapshot) { await emitRuntimeStatus(input.onRuntimeProgress, "git_sync", "Syncing git history to sandbox"); + const gitTimer = createSyncStageTimer({ + sink: input.onProgress, + phase: "git_sync", + artifact: "git history", + transport: syncTransport, + }); await withShallowGitWorkspaceClone({ localDir: input.workspaceLocalDir, snapshot: gitSnapshot, }, async (cloneDir) => { const gitTarPath = path.join(tempDir, "git-workspace.tar"); - await createTarballFromDirectory({ - localDir: cloneDir, - archivePath: gitTarPath, - exclude: [".paperclip-runtime"], + const gitTarBytes = await gitTimer.time("tar", async () => { + await createTarballFromDirectory({ + localDir: cloneDir, + archivePath: gitTarPath, + exclude: [".paperclip-runtime"], + }); + return fs.readFile(gitTarPath); }); - const gitTarBytes = await fs.readFile(gitTarPath); const remoteGitTar = path.posix.join(runtimeRootDir, "git-workspace-upload.tar"); await input.client.makeDir(runtimeRootDir); const gitUpload = makeTransferProgress( @@ -545,9 +561,11 @@ export async function prepareSandboxManagedRuntime(input: { "git history", { sink: input.onRuntimeProgress, phase: "git_sync" }, ); - await input.client.writeFile(remoteGitTar, toArrayBuffer(gitTarBytes), gitUpload.options); - await gitUpload.finish(gitTarBytes.byteLength, gitTarBytes.byteLength); - await input.client.run( + await gitTimer.time("upload", async () => { + await input.client.writeFile(remoteGitTar, toArrayBuffer(gitTarBytes), gitUpload.options); + await gitUpload.finish(gitTarBytes.byteLength, gitTarBytes.byteLength); + }); + await gitTimer.time("extract", () => input.client.run( `sh -c ${shellQuote( `mkdir -p ${shellQuote(workspaceRemoteDir)} && ` + `find ${shellQuote(workspaceRemoteDir)} -mindepth 1 -maxdepth 1 ${preserveFindArgs([".paperclip-runtime"])} -exec rm -rf -- {} + && ` + @@ -555,27 +573,36 @@ export async function prepareSandboxManagedRuntime(input: { `rm -f ${shellQuote(remoteGitTar)}`, )}`, { timeoutMs: input.spec.timeoutMs }, - ); + )); }); + await gitTimer.finish(); } const workspaceTarPath = path.join(tempDir, "workspace.tar"); const workspaceArchiveDir = gitSnapshot ? path.join(tempDir, "workspace-overlay") : input.workspaceLocalDir; await emitRuntimeStatus(input.onRuntimeProgress, "config_sync", "Syncing workspace to sandbox"); - if (gitSnapshot) { - await copySelectedWorkspaceEntries({ - sourceDir: input.workspaceLocalDir, - targetDir: workspaceArchiveDir, - relativePaths: gitSnapshot.overlayPaths, - exclude: workspaceArchiveExclude, + const workspaceTimer = createSyncStageTimer({ + sink: input.onProgress, + phase: "config_sync", + artifact: "workspace", + transport: syncTransport, + }); + const workspaceTarBytes = await workspaceTimer.time("tar", async () => { + if (gitSnapshot) { + await copySelectedWorkspaceEntries({ + sourceDir: input.workspaceLocalDir, + targetDir: workspaceArchiveDir, + relativePaths: gitSnapshot.overlayPaths, + exclude: workspaceArchiveExclude, + }); + } + await createTarballFromDirectory({ + localDir: workspaceArchiveDir, + archivePath: workspaceTarPath, + exclude: gitSnapshot ? undefined : workspaceArchiveExclude, }); - } - await createTarballFromDirectory({ - localDir: workspaceArchiveDir, - archivePath: workspaceTarPath, - exclude: gitSnapshot ? undefined : workspaceArchiveExclude, + return fs.readFile(workspaceTarPath); }); - const workspaceTarBytes = await fs.readFile(workspaceTarPath); const remoteWorkspaceTar = path.posix.join(runtimeRootDir, "workspace-upload.tar"); await input.client.makeDir(runtimeRootDir); const workspaceUpload = makeTransferProgress( @@ -585,12 +612,14 @@ export async function prepareSandboxManagedRuntime(input: { "workspace", { sink: input.onRuntimeProgress, phase: "config_sync" }, ); - await input.client.writeFile( - remoteWorkspaceTar, - toArrayBuffer(workspaceTarBytes), - workspaceUpload.options, - ); - await workspaceUpload.finish(workspaceTarBytes.byteLength, workspaceTarBytes.byteLength); + await workspaceTimer.time("upload", async () => { + await input.client.writeFile( + remoteWorkspaceTar, + toArrayBuffer(workspaceTarBytes), + workspaceUpload.options, + ); + await workspaceUpload.finish(workspaceTarBytes.byteLength, workspaceTarBytes.byteLength); + }); const extractWorkspaceTarCommand = gitSnapshot ? `mkdir -p ${shellQuote(workspaceRemoteDir)} && ` + `tar -xf ${shellQuote(remoteWorkspaceTar)} -C ${shellQuote(workspaceRemoteDir)} && ` + @@ -599,10 +628,11 @@ export async function prepareSandboxManagedRuntime(input: { `find ${shellQuote(workspaceRemoteDir)} -mindepth 1 -maxdepth 1 ${preserveFindArgs([...preservedNames])} -exec rm -rf -- {} + && ` + `tar -xf ${shellQuote(remoteWorkspaceTar)} -C ${shellQuote(workspaceRemoteDir)} && ` + `rm -f ${shellQuote(remoteWorkspaceTar)}`; - await input.client.run( + await workspaceTimer.time("extract", () => input.client.run( `sh -c ${shellQuote(extractWorkspaceTarCommand)}`, { timeoutMs: input.spec.timeoutMs }, - ); + )); + await workspaceTimer.finish(); if (gitSnapshot) { await removeDeletedPathsInSandbox({ client: input.client, @@ -614,14 +644,22 @@ export async function prepareSandboxManagedRuntime(input: { for (const asset of input.assets ?? []) { await emitRuntimeStatus(input.onRuntimeProgress, "config_sync", "Syncing runtime assets to sandbox"); + const assetTimer = createSyncStageTimer({ + sink: input.onProgress, + phase: "config_sync", + artifact: asset.key, + transport: syncTransport, + }); const assetTarPath = path.join(tempDir, `${asset.key}.tar`); - await createTarballFromDirectory({ - localDir: asset.localDir, - archivePath: assetTarPath, - followSymlinks: asset.followSymlinks, - exclude: asset.exclude, + const assetTarBytes = await assetTimer.time("tar", async () => { + await createTarballFromDirectory({ + localDir: asset.localDir, + archivePath: assetTarPath, + followSymlinks: asset.followSymlinks, + exclude: asset.exclude, + }); + return fs.readFile(assetTarPath); }); - const assetTarBytes = await fs.readFile(assetTarPath); const remoteAssetDir = path.posix.join(runtimeRootDir, asset.key); const remoteAssetTar = path.posix.join(runtimeRootDir, `${asset.key}-upload.tar`); const assetUpload = makeTransferProgress( @@ -631,30 +669,33 @@ export async function prepareSandboxManagedRuntime(input: { asset.key, { sink: input.onRuntimeProgress, phase: "config_sync" }, ); - await input.client.writeFile(remoteAssetTar, toArrayBuffer(assetTarBytes), assetUpload.options); - await assetUpload.finish(assetTarBytes.byteLength, assetTarBytes.byteLength); - for (const stageFile of asset.provision?.stageFiles ?? []) { - const stageBytes = typeof stageFile.contents === "string" - ? Buffer.from(stageFile.contents) - : stageFile.contents; - const safeName = stageFile.name; - if (/[\\/]|\.\.(\.|$)/.test(safeName) || safeName === "..") { - throw new Error(`provision stageFile.name must be a simple basename, got: ${safeName}`); + await assetTimer.time("upload", async () => { + await input.client.writeFile(remoteAssetTar, toArrayBuffer(assetTarBytes), assetUpload.options); + await assetUpload.finish(assetTarBytes.byteLength, assetTarBytes.byteLength); + for (const stageFile of asset.provision?.stageFiles ?? []) { + const stageBytes = typeof stageFile.contents === "string" + ? Buffer.from(stageFile.contents) + : stageFile.contents; + const safeName = stageFile.name; + if (/[\\/]|\.\.(\.|$)/.test(safeName) || safeName === "..") { + throw new Error(`provision stageFile.name must be a simple basename, got: ${safeName}`); + } + await input.client.writeFile( + path.posix.join(runtimeRootDir, safeName), + toArrayBuffer(stageBytes), + ); } - await input.client.writeFile( - path.posix.join(runtimeRootDir, safeName), - toArrayBuffer(stageBytes), - ); - } + }); const extractCommand = asset.provision?.extractCommand?.({ assetTarPath: remoteAssetTar, assetDir: remoteAssetDir, runtimeRootDir, }) ?? buildDefaultExtractRuntimeAssetCommand({ remoteAssetDir, remoteAssetTar }); - await input.client.run( + await assetTimer.time("extract", () => input.client.run( `sh -c ${shellQuote(extractCommand)}`, { timeoutMs: input.spec.timeoutMs }, - ); + )); + await assetTimer.finish(); } });