feat(infra): add automated slow query execution time logging (#1365)

backend/src/dal/index.js

@@ -1,5 +1,6 @@
 import Database from 'better-sqlite3';
 import { runMigrations } from '../db/migrate.js';
+import { instrumentSqlite } from '../lib/slowQueryLogger.js';
 import { assertCampaignRepository } from './campaignRepository.js';
 import {
   createSqliteCampaignRepository,
@@ -55,7 +56,7 @@ export async function createDal({
   allowedCategories,
   allowlistRepository,
 } = {}) {
-  const db = new Database(dbPath);
+  const db = instrumentSqlite(new Database(dbPath));
   await runMigrations(db);
 
   const categories = allowedCategories ?? parseCategoriesConfig(process.env.TRIVELA_CATEGORIES);

backend/src/dal/pg/pgClient.js

@@ -1,4 +1,5 @@
 import pg from 'pg';
+import { createSlowQueryMonitor, instrumentPg } from '../../lib/slowQueryLogger.js';
 
 const { Pool } = pg;
 
@@ -14,11 +15,12 @@ export function createPool(connectionString) {
   if (!connectionString) {
     throw new Error('createPool requires a DATABASE_URL');
   }
-  return new Pool({
+  const pool = new Pool({
     connectionString,
     application_name: 'trivela-backend',
     max: Number(process.env.PG_POOL_MAX ?? 10),
   });
+  return instrumentPg(pool, createSlowQueryMonitor({ driver: 'postgres' }));
 }
 
 /**

backend/src/lib/slowQueryLogger.js

@@ -0,0 +1,147 @@
+/**
+ * Slow database query detection (#1365).
+ *
+ * Wraps better-sqlite3 and pg query paths, timing each execution. Queries over
+ * the threshold (default 200ms, SLOW_QUERY_THRESHOLD_MS) are reported to:
+ *   - Sentry (captureMessage, when SENTRY_DSN is configured)
+ *   - CloudWatch, via a CloudWatch Embedded Metric Format (EMF) line on stdout
+ *     which the CloudWatch agent / awslogs driver turns into a metric.
+ */
+
+import { log } from '../middleware/logger.js';
+import { captureMessage } from '../services/sentryIntegration.js';
+
+export const DEFAULT_SLOW_QUERY_THRESHOLD_MS = 200;
+const MAX_SQL_LENGTH = 500;
+
+export function getSlowQueryThresholdMs(env = process.env) {
+  const raw = env.SLOW_QUERY_THRESHOLD_MS;
+  if (raw === undefined || raw === '') return DEFAULT_SLOW_QUERY_THRESHOLD_MS;
+  const n = Number(raw);
+  return Number.isFinite(n) && n >= 0 ? n : DEFAULT_SLOW_QUERY_THRESHOLD_MS;
+}
+
+export function truncateSql(sql) {
+  const text = typeof sql === 'string' ? sql.replace(/\s+/g, ' ').trim() : String(sql ?? '');
+  return text.length > MAX_SQL_LENGTH ? `${text.slice(0, MAX_SQL_LENGTH)}…` : text;
+}
+
+/** CloudWatch EMF payload for a slow query. */
+export function buildCloudWatchMetric({ durationMs, driver, namespace, timestamp = Date.now() }) {
+  return {
+    _aws: {
+      Timestamp: timestamp,
+      CloudWatchMetrics: [
+        {
+          Namespace: namespace,
+          Dimensions: [['Driver']],
+          Metrics: [{ Name: 'SlowQueryDurationMs', Unit: 'Milliseconds' }],
+        },
+      ],
+    },
+    Driver: driver,
+    SlowQueryDurationMs: durationMs,
+  };
+}
+
+const defaultReporters = {
+  logger: log,
+  sentry: captureMessage,
+  cloudwatch: (payload) => process.stdout.write(`${JSON.stringify(payload)}\n`),
+};
+
+/**
+ * Create a slow query monitor.
+ * @param {{ thresholdMs?: number, driver?: string, reporters?: object, now?: () => number }} [opts]
+ */
+export function createSlowQueryMonitor({
+  thresholdMs = getSlowQueryThresholdMs(),
+  driver = 'sqlite',
+  reporters = {},
+  now = () => performance.now(),
+} = {}) {
+  const r = { ...defaultReporters, ...reporters };
+  const namespace = process.env.CLOUDWATCH_NAMESPACE || 'Trivela/Database';
+
+  function report(sql, durationMs) {
+    const rounded = Math.round(durationMs * 100) / 100;
+    const query = truncateSql(sql);
+    // Each sink is isolated so monitoring can never break a query.
+    try {
+      r.logger.warn({ query, durationMs: rounded, thresholdMs, driver }, '[db] slow query');
+    } catch { /* ignore */ }
+    try {
+      r.sentry(`Slow database query (${rounded}ms)`, 'warning', {
+        query,
+        durationMs: rounded,
+        thresholdMs,
+        driver,
+      });
+    } catch { /* ignore */ }
+    try {
+      r.cloudwatch(buildCloudWatchMetric({ durationMs: rounded, driver, namespace }));
+    } catch { /* ignore */ }
+  }
+
+  /** Time a sync function; report if slow. Errors are timed too and rethrown. */
+  function timeSync(sql, fn) {
+    const start = now();
+    try {
+      return fn();
+    } finally {
+      const d = now() - start;
+      if (d > thresholdMs) report(sql, d);
+    }
+  }
+
+  async function timeAsync(sql, fn) {
+    const start = now();
+    try {
+      return await fn();
+    } finally {
+      const d = now() - start;
+      if (d > thresholdMs) report(sql, d);
+    }
+  }
+
+  return { thresholdMs, report, timeSync, timeAsync };
+}
+
+const STATEMENT_METHODS = ['run', 'get', 'all', 'iterate'];
+
+/**
+ * Instrument a better-sqlite3 Database in place: prepare() statements and
+ * exec() are timed. Idempotent. Returns the same db.
+ */
+export function instrumentSqlite(db, monitor = createSlowQueryMonitor({ driver: 'sqlite' })) {
+  if (!db || db.__slowQueryInstrumented) return db;
+  const origPrepare = db.prepare.bind(db);
+  const origExec = db.exec.bind(db);
+
+  db.prepare = (sql) => {
+    const stmt = origPrepare(sql);
+    for (const method of STATEMENT_METHODS) {
+      if (typeof stmt[method] !== 'function') continue;
+      const orig = stmt[method].bind(stmt);
+      stmt[method] = (...args) => monitor.timeSync(sql, () => orig(...args));
+    }
+    return stmt;
+  };
+  db.exec = (sql) => monitor.timeSync(sql, () => origExec(sql));
+  Object.defineProperty(db, '__slowQueryInstrumented', { value: true });
+  return db;
+}
+
+/** Instrument a pg Pool/Client: query() is timed. Idempotent. */
+export function instrumentPg(pool, monitor = createSlowQueryMonitor({ driver: 'postgres' })) {
+  if (!pool || pool.__slowQueryInstrumented) return pool;
+  const orig = pool.query.bind(pool);
+  pool.query = (...args) => {
+    const first = args[0];
+    const sql = typeof first === 'string' ? first : first?.text;
+    const result = monitor.timeAsync(sql, () => Promise.resolve(orig(...args)));
+    return result;
+  };
+  Object.defineProperty(pool, '__slowQueryInstrumented', { value: true });
+  return pool;
+}

backend/src/lib/slowQueryLogger.test.js

@@ -0,0 +1,109 @@
+import { test } from 'node:test';
+import assert from 'node:assert/strict';
+import Database from 'better-sqlite3';
+import {
+  createSlowQueryMonitor,
+  getSlowQueryThresholdMs,
+  instrumentSqlite,
+  instrumentPg,
+  truncateSql,
+  buildCloudWatchMetric,
+} from './slowQueryLogger.js';
+
+function makeMonitor(clock, thresholdMs = 200) {
+  const calls = { logger: [], sentry: [], cloudwatch: [] };
+  const monitor = createSlowQueryMonitor({
+    thresholdMs,
+    now: () => clock.t,
+    reporters: {
+      logger: { warn: (...a) => calls.logger.push(a) },
+      sentry: (...a) => calls.sentry.push(a),
+      cloudwatch: (p) => calls.cloudwatch.push(p),
+    },
+  });
+  return { monitor, calls };
+}
+
+test('threshold defaults to 200 and honours env', () => {
+  assert.equal(getSlowQueryThresholdMs({}), 200);
+  assert.equal(getSlowQueryThresholdMs({ SLOW_QUERY_THRESHOLD_MS: '50' }), 50);
+  assert.equal(getSlowQueryThresholdMs({ SLOW_QUERY_THRESHOLD_MS: 'abc' }), 200);
+  assert.equal(getSlowQueryThresholdMs({ SLOW_QUERY_THRESHOLD_MS: '-1' }), 200);
+});
+
+test('fast queries are not reported; slow ones go to all sinks', () => {
+  const clock = { t: 0 };
+  const { monitor, calls } = makeMonitor(clock);
+  monitor.timeSync('SELECT 1', () => { clock.t += 200; });
+  assert.equal(calls.sentry.length, 0);
+  assert.equal(monitor.timeSync('SELECT 2', () => { clock.t += 250; return 'ok'; }), 'ok');
+  assert.equal(calls.logger.length, 1);
+  assert.equal(calls.sentry.length, 1);
+  assert.equal(calls.cloudwatch[0].SlowQueryDurationMs, 250);
+  assert.equal(calls.cloudwatch[0]._aws.CloudWatchMetrics[0].Metrics[0].Name, 'SlowQueryDurationMs');
+});
+
+test('slow failing query is reported and error rethrown', () => {
+  const clock = { t: 0 };
+  const { monitor, calls } = makeMonitor(clock);
+  assert.throws(() => monitor.timeSync('BAD', () => { clock.t += 300; throw new Error('boom'); }), /boom/);
+  assert.equal(calls.sentry.length, 1);
+});
+
+test('reporter failures never break the query', () => {
+  const clock = { t: 0 };
+  const monitor = createSlowQueryMonitor({
+    thresholdMs: 10,
+    now: () => clock.t,
+    reporters: {
+      logger: { warn: () => { throw new Error('x'); } },
+      sentry: () => { throw new Error('x'); },
+      cloudwatch: () => { throw new Error('x'); },
+    },
+  });
+  assert.equal(monitor.timeSync('q', () => { clock.t += 50; return 7; }), 7);
+});
+
+test('truncateSql collapses whitespace and caps length', () => {
+  assert.equal(truncateSql('SELECT  *\n FROM t'), 'SELECT * FROM t');
+  assert.ok(truncateSql('x'.repeat(1000)).length <= 501);
+});
+
+test('buildCloudWatchMetric produces EMF', () => {
+  const m = buildCloudWatchMetric({ durationMs: 5, driver: 'sqlite', namespace: 'NS', timestamp: 1 });
+  assert.equal(m._aws.CloudWatchMetrics[0].Namespace, 'NS');
+  assert.equal(m.Driver, 'sqlite');
+});
+
+test('instrumentSqlite times statements and exec, is idempotent', () => {
+  const clock = { t: 0 };
+  const { monitor, calls } = makeMonitor(clock, 0);
+  const db = new Database(':memory:');
+  instrumentSqlite(db, monitor);
+  instrumentSqlite(db, monitor);
+  db.exec('CREATE TABLE t (id INTEGER)');
+  const before = calls.sentry.length;
+  clock.t = 0;
+  const stmt = db.prepare('INSERT INTO t (id) VALUES (?)');
+  const tick = monitor.timeSync; // ensure clock advances between calls
+  monitor.timeSync = (sql, fn) => { clock.t += 1; return tick(sql, () => { const r = fn(); clock.t += 5; return r; }); };
+  stmt.run(1);
+  assert.equal(db.prepare('SELECT COUNT(*) AS c FROM t').get().c, 1);
+  assert.ok(calls.sentry.length > before);
+});
+
+test('instrumentPg times async queries and propagates results/errors', async () => {
+  const clock = { t: 0 };
+  const { monitor, calls } = makeMonitor(clock);
+  const pool = {
+    query: async (q) => {
+      clock.t += 400;
+      if (q === 'bad') throw new Error('pg fail');
+      return { rows: [1] };
+    },
+  };
+  instrumentPg(pool, monitor);
+  assert.deepEqual(await pool.query('SELECT 1'), { rows: [1] });
+  await assert.rejects(pool.query('bad'), /pg fail/);
+  assert.equal(calls.sentry.length, 2);
+});

backend/src/services/sentryIntegration.js

@@ -1,4 +1,4 @@
-import { logger } from '../lib/logger.js';
+import { log as logger } from '../middleware/logger.js';
 
 let sentryClient = null;