feat(open): the open names the STEP that cost the time, not just the phase

A phase that costs a minute and names only itself tells an operator where to
look but not what to look at. MEASURED on a real 14,056-noun / 72,679-verb
store, the warm reopen's generation-store phase cost 55,538 ms with nothing
inside it named — the fold was skipped (the close was clean), so the cost was
somewhere else entirely and the breakdown could not say where.

Six steps inside the open now report their own wall with their own cause when
they exceed the phase threshold: the generation store's open (manifest,
committed ranges, fact log, packed tier, crash replay), the entity-tree stamp
verification, the brain-format read, the pre-upgrade backup, the derived-index
gate, and the VFS init. Silent under the threshold, so a fast open says nothing
extra. Same always-visible channel as the phase lines.
This commit is contained in:
David Snelling 2026-08-28 11:02:57 -07:00
parent 4a67aa0fb9
commit 5a091ccad9

View file

@ -1163,6 +1163,23 @@ export class Brainy<T = any> implements BrainyInterface<T> {
) )
}, OPEN_HEARTBEAT_MS) }, OPEN_HEARTBEAT_MS)
if (typeof openHeartbeat.unref === 'function') openHeartbeat.unref() if (typeof openHeartbeat.unref === 'function') openHeartbeat.unref()
/**
* Narrate one STEP inside a phase when it turns out to be expensive.
* A phase that costs a minute and names only itself tells an operator
* where to look but not what to look at; this names the step. Silent
* under OPEN_PHASE_NARRATE_MS, so a fast open says nothing extra.
*/
const step = async <T>(name: string, cause: string, run: () => Promise<T>): Promise<T> => {
const startedAt = Date.now()
try {
return await run()
} finally {
const elapsed = Date.now() - startedAt
if (elapsed >= OPEN_PHASE_NARRATE_MS) {
prodLog.narrate(`[Brainy] open: step "${name}" took ${elapsed}ms — ${cause}`)
}
}
}
const markPhase = (name: string): void => { const markPhase = (name: string): void => {
const now = Date.now() const now = Date.now()
const elapsed = now - lastPhaseCheckpoint const elapsed = now - lastPhaseCheckpoint
@ -1263,9 +1280,12 @@ export class Brainy<T = any> implements BrainyInterface<T> {
// instances skip recovery (readers never write; the next writer // instances skip recovery (readers never write; the next writer
// repairs). // repairs).
this.generationStore = new GenerationStore(this.storage) this.generationStore = new GenerationStore(this.storage)
const generationOpenResult = await this.generationStore.open({ const generationOpenResult = await step(
readOnly: this.config.mode === 'reader' 'generation-store.open',
}) 'reading the generation manifest and committed ranges, opening the fact log and the ' +
'packed segment tier, and folding any crash-recovery replay',
() => this.generationStore.open({ readOnly: this.config.mode === 'reader' })
)
// The generation fact log is CANONICAL state, not a derived index — no // The generation fact log is CANONICAL state, not a derived index — no
// sweeper, GC, or blob-lifecycle path may ever delete under it. Declare // sweeper, GC, or blob-lifecycle path may ever delete under it. Declare
@ -1303,7 +1323,11 @@ export class Brainy<T = any> implements BrainyInterface<T> {
// rollup invariants against the log head + live counters. Loud on // rollup invariants against the log head + live counters. Loud on
// genuine incoherence (repairIndex heals), silent on absent/coherent, // genuine incoherence (repairIndex heals), silent on absent/coherent,
// benign-behind refreshes at the next flush. Never blocks open. // benign-behind refreshes at the next flush. Never blocks open.
await this.verifyEntityTreeStamp() await step(
'verify-entity-tree-stamp',
'comparing the entity tree\'s stamped generation and rollups against the store',
() => this.verifyEntityTreeStamp()
)
// 8.0 ⇄ native-provider version handshake: load the on-disk brain-format // 8.0 ⇄ native-provider version handshake: load the on-disk brain-format
// marker (`_system/brain-format.json`) into an in-memory field NOW — // marker (`_system/brain-format.json`) into an in-memory field NOW —
@ -1315,7 +1339,11 @@ export class Brainy<T = any> implements BrainyInterface<T> {
// them from the canonical records and then re-stamps the marker AFTER the // them from the canonical records and then re-stamps the marker AFTER the
// rebuild verifies (non-destructive: a crash mid-rebuild leaves the old / // rebuild verifies (non-destructive: a crash mid-rebuild leaves the old /
// absent marker, so the next open idempotently re-rebuilds). // absent marker, so the next open idempotently re-rebuilds).
this._brainFormat = await readBrainFormat(this.storage) this._brainFormat = await step(
'read-brain-format',
'reading the on-disk format marker that decides whether the derived indexes are stale',
() => readBrainFormat(this.storage)
)
this._indexEpochStale = this._indexEpochStale =
this._brainFormat === null || this._brainFormat.indexEpoch !== EXPECTED_INDEX_EPOCH this._brainFormat === null || this._brainFormat.indexEpoch !== EXPECTED_INDEX_EPOCH
@ -1326,7 +1354,11 @@ export class Brainy<T = any> implements BrainyInterface<T> {
// upgrade verifies + stamps; retained on failure. No-op for a reader, for // upgrade verifies + stamps; retained on failure. No-op for a reader, for
// non-filesystem storage, or for a brain with no persisted data. // non-filesystem storage, or for a brain with no persisted data.
if (this._indexEpochStale && this.config.migrationBackup && !this.isReadOnly) { if (this._indexEpochStale && this.config.migrationBackup && !this.isReadOnly) {
await this.createMigrationBackupIfNeeded() await step(
'pre-upgrade-backup',
'snapshotting the brain directory before a one-time format rebuild (migrationBackup)',
() => this.createMigrationBackupIfNeeded()
)
} }
// PHASE 2 of 5 — "generation-store open+fold": GenerationStore // PHASE 2 of 5 — "generation-store open+fold": GenerationStore
@ -1606,7 +1638,11 @@ export class Brainy<T = any> implements BrainyInterface<T> {
// init() returns — there is no more first-query lazy path, so the flag // init() returns — there is no more first-query lazy path, so the flag
// below (kept for getIndexStatus() API compatibility) simply flips true // below (kept for getIndexStatus() API compatibility) simply flips true
// once this open-time step has run. // once this open-time step has run.
await this.rebuildIndexesIfNeeded() await step(
'rebuild-indexes-if-needed',
'the derived-index gate: each family\'s readiness verdict, and any build it asks for',
() => this.rebuildIndexesIfNeeded()
)
this.lazyRebuildCompleted = true this.lazyRebuildCompleted = true
// Check for pending data migrations // Check for pending data migrations
@ -1679,7 +1715,11 @@ export class Brainy<T = any> implements BrainyInterface<T> {
// Initialize VFS: Ensure VFS is ready when accessed as property // Initialize VFS: Ensure VFS is ready when accessed as property
// This eliminates need for separate vfs.init() calls - zero additional complexity // This eliminates need for separate vfs.init() calls - zero additional complexity
this._vfs = new VirtualFileSystem(this) this._vfs = new VirtualFileSystem(this)
await this._vfs.init() await step(
'vfs.init',
'creating or adopting the VFS root and wiring the path resolver',
() => this._vfs!.init()
)
this._vfsInitialized = true // Mark VFS as fully initialized this._vfsInitialized = true // Mark VFS as fully initialized
// 8.0 MVCC: infrastructure bootstrap (VFS root, etc.) is now the // 8.0 MVCC: infrastructure bootstrap (VFS root, etc.) is now the