[sim-world] Repro: Date.now() after Promise.race is not deterministic - #3583
[sim-world] Repro: Date.now() after Promise.race is not deterministic#3583shalabhc wants to merge 5 commits into
Conversation
|
📊 Workflow Benchmarkscommit Backend:
Streams
📈 STSO distribution vs main (inline / queue-hop histograms)1020 steps (inline) Cumulative STSO time: main 413585ms → this run 433700ms (Δ +20115ms, +5%) 1020 steps (queue-hop) Cumulative STSO time: 3364ms over 1 samples No 📈 CRTT drill-down vs main (RTT distributions & profiles)RTT over stream progress (avg per tenth of stream, bars scaled min→max): RTT by chunk size (avg per log size bin, ~160B → ~12KB serialized, bars scaled min→max): Delivery jitter over stream progress (avg positive CDV per tenth of stream, bars scaled min→max): ℹ️ Metric definitions & methodologyStreams: writer/reader sustained rates (steady window, 10% trimmed each side), first-chunk RTT (the stream-open path, before any buffering/backpressure), CRTT percentiles, and worst delivery stall (CDV max). Cells are medians across iterations; per-run values in the artifacts. No 🔴/🟢 marks until targets attach. The collapsed STSO distribution section above buckets every step gap, split inline (same warm process — pure framework overhead) vs queue-hop (fresh process — dispatch, reinit, replay). The collapsed CRTT drill-down: per-variant RTT histograms (fixed log bins, Best/P75/P90/P99 deltas compare against the most recent benchmark run on Metrics — TTFS: time to first step body (in-deployment start() → first step body) · Fan-out TTFS: fan-out time to first step (in-deployment start() → first of the parallel step bodies to complete) · Fan-out TTLS: fan-out time to last step (in-deployment start() → last of the parallel step bodies to complete, i.e. when the Promise.all resolves) · STSO: step-to-step overhead (gap between consecutive step bodies) · WO: workflow overhead (whole-run time outside step bodies, in-deployment anchored) · CRTT: chunk round-trip time (per-chunk write → read latency, one clock domain: deployment → stream backend → same deployment) · CDV: chunk delay variation / delivery jitter (inter-arrival gap minus inter-write gap per seq-adjacent pair; skew-free; the row is each run's MAX positive value, so one stall moves it) Scenarios — step: one trivial no-op step, no stream; no hooks, so the run stays in turbo mode (in-process fast path) · stream: one streaming step; no hooks, so the run stays in turbo mode (in-process fast path) · hook + stream: registers a hook before one step, which exits turbo mode (dispatch path) · 1020 steps: 1020 trivial sequential steps; STSO is measured between consecutive steps in the given step ranges, and WO is the whole-run overhead outside step bodies · Promise.all(100 steps): 100 trivial no-op steps started together in a single Promise.all; Fan-out TTFS is the first of them to complete and Fan-out TTLS the last, both from the in-deployment clientStart, so their gap is the spread the runtime adds across the fan-out · paced control (100/s, 60B): the control: 300 tiny (~60B) deltas metronome-paced at 100/s — zero workload structure, so it reads the transport floor and flush cadence, and disambiguates transport-wide vs workload-specific when a replay row moves · size sweep (100/s, 160B-12KB): same pacing as the control with deltas padded in rotation across seven log-spaced sizes (~160B–12KB) — rotation decouples size from stream position, so it isolates whether chunk size causes latency · replay gateway-gpt-5.4-nano-2000t (1x): raw provider SSE cadence captured at the AI gateway boundary (gpt-5.4-nano, the most popular gateway model; per-token deltas p50 208B = the modal production chunk size), replayed exactly as measured — the typical customer's workload; its CDV is the typical customer's real delivery jitter · replay eve-gpt-5.6-sol-2000t (1x): a captured eve turn (gpt-5.6-sol, the most-used demanding eve model; ~2000 output tokens = production p50 turn length) replayed exactly as measured — eve's envelope protocol re-ships the cumulative message so sizes ramp 142B→13KB; the demanding outlier tenant's reality · replay eve-gpt-5.6-sol-2000t (2x): the same eve capture at 2x — the headroom/stress row; real fast-tier models emit the same chunk sizes at proportionally higher rate, so time compression is a faithful speed model · first chunk (pooled): every run's seq-0 RTT pooled across all stream scenarios — the first chunk precedes any workload differentiation, so pooling samples one shared stream-open path with exact percentiles Replay cadences (semantic sha256) — eve-gpt-5.6-sol-2000t 🔴 marks a percentile over its target (within target is left unmarked). Targets (p75/p90/p99, ms) — TTFS 200/300/600 All timestamps are deployment-side; runs are triggered in-deployment, so the CI runner and api.vercel.com sit outside every measured window. TTFS = Cold starts stay in the numbers (real bursty-workload latency, inflates P75+); Best is the warm floor. |
🧪 E2E Test Results✅ All tests passed
|
| Passed | Failed | Skipped | Total | |
|---|---|---|---|---|
| ✅ ▲ Vercel Production | 3321 | 0 | 735 | 4056 |
| ✅ 💻 Local Development | 3498 | 0 | 558 | 4056 |
| ✅ 📦 Local Production | 3810 | 0 | 558 | 4368 |
| ✅ 🐘 Local Postgres | 3810 | 0 | 558 | 4368 |
| ✅ 🪟 Windows | 312 | 0 | 0 | 312 |
| ✅ 🌐 Cross-language Conformance | 9 | 0 | 128 | 137 |
| ✅ vercel-multi-region | 27 | 0 | 0 | 27 |
| Total | 14787 | 0 | 2537 | 17324 |
Details by Category
✅ ▲ Vercel Production
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-node | 128 | 0 | 28 |
| ✅ astro-quickjs | 128 | 0 | 28 |
| ✅ example-node | 128 | 0 | 28 |
| ✅ example-quickjs | 128 | 0 | 28 |
| ✅ express-node | 128 | 0 | 28 |
| ✅ express-quickjs | 128 | 0 | 28 |
| ✅ fastify-node | 128 | 0 | 28 |
| ✅ fastify-quickjs | 128 | 0 | 28 |
| ✅ hono-node | 128 | 0 | 28 |
| ✅ hono-quickjs | 128 | 0 | 28 |
| ✅ nest-node | 128 | 0 | 28 |
| ✅ nest-quickjs | 128 | 0 | 28 |
| ✅ nextjs-turbopack-node | 153 | 0 | 3 |
| ✅ nextjs-webpack-node | 153 | 0 | 3 |
| ✅ nextjs-webpack-quickjs | 153 | 0 | 3 |
| ✅ nitro-node | 128 | 0 | 28 |
| ✅ nitro-quickjs | 128 | 0 | 28 |
| ✅ nuxt-node | 128 | 0 | 28 |
| ✅ nuxt-quickjs | 128 | 0 | 28 |
| ✅ python-node | 8 | 0 | 148 |
| ✅ sveltekit-node | 147 | 0 | 9 |
| ✅ sveltekit-quickjs | 147 | 0 | 9 |
| ✅ tanstack-start-node | 128 | 0 | 28 |
| ✅ tanstack-start-quickjs | 128 | 0 | 28 |
| ✅ vite-node | 128 | 0 | 28 |
| ✅ vite-quickjs | 128 | 0 | 28 |
✅ 💻 Local Development
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 130 | 0 | 26 |
| ✅ astro-stable-quickjs | 130 | 0 | 26 |
| ✅ express-stable-node | 130 | 0 | 26 |
| ✅ express-stable-quickjs | 130 | 0 | 26 |
| ✅ fastify-stable-node | 130 | 0 | 26 |
| ✅ fastify-stable-quickjs | 130 | 0 | 26 |
| ✅ hono-stable-node | 130 | 0 | 26 |
| ✅ hono-stable-quickjs | 130 | 0 | 26 |
| ✅ nest-stable-node | 130 | 0 | 26 |
| ✅ nest-stable-quickjs | 130 | 0 | 26 |
| ✅ nextjs-turbopack-canary-node | 137 | 0 | 19 |
| ✅ nextjs-turbopack-canary-quickjs | 137 | 0 | 19 |
| ✅ nextjs-webpack-canary-node | 137 | 0 | 19 |
| ✅ nextjs-webpack-canary-quickjs | 137 | 0 | 19 |
| ✅ nextjs-webpack-stable-node | 156 | 0 | 0 |
| ✅ nextjs-webpack-stable-quickjs | 156 | 0 | 0 |
| ✅ nitro-stable-node | 130 | 0 | 26 |
| ✅ nitro-stable-quickjs | 130 | 0 | 26 |
| ✅ nuxt-stable-node | 130 | 0 | 26 |
| ✅ nuxt-stable-quickjs | 130 | 0 | 26 |
| ✅ sveltekit-stable-node | 149 | 0 | 7 |
| ✅ sveltekit-stable-quickjs | 149 | 0 | 7 |
| ✅ tanstack-start-node | 130 | 0 | 26 |
| ✅ tanstack-start-quickjs | 130 | 0 | 26 |
| ✅ vite-stable-node | 130 | 0 | 26 |
| ✅ vite-stable-quickjs | 130 | 0 | 26 |
✅ 📦 Local Production
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 130 | 0 | 26 |
| ✅ astro-stable-quickjs | 130 | 0 | 26 |
| ✅ express-stable-node | 130 | 0 | 26 |
| ✅ express-stable-quickjs | 130 | 0 | 26 |
| ✅ fastify-stable-node | 130 | 0 | 26 |
| ✅ fastify-stable-quickjs | 130 | 0 | 26 |
| ✅ hono-stable-node | 130 | 0 | 26 |
| ✅ hono-stable-quickjs | 130 | 0 | 26 |
| ✅ nest-stable-node | 130 | 0 | 26 |
| ✅ nest-stable-quickjs | 130 | 0 | 26 |
| ✅ nextjs-turbopack-canary-node | 137 | 0 | 19 |
| ✅ nextjs-turbopack-canary-quickjs | 137 | 0 | 19 |
| ✅ nextjs-turbopack-stable-node | 156 | 0 | 0 |
| ✅ nextjs-turbopack-stable-quickjs | 156 | 0 | 0 |
| ✅ nextjs-webpack-canary-node | 137 | 0 | 19 |
| ✅ nextjs-webpack-canary-quickjs | 137 | 0 | 19 |
| ✅ nextjs-webpack-stable-node | 156 | 0 | 0 |
| ✅ nextjs-webpack-stable-quickjs | 156 | 0 | 0 |
| ✅ nitro-stable-node | 130 | 0 | 26 |
| ✅ nitro-stable-quickjs | 130 | 0 | 26 |
| ✅ nuxt-stable-node | 130 | 0 | 26 |
| ✅ nuxt-stable-quickjs | 130 | 0 | 26 |
| ✅ sveltekit-stable-node | 149 | 0 | 7 |
| ✅ sveltekit-stable-quickjs | 149 | 0 | 7 |
| ✅ tanstack-start-node | 130 | 0 | 26 |
| ✅ tanstack-start-quickjs | 130 | 0 | 26 |
| ✅ vite-stable-node | 130 | 0 | 26 |
| ✅ vite-stable-quickjs | 130 | 0 | 26 |
✅ 🐘 Local Postgres
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ astro-stable-node | 130 | 0 | 26 |
| ✅ astro-stable-quickjs | 130 | 0 | 26 |
| ✅ express-stable-node | 130 | 0 | 26 |
| ✅ express-stable-quickjs | 130 | 0 | 26 |
| ✅ fastify-stable-node | 130 | 0 | 26 |
| ✅ fastify-stable-quickjs | 130 | 0 | 26 |
| ✅ hono-stable-node | 130 | 0 | 26 |
| ✅ hono-stable-quickjs | 130 | 0 | 26 |
| ✅ nest-stable-node | 130 | 0 | 26 |
| ✅ nest-stable-quickjs | 130 | 0 | 26 |
| ✅ nextjs-turbopack-canary-node | 137 | 0 | 19 |
| ✅ nextjs-turbopack-canary-quickjs | 137 | 0 | 19 |
| ✅ nextjs-turbopack-stable-node | 156 | 0 | 0 |
| ✅ nextjs-turbopack-stable-quickjs | 156 | 0 | 0 |
| ✅ nextjs-webpack-canary-node | 137 | 0 | 19 |
| ✅ nextjs-webpack-canary-quickjs | 137 | 0 | 19 |
| ✅ nextjs-webpack-stable-node | 156 | 0 | 0 |
| ✅ nextjs-webpack-stable-quickjs | 156 | 0 | 0 |
| ✅ nitro-stable-node | 130 | 0 | 26 |
| ✅ nitro-stable-quickjs | 130 | 0 | 26 |
| ✅ nuxt-stable-node | 130 | 0 | 26 |
| ✅ nuxt-stable-quickjs | 130 | 0 | 26 |
| ✅ sveltekit-stable-node | 149 | 0 | 7 |
| ✅ sveltekit-stable-quickjs | 149 | 0 | 7 |
| ✅ tanstack-start-node | 130 | 0 | 26 |
| ✅ tanstack-start-quickjs | 130 | 0 | 26 |
| ✅ vite-stable-node | 130 | 0 | 26 |
| ✅ vite-stable-quickjs | 130 | 0 | 26 |
✅ 🪟 Windows
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ nextjs-turbopack-node | 156 | 0 | 0 |
| ✅ nextjs-turbopack-quickjs | 156 | 0 | 0 |
✅ 🌐 Cross-language Conformance
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ python | 9 | 0 | 128 |
✅ vercel-multi-region
| App | Passed | Failed | Skipped |
|---|---|---|---|
| ✅ nextjs-turbopack | 27 | 0 | 0 |
Sim WorldSimulated world deterministic testing for races. Traces 🟠 world-sim scenario book — 2 fail of 42 total
Full trace: |
`sleep(param)` resolves a duration to an instant by reading the *host* wall clock: `createSleep` is a host closure installed on the VM global, so `parseDurationToDate` runs in host scope and never sees the VM's deterministic clock. The conversion happens where the body reaches the `sleep()` call, so every pass that gets there without having consumed a `wait_created` for that wait resolves the duration afresh. Nothing pins the passes to each other. Two scenarios, both red, for the two things that costs: - `sleep-resumeat-recomputed` — the drift. The orchestrator is held inside its `wait_created` write, a bystander hook commits behind it so the held write's snapshot goes stale, the fence rejects it, and the restarted pass reads a clock that has moved. Pass A asks for +30m, pass B for +31m30s, and pass B's value is the one that commits because pass A's never landed. The run completes and its log replays clean — the committed timestamp is self-consistent and nothing in the log records what was originally asked for, so no oracle over the log can see that the answer moved. - `sleep-wait-continuation-stranded` — the same recompute reached from the other side, and it costs the run. A wait continuation whose read is missing its own `wait_created` replays the body, recomputes the deadline, re-creates the wait (rejected as a duplicate, and the suspension writer swallows the conflict), then dispatches a continuation under the same idempotency key as the delivery it is running inside. The queue dedupes it against that in-flight key; the message settles; nothing is queued. The wait stays open and the run never wakes up. The 409 guard the design counts on protects the *log* — one `wait_created`, one `resumeAt`, replays clean. It does not protect the *run*: swallowing the conflict and carrying on is what walks into the deduped re-dispatch. Both fail identically with `--append-only`, which is the point: assigning log positions at commit fixes six position-ordering scenarios and has nothing to say about a client-side clock read. Adds `sleepWithBystanderHookWorkflow` — a plain sleep with an open hook nobody awaits, so a scenario has an out-of-band writer it can fire without changing which branch runs. Book: 38/3/3 -> 38/5/3 mint-ordered, 41/0/0 -> 41/2/0 append-only. No existing scenario changes colour. Co-Authored-By: shalabhc <shalabh.chaturvedi@vercel.com> Co-Authored-By: Shalabh Chaturvedi <7066873+shalabhc@users.noreply.github.com>
`sleep-resumeat-recomputed` shows a pass resolving `sleep()` against a moved clock. Read alone it invites a broader conclusion than the code supports — that every replay re-reads the clock, so a run could never finish a sleep. Measure it instead. `sleep-replay-inherits-resumeat` commits the wait, moves the host clock, and forces a full replay of the body mid-sleep. The replay does re-read the clock — `createSleep` consults no log first — but the wait consumer then overwrites `queueItem.resumeAt` with the logged `wait_created`'s value and sets `hasCreatedEvent`, so the suspension handler neither re-writes the wait nor counts down from the fresh read. The wait fires at the originally committed instant, 0ms late. So the exposure is only a pass reaching `sleep()` with no visible `wait_created`: the first pass, or one whose predecessor's write never landed. That same overwrite is why the `ReplayDivergenceError` in `sleep.ts` is unreachable — the guard passing is the evidence the overwrite happened. Also name which clock, since "not deterministic" does not. Separating the two candidates by 90s of idle time, the drifting pass tracks `hostClock + 30m` off by 0ms while `newestEventCreatedAt + 30m` is off by 90000ms. Recorded as notes rather than checks: both state present behaviour, so asserting them would invert on the fix. Book: 44 scenarios, 39/5/3 default and 42/2/0 append-only. The control passes in both worlds — none of this turns on log-position policy. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Co-Authored-By: shalabhc <shalabh.chaturvedi@vercel.com> Co-Authored-By: Shalabh Chaturvedi <7066873+shalabhc@users.noreply.github.com>
`sleep-resumeat-recomputed` reads as a story about downtime, because the
Slack thread it answers is one. It is not. The trigger for re-reading the
clock is the optimistic-concurrency fence, which fires whenever anything
commits behind an in-flight suspension write — an out-of-band hook payload,
another branch's step result, an attribute write. That is what a busy run
looks like, not a failure mode, and there is no outage anywhere in the
existing repro either: its rejection is a `PreconditionFailedError` raised by
a bystander hook.
`sleep-resumeat-drift-compounds` makes that explicit and adds the part that
changes the risk assessment. Two bystander payloads, each landing behind a
held `wait_created`, give two fence rejections and so three resolutions of
one `sleep('30m')`: 00:30:00, then 00:30:45, then 00:31:30, and the third is
what commits. The drift is the sum of the restarts, so it scales with the
concurrency the run is under rather than being a one-off a retry settles.
The runtime is behaving correctly at every step — it rejects a stale write
and restarts the replay; what it cannot do is carry the deadline across the
restart, because nothing ever wrote the deadline down.
The 45s gaps are inflated for legibility, not a claim about magnitude. In
production the drift is the restart latency; what matters is the ratio, and
the absolute drift that is noise against `sleep('30m')` is the entire
interval for the short sleeps used as poll intervals and race timeouts.
Book: 45 scenarios, 39/6/3 default and 42/3/0 append-only.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Co-Authored-By: shalabhc <shalabh.chaturvedi@vercel.com>
Co-Authored-By: Shalabh Chaturvedi <7066873+shalabhc@users.noreply.github.com>
Co-Authored-By: Shalabh Chaturvedi <7066873+shalabhc@users.noreply.github.com>
Co-Authored-By: Shalabh Chaturvedi <7066873+shalabhc@users.noreply.github.com>
45493c0 to
ea54074
Compare
Summary
Repro only: this PR adds one sim-world scenario proving that
Date.now()immediately afterPromise.raceis not deterministic across workflow passes, even with:Promise.racewinner ordering,It removes the earlier
sleep()scenarios. Those scenarios combined append-only positioning with the old stale-write 412 fence, but slot-identity writes do not use that fence, so they were not valid evidence for the production mode in scope.Repro
The workflow races a step against an out-of-band hook, then reads
Date.now()and branches around a fixed cutoff:The scenario scripts this append-only history:
+0msand wins the race.+0ms, selects the before-cutoff branch, and proposes a two-minutewait_created. The scenario holds that write before commit.step_completed,hook_received,wait_created.EventsConsumersynchronously consumes both the step completion and hook payload before promise continuations run.Promise.race, but event consumption has already advanced the VM clock to the hook's+1mtimestamp.The scenario has two independent observations:
That isolates the bug: the race winner is deterministic, while the clock value observed immediately after the race depends on how much of the committed log that pass consumed.
Why delivery ordering does not fix it
Delivery barriers order when resolved values reach workflow code. The VM clock advances earlier, in
EventsConsumer.onConsumedEvent, while the log is synchronously drained. By the time barriers deliver the stable winner,Date.now()already reflects the newest consumed event, including a losing competitor that was absent from the earlier pass.Result
The live run completes and the final log passes cold replay. The red signal is the scenario's cross-pass check, because the durable log contains only the later branch and cannot recover the first pass's clock observation.
No runtime fix is included.
Verification