Three idle-burn items from the steady-state audit, and one correction. THE FLUSH-REQUEST WATCH (the strongest of them). It readdir'd the request directory every 500 ms, per brain, for the life of every writer — armed on every non-reader brain whether or not any inspector process existed. On a process holding 21 brains that is 42 directory reads per second on a completely idle service, plus a stale-request GC on every one of them. It now uses fs.watch, so the arrival itself wakes it and a request is seen SOONER than the poll saw it. Two concessions ride along, both stated in the code: a 30s safety sweep (fs.watch drops events on some network and fuse filesystems, and the GC needs a tick of its own — 0.7 reads/s across 21 brains where the poll cost 42), and a fall back to the original 500 ms poll, narrated, on a filesystem that cannot watch at all, because an inspector whose request is never seen waits forever. THE WRITER HEARTBEAT goes 10s → 60s. It is observability ONLY — staleness is decided by pid liveness and the fence compares pid + hostname, so no decision anywhere reads the timestamp — and at 10s it was a lock-file write every ten seconds per brain forever, for a value nothing computes with. An operator still sees a heartbeat inside the minute. THE HEALTH NARRATION dedupes by CONTENT, not by the provider's generation counter. That counter bumps on every ledger mutation and rebuild boundary, so a provider bumping it on routine work re-emitted the same unchanged line on every read, while one that never bumped could suppress a line whose reasons had genuinely changed. The generation is still reported; it no longer decides whether the line is worth saying. CORRECTION, and it is against my own earlier claim: the idle-flush commit read the field's "21 brains, no writes, a flush every ~35s, 1.26 cores" as caused by the flush path. That does not follow — this engine's cadence is write-driven (every trigger runs through noteWriteForPersistence, which only a committed write calls), so something was CALLING flush() on those brains and the caller is still unidentified. The clean-flush gate makes such a call free; it does not account for it. The code comments and the idle lane now say exactly that. Pins: tests/integration/flush-watcher-event-driven.test.ts — an idle writer makes at most one request-directory read in 8 seconds (the old poll made ~16), and a dropped request is still acked well inside the safety sweep.
152 lines
6.4 KiB
TypeScript
152 lines
6.4 KiB
TypeScript
/**
|
||
* @module tests/integration/idle-costs-nothing
|
||
* @description AN IDLE BRAIN DOES NO WORK.
|
||
*
|
||
* A flush used to re-persist state identical to what was already on disk —
|
||
* the provider flushes, the watermark stamps, the generation counter, the
|
||
* entity-tree stamp, roughly 28 writes — because `flush()` never asked whether
|
||
* anything had changed.
|
||
*
|
||
* The field observation that started this: a production process holding 21
|
||
* brains printed "All indexes flushed to disk in 216–601ms" per brain every
|
||
* ~35 seconds and idled at 1.26 cores, with no writes for ten minutes. This
|
||
* engine's cadence is WRITE-DRIVEN, so that observation is NOT explained by
|
||
* the cadence and is not claimed to be fixed here — what is fixed is that such
|
||
* a call now costs nothing. Who was calling flush() remains open.
|
||
*
|
||
* The laws pinned here:
|
||
* (a) the persistence cadence arms only on a write — a brain nobody writes
|
||
* to flushes zero times, however long it is left open;
|
||
* (b) a flush on a clean brain is O(1): no provider is called, nothing is
|
||
* written, and nothing is printed;
|
||
* (c) one write earns exactly one flush's worth of work, and no more.
|
||
*/
|
||
|
||
import { describe, it, expect, afterEach, vi } from 'vitest'
|
||
import { mkdtempSync, rmSync } from 'node:fs'
|
||
import { tmpdir } from 'node:os'
|
||
import { join } from 'node:path'
|
||
import { Brainy } from '../../src/brainy.js'
|
||
import { NounType } from '../../src/types/graphTypes.js'
|
||
|
||
/** Wait for any in-flight background flush, then let the idle timer settle. */
|
||
async function drainCadence(brain: Brainy): Promise<void> {
|
||
const inner = brain as unknown as { _persistBackgroundFlight: Promise<void> | null }
|
||
await new Promise((r) => setTimeout(r, 3_000))
|
||
await (inner._persistBackgroundFlight ?? Promise.resolve())
|
||
await new Promise((r) => setTimeout(r, 500))
|
||
}
|
||
|
||
/** How long an idle brain is watched. Longer than the 30s flush interval. */
|
||
const IDLE_WATCH_MS = 90_000
|
||
|
||
describe('an idle brain costs nothing', () => {
|
||
const dirs: string[] = []
|
||
const brains: Brainy[] = []
|
||
|
||
afterEach(async () => {
|
||
for (const b of brains.splice(0)) {
|
||
try { await b.close() } catch { /* already closed */ }
|
||
}
|
||
for (const d of dirs.splice(0)) {
|
||
try { rmSync(d, { recursive: true, force: true }) } catch { /* ignore */ }
|
||
}
|
||
vi.restoreAllMocks()
|
||
})
|
||
|
||
async function openBrain(): Promise<Brainy> {
|
||
const dir = mkdtempSync(join(tmpdir(), 'brainy-idle-'))
|
||
dirs.push(dir)
|
||
const brain = new Brainy({ requireSubtype: false, storage: { type: 'filesystem', path: dir } })
|
||
brains.push(brain)
|
||
await brain.init()
|
||
return brain
|
||
}
|
||
|
||
it('flushes zero times over 90 idle seconds, and prints nothing', async () => {
|
||
const brain = await openBrain()
|
||
// One write and one flush to reach a clean, settled state — then nothing.
|
||
await brain.add({ data: 'the only write this test performs', type: NounType.Concept })
|
||
await brain.flush()
|
||
|
||
const logged: string[] = []
|
||
const origLog = console.log
|
||
console.log = ((...a: unknown[]) => { logged.push(a.map(String).join(' ')) }) as typeof console.log
|
||
|
||
// Watch the providers directly: a flush that runs calls all of them.
|
||
const storage = (brain as unknown as { storage: { flushCounts: () => Promise<void> } }).storage
|
||
const metadataIndex = (brain as unknown as { metadataIndex: { flush: () => Promise<void> } }).metadataIndex
|
||
const graphIndex = (brain as unknown as { graphIndex: { flush: () => Promise<void> } }).graphIndex
|
||
const countsSpy = vi.spyOn(storage, 'flushCounts')
|
||
const metadataSpy = vi.spyOn(metadataIndex, 'flush')
|
||
const graphSpy = vi.spyOn(graphIndex, 'flush')
|
||
|
||
try {
|
||
await new Promise((r) => setTimeout(r, IDLE_WATCH_MS))
|
||
} finally {
|
||
console.log = origLog
|
||
}
|
||
|
||
// (a) + (b): nothing ran, nothing was said.
|
||
expect(logged.filter((l) => /All indexes flushed to disk/.test(l))).toEqual([])
|
||
expect(logged.filter((l) => /Flushing Brainy indexes/.test(l))).toEqual([])
|
||
expect(countsSpy).not.toHaveBeenCalled()
|
||
expect(metadataSpy).not.toHaveBeenCalled()
|
||
expect(graphSpy).not.toHaveBeenCalled()
|
||
}, 180_000)
|
||
|
||
it('an explicit flush over a clean brain calls no provider and prints nothing', async () => {
|
||
const brain = await openBrain()
|
||
await brain.add({ data: 'one write', type: NounType.Concept })
|
||
await brain.flush() // this one does the work
|
||
|
||
const storage = (brain as unknown as { storage: { flushCounts: () => Promise<void> } }).storage
|
||
const metadataIndex = (brain as unknown as { metadataIndex: { flush: () => Promise<void> } }).metadataIndex
|
||
const countsSpy = vi.spyOn(storage, 'flushCounts')
|
||
const metadataSpy = vi.spyOn(metadataIndex, 'flush')
|
||
const logged: string[] = []
|
||
const origLog = console.log
|
||
console.log = ((...a: unknown[]) => { logged.push(a.map(String).join(' ')) }) as typeof console.log
|
||
try {
|
||
await brain.flush() // ...and this one has nothing to do
|
||
await brain.flush()
|
||
await brain.flush()
|
||
} finally {
|
||
console.log = origLog
|
||
}
|
||
|
||
expect(countsSpy).not.toHaveBeenCalled()
|
||
expect(metadataSpy).not.toHaveBeenCalled()
|
||
expect(logged.filter((l) => /All indexes flushed to disk/.test(l))).toEqual([])
|
||
}, 120_000)
|
||
|
||
it('one write earns exactly one flush', async () => {
|
||
const brain = await openBrain()
|
||
await brain.add({ data: 'first', type: NounType.Concept })
|
||
await brain.flush()
|
||
// Settle: the first write also kicked a BACKGROUND flush, which is not
|
||
// awaited by design. Drain it before counting, or its provider calls land
|
||
// inside this test's window and are attributed to the write below.
|
||
await drainCadence(brain)
|
||
|
||
// Count the flushes that actually RAN. (Provider spies cannot answer this:
|
||
// the storage adapter's own count ledger is write-through, so a write calls
|
||
// flushCounts() on its own account, with no flush involved.)
|
||
const logged: string[] = []
|
||
const origLog = console.log
|
||
console.log = ((...a: unknown[]) => { logged.push(a.map(String).join(' ')) }) as typeof console.log
|
||
const ran = () => logged.filter((l) => /All indexes flushed to disk/.test(l)).length
|
||
try {
|
||
await brain.add({ data: 'second — this is the cause', type: NounType.Concept })
|
||
await brain.flush()
|
||
expect(ran()).toBe(1)
|
||
|
||
// No further cause, no further work.
|
||
await brain.flush()
|
||
await brain.flush()
|
||
expect(ran()).toBe(1)
|
||
} finally {
|
||
console.log = origLog
|
||
}
|
||
}, 120_000)
|
||
})
|