[devnet-8] grandine-reth-1/2 proposals orphaned: reth changeset-cache MISS wedges engine API ~18s during payload prep

[barnabasbusa]

Summary

~28% of grandine-reth-1/2 proposals on devnet-8 publish ~8.2s into the slot and mostly get orphaned. Root cause is on the reth side: during payload preparation, reth's trie changeset cache misses and falls back to a synchronous DB computation that wedges the entire engine API for ~18s. The snooper-engine connection errors in grandine's logs are a downstream symptom of the wedged engine, not the cause.

Broken since genesis (first occurrence 2026-08-13 13:01 UTC, one hour in). All numbers below are from the first ~24h of the network (genesis 1786622400 = 2026-08-13 12:00:00 UTC, 12s slots).

Impact (24h)

instance	proposals	published ≥4s late	avg publish delay	max
grandine-reth-1	76	21	2.36s	8.27s
grandine-reth-2	64	19	2.52s	8.27s
every other grandine-<el> pair	58–88 each	0	~0.1s	≤1.13s

The late proposals match reth's Changeset cache MISS events 1:1 (21 and 19 respectively), and the affected slots line up exactly with Dora's orphan list (517, 834, 1177, 2516, 3004, 3209, 6117, …). The two non-grandine orphans currently visible in Dora (prysm-geth-2 slot 1246, prysm-ethrex-2 slot 857) are a different issue — note their 1.56% / 0.98% sync participation.

Mechanism (traced on slot 6117, grandine-reth-1)

1. 08:23:12.6 (slot 6116 +0.6s) — grandine imports the head block and sends its payload-prep engine_forkchoiceUpdated with attributes for its slot-6117 proposal. Reth creates the payload job normally (New payload job created id=0x371d35520ad3de13).
2. 08:23:13.65 — reth logs:

   WARN trie::changeset_cache: Changeset cache MISS in range, falling back to aggregate DB-based computation start_block=6076 end_block=6078
   

   then goes completely silent for 18.4s. The engine API is blocked.
3. 08:23:24.02 (slot 6117 start) — grandine's slot-start fcU fails instantly:

   WARN eth1_api: last available Eth1 RPC endpoint http://snooper-engine:8561/ returned an error: failed to send request
   WARN eth1_api::execution_service: engine_forkchoiceUpdated call failed: all Eth1 RPC endpoints exhausted
   WARN block_producer: error while preparing execution payload: oneshot canceled
   

4. 08:23:32.04 (slot +8.0s) — reth finishes the computation and drains the queued fcUs (WARN engine::tree: Failed to deliver forkchoiceUpdated response, receiver dropped (request cancelled) ×2, each with elapsed in µs — the clients were long gone).
5. 08:23:32.18 (slot +8.2s) — grandine publishes the block. Attesters voted for the parent seconds ago → orphaned.

Why only grandine-reth orphans

All six reth nodes (teku-reth, prysm-reth, grandine-reth ×2) hit the MISS on ~30% of their proposals, always with the same 3-block recompute span (~N-7..N-5 behind head), on identical droplet sizes:

instance	MISS events	post-MISS stall (median / max)
grandine-reth-1	21	18.4s / 18.9s
grandine-reth-2	19	18.4s / 18.6s
teku-reth-1	26	10.5s / 11.5s
teku-reth-2	22	10.5s / 10.9s
prysm-reth-1	18	10.4s / 10.9s
prysm-reth-2	25	10.6s / 10.9s

Both grandine and teku issue the payload-prep fcU ~0.4–0.6s after the previous block imports (≈11.4s before their proposal slot). teku/prysm stalls end ~2s before the proposal slot starts, so their blocks go out on time; grandine's consistently run ~8s longer and overrun the slot. (The teku/prysm figures are gap-to-next-log-line, so they're upper bounds; grandine's 18.4s is exact — the gap terminates with the queued-fcU processing. Why grandine's stalls are ~2x longer is unresolved: possibly disk variance, or grandine's slot-start fcU retriggering work.)

Regardless of the asymmetry, a 10–18s synchronous stall of the engine API during payload prep is the bug.

Code pointer

crates/storage/storage-overlay/src/changeset_cache.rs → get_or_compute_range(): on cache miss it calls reth_trie_db::compute_range_trie_changesets synchronously. The cache backs OverlayStateProviderFactory, used by the engine-tree payload validator / state-root strategy (crates/engine/tree/src/tree/payload_validator.rs, state_root_strategy/). Upstream reth code, shipped in ethpandaops/reth:glamsterdam-devnet-8.

Very likely the same root cause as the devnet-7 grandine-reth-1 orphan streak (~50% of proposals, blocks 4.3s/12.16s late since the Aug 7 reth watchtower bump) that was attributed at the time to a broken "snooper-engine path" — same snooper error signature, which this investigation shows is just the symptom.

Reproduce the numbers (panda CLI)

All queries go through panda clickhouse query-raw clickhouse-raw '<sql>'. Node logs live in external.otel_logs; filter with ResourceAttributes['network']='glamsterdam-devnet-8' and ResourceAttributes['instance']='<node>'. Slot math uses genesis 1786622400, 12s slots.

Snooper/engine failure counts per node (grandine-reth-1: 42, grandine-reth-2: 38, next highest: 2):

panda clickhouse query-raw clickhouse-raw "
SELECT ResourceAttributes['instance'] AS inst, count() AS c, min(Timestamp) AS first, max(Timestamp) AS last
FROM external.otel_logs
WHERE Timestamp > now() - INTERVAL 24 HOUR
  AND ResourceAttributes['network']='glamsterdam-devnet-8'
  AND ServiceName='beacon'
  AND Body ILIKE '%failed to send request%' AND Body ILIKE '%snooper-engine%'
