Skip to content

Durable Object → Durable Object RPC calls delivered ~3.1 s late between specific objects in one colo (SEA), persisting across deploys #7607

Open

Description

@daveycodez

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-p10 has 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-p8 was unaffected until 10-02 12:57:25 UTC. At that second it started in the isolate that already held engine-wnam-p10 — our log line reads isolate 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 of engine-wnam-* objects shared an isolate in that period.
  • Earlier episodes ended with no action on our side: engine-wnam-p9 on 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-p1 on 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' http CPU 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

  1. Between the host(s) running 669242d4… and 977e77a7… and the host(s) running 8f8f238f…, 453c5a67…, f213f8cb…, 66edffef… and 7df13fa1… 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.
  2. Can 669242d4… and 977e77a7… be migrated to another host, or the path between those hosts be checked?
  3. 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

  1. daveycodez commented on Oct 5, 2026

    @daveycodez
    Author

    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 -e1 suffix, so each replacement is a different object placed afresh). Counts below are of our own slow gather log line (a gather where the slowest sibling call took long), over the same hours of 10-03 and 10-04.

    object 10-03 hours 10-04 hours note
    p8 (abandoned 02:00 UTC) 899 9 (p8-e1) 16.5 h each side; traffic down 18%; p8-e1 reports colo=SJC
    p10 (left in place until 19:00 UTC) 1,002 205 fell after p8 left its isolate; still the only outlier, every other wnam coordinator logged 7 to 26
    all coordinators 2,383 605 workaround was partial

    p10 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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions