debug `ensv2` indexing slowness

[shrugs]

Current Findings

• ran into late slowness (last ~6 weeks of realtime) where eps dropped from ~2-3k to 100
  • rpc cache was backfilled to -40hrs so that's not it
  • just overhead of omnichain ordering?
  • try multichain ordering?
• ensv2/ENSv1Registry:NewOwner is still the worst offender just due to complexity. 16.5M events at 1.16ms/event, which seems fast is still ~5.5 hours alone. not sure how much further it could be optimized.
  • each NewOwner event in ensv2 results in more db ops than its subgraph counterpart
• ponder in-memory cache is too small and/or is flushing to postgres too often?
  • how do we measure when ponder flushes to postgres
  • can we increase the in-memory cache size?
• have ensureEvent return eventId and have ensure*Event accept it; because it's sometimes called twice in a handler, reduces db ops in those event handlers by 50% but there aren't that many of them, so probably looking at 1-5% tops.
• try Promise.all parallelization for independent db ops, maybe ponder can make them more efficent

[shrugs]

Wall-clock to realtime: 39h 02m 01s (140,521s)

  - Branch: test/ensv2-perf (with refactor/ensv1-domain-model bug fix)
  - Config: NAMESPACE=mainnet, PLUGINS=ensv2,protocol-acceleration, LABEL_SET_ID=subgraph
  - Stub: apps/ensindexer/src/lib/ensv2/label-db-helpers.ts healedLabel = null
  - Start: 2026-04-24 20:17:17 UTC
  - End: 2026-04-26 11:19:18 UTC (omnichain-following at 11:18:54)
  - Total events: 149.8 M
  - Average EPS: 1066/s overall
  - Peak EPS: ~4122/s (first minute), sustained 2200-3000/s in middle phase
  - Final-tail EPS: ~100/s (omnichain coordination throttle)

  Hot paths (top 25 by wall-clock at finish)

  ┌───────┬────────────┬───────────┬────────┬─────────────────────────────────────────────────┐
  │ Share │ Wall-clock │ Avg ms/ev │ Events │                     Handler                     │
  ├───────┼────────────┼───────────┼────────┼─────────────────────────────────────────────────┤
  │ 37.6% │    19,191s │      1.16 │  16.5M │ ensv2/ENSv1Registry:NewOwner                    │
  ├───────┼────────────┼───────────┼────────┼─────────────────────────────────────────────────┤
  │  8.3% │     4,242s │      0.34 │  12.6M │ protocol-acceleration/ENSv1Registry:NewResolver │
  ├───────┼────────────┼───────────┼────────┼─────────────────────────────────────────────────┤
  │  6.8% │     3,473s │      0.27 │  12.7M │ ensv2/BaseRegistrar:Transfer                    │
  ├───────┼────────────┼───────────┼────────┼─────────────────────────────────────────────────┤
  │  5.1% │     2,621s │      0.23 │  11.6M │ protocol-acceleration/Resolver:AddressChanged   │
  ├───────┼────────────┼───────────┼────────┼─────────────────────────────────────────────────┤
  │  5.1% │     2,612s │      0.21 │  12.6M │ ensv2/ENSv1Registry:NewResolver                 │
  ├───────┼────────────┼───────────┼────────┼─────────────────────────────────────────────────┤
  │  4.9% │     2,502s │      1.72 │  1.46M │ ensv2/BaseRegistrar:NameRenewed                 │
  ├───────┼────────────┼───────────┼────────┼─────────────────────────────────────────────────┤
  │  4.4% │     2,225s │      0.19 │  11.6M │ ensv2/Resolver:AddressChanged                   │
  ├───────┼────────────┼───────────┼────────┼─────────────────────────────────────────────────┤
  │  4.1% │     2,085s │      0.58 │  3.57M │ ensv2/BaseRegistrar:NameRegisteredWithRecord    │
  ├───────┼────────────┼───────────┼────────┼─────────────────────────────────────────────────┤
  │  4.1% │     2,080s │      0.45 │  4.61M │ ensv2/BaseRegistrar:NameRegistered              │
  ├───────┼────────────┼───────────┼────────┼─────────────────────────────────────────────────┤
  │  3.4% │     1,745s │      0.20 │  8.54M │ protocol-acceleration/Resolver:NameChanged      │
  └───────┴────────────┴───────────┴────────┴─────────────────────────────────────────────────┘

  Headlines

  - ensv2/ENSv1Registry:NewOwner is still ~38% of total wall-clock, down from ~50% in the buggy run but still the dominant cost. 1.16 ms/event × 16.5M events = ~5.3h of CPU time on this single handler alone.
  - paired duplication still apparent: every ENSv1Registry:* and Resolver:* event runs in both ensv2/ and protocol-acceleration/. The ensv2 side is 5-15× heavier per event (eg NewOwner ensv2 1.16 ms vs PA 0.07 ms
   — a 17× ratio).
  - BaseRegistrar:NameRenewed at 1.72 ms/event is the second slowest per-event handler — only 1.46M events but expensive each.
  - Long tail of omnichain coordination cost — last ~12h were spent advancing the cursor at ~15-18× wall-clock through the 6-week-behind state. Backfill % was at 98.7% from hour 16 to hour 38.

  ┌──────────────────────────────────────────────┬────────────────────┐
  │                                              │        Time        │
  ├──────────────────────────────────────────────┼────────────────────┤
  │ Wall-clock (39.03h)                          │          140,521 s │
  ├──────────────────────────────────────────────┼────────────────────┤
  │ Handler total (sum of all per-event seconds) │           51,029 s │
  ├──────────────────────────────────────────────┼────────────────────┤
  │ Ponder framework / DB / coordination         │ 89,492 s = 24.86 h │
  └──────────────────────────────────────────────┴────────────────────┘

  ~64% of Run B was not spent in user code. Single-threaded equivalent — Ponder may be doing some of this in parallel with handlers, but the time still came out of wall-clock.

