Skip to content

quereus-plugin-optimystic implements neither beginSchemaBatch nor endSchemaBatch: a cold apply schema makes ~190 raw-storage calls per object, ~90% of them redundant reads #8

Description

@risavian

Affected versions: @optimystic/quereus-plugin-optimystic@0.17.0 (latest published at time of
writing), against @quereus/quereus 4.4.1 and 4.5.0.

Summary

Quereus lets a virtual-table module opt into folding an entire APPLY SCHEMA migration into a
single substrate commit, via the optional beginSchemaBatch / endSchemaBatch module hooks
(packages/quereus/src/vtab/module.ts:473). Quereus's own @quereus/isolation implements them and
documents the consequence of not doing so, in isolation-module.ts:

A batching-capable underlying module folds the whole APPLY SCHEMA into a single substrate commit
by opening a batch here that its subsequent create/destroy/alter callbacks (which IsolationModule
forwards to the underlying) join. Without this forward the underlying is never reached and
silently falls back to per-DDL commits.

@optimystic/quereus-plugin-optimystic implements neither hook. Confirmed both by grep (0 hits
across the published package) and at runtime off db.schemaManager.allModules():

module          beginSchemaBatch   endSchemaBatch
memory          false              false
optimystic      false              false

So an APPLY SCHEMA against the optimystic vtab is executed as a series of independent DDL
statements with no batch context — runBatchedMigrationLoop awaits each
db._execWithinTransaction(ddl) in turn, and the module is never told they belong together.

The consequence turned out to be read amplification rather than commit count (measurements
below): without a batch-scoped context, each table's initialisation re-reads revision, block and
metadata state that the same APPLY SCHEMA already read moments earlier. Applying a real
schema of 54 tables + 13 indexes issues 13,025 raw-storage calls — 194 per created object —
of which 89.3% are provably redundant. This is the dominant cost of first-time schema creation,
and it is reproducible with the published packages and a synthetic schema (see below).

Measured impact

All figures below marked [repro] come from the script in the next section, which uses only
published packages and a synthetic schema — you can run it directly. Figures marked
[app schema] come from a real 92 KB / 54-table / 14-view application schema that is not
public; they are included only as corroboration and are not needed to see the problem.

Read amplification

[repro] One cold apply schema creating 54 tables + 13 indexes issues 13,025 IRawStorage
calls — 194.4 per created object — accounting for 76% of the apply
:

op calls total
listRevisions 1,676 83.5 ms
getMaterializedBlock 1,676 69.4 ms
getMetadata 5,974 12.1 ms
saveMaterializedBlock 303 7.1 ms
listPendingTransactions 1,720 2.7 ms
getPendingTransaction 920 2.7 ms
savePendingTransaction 178 2.1 ms
saveMetadata 222 0.7 ms
saveRevision 178 0.4 ms
promotePendingTransaction 178 0.4 ms
TOTAL 13,025 181.1 ms

Note only 178 saveRevision / promotePendingTransaction — roughly 178 transactions for 67
objects. The dominant cost is repeated READS, not commit count. Each object's initialisation
re-reads revision, block and metadata state that the same APPLY SCHEMA already read.

calls / object is ~constant as the schema scales (194.4 at 54 tables, 181.8 at 10), so total cost
is ~linear in object count.

Confirmed win from implementing the hooks

[repro] Prototyping a batch-scoped read context — memoising those reads for the duration of one
APPLY SCHEMA, invalidating on write:

baseline with batch read context
apply wall time ~186–213 ms ~110–125 ms
speedup (median of 5) — 1.63x (range 1.55–1.91x)
raw-storage time 181.1 ms 47.6 ms
read cache hits / misses — 10,677 / 1,286

89.3% of the reads a cold apply performs are redundant. The elided work is provably
unnecessary rather than merely cacheable: both runs produce an identical catalog (all 54 tables,
name + column-count fingerprint) and an identical successful write/read round-trip
(write+read OK (Amount=7)).

[app schema] The same experiment on the real 92 KB schema: 14,447 storage calls (~198/object,
68% of the apply), 11,913 / 1,400 cache hits/misses (89.5% redundant), 1.83x median speedup.

