HarperFast / HarperFast/harper-pro
Replication receive path: the inbound frame queue is unbounded — one worker retained 43 GB of raw WS frames at the inbound line rate and OOM-cycled the node
- Dominant language
- JavaScript
- Stars
- 3
- Forks
- 0
- Avg merge
- 1d 21h
- Merged PRs (30d)
- 80
Description
## Summary
`ws.on('message')` in the replication receive path chains every inbound frame onto a serial promise
chain, and each link retains the **whole frame body** until its turn runs:
```ts
ws.on('message', (body: Buffer) => {
resetPingTimer();
messageProcessing = messageProcessing.then(
() => (wsClosed ? undefined : onWSMessage(body)),
() => (wsClosed ? undefined : onWSMessage(body))
);
});
```
That chain is an **unbounded queue of raw bytes**. The socket is paused only by explicit pause
reasons taken *inside* `onWSMessage`; the handler itself applies no admission control. So whenever
the receive loop runs slower than the peer sends, the queue grows at the full inbound line rate —
and past a few GB, GC pressure guarantees the loop stays slower, so it never recovers.
Measured on a live 4-node cluster on 5.2.3: **one worker holding 43 GB of retained frames, growing
1:1 with a 49 MB/s inbound rate, OOM-killed every 11–17 minutes, 12 restarts.**
## Why the existing bounds cannot cover it
| Bound | What it bounds | Why not this |
|---|---|---|
| `RECEIVE_EVENT_HIGH_WATER_MARK` (100) | decoded records awaiting apply | a later stage; frames queue before decode |
| `MAX_OUTSTANDING_BLOBS_BEING_SENT` (5) | concurrent **sends** | sender-side; unrelated to receiver retention |
| `blobsTimer` + `blobTimeout` | blob streams in `blobsInFlight` | not blob buffers — see below |
| `maxPayload` (100 MB) | one frame | not the number of queued frames |
## Evidence that this is frames, not blob buffering
Taken live via CDP `Runtime.queryObjects` (no heap snapshot) on the worker while it held 43 GB:
| Probe | Result |
|---|---|
| Live `PassThrough` instances | **0** |
| Live `Map`s / largest / any holding blob-stream values | 1,553 / 3,081 entries / **0** — `blobsInFlight` is empty |
| Live `ArrayBuffer`s | **378,995**, 13.7 GB at that sample; 94k in the 64–256 KB bucket |
| Top allocation site (`HeapProfiler` sampling) | **37.2%** at the `ws.on('message')` handler; 8.8% `ws/lib/receiver.js consume` |
| CPU profile | **62.9% garbage collector**, 18.4% txn-log iterator, 5.8% idle |
| Host `eth0` RX vs worker `arrayBuffers` growth | 2.95 GB/min vs 3.3 GB/min — **1:1** |
The affected socket reported `lastReceivedStatus: Receiving` with `lastReceivedRemoteTime` and
`receivedVersion` **null for its entire lifetime** (sampled repeatedly over 75 s): it never
completed a single batch, so its resume cursor never advanced, so every restart re-streamed the same
backlog from the same position. The work never shrank — a livelock, not a slow leak. Sibling sockets
for the same database from other peers were `Waiting` with fresh timestamps throughout.
A 1:1 retention ratio rules out *amplification* (e.g. zero-copy subarrays pinning larger frames); it
does not distinguish blob buffers from frame buffers. The probes above do.
## Fix
`createReceiveQueueGate` — a byte budget with hysteresis (pause at the high-water mark, resume at
half), exported as pure bookkeeping so the policy is unit-testable.
**Pausing here is deadlock-free**, unlike the blob-chunk back-pressure pause: it waits only for
frames *already accepted* to finish, and nothing in the receive loop awaits a **future** frame — blob
saves are fire-and-forget through `outstandingBlobsToFinish` (the synchronous `await Promise.all(...)`
that did create a circular wait was removed in #426), the apply-queue wait drains from the apply
loop, and the blob drain wait is satisfied by `saveBlob` consuming what it already holds. A
consumer-less blob stream is never waited on here. Each settled frame ticks `consumerProgress` so a
draining queue is not read as a dead leg by the pause-stall watchdog (#466).
- `replication.receiveQueueHighWaterMark`, default **32 MB**; `0` restores the old unbounded behavior.
- A throttled `warn` when the budget engages — the first operator-visible signal this condition has
ever had. Today the only symptom is one worker's `arrayBuffers` climbing with nothing logged.
### Tests
- Unit: the gate's pause/resume/hysteresis policy, oversized-frame handling, balanced pause reasons,
and the zero-budget (pre-fix) behavior it guards against.
- Integration: a blob-dense base copy with the budget set to **4 KB** — smaller than one blob chunk,
so it pauses on essentially every frame — asserting it still **converges**. That is the deadlock
class of #457 / #403 / #420, and it is the property worth proving, since the bound itself is
arithmetic.
## Two adjacent findings
1. **Four replication config knobs are inert.** `env.get` resolves only names registered in
`CONFIG_PARAMS` (`getConfigValue` returns `undefined` for anything absent from
`CONFIG_PARAM_MAP`), and these are not registered: `replication_receiveEventHighWaterMark`,
`replication_receiveYieldInterval`, `replication_copyCheckpointRecords`,
`replication_copyCheckpointMaxIntervalMs`. Their config values are silently ignored and the
compiled-in defaults always apply — so reports of "`receiveEventHighWaterMark` unset (100)" are
describing a value that cannot be changed. Confirmed empirically: the new param behaved exactly
this way until registered. Worth its own issue; I registered only the new key here.
2. **`Table.commit` does a transaction-log lookup per record** —
`RocksTransactionLogStore.get` → `getSync` → a `getRange` walk (`transaction-log-reader` +
`replayLogsGuards`). Every CDP evaluation on the wedged worker landed inside that stack, and it
is 18.4% of CPU while the socket makes no progress. It is bounded (bails when
`entry.version !== key`), so it may simply be the visible work between GC pauses rather than a
defect — but it is the consumer-side cost worth profiling next, because the bound above stops the
OOM without making the consumer any faster.
## Relationship to the other issues
- **#659** — same symptom, and its "receive side is unbounded" framing is right; the mechanism here
is the frame queue rather than `blobsInFlight` occupancy. Its 116k blob-stream timeouts were a real
but separate condition.
- **#703** (bound the copy walk's lookahead) — complementary and still worth doing, but only under a
*settle-based* definition of "outstanding". Under send-completion it adds nothing here, since the
sender's cap already bounds concurrent sends and the growth is entirely receiver-side.
- The unconnected-blob-buffer path *is* separately unbounded (no byte accounting anywhere in it, and
a local repro reaches ~25× the bound the code comment claims). It caps near
`receiveEventHighWaterMark` in practice, so it is a real but much smaller exposure — worth fixing,
not what kills a node.
Contributor guide
Research direction
Start at the replication receive path's ws.on('message') handler and the onWSMessage entry point, then trace the pause reasons and consumerProgress behavior. Use the described createReceiveQueueGate unit tests to verify byte-budget hysteresis, oversized frames, balanced reasons, and zero-budget behavior; the integration test should converge with a 4 KB budget, and the new configuration key should be registered and warn when engaged.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- node.js, typescript
- Domain
- backend, distributed-systems, performance
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Active
- Clarity
- Mostly clear
- Newbie friendliness
- 55/100