diff --git a/.env.example b/.env.example index 7124076..f6f06a9 100644 --- a/.env.example +++ b/.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 diff --git a/README.md b/README.md index a0e8f83..91a059c 100644 --- a/README.md +++ b/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 ` 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. diff --git a/package.json b/package.json index e60ccd2..889dc27 100644 --- a/package.json +++ b/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", diff --git a/scripts/database-diagnostics.mjs b/scripts/database-diagnostics.mjs new file mode 100644 index 0000000..7b4559a --- /dev/null +++ b/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(); } diff --git a/src/lib/server/db/index.ts b/src/lib/server/db/index.ts index 9cfe614..8796ff8 100644 --- a/src/lib/server/db/index.ts +++ b/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(); + 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; diff --git a/src/lib/server/db/slow-statements.ts b/src/lib/server/db/slow-statements.ts new file mode 100644 index 0000000..f78c91f --- /dev/null +++ b/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; +} diff --git a/tests/unit/slow-statements.test.ts b/tests/unit/slow-statements.test.ts new file mode 100644 index 0000000..4416113 --- /dev/null +++ b/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(); } +});