perf(flush): an idle brain does no work — no periodic flush without a write
REPORTED from the field: a process holding many stores, with no writes for ten minutes, printed "All indexes flushed to disk in 216-601ms" per store every ~35 seconds and burned over a core at idle. Every one of those flushes re-persisted state identical to what was already on disk — the provider flushes, the watermark stamps, the generation counter, the entity-tree stamp — because flush() never asked whether anything had changed. - flush() over a clean brain is now O(1) and silent: a dirty witness is set by every committed write (both commit paths end at noteWriteForPersistence, and the deferred-embed worker lands through the single-op path) and cleared by a flush that runs. A write landing DURING a flush sets it again, so no write's work is ever skipped — it is done by the next flush. Set before the policy check, so a `'manual'` consumer's explicit flush is never a no-op it didn't ask for. - An explicit flush now tells the cadence it happened. It didn't, so the very next write saw "30s since the last flush" and kicked a background flush with nothing to do, and the idle timer fired two seconds later over writes the explicit flush had already persisted. - The graph adjacency index's auto-flush asks before it acts: two O(1) reads of the LSM MemTables, and a tick over a quiet index returns without calling into the trees at all. assessProviderHealth is NOT timer-driven — it is a synchronous O(1) read of a provider's own healthReport(), called on the read gate, so it costs nothing on an idle brain. No change needed there. Pins: tests/integration/idle-costs-nothing.test.ts — 90 idle seconds produce zero flushes, zero provider calls and zero log lines; three explicit flushes over a clean brain call no provider; one write earns exactly one flush.
This commit is contained in:
parent
0e45dfdaaa
commit
5024b01906
4 changed files with 208 additions and 0 deletions
147
tests/integration/idle-costs-nothing.test.ts
Normal file
147
tests/integration/idle-costs-nothing.test.ts
Normal file
|
|
@ -0,0 +1,147 @@
|
|||
/**
|
||||
* @module tests/integration/idle-costs-nothing
|
||||
* @description AN IDLE BRAIN DOES NO WORK.
|
||||
*
|
||||
* Measured on a production process holding 21 brains: with no writes for ten
|
||||
* minutes it printed "All indexes flushed to disk in 216–601ms" per brain
|
||||
* every ~35 seconds and idled at 1.26 cores. Every one of those flushes
|
||||
* re-persisted state identical to what was already on disk — the provider
|
||||
* flushes, the watermark stamps, the generation counter, the entity-tree
|
||||
* stamp — because `flush()` never asked whether anything had changed.
|
||||
*
|
||||
* 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)
|
||||
})
|
||||
Loading…
Add table
Add a link
Reference in a new issue