Cost relative to other substrates

[app schema] Identical schema and identical 88 generated statements, local transactor with
MemoryRawStorage (no libp2p, no disk):

substrate total apply per statement
quereus built-in in-memory vtab 24 ms 0.3 ms
real LevelDB via @quereus/plugin-leveldb ~60 ms 0.7 ms
optimystic vtab ~300–590 ms ~4–7 ms

Why each read is expensive

[app schema] CPU profile of the apply window:

self time share
structuredClone (V8 builtin) 100.6 ms 27.7%
decodeJson (@optimystic/db-p2p) 87.0 ms 23.9%
rangeRevisions (db-p2p) 12.1 ms 3.3%
encodeJson (db-p2p) 7.1 ms 2.0%

By package: @optimystic/db-p2p 37.1%, node internals 38.7%, @quereus/quereus 16.4%,
@optimystic/db-core 5.6%. Every redundant read pays a JSON decode plus a structuredClone.

This is much worse on React Native/Hermes. structuredClone is not native there — it is
polyfilled in JS (e.g. @ungap/structured-clone) — and Hermes has no JIT. A path hit ~1,700+
times per create, paying a JS deep-clone plus a JS JSON decode each time, is the most plausible
explanation for a multi-second schema creation on device. Not measured on device — stated as a
hypothesis, not a result.

Reproduction

Self-contained — published packages, synthetic schema, no external files. Applies to main with
tables + indexes only, deliberately, so this stays independent of quereus's separate
non-main-schema view/assertion defect.

npm init -y && npm pkg set type=module
npm i @quereus/quereus@4.5.0 @optimystic/quereus-plugin-optimystic@0.17.0 @optimystic/db-p2p@0.17.0
node repro.mjs               # 54 tables + 13 indexes
TABLES=10 INDEXES=3 node repro.mjs

The script instruments IRawStorage, runs the apply once as-is, then runs it again with a
batch-scoped read context prototyped at the storage seam, and checks the two runs produce the
same catalog and a working write/read round-trip.

repro.mjs
// Self-contained reproduction for Optimystic issue #8.
//
//   `quereus-plugin-optimystic` implements neither `beginSchemaBatch` nor `endSchemaBatch`.
//   A cold `apply schema` makes ~200 IRawStorage calls per created object, ~90% of which are
//   redundant reads within that same apply.
//
// Published packages only, synthetic schema, no external files:
//
//   npm init -y && npm pkg set type=module
//   npm i @quereus/quereus@4.5.0 @optimystic/quereus-plugin-optimystic@0.17.0 @optimystic/db-p2p@0.17.0
//   node repro.mjs                # default 54 tables / 13 indexes
//   TABLES=10 node repro.mjs      # scale it — cost is ~linear in object count
//
// Applies to `main` with tables+indexes only, deliberately: that keeps this focused on the
// optimystic module and avoids quereus's separate non-main-schema view/assertion defect.

import { Database, registerPlugin } from '@quereus/quereus';
import optimysticPlugin from '@optimystic/quereus-plugin-optimystic/plugin';
import { MemoryRawStorage } from '@optimystic/db-p2p';

const TABLES = Number(process.env.TABLES ?? 54);
const INDEXES = Number(process.env.INDEXES ?? 13);

// ---------------------------------------------------------------------------
// synthetic schema of roughly the shape a real app schema has
// ---------------------------------------------------------------------------
function buildSchema(tables, indexes) {
	const parts = [];
	for (let i = 0; i < tables; i++) {
		parts.push(`
  table T${i} (
    Id text,
    Name text,
    Amount integer,
    CreatedAt datetime,
    primary key (Id),
    constraint T${i}NameNotEmpty check (Name is null or Name <> '')
  );`);
	}
	for (let i = 0; i < indexes; i++) {
		parts.push(`\n  index T${i}ByName on T${i} (Name);`);
	}
	return parts.join('');
}

const DDL = buildSchema(TABLES, INDEXES);
const WRAPPED = `declare schema main {${DDL}\n}\napply schema main;`;