Per-event cost grew, but DB was not slowing down

  ensv2/ENSv1Registry:NewOwner:
  - Whole run: 1.16 ms/event
  - Last 11h: 2.26 ms/event (~2× slower)
  - Last 7h: 1.87 ms/event

  ponder_indexing_store_queries_total rate over the run:
  17:53 UTC → 312/sec
  21:53     → 403/sec
  01:53 UTC → 508/sec
  05:53     → 610/sec
  09:53     → 1,421/sec

DB ops/sec increased 4.5× through the run. Combined with EPS dropping from ~2200 to ~100, that means each event triggered far more store ops at the tail. So DB throughput was healthy; events in the dense recent era inherently issue more inserts/upserts.

which begs the question; why do the recent dense event handlers produce more db ops?

[shrugs]

⏺ Run C Final Report

  Wall-clock to realtime: 10h 16m 40s (37,000s)

  - Branch: test/ensv2-perf (with refactor/ensv1-domain-model)
  - Config: NAMESPACE=mainnet, PLUGINS=subgraph,basenames,lineanames,protocol-acceleration
  - Stub: apps/ensindexer/src/lib/graphnode-helpers.ts labelByLabelHash → null
  - Start: 2026-04-26 15:23:44 UTC
  - End: 2026-04-27 01:40:24 UTC

  Run B vs Run C — head to head

  ┌───────────────────────────────┬────────────────────┬───────────────┬─────────────────────┐
  │            metric             │ Run B (ensv2 + PA) │ Run C (alpha) │      ratio C/B      │
  ├───────────────────────────────┼────────────────────┼───────────────┼─────────────────────┤
  │ Wall-clock                    │            39h 02m │       10h 17m │ 0.26× (3.8× faster) │
  ├───────────────────────────────┼────────────────────┼───────────────┼─────────────────────┤
  │ Total events                  │            149.8 M │       147.0 M │                0.98 │
  ├───────────────────────────────┼────────────────────┼───────────────┼─────────────────────┤
  │ Avg EPS                       │              1,066 │         3,974 │               3.73× │
  ├───────────────────────────────┼────────────────────┼───────────────┼─────────────────────┤
  │ Handler total time            │            14.17 h │        7.19 h │               0.51× │
  ├───────────────────────────────┼────────────────────┼───────────────┼─────────────────────┤
  │ Framework / DB / coordination │            24.86 h │        3.08 h │    0.12× (8× less!) │
  ├───────────────────────────────┼────────────────────┼───────────────┼─────────────────────┤
  │ Framework share of wall-clock │                64% │           30% │                  -- │
  └───────────────────────────────┴────────────────────┴───────────────┴─────────────────────┘

