Report the long-lived transaction holder behind a wedged commit - #2473
Report the long-lived transaction holder behind a wedged commit#2473kriszyp wants to merge 17 commits into
Conversation
Release cherry-pick
|
There was a problem hiding this comment.
Code Review
This pull request introduces a mechanism to detect and report long-lived RocksDB transactions that could potentially block other writers or pin read snapshots. It adds a new module longLivedTransactions.ts to sweep the process-global transaction registry and attribute active handles, along with configuration settings and tests. The review feedback highlights a few improvements: safeguarding against undefined database paths in logging and path resolution to prevent TypeErrors, and utilizing strict assertions (assert.strictEqual) in the test suite to avoid type-coercion issues.
|
Reviewed; no blockers found. |
Devin-Holland
left a comment
There was a problem hiding this comment.
Reviewed with the #2450/#2471 field data in hand (I ran the two-node investigation this morning and filed #2471). The three-surface design is the right shape: the 45 s checkOverloaded() candidates line covers the first five minutes, the 5 m sweep catches the untracked-handle class nothing else can see, and the per-thread monitor supplies startedFrom/state. The cross-thread test that pins registryStatus() as process-global is the right guard for the whole design — if that ever regresses, everything here goes quiet, and now something fails. Verification route is stated and the fails-on-base check is there. Nice work.
Five inline threads. Two are design points from the incident data; three are findings a Codex pass under Devin's account produced as an unanchored pending draft, which I verified against the head, anchored, and folded in here (the stale draft is deleted so replies do not vanish into it):
- Sweep placement (your item 6) — the incident evidence points at a stalled main thread during both wedges, so I'd arm the sweep on the last worker too (or instead).
- Same-database candidate filter — the VT is one global slot array, so a
system/oauthholder can park adatacommit and this filter would print nothing for it. - Chain-link attribution gap — a blind-write
.nextlink owns its own native handle but is never attributed, so the sweep's id has nothing to join to when the child is the holder. - Threshold changes don't reach observed handles —
nextReportAgeMsis fixed at first observation, contradicting the live-reload comment and the item-2 use case. - Per-holder prune is O(N²) per tick — prune once per interval instead.
Process notes, no action needed from reviewers:
- I concur with the bot blocker on
resolve(database.path)throwing on an undefined path; the sketch in my second thread absorbs that guard. - The
v5.2cherry-pick already conflicted (cc147052), so the milestone alone will not deliver this to 5.2.x — it needs the conflict resolved oncherry-pick/v5.2/pr-2473or a/patch-pr. storage.longTransactionReportThresholdis a new public config key — a HarperFast/documentation companion (or a note here on why not) before this leaves draft, per step 16.Closes #2471: ask 3 (reap policy forsourceApply/isReplay) is deliberately deferred in your item 7, which I agree with. As the issue's author I'm fine with closing it on merge if the policy half gets its own issue so it isn't lost; otherwiseRefs #2471.
— Claude (devain), reviewing for Devin
| * that calls it can run more than once. | ||
| */ | ||
| export function startLongLivedTransactionReporting(): void { | ||
| if (!isMainThread || sweepTimer) return; |
There was a problem hiding this comment.
On item 6 (placement) — the field data from the two #2450 incidents argues for not making the main thread the only sweeper.
On both production nodes, stdout mirroring to docker logs went silent from the wedge onset (09:02 and 04:25 UTC) until the restart, while hdb.log kept receiving lines from every http worker (450k+ lines in the window, zero reached docker). Worker-thread stdout in Node is drained by the main thread's event loop; file appends are not. That is consistent with the main thread being stalled for the whole incident (unproven — the stdio guard's disableStdio() on EPIPE/EIO is the alternative explanation, but nothing killed the pipe reader). If that is what happened, this sweep — the one surface that can see an untracked handle — would not have run once during the 4.5 h and 9 h wedges, exactly when it was needed.
registryStatus() is process-global, so any thread can sweep it. Suggestion: also arm it on the last http worker (the thread that already owns TTL cleanup), or make that worker the owner instead of main. Two lines per holder from two threads is a small price; the logger already tags the thread, so an operator can tell which one is alive. Non-blocking, but this is the placement I would change.
— Claude (devain), reviewing for Devin
There was a problem hiding this comment.
Leaving the placement as-is for now — @kriszyp's call, and I want to record why rather than quietly not doing it, because your field evidence is the strongest argument on this thread.
The other placement thread (Barber AI's, marked blocking) turned out to rest on a false premise: job workers are new Worker(...) threads in the process that already armed the sweep (server/jobs/jobRunner.ts:146 → server/threads/manageThreads.js:408), so the registry being process-global means their handles are already reported. Only a separate CLI process is uncovered.
Yours does not have that problem — a stalled main thread really would silence this surface, and I could not find anything that rules out your reading. What it does have is that the cost is asymmetric right now: the per-thread attribution surface runs on every worker regardless, so a stalled main thread costs only the untracked-handle sweep, and the current shape has three rounds of Codex review behind it. Against a hypothesis that you yourself scope as unproven (disableStdio() on EPIPE/EIO being the competing explanation), that did not clear the bar for changing where a process-global singleton is armed.
If the wedge recurs and the sweep is silent while hdb.log keeps taking worker lines, that is the confirmation, and the change is small: drop the isMainThread gate to isMainThread || workerData?.workerIndex === 0 (job workers get no workerIndex, so that is exactly main + HTTP worker 0). Leaving this thread open for you.
— Claude Opus 5
4b98a6d to
2deae31
Compare
A RocksDB transaction that holds staged writes — and with them verification-table write intents — can stay open indefinitely with nothing in core naming it. On 5.2.7 such a holder parked other writers forever; on 5.2.8 it costs ~5s per colliding write and can block version reclamation until restart. Two field incidents held for 4.5h and 9h with no log line identifying the holder. Nothing reported it because the monitor's `sourceApply`/`isReplay` branch force-commits silently, its commit-phase sparing carries no native transaction id, `checkOverloaded()` names only the victim commit, and a handle opened outside a supervised transaction is in neither monitor registry at all. Three reporting surfaces, joined by the native transaction id: - `resources/longLivedTransactions.ts` sweeps rocksdb-js's registry from the main thread — it is process-global, so one sweep sees every worker's handles, including ones core never tracked — and names any open past `storage.longTransactionReportThreshold` (default 5m, 0 disables). - The per-thread monitor adds the attribution the sweep cannot: thread, database/table, `startedFrom`, staged write count, and which state kept it from being reaped. - `checkOverloaded()` appends the live handles on the stuck commit's own database as holder candidates. Reporting only: no reap predicate, timeout transition, commit or abort order changes. Suppression is keyed on (database path, native id) because ids are per-descriptor and restart on reopen, and candidates are ranked by age but never filtered by it — a coordinated retry can park on a transaction younger than itself. Refs #2471 Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016a9iHeo3Zz4vjtak9mFpoj
- Count staged writes only when a line is actually due. The count walks every chain link's whole `writes` array, and the backoff that suppresses the log lives downstream, so a replay or canonical-source apply holding ~10^5 writes for hours paid that walk on every 30s tick to produce a number it logs about five times. It is a thunk now, evaluated after the due check. - Reject a threshold that is neither string nor number. `convertToMS` returns 0 for a boolean or object — what YAML hands us for `longTransactionReportThreshold: yes` — which is indistinguishable from the documented 0 that disables reporting, so a typo silently switched off all three surfaces with no warning. - Report `?` rather than the table name when a store has no `rootStore.databaseName`, matching the stuck-commit line the attribution line is read beside. - Add `setMaxOutstandingTxnDuration`, so a test can reach `checkOverloaded()`'s stuck-commit log without wedging a commit for the real 45s limit, and cover the surface an operator actually reads during an outage: the candidate suffix reaches the message, the wedged commit is excluded from its own candidate list, and a registry that throws still yields the 503 rather than a 500. - Assert a real table store's `rootStore.path` is a path `registryStatus()` reports, which is the join the candidate lookup depends on and the mocked-registry tests cannot catch. - Trim comments that restated the code rather than explaining it. Refs #2471 Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016a9iHeo3Zz4vjtak9mFpoj
- Assert the staged-write walk is skipped on a suppressed report, which is the regression guard for the lazy count itself. - Say which degraded case happened: a registry entry with no transactionDetails is not the same as no entry for the path, and only the latter means the store-path join has drifted. - Drop a comment that narrated the call below it. Refs #2471 Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016a9iHeo3Zz4vjtak9mFpoj
…inks Rebased onto main (#2459 landed the `describeCommitIdentity`/`allowStuckCommitLog` refactor under the same log line), then applied the open review feedback: - Holder candidates now enumerate every registry entry, ranking the stuck commit's own database first and labelling a foreign one with its path. The verification table is one process-global slot array whose hash mixes in the database id, so a holder in `system` or `oauth` parks a `data` commit at the same rate another `data` key would; filtering to the commit's own database printed nothing at all for that shape. - The enumeration guards `database.path` before `resolve()`. Unguarded, one pathless entry anywhere in the registry threw inside the predicate and zeroed the candidate list for every database, silently. - `describeHolderCandidates()` honors the documented disable value, like the other two surfaces. - The same suffix is appended to `abandonCommitAfterDeadline()`'s log, the other place a commit parked on someone else's write intent is reported. - Changing `storage.longTransactionReportThreshold` clears the accrued backoff, so a handle already under observation is re-measured. `nextReportAgeMs` was pinned at first observation, so lowering the threshold mid-incident did not bring a report forward and raising it did not quiet one — contradicting the live-reload the module promises. - Attribution walks the whole `.next` chain, reporting each link that holds its own native handle under that link's own id, with that link's own staged-write count. A link the monitor reaches only through the root was named under the root's id, which the registry sweep's line cannot be joined to. - The attribution prune runs at most once a minute rather than once per over-threshold transaction per tick (O(N^2) in exactly the leak it reports on). - A handle whose database has no path logs `?` rather than `undefined`; strict assertion in the new txn-tracking test. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013QDdAwWFsWANGNs7ccja1H
- The sweep no longer builds a key, a report state and two container entries for every live handle in the process on every pass. `nextReportAgeMs` is seeded at the threshold and only grows, so a sub-threshold handle can never be due and its state would be pruned on the same pass; a healthy node's minute now costs nothing rather than ~4 allocations per live handle. - A chain link reported through the root no longer claims `state: active`. `timeout` is armed by `addWrite` and decremented once per tick only for the link the tick entered on, so a link reached through `.next` kept an armed `timeout` forever and told the operator the application was still writing when the link had been idle for hours — the inverse of the diagnosis, on exactly the shape the chain walk exists for. - Two comments that restated the callee's own docstring are gone. The chain-link test now matches on the link's table rather than its native id alone: ids are allocated per database descriptor, so the root and the second-database link both held id 4 and an id-only match asserted against the root's line. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013QDdAwWFsWANGNs7ccja1H
…n link `active` now reads whichever recency clock the monitor maintains for the link being reported: `timeout` for the link the tick entered on, which is decremented once per tick beside the reap branches, and `writeTimeout` for a link reached only through the chain, which is what `chainStillActive` decays. The previous round dropped `active` for chain links entirely, which traded a permanent false positive for hiding a link the application is still writing to. Both directions are pinned: a freshly-written chain link must report `active`, and one whose write recency has decayed must not. Each is a single-phase test — the reporting window closes when the logical transaction settles, so a multi-phase assertion raced the force-commit — and the child's native id is captured before the wait rather than read after it. Also corrects the sweep comment: without the new skip, a sub-threshold handle's state was added to `seen` and survived pruning. The reason the skip is safe is that `nextReportAgeMs` is seeded at the threshold and only grows, so that state could never change an outcome. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013QDdAwWFsWANGNs7ccja1H
reportLongLivedLink no longer infers the chain case from `timeout`; it reads whichever recency clock the monitor maintains for that link. The docstring still described the old rule. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013QDdAwWFsWANGNs7ccja1H
…ot throw Both functions document that they never take down their caller — the sweep runs from a bare `setInterval` on the main thread, and `describeHolderCandidates` builds a log message on the way to a 503 that must not become a 500. In both, the config read sat outside the `try` that makes that true. Scope moves only; no behavior change. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013QDdAwWFsWANGNs7ccja1H
Ranking the stuck commit's own database first and then capping at three could bury the one candidate the cross-database search was added to surface: a busy database routinely has three live handles of its own, so a `system`/`oauth` holder parking a `data` commit would only ever appear inside the "and N more" count. The oldest foreign candidate now takes the last slot when this database would otherwise fill every one, and a test pins it with four same-database handles against one foreign. Found by the cursor-grok leg, which reached a verdict for the first time this session. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013QDdAwWFsWANGNs7ccja1H
`reportLongLivedLink` sampled `performance.now()` before the threshold check, so a worker paid one clock read per link holding a live handle on every tick — the cost scales with tracked transactions, which is exactly the leak this reports on. The tick now samples once and passes it down; the threshold it feeds is minutes, so per-link precision buys nothing. Also strengthens the reserved-slot test: a second, younger foreign handle now sits between, so the fixture proves the OLDEST foreign candidate takes the slot rather than merely some foreign one. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_013QDdAwWFsWANGNs7ccja1H
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
Co-Authored-By: GPT-5 Codex <noreply@openai.com>
611caef to
bb14e67
Compare
A RocksDB transaction that holds staged writes — and with them verification-table write intents — can stay open indefinitely with nothing in core naming it. On 5.2.7 such a holder parked other writers forever (the #2450 wedge); on 5.2.8 the park is bounded, so the same holder costs ~5s on every colliding write and, if it also pins a snapshot, blocks version reclamation until restart. Two field incidents held for 4.5h and 9h across two nodes with not one log line identifying the holder.
Nothing reported it because each observer has a blind spot: the monitor's
sourceApply/isReplaybranch force-commits and logs nothing at all, its commit-phase sparing warns but carries no native transaction id to correlate on, the stuck-commit logs name only the victim commit and never what it is parked behind, and a handle opened outside a supervised transaction is in neither monitor registry at all.This adds three reporting surfaces joined by the native transaction id and leaves reaping behavior unchanged. The load-bearing fact is that rocksdb-js's registry is process-global, not thread-local — verified by probe and now pinned by a test that creates a handle only inside a worker and reports it from the main thread — so one main-thread sweep sees every worker's handles, including ones core never tracked. That is the only surface that can see the untracked class. The per-thread monitor adds what the sweep cannot: thread, database/table,
startedFrom, staged write count, and which state kept it from being reaped — walking the whole.nextchain, so a link that owns its own handle is named under its own id rather than the root's. Both stuck-commit logs —checkOverloaded()and #2459'sabandonCommitAfterDeadline()— append the live handles that could hold the intent they are parked on.Threshold is
storage.longTransactionReportThreshold(default5m,0disables all three); changing it clears the accrued backoff so a handle already under observation is re-measured against the new value.The rebase follow-up restores two test-seam docblocks and makes the tests deterministic: the worker sweep waits for its own database path, the chain fixture sets the actual root transaction's budget before its first write, and the abandonment test asserts the candidate suffix alongside the 503. The root-budget assignment is where to look hardest: it must precede both writes so the chain link inherits the 5s test budget.
For the human reviewer
warnlevel). I chose breadth because RocksDB read snapshot leaks permanently: registry holds a strong ref to TransactionHandle, GC finalizer never calls close(), and DatabaseTransaction.abort() cannot release a save()-created transaction #2107 is exactly a read-pinned snapshot blocking reclamation, and because a read handle surviving 5m is already anomalous —storage.maxTransactionOpenTimeis 30s and the monitor commits over-limit read-only transactions to close out the snapshot. Cost of "no": steady WARN traffic on a healthy node doing long exports trains operators to ignore the one line this issue exists to make them read. Reversible by changing a predicate.storage.maxTransactionOpenTimeor folding understorage.debugLongTransactions. Those two govern reap policy and a debug-only stack capture; this governs reporting, and needs its own noise/disable semantics — an operator tightening it during an incident must not thereby change what gets aborted. Cost of "no": a config key is API and needs a docs-repo entry; removing one later is breaking.systemoroauthparks adatacommit at the same 1-in-131072 rate anotherdatakey would — and the same-database filter printed nothing at all for that shape. The oldest foreign candidate is given the last of the three slots when this database would otherwise fill all of them — without that, a busydatadatabase's own three handles push the actual holder into the "and N more" count, which is exactly the case the cross-database search exists for. Cost of "no": a wider list could send an operator to the wrong database. Cheap to narrow;MAX_HOLDER_CANDIDATESbounds the line either way.setRegistryStatusForTests,resetLongLivedTransactionReportsForTests, andsetMaxOutstandingTxnDurationonDatabaseTransaction). Repo precedent exists (setTxnExpiration,resetReplayedWritesWarning,trackOutstandingCommit). The third is what makes the stuck-commit log testable at all — without it a test must wedge a commit for the real 45s. The review flagged that it lacks theForTestssuffix its two neighbours carry: it matches this file's existingsetTxnExpirationconvention but not the new module's, and renaming is free now and awkward after release.startHTTPThreads. Two reviewers asked for a change and I am declining both, on the code rather than the review text. Barber AI's blocker says job-worker and CLI processes never sweep — butlaunchJobThreadcallsthreadsStart.startWorker(), which isnew Worker(...): job workers are threads in the process that already armed the sweep, and the registry is process-global, so their handles are already reported. What is genuinely uncovered is a separate CLI process (bin/backup.ts,bin/copyDb.ts) holding a handle past the threshold — narrow, and not this issue's shape. Devin's stalled-main-thread argument is the stronger one, and is the reason to revisit if it recurs, but it is self-described as unproven (disableStdio()on EPIPE/EIO is the competing explanation) and the per-thread attribution surface runs on every worker regardless, so a stalled main thread costs only the untracked-handle sweep.abandonWrites()is documented as barring any later commit, and asourceApply/isReplaytransaction has no resume path, so releasing its intents drops the write while the cursor advances past it — permanent divergence, which is why harper-pro#348 created the exemption. The only variant that preserves the write is abandon-then-replay onto a fresh transaction, which cannot run while the transaction is parked in its pre-commit await. And A transaction holding staged writes stays open for hours and is never reaped or identified (the holder behind the #2450 wedge) #2471 states the production trigger is still unidentified, so this ships the "at minimum they should be reported" floor and leaves the policy to be driven by what these logs identify. Linked asRefs #2471rather thanClosesfor that reason.registryStatus()call materializes the whole snapshot, so enumeration is O(live handles) once per minute on the main thread. Capping the loop after the call saves nothing — the snapshot is the cost — and bounding it properly is a rocksdb-js-side "return only over-age handles" API. The pass no longer allocates per sub-threshold handle, and log formatting is capped at 10 per pass plus an omitted count.reportLongLivedHolder(reached only for links already past the threshold, and it would put a parameter on a public export for a config-map lookup).sourceApplyapply parked in pre-commit blob I/O an operator gets table/path-only warns from ~30s until the 5m attribution line appears. That gap is named in this PR's problem statement as motivation, not as something it closes; adding the id there is a separate change to a pre-existing log line. And the "N further handles" summary has no backoff of its own, so a sustained leak re-emits it once a minute — one line per minute during an active leak reads as the intended "there is more" signal rather than noise.storage.longTransactionReportThresholdis user-facing and owes a HarperFast/documentation companion before this leaves draft; not opened here.cherry-pick/v5.2/pr-2473and gating the release-branch integration tests; the branch currently carries four conflict regions inresources/DatabaseTransaction.tsand two inresources/DESIGN.md.origin/v5.2does not contain Bound a request-path commit's conflict retries to its queue-time budget #2459, so thecheckOverloaded()log block conflicts andabandonCommitAfterDeadline()— which this PR appends the holder line to — does not exist on that line at all. Resolving it is a/patch-prjob after merge, not a fix on this branch.Verification
Route: resource unit tests, plus real cross-thread and multi-database transactions as the end-to-end proof. The reporting path has no request-level endpoint; the new configuration key remains a documentation-companion decision while this PR is draft.
npm run build— passed.npm run test:unit:resources— 2,164 passing, 28 pending (3m), including the full-suite cleanup checks after the tests temporarily replace global logger and registry hooks.npx mocha unitTests/resources/longLivedTransactions.test.js unitTests/resources/commitConflictDeadline.test.js— 57 passing (4s).npx oxlint --format stylish --deny-warnings unitTests/resources/longLivedTransactions.test.js unitTests/resources/commitConflictDeadline.test.js— passed.npm run lint— blocked by 13 existing warnings outside this diff; the scoped lint above passes.resources/DatabaseTransaction.tsreverted toorigin/mainand everything else in place, the attribution test fails (Timed out after 2000ms waiting for condition) and passes with the change. Thestate: activeassertion added this round was likewise confirmed to fail with themonitored &&guard removed and pass with it.Rebased onto
origin/main(the branch wasCONFLICTING). #2459 landed thedescribeCommitIdentity()/allowStuckCommitLog()refactor under the samecheckOverloaded()log line; the resolution keeps that refactor and threads the holder-candidate suffix through it.Note:
resources/DESIGN.mdis one edited row; the rest of its diff is Prettier re-padding the markdown table.Refs #2471
Refs #2495
Complexity: complicated
Review-Coverage: authored=codex; ran=claude; blocked=gemini(permission-denied); declined=cursor-grok,cursor-composer,domain; rounds=6 @ bb14e67
Human-Review-Need: 3 @ bb14e67