// ---------------------------------------------------------------------------
// IRawStorage instrumentation
//
// NOTE: walk the WHOLE prototype chain. MemoryRawStorage's own prototype carries only
// `constructor`; the storage methods live one level further up. A single
// Object.getPrototypeOf() instruments nothing and reports a misleading "0 calls".
// Also preserve async-generator-ness — several methods are AsyncGeneratorFunctions and
// callers do `yield* storage.listRevisions(...)`.
// ---------------------------------------------------------------------------
function methodNames(obj) {
	const names = new Set();
	for (let p = Object.getPrototypeOf(obj); p && p !== Object.prototype; p = Object.getPrototypeOf(p)) {
		for (const n of Object.getOwnPropertyNames(p)) if (n !== 'constructor') names.add(n);
	}
	for (const n of Object.keys(obj)) names.add(n);
	return [...names].filter((n) => typeof obj[n] === 'function');
}

function instrument(storage) {
	const stats = new Map();
	const bump = (name, t) => {
		const s = stats.get(name) ?? { calls: 0, totalMs: 0 };
		s.calls++;
		s.totalMs += performance.now() - t;
		stats.set(name, s);
	};
	for (const name of methodNames(storage)) {
		const real = storage[name];
		const bound = real.bind(storage);
		const kind = real.constructor?.name;
		if (kind === 'AsyncGeneratorFunction') {
			storage[name] = async function* (...a) {
				const t = performance.now();
				try { yield* bound(...a); } finally { bump(name, t); }
			};
		} else {
			storage[name] = (...a) => {
				const t = performance.now();
				const out = bound(...a);
				if (out && typeof out.then === 'function') return out.finally(() => bump(name, t));
				bump(name, t);
				return out;
			};
		}
	}
	return stats;
}

// ---------------------------------------------------------------------------
// The proposed mechanism, prototyped at the IRawStorage seam: while a schema batch is
// open, memoise reads and invalidate them on the corresponding write. Outside a batch it
// is a pass-through, mirroring the beginSchemaBatch contract.
//
// This is a DEMONSTRATION of the available win, not a proposed patch — a real fix belongs
// inside the module (one transaction + one read context for the whole APPLY SCHEMA).
// ---------------------------------------------------------------------------
const READS = {
	getMetadata: (a) => `md:${a[0]}`,
	listRevisions: (a) => `rev:${a[0]}:${JSON.stringify(a.slice(1))}`,
	getMaterializedBlock: (a) => `mb:${a[0]}:${JSON.stringify(a.slice(1))}`,
	getPendingTransaction: (a) => `pt:${a[0]}:${JSON.stringify(a.slice(1))}`,
	listPendingTransactions: (a) => `lpt:${a[0]}:${JSON.stringify(a.slice(1))}`,
};
const WRITES = {
	saveMetadata: ['md', 'rev', 'mb'],
	saveRevision: ['rev', 'mb'],
	saveMaterializedBlock: ['mb'],
	savePendingTransaction: ['pt', 'lpt'],
	deletePendingTransaction: ['pt', 'lpt'],
	promotePendingTransaction: ['md', 'rev', 'mb', 'pt', 'lpt'],
};

function withBatchReadContext(storage) {
	let open = false;
	const cache = new Map();
	const counters = { hits: 0, misses: 0 };

	const invalidate = (blockId, namespaces) => {
		for (const key of [...cache.keys()]) {
			const [ns, id] = key.split(':');
			if (namespaces.includes(ns) && (id === String(blockId) || blockId === undefined)) cache.delete(key);
		}
	};

	for (const [name, keyOf] of Object.entries(READS)) {
		const real = storage[name];
		if (typeof real !== 'function') continue;
		const bound = real.bind(storage);
		if (real.constructor?.name === 'AsyncGeneratorFunction') {
			storage[name] = async function* (...a) {
				if (!open) { yield* bound(...a); return; }
				const k = keyOf(a);
				let arr = cache.get(k);
				if (arr === undefined) {
					counters.misses++;
					arr = [];
					for await (const x of bound(...a)) arr.push(x);
					cache.set(k, arr);
				} else counters.hits++;
				yield* arr;
			};
		} else {
			storage[name] = async (...a) => {
				if (!open) return bound(...a);
				const k = keyOf(a);
				if (cache.has(k)) { counters.hits++; return cache.get(k); }
				counters.misses++;
				const v = await bound(...a);
				cache.set(k, v);
				return v;
			};
		}
	}
	for (const [name, dirties] of Object.entries(WRITES)) {
		const real = storage[name];
		if (typeof real !== 'function') continue;
		const bound = real.bind(storage);
		storage[name] = async (...a) => {
			const r = await bound(...a);
			if (open) invalidate(a[0], dirties);
			return r;
		};
	}
	return {
		counters,
		begin() { open = true; cache.clear(); },
		end() { open = false; cache.clear(); },
	};
}