• absolute event counts are essentially identical between configs (147M vs 150M), so the difference is work done per event, not number of events processed
• subgraph/ENSv1Registry:NewOwner at 0.10 ms/ev × 7.9M events = 13 minutes. 80× cheaper per event for that one handler
• framework/DB overhead dropped 8× (24.9h → 3.1h) (measured as wall-clock time not spent in handlers)
  • they trigger similar degrees of db operations, but ensv2 obviously triggers more, but not 10x more
• suspect: VersionChanged custom sql? especially if lots later

[shrugs]

• because we use CAIP ids and the ponder prefetcher doesn't understand them, we don't get access to prefetching
  • which increases framework-level flushes

here's what claude has to say

  Sources of the framework-time delta (the 8×)

  Items below are all in flush + prefetch + commit, i.e. outside handler time:

  1. Row-volume multiplier (~2–3×): ensv2's ENSv1Registry:NewOwner writes ~7 distinct rows per event (registry-if-TLD, virtual registry, registryCanonicalDomain, account, domain, label, event+domainEvent). Alpha's
  equivalent writes ~3 (account, domain, transferEvent/newOwnerEvent). Per batch (~1,720 events from syncEventsQuerySize: 12_000 divided across chains, see options.ts:128), ensv2 buffers ~12k rows vs alpha's ~5k.
  2. Distinct-table multiplier (~1.75×): ensv2 touches ~7 tables per batch, alpha ~4. Each table is one flushTable() invocation, sequential at the driver. Even when most are empty inserts (skipped at line 555), the
   iteration walks every cached table.
  3. Update-temp-table tax: ensv2's domain upsert re-asserts ownerId/rootRegistryOwnerId on every NewOwner. With >20 updates per batch (almost always for domain), the flush emits 4 SQL statements instead of 1
  (cache.ts:607–641: CREATE TEMP TABLE, COPY, UPDATE FROM, TRUNCATE). Alpha hits this path on fewer tables.
  4. Per-batch overhead amplification: prefetch issues 1 SELECT per predicted table (cache.ts:972–1029). If ensv2's predictions cover few tables (because the matcher couldn't derive keys), prefetch is cheap — so
  this helps ensv2 framework time. The win on prefetch is partially offset by the extra flushTable iterations on the write side.
  5. Per-op JS work: every db.* call calls copy(value) (deep clone), normalizeRow, getCacheKey (string serialization of pk), plus mutex acquire/release. At ~1.2B operations across 150M events, this compounds.
  Counts as handler time mostly, but flush() also walks insertBuffer / updateBuffer building COPY text — that's framework.

  Combined: ~2.5× rows × ~1.75× tables × ~1.5× update-statement-cost ≈ ~6–8× framework overhead. Matches the observed 8×.

[shrugs]

Run D — perf/delimited-ids experiment

Tested the hypothesis that Ponder's profile-pattern matcher (which drives the indexing-cache prefetcher) was failing to decompose our composite primary keys because they used CAIP-style mixed :// delimiters. Ponder's matcher (profile.ts:480-503) is a single-level splitter — it picks ONE delimiter per call and recurses one level. Mixed delimiters defeated it.

What changed

Branch perf/delimited-ids (off refactor/ensv1-domain-model):

• f988de4f — packages/enssdk/src/lib/ids.ts: switched all composite id constructors from CAIP-mixed :// to single - delimiter. Concretely, makeENSv1RegistryId etc. now produce ${chainId}-${address}-${node} instead of eip155:${chainId}:${address}/${node}. Dropped the erc1155 literal from makeENSv2DomainId (registry contract already namespaces).
• 2b09930c — apps/ensindexer/src/lib/graphnode-helpers.ts: stubbed labelByLabelHash to return null. Same as Run B (which also had ENSRainbow stubbed), so this is not a confounder vs Run B.

Both commits are local-only on the branch — not pushed.

Headline result

	Wall clock backfill	events/sec
Run B (CAIP-style ids, ENSRainbow stubbed)	~24h 51m	~1,675
Run D (dash-delimited ids, ENSRainbow stubbed)	11h 13m 51s	~3,700
Speedup	~2.21x

Run D ran from 2026-04-27 22:06 CDT to 2026-04-28 09:20 CDT on the same machine, same ponder_sync cache, same plugin config (ensv2,protocol-acceleration on mainnet), same ENSRainbow-stubbed code path. Apples-to-apples vs Run B — only the id format changed.

