notifier.publish() delays the serial block loop: notification publish/encoding path is ~79% of sampled CPU and causes 30-45s stalls at HEAD

[bgpntx]

Edited after review — corrected the scope of what gets notified, the event-loop claim, the attribution of the 79 % figure, and the payload suggestion (the full tx is part of the public Socket.IO contract). Runtime caveat added. See the comment below for details.

Summary

At chain head, the notification publish/encoding path accounts for ~79 % of sampled CPU in the filler (publish itself: 52.5 % self time) and delays the serial block-processing path for 30–45 s at a time whenever a block carries a lot of AtomicAssets handler events. The reader stops advancing, the SHiP queue backs up, and the node then catches up in a burst. It self-heals, so it usually gets reported as "the indexer stalled for a few minutes and recovered".

The implementation pattern is unchanged on current main; the performance measurements below were collected on v1.3.24 / Node 16 / ioredis. Current main is 2.0.0 on Node ≥ 22 with iovalkey, so the absolute numbers have not been re-validated there — the structural defect has.

Root cause

src/filler/notifier.ts:

async publish(): Promise<void> {
    if (this.processor.getState() === ProcessingState.HEAD) {
        const chunks = arrayChunk(this.notifications, 50);
        for (const chunk of chunks) {
            await this.connection.redis.ioRedis.publish(this.channelName, JSON.stringify(chunk));
        }
    }
    this.notifications = [];
}

Each relevant handler event is queued as a separate notification. Every trace notification embeds the entire transaction object:

this.notifications.push({channel, type: 'trace', data: {block: prepareNotificationBlock(block), tx, trace}});

so multiple traces from the same transaction duplicate that transaction in the serialized payload. A block with heavy AtomicAssets activity produces on the order of 1 500–1 700 notifications. They are chunked by 50, and each chunk is JSON.stringify-ed and published sequentially.

This happens inside the strictly serial block path — src/filler/receiver.ts:

this.dsQueue = new PQueue({concurrency: 1, autoStart: true});   // line 96
this.dsLock  = new Semaphore(config.ship_ds_queue_size);        // line 97
...
await this.processor.notifyCommit();
await this.notifier.publish();                                  // line 344

The serial block-processing queue cannot advance until all chunks have been serialized and published. Each serialization/command-encoding step is synchronous and temporarily blocks the Node.js event loop; the await between chunks does yield, so the loop is not blocked continuously for the whole stall.

The ProcessingState.HEAD guard explains a symptom operators notice but rarely connect: catch-up replays at 80+ blk/s while real-time crawls. Notifications are only published at head, so the expensive path is skipped entirely during catch-up.

Evidence — V8 CPU profile of a live filler

Profiled the running worker via the inspector (kill -USR1 <worker pid> → Profiler.start/Profiler.stop over CDP), 10 s sample taken while the reader was frozen:

   self_s   share  function            location
     5.57   52.5%  publish             build/filler/notifier.js
     0.99    9.3%  (garbage collector)
     0.98    9.2%  writeUtf8String
     0.96    9.1%  handleWriteReq      node:internal/stream_base_commons:45
     0.89    8.4%  byteLengthUtf8

publish self time is 52.5 %. The remaining ~26.7 % are generic UTF-8/socket-write frames; attributing them specifically to the Redis publish path would need a bottom-up/call-tree profile, which I have not produced — treat the ~79 % as the publish/encoding path as a whole. ioredis/Command.js also appears in the profile.

Supporting measurements on the same node while frozen:

• 1.21 logical CPU cores on average consumed across stalls (sampled /proc/<pid>/stat every 250 ms; 24 stalls, 890 s frozen, 1081 s of CPU) — the filler is computing, not waiting.
• No evidence indicates PostgreSQL is the bottleneck. 423 pg_stat_activity snapshots taken during stalls: 53–59 % show zero active backends and zero pg_blocking_pids.
• strace over 3 s: 11 713 futex (3 332 EAGAIN), 4 940 munmap, 2 765 mprotect, 2 474 mmap.
• The SHiP socket has unread data queued (Recv-Q ≈ 71 KB) — the source is fine, the consumer is busy.
• The filler's own progress line shows DB operations jumping from a normal 4–50 W/s to 1515–1622 W/s on the block where the stall starts.

Confirmation that this is the cause

Short-circuiting publish() on one node (early return after clearing this.notifications), everything else unchanged:

	before	after
publish in profile	52.5 % self time	gone
(idle) in profile	5.7 %	98.4 %
stalls	69–94 per 10 min	0
lag	up to 200+ blocks	0–1 block

That node has since been serving production traffic at head with no stalls.

Circumstantial supporting observation

Point-in-time sample of public WAX AtomicAssets endpoints (chain.head_block − readers[0].block_num from /health, 8 samples over 90 s). Their versions, configuration and hardware are unknown to me, so this is circumstantial only:

endpoint	min	avg	max
endpoint A	1182	2603	3130
endpoint B	363	444	512
endpoint C	280	348	389
endpoint D	112	158	223
our node, publish() disabled	−1	0	0

Another operator independently reported the same signature in a producer channel: No blocks processed for a few minutes, then self-recovery, on 1.3.24.

Suggested directions

