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.
2026-08-28 10:44:38 -07:00
/ * *
* @module tests / integration / idle - costs - nothing
* @description AN IDLE BRAIN DOES NO WORK .
*
perf(idle): the flush-request watch is event-driven; the heartbeat is observability
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. In a process holding many stores that is tens of 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 — two orders of magnitude fewer reads than
the poll made), 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
a reported idle-CPU observation (many stores, no writes, a flush every ~35s,
over a core burned) 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.
2026-08-28 11:25:47 -07:00
* 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 .
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.
2026-08-28 10:44:38 -07:00
*
* 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 )
} )