Add opt-in slow SQL and database diagnostics

.env.example

@@ -32,3 +32,5 @@ PLUTAINER_IMAGE=ghcr.io/ayymoss/plutainer:latest
 
 # Optional request/report timings and event-loop delay diagnostics.
 EC_PERF_LOG=false
+# Log statements taking at least this many milliseconds; 0 disables logging.
+EC_SLOW_SQL_MS=0

README.md

@@ -184,6 +184,13 @@ record an `ec:navigation` performance measure. `npm run benchmark:leaderboard`
 uses an isolated synthetic database; pass `-- --scenario all --baseline-ref <commit>`
 to compare full response parity and warm query timings with an earlier revision.
 
+Set `EC_SLOW_SQL_MS=20` to log runtime statements taking at least 20 ms; bound
+values and string literals are omitted. It is disabled by default. Before and
+after database changes, capture these timings under the same fleet load and run
+`npm run diagnostics:database -- /data/cherry.db` inside the controller to report
+the largest tables/indexes, database and WAL sizes, and free pages. This command
+opens an existing database read-only and does not run app migrations.
+
 Local controller
 metadata defaults to `./data/cherry.db`; use a separate test database when
 exercising enrollment. Production agent transport requires HTTPS.

package.json

@@ -12,6 +12,7 @@
     "test": "vitest run",
     "test:watch": "vitest",
     "benchmark:leaderboard": "node scripts/benchmark-leaderboard.mjs",
+    "diagnostics:database": "node scripts/database-diagnostics.mjs",
     "seed:fixture": "tsx scripts/seed-fixture.ts",
     "agent:package": "python3 agent/package_release.py",
     "prebuild": "npm run agent:package",

scripts/database-diagnostics.mjs

@@ -0,0 +1,16 @@
+import Database from 'better-sqlite3';
+import { statSync } from 'node:fs';
+
+const path = process.argv[2] ?? process.env.DB_PATH ?? './data/cherry.db';
+const db = new Database(path, { readonly: true, fileMustExist: true });
+try {
+    console.table(['', '-wal', '-shm'].map(suffix => {
+        try { return { file: path + suffix, bytes: statSync(path + suffix).size }; }
+        catch (error) { if (error.code !== 'ENOENT') throw error; return { file: path + suffix, bytes: 0 }; }
+    }));
+    console.table(db.prepare(`SELECT name, ROUND(SUM(pgsize)/1048576.0, 2) AS mib
+        FROM dbstat GROUP BY name ORDER BY SUM(pgsize) DESC LIMIT 20`).all());
+    console.table(['page_size', 'page_count', 'freelist_count', 'auto_vacuum'].map(pragma => ({
+        pragma, value: db.pragma(pragma, { simple: true })
+    })));
+} finally { db.close(); }

src/lib/server/db/index.ts

@@ -10,6 +10,7 @@ import { backfillLeaderboard } from '../fleet/leaderboard-ingest.js';
 import { initializeFleetSettings } from './fleet-settings.js';
 import { migrateServerHistory } from './server-history.js';
 import { migrateNativeInstances } from '../backends/schema.js';
+import { timeStatement } from './slow-statements.js';
 
 let _db: Database.Database | null = null;
 
@@ -414,11 +415,12 @@ export function db(): Database.Database {
     // Callers share statement options (e.g. raw()); use consistent options for
     // identical SQL and pass values to run/get/all rather than binding permanently.
     const statements = new Map<string, Database.Statement>();
+    const slowMs = Number(process.env.EC_SLOW_SQL_MS ?? 0);
     const prepare = handle.prepare.bind(handle);
     handle.prepare = ((sql: string) => {
         let statement = statements.get(sql);
         if (!statement) {
-            statement = prepare(sql);
+            statement = timeStatement(prepare(sql), sql, slowMs);
             statements.set(sql, statement);
         }
         return statement;

src/lib/server/db/slow-statements.ts

@@ -0,0 +1,19 @@
+import type Database from 'better-sqlite3';
+
+/** Log query shapes, never bound values or SQL string literals. Disabled by default. */
+export function timeStatement(statement: Database.Statement, sql: string, thresholdMs: number): Database.Statement {
+    if (!Number.isFinite(thresholdMs) || thresholdMs <= 0) return statement;
+    const shape = sql.replace(/'(?:''|[^'])*'/g, '?').replace(/\s+/g, ' ').trim().slice(0, 200);
+    for (const method of ['run', 'get', 'all'] as const) {
+        const original = statement[method].bind(statement) as (...args: unknown[]) => unknown;
+        Object.defineProperty(statement, method, { value: (...args: unknown[]) => {
+            const started = performance.now();
+            try { return original(...args); }
+            finally {
+                const ms = performance.now() - started;
+                if (ms >= thresholdMs) console.warn('[sql]', { ms: Math.round(ms), method, sql: shape });
+            }
+        } });
+    }
+    return statement;
+}

tests/unit/slow-statements.test.ts

@@ -0,0 +1,32 @@
+import Database from 'better-sqlite3';
+import { afterEach, expect, it, vi } from 'vitest';
+import { timeStatement } from '../../src/lib/server/db/slow-statements.js';
+
+afterEach(() => vi.restoreAllMocks());
+
+it('preserves results and errors, logs slow query shapes without values', () => {
+    const db = new Database(':memory:');
+    const log = vi.spyOn(console, 'warn').mockImplementation(() => {});
+    vi.spyOn(performance, 'now').mockReturnValueOnce(0).mockReturnValueOnce(21)
+        .mockReturnValueOnce(30).mockReturnValueOnce(31).mockReturnValueOnce(40).mockReturnValueOnce(62);
+    try {
+        const query = timeStatement(db.prepare("SELECT ? AS value, 'private''literal' AS literal"), "SELECT ? AS value, 'private''literal' AS literal", 20);
+        expect(query.get('secret')).toEqual({ value: 'secret', literal: "private'literal" });
+        expect(query.all('other')).toHaveLength(1);
+        expect(() => query.get()).toThrow();
+        expect(log).toHaveBeenCalledTimes(2);
+        expect(log.mock.calls[0]).toEqual(['[sql]', { ms: 21, method: 'get', sql: 'SELECT ? AS value, ? AS literal' }]);
+        expect(JSON.stringify(log.mock.calls)).not.toMatch(/secret|private|other/);
+    } finally { db.close(); }
+});
+
+it('does not wrap statements when disabled or invalid', () => {
+    const db = new Database(':memory:');
+    try {
+        const statement = db.prepare('SELECT 1');
+        const get = statement.get;
+        for (const threshold of [0, -1, NaN, Infinity]) {
+            expect(timeStatement(statement, 'SELECT 1', threshold).get).toBe(get);
+        }
+    } finally { db.close(); }
+});