// ---------------------------------------------------------------------------
async function run({ batched }) {
	const storage = new MemoryRawStorage();
	const gate = withBatchReadContext(storage);
	const stats = instrument(storage);

	const db = new Database();
	const networkName = `repro-${batched ? 'batched' : 'baseline'}`;
	const result = optimysticPlugin(db, {
		default_transactor: 'local',
		default_key_network: 'libp2p',
		default_network_name: networkName,
		enable_cache: true,
		rawStorageFactory: () => storage,
	});
	for (const v of result.vtables ?? []) db.registerModule(v.name, v.module, v.auxData);
	for (const f of result.functions ?? []) db.registerFunction(f.schema);
	for (const c of result.collations ?? []) db.registerCollation(c.name, c.func, c.normalizer);

	db.setDefaultVtabName('optimystic');
	db.setDefaultVtabArgs({ networkName, transactor: 'local', keyNetwork: 'libp2p' });
	await result.hydrate(db);

	if (batched) gate.begin();
	const t0 = performance.now();
	await db.exec(WRAPPED);
	const applyMs = performance.now() - t0;
	if (batched) gate.end();

	// correctness: identical catalog + a working write/read round-trip
	const schema = db.schemaManager.getSchema('main');
	const names = [...(schema?.tables?.keys?.() ?? [])].filter((n) => /^t\d+$/i.test(n)).sort();
	const fingerprint = names.map((n) => `${n}:${schema.tables.get(n)?.columns?.length ?? '?'}`).join(',');
	let roundTrip;
	try {
		await db.exec(`insert into T0 (Id, Name, Amount, CreatedAt) values ('a', 'alice', 7, '2026-01-01T00:00:00')`);
		const row = await db.get(`select Amount from T0 where Id = 'a'`);
		roundTrip = `write+read OK (Amount=${row?.Amount})`;
	} catch (e) {
		roundTrip = 'FAILED: ' + String(e?.message ?? e).split('\n')[0].slice(0, 70);
	}

	try { await db.close(); } catch { /* ignore */ }
	return { applyMs, stats, counters: gate.counters, tableCount: names.length, fingerprint, roundTrip };
}

const fmt = (x) => `${x.toFixed(1)}ms`;

console.log('=== Optimystic #8 repro: quereus 4.5.0 + quereus-plugin-optimystic 0.17.0 ===');
console.log(`schema: ${TABLES} tables + ${INDEXES} indexes, transactor=local, MemoryRawStorage, no libp2p`);
console.log(`node ${process.version} ${process.platform}/${process.arch}\n`);

// 1. the gap itself
{
	const db = new Database();
	const r = optimysticPlugin(db, {
		default_transactor: 'local', default_key_network: 'libp2p',
		default_network_name: 'hookcheck', enable_cache: true,
		rawStorageFactory: () => new MemoryRawStorage(),
	});
	for (const v of r.vtables ?? []) db.registerModule(v.name, v.module, v.auxData);
	const mod = (r.vtables ?? []).find((v) => v.name === 'optimystic')?.module;
	console.log('hook presence on the optimystic module:');
	console.log(`  beginSchemaBatch : ${typeof mod?.beginSchemaBatch}`);
	console.log(`  endSchemaBatch   : ${typeof mod?.endSchemaBatch}`);
	try { await db.close(); } catch { /* ignore */ }
}

