From 8c7071eda72711aa6b844c03ffdf79c632861b2b Mon Sep 17 00:00:00 2001 From: Framma Williansyah Akbar Date: Wed, 30 Sep 2026 11:40:30 +0700 Subject: [PATCH] feat(infra): Automated database query execution time logging for slow query detection (#1365) --- backend/src/dal/index.js | 3 +- backend/src/dal/pg/pgClient.js | 4 +- backend/src/lib/slowQueryLogger.js | 147 ++++++++++++++++++++++ backend/src/lib/slowQueryLogger.test.js | 109 ++++++++++++++++ backend/src/services/sentryIntegration.js | 2 +- 5 files changed, 262 insertions(+), 3 deletions(-) create mode 100644 backend/src/lib/slowQueryLogger.js create mode 100644 backend/src/lib/slowQueryLogger.test.js diff --git a/backend/src/dal/index.js b/backend/src/dal/index.js index cc72c9d1..c7b124fb 100644 --- a/backend/src/dal/index.js +++ b/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); diff --git a/backend/src/dal/pg/pgClient.js b/backend/src/dal/pg/pgClient.js index 685e6f9b..4547c8c7 100644 --- a/backend/src/dal/pg/pgClient.js +++ b/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' })); } /** diff --git a/backend/src/lib/slowQueryLogger.js b/backend/src/lib/slowQueryLogger.js new file mode 100644 index 00000000..4b87ae67 --- /dev/null +++ b/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; +} diff --git a/backend/src/lib/slowQueryLogger.test.js b/backend/src/lib/slowQueryLogger.test.js new file mode 100644 index 00000000..0d7f50dc --- /dev/null +++ b/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); +}); diff --git a/backend/src/services/sentryIntegration.js b/backend/src/services/sentryIntegration.js index 78e42d7f..ac521b43 100644 --- a/backend/src/services/sentryIntegration.js +++ b/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;