Repository navigation
Durable Object → Durable Object RPC calls delivered ~3.1 s late between specific objects in one colo (SEA), persisting across deploys #7607
Description
Summary
On the hosted Workers platform (production, not local workerd), JS RPC calls from two specific Durable Objects to five specific sibling objects of the same class, all in colo SEA, reach the callee about 3.1 s after they are sent. Other calls of the same request, sent in the same millisecond to other siblings, are answered in tens of milliseconds, and the late callee runs the call in 10–60 ms once it is invoked. It has been continuous since 2026-10-01 23:25 UTC, has survived six deploys and several hundred fresh isolates, and was ongoing at 2026-10-03 22:40 UTC. The same code in other regions does not show it (for example enam, all eleven objects in EWR: 0 of 12,724 requests on 10-03).
Worker sylvan-librarian · Durable Object class SearchEngine (SQLite-backed, migration tag v2) · colo SEA · Workers Paid · account id and namespace id available to Cloudflare staff on request / via a support ticket. Earliest episode in our retained metrics is 2026-09-26.
What the application does
Eleven objects named engine-wnam-p0 … engine-wnam-p10 (created with locationHint: "wnam") each hold one partition of a read-only index in wasm memory. A Worker calls one of them over fetch; that object (the "coordinator") calls its ten siblings in parallel over JS RPC (stub.searchKeys(...), then stub.fetchRows(...)), each call on a stub from env.SEARCH_ENGINE.get(env.SEARCH_ENGINE.idFromName(name)), with at most six calls outstanding at a time. No storage is touched on this path. All eleven objects reported colo SEA in every one of 97 self-probes (a fetch of https://www.cloudflare.com/cdn-cgi/trace from inside the object) between 09-27 and 10-03, and GraphQL durableObjectsInvocationsAdaptiveGroups.coloCode is SEA for all of them on every day of that week.
Observed behaviour
From two coordinators, one to four of the ten sibling calls of a request reach their sibling about 3.1 s after they were sent.
| object | id | role |
|---|---|---|
engine-wnam-p10 |
669242d40ff0a82acea97ae47009b9698e2bc39877c89632ea7a7d4fdac88691 |
caller whose calls are late, since 10-01 23:25 UTC |
engine-wnam-p8 |
977e77a7bd4e8d4da79e3df14ae9c3059a01d9ec8b9e9324fd8c35411b8ff447 |
caller whose calls are late, since 10-02 12:57 UTC |
engine-wnam-p0 |
8f8f238f208d36fb912f56b1c9c1052c4d6250289269d32935c8d2587ebaebae |
callee reached late |
engine-wnam-p4 |
453c5a6717f48fbaa406c1b23e624d1f1d0b36d1dc1a47d62edb85ea106483a0 |
callee reached late |
engine-wnam-p5 |
f213f8cb46397c73659bd1322090db1ced95609b17e3bfa5046b92594968d692 |
callee reached late |
engine-wnam-p6 |
66edffefea211d356f46c772fcb6765ab4d330c37c320c4d3afed3c6c11619de |
callee reached late |
engine-wnam-p7 |
7df13fa1dfa6d38cbad7bc30f8967c93db794dd1320a5a0929528c41312d0e28 |
callee reached late |
engine-wnam-p1 |
d35d067a51f6574937803ece61c40f4d6d9a9a07d91d08758b9c9e0aa27d528d |
callee reached on time from the same two callers |
engine-wnam-p2 |
1897b9410e069e7f3c7d3afd7fbb0e21d067fcef45f352f0d10c3bb6efa99b94 |
callee reached on time |
engine-wnam-p3 |
102d4c9676d1c5d3a6535a6e9bfdfc491508923bc05ffc969ced1da2e37a7536 |
callee reached on time |
engine-wnam-p9 |
819ca8fba9547800b657adffe170ba5257088731f45a785c72d158f58cdea4c2 |
callee reached on time |
Scale (2026-10-03 00:00–23:00 UTC)
Requests with at least one sibling call ≥ 2.8 s late, or still unanswered when a duplicate call had already answered:
engine-wnam-p10: 1,470 of 4,073 coordinated (36%)engine-wnam-p8: 1,327 of 3,949 (34%)- each of the other nine
engine-wnam-*coordinators: 44–78 of about 3,900 (1–2%)
The late callee was p0, p4, p5, p6 or p7 in 4,776 of the two callers' 4,825 late calls, and p1, p2, p3 or p9 in 35.
Other regions, same code, same day: enam (all eleven objects in EWR) 0 of 12,724; weur (AMS and LHR) 2 of 1,086; apac-se (SIN) 0 of 854.
The same two objects are also slower as callees: on 10-03 their jsrpc wallTimeP99 is 2,481 ms (p8) and 2,585 ms (p10), against 433–695 ms for the other nine engine-wnam-* objects on near-identical request counts (43,202–44,340 each).
Quantisation. Before we sent any duplicate calls (10-02 05:42–07:34 UTC), 68 late calls were logged: 58 took 3,100–3,299 ms, 3 took 3,300–3,499 ms, 6 took 1,400–2,999 ms and 1 took between 1,000 and 1,399 ms. Nothing in our code waits 1 s or 3 s.
Samples (2026-10-02, UTC)
"Sent" and "answered after" are measured by the caller with Date.now() around the RPC. The callee columns are from durableObjectsInvocationsAdaptiveGroups at one-second resolution (type: jsrpc, dimensions name datetime).
| caller | sent | callee | answered after | callee, in the second the call was sent | callee's next invocation, and its wall time | the other callees of the same request |
|---|---|---|---|---|---|---|
| p10 | 05:45:46.246 | p6 | 3,160 ms | no invocation | 05:45:49, 34 ms | all nine invoked in 05:45:46, 20–41 ms (one 339 ms) |
| p10 | 06:08:55.778 | p0 | 3,179 ms | no invocation | 06:08:57–58, 62–213 ms | all nine invoked in 06:08:55, 29–95 ms (one 391 ms) |
| p10 | 06:15:40.747 | p5 | 3,372 ms | one invocation fewer than its peers | 06:15:44, 40 ms | invoked in 06:15:40, 16–57 ms |
| p10 | 06:15:40.747 | p7 | 3,267 ms | one invocation fewer than its peers | 06:15:44, 48 ms | same request |
| p10 | 06:57:32.575 | p4 | 3,145 ms | no invocation | 06:57:35, 17 ms | all nine invoked in 06:57:32, 6–23 ms |
| p10 | 07:13:25.722 | p5 | 3,223 ms | one invocation fewer than its peers | 07:13:28, 30 ms | invoked in 07:13:25, 6–33 ms |
| p8 | ≈14:14:01.97 | p0 | 3,168 ms | no invocation in 14:14:02 | 14:14:05, 39 ms | p1, p2, p3, p9, p10 invoked in 14:14:02; p4, p6, p7 also next invoked in 14:14:05 |
| p8 | ≈18:31:07.98 | p6 | 3,309 ms | no invocation in 18:31:08 | 18:31:11, 13 ms | p1, p2, p3, p5, p7, p9, p10 invoked in 18:31:08; p0 and p4 also next invoked in 18:31:11 |
In the last two rows the caller sent a second, identical call on a new stub 500 ms after the first. In the last row p0, p4 and p6 each show two invocations in second 18:31:11: the first call and the second arrived together. Across 10-02 09:48–19:48 UTC the second call was answered first in 194 of 248 such cases (median 17 ms after it was sent); in 36 it was sent on time and was still answered only when the first was, about 3 s late.
It follows where an object runs, and it survives restarts
engine-wnam-p10has been affected since our deploy of 10-01 23:25:43 UTC, across six later deploys (10-02 01:40, 05:42, 07:34, 09:17, 09:46, 21:09 UTC), two nightly data swaps, and several hundred fresh isolates (the object is evicted after about 10 idle seconds; it loaded its store 293 times on 10-03). Late calls occur on isolates 1 s old and 1,798 s old alike.engine-wnam-p8was unaffected until 10-02 12:57:25 UTC. At that second it started in the isolate that already heldengine-wnam-p10— our log line readsisolate load #2 (first 138s ago), holds 2 engine(s): engine-wnam-p10, engine-wnam-p8, and no store load before that second, back to 09-27, lists the two together. Its first duplicate calls for a late sibling are logged at 13:06:07 UTC. We deployed nothing between 09:46 and 21:09 UTC. 334 later store loads found the two objects in one isolate; no other pair ofengine-wnam-*objects shared an isolate in that period.- Earlier episodes ended with no action on our side:
engine-wnam-p9on 09-29 04:00–09:00 and 20:30–24:00 UTC (we deployed nothing between 09-26 23:29 and 10-01 20:10 UTC);engine-wnam-p1on 09-26 23:15 – 09-27 01:30 and on 10-02 00:30–08:15 UTC.
Ruled out
- The six-connection limit. Since the deploy of 10-02 05:42 UTC a request keeps at most six sibling calls outstanding; the late calls continued unchanged.
- Cold starts. A callee reports its own store-load time in its reply, and calls that carried one are excluded from every count above.
- Callee CPU or queueing. The callee's wall time is 10–60 ms once it is invoked, and the same callees answer other coordinators within the same second.
- Caller CPU. On 10-03 the two affected callers'
httpCPU p50 is 8.5–8.7 ms, inside their siblings' range (6.6–13.7 ms); their wall-time p50 is 364–417 ms against 88–170 ms. - Distance between colos. All eleven objects are in SEA. Regions whose objects are split across colos (weur AMS/LHR, eeur WAW/FRA/VIE, oc SYD/BNE/MEL) show at most 3 such requests a day.
Questions
- Between the host(s) running
669242d4…and977e77a7…and the host(s) running8f8f238f…,453c5a67…,f213f8cb…,66edffef…and7df13fa1…in SEA, is connection setup for Durable Object RPC being retried — for example SYN or handshake loss on a 1 s then 2 s retransmit timer? We ask because of the 3.1 s delay, the occasional delay of just over 1 s, and two calls sent 500 ms apart arriving together. We have no visibility below the RPC and do not know that this is the cause. - Can
669242d4…and977e77a7…be migrated to another host, or the path between those hosts be checked? - If we stop using these two names and create replacements under new names, what determines the colo and host the new objects are placed on, and can they land on the same host?
We can supply more timestamps and the request ids of affected fetch invocations, or run a minimal reproduction Worker in this account, on request.
Activity
Placement: engine-wnam-p8 on DeckGen Is Abandoned for Its Next Epoch …
daveycodez commentedon Oct 5, 2026
Update, with a workaround in place. On 2026-10-04 we stopped using two of the affected objects and addressed replacements instead (the name gained an
-e1suffix, so each replacement is a different object placed afresh). Counts below are of our ownslow gatherlog line (a gather where the slowest sibling call took long), over the same hours of 10-03 and 10-04.colo=SJCp10 averaged 12.1 slow gathers per hour over 02:00–19:00 UTC on 10-04. Since it was abandoned at 19:00 UTC, it and p10-e1 each log about 1.1 per hour, over 5.3 hours.
Our inference, not a diagnosis: the same code and traffic on freshly placed objects does not show the stall, so it looks tied to where the original two objects were placed, not to our code or request pattern. That partly answers our third question: the replacement for p8 was placed in SJC.
Caveat: these are counts of our own log line, not a platform metric, and a deploy that rebuilds the store causes a separate, expected burst (about 400 to 500 slow gathers in the following hour across all objects, as they reload).
If a maintainer wants to inspect the original p8 and p10 instances, we can keep them alive; they are unused now and not deleted.