GROUP BY inst ORDER BY c DESC LIMIT 30"

Map those failures to slots (they come in pairs at t+0s and t+8s of grandine-reth's own proposal slots):

panda clickhouse query-raw clickhouse-raw "
SELECT Timestamp, intDiv(toUnixTimestamp(Timestamp) - 1786622400, 12) AS slot
FROM external.otel_logs
WHERE Timestamp > now() - INTERVAL 24 HOUR
  AND ResourceAttributes['network']='glamsterdam-devnet-8'
  AND ResourceAttributes['instance']='grandine-reth-1'
  AND ServiceName='beacon'
  AND Body ILIKE '%failed to send request%' AND Body ILIKE '%snooper-engine%'
ORDER BY Timestamp LIMIT 50"

Changeset-cache MISS events per reth node, mapped to slots (fires at slot N-1 for each affected proposal at slot N):

panda clickhouse query-raw clickhouse-raw "
SELECT ResourceAttributes['instance'] AS inst, Timestamp,
       intDiv(toUnixTimestamp(Timestamp) - 1786622400, 12) AS slot
FROM external.otel_logs
WHERE Timestamp > now() - INTERVAL 24 HOUR
  AND ResourceAttributes['network']='glamsterdam-devnet-8'
  AND ServiceName='execution'
  AND ResourceAttributes['instance'] LIKE '%-reth-%'
  AND Body ILIKE '%Changeset cache MISS%'
ORDER BY Timestamp LIMIT 150"

Post-MISS stall duration per node (gap from the MISS line to the node's next execution log line):

panda clickhouse query-raw clickhouse-raw "
SELECT inst, t0, round(gap_s, 1) AS stall_s FROM (
  SELECT ResourceAttributes['instance'] AS inst, Timestamp AS t0, Body,
         dateDiff('millisecond', Timestamp,
           leadInFrame(Timestamp) OVER (PARTITION BY ResourceAttributes['instance'] ORDER BY Timestamp
             ROWS BETWEEN CURRENT ROW AND 1 FOLLOWING))/1000.0 AS gap_s
  FROM external.otel_logs
  WHERE Timestamp > now() - INTERVAL 24 HOUR
    AND ResourceAttributes['network']='glamsterdam-devnet-8'
    AND ServiceName='execution'
    AND ResourceAttributes['instance'] LIKE '%-reth-%'
) WHERE Body ILIKE '%Changeset cache MISS%'
ORDER BY inst, t0 LIMIT 150"

Recompute range span per node (always end_block - start_block = 2, i.e. 3 blocks; strip ANSI escapes before extracting):

panda clickhouse query-raw clickhouse-raw "
WITH replaceRegexpAll(Body, '\\x1b\\[[0-9;]*m', '') AS clean
SELECT ResourceAttributes['instance'] AS inst,
       toInt64(extract(clean, 'end_block=(\\d+)')) - toInt64(extract(clean, 'start_block=(\\d+)')) AS span,
       count() AS c
FROM external.otel_logs
WHERE Timestamp > now() - INTERVAL 24 HOUR
  AND ResourceAttributes['network']='glamsterdam-devnet-8'
  AND ServiceName='execution'
  AND ResourceAttributes['instance'] LIKE '%-reth-%'
  AND Body ILIKE '%Changeset cache MISS%'
GROUP BY inst, span ORDER BY inst, span LIMIT 40"

Publish delay for every grandine proposal (the impact table above):

panda clickhouse query-raw clickhouse-raw "
WITH toUnixTimestamp(Timestamp) - 1786622400 AS t
SELECT ResourceAttributes['instance'] AS inst,
       round(avg(t - intDiv(t,12)*12 + (toUnixTimestamp64Milli(Timestamp) % 1000)/1000.0),2) AS avg_delay_s,
       round(max(t - intDiv(t,12)*12 + (toUnixTimestamp64Milli(Timestamp) % 1000)/1000.0),2) AS max_delay_s,
       countIf((t - intDiv(t,12)*12) >= 4) AS late_ge4s,
       count() AS proposals
FROM external.otel_logs
WHERE Timestamp > now() - INTERVAL 24 HOUR
  AND ResourceAttributes['network']='glamsterdam-devnet-8'
  AND ServiceName='beacon'
  AND ResourceAttributes['instance'] LIKE 'grandine-%'
  AND Body ILIKE '%publishing beacon block%'
GROUP BY inst ORDER BY inst LIMIT 20"

Full log context for one incident (slot 6117, grandine-reth-1 — swap the window for other slots):

panda clickhouse query-raw clickhouse-raw "
SELECT Timestamp, ServiceName, Body
FROM external.otel_logs
WHERE Timestamp BETWEEN '2026-08-14 08:23:10' AND '2026-08-14 08:23:35'
  AND ResourceAttributes['network']='glamsterdam-devnet-8'
  AND ResourceAttributes['instance']='grandine-reth-1'
  AND ServiceName IN ('beacon','execution')
  AND Body NOT ILIKE '%data column sidecar%'
ORDER BY Timestamp LIMIT 100"

Next step

Report upstream to the reth team: the fallback compute_range_trie_changesets DB walk should not block the engine message loop (or the changeset cache should cover/precompute the ranges the overlay factory asks for). The 8–18s engine wedge lands exactly in the proposer's critical path.

[barnabasbusa]

Reported upstream: paradigmxyz/reth#26704