1
0

wal-valve.ts 15 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290
  1. /**
  2. * WAL checkpoint valve — bounds WAL growth while auto-checkpointing is
  3. * deferred during a bulk index (#1231).
  4. *
  5. * Why deferral: SQLite's default `wal_autocheckpoint` (1000 pages) re-writes
  6. * hot B-tree/FTS pages into the main DB file over and over during a bulk
  7. * index — measured at ~95% of ALL disk I/O, and the difference between 45s
  8. * and 19+ minutes on HDD-class storage (150 random IOPS). Deferring
  9. * checkpoints turns the store into pure sequential WAL appends; each backfill
  10. * pass writes distinct pages once, in page order (≈ sequential).
  11. *
  12. * Why a valve: unbounded deferral is its own failure mode, both measured in
  13. * the #1231 repro. The WAL duplicates hot pages per COMMIT, so it grows far
  14. * faster than the DB (5.9GB WAL for a ~340MB DB on a 3.3k-file index) —
  15. * filling the disk, and poisoning every subsequent read that must page
  16. * through it (the first resolution-phase read blocked the main thread >60s
  17. * and the #850 liveness watchdog killed the healthy index). The valve
  18. * watches WAL growth on a timer and, past a soft threshold, backfills with
  19. * `PRAGMA wal_checkpoint(PASSIVE)` on a worker-thread connection — PASSIVE
  20. * never blocks the writer, and off-thread means the main thread (and the
  21. * watchdog heartbeat) keep turning regardless of how long a backfill takes.
  22. *
  23. * The load-bearing subtlety: a WAL file's SIZE never shrinks. After a full
  24. * backfill, the writer's next commit RESTARTS the WAL from the top and the
  25. * frames recycle inside the same file — so raw size says nothing about the
  26. * un-backfilled backlog, and a size-triggered valve degenerates into firing
  27. * (and pausing the writer) forever once the file passes its threshold
  28. * (measured: guava crawled at ~9min per 160 files). Instead the valve
  29. * tracks `sizeAtLastFullBackfill` — refreshed whenever a checkpoint reports
  30. * `log === checkpointed` (everything backfilled) — and triggers on GROWTH
  31. * beyond that baseline, which only happens when genuinely un-backfilled
  32. * frames push past the file's high-water mark.
  33. *
  34. * Backpressure: if the writer outruns the checkpointer past a hard cap of
  35. * growth (2× soft), {@link backpressure} pauses the writer (at a safe,
  36. * between-transactions boundary) until a FULL backfill lands. One in-flight
  37. * pass is not enough: on a disk saturated by the writer, every concurrent
  38. * PASSIVE pass is already stale by the time it finishes (the writer appended
  39. * past its snapshot), so neither SQLite's WAL wrap nor the baseline ever
  40. * trigger and the WAL grows without bound (measured: 5.9GB on guava at 150
  41. * IOPS, then a >60s read stall and a watchdog kill). With the writer parked,
  42. * the next pass covers everything, the WAL wraps on the following commit,
  43. * and the pause is the disk's honest catch-up cost — the correct terminal
  44. * mode when hardware genuinely can't keep up with the append rate.
  45. */
  46. import type { DatabaseConnection } from './index';
  47. /** Soft WAL-growth threshold (MB) that triggers an off-thread passive checkpoint. */
  48. const DEFAULT_WAL_VALVE_MB = 256;
  49. /** Hard cap = this × soft threshold; past it the writer pauses for a full backfill. */
  50. const HARD_CAP_MULTIPLIER = 2;
  51. /** File cap = this × soft threshold; past it the barrier also TRUNCATEs the file. */
  52. const FILE_CAP_MULTIPLIER = 4;
  53. /** Passes attempted per writer pause before giving up (a pinned reader could stall forever). */
  54. const MAX_PAUSED_BACKFILL_PASSES = 20;
  55. /** How often the timer looks at the WAL file size. */
  56. const CHECK_INTERVAL_MS = 2000;
  57. /**
  58. * Resolve the valve's soft threshold from the `CODEGRAPH_WAL_VALVE_MB`
  59. * override; non-numeric / non-positive values fall back to the default.
  60. */
  61. export function resolveWalValveMb(envVal: string | undefined, dbSizeBytes?: number): number {
  62. if (envVal !== undefined && envVal !== '') {
  63. const n = Number(envVal);
  64. if (Number.isFinite(n) && n > 0) return Math.floor(n);
  65. }
  66. // Scale with the project when the caller knows the DB size: every fold
  67. // re-writes hot B-tree pages into the main file (the #1231 pathology in
  68. // bounded form — 111s of a kernel-scale batch loop at the flat 256MB cap,
  69. // §7a.2), so a big project affords a proportionally bigger transient WAL
  70. // (~dbSize/4 soft ⇒ file cap ≈ dbSize) in exchange for ~4× fewer folds.
  71. if (dbSizeBytes !== undefined && dbSizeBytes > 0) {
  72. return Math.min(2048, Math.max(DEFAULT_WAL_VALVE_MB, Math.floor(dbSizeBytes / 4 / (1024 * 1024))));
  73. }
  74. return DEFAULT_WAL_VALVE_MB;
  75. }
  76. export class WalCheckpointValve {
  77. private timer: ReturnType<typeof setInterval> | null = null;
  78. private inflight: Promise<void> | null = null;
  79. /** Writer pause in progress (hard cap breached): passes loop until a full backfill. */
  80. private pause: Promise<void> | null = null;
  81. /**
  82. * WAL file size observed when a checkpoint last reported the ENTIRE WAL
  83. * backfilled. Growth is measured against this baseline — see the header
  84. * comment for why absolute size cannot be used.
  85. */
  86. private sizeAtLastFullBackfill = 0;
  87. private readonly softBytes: number;
  88. private readonly hardBytes: number;
  89. private readonly fileCapBytes: number;
  90. /**
  91. * Futility latch: consecutive backfill give-ups (a reader pinning the WAL)
  92. * disable further writer pauses for a cooldown, so a pinned phase degrades
  93. * to the pre-valve behavior (unbounded WAL, folded when the pinner exits)
  94. * instead of burning a 20-pass checkpoint attempt — each pass a worker
  95. * thread + fresh connection — at EVERY over-cap boundary. That churn is
  96. * what turned a pinned kernel-scale resolution from slow into OOM-killed
  97. * (§7a.1 run 1: 22GB WAL, exit 137 at an envelope the pre-fix build
  98. * survived).
  99. */
  100. private consecutiveGiveUps = 0;
  101. private futileUntil = 0;
  102. constructor(
  103. private readonly db: DatabaseConnection,
  104. softMb: number = resolveWalValveMb(process.env.CODEGRAPH_WAL_VALVE_MB),
  105. private readonly intervalMs: number = CHECK_INTERVAL_MS,
  106. log: (msg: string) => void = () => {}
  107. ) {
  108. this.softBytes = softMb * 1024 * 1024;
  109. this.hardBytes = this.softBytes * HARD_CAP_MULTIPLIER;
  110. this.fileCapBytes = this.softBytes * FILE_CAP_MULTIPLIER;
  111. // CODEGRAPH_WAL_VALVE_DEBUG=1 surfaces valve decisions to stderr without
  112. // needing the caller's verbose plumbing — the observability gap that let
  113. // §7a.1 run 1 fail silently (give-ups were verbose-gated and invisible).
  114. this.log = process.env.CODEGRAPH_WAL_VALVE_DEBUG
  115. ? (m) => console.error(`[wal-valve] ${m}`)
  116. : log;
  117. }
  118. private readonly log: (msg: string) => void;
  119. private mb(n: number): string {
  120. return `${Math.round(n / 1024 / 1024)}MB`;
  121. }
  122. /** Un-backfilled growth estimate: bytes the WAL has grown past the last full backfill. */
  123. private growthBytes(): number {
  124. return this.db.getWalSizeBytes() - this.sizeAtLastFullBackfill;
  125. }
  126. /** Begin watching the WAL. Idempotent; the timer never holds the loop open. */
  127. start(): void {
  128. if (this.timer) return;
  129. // One armed line per run under either diagnostics env: §7a.1's failed
  130. // kernel-scale runs burned three 25-minute cycles before "is the valve
  131. // even alive?" could be answered.
  132. if (process.env.CODEGRAPH_SYNTH_TIMINGS || process.env.CODEGRAPH_WAL_VALVE_DEBUG) {
  133. console.error(`[wal-valve] armed soft=${this.mb(this.softBytes)} hard=${this.mb(this.hardBytes)} wal=${this.mb(this.db.getWalSizeBytes())}`);
  134. }
  135. let ticks = 0;
  136. this.timer = setInterval(() => {
  137. if ((++ticks % 15) === 0) {
  138. this.log(`alive: wal=${this.mb(this.db.getWalSizeBytes())} baseline=${this.mb(this.sizeAtLastFullBackfill)} inflight=${this.inflight ? 'y' : 'n'} paused=${this.pause ? 'y' : 'n'}`);
  139. }
  140. this.check();
  141. }, this.intervalMs);
  142. this.timer.unref?.();
  143. }
  144. /** Stop watching. Any in-flight checkpoint keeps running — await drain(). */
  145. stop(): void {
  146. if (this.timer) {
  147. clearInterval(this.timer);
  148. this.timer = null;
  149. }
  150. }
  151. /** One poll: fire an off-thread passive checkpoint when growth passes the soft threshold. */
  152. check(): void {
  153. if (!this.pause && !this.inflight && this.growthBytes() > this.softBytes) this.fire();
  154. }
  155. /**
  156. * Writer-side backstop, called at a between-transactions boundary. Returns
  157. * null (no wait) while growth is under the hard cap; past it, returns a
  158. * promise that resolves only once a FULL backfill has landed — see the
  159. * header comment for why a single pass is not enough on a saturated disk.
  160. */
  161. backpressure(): Promise<void> | null {
  162. if (this.pause) return this.pause;
  163. if (Date.now() < this.futileUntil) return null; // pinned reader — parking is churn, not progress
  164. // Two independent triggers:
  165. // - growth: un-backfilled BACKLOG past the hard cap (the original valve).
  166. // - file size: a WAL can stay fully backfilled and still grow without
  167. // bound — the writer only restarts at frame 0 if a commit finds no
  168. // reader marks, which §7a.1's instrumented run showed never happens
  169. // in practice (file marched 361→721MB through two COMPLETE
  170. // backfills). Past the file cap, park and TRUNCATE at the barrier —
  171. // the backfill part is instant when the backlog is already folded.
  172. if (this.growthBytes() <= this.hardBytes && this.db.getWalSizeBytes() <= this.fileCapBytes) return null;
  173. this.log(`backpressure: wal=${this.mb(this.db.getWalSizeBytes())} baseline=${this.mb(this.sizeAtLastFullBackfill)} — pausing writer for full backfill`);
  174. const t0 = Date.now();
  175. this.pause = this.backfillFully().finally(() => {
  176. this.pause = null;
  177. this.log(`backpressure released after ${Date.now() - t0}ms: wal=${this.mb(this.db.getWalSizeBytes())} baseline=${this.mb(this.sizeAtLastFullBackfill)}`);
  178. });
  179. return this.pause;
  180. }
  181. /** Await any in-flight checkpoint and writer pause. */
  182. async drain(): Promise<void> {
  183. while (this.pause || this.inflight) {
  184. if (this.pause) await this.pause;
  185. if (this.inflight) await this.inflight;
  186. }
  187. }
  188. /**
  189. * Phase-boundary fold: backfill the ENTIRE WAL now (off-thread, awaited).
  190. * Called between bulk phases — e.g. after parsing, before resolution's
  191. * first reads — so the next phase never pages a bulk-write-sized WAL on
  192. * the main thread (the post-parse read against a multi-GB WAL is what
  193. * blew the #850 watchdog's 60s window in the #1231 repro). The await
  194. * keeps the event loop (and the watchdog heartbeat) turning.
  195. */
  196. async foldNow(): Promise<void> {
  197. await this.drain();
  198. if (this.growthBytes() <= 0) return;
  199. this.log(`foldNow: wal=${this.mb(this.db.getWalSizeBytes())} baseline=${this.mb(this.sizeAtLastFullBackfill)}`);
  200. this.pause = this.backfillFully().finally(() => { this.pause = null; });
  201. await this.pause;
  202. }
  203. /**
  204. * With the writer parked on the returned promise, loop passive passes until
  205. * one reports the entire WAL backfilled (typically the second: the first
  206. * drains the pass that was already running against a stale snapshot). Gives
  207. * up after a bounded number of passes — e.g. a reader pinning the WAL —
  208. * because unbounded WAL growth degrades; a wedged writer never recovers.
  209. */
  210. private async backfillFully(): Promise<void> {
  211. for (let i = 0; i < MAX_PAUSED_BACKFILL_PASSES; i++) {
  212. if (this.inflight) await this.inflight; // fold in the stale in-flight pass first
  213. const res = await this.db.checkpointWalPassive();
  214. if (!res) return; // checkpoint machinery unavailable — don't spin
  215. this.log(`backfill pass ${i + 1}: busy=${res.busy} log=${res.log} checkpointed=${res.checkpointed} wal=${this.mb(this.db.getWalSizeBytes())}`);
  216. if (res.busy === 0 && res.log === res.checkpointed) {
  217. // Backfill complete AND we are at a parked barrier (backfillFully only
  218. // runs under a writer pause): the no-reader window is guaranteed, so
  219. // chop the FILE too — a fully-backfilled WAL otherwise keeps growing
  220. // whenever commits land while pool readers hold marks (§7a.1: 22GB
  221. // on-disk at kernel scale despite backfills). A racing reader turns
  222. // this into a no-op (busy=1); the passive result above still stands.
  223. const trunc = await this.db.checkpointWalTruncate();
  224. if (trunc) this.log(`truncate: busy=${trunc.busy} wal=${this.mb(this.db.getWalSizeBytes())}`);
  225. this.sizeAtLastFullBackfill = this.db.getWalSizeBytes();
  226. this.consecutiveGiveUps = 0;
  227. this.futileUntil = 0;
  228. return;
  229. }
  230. }
  231. this.consecutiveGiveUps++;
  232. if (this.consecutiveGiveUps >= 2) {
  233. this.futileUntil = Date.now() + 60_000;
  234. }
  235. const msg = `backfill gave up after ${MAX_PAUSED_BACKFILL_PASSES} passes (streak ${this.consecutiveGiveUps}${this.futileUntil ? ', parking disabled 60s' : ''}) — a reader is pinning the WAL`;
  236. this.log(msg);
  237. // Give-ups are rare and load-bearing for §7a.1-class diagnosis — surface
  238. // them on any timing-instrumented run, not just valve-debug ones.
  239. if (process.env.CODEGRAPH_SYNTH_TIMINGS && !process.env.CODEGRAPH_WAL_VALVE_DEBUG) {
  240. console.error(`[wal-valve] ${msg}`);
  241. }
  242. }
  243. private fire(): void {
  244. this.log(`fire: wal=${this.mb(this.db.getWalSizeBytes())} baseline=${this.mb(this.sizeAtLastFullBackfill)}`);
  245. const p = this.db
  246. .checkpointWalPassive()
  247. .then((res) => {
  248. this.log(`timer pass: ${res ? `busy=${res.busy} log=${res.log} checkpointed=${res.checkpointed}` : 'null (machinery unavailable)'} wal=${this.mb(this.db.getWalSizeBytes())}`);
  249. // Full backfill (busy 0, every log frame checkpointed) ⇒ the writer's
  250. // next commit wraps the WAL; the file's current size becomes the new
  251. // growth baseline. A partial pass (writer appended during it, or a
  252. // read transaction pinned frames) leaves the baseline alone, so the
  253. // next tick fires again and copies the remainder. In non-WAL mode
  254. // SQLite reports log = checkpointed = -1, which is harmless here.
  255. if (res && res.busy === 0 && res.log === res.checkpointed) {
  256. this.sizeAtLastFullBackfill = this.db.getWalSizeBytes();
  257. // NO truncate here. A truncate checkpoint that starts against an
  258. // ACTIVE writer wins the lock race and then blocks that writer for
  259. // its entire backfill — after a multi-GB single-transaction burst
  260. // (edge-index recreate) that exceeds the writer's 5s busy_timeout
  261. // and fails the index with "database is locked" (§7a.2 record run).
  262. // The file chop happens exclusively at parked barriers
  263. // (backpressure/foldNow), where the writer is awaiting us by
  264. // construction and cannot collide.
  265. }
  266. })
  267. .catch(() => { /* best-effort */ })
  268. .finally(() => {
  269. if (this.inflight === p) this.inflight = null;
  270. });
  271. this.inflight = p;
  272. }
  273. }