feat(adapter-utils): instrument sandbox sync with per-stage duration timers

Add tar -> upload -> extract duration timers around the git, workspace
overlay, and asset upload seams in prepareSandboxManagedRuntime, emitted
per artifact + per stage under the existing git_sync/config_sync phase
labels. Each line carries a placeholder transport tag (native|fallback,
default fallback) for later phases to populate. Observability only: no
transport behavior change. Establishes the measurement baseline for
before/after sync performance comparison.

Co-authored-by: Paperclip <noreply@paperclip.ing>

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.

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();
+  });
+});

packages/adapter-utils/src/runtime-progress.ts

@@ -39,6 +39,75 @@ export interface RuntimeStatusUpdate {
 
 export type RuntimeStatusSink = (update: RuntimeStatusUpdate) => void | Promise<void>;
 
+/**
+ * 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<T>(stage: string, fn: () => Promise<T>): Promise<T>;
+  /**
+   * 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<void>;
+}
+
+/**
+ * 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;

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.

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<PreparedSandboxManagedRuntime> {
+  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();
     }
   });