Files
PaperClipAI/server/src/storage/request-stats.ts
T
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

87 lines
3.3 KiB
TypeScript

import { AsyncLocalStorage } from "node:async_hooks";
/**
* Per-operation durable-storage request statistics, collected without
* threading a sink through every provider call. A caller opens a collector
* around a save or restore; every S3 request sent inside it adds its SDK
* attempts and retry delay, and the multipart uploader adds its own backoff.
* Counts only: no keys, paths or provider text. The run log and save timing
* record them so a slow or retried storage call is visible.
*/
export type StorageRequestStats = {
/** S3 requests sent (each may take several SDK attempts). */
requests: number;
/** SDK attempts across those requests. */
attempts: number;
/** Requests that ultimately failed. */
failedRequests: number;
/** Time the SDK spent waiting between its own retries. */
retryDelayMs: number;
/** Multipart parts uploaded. */
parts: number;
/** Part sends the backend rate-limited (503, 429, SlowDown). */
throttled: number;
/** Time the multipart uploader waited before resending a part. */
backoffMs: number;
};
const current = new AsyncLocalStorage<StorageRequestStats>();
export function newStorageRequestStats(): StorageRequestStats {
return { requests: 0, attempts: 0, failedRequests: 0, retryDelayMs: 0, parts: 0, throttled: 0, backoffMs: 0 };
}
/** Runs `work` with `stats` collecting every durable-storage request it sends. */
export function collectStorageRequestStats<T>(stats: StorageRequestStats, work: () => Promise<T>): Promise<T> {
return current.run(stats, work);
}
function metadataOf(value: unknown): { attempts?: unknown; totalRetryDelay?: unknown } | undefined {
if (!value || typeof value !== "object") return undefined;
const metadata = (value as { $metadata?: unknown }).$metadata;
return metadata && typeof metadata === "object" ? metadata as { attempts?: unknown; totalRetryDelay?: unknown } : undefined;
}
const count = (value: unknown, fallback: number) =>
typeof value === "number" && Number.isFinite(value) && value >= 0 ? value : fallback;
/** Records one S3 request's outcome from its SDK response or error metadata. */
export function recordStorageRequest(outcome: unknown, failed: boolean): void {
const stats = current.getStore();
if (!stats) return;
const metadata = metadataOf(outcome);
stats.requests += 1;
stats.attempts += count(metadata?.attempts, 1);
stats.retryDelayMs += count(metadata?.totalRetryDelay, 0);
if (failed) stats.failedRequests += 1;
}
export function recordStoragePart(): void {
const stats = current.getStore();
if (stats) stats.parts += 1;
}
/** Records a part send the backend rate-limited (503, 429, SlowDown), including a final one. */
export function recordStorageThrottle(): void {
const stats = current.getStore();
if (stats) stats.throttled += 1;
}
/** Records a wait before resending a part. */
export function recordStorageBackoff(waitMs: number): void {
const stats = current.getStore();
if (stats) stats.backoffMs += count(waitMs, 0);
}
/** Counts a request sent outside the failure-diagnostics wrapper (cleanup), keeping its error handling. */
export async function withStorageRequestStats<T>(send: () => Promise<T>): Promise<T> {
try {
const result = await send();
recordStorageRequest(result, false);
return result;
} catch (error) {
recordStorageRequest(error, true);
throw error;
}
}