u

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<import('../provider.js').QueryResult>} */
   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 ?? {},
-    };
   }
 }
 

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);
+    }
+  }
+}

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<import('../provider.js').QueryResult>} */
   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),
-    };
   }
 }
 

src/store/runner.js

@@ -12,21 +12,28 @@
  * @returns {((sql: string, params?: object) => Promise<import('../providers/provider.js').QueryResult>) & { 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 };
     },
   };
 }