Why it worked — prefetch hit rates per table (final snapshot, ~09:39)

table	hit rate
events	100.0%
accounts	100.0%
resolver_events	100.0%
resolvers / resolver_records	100.0%
registries	99.6%
registry_canonical_domains	99.6%
domains	86.9%
resolver_address_records	85.8%
domain_resolver_relations	80.9%
labels	98.7%
domain_events	26.4% ← structural floor
migrated_nodes	0% prefetch

Overall: 83.6% cache hit rate. Pre-change (Run B) would have been near 0% across the board — the prefetch metric is what makes the causal attribution clean.

Minor caveats (not Run-B-vs-Run-D confounders)

• A stale ens-test-env indexer was contending on the same schema for the first ~30 min — killed at 22:36.
• Transient Optimism RPC blip at 04:23 (~1900 retried readContract warns, no errors propagated).

Follow-ups (sorted by expected impact)

1. migrated_nodes (0% prefetch, 1.3M+ row hot path): re-key by (parentNode, labelHash) — both are in event.event.args for every ENSv1RegistryOld event, so the matcher would derive them.
2. domain_events floor at ~26%: composite (domainId, eventId) keys ARE supported by Ponder's matcher (verified: profile.ts:42-56, profile.ts:70 for event.id, cache.ts:880-1029 for the prefetch path). The miss rate is structural — handler writes for the child domain use keccak256(parent_node || label) for domainId, unmatchable. A flat single-column key would NOT help (Ponder's delimiter splitter is single-level). Same fix shape as migrated_nodes — re-key the child-domain writes by (parentNode, labelHash, eventId). Same applies to resolver_events / permissions_events if they hit similar floors.

Snapshot log archived locally at packages/ensindexer-perf-testing/logs/run-D-perf-snapshots.log (with summary block prepended).

[shrugs]

Quick note on a domain_events prefetch floor I noticed while running perf/delimited-ids (this is suspected, not measured — surface for the record):

