diff --git a/src/providers/mssql/index.js b/src/providers/mssql/index.js index 29a4327..3ddea49 100644 --- a/src/providers/mssql/index.js +++ b/src/providers/mssql/index.js @@ -5,6 +5,7 @@ */ import sql from 'mssql'; +import { logSlowQuery } from '../provider.js'; function normalizeRows(result) { const recordset = result?.recordset ?? []; @@ -24,11 +25,16 @@ export class MssqlExecutor { /** @returns {Promise} */ async query(sql, params = {}) { - const req = this.#requestFactory(); - for (const [key, value] of Object.entries(params)) { - req.input(key, value); + const start = performance.now(); + try { + const req = this.#requestFactory(); + for (const [key, value] of Object.entries(params)) { + req.input(key, value); + } + return normalizeRows(await req.query(sql)); + } finally { + logSlowQuery(sql, performance.now() - start, params); } - return normalizeRows(await req.query(sql)); } /** @@ -37,22 +43,27 @@ export class MssqlExecutor { * (`getnextnumberwithprefixandpadding`). */ async exec(procName, { inputs = {}, outputs = [] } = {}) { - const req = this.#requestFactory(); - for (const [key, value] of Object.entries(inputs)) { - req.input(key, value); + const start = performance.now(); + try { + const req = this.#requestFactory(); + for (const [key, value] of Object.entries(inputs)) { + req.input(key, value); + } + for (const out of outputs) { + req.output(out); + } + const result = await req.execute(procName); + return { + rows: result.recordset ?? [], + rowsAffected: Array.isArray(result.rowsAffected) + ? result.rowsAffected.reduce((a, b) => a + b, 0) + : 0, + insertId: null, + outputs: result.output ?? {}, + }; + } finally { + logSlowQuery(`EXEC ${procName}`, performance.now() - start, inputs); } - for (const out of outputs) { - req.output(out); - } - const result = await req.execute(procName); - return { - rows: result.recordset ?? [], - rowsAffected: Array.isArray(result.rowsAffected) - ? result.rowsAffected.reduce((a, b) => a + b, 0) - : 0, - insertId: null, - outputs: result.output ?? {}, - }; } } diff --git a/src/providers/provider.js b/src/providers/provider.js index c4eb69d..86e6c4d 100644 --- a/src/providers/provider.js +++ b/src/providers/provider.js @@ -46,3 +46,22 @@ export function isForeignKeyConstraintError(err) { err?.code === 'SQLITE_CONSTRAINT_FOREIGNKEY' ); } + +export const SLOW_QUERY_THRESHOLD_MS = 20; + +/** + * Logs a SQL statement to the console if execution time exceeded SLOW_QUERY_THRESHOLD_MS (20ms). + * + * @param {string} sql + * @param {number} durationMs + * @param {object} [params] + */ +export function logSlowQuery(sql, durationMs, params = null) { + if (durationMs > SLOW_QUERY_THRESHOLD_MS) { + const timeStr = `${durationMs.toFixed(1)}ms`; + console.log(`[SQL >20ms] (${timeStr})\n${typeof sql === 'string' ? sql.trim() : sql}`); + if (params && Object.keys(params).length > 0) { + console.log('Params:', params); + } + } +} diff --git a/src/providers/sqlite3/index.js b/src/providers/sqlite3/index.js index 43a659f..0196406 100644 --- a/src/providers/sqlite3/index.js +++ b/src/providers/sqlite3/index.js @@ -6,6 +6,7 @@ */ import Database from 'better-sqlite3'; +import { logSlowQuery } from '../provider.js'; import { SCHEMA_SCRIPTS } from './schema.js'; function normalizeParamValue(value) { @@ -236,24 +237,29 @@ export class BetterSqlite3Executor { /** @returns {Promise} */ async query(sql, params = {}) { - const statement = this.db.prepare(sql); - const bindings = bindParams(params, sql); + const start = performance.now(); + try { + const statement = this.db.prepare(sql); + const bindings = bindParams(params, sql); - if (statement.reader) { - const rows = statement.all(bindings); + if (statement.reader) { + const rows = statement.all(bindings); + return { + rows, + rowsAffected: rows.length, + insertId: normalizeInsertId(rows[0]?.id), + }; + } + + const result = statement.run(bindings); return { - rows, - rowsAffected: rows.length, - insertId: normalizeInsertId(rows[0]?.id), + rows: [], + rowsAffected: result.changes, + insertId: normalizeInsertId(result.lastInsertRowid), }; + } finally { + logSlowQuery(sql, performance.now() - start, params); } - - const result = statement.run(bindings); - return { - rows: [], - rowsAffected: result.changes, - insertId: normalizeInsertId(result.lastInsertRowid), - }; } } diff --git a/src/store/runner.js b/src/store/runner.js index a85dd6a..248f140 100644 --- a/src/store/runner.js +++ b/src/store/runner.js @@ -12,21 +12,28 @@ * @returns {((sql: string, params?: object) => Promise) & { query: Function, dialect?: string }} */ +import { logSlowQuery } from '../providers/provider.js'; + /** Wraps a raw mssql pool/transaction in the provider query contract. */ function wrapMssql(target) { return { dialect: 'mssql', async query(sql, params = {}) { - const req = target.request(); - for (const [key, value] of Object.entries(params)) { - req.input(key, value); + const start = performance.now(); + try { + const req = target.request(); + for (const [key, value] of Object.entries(params)) { + req.input(key, value); + } + const result = await req.query(sql); + const rows = result.recordset ?? []; + const rowsAffected = Array.isArray(result.rowsAffected) + ? result.rowsAffected.reduce((a, b) => a + b, 0) + : 0; + return { rows, rowsAffected, insertId: null }; + } finally { + logSlowQuery(sql, performance.now() - start, params); } - const result = await req.query(sql); - const rows = result.recordset ?? []; - const rowsAffected = Array.isArray(result.rowsAffected) - ? result.rowsAffected.reduce((a, b) => a + b, 0) - : 0; - return { rows, rowsAffected, insertId: null }; }, }; }