mirror of
https://github.com/paperclipai/paperclip.git
synced 2026-11-10 12:37:55 +01:00
test(restart-chaos): do not grade a recovery that a back-to-back fault interrupted (#20243)
## Thinking Path
- #20183 split restart recovery so the speed budget judges Paperclip's
own share (`restart_recovery_control_plane`).
- In Phase 3's local mixed wave (`w-20261109T104527-s9901`, master
3963d38560), Claude's control-plane recovery was p50 1.4 s but p95 24.2
s (n=19). That suggested an occasional 20 s wait on Paperclip's side.
- The kept database shows otherwise. The slow samples all come from
back-to-back faults on one run (`566c07b4`):
- f07 was ready at 10:56:45.39; the run requested its runner at 45.70;
f08 (K6) killed the server at 45.78.
- f09 started 0.69 s after f08 was ready.
- So each "sample" spans the next fault's outage plus a repeated
recovery. Outage time is removed, but the repeated claim, prepare and
launch work and the partial attempt are still charged. Paperclip has no
wait to fix; the grader mismeasures overlapping faults.
## Linked Issues or Issue Description
Refs #20183
**What happened?**
A recovery sample that a later fault interrupted before its next
provider event was graded as if it were one long recovery. That inflated
the control-plane p95 (Claude, 24.2 s) in fault storms.
**Steps to reproduce**
1. Run a chaos wave with back-to-back faults (for example the mixed wave
seed 9901: f07 K4 → f08 K6 0.4 s after ready → f09 K6 0.7 s after
ready).
2. Look at `restart_recovery_control_plane` for runs in flight across
those faults.
**Expected behavior**
Only uninterrupted recoveries are graded. Interrupted ones are counted
and reported.
## What Changed
- `tests/restart-chaos/ttft-baseline-stats.ts`:
- `BaselineFault` gains `startedAt`.
- When a later fault starts inside a sample's window (after ready,
before the next provider event), `recoverySamples` marks the sample
`interruptedByFault` and nulls its latencies. The later fault's own
sample measures that run.
- `tests/restart-chaos/wave-speed.ts`:
- `faultRuns` passes `startedAt`.
- `WaveSpeed` reports `recoveryInterruptedByFault`, which no longer
counts as "no provider event".
- The speed summary prints it.
- Tests:
- A new back-to-back case: the interrupted sample is skipped and the
later fault's 1.5 s recovery is graded. It's red without the change and
green with it.
- The `faultRuns` expectation includes `startedAt`.
## Verification
- `npx vitest run --config tests/restart-chaos/vitest.config.ts
tests/restart-chaos/wave-speed.test.ts
tests/restart-chaos/ttft-baseline-stats.test.ts`: 32 passed.
- Against the wave: the two samples behind the tail (f07 → f08, f08 →
f09) are exactly the interrupted ones. The next slowest Claude sample
(f10, 15.6 s) includes a 9.4 s `provider.session.load`, so its
control-plane share is about 6 s.
## Risks
- **Harness grading only; no product change.** Fault storms produce
fewer graded samples, and the count is reported, so a wave that is
mostly interrupted is visible.
- **A real Paperclip wait** that happened to straddle a later fault
would be hidden in that sample. It would show up in uninterrupted
samples.
## 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>
This commit is contained in:
1 parent
3f2a940d5b
commit
9715b3d210
3 files changed
+35
-5
No files matched your search
@@ -24,6 +24,9 @@ export interface BaselineRun {
|
||||
export interface BaselineFault {
|
||||
kind: string;
|
||||
readyAt: number;
|
||||
/** When the fault began. A recovery that a later fault interrupts before its
|
||||
* next provider event is not a measurement of this fault's recovery. */
|
||||
startedAt?: number;
|
||||
/** Runs that were in flight when the fault started. */
|
||||
runIds: string[];
|
||||
}
|
||||
@@ -137,7 +140,11 @@ export interface RecoverySample { runId: string; adapter: string; kind: string;
|
||||
* latency when nothing reloads. The judged row. */
|
||||
controlPlaneMs: number | null;
|
||||
/** The provider's share: session load start to the next provider event. Reported. */
|
||||
providerLoadMs: number | null }
|
||||
providerLoadMs: number | null;
|
||||
/** A later fault began before this recovery reached its next provider event
|
||||
* (back-to-back faults). Its latencies are null: the later fault's own sample
|
||||
* measures that run. */
|
||||
interruptedByFault?: true }
|
||||
|
||||
/** Control plane ready → the recovered run's next provider event, keyed by runner disposition. */
|
||||
/** The run's trace start: every span records its offset from it. A span event is
|
||||
@@ -180,6 +187,12 @@ export function recoverySamples(runs: readonly BaselineRun[], faults: readonly B
|
||||
&& Date.parse(event.createdAt) >= fault.readyAt - 60_000);
|
||||
const next = run.events.find(event => PROVIDER_EVENT_TYPES.has(event.eventType) && Date.parse(event.createdAt) >= fault.readyAt);
|
||||
const nextAt = next ? Date.parse(next.createdAt) : null;
|
||||
if (nextAt !== null && faults.some(other => other.startedAt !== undefined && other.startedAt > fault.readyAt && other.startedAt < nextAt)) {
|
||||
samples.push({ runId, adapter: run.adapter, kind: fault.kind, readyAt: fault.readyAt,
|
||||
disposition: String(transition?.payload?.runnerDisposition ?? "none"),
|
||||
latencyMs: null, controlPlaneMs: null, providerLoadMs: null, interruptedByFault: true });
|
||||
continue;
|
||||
}
|
||||
const stamped = stampProviderLoadStarts(run);
|
||||
const loadStarts = nextAt === null ? [] : stamped.events.flatMap(event => {
|
||||
if (event.eventType !== "run.performance.span" || event.payload?.span !== "provider.session.load") return [];
|
||||
|
||||
@@ -64,6 +64,19 @@ describe("wave speed grade", () => {
|
||||
expect(speed.breaches).toBe(0);
|
||||
});
|
||||
|
||||
it("does not grade a recovery that a back-to-back fault interrupted before its next provider event", () => {
|
||||
// f1 is ready at 10 s; f2 hits 0.4 s later and is ready at 30 s; the run resumes 1.5 s after f2.
|
||||
const recovered: BaselineRun = { runId: "r", adapter: "claude", environment: "local", phase: "cold",
|
||||
events: [{ eventType: "session.resumed", createdAt: new Date(31_500).toISOString() }] };
|
||||
const faults = [{ kind: "K4", startedAt: 1_000, readyAt: 10_000, runIds: ["r"] },
|
||||
{ kind: "K6", startedAt: 10_400, readyAt: 30_000, runIds: ["r"] }];
|
||||
const windows = outageWindows(faults.map(fault => ({ startedAt: fault.startedAt, readyAt: fault.readyAt }) as FaultReceipt));
|
||||
const speed = gradeWaveSpeed("local", [recovered], faults, 0, [], { adjusted: 0, removedMs: 0, windows });
|
||||
expect(speed.rows.find(row => row.metric === "restart_recovery_control_plane")).toMatchObject({ measured: { n: 1, p50: 1_500 }, breaches: [] });
|
||||
expect(speed.recoveryInterruptedByFault).toBe(1);
|
||||
expect(speed.recoveryWithoutProviderEvent).toBe(0);
|
||||
});
|
||||
|
||||
it("removes a later outage from restart recovery", () => {
|
||||
const recovered: BaselineRun = { runId: "r", adapter: "claude", environment: "local", phase: "cold",
|
||||
events: [{ eventType: "turn.started", createdAt: new Date(10_000 + 302_000).toISOString() }] };
|
||||
@@ -183,6 +196,6 @@ describe("wave speed grade", () => {
|
||||
const fault = { kind: "K2", startedAt: 1_000, readyAt: 2_000 } as FaultReceipt;
|
||||
expect(faultRuns([fault], [{ id: "before", createdAt: 0, finishedAt: 500 }, { id: "live", createdAt: 0, finishedAt: null },
|
||||
{ id: "during", createdAt: 1_500, finishedAt: null }, { id: "after", createdAt: 2_500, finishedAt: null }]))
|
||||
.toEqual([{ kind: "K2", readyAt: 2_000, runIds: ["live", "during"] }]);
|
||||
.toEqual([{ kind: "K2", readyAt: 2_000, startedAt: 1_000, runIds: ["live", "during"] }]);
|
||||
});
|
||||
});
|
||||
@@ -22,6 +22,8 @@ export interface WaveSpeed {
|
||||
outageAdjustedSpans: number;
|
||||
outageRemovedMs: number;
|
||||
recoveryWithoutProviderEvent: number;
|
||||
/** Recovery samples a later fault interrupted before their next provider event (not graded). */
|
||||
recoveryInterruptedByFault: number;
|
||||
runBudgetExceeded: number;
|
||||
singleRunBreaches: number;
|
||||
breaches: number;
|
||||
@@ -53,7 +55,7 @@ export function breachesOf(measured: Distribution, budget: SpeedBudget | null):
|
||||
}
|
||||
|
||||
export function faultRuns(faults: readonly FaultReceipt[], runs: ReadonlyArray<{ id: string; createdAt: number; finishedAt: number | null }>): BaselineFault[] {
|
||||
return faults.filter(fault => fault.readyAt !== null).map(fault => ({ kind: fault.kind, readyAt: fault.readyAt!,
|
||||
return faults.filter(fault => fault.readyAt !== null).map(fault => ({ kind: fault.kind, readyAt: fault.readyAt!, startedAt: fault.startedAt,
|
||||
runIds: runs.filter(run => run.createdAt <= fault.readyAt! && (run.finishedAt === null || run.finishedAt >= fault.startedAt))
|
||||
.map(run => run.id) }));
|
||||
}
|
||||
@@ -211,7 +213,9 @@ export function gradeWaveSpeed(environment: EnvironmentKind, runs: readonly Base
|
||||
|| (boot !== null && bootBudget !== null && boot > bootBudget.p95Ms);
|
||||
}).length;
|
||||
const breaches = rows.reduce((total, row) => total + row.breaches.length, 0) + singleRunBreaches;
|
||||
return { environment, rows, recoveryWithoutProviderEvent: samples.filter(sample => sample.latencyMs === null).length,
|
||||
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 };
|
||||
}
|
||||
|
||||
@@ -282,7 +286,7 @@ export function speedMarkdown(speed: WaveSpeed): string {
|
||||
const s = (value: number | null) => value === null ? "—" : `${(value / 1000).toFixed(1)} s`;
|
||||
const lines = [`## Speed (${speed.environment})`, "",
|
||||
`Breaches: ${speed.breaches} (aggregate p50/p95 rows plus ${speed.singleRunBreaches} runs 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}.`,
|
||||
`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).`, "",
|
||||
"| Adapter | Metric | Start | n | p50 | p95 | Budget p50 / p95 | Breach |", "|---|---|---|---|---|---|---|---|"];
|
||||
for (const row of speed.rows) {
|
||||
|
||||
Reference in new issue
Block a user