The domain_events table sat at ~17–22% prefetch share across runs, while sibling event tables (resolver_events) hit ~50%. I think the structural floor is the dual-write pattern in ENSv1 NewOwner-style handlers: the same handler writes a domain_events row for both the parent (domainId derived from args.node — profileable) and the child (domainId derived from keccak256(parent ‖ label) — non-profileable, since Ponder's pattern matcher only does direct equality + single-level string splits, not hashes).

Composite PK shape (domainId, eventId) is not the issue — Ponder handles each column independently and runs the delimiter splitter inside each. Flattening to a single id = "${domainId}-${eventId}" wouldn't help either; the keccak-derived child node still appears in the key string.

A theoretical fix mirrors what worked for migrated_nodes: re-key the child-domain writes by (parentNode, labelHash, eventId) so all three fields come straight from event args, plus a node-keyed sibling index for the API/query consumers that only have the post-keccak node.

Probably not worth it though: the upper-bound headroom is roughly the gap between domain_events' ~17% and resolver_events' ~50% prefetch — call it ~30 percentage points on one table — at the cost of two-table writes, sibling-index maintenance, and a recompute-node-from-parent+label step on every read site. The migrated_nodes re-key paid off because reads were the bottleneck and writes were already cheap. For domain_events the math is less obvious. Filing this here so it's discoverable rather than acted on.

[shrugs]

Run E — perf/delimited-ids + migrated_nodes split

Follow-up to Run D — adds the migrated_nodes two-table split (Run D follow-up #1 above) and un-stubs ENSRainbow. So: not apples-to-apples vs Run D. The signal we care about is whether the migrated_nodes_by_parent re-key delivered the predicted prefetch lift, plus a re-confirm at scale of the domain_events floor.

PR: #2016

What changed

• migrated_nodes split into migrated_nodes_by_parent (composite PK on (parentNode, labelHash)) + sibling migrated_nodes_by_node (PK on node). Both rows written together by migrateNode. Each read site addresses whichever key matches its event payload.
• labelByLabelHash un-stubbed — real ENSRainbow round-trips on the NewOwner hot path now.
• 10 days of main merged in (HCA-aware events feat(ensv2): HCA-aware Event.sender + filter + docs #2014, indexing-metadata-context Introduce indexing metadata context data model #1997, ENSRainbow /ready endpoint feat(ensrainbow): implement background database bootstrapping and new readiness endpoint #1968, etc.).

Wall clock

Run started 2026-04-29 23:05 CDT, stopped 2026-04-30 09:14 CDT after 10.1h elapsed, did not finish. Scroll was the bottleneck at ~69.5% of its backfill range; mainnet was at ~97.4%.

chain	indexed	remaining	% done	rate (blk/h)	ETA
1 (mainnet)	21.1M	571K	97.4%	2.1M/h	+16 min
8453 (Base)	24.4M	3.44M	87.6%	2.4M/h	+85 min
59144 (Linea)	22.0M	1.72M	92.8%	2.2M/h	+47 min
10 (Optimism)	37.1M	3.46M	91.5%	3.7M/h	+57 min
42161 (Arbitrum)	80.0M	28.5M	73.7%	7.9M/h	+3.6 h
534352 (Scroll)	11.8M	5.17M	69.5%	1.2M/h	+4.4 h

Linear extrapolation → ~14.5h total to backfill-complete. Realistic band 15–18h once tail-end backfill slowdown is folded in (less batch parallelism, more single-threaded RPC time near tip).

13.5M ENSv1Registry:NewOwner events processed (avg ~371 ev/s, recent ~266 ev/s).

Per-table prefetch share (final snapshot)

table	reqs	hit%	pf%	miss%	comp%
events	131M	46.2	52.0	1.5	0.3
domains	53M	75.4	1.1	22.7	0.8
domain_events	50M	19.8	20.4	59.2	0.6
resolver_events	43M	48.4	50.0	1.6	0.0
accounts	39M	84.4	14.5	0.6	0.5
resolver_records	38M	71.0	28.1	0.9	0.0
labels	37M	57.1	23.8	0.9	18.2
migrated_nodes_by_parent	20M	41.4	56.5	0.8	1.3
domain_resolver_relations	20M	48.1	49.4	2.4	0.1
resolvers	22M	99.8	0.1	0.0	0.1
registries	14M	97.8	0.6	0.2	1.4
migrated_nodes_by_node	8M	31.6	1.2	66.6	0.5

Key findings

1. migrated_nodes_by_parent reached 56.5% prefetch share — Run D follow-up # 1 hypothesis confirmed. Composite (parentNode, labelHash) PK is profileable from event args; up from 0% on the old node-keyed table. Climbed from 35.5% in an earlier 1.5h sample as the table filled out.
2. migrated_nodes_by_node is ~67% miss — expected. Most node-only lookups are for nodes that haven't been migrated, so there's no row to prefetch. Read path is profileable; the existence-check semantics are correct (return false on miss = not migrated).
3. domain_events floor confirmed at ~20.4% across 50M requests — exactly the structural floor predicted in the earlier comment. The keccak-derived child-write half is unprofileable; the parent-write half profiles cleanly. Reaffirms the "probably not worth it" verdict.
4. labels table is now 23.8% prefetch + 18.2% complete (full table in cache) — a positive surprise vs Run D's 0% prefetch. Could be: (a) something in the merged-in main commits changed labels's key shape, or (b) the longer/different sample exposes behavior Run D's 1h didn't. Worth a separate look but not blocking.

Caveat — wall clock vs Run D

ENSRainbow was un-stubbed for this run — the ensureUnknownLabel path adds one network round-trip per first-sight labelHash on the NewOwner hot path. That accounts for the runtime regression vs Run D's 11h13m. Prefetch shares are the apples-to-apples signal here, not wall clock. If wall clock comparable to Run D is wanted, re-stub labelByLabelHash and re-run.

Follow-ups

• ENSv2 storageId-keyed tables (Domain rows for v2, downstream domain_events for those rows) likely have a hidden prefetch hole — storageId = zeroLower32Bits(tokenId) is a derivation Ponder's matcher doesn't recognize. Documented in the ids.ts block comment in perf(ensindexer): unblock Ponder prefetch on hot tables #2016. Would need a Ponder-side patch (zeroLower32Bits added to the matcher's recognized fn set, or per-entity prefetch-key generation). Not actioned.
• domain_events 20.4% floor: re-confirmed at scale. Per the earlier comment, probably not worth the architectural cost.