Files
PaperClipAI/server
DottaandClaude Opus 5.5 dc9ad17515 perf(storage): time workspace snapshot save and restore steps and count storage retries (#20280)
## Thinking Path

- Cloud durable storage is a major source of failures and slowness on
staging. For example, a staging task failed when saving files after
automatic retries.
- Before measuring or fixing it, we need to see where storage time goes.
Today a saved-workspace restore before the turn appears only inside the
coarse `workspace_environment_realize` phase.
- After the turn, the save's encrypt, put, verify and multipart throttle
backoff have no timing at all. Only `captureMs`, `transferMs`,
`verifyMs`, `uploadMs` and `publishMs` exist, in `saveTiming`.
- Storage retries happen in the SDK and in the multipart uploader,
invisibly.
- This adds the measurement first, so the storage-mode chaos waves
(MinIO behind a fault proxy) can report save and restore p50/p95 and
point at the dominant wait.

## Linked Issues or Issue Description

**What happened?**
Durable-storage saves and restores were opaque in the run log and save
timing. A slow or repeatedly retried storage call could not be told
apart from slow capture, encryption or sandbox work.

**Steps to reproduce**
1. Run a remote task with S3-compatible durable storage, so it saves
after the turn and restores on the next run.
2. Inspect the run log and the `remote_workspace_snapshot` operation's
`saveTiming`. The restore's download, decrypt and verify, and the save's
put, verify and throttle backoff, have no timing.

**Expected behavior**
Each storage step has a duration, and storage request retries and
backoff are counted.

## What Changed

- `server/src/storage/request-stats.ts` (new): an async-local collector
of storage request statistics. Counts only:
  - `requests`, `attempts` and `failedRequests`;
  - `retryDelayMs` (SDK waits);
- `parts`, `throttled` and `backoffMs` (the multipart uploader's waits).
- `server/src/storage/s3-failure.ts`: `withS3FailureDiagnostics`, which
wraps every S3 send, records each request's SDK `$metadata.attempts` and
`totalRetryDelay`, on success and on failure.
- `server/src/storage/s3-multipart.ts`: records each uploaded part and
each resend wait, flagged throttled when the backend returned 503, 429
or SlowDown.
- `server/src/services/remote-workspace-snapshot-storage.ts`:
  - Each step is a `storage.snapshot.*` run phase:
    - save: `prior_attempts`, `encrypt`, `digest`, `put`, `verify`;
    - restore: `download`, `decrypt`, `verify_plaintext`, `publish`.
- A caller can pass a `timing` record that receives the step durations,
the bytes and the request statistics.
- `server/src/services/remote-workspaces.ts`:
  - The save passes a timing record, kept in `saveTiming.storage`.
- The sandbox unpack during a restore is its own phase,
`workspace.snapshot.sandbox_restore`.
- `execution-preparation-timing.ts`: the new phase names.
- `doc/run-log-events.md`: a new "Durable storage timing" section.

Because the restore runs inside run preparation, its steps of 50 ms or
more become `run.performance.span` rows with no extra plumbing. This is
run-log and instance-database data only; there's no Telemetry change.

## Verification

- `server`: `storage-s3-multipart-backoff`, `storage-s3-multipart`,
`storage-s3-multipart-throttle`, `storage-s3-failure-diagnostics`,
`remote-workspace-snapshot-storage` and `execution-preparation-timing`
tests: 86 passed. They include:
- collected stats for a throttled multipart upload: 12 requests, 7
failed, 7 throttled, 35.5 s backoff and 3 parts;
  - a save and restore that fill every step duration and the byte count.
- `remote-workspaces.integration.test.ts`: 112 passed. Its `saveTiming`
assertion now includes `storage`.
- Server typecheck: no errors in the touched files.

## Risks

- **Overhead:** one async-local lookup per S3 request, plus timestamps
per snapshot step.
- **Collector scope:** the collector only exists inside a snapshot save
or restore. Other storage callers are unaffected; they record nothing.
- **`saveTiming`** gains a `storage` object. Readers that compare it
exactly (one test, updated) will see the new field.

## Model Used

Claude Opus 5.5 (`claude-opus-5-5`, Anthropic), 1M context window, tool
use and code execution, via Claude Code.

## 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>
2026-11-09 09:41:53 -06:00
..