const base = await run({ batched: false });

console.log('\n--- BASELINE raw-storage traffic for one cold apply ---');
const rows = [...base.stats.entries()].sort((a, b) => b[1].totalMs - a[1].totalMs).filter(([, s]) => s.calls);
const totalCalls = rows.reduce((a, [, s]) => a + s.calls, 0);
const totalMs = rows.reduce((a, [, s]) => a + s.totalMs, 0);
console.log(`${'op'.padEnd(28)}${'calls'.padStart(8)}${'total'.padStart(11)}`);
for (const [n, s] of rows) console.log(`${n.padEnd(28)}${String(s.calls).padStart(8)}${fmt(s.totalMs).padStart(11)}`);
console.log(`${'TOTAL'.padEnd(28)}${String(totalCalls).padStart(8)}${fmt(totalMs).padStart(11)}`);
console.log(`\napply wall time        : ${fmt(base.applyMs)}`);
console.log(`raw storage share      : ${((totalMs / base.applyMs) * 100).toFixed(1)}%`);
console.log(`objects created        : ${TABLES + INDEXES}`);
console.log(`storage calls / object : ${(totalCalls / (TABLES + INDEXES)).toFixed(1)}`);

const proto = await run({ batched: true });
const protoCalls = [...proto.stats.values()].reduce((a, s) => a + s.calls, 0);
const protoMs = [...proto.stats.values()].reduce((a, s) => a + s.totalMs, 0);
const hits = proto.counters.hits, misses = proto.counters.misses;

console.log('\n--- WITH a batch-scoped read context ---');
console.log(`apply wall time        : ${fmt(proto.applyMs)}`);
console.log(`raw storage time       : ${fmt(protoMs)}  (baseline ${fmt(totalMs)})`);
console.log(`read cache hits/misses : ${hits} / ${misses}  => ${((hits / (hits + misses)) * 100).toFixed(1)}% of reads redundant`);

console.log('\n=== result ===');
console.log(`  speedup        : ${(base.applyMs / proto.applyMs).toFixed(2)}x  (${fmt(base.applyMs)} -> ${fmt(proto.applyMs)})`);
console.log(`  tables created : ${base.tableCount} vs ${proto.tableCount}`);
console.log(`  catalog match  : ${base.fingerprint === proto.fingerprint ? 'IDENTICAL' : 'MISMATCH'}`);
console.log(`  round-trip     : "${base.roundTrip}" vs "${proto.roundTrip}" ${base.roundTrip === proto.roundTrip ? '(identical)' : '(MISMATCH)'}`);

Output (@quereus/quereus@4.5.0 + @optimystic/quereus-plugin-optimystic@0.17.0, node 24, linux/arm64):

=== Optimystic #8 repro: quereus 4.5.0 + quereus-plugin-optimystic 0.17.0 ===
schema: 54 tables + 13 indexes, transactor=local, MemoryRawStorage, no libp2p
node v24.15.0 linux/arm64

hook presence on the optimystic module:
  beginSchemaBatch : undefined
  endSchemaBatch   : undefined

--- BASELINE raw-storage traffic for one cold apply ---
op                             calls      total
listRevisions                   1692     74.7ms
getMaterializedBlock            1692     60.5ms
getMetadata                     6043     11.4ms
saveMaterializedBlock            308      6.0ms
getPendingTransaction            930      2.5ms
listPendingTransactions         1739      2.4ms
savePendingTransaction           183      2.1ms
saveMetadata                     230      0.5ms
promotePendingTransaction        183      0.4ms
saveRevision                     183      0.3ms
TOTAL                          13183    161.0ms

apply wall time        : 232.8ms
raw storage share      : 69.2%
objects created        : 67
storage calls / object : 196.8

--- WITH a batch-scoped read context ---
apply wall time        : 127.1ms
raw storage time       : 54.1ms  (baseline 161.0ms)
read cache hits/misses : 10677 / 1286  => 89.3% of reads redundant

=== result ===
  speedup        : 1.83x  (232.8ms -> 127.1ms)
  tables created : 54 vs 54
  catalog match  : IDENTICAL
  round-trip     : "write+read OK (Amount=7)" vs "write+read OK (Amount=7)" (identical)

Speedup over 5 consecutive runs: 1.69 / 1.55 / 1.57 / 1.63 / 1.91 -> median 1.63x.

calls / object stays roughly constant as the schema scales (194.4 at 54 tables, 181.8 at
10 tables, with 87.8% of reads redundant at the smaller size), so the cost is ~linear in object
count — consistent with per-object read amplification rather than a fixed startup cost.

Root cause

@optimystic/quereus-plugin-optimystic@0.17.0's virtual-table module object defines no
beginSchemaBatch / endSchemaBatch. Quereus's beginSchemaBatchAll skips modules without the
hook (packages/quereus/src/runtime/emit/schema-declarative.ts), so the module never learns that a
batch of DDL is in flight — it has no scope in which to reuse a transaction or cache a read.

The plugin's own source already documents the adjacent case, at src/optimystic-module.ts:193:

every cold-start connect() after hydrate() re-writes a byte-identical schema and re-reads it
back — one transaction per table+index, which dominates post-hydrate cold-start time

That short-circuit only fires when a schema is already persisted, so it helps a warm reopen but
misses every object on a cold create — which is exactly the case measured here.

Note this also affects @quereus/store's StoreModule, which likewise does not implement the
hooks — so createIsolatedStoreModule's IsolationModule (which does implement them, as a pure
delegate to underlying) forwards into a dead end. That half is a quereus-side gap; this issue is
about the optimystic module.

Suggested fix

Implement the two hooks on the optimystic vtab module, and use them to establish a
batch-scoped read context (not merely a shared write transaction — the measurements above
show reads are the cost):

async beginSchemaBatch(db, schemaName) {
  // open ONE transaction for the whole APPLY SCHEMA, and a per-batch read context that
  // memoises revision / materialized-block / metadata lookups
},
async endSchemaBatch(db, schemaName, error) {
  // commit once on success; discard on failure; drop the read context either way
}

Contract points worth honouring, per quereus's docs on the hooks:

  • endSchemaBatch fires exactly once per successful beginSchemaBatch, on both the success
    and failure paths (error is set on failure).
  • A module that owns no tables in schemaName should treat both as no-ops.
  • Subsequent create/destroy/alter callbacks during the loop join the open batch.

Two follow-ups worth considering independently of the hooks, since batching only hides them:

  1. ~198 raw-storage calls per created object looks high on its own merits. A single
    CREATE TABLE re-reading revision and block state ~25 times suggests missing memoisation
    inside table initialisation regardless of any batch.
  2. structuredClone on every decode is a heavy default for a storage layer, and is
    pathological on runtimes where it is polyfilled (React Native/Hermes). If the clone is
    defensive copying, consider making it opt-in or using a cheaper structural copy for
    internally-owned values.

Severity

High for first-time schema creation on the optimystic substrate, and disproportionately so on
React Native/Hermes where structuredClone is polyfilled in JS. It does not affect steady-state
reads/writes, and it does not affect warm reopen: composeStrand's
hydrate-before-apply step means a re-attach diffs against a hydrated catalog, emits zero DDL, and
costs ~30 ms instead of ~430 ms (a 92.6% saving, measured). So the cost lands entirely on the
first apply per store — which is exactly the user-visible "create" action.

Unmeasured

Per-commit latency on a real distributed/networked transactor, on real LevelDB raw storage, and
under Hermes were not measured (no Android device available on the test host). The commit count
and the ~10× in-memory ratio are measured facts; the absolute on-device figure is not.

Side observation (separate issue material)

On the @quereus/plugin-leveldb path, closing the database logs
[StoreModule] Failed to persist catalog DDL after schema change: Database failed to open. It
reproduces in an uninstrumented control, so it is pre-existing and not caused by the harness. That
belongs to quereus/@quereus/store, not Optimystic, but it means catalog DDL persistence is
failing silently on that path.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions