Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 3 additions & 1 deletion packages/analyze-query/src/bin-analyze.ts
Original file line number Diff line number Diff line change
Expand Up @@ -375,7 +375,9 @@ colorConsole.log(
);

colorConsole.log(styleText(['blue', 'bold'], '\n\n=== Query Plans: ===\n'));
const plans = explainQueries(debug.getVendedRowCounts() ?? {}, db);
const fallbackPlans = explainQueries(debug.getVendedRowCounts() ?? {}, db);
const capturedPlans = debug.getSQLitePlans();
const plans: Record<string, string[]> = {...fallbackPlans, ...capturedPlans};
for (const [query, plan] of Object.entries(plans)) {
colorConsole.log(styleText('bold', 'query'), query);
colorConsole.log(plan.map((row, i) => colorPlanRow(row, i)).join('\n'));
Expand Down
5 changes: 5 additions & 0 deletions packages/analyze-query/src/run-ast.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -109,6 +109,7 @@ test('runAst always returns vendedRowCounts regardless of vendedRows option', as
},
},
"readRows": undefined,
"sqlitePlans": {},
"start": 1004,
"syncedRowCount": 0,
"syncedRows": undefined,
Expand Down Expand Up @@ -158,6 +159,7 @@ test('runAst always returns vendedRowCounts regardless of vendedRows option', as
],
},
},
"sqlitePlans": {},
"start": 1018,
"syncedRowCount": 0,
"syncedRows": undefined,
Expand Down Expand Up @@ -194,6 +196,7 @@ test('runAst always returns vendedRowCounts regardless of vendedRows option', as
},
},
"readRows": undefined,
"sqlitePlans": {},
"start": 1032,
"syncedRowCount": 0,
"syncedRows": undefined,
Expand Down Expand Up @@ -237,6 +240,7 @@ test('runAst returns empty object for vendedRowCounts when no debug tracking', a
"readRowCount": 0,
"readRowCountsByQuery": {},
"readRows": undefined,
"sqlitePlans": {},
"start": 1004,
"syncedRowCount": 0,
"syncedRows": undefined,
Expand Down Expand Up @@ -284,6 +288,7 @@ test('runAst basic structure and functionality', async () => {
},
},
"readRows": undefined,
"sqlitePlans": {},
"start": 1004,
"syncedRowCount": 0,
"syncedRows": undefined,
Expand Down
12 changes: 11 additions & 1 deletion packages/zero-cache/src/services/analyze.ts
Original file line number Diff line number Diff line change
Expand Up @@ -106,7 +106,17 @@ export async function analyzeQuery(
yieldProcess,
);

result.sqlitePlans = explainQueries(result.readRowCountsByQuery ?? {}, db);
// Fill in plans for any queries SQLite did not actually execute (and thus
// did not populate scanStatus EXPLAIN for) using the substituted-binding
// fallback. Plans captured at execution time use the real bindings and win.
const fallback = explainQueries(result.readRowCountsByQuery ?? {}, db);
const captured = result.sqlitePlans ?? {};
for (const [query, plan] of Object.entries(fallback)) {
if (!captured[query]) {
captured[query] = plan;
}
}
result.sqlitePlans = captured;

if (planDebugger) {
result.joinPlans = serializePlanDebugEvents(planDebugger.events);
Expand Down
1 change: 1 addition & 0 deletions packages/zero-cache/src/services/run-ast.ts
Original file line number Diff line number Diff line change
Expand Up @@ -187,6 +187,7 @@ export async function runAst(
}
result.readRowCount = readRowCount;
result.dbScansByQuery = host.debug?.getNVisitCounts() ?? {};
result.sqlitePlans = host.debug?.getSQLitePlans() ?? {};

if (options.vendedRows) {
result.readRows = host.debug?.getVendedRows();
Expand Down
15 changes: 15 additions & 0 deletions packages/zql/src/builder/debug-delegate.ts
Original file line number Diff line number Diff line change
Expand Up @@ -14,13 +14,17 @@ export const runtimeDebugFlags = {
type SourceName = string;
type SQL = string;

export type SQLitePlans = Record<SQL, string[]>;

export interface DebugDelegate {
initQuery(table: SourceName, query: SQL): void;
rowVended(table: SourceName, query: SQL, row: Row): void;
getVendedRowCounts(): RowCountsBySource;
getVendedRows(): RowsBySource;
recordNVisit(table: SourceName, query: SQL, nvisit: number): void;
getNVisitCounts(): RowCountsBySource;
recordExplain(table: SourceName, query: SQL, plan: string[]): void;
getSQLitePlans(): SQLitePlans;
// clears all internal state
reset(): void;
}
Expand All @@ -29,11 +33,13 @@ export class Debug implements DebugDelegate {
#rowCountsBySource: RowCountsBySource;
#rowsBySource: RowsBySource;
#nvisitBySource: RowCountsBySource;
#plans: SQLitePlans;

constructor() {
this.#rowCountsBySource = {};
this.#rowsBySource = {};
this.#nvisitBySource = {};
this.#plans = {};
}

getVendedRowCounts(): RowCountsBySource {
Expand All @@ -48,6 +54,10 @@ export class Debug implements DebugDelegate {
return this.#nvisitBySource;
}

getSQLitePlans(): SQLitePlans {
return this.#plans;
}

initQuery(table: SourceName, query: SQL): void {
const {counts} = this.#getRowStats(table);
if (counts) {
Expand All @@ -61,6 +71,7 @@ export class Debug implements DebugDelegate {
this.#rowCountsBySource = {};
this.#rowsBySource = {};
this.#nvisitBySource = {};
this.#plans = {};
}

rowVended(table: SourceName, query: SQL, row: Row): void {
Expand All @@ -85,6 +96,10 @@ export class Debug implements DebugDelegate {
nvisitCounts[query] += nvisit;
}

recordExplain(_table: SourceName, query: SQL, plan: string[]): void {
this.#plans[query] = plan;
}

#getRowStats(source: SourceName) {
let counts: RowCountsByQuery | undefined;
let rows: RowsByQuery | undefined;
Expand Down
110 changes: 109 additions & 1 deletion packages/zqlite/src/table-source.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -5,7 +5,10 @@ import type {JSONValue} from '../../shared/src/json.ts';
import {createSilentLogContext} from '../../shared/src/logging-test-utils.ts';
import {must} from '../../shared/src/must.ts';
import type {Row, Value} from '../../zero-protocol/src/data.ts';
import type {DebugDelegate} from '../../zql/src/builder/debug-delegate.ts';
import {
Debug,
type DebugDelegate,
} from '../../zql/src/builder/debug-delegate.ts';
import {Catch} from '../../zql/src/ivm/catch.ts';
import {
makeAddChange,
Expand All @@ -21,6 +24,7 @@ import {
} from '../../zql/src/ivm/source.ts';
import {consume} from '../../zql/src/ivm/stream.ts';
import {Database, Statement} from './db.ts';
import {explainQueries} from './explain-queries.ts';
import {format} from './internal/sql.ts';
import {filtersToSQL} from './query-builder.ts';
import {
Expand Down Expand Up @@ -967,6 +971,108 @@ describe('fromSQLiteTypes error messages', () => {
});
});

test('debug.recordExplain captures the plan SQLite picked for the real bindings', () => {
const db = new Database(lc, ':memory:');
db.exec(`
CREATE TABLE users (id TEXT PRIMARY KEY, email TEXT);
CREATE UNIQUE INDEX idx_users_email ON users(email);
`);
db.prepare('INSERT INTO users (id, email) VALUES (?, ?)').run('1', 'a@b');
db.prepare('INSERT INTO users (id, email) VALUES (?, ?)').run('2', 'c@d');

const source = new TableSource(
lc,
testLogConfig,
db,
'users',
{id: {type: 'string'}, email: {type: 'string'}},
['id'],
);

const debug = new Debug();
const input = source.connect([['id', 'asc']], undefined, undefined, debug);

// Drain the iterator with a constraint that uses the email index.
[...input.fetch({constraint: {email: 'a@b'}})];

const plans = debug.getSQLitePlans();
const entries = Object.entries(plans);
expect(entries).toHaveLength(1);
const [sql, planLines] = entries[0];
expect(sql).toContain('"email" = ?');
// The captured plan reflects what SQLite actually ran with email='a@b'.
// SQLite picks the unique index here (SEARCH ... USING INDEX), not a SCAN.
expect(planLines.join('\n')).toMatch(/SEARCH .* USING (COVERING )?INDEX/);
});

test('captured plan diverges from substituted-literal plan when bindings affect plan choice', () => {
// Demonstrates the bug explainQueries has: substituting 'sdfse' for ?
// can cause SQLite to pick a more optimistic plan than the prepared
// statement actually uses.
//
// For `WHERE name LIKE ?` with PRAGMA case_sensitive_like = 1, SQLite
// cannot know at prepare time whether the bound value contains wildcards,
// so it conservatively picks SCAN. When the literal 'sdfse' is substituted,
// SQLite sees a wildcard-free pattern and rewrites it to an index range
// search — a plan that bears no resemblance to what actually runs.
const db = new Database(lc, ':memory:');
db.exec(`
PRAGMA case_sensitive_like = 1;
CREATE TABLE items (id TEXT PRIMARY KEY, name TEXT);
CREATE INDEX idx_items_name ON items(name);
`);
for (let i = 0; i < 50; i++) {
db.prepare('INSERT INTO items (id, name) VALUES (?, ?)').run(
String(i),
`name_${i}`,
);
}
db.exec('ANALYZE');

const source = new TableSource(
lc,
testLogConfig,
db,
'items',
{id: {type: 'string'}, name: {type: 'string'}},
['id'],
);

const likeFilter = {
type: 'simple',
left: {type: 'column', name: 'name'},
op: 'LIKE',
right: {type: 'literal', value: 'name_5%'},
} as const;

const debug = new Debug();
const input = source.connect([['id', 'asc']], likeFilter, undefined, debug);

[...input.fetch({})];

const plans = debug.getSQLitePlans();
const entries = Object.entries(plans);
expect(entries).toHaveLength(1);
const [sql, capturedPlan] = entries[0];
expect(sql).toContain('"name" LIKE ?');

// Captured plan reflects the real prepared statement: SCAN, since SQLite
// cannot prove the LIKE pattern is wildcard-free.
expect(capturedPlan.join('\n')).toMatch(/SCAN/);
expect(capturedPlan.join('\n')).not.toMatch(
/SEARCH .* USING (COVERING )?INDEX/,
);

// explainQueries substitutes 'sdfse' for ?, so SQLite sees a wildcard-free
// pattern and produces a range-scan plan that does not match reality.
const substitutedPlan = explainQueries({items: {[sql]: 1}}, db)[sql];
expect(substitutedPlan.join('\n')).toMatch(
/SEARCH .* USING (COVERING )?INDEX/,
);

expect(capturedPlan).not.toEqual(substitutedPlan);
});

test('SQLite iterator is closed when an error occurs before #mapFromSQLiteTypes is iterated', () => {
const db = new Database(lc, ':memory:');
db.exec('CREATE TABLE test (id TEXT PRIMARY KEY, val INTEGER);');
Expand Down Expand Up @@ -1012,6 +1118,8 @@ test('SQLite iterator is closed when an error occurs before #mapFromSQLiteTypes
getVendedRows: () => ({}),
recordNVisit() {},
getNVisitCounts: () => ({}),
recordExplain() {},
getSQLitePlans: () => ({}),
reset() {},
};

Expand Down
17 changes: 14 additions & 3 deletions packages/zqlite/src/table-source.ts
Original file line number Diff line number Diff line change
Expand Up @@ -342,21 +342,32 @@ export class TableSource implements Source {
rowIterator.return?.();
if (debug) {
let totalNvisit = 0;
let i = 0;
while (true) {
const planLines: string[] = [];
for (let i = 0; ; i++) {
const nvisit = cachedStatement.statement.scanStatus(
i++,
i,
SQLite3Database.SQLITE_SCANSTAT_NVISIT,
1,
);
if (nvisit === undefined) {
break;
}
totalNvisit += Number(nvisit);
const explain = cachedStatement.statement.scanStatus(
i,
SQLite3Database.SQLITE_SCANSTAT_EXPLAIN,
1,
);
if (typeof explain === 'string' && explain.length > 0) {
planLines.push(explain);
}
}
if (totalNvisit !== 0) {
debug.recordNVisit(this.#table, sqlAndBindings.text, totalNvisit);
}
if (planLines.length > 0) {
debug.recordExplain(this.#table, sqlAndBindings.text, planLines);
}
cachedStatement.statement.scanStatusReset();
}
this.#stmts.cache.return(cachedStatement);
Expand Down
Loading