1. Deduplicate transactions in the internal Redis batch and rehydrate notifications in the receiver, preserving the existing Socket.IO payload contract. The socket routes do emit the full transaction (transaction: notification.data.tx in e.g. src/api/namespaces/atomicassets/routes/assets.ts), so simply trimming tx from the notification would be a breaking change to the external API — but the wire format between filler and API is internal and can dedupe repeated transactions.
2. Get it off the serial path, so block processing does not wait on publishing. Note this alone is insufficient while serialization stays synchronous per chunk.
3. Skip the work when nobody is listening (PUBSUB NUMSUB), or gate it behind a config/env flag. There is currently no supported way to turn notifications off for indexers that do not serve Socket.IO.
4. Consider a cap or coarser granularity for notifications on very large blocks.

Environment

• Measured on eosio-contract-api 1.3.24, Node 16, ioredis, PostgreSQL 14, Redis on localhost, WAX mainnet at head
• store_logs: true for the atomicassets and atomicmarket handlers
• publish() and the receiver.ts call site verified byte-identical on this repo's main

Happy to instrument a node and report per-block notifications.length, serialized bytes, total JSON.stringify time, total publish-await time and subscriber count if that would help quantify it on the current runtime.

[bgpntx]

I have edited the description above to correct several overreaching claims from my original report. Listing them explicitly so the record is clear:

1. "every changed contract row" was wrong. sendContractRow() has no production call sites — on 1.3.24 it exists only as a definition in notifier.ts, and the same holds on main. Only handler-invoked sendActionTrace() events are notified. The real amplifier is that each trace notification embeds the entire transaction, so multiple traces from one transaction duplicate that transaction in the payload.

2. The event loop is not blocked continuously for the whole stall. JSON.stringify and command encoding block it synchronously per chunk, but the await between chunks yields. What is continuously stalled is the serial block-processing queue, which cannot advance until every chunk is published.

3. The 79 % figure is the publish/encoding path as a whole, not publish alone. publish self time is 52.5 %; the remaining ~26.7 % are generic UTF-8/socket-write frames that I attributed by inference. Confirming that attribution needs a bottom-up/call-tree profile, which I have not produced.

4. Trimming tx from the notification would be a breaking change — I withdrew that suggestion. The socket routes emit transaction: notification.data.tx (e.g. src/api/namespaces/atomicassets/routes/assets.ts), so it is part of the external Socket.IO contract. Replaced with: dedupe transactions in the internal filler→API batch and rehydrate in the receiver, leaving the emitted payload unchanged.

5. Runtime caveat. All numbers were collected on 1.3.24 / Node 16 / ioredis. Current main is 2.0.0 on Node ≥ 22 with iovalkey, so the magnitudes are not validated there. The code pattern — sequential per-chunk stringify + publish awaited inside the serial queue — is unchanged, which is the part of the report I do stand behind.

I also softened the PostgreSQL claim to "no evidence indicates PostgreSQL is the bottleneck", relabelled the public-endpoint lag table as circumstantial (their versions and hardware are unknown to me), and changed "121 % of one core" to "1.21 logical CPU cores on average".

If it is useful, I can instrument a node and post per-block figures for a stalling block — notifications.length, serialized bytes, total JSON.stringify time, total publish-await time, and subscriber count — which would replace the inferred attribution in point 3 with measurements.

[bgpntx]

Measured per-block numbers, as promised

I instrumented publish() on a node taken out of rotation and logged, per invocation: block, notifications.length, unique transaction ids in the batch, serialized bytes, JSON.stringify time, publish-await time, and PUBSUB NUMSUB. 1280 blocks over ~1 hour, still on 1.3.24 / Node 16 / ioredis.

samples: 1280   subscribers: 1

                          total    avg/block
notifications              6072          4.7
payload bytes             155.7 MB     124.6 KB
JSON.stringify              0.9 s        0.7 ms
publish await               0.6 s        0.5 ms
total in publish()          1.6 s        1.2 ms

transaction duplication (n / uniq_tx): 4.1x average

heaviest by payload:  block=448692482 n=175 uniq_tx=1 bytes=31.29 MB stringify=158.2ms publish=89.7ms
share of publish() time: stringify 59%, redis await 39%

The duplication is the dominant cost

The worst block in the sample produced 175 notifications from a single transaction and serialized 31.29 MB — roughly 179 KB of transaction repeated 175 times. Average duplication across the sample is 4.1×.

This is the concrete case for deduplicating transactions in the internal filler→API batch: for that block, dedupe would take the payload from ~31.3 MB to ~0.2 MB while leaving the emitted Socket.IO payload byte-identical after rehydration in the receiver.

Measured attribution, replacing my earlier inference

In my original report I attributed ~26.7 % of profile self-time (writeUtf8String, byteLengthUtf8, handleWriteReq) to the publish path by inference, which was fair to push back on. Direct timing inside publish() gives JSON.stringify 59 %, Redis await 39 % of time spent in the method. So serialization — not Redis round-trips — is the larger component, which supports fixing the payload rather than the transport.

Caveats

• This window was a quiet period: the largest block reached 175 notifications, whereas the stall-inducing blocks in my earlier report carry 1500–1700. No stall occurred during this sample, so these numbers characterise the cost curve, not the stall itself. I will post heavy-block figures if I capture one.
• subscribers: 1 is the API server's own ioRedisSub; there were no Socket.IO clients on this node, so all of that serialization was discarded work. That is specific to my out-of-rotation node, not a general claim.
• Still 1.3.24 / Node 16 / ioredis; current main is 2.0.0 / Node ≥ 22 / iovalkey. The duplication is structural (sendActionTrace embeds the whole tx, one notification per handler event) and is unchanged on main, but these magnitudes are not re-validated there.

Instrumentation patch is a few lines inside publish() if it would be useful to run the same measurement on current main.