perf(workspaces): record per-phase timings for workspace saves (#19472)

## Thinking Path

> - Paperclip is the open source app people use to manage AI agents for
work.
> - Native runs in a sandbox save the workspace to object storage. A run
saves before it starts work and again at the end.
> - A save of a large repository takes 150 to 250 seconds when it runs
alone. When several large saves overlap, each save takes 510 to 900
seconds.
> - A slow save before the run starts delays the agent. It also gives a
deploy a wider window to interrupt the run.
> - The save operation records only a start time and an end time. It
does not show which phase uses the time: in-sandbox capture, provider
download, re-hash, encrypted upload, or publication.
> - Without that data, a speed fix is a guess. Each possible bottleneck
needs a different fix.
> - This pull request records a bounded duration for each phase in the
save operation's local metadata.
> - The benefit is that one busy window on a deployment identifies the
bottleneck. Then a targeted fix can be measured.

## Linked Issues or Issue Description

**Is your feature request related to a problem?**
Saves of large repository workspaces are slow, and a save does not
record where the time goes. On one deployment, saves of a 460MB
workspace archive (a full repository with history) took 150 to 250
seconds when they ran alone. During a window where eight large saves
overlapped, each save took 510 to 895 seconds. Saves of small
repositories in the same window stayed at 2 to 6 seconds. The operation
row has only `startedAt` and `finishedAt`, so the contended resource is
unknown. It can be the sandbox CPU, the provider download, or server
disk and network.

**Describe the solution you'd like**
Each save invocation records per-phase durations and the archive size in
the operation's metadata, for both outcomes.

**Describe alternatives you've considered**
Changes to the speed of a single phase without phase data. A local
profile of one capture showed that `git fsck --full` on the archived
history uses about half of the capture time. But full object integrity
is a tested requirement, and the cheaper `--connectivity-only` check
does not meet it. A larger delta-base cache gave no gain. A threaded
check helps only on sandboxes with more than one core. Also, the overlap
slowdown can come from the server, not the sandbox. A fix chosen without
phase data could miss the real bottleneck.

Related: #19444 (skip redundant saves on follow-up runs), #19458
(overlap file hashing in capture), #19462 (bounded bootstrap retry after
a closed runtime listener).

## What Changed

- `captureRemoteWorkspaceArchive` accepts an optional `timing` record.
It writes `captureMs` (helper install and in-sandbox capture),
`transferMs` (provider download), `verifyMs` (server re-hash),
`byteSize`, and `entries` as each phase ends.
- `saveRemoteWorkspace` adds `uploadMs` (encrypt, hash, and store) and
`publishMs` (manifest read and authority commit). It also sets
`reusedUpload` when it reuses an earlier upload.
- `settleSaveInvocation` writes a `saveTiming` record
(`paperclip.remote-workspace-save-timing.v1`) with `outcome`, `totalMs`,
and the finished phases. It writes the record on success and on failure.
A failed save keeps the phases that it finished.
- The record holds only numbers, a fixed outcome, and a timestamp. It
holds no paths or provider text. It stays in the instance database
(`workspace_operations.metadata`), so it is not Telemetry.

## Verification

- Extended `retains the writer and previous snapshot when object storage
fails` in `server/src/services/remote-workspaces.integration.test.ts`.
After the storage failure, the `final` operation has a `failed` timing
with capture, transfer, and verify phases and no upload phase. After the
retry, it has a `succeeded` timing with every phase.
- Red/green: with the source change reverted, the test fails (`expected
[ undefined ] to deeply equal [ { …(9) } ]`). With the change, it
passes.
- `npx vitest run src/services/remote-workspaces.integration.test.ts -t
"object storage fails"` passes.
- `npx tsc --noEmit -p server` passes.
- A reviewer can read the record through `GET
/api/heartbeat-runs/:runId/workspace-operations`
(`metadata.saveTiming`).

## Risks

- Low risk. The change adds metadata only. It does not change save
order, fencing, retries, or archive bytes.
- The latest settled invocation replaces `saveTiming`. Concurrent
invocations of the same boundary keep only the last record. That is
acceptable for diagnosis.
- `performance.now()` calls add negligible cost.

## Model Used

- Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, through Claude Code
with tool use (shell, browser for read-only staging GETs, code
execution).

## Checklist

- [x] I have included a thinking path that traces from project context
to this change
- [x] I have specified the model used (with version and capability
details)
- [x] I have checked ROADMAP.md and confirmed this PR does not duplicate
planned core work
- [x] I have searched GitHub for duplicate or related PRs and linked
them above
- [x] I have either (a) linked existing issues with `Fixes: #` / `Closes
#` / `Refs #` OR (b) described the issue in-PR following the relevant
issue template
- [x] I have not referenced internal/instance-local Paperclip issues or
links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip`
URLs)
- [x] My branch name describes the change (e.g. `docs/...`, `fix/...`)
and contains no internal Paperclip ticket id or instance-derived details
- [x] I have run tests locally and they pass
- [x] I have added or updated tests where applicable
- [x] I have updated relevant documentation to reflect my changes
- [x] I have considered and documented any risks above
- [ ] All Paperclip CI gates are green
- [ ] Greptile is 5/5 with no open P2s, recommendations, or follow-ups
- [x] I will address all Greptile and reviewer comments before
requesting merge

🤖 Generated with [Claude Code](https://claude.com/claude-code)

---------

Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>

server/src/services/remote-workspace-transport.ts

@@ -398,9 +398,29 @@ export async function cleanupRemoteWorkspaceArchive(input: {
   await command(input.target, "cleanup", ["-e", script, input.remoteCwd, input.operationId], undefined, 10_000);
 }
 
+/**
+ * Wall-clock milliseconds for each save phase, filled in as each phase ends so a
+ * failed save still reports the phases it finished. It holds only durations and
+ * archive counts, never paths or provider text.
+ */
+export type RemoteWorkspaceSavePhaseTiming = {
+  /** Archive helper install plus in-sandbox capture. */
+  captureMs?: number;
+  /** Provider download of the captured archive. */
+  transferMs?: number;
+  /** Server-side re-hash of the downloaded archive. */
+  verifyMs?: number;
+  byteSize?: number;
+  entries?: number;
+};
+
+const elapsedSince = (started: number) => Math.max(0, Math.round(performance.now() - started));
+
 export async function captureRemoteWorkspaceArchive(input: {
-  target: RemoteWorkspaceTarget; remoteCwd: string; operationId: string;
+  target: RemoteWorkspaceTarget; remoteCwd: string; operationId: string; timing?: RemoteWorkspaceSavePhaseTiming;
 }) {
+  const timing = input.timing ?? {};
+  const captureStarted = performance.now();
   const staged = await installArchiveHelper(input.target, input.remoteCwd, input.operationId);
   // Publish the archive and receipt as one immutable directory. Concurrent
   // invocations own separate attempts; no invocation unlinks another's archive.
@@ -444,14 +464,20 @@ export async function captureRemoteWorkspaceArchive(input: {
   };
   if (!["legacy", "captured"].includes(layout) || !/^[a-f0-9]{64}$/.test(receipt.manifestDigest) || !/^[a-f0-9]{64}$/.test(receipt.sha256)
     || !Number.isSafeInteger(receipt.byteSize) || receipt.byteSize <= 0) throw new Error("remote_workspace_capture_receipt_invalid");
+  timing.captureMs = elapsedSince(captureStarted); timing.byteSize = receipt.byteSize;
+  if (Number.isSafeInteger(receipt.entries) && receipt.entries >= 0) timing.entries = receipt.entries;
   const root = await mkdtemp(path.join(os.tmpdir(), "paperclip-workspace-upload-"));
   const archivePath = path.join(root, "workspace.pcws");
   try {
+    const transferStarted = performance.now();
     await transferArchive(input.target, "syncOut", [{ operationId: input.operationId,
       files: [{ kind: "file", sourcePath: layout === "captured" ? path.posix.join(staged.directory, "captured", "workspace.pcws") : staged.archive, targetPath: archivePath }],
     }], receipt.byteSize);
+    timing.transferMs = elapsedSince(transferStarted);
+    const verifyStarted = performance.now();
     const hash = createHash("sha256"); let bytes = 0;
     for await (const chunk of createReadStream(archivePath)) { hash.update(chunk); bytes += chunk.length; }
+    timing.verifyMs = elapsedSince(verifyStarted);
     if (hash.digest("hex") !== receipt.sha256 || bytes !== receipt.byteSize) throw new Error("remote_workspace_capture_transfer_mismatch");
     return { ...receipt, archivePath, cleanup: () => rm(root, { recursive: true, force: true }) };
   } catch (error) {

server/src/services/remote-workspaces.integration.test.ts

@@ -1115,9 +1115,26 @@ suite("remote workspace lifecycle with real Postgres and independent filesystem
     expect(readRemoteWorkspaceAuthority((await workspace(reserved.id)).metadata)).toMatchObject({ dirty: true, writerRunId: ids.run,
       snapshotId: readRemoteWorkspaceAuthority(prepared.workspace.metadata)!.snapshotId });
     expect((await fs.readdir(path.join(prepared.remoteRoot, ".paperclip-runtime", "workspace-snapshots"))).length).toBe(1);
-    const saved = await saveRemoteWorkspace({ db, storage, workspace: await workspace(reserved.id), runId: ids.run,
+    // Each settled save records where its time went: the failed upload keeps the
+    // phases it finished, and the retry of the same boundary records every phase.
+    const finalTiming = async () => (await db.select().from(workspaceOperations).where(and(
+      eq(workspaceOperations.executionWorkspaceId, reserved.id), eq(workspaceOperations.phase, "remote_workspace_snapshot"),
+      sql`${workspaceOperations.metadata}->>'boundary' = 'final'`))).map(save => save.metadata?.saveTiming);
+    const duration = expect.any(Number), archive = { byteSize: expect.any(Number), entries: expect.any(Number) };
+    expect(await finalTiming()).toEqual([{ schema: "paperclip.remote-workspace-save-timing.v1", outcome: "failed", totalMs: duration,
+      captureMs: duration, transferMs: duration, verifyMs: duration, ...archive, at: expect.any(String) }]);
+    const beforeSuccess = await workspace(reserved.id);
+    const saved = await saveRemoteWorkspace({ db, storage, workspace: beforeSuccess, runId: ids.run,
       lease: prepared.lease, target: first, assertOwned: async () => undefined });
     expect(saved.generation).toBe(2);
+    const [succeededTiming] = await finalTiming();
+    // A lost-reply replay of the committed save keeps the measured record.
+    await expect(saveRemoteWorkspace({ db, storage, workspace: beforeSuccess, runId: ids.run,
+      lease: prepared.lease, target: first, assertOwned: async () => undefined })).resolves.toMatchObject({ snapshotId: saved.snapshotId });
+    expect(await finalTiming()).toEqual([succeededTiming]);
+    expect(await finalTiming()).toEqual([{ schema: "paperclip.remote-workspace-save-timing.v1", outcome: "succeeded", totalMs: duration,
+      captureMs: duration, transferMs: duration, verifyMs: duration, uploadMs: duration, publishMs: duration, ...archive,
+      at: expect.any(String) }]);
     expect(await fs.readdir(path.join(prepared.remoteRoot, ".paperclip-runtime", "workspace-snapshots"))).toEqual([]);
   }, 60_000);
 
@@ -1224,9 +1241,12 @@ suite("remote workspace lifecycle with real Postgres and independent filesystem
       .rejects.toThrow("remote_workspace_snapshot_operation_binding_changed");
     expect(upload).not.toHaveBeenCalled();
     const [held] = await db.select().from(workspaceOperations).where(eq(workspaceOperations.id, poisoned!.id));
-    const { saveWork, ...originalMetadata } = held!.metadata!;
+    const { saveWork, saveTiming, ...originalMetadata } = held!.metadata!;
     expect(originalMetadata).toEqual(poisoned!.metadata);
     expect(saveWork).toMatchObject({ activeIds: [], unknown: true, quiescedAt: expect.any(String) });
+    // The refused invocation records only its own failed duration; it never captured or uploaded.
+    expect(saveTiming).toEqual({ schema: "paperclip.remote-workspace-save-timing.v1", outcome: "failed",
+      totalMs: expect.any(Number), at: expect.any(String) });
     expect(Number.isFinite(Date.parse((saveWork as { quiescedAt: string }).quiescedAt))).toBe(true);
     expect(await db.select().from(executionWorkspaceSnapshots).where(eq(executionWorkspaceSnapshots.sourceOperationId, poisoned!.id)))
       .toHaveLength(0);

server/src/services/remote-workspaces.ts

@@ -28,6 +28,7 @@ import {
   captureRemoteWorkspaceArchive, cleanupRemoteWorkspaceArchive, prepareRemoteWorkspaceDirectory, prepareRemoteRepository, remoteWorkspaceRepositoryPath,
   RemoteWorkspaceOperationTimeoutError, RemoteWorkspacePreparationTimeoutError, remoteWorkspaceFailureCause,
   requireRemoteWorkspaceTarget, restoreRemoteWorkspaceDirectory, RemoteWorkspaceRestoreError, type RemoteWorkspaceRestoreStep,
+  type RemoteWorkspaceSavePhaseTiming,
 } from "./remote-workspace-transport.js";
 import {
   beginWorkspaceSnapshot, getWorkspaceSnapshot, loadWorkspaceSnapshotArchive, uploadWorkspaceSnapshot,
@@ -46,6 +47,16 @@ type Workspace = Pick<typeof executionWorkspaces.$inferSelect, "id" | "companyId
 type Transaction = Parameters<Parameters<Db["transaction"]>[0]>[0];
 const object = (value: unknown): Record<string, unknown> => value && typeof value === "object" && !Array.isArray(value) ? value as Record<string, unknown> : {};
 const SAVE_WORK_SCHEMA = "paperclip.remote-workspace-save-work.v1";
+const SAVE_TIMING_SCHEMA = "paperclip.remote-workspace-save-timing.v1";
+
+/** Per-phase durations of the latest settled save invocation, kept in the operation's local metadata. */
+type RemoteWorkspaceSaveTiming = RemoteWorkspaceSavePhaseTiming & {
+  /** Encrypt, hash, and store the archive (zero work when a prior upload is reused). */
+  uploadMs?: number;
+  /** Read the archive manifest and commit the saved authority. */
+  publishMs?: number;
+  reusedUpload?: boolean;
+};
 const RETIRED_SAVE_SCHEMA = "paperclip.remote-workspace-retired-save.v1";
 type SaveWork = { schema: typeof SAVE_WORK_SCHEMA; activeIds: string[]; unknown: boolean; quiescedAt: string | null };
 function readSaveWork(metadata: Record<string, unknown> | null | undefined): SaveWork | null {
@@ -610,9 +621,15 @@ export function remoteWorkspaceSaveFailure(error: unknown): { code: string; caus
   return cause ? { code, cause } : { code };
 }
 
+function saveTimingRecord(timing: RemoteWorkspaceSaveTiming & { startedAt: number }, outcome: "succeeded" | "failed", at: Date) {
+  const { startedAt, ...phases } = timing;
+  return { schema: SAVE_TIMING_SCHEMA, outcome, totalMs: Math.max(0, Math.round(performance.now() - startedAt)),
+    ...phases, at: at.toISOString() };
+}
+
 async function settleSaveInvocation(input: { db: Db; workspace: Workspace; runId: string; epoch: number;
   location: NonNullable<RemoteWorkspaceAuthority["location"]>; operationId: string; invocationId: string;
-  failure?: { code: string; cause?: string } }) {
+  failure?: { code: string; cause?: string }; timing?: RemoteWorkspaceSaveTiming & { startedAt: number } }) {
   return input.db.transaction(async tx => {
     const workspace = await currentWorkspace(tx, input.workspace.companyId, input.workspace.id);
     const [operation] = await tx.select().from(workspaceOperations).where(and(eq(workspaceOperations.id, input.operationId),
@@ -629,6 +646,7 @@ async function settleSaveInvocation(input: { db: Db; workspace: Workspace; runId
     const failed = Boolean(failure) && operation.status === "running" && !activeIds.length && !work.unknown;
     await tx.update(workspaceOperations).set({ metadata: { ...operation.metadata,
       saveWork: { ...work, activeIds, quiescedAt: activeIds.length ? null : now.toISOString() },
+      ...(input.timing ? { saveTiming: saveTimingRecord(input.timing, input.failure ? "failed" : "succeeded", now) } : {}),
       ...(failed && failure ? { lastFailure: { ...failure, at: now.toISOString() } } : {}) },
       ...(failed && failure ? { status: "failed", exitCode: 1, finishedAt: now,
         stderrExcerpt: `${[failure.code, failure.cause].filter(Boolean).join("\n")}\n` } : {}),
@@ -644,6 +662,7 @@ export async function saveRemoteWorkspace(input: {
   assertOwned: () => Promise<void>; storage?: StorageService; boundary?: string;
   repositories?: NonNullable<RemoteWorkspaceSource["repositories"]>;
 }) {
+  const saveStarted = performance.now();
   const target = requireRemoteWorkspaceTarget(input.target), boundary = input.boundary ?? "final";
   const expected = readRemoteWorkspaceAuthority(input.workspace.metadata);
   if (!expected?.location || expected.location.providerLeaseId !== input.lease.providerLeaseId || expected.location.leaseId !== input.lease.id) throw new Error("remote_workspace_save_binding_mismatch");
@@ -696,21 +715,31 @@ export async function saveRemoteWorkspace(input: {
   let captured: Awaited<ReturnType<typeof captureRemoteWorkspaceArchive>> | null = null;
   let publicationScratch: string | undefined;
   let failure: { code: string; cause?: string } | undefined;
+  const timing: RemoteWorkspaceSaveTiming & { startedAt: number } = { startedAt: saveStarted };
+  // A replay of an already-committed save measures no phase; it keeps the
+  // original save's timing instead of overwriting it with an empty record.
+  let replayedCommittedSave = false;
   try {
     const snapshot = await beginWorkspaceSnapshot(input.db, { companyId: input.workspace.companyId, workspaceId: input.workspace.id,
       operationId: operation.id, runId: input.runId, parentSnapshotId: operation.metadata?.parentSnapshotId as string | null,
       generation: operation.metadata?.generation as number, epoch: expected.epoch });
     if (operation.status === "succeeded" && ["committed", "superseded"].includes(snapshot.status)) {
+      replayedCommittedSave = true;
       return { snapshotId: snapshot.id, generation: snapshot.generation, sha256: snapshot.sha256!, savedAt: snapshot.updatedAt.toISOString() };
     }
     const existingUpload = snapshot.status === "uploaded" ? await getWorkspaceSnapshot(input.db, { companyId: input.workspace.companyId,
       workspaceId: input.workspace.id, snapshotId: snapshot.id }) : null;
-    captured = existingUpload ? null : await captureRemoteWorkspaceArchive({ target, remoteCwd: expected.location.remoteCwd, operationId: operation.id });
+    if (existingUpload) timing.reusedUpload = true;
+    captured = existingUpload ? null : await captureRemoteWorkspaceArchive({ target, remoteCwd: expected.location.remoteCwd,
+      operationId: operation.id, timing });
     await input.assertOwned();
+    const uploadStarted = performance.now();
     const saved = await uploadWorkspaceSnapshot({ db: input.db, storage: input.storage ?? getStorageService(), snapshotId: snapshot.id,
       companyId: input.workspace.companyId, workspaceId: input.workspace.id, archivePath: captured?.archivePath ?? "",
       manifestDigest: existingUpload?.manifestDigest ?? captured!.manifestDigest });
+    timing.uploadMs = Math.max(0, Math.round(performance.now() - uploadStarted));
     await input.assertOwned();
+    const publishStarted = performance.now();
     let publicationArchive = captured?.archivePath;
     if (!publicationArchive) {
       publicationScratch = await mkdtemp(path.join(os.tmpdir(), "pc-workspace-publication-"));
@@ -756,6 +785,7 @@ export async function saveRemoteWorkspace(input: {
         deleteAfter: new Date(at.getTime() + 7 * 86400_000), updatedAt: at }).where(and(eq(executionWorkspaceSnapshots.id, snapshot.parentSnapshotId),
         eq(executionWorkspaceSnapshots.companyId, workspace.companyId), eq(executionWorkspaceSnapshots.executionWorkspaceId, workspace.id)));
     });
+    timing.publishMs = Math.max(0, Math.round(performance.now() - publishStarted));
     return { snapshotId: saved.id, generation: saved.generation, sha256: saved.sha256, savedAt: at.toISOString() };
   } catch (error) {
     failure = remoteWorkspaceSaveFailure(error);
@@ -768,7 +798,8 @@ export async function saveRemoteWorkspace(input: {
     catch { logger.warn({ runId: input.runId, operationId: operation.id }, "Remote workspace local archive cleanup failed"); }
     try {
       if (await settleSaveInvocation({ db: input.db, workspace: input.workspace, runId: input.runId, epoch: expected.epoch,
-        location: expected.location, operationId: operation.id, invocationId, failure })) {
+        location: expected.location, operationId: operation.id, invocationId, failure,
+        timing: replayedCommittedSave ? undefined : timing })) {
         await cleanupSavedExports({ db: input.db, companyId: input.workspace.companyId, workspaceId: input.workspace.id,
           location: expected.location, target, assertOwned: input.assertOwned });
       }