mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-11 05:11:49 +01:00
test(restart-chaos): remove storage fault window time from speed budgets (#20501)
## Thinking Path > - Paperclip is the open source app people use to manage AI agents for work > - The restart-chaos harness grades each wave's speed against local budgets (`wave-speed.ts`) > - The speed grade already removes restart outage time (fault start to server ready) from spans and restart recoveries > - It did not remove storage fault window time (ST1 outage, ST5 rejected credentials, and so on) > - A restart recovery that correctly waits for the store inside a storage fault window then counts as a speed breach > - This pull request removes the overlap with storage fault windows the same way, and shows the removed time on its own line > - The benefit is that storage waves fail only on real slowness, not on correct waiting ## Linked Issues or Issue Description **What existing behavior does this improve?** The wave speed grade treats time spent inside a storage fault window as product slowness. **Subsystem affected** tests/restart-chaos (speed grade). **Current behavior** The ST5 waves w-20261110T050044-s503 and w-20261110T062313-s506 exited 1 on speed breaches only. Their `restart_recovery_control_plane` p95 was 62–67 s against a 4 s budget. The recoveries were inside an ST5R window and correctly waited for a valid key. **Proposed behavior** Spans and restart recoveries do not count time inside storage fault windows (from the `storage-faults.json` receipts). Restart outage and storage windows that overlap are removed once. `SUMMARY.md` shows the storage time that was removed, and `speed.json` has `storageFaultWindows` and `storageFaultRemovedMs`. **Reason and benefit** Storage waves must fail on real product failures and real slowness, not on the harness's own fault windows. ## What Changed - `wave-speed.ts`: `storageFaultWindows()` turns receipts into windows (an open window ends now). `mergeWindows()` joins overlapping windows, so `outageFreeClock()` removes shared time once. `collectWaveSpeed()` takes the storage receipts and removes their time from spans; `gradeWaveSpeed()` removes it from restart recoveries. The storage share is reported apart from the restart outage share. - `main.ts`: one line passes `storageChaos.receipts` to `collectWaveSpeed()`. - README: one paragraph in the Cloud storage section. ## Verification - `PAPERCLIP_IN_WORKTREE=false npx vitest run --config tests/restart-chaos/vitest.config.ts tests/restart-chaos/wave-speed.test.ts`: 20 pass. The 3 new tests fail before this change (`storageFaultWindows is not a function`, overlap removed twice, span not trimmed) and pass after. - `node scripts/typecheck-test-projects.mjs tests/restart-chaos` passes. ## Risks - Test harness only. No product code changes. - ST2 (slow store) windows are also removed from speed budgets. Slowness during a slow-store window is expected, so this is intended. ## Model Used - Claude Opus 5.5 (`claude-opus-5-5`), Anthropic, with tool use and code execution in 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>
This commit is contained in:
1 parent
a14ae9b5c9
commit
7fef6321fe
4 files changed
+86
-12
No files matched your search
@@ -374,6 +374,9 @@ that re-resolves its credentials after a rejection keeps going. Rotations and pu
|
||||
|
||||
`--storage-fault-seconds 15-45` sets the window length range (5–900 s), for example to find how long
|
||||
an outage a run survives. The windows are logged in the timeline and written to `storage-faults.json`.
|
||||
The speed grade removes storage fault window time from spans and restart recoveries the same way it
|
||||
removes restart outage time (overlap counted once), and reports the removed time on its own line in
|
||||
`SUMMARY.md` and as `storageFaultRemovedMs` in `speed.json`.
|
||||
|
||||
With `--env daytona --storage s3`, each task's workspace is a remote workspace: the controller saves
|
||||
and restores it through the store, so the faults also hit workspace save, restore and copyback. R1
|
||||
|
||||
@@ -595,7 +595,7 @@ async function main(): Promise<number> {
|
||||
const speed = await (async () => {
|
||||
const childTasks = await childSpeedTasksInTurn(launched);
|
||||
return collectWaveSpeed(api, plan.options.env, [...launched.flatMap(observer => observer.record.issueId
|
||||
? [{ issueId: observer.record.issueId, adapter: observer.plan.adapter, samples: observer.record.samples }] : []), ...childTasks], faults);
|
||||
? [{ issueId: observer.record.issueId, adapter: observer.plan.adapter, samples: observer.record.samples }] : []), ...childTasks], faults, storageChaos?.receipts ?? []);
|
||||
})().catch(error => { timeline.add("wave_speed_failed", { error: String(error) }); anyFailure = true; return null; });
|
||||
if (speed) {
|
||||
speedSection = speedMarkdown(speed);
|
||||
|
||||
@@ -2,7 +2,7 @@ import { describe, expect, it } from "vitest";
|
||||
import type { BaselineRun } from "./ttft-baseline-stats.js";
|
||||
import type { ChaosApi } from "./api.js";
|
||||
import type { FaultReceipt } from "./types.js";
|
||||
import { bootWithoutProvisionMs, breachesOf, budgetFor, collectWaveSpeed, faultBeforeFirstActivity, faultRuns, firstActivityMs, gradeWaveSpeed, outageWindows, speedMarkdown, traceStartMs, withoutOutage } from "./wave-speed.js";
|
||||
import { bootWithoutProvisionMs, breachesOf, budgetFor, collectWaveSpeed, faultBeforeFirstActivity, faultRuns, firstActivityMs, gradeWaveSpeed, outageFreeClock, outageWindows, speedMarkdown, storageFaultWindows, traceStartMs, withoutOutage } from "./wave-speed.js";
|
||||
import { runMetrics } from "./ttft-baseline-stats.js";
|
||||
|
||||
const span = (name: string, startOffsetMs: number, durationMs: number, extra: Record<string, unknown> = {}) =>
|
||||
@@ -90,6 +90,40 @@ describe("wave speed grade", () => {
|
||||
expect(speed.rows.find(row => row.metric === "restart_recovery_control_plane")).toMatchObject({ measured: { p50: 2_000 }, breaches: [] });
|
||||
});
|
||||
|
||||
it("removes storage fault window time from restart recovery and reports it apart from restart outage", () => {
|
||||
const recovered: BaselineRun = { runId: "r", adapter: "claude", environment: "local", phase: "cold",
|
||||
events: [{ eventType: "session.resumed", createdAt: new Date(10_000 + 62_000).toISOString() }] };
|
||||
const restart = outageWindows([{ startedAt: 1_000, readyAt: 10_000 } as FaultReceipt]);
|
||||
const storage = storageFaultWindows([{ kind: "ST5R", startedAt: 5_000, endedAt: 70_000, rules: [] },
|
||||
{ kind: "ST1", startedAt: 90_000, endedAt: null, rules: [] }], 95_000);
|
||||
expect(storage).toEqual([{ startedAt: 5_000, readyAt: 70_000 }, { startedAt: 90_000, readyAt: 95_000 }]);
|
||||
const faults = [{ kind: "K1", startedAt: 1_000, readyAt: 10_000, runIds: ["r"] }];
|
||||
const unadjusted = gradeWaveSpeed("local", [recovered], faults, 0, [], { adjusted: 0, removedMs: 0, windows: restart });
|
||||
expect(unadjusted).toMatchObject({ singleRunBreaches: 1, breaches: 1 });
|
||||
const speed = gradeWaveSpeed("local", [recovered], faults, 0, [], { adjusted: 0, removedMs: 0, windows: restart, storageWindows: storage });
|
||||
expect(speed.rows.find(row => row.metric === "restart_recovery_control_plane")).toMatchObject({ measured: { p50: 2_000 }, breaches: [] });
|
||||
expect(speed).toMatchObject({ breaches: 0, storageFaultWindows: 2, storageFaultRemovedMs: 60_000 });
|
||||
expect(speedMarkdown(speed)).toContain("Storage fault time removed: 60.0 s across 2 windows");
|
||||
});
|
||||
|
||||
it("removes overlapping restart and storage fault time once", () => {
|
||||
const clock = outageFreeClock([{ startedAt: 10_000, readyAt: 50_000 }, { startedAt: 30_000, readyAt: 70_000 }]);
|
||||
expect(clock(100_000)).toBe(40_000);
|
||||
expect(clock(40_000)).toBe(10_000);
|
||||
});
|
||||
|
||||
it("removes storage fault time from spans in a collected wave and counts it apart", async () => {
|
||||
const run = traced(1_000_000, [["heartbeat.queue", 0, 100], ["task.time_to_first_agent_activity", 0, 70_000]]);
|
||||
const api = { get: async (route: string) => route.includes("workspace-operations") ? []
|
||||
: run.events.map((event, seq) => ({ ...event, seq })) } as unknown as ChaosApi;
|
||||
const sample = { runs: [{ id: "t", status: "succeeded", createdAt: new Date(1_000_000).toISOString(),
|
||||
finishedAt: new Date(1_080_000).toISOString() }] } as never;
|
||||
const speed = await collectWaveSpeed(api, "local", [{ issueId: "i", adapter: "claude", samples: [sample] }], [],
|
||||
[{ kind: "ST1", startedAt: 1_005_000, endedAt: 1_065_000, rules: [] }]);
|
||||
expect(speed.rows.find(row => row.metric === "time_to_first_activity")).toMatchObject({ measured: { p50: 10_000 } });
|
||||
expect(speed).toMatchObject({ storageFaultWindows: 1, storageFaultRemovedMs: 60_000, outageRemovedMs: 0, outageAdjustedSpans: 0 });
|
||||
});
|
||||
|
||||
it("has no budget for remote environments or unbudgeted adapters", () => {
|
||||
expect(budgetFor("daytona", "codex", "ttft", "cold")).toBeNull();
|
||||
expect(budgetFor("local", "unknown", "ttft", "cold")).toBeNull();
|
||||
|
||||
@@ -4,6 +4,7 @@ import {
|
||||
baselineRows, distribution, recoverySamples, runMetrics, runSpans, runWarmth, stampProviderLoadStarts,
|
||||
type BaselineEvent, type BaselineFault, type BaselineRun, type Distribution,
|
||||
} from "./ttft-baseline-stats.js";
|
||||
import type { StorageFaultReceipt } from "./storage-chaos.js";
|
||||
import type { AdapterId, EnvironmentKind, FaultReceipt, RunSample } from "./types.js";
|
||||
|
||||
type Json = Record<string, unknown>;
|
||||
@@ -21,6 +22,8 @@ export interface WaveSpeed {
|
||||
rows: SpeedRow[];
|
||||
outageAdjustedSpans: number;
|
||||
outageRemovedMs: number;
|
||||
storageFaultWindows: number;
|
||||
storageFaultRemovedMs: number;
|
||||
recoveryWithoutProviderEvent: number;
|
||||
/** Recovery samples a later fault interrupted before their next provider event (not graded). */
|
||||
recoveryInterruptedByFault: number;
|
||||
@@ -68,6 +71,23 @@ export function outageWindows(faults: readonly FaultReceipt[]): OutageWindow[] {
|
||||
return faults.filter(fault => fault.readyAt !== null).map(fault => ({ startedAt: fault.startedAt, readyAt: fault.readyAt! }));
|
||||
}
|
||||
|
||||
export function storageFaultWindows(receipts: readonly StorageFaultReceipt[], now: number): OutageWindow[] {
|
||||
return receipts.flatMap(receipt => {
|
||||
const readyAt = receipt.endedAt ?? now;
|
||||
return readyAt > receipt.startedAt ? [{ startedAt: receipt.startedAt, readyAt }] : [];
|
||||
});
|
||||
}
|
||||
|
||||
export function mergeWindows(windows: readonly OutageWindow[]): OutageWindow[] {
|
||||
const merged: OutageWindow[] = [];
|
||||
for (const window of [...windows].sort((a, b) => a.startedAt - b.startedAt)) {
|
||||
const last = merged.at(-1);
|
||||
if (last && window.startedAt <= last.readyAt) last.readyAt = Math.max(last.readyAt, window.readyAt);
|
||||
else merged.push({ ...window });
|
||||
}
|
||||
return merged;
|
||||
}
|
||||
|
||||
export function traceStartMs(run: BaselineRun): number | null {
|
||||
let earliest: number | null = null;
|
||||
for (const event of run.events) {
|
||||
@@ -82,7 +102,8 @@ export function traceStartMs(run: BaselineRun): number | null {
|
||||
}
|
||||
|
||||
export function outageFreeClock(windows: readonly OutageWindow[]): (at: number) => number {
|
||||
return at => at - windows.reduce((total, window) =>
|
||||
const merged = mergeWindows(windows);
|
||||
return at => at - merged.reduce((total, window) =>
|
||||
total + Math.max(0, Math.min(at, window.readyAt) - window.startedAt), 0);
|
||||
}
|
||||
|
||||
@@ -172,7 +193,8 @@ function firstActivityByGroup(runs: readonly BaselineRun[]): Map<string, number[
|
||||
|
||||
export function gradeWaveSpeed(environment: EnvironmentKind, runs: readonly BaselineRun[], faults: readonly BaselineFault[],
|
||||
runBudgetExceeded: number, errors: string[] = [],
|
||||
outage: { adjusted: number; removedMs: number; windows?: readonly OutageWindow[] } = { adjusted: 0, removedMs: 0 }): WaveSpeed {
|
||||
outage: { adjusted: number; removedMs: number; windows?: readonly OutageWindow[]; storageWindows?: readonly OutageWindow[];
|
||||
storageRemovedMs?: number } = { adjusted: 0, removedMs: 0 }): WaveSpeed {
|
||||
const rows: SpeedRow[] = [];
|
||||
const activity = firstActivityByGroup(runs);
|
||||
const boots = byGroup(runs, bootWithoutProvisionMs), provisions = byGroup(runs, provisionMs);
|
||||
@@ -186,9 +208,18 @@ export function gradeWaveSpeed(environment: EnvironmentKind, runs: readonly Base
|
||||
rows.push({ adapter: row.adapter, metric, start: row.warmth, measured, budget, breaches: breachesOf(measured, budget) });
|
||||
}
|
||||
}
|
||||
const clock = outageFreeClock(outage.windows ?? []);
|
||||
const storageWindows = outage.storageWindows ?? [];
|
||||
const clock = outageFreeClock([...(outage.windows ?? []), ...storageWindows]);
|
||||
const restartClock = outageFreeClock(outage.windows ?? []);
|
||||
const outageFree = (readyAt: number, ms: number | null) => ms === null ? null : Math.max(0, clock(readyAt + ms) - clock(readyAt));
|
||||
const samples = recoverySamples(runs, faults).map(sample => sample.latencyMs === null ? sample : {
|
||||
let storageRemovedMs = outage.storageRemovedMs ?? 0;
|
||||
const samples = recoverySamples(runs, faults).map(sample => {
|
||||
if (sample.latencyMs !== null) {
|
||||
const end = sample.readyAt + sample.latencyMs;
|
||||
storageRemovedMs += (restartClock(end) - restartClock(sample.readyAt)) - (clock(end) - clock(sample.readyAt));
|
||||
}
|
||||
return sample;
|
||||
}).map(sample => sample.latencyMs === null ? sample : {
|
||||
...sample, latencyMs: outageFree(sample.readyAt, sample.latencyMs),
|
||||
controlPlaneMs: outageFree(sample.readyAt, sample.controlPlaneMs),
|
||||
providerLoadMs: sample.providerLoadMs === null || sample.controlPlaneMs === null ? sample.providerLoadMs
|
||||
@@ -221,7 +252,8 @@ export function gradeWaveSpeed(environment: EnvironmentKind, runs: readonly Base
|
||||
return { environment, rows,
|
||||
recoveryWithoutProviderEvent: samples.filter(sample => sample.latencyMs === null && !sample.interruptedByFault).length,
|
||||
recoveryInterruptedByFault: samples.filter(sample => sample.interruptedByFault).length,
|
||||
runBudgetExceeded, singleRunBreaches, breaches, errors, outageAdjustedSpans: outage.adjusted, outageRemovedMs: outage.removedMs };
|
||||
runBudgetExceeded, singleRunBreaches, breaches, errors, outageAdjustedSpans: outage.adjusted, outageRemovedMs: outage.removedMs,
|
||||
storageFaultWindows: storageWindows.length, storageFaultRemovedMs: storageRemovedMs };
|
||||
}
|
||||
|
||||
async function runEventsWithRetry(api: ChaosApi, runId: string, attempts = 3): Promise<BaselineEvent[]> {
|
||||
@@ -249,12 +281,13 @@ async function runEvents(api: ChaosApi, runId: string): Promise<BaselineEvent[]>
|
||||
}
|
||||
|
||||
export async function collectWaveSpeed(api: ChaosApi, environment: EnvironmentKind, tasks: readonly WaveSpeedTask[],
|
||||
faults: readonly FaultReceipt[]): Promise<WaveSpeed> {
|
||||
faults: readonly FaultReceipt[], storageReceipts: readonly StorageFaultReceipt[] = [], now = Date.now()): Promise<WaveSpeed> {
|
||||
const runs: BaselineRun[] = [];
|
||||
const timing: Array<{ id: string; createdAt: number; finishedAt: number | null }> = [];
|
||||
const errors: string[] = [];
|
||||
const windows = outageWindows(faults);
|
||||
const outage = { adjusted: 0, removedMs: 0, windows };
|
||||
const storageWindows = storageFaultWindows(storageReceipts, now);
|
||||
const outage = { adjusted: 0, removedMs: 0, windows, storageWindows, storageRemovedMs: 0 };
|
||||
const perTask = tasks.map(task => {
|
||||
const seen = new Map<string, RunSample>();
|
||||
for (const sample of task.samples) for (const run of sample.runs ?? []) if (run.createdAt) seen.set(run.id, run);
|
||||
@@ -275,8 +308,11 @@ export async function collectWaveSpeed(api: ChaosApi, environment: EnvironmentKi
|
||||
if (run.retryOfRunId && faultHit.has(run.retryOfRunId)) raw.phase = "restart";
|
||||
if (faultBeforeFirstActivity(raw, windows, Date.parse(run.createdAt!))) raw.phase = "restart";
|
||||
// Stamp provider load starts from raw offsets before outage removal rewrites them.
|
||||
const trimmed = withoutOutage(stampProviderLoadStarts(raw), windows);
|
||||
outage.adjusted += trimmed.adjusted; outage.removedMs += trimmed.removedMs;
|
||||
const stamped = stampProviderLoadStarts(raw);
|
||||
const restartOnly = withoutOutage(stamped, windows);
|
||||
const trimmed = withoutOutage(stamped, [...windows, ...storageWindows]);
|
||||
outage.adjusted += restartOnly.adjusted; outage.removedMs += restartOnly.removedMs;
|
||||
outage.storageRemovedMs += trimmed.removedMs - restartOnly.removedMs;
|
||||
runs.push(trimmed.run);
|
||||
timing.push({ id: run.id, createdAt: Date.parse(run.createdAt!), finishedAt: run.finishedAt ? Date.parse(run.finishedAt) : null });
|
||||
} catch (error) {
|
||||
@@ -299,7 +335,8 @@ export function speedMarkdown(speed: WaveSpeed): string {
|
||||
const lines = [`## Speed (${speed.environment})`, "",
|
||||
`Breaches: ${speed.breaches} (aggregate p50/p95 rows with at least ${MIN_AGGREGATE_SAMPLES} samples plus ${speed.singleRunBreaches} runs or restart recoveries over the p95 budget after outage removal; the server logged ${speed.runBudgetExceeded} budget_exceeded events before removal).`,
|
||||
`Restart samples with no provider event after ready: ${speed.recoveryWithoutProviderEvent}. Interrupted by a later fault (not graded): ${speed.recoveryInterruptedByFault}.`,
|
||||
`Outage time removed from ${speed.outageAdjustedSpans} spans: ${s(speed.outageRemovedMs)} (fault start to server ready; budgets judge the rest).`, "",
|
||||
`Outage time removed from ${speed.outageAdjustedSpans} spans: ${s(speed.outageRemovedMs)} (fault start to server ready; budgets judge the rest).`,
|
||||
...(speed.storageFaultWindows ? [`Storage fault time removed: ${s(speed.storageFaultRemovedMs)} across ${speed.storageFaultWindows} windows (storage fault start to end, from storage-faults.json; overlap with restart outage counted once).`] : []), "",
|
||||
"| Adapter | Metric | Start | n | p50 | p95 | Budget p50 / p95 | Breach |", "|---|---|---|---|---|---|---|---|"];
|
||||
for (const row of speed.rows) {
|
||||
lines.push(`| ${row.adapter} | ${row.metric} | ${row.start} | ${row.measured.n} | ${s(row.measured.p50)} | ${s(row.measured.p95)} | `
|
||||
|
||||
Reference in new issue
Block a user