Repository navigation
Keyed audit dedup lookup scans the origin log when the exact start key is missing (not covered by #3366) #3467
Description
Summary
On a 16-node RocksDB cluster on 5.3.3 (which already includes the #3377 backport of #3366), receivers that apply old replicated duplicates spend seconds per write in Table.commit. This isn't in the retry path that #3366 / #3377 fixed, and it persists with that fix installed. It's in the up-front keyed dedup lookup, which runs for these writes because they are not retries. The lookup's exact-start positioning in the origin's transaction log doesn't find the key and scans the log segment. The affected entries come from a v4-era origin that stopped writing at a migration cutover. Its last log file is never purged, so the same entries are replayed on every receiver reconnect or restart, indefinitely.
Evidence (5.3.3, captured 2026-10-23)
CPU profile, 3 pinned http workers, 10 s each: 92 to 96% of samples in
transaction.js onComplete
-> DatabaseTransaction commit -> performCommit -> save
-> Table.commit (5.3.3 Table.ts keyed dedup, ~L4830)
-> RocksTransactionLogStore.get / getSync
-> replayLogsGuards next
-> rocksdb-js transaction log iterator next
Paused frames (2 workers, about 2 s held per pause):
- puts to a cache table, versions 2026-09-15T04:00:23Z and 04:04:24Z, origin
nodeId=35(a v4-era node from the migration), relayed via two different peers (viaNodeId3 and 4) isNotification=true,sourceApply=true,replaying=falseprecedesExisting=0: the stored entry has the same version and origin as the incoming writeretry=undefined,stagedOwnAuditEntry=undefined, so the keyed dedup guard is taken and Fix replicated duplicate retries entering the audit walk #3366's retry-path skip does not applygetSync(key=txnTime, tableId, recordId, nodeId=35)->getRange({ start: key, exactStart: true, log: 35 })- rocksdb-js iterator:
foundExactStart=false, about 15.9 MB into a 16.7 MB segment. On one worker the iterator's current timestamp was about 3 min before the start key; on the other, about 63 s past it.getSyncreturns at the first non-matching entry, so the cost is in positioning the iterator. - records'
expiresAtwas 2026-09-16
Why it never ages out
The node's oldest retained audit time is 2026-09-15T04:00:15Z, 38 days later. Retention removes whole files but keeps each origin's newest file. Origin 35 stopped writing at the cutover, so its last file is retained forever, and receivers resume from that stretch after every reconnect (about every 10 min, per #3361) and every restart.
Impact
- Pinned http workers queue request traffic behind these commits. On the worst node, p95 on a request path rose from about 65 ms to about 470 ms. Another node has sat at about 1.4 s p95 for over a day.
- Restarts make it worse: 3 worker restarts in 13 minutes (two overlapping rolling restarts from a replicated
deploy_componentplus one manual restart) took one node from about 2 pinned workers to 13. It stayed there. - A control cluster running the same app on 5.x, but without v4 migration history, is unaffected (see Out-of-order audit walk still pegs replication receivers on 5.3.2: retried duplicate writes bypass both the dedup skip and #2684's floor check #3361).
Possible fixes
- Bound the exact-start positioning, or fail fast when the key isn't present (or fall back to an indexed lookup), so a miss can't cost a segment scan.
- Let retention purge an origin's last log file once it's past retention and the origin is inactive.
- Skip applying a replicated write whose
expiresAtis already in the past.
A 5.3 backport of whichever fix lands is needed for the affected cluster.
Related
#3361 (closed by #3366, backported to 5.3.3 in #3377: retry path only; this cluster runs 5.3.3), #3453 (retry-path correctness, open), #3451 item 3 (another lookup that can scan to end of log), #2642.
Activity
maurice-harper commentedon Oct 23, 2026
@kriszyp @DavidCockerill tagging you both since this follows on from #3361 / #3366. The affected cluster is already on 5.3.3, which includes the #3377 backport, and this still happens: the backport covers the retry path, but this capture is the non-retry case (
retry=undefined), where the keyed dedup lookup itself is the cost. Whichever fix lands will need a 5.3 backport.maurice-harper commentedon Oct 23, 2026
Confirmed on a fourth node in the same cluster (5.3.3), relayed via a different peer.
nextviareplayLogsGuards.next, same stack as above.nodeId=35,viaNodeId=9,isNotification=true,retry=undefined,stagedOwnAuditEntry=undefined, stored entry has the same version and origin. Stuck in the keyed dedupgetSync(key=txnTime, nodeId=35), iteratorfoundExactStart=falseabout 13.7 MB into a 16.8 MB segment.expiresAt2026-09-16.So far three different relaying peers (
viaNodeId3, 4, 9) deliver the same origin-35 stretch to different receivers.maurice-harper commentedon Oct 23, 2026
The replay scans are disk-bound, and that is what turns this into minute-long request stalls. Measured 2026-10-23 ~06:35Z on 5.3.3 hosts (125 GB RAM, ~60-73 GB page cache each):
Stalled workers sit in D state on
folio_wait_bit_common/lock_mm_and_find_vma/vm_mmap_pgoff(from the worker ack-timeout diagnostics), and the CPU profiles above show the time in the rocksdb-js log iterator over memory-mapped segments (getLogMemoryMap). So each replayed duplicate's lookup page-faults through log segments that aren't resident, which explains 60 s to 6 min p95 spikes on request paths when requests queue behind those workers.Also seen: four affected nodes went silent within 0.4 s of each other (05:18:02.3 to 02.7Z), and 15 long-lived handles on the data database all date to that moment, which points to one replicated batch hitting all of them at once. Only warn/error logs are retained, so we can't see what it was.
Bounding or indexing the exact-start lookup (fix 1 in the description) should remove both the CPU and the I/O cost.
kriszyp commentedon Oct 23, 2026
In progress: building a fix in
Table.commitso a replicated write that exactly matches the committed record (same version, same origin, log key equal to the version, no additional audit refs) is skipped as a duplicate straight from the record, with no transaction-log lookup. That should also stop these duplicates from being re-appended to the origin's log under their old keys, which is what keeps the stretch replaying. A 5.3 backport will follow.🤖 Generated by Claude Code (Claude Opus 5.5); posted via @kriszyp.
maurice-harper commentedon Oct 27, 2026
Still seeing this class on v5.3.4 (which includes #3476 / #3478) on one node of a 16-node production cluster, via a different trigger than the one #3476 covers.
Symptom: after a rolling restart, ~9-14 http workers on one node sit at utilization 1.0. The other nodes are at 1-6. A 10s CPU profile of two pinned workers shows 93% inclusive in the same stack as before:
A third pinned worker is on the sending side, in
getCopyTxnLogKey->RocksTransactionLogStore.getSync-> the same iterator, plusgetRange/trackCorruptFrames(~65%).Debugger.pause on one pinned worker (Table.commit frame, dist Table.js ~4077):
put,isNotification=true,sourceApply=true,isCopyApply=false,nodeId=11,viaNodeId=11, version 2026-10-24T12:34:41Z, already expired (expiresAt2026-10-25).retry=undefined,stagedOwnAuditEntry=undefined.existingEntry: local write (nodeIdundefined/0) at version 2026-10-25T08:37:47Z, also expired.precedesExisting=-1, so the incoming version is older than the head. It is not a duplicate of the head, which means Skip relayed duplicates of a record's committed head without reading the transaction log #3476's skip does not apply.walkSteps=1,retryBaseIsCommitted=true,walkOriginKnown=true,belowAuditFloor=false,auditWalkCapped=false.getSync(key=<head localTime>, nodeId=0), against the node's own log, withexactStart=true.fromLogId=12137,latestLogId=12637(~500 segments of ~16 MB),candidateLogId=12138, positioned at the end of a 16,776,957-byte segment withfoundExactStart=false. So the lookup for the head's own audit entry is not seeking to the key. It reads forward through hundreds of segments, page-faulting the mmap'd files.Difference from the original report: the original was a relayed duplicate of a v4-origin head on another origin's log. This is an older relayed version arriving after a newer local write; peers' cursors replay days-old writes after restarts. It takes the walk on the local log, and the exact-start lookup for a key that should be present fails to position.
Open questions:
localTimekey and position near it. Either the position index for that range is missing, or the key is not present in the log.expiresAt.Impact: the node is held out of client routing, so there is no user impact. It has not self-healed across restarts.
maurice-harper commentedon Oct 27, 2026
Second capture on v5.3.4, from a different node in the same cluster. This one is the retried exact-duplicate trigger, not the older-version trigger from the previous comment. It is a node in client rotation, and it shows up as ~1-minute p95 spikes (250-850 ms) whenever a worker sits in this path for 30-70 s.
Profile: 10 s each on three busy http workers. 75-98% inclusive in the same stack:
One worker also spends ~27% in
resolveAuditHead/findHeadand ~10% indedupVersionCouldBeRetained.Debugger.pause (Table.commit frame, dist Table.js ~4077):
put,isNotification=true,sourceApply=true,isCopyApply=false,nodeId=12,viaNodeId=12, version 2026-10-24T20:23:23Z. ItsexpiresAt(2026-10-25) has already passed.retry=true,stagedOwnAuditEntry=true.existingEntry: the same version and the same origin (nodeId=12), soprecedesExisting=0, an exact tie. The stored entry'sexpiresAtis 2026-10-27, so it was refreshed after this version.walkSteps=1,retryBaseIsCommitted=true,walkOriginKnown=true,belowAuditFloor=false.getSync(key=<version>, nodeId=12)on origin 12's log,exactStart=true. The iterator is ~2 MB into a 16.7 MB segment withfoundExactStart=false.This is the case from the original #3361 capture (retry=true / staged). The
stagedOwnAuditEntryshield intentionally keeps the keyed probe from skipping, so #3476 does not apply here.Summary of the two captures on 5.3.4:
precedesExisting=-1)0)nodeId=0)nodeId=12)Both triggers end in the same place: an
exactStartlookup that does not position on the key, so it iterates forward through mmap'd segments. Fixing the positioning (or bounding the scan) would cover both. Adding more skips would only cover each trigger one at a time.Still unknown: why the apply is retried. Conflict retries below 40 only log at debug.
maurice-harper commentedon Oct 27, 2026
Follow-up for the two 5.3.4 captures above is tracked in #3628 (shared root: the
exactStartlookup failing to position, reachable via paths #3476 does not cover).