Skip to content

Make a WriteBufferManager write stall observable - #824

Open
kriszyp wants to merge 8 commits into
mainfrom
feat/write-buffer-manager-observability
Open

Make a WriteBufferManager write stall observable#824
kriszyp wants to merge 8 commits into
mainfrom
feat/write-buffer-manager-observability

Conversation

@kriszyp

@kriszyp kriszyp commented Sep 4, 2026

Copy link
Copy Markdown
Member

A WriteBufferManager stall is a second, entirely separate stall mechanism from the one RocksDB reports on. DBImpl::WriteBufferManagerStallWrites parks writers on the manager's own queue without touching the WriteController, so rocksdb.stall.micros, the WRITE_STALL histogram and OnStallConditionsChanged — and therefore db.isWriteStalled() and the 'writeStall' event — all read 0 for its entire duration. Through an eight-hour production wedge every one of them did, while reads kept working and diagnosis needed gdb.

This makes the condition visible. It is additive: no write-path behavior changes, and nothing about allowStall, WriteBufferManager sizing, or the retained-history resolution (#821) is touched.

1. The manager's live state, on two surfaces. db.getStats() / db.getStat() gain five keys under a writeBufferManager. prefix — bufferSize, memoryUsage, mutableMemoryUsage, stallActive, stallActiveMs — added unconditionally, the same treatment the existing txnlog.* and commitPipeline.* keys get, so they appear with enableStats: false. They are routed through the same prefix branch in DBHandle::getStat those two use, because a single-key read that fell through to the RocksDB statistics path would throw "Statistics are not enabled" during exactly the incident an operator is reaching for it in. RocksDatabase.getWriteBufferManagerStats() returns the same values plus the manager's configuration and its live column-family inventory. Both read the manager through an std::atomic<WriteBufferManager*> published at construction, so a metrics scrape takes no lock and never materializes the manager as a side effect.

These are process-wide values coming back from a per-database call — the manager is a singleton shared by every database in the process, worker_threads included — which is stated in the docs, the JSDoc, and the stat-name reference.

2. A watchdog that logs one warn line per stall episode, carrying the budget, usage, mutable share, live column-family count and the effective per-CF max_write_buffer_size_to_maintain — effective, not requested, because #821's whole finding is that TransactionDB::Open rewrites a requested 0 into 256 MiB per column family, so the requested value would hide the fact the line exists to expose. Every one of those was needed to explain the wedge and every one required the RocksDB LOG or a debugger.

It owns a thread because every other tick in the process is blocked by the condition it reports: CommitWorker parks in db->Write() (the rocksdb-commit lanes are in #822's backtrace), logWorker is event-driven off commits the stall prevents, ParkTimeoutRegistry's thread is per-descriptor and only exists after a VT conflict, RocksDB's stall callbacks never fire, and a JS timer cannot run on a thread parked in store.putSync(). One thread per process, started lazily only while a manager exists with allowStall (ShouldStall() short-circuits otherwise, so no stall is reachable and no thread is started), sampling one relaxed atomic per second.
Three lifecycle constraints on that thread are the places to look hardest, each of which the review found the hard way:

  • Lock order is databasesMutex -> writeBufferManagerMutex -> watchdogMutex, because DBRegistry::OpenDB holds the first across DBDescriptor::open. So the start path never joins a retiring thread — the thread it would join may be waiting for exactly that lock — and a per-start generation counter retires stale threads instead.
  • The inventory walk try_locks databasesMutex and reports inventoryAvailable: false rather than waiting: PurgeAll holds that lock across a close whose flush waits out a write stall (AGENTS.md note 16), so blocking there would silence the alarm and hang getWriteBufferManagerStats() during the incident both exist to report.
  • Stop and join are splitat teardown so the flush runs before the join, and on the allowStall falling edge so a report blocked on a full stderr pipe holds no lock any database open needs. The falling edge then re-reads the live setting, because a concurrent re-enable in that unlocked window would otherwise be left with stalling on and no alarm behind it. ~DBSettings and an atexit handler registered at watchdog start both join, so the process.exit() path (which skips the module cleanup hook) neither destroys a joinable thread nor outlives the registry; the global event emitter is leaked for the same ordering reason.

The decision FSM itself is Node-free and GoogleTest-covered, so the sampling logic is proved without threads or RocksDB.

For the human reviewer

The step-6 planning gate ran before any code and cleared: Framing-Verdict: chosen-approach-sound. Six pre-push review rounds followed (gemini + codex + harper-domain); the decisions below are the ones a reviewer should weigh rather than defects left open.

Decisions taken, each reversible:

  • The warn line goes to stderr as well as the 'log.warn' event. Harper registers no log.warn listener today, so an event-only line reaches nothing without a Harper change. The cost is unstructured output a log pipeline cannot format; route the event and ignore stderr if you would rather have it structured. @kriszyp ruled on this, and corrected the rationale I had offered for it: WBM stalls have not been observed freezing Harper's JS threads (no putSync on active paths; the observed symptom is every thread complaining about slow commits), so the load-bearing argument for stderr is the missing listener, not a blocked event loop. A direct consumer of this library's synchronous write path can still block its own loop, which is why the sampler still cannot be a JS timer.
  • The process-wide keys live inside per-database getStats(). That is what makes a stall visible in Harper's system_information with no Harper change. A scraper summing them across databases will N-count; the alternative was leaving them only on the static accessor, where nothing scrapes them.
  • The threshold is env-only (ROCKSDB_JS_WBM_STALL_WARN_MS, read once per process), not a config() knob like every other WriteBufferManager setting. Adding the knob later is additive.
  • 0 disables the watchdog thread entirely, and with it stallActiveMs — silencing the log also silences that gauge, because only the thread populates it.
  • An out-of-range threshold falls back to 5 s rather than clamping, erring toward alarming earlier than asked, never later. It now says so on stderr instead of doing it silently.
  • The inventory counts only writable descriptors that attached this manager. A read-only database does attach it but cannot explain its memory, so the reported columnFamilies will not reconcile with a count of open handles.
  • The end-to-end stall test lives in the default suite (~9 s, and it hard-fails rather than skips if no stall is reached). It is the only proof the wiring works end to end.

Accepted residuals, all raised by the review and deliberately not fixed:

  • config({ writeBufferManagerAllowStall: false }) joins the retiring watchdog synchronously. The join is outside writeBufferManagerMutex (so it blocks no database open) and the sample path abandons a report once a stop is requested, but a report already inside its stderr write is unbounded on a full pipe. The same unbounded wait already exists on the teardown path, where the split stop/join keeps it behind the flush rather than in front of it.
  • If atexit() registration fails, the watchdog keeps running and ~DBSettings is the backstop join — it is not the only pre-destruction join, so the failure is not silent in the way the finding describes.
  • The end-to-end test does not exercise stall recovery or a stall during teardown. The recovery FSM is covered deterministically in test/native/wbm_stall_watchdog_test.cc; reaching a recovering stall end-to-end needs a scenario whose retained history can drain, which this one deliberately cannot.

Not implemented, by instruction: issue item 3 (SetAllowStall(false) after N seconds to release queued writers). The hook is now obvious — the watchdog is the only thing in the process that knows how long a stall has lasted, so a bounded escape hatch is a second threshold in the same FSM — but it converts a hang into unbounded memtable growth, which is a maintainer's call.

A finding the task anticipated that did not hold. The context expected that with atomic_flush (which this library always sets) a WBM-pressure flush is recorded under ATOMIC_FLUSH_REQUEST_REASON_WRITE_BUFFER_MANAGER instead of FLUSH_REASON_WRITE_BUFFER_MANAGER, and asked for a docs/stats.md correction if so. Measured here, both counters move: 13/13 with one column family, roughly 1:2 with two to six, and requests can outnumber executed flushes when several databases share a manager. So rocksdb.flush.reason.write_buffer_manager is not the wrong counter, and the production 0 was genuine — no manager-pressure flush was ever requested, because the trigger looks only at mutable memory. The docs carry the measured relationship rather than the anticipated correction; writing the anticipated note would have shipped a false statement.

Verification

  • Full suite green on the pushed head: 64 files passed, 1 skipped, 854 tests passed, 9 skipped, 0 failed (pnpm test, Node 26 / Linux). Three earlier full runs had different files time out each time — all passed in isolation, on a box running several agents concurrently.
  • Native GoogleTest: 174 tests pass (pnpm test:native), including 14 new ones covering the watchdog FSM (rising edge, threshold crossing, one-shot, retry-until-acknowledged, recovery re-arm, flapping, threshold 0), the env-var parse (clamp, reject, out-of-range) and the report formatter.
  • The end-to-end stall test reaches a real stall and asserts exactly one warn line across several times the threshold, its full payload, the 'log.warn' event carrying the same line once, and — from the child's main thread while a worker is blocked in putSyncstallActive, a rising stallActiveMs, and agreement between getWriteBufferManagerStats(), getStats() and getStat().
  • process.exit() with a live watchdog exits 0, verified directly; without the join it is std::terminate() by construction.
  • The allowStall runtime edges start and stop the watchdog, verified by test and by hand (on → off → back on).
  • pnpm check (type-check, lint, format) clean.

Refs #822

🤖 Generated with Claude Code

https://claude.ai/code/session_01GxngG4PtHJ7BZzYjWi33Jk

Review-Coverage: authored=claude; ran=codex,gemini; declined=cursor-grok,cursor-composer,domain; rounds=8 @ 0adf538

Human-Review-Need: 3 @ 0adf538

Kris Zyp and others added 6 commits September 3, 2026 17:07
A WriteBufferManager stall is a second, entirely separate stall mechanism, and
nothing in RocksDB reports it: `DBImpl::WriteBufferManagerStallWrites` parks
writers on the manager's own queue without touching the `WriteController`, so
`rocksdb.stall.micros`, the `WRITE_STALL` histogram and `OnStallConditionsChanged`
(hence `isWriteStalled()` and the `'writeStall'` event) all read 0 for its entire
duration. An eight-hour production wedge was invisible to every one of them.

Two additive surfaces, no write-path behavior change:

- `writeBufferManager.{bufferSize,memoryUsage,mutableMemoryUsage,stallActive,
  stallActiveMs}` on `db.getStats()` / `db.getStat()`, and
  `RocksDatabase.getWriteBufferManagerStats()` which adds the manager's
  configuration and its live column-family inventory. Both read the manager
  through an atomic pointer published at construction, so a scrape never takes
  a lock or materializes the manager.
- A process-wide watchdog thread, started only while a manager exists with
  `allowStall`, that samples `IsStallActive()` once a second and writes one warn
  line per stall episode (stderr plus a `log.warn` event) carrying the budget,
  usage, mutable share, live column-family count and the effective per-CF
  `max_write_buffer_size_to_maintain`. It needs its own thread because every
  other tick in the process is blocked by the condition it reports.

Refs #822

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GxngG4PtHJ7BZzYjWi33Jk
Pre-push review round 1 (gemini + harper-domain):

- `~DBSettings` now joins the watchdog. `process.exit()` skips N-API env cleanup,
  and destroying a joinable `std::thread` calls `std::terminate()` — an
  observability feature must not turn a clean exit into SIGABRT. Mirrors
  `~CommitWorker`.
- A per-start generation counter retires a stale watchdog. `join()` releases
  `watchdogMutex` before `join()` returns, so a concurrent start could clear
  `watchdogStopRequested` and leave the retiring thread looping forever with its
  joiner blocked on it.
- The inventory walk takes `databasesMutex` with `try_lock` and reports
  `inventoryAvailable: false` instead of waiting. `PurgeAll` holds that lock
  across a close whose flush waits out a write stall, so blocking there would
  silence the alarm and hang `getWriteBufferManagerStats()` during exactly the
  incident both exist to report.
- The episode is retired when either channel carried the line, not `stderr`
  alone: with fd 2 closed and a listener attached, the old gate re-reported every
  second for the whole stall.
- A refused `ROCKSDB_JS_WBM_STALL_WARN_MS` now says so on stderr rather than
  silently falling back to 5s.
- docs/stats.md: a blank line detached the five new rows from the table, so
  GitHub rendered them as literal text.
- The stall test asserts the `'log.warn'` event as well as stderr, anchors its
  `STALLED` sentinel (`NEVER_STALLED` contained it), and cleans up with the same
  retry/`KEEP_FILES` discipline as its neighbour.

Refs #822

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GxngG4PtHJ7BZzYjWi33Jk
Pre-push review round 2 (gemini LGTM; harper-domain findings):

- `GlobalEvents`'s emitter is now leaked. Block-scope statics are destroyed in
  reverse construction order and it is normally constructed after `DBSettings`,
  so on the `process.exit()` path it would be destroyed while `~DBSettings` is
  still joining the watchdog — whose report path emits through it.
- `config({ writeBufferManagerAllowStall: false })` now stops the watchdog. It
  previously left a permanent 1 Hz thread and reported `watchdogRunning: true`
  alongside `allowStall: false`, contradicting the documented lifetime.
- `watchdogRunning` is published when the thread is started rather than when it
  is first scheduled, so enabling stalling and reading straight back no longer
  reports the watchdog absent.
- Dropped the added comments that restate the identifier below them, and made the
  child fixture's `CLEARED` outcome terminal — it previously printed `STALLED`
  as well, which the parent reads as "a stall was reached".

Refs #822

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GxngG4PtHJ7BZzYjWi33Jk
Pre-push review round 3 (codex + harper-domain). The `allowStall` falling edge
joined the watchdog from inside `Config()`'s `writeBufferManagerMutex` critical
section, so a report blocked on a full stderr pipe would hold that lock — wedging
the caller's event loop and every concurrent `DBDescriptor::open` behind it. The
join now happens after the critical section closes: the same stop/join split, for
the same reason, as the teardown path in `binding.cpp`.

Refs #822

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GxngG4PtHJ7BZzYjWi33Jk
Pre-push review round 4 (codex + gemini) on the previous commit's unlocked join:

- Another environment enabling stalling between the mutex release and the join
  found the retiring thread still started, declined to start one, and was then
  stopped by the retiring caller — leaving `allowStall: true` with no alarm. The
  falling edge now re-reads the live setting after joining and restarts if it is
  still on.
- The sample path abandons a report once a stop has been requested, so a joiner
  waits behind a write already in progress rather than one about to start.

Refs #822

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GxngG4PtHJ7BZzYjWi33Jk
Pre-push review round 5 raised the reverse question about the exit path: whether
`~DBSettings`'s join can run after `DBRegistry`'s static instance is gone, since
the watchdog's inventory walk touches it. It cannot — static destructors run in
reverse order of construction completion, and the registry's instance is a class
static registered before `main` while `DBSettings` is first touched by `config()`
— but that is an argument, not a guarantee. Registering the join with `atexit()`
at watchdog start makes it one: the handler runs ahead of every destructor
registered earlier. `~DBSettings` stays as the backstop; both are idempotent.

Refs #822

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GxngG4PtHJ7BZzYjWi33Jk
@kriszyp
kriszyp requested a review from cb1kenobi September 4, 2026 02:08

@gemini-code-assist gemini-code-assist Bot left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code Review

This pull request introduces a process-wide WriteBufferManager stall watchdog to detect and report sustained write stalls that are otherwise invisible to RocksDB's default counters. It adds a background watchdog thread, exposes new APIs and metrics via getWriteBufferManagerStats(), and integrates these metrics into db.getStats(). The feedback suggests replacing Date.now() with performance.now() in the test fixture fork-wbm-stall-watchdog.mts to ensure a monotonic clock is used for measuring deadlines and elapsed time.

Comment thread test/fixtures/fork-wbm-stall-watchdog.mts Outdated
Comment thread test/fixtures/fork-wbm-stall-watchdog.mts Outdated
@github-actions

github-actions Bot commented Sep 4, 2026

Copy link
Copy Markdown
Contributor

📊 Benchmark Results

get-sync.bench.ts

getSync() > random keys - small key size (100 records)

Implementation Rank Operations/sec Mean (ms) Min (ms) Max (ms) RME (%) Samples
🥇 lmdb 1 22.71K ops/sec 44.03 40.17 2,042.168 0.138 113,565
🥈 rocksdb 2 11.23K ops/sec 89.09 85.34 23,744.609 0.957 56,126

getSync() > sequential keys - small key size (100 records)

Implementation Rank Operations/sec Mean (ms) Min (ms) Max (ms) RME (%) Samples
🥇 lmdb 1 25.99K ops/sec 38.48 34.89 492.226 0.109 129,929
🥈 rocksdb 2 11.30K ops/sec 88.50 84.28 3,327.804 0.138 56,500

ranges.bench.ts

getRange() > small range (100 records, 50 range)

Implementation Rank Operations/sec Mean (ms) Min (ms) Max (ms) RME (%) Samples
🥇 lmdb 1 25.22K ops/sec 39.65 34.63 2,060.514 0.292 126,118
🥈 rocksdb 2 14.69K ops/sec 68.09 60.62 1,086.527 0.120 73,434

realistic-load.bench.ts

Realistic write load with workers > write variable records with transaction log

Implementation Rank Operations/sec Mean (ms) Min (ms) Max (ms) RME (%) Samples
🥇 rocksdb 1 348.68 ops/sec 2,867.976 57.81 82,150.239 21.66 706
🥈 lmdb 2 26.25 ops/sec 38,098.181 425.79 1,193,069.222 136.236 64.00

transaction-log.bench.ts

Transaction log > read 100 iterators while write log with 100 byte records

Implementation Rank Operations/sec Mean (ms) Min (ms) Max (ms) RME (%) Samples
🥇 rocksdb 1 38.72K ops/sec 25.82 11.35 20,719.735 0.837 193,622
🥈 lmdb 2 438.39 ops/sec 2,281.065 82.79 25,058.276 1.51 2,192

Transaction log > read one entry from random position from log with 1000 100 byte records

Implementation Rank Operations/sec Mean (ms) Min (ms) Max (ms) RME (%) Samples
🥇 rocksdb 1 724.57K ops/sec 1.38 1.22 464.169 0.064 3,622,843
🥈 lmdb 2 468.68K ops/sec 2.13 1.15 7,643.417 0.463 2,343,403

worker-put-sync.bench.ts

putSync() > random keys - small key size (100 records, 10 workers)

Implementation Rank Operations/sec Mean (ms) Min (ms) Max (ms) RME (%) Samples
🥇 rocksdb 1 796.31 ops/sec 1,255.793 1,077.134 1,944.037 0.424 1,593
🥈 lmdb 2 1.15 ops/sec 867,440.084 780,815.704 914,826.511 3.36 10.00

worker-transaction-log.bench.ts

Transaction log with workers > write log with 100 byte records

Implementation Rank Operations/sec Mean (ms) Min (ms) Max (ms) RME (%) Samples
🥇 rocksdb 1 22.80K ops/sec 43.86 29.28 20,641.392 2.10 45,606
🥈 lmdb 2 832.20 ops/sec 1,201.634 177.241 11,325.486 5.34 1,666

Results from commit 6994f4e

Kris Zyp and others added 2 commits September 3, 2026 20:35
The Windows CRT opens stderr in text mode, so the watchdog's `fprintf(stderr,
"…\n")` lands as `\r\n` while Node's `console.log` on stdout does not translate.
Splitting both on `\n` alone left the stderr line with a trailing `\r`, and the
assertion that the `'log.warn'` event carries the same payload compared it
against an untranslated copy. Failed on Bun and Deno for windows-latest.

Refs #822

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GxngG4PtHJ7BZzYjWi33Jk
Gemini's PR review: the child fixture timed its observation window with
Date.now(), which a system clock adjustment can move under it. performance.now()
is monotonic.

Refs #822

Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01GxngG4PtHJ7BZzYjWi33Jk
Comment thread src/database.ts
* }
* ```
*/
static getWriteBufferManagerStats(): WriteBufferManagerStats {

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This exposes a second surface for the same API.

import { RocksDatabase, getWriteBufferManagerStats } from '@harperfast/rocksdb-js';
const wbm1 = RocksDatabase.getWriteBufferManagerStats();
const wbm2 = getWriteBufferManagerStats();

I think we should remove this static method version and be more like registryStatus and only have a top-level export.

Comment thread src/index.ts
coolTransactionLogs,
currentThreadId,
fileLockRelease,
getWriteBufferManagerStats,

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

getWriteBufferManagerStats() is the only top-level export with the "get" prefix, yet provides similar readonly view as registryStatus() does. For consistency, we should either drop the "get" or add the "get" to registryStatus(). I'm thinking we do the latter. I kinda of like the "get" and I should probably have done it in the first place. Ticket created: #840.

* walks the database registry, while everything above it is a handful of atomic
* loads. `getStats()` is a scrape path and takes the cheap half.
*/
struct WriteBufferManagerStats final {

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't love putting the WriteBufferManagerStats logic in db_settings. db_settings is for incoming database settings, not APIs returning data and wiring up watchdogs. I think all of this write buffer stats stuff should go in a database/db_stats.* (or whatever) files with it's own singleton and Init().

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants