Fix review issues: partial index, middleware scope, add timing tests

- Change idx_financing_plans_active to partial index (WHERE active = true) to avoid useless B-tree index on low-cardinality boolean column - Scope timingMiddleware to /api routes only (was globally registered, which caused noise from static asset requests) - Add unit tests for timing middleware (5 tests covering: next() call, timing log format, SLOW warning threshold, fast-request path, status code) Nightshift-Task: perf-regression Nightshift-Ref: https://github.com/marcus/nightshift
Docs: update CLAUDE.md with perf tooling notes
2026-03-20 02:48:32 -04:00 · 2026-03-20 02:45:14 -04:00 · 2026-03-20 02:44:57 -04:00
8 changed files with 205 additions and 253 deletions
--- a/CLAUDE.md
+++ b/CLAUDE.md
@@ -94,3 +94,16 @@ The default route `/` renders the paycheck-centric main view (`client/src/pages/
 **Financing:** `GET/POST /api/financing`, `PUT/DELETE /api/financing/:id`, `PATCH /api/financing-payments/:id/paid`. Plans track a total amount, payoff due date, and `start_date`. Payment per period is auto-calculated as `(remaining balance) / (remaining periods)`. Split plans (`assigned_paycheck = null`) divide each period's payment across both paychecks. Plans auto-close when fully paid. Financing payments are included in the paycheck remaining balance. `start_date` prevents a plan from appearing on paycheck months before it was created — both virtual previews and `generate` respect this guard.

 **Migrations:** SQL files in `db/migrations/` are applied in filename order on server startup. Add new migrations as `00N_description.sql` — they run once and are tracked in the `migrations` table.
+
+## Performance Tooling
+
+**Timing middleware** (`server/src/middleware/timing.js`): Registered early in `app.js`. Logs every request's method, path, status code, and duration. Emits a `[SLOW]` warning for responses exceeding 200 ms.
+
+**Benchmark script** (`scripts/perf-benchmark.js`): Hits `GET /api/paychecks`, `GET /api/financing`, and `GET /api/summary/annual` five times each and reports min/mean/max latency. Exits non-zero if any mean exceeds the threshold (default 500 ms, override via `SLOW_THRESHOLD_MS` env var). Target server URL defaults to `http://localhost:3001` (override via `BENCHMARK_URL`).
+
+```bash
+cd server && npm run perf          # run against localhost:3001
+BENCHMARK_URL=http://localhost:3000 npm run perf
+```
+
+**Performance indexes** (`db/migrations/005_performance_indexes.sql`): Adds indexes on `paychecks(period_year, period_month)`, `paycheck_bills(paycheck_id)`, `actuals(paycheck_id)`, `one_time_expenses(paycheck_id)`, `financing_payments(plan_id)`, and `financing_plans(active)` — applied automatically on server startup.
--- a/db/migrations/005_performance_indexes.sql
+++ b/db/migrations/005_performance_indexes.sql
@@ -0,0 +1,7 @@
+-- Performance indexes for high-traffic query patterns
+CREATE INDEX IF NOT EXISTS idx_paychecks_period ON paychecks(period_year, period_month);
+CREATE INDEX IF NOT EXISTS idx_paycheck_bills_paycheck_id ON paycheck_bills(paycheck_id);
+CREATE INDEX IF NOT EXISTS idx_actuals_paycheck_id ON actuals(paycheck_id);
+CREATE INDEX IF NOT EXISTS idx_one_time_expenses_paycheck_id ON one_time_expenses(paycheck_id);
+CREATE INDEX IF NOT EXISTS idx_financing_payments_plan_id ON financing_payments(plan_id);
+CREATE INDEX IF NOT EXISTS idx_financing_plans_active ON financing_plans(active) WHERE active = true;
--- a/scripts/metrics-coverage.js
+++ b/scripts/metrics-coverage.js
@@ -1,251 +0,0 @@
-#!/usr/bin/env node
-/**
- * metrics-coverage.js — Static analysis script for metrics/logging instrumentation coverage.
- *
- * Scans all Express route files in server/src/routes/*.js and app.js to measure
- * how many route handlers contain logging calls (console.error/console.warn/console.log).
- *
- * Usage:
- *   node scripts/metrics-coverage.js              # JSON output (default)
- *   node scripts/metrics-coverage.js --format=text  # Human-readable table
- *
- * Sample output (captured 2026-03-20):
- * {
- *   "files": [
- *     { "file": "actuals.js", "total": 5, "logged": 5, "unlogged": 0, "coverage": 100 },
- *     { "file": "bills.js", "total": 6, "logged": 6, "unlogged": 0, "coverage": 100 },
- *     { "file": "config.js", "total": 2, "logged": 2, "unlogged": 0, "coverage": 100 },
- *     { "file": "financing.js", "total": 6, "logged": 6, "unlogged": 0, "coverage": 100 },
- *     { "file": "health.js", "total": 1, "logged": 0, "unlogged": 1, "coverage": 0 },
- *     { "file": "one-time-expenses.js", "total": 3, "logged": 3, "unlogged": 0, "coverage": 100 },
- *     { "file": "paychecks.js", "total": 6, "logged": 6, "unlogged": 0, "coverage": 100 },
- *     { "file": "summary.js", "total": 2, "logged": 2, "unlogged": 0, "coverage": 100 }
- *   ],
- *   "app": {
- *     "has_request_timing_middleware": false,
- *     "has_error_handling_middleware": false,
- *     "middleware_count": 11
- *   },
- *   "aggregate": {
- *     "total_handlers": 31,
- *     "logged_handlers": 30,
- *     "unlogged_handlers": 1,
- *     "coverage_pct": 96.77
- *   }
- * }
- */
-
-'use strict';
-
-const fs = require('fs');
-const path = require('path');
-
-const ROUTES_DIR = path.resolve(__dirname, '../server/src/routes');
-const APP_FILE   = path.resolve(__dirname, '../server/src/app.js');
-
-// Regex patterns for route handler definitions.
-// Matches: router.get/post/put/patch/delete( and app.get/post/put/patch/delete(
-const ROUTE_DEF_RE = /\b(?:router|app)\.(get|post|put|patch|delete)\s*\(/g;
-
-// Logging call patterns
-const LOG_RE = /\bconsole\.(error|warn|log)\s*\(/;
-
-/**
- * Extract individual route handler bodies from source.
- * Strategy: find each route definition, then walk forward counting
- * braces to find the closing of the outermost async/function callback.
- */
-function extractHandlerBodies(src) {
-  const handlers = [];
-  let match;
-  ROUTE_DEF_RE.lastIndex = 0;
-
-  while ((match = ROUTE_DEF_RE.exec(src)) !== null) {
-    const startIdx = match.index;
-    // Find the opening paren of the route call
-    const parenOpen = src.indexOf('(', startIdx);
-    if (parenOpen === -1) continue;
-
-    // Walk from the paren open, tracking paren depth to find the matching close.
-    // The handler callback body will be inside the outer parens.
-    let depth = 0;
-    let bodyStart = -1;
-    let bodyEnd = -1;
-    let inString = false;
-    let stringChar = '';
-    let i = parenOpen;
-
-    while (i < src.length) {
-      const ch = src[i];
-
-      // Basic string tracking (skip contents of string literals)
-      if (!inString && (ch === '"' || ch === "'" || ch === '`')) {
-        inString = true;
-        stringChar = ch;
-        i++;
-        continue;
-      }
-      if (inString) {
-        if (ch === '\\') { i += 2; continue; } // skip escape
-        if (ch === stringChar) inString = false;
-        i++;
-        continue;
-      }
-
-      if (ch === '(') {
-        depth++;
-        if (depth === 1) {
-          // This is the opening of the route call args
-        }
-      } else if (ch === ')') {
-        depth--;
-        if (depth === 0) {
-          bodyEnd = i;
-          break;
-        }
-      } else if (ch === '{' && depth >= 1 && bodyStart === -1) {
-        // First brace inside the outer parens — start of the handler body
-        bodyStart = i;
-      }
-
-      i++;
-    }
-
-    if (bodyStart !== -1 && bodyEnd !== -1) {
-      handlers.push(src.slice(bodyStart, bodyEnd));
-    }
-  }
-
-  return handlers;
-}
-
-/**
- * Analyse a single route file.
- */
-function analyseRouteFile(filePath) {
-  const src = fs.readFileSync(filePath, 'utf8');
-  const handlers = extractHandlerBodies(src);
-
-  const logged = handlers.filter(body => LOG_RE.test(body));
-
-  return {
-    file: path.basename(filePath),
-    total: handlers.length,
-    logged: logged.length,
-    unlogged: handlers.length - logged.length,
-    coverage: handlers.length === 0
-      ? null
-      : Math.round((logged.length / handlers.length) * 10000) / 100,
-  };
-}
-
-/**
- * Analyse app.js for middleware-level instrumentation.
- */
-function analyseApp(filePath) {
-  const src = fs.readFileSync(filePath, 'utf8');
-
-  // Request timing: morgan, custom middleware checking req.method, Date.now() at top-level use()
-  const hasRequestTiming =
-    /\brequire\s*\(\s*['"]morgan['"]\s*\)/.test(src) ||
-    /app\.use\s*\(.*Date\.now\(\)/.test(src) ||
-    /app\.use\s*\(.*req,\s*res,\s*next/.test(src) && /Date\.now|performance\.now/.test(src);
-
-  // Error handling middleware: app.use((err, req, res, next) => ...)
-  const hasErrorHandling = /app\.use\s*\(\s*(?:\S+\s*,\s*)?\(\s*err\s*,/.test(src);
-
-  // Count top-level app.use() calls (middleware registrations)
-  const middlewareMatches = src.match(/app\.use\s*\(/g) || [];
-
-  return {
-    has_request_timing_middleware: hasRequestTiming,
-    has_error_handling_middleware: hasErrorHandling,
-    middleware_count: middlewareMatches.length,
-  };
-}
-
-function run() {
-  const format = process.argv.includes('--format=text') ? 'text' : 'json';
-
-  // Analyse all route files
-  const routeFiles = fs.readdirSync(ROUTES_DIR)
-    .filter(f => f.endsWith('.js'))
-    .sort();
-
-  const fileResults = routeFiles.map(f =>
-    analyseRouteFile(path.join(ROUTES_DIR, f))
-  );
-
-  // Aggregate
-  const totalHandlers  = fileResults.reduce((s, r) => s + r.total,   0);
-  const loggedHandlers = fileResults.reduce((s, r) => s + r.logged,  0);
-
-  const aggregate = {
-    total_handlers:   totalHandlers,
-    logged_handlers:  loggedHandlers,
-    unlogged_handlers: totalHandlers - loggedHandlers,
-    coverage_pct: totalHandlers === 0
-      ? null
-      : Math.round((loggedHandlers / totalHandlers) * 10000) / 100,
-  };
-
-  const appInfo = analyseApp(APP_FILE);
-
-  const result = {
-    files: fileResults,
-    app: appInfo,
-    aggregate,
-  };
-
-  if (format === 'json') {
-    console.log(JSON.stringify(result, null, 2));
-    return;
-  }
-
-  // Text table
-  const COL_FILE    = 28;
-  const COL_TOTAL   = 7;
-  const COL_LOGGED  = 8;
-  const COL_COVER   = 10;
-
-  const pad = (s, n) => String(s).padEnd(n);
-  const lpad = (s, n) => String(s).padStart(n);
-
-  const hr = '-'.repeat(COL_FILE + COL_TOTAL + COL_LOGGED + COL_COVER + 6);
-
-  console.log('\nMetrics Instrumentation Coverage\n');
-  console.log(
-    pad('Route File', COL_FILE) +
-    lpad('Handlers', COL_TOTAL) +
-    lpad('Logged', COL_LOGGED) +
-    lpad('Coverage', COL_COVER)
-  );
-  console.log(hr);
-
-  for (const r of fileResults) {
-    const cov = r.coverage === null ? 'N/A' : `${r.coverage}%`;
-    console.log(
-      pad(r.file, COL_FILE) +
-      lpad(r.total,  COL_TOTAL) +
-      lpad(r.logged, COL_LOGGED) +
-      lpad(cov,      COL_COVER)
-    );
-  }
-
-  console.log(hr);
-  const aggCov = aggregate.coverage_pct === null ? 'N/A' : `${aggregate.coverage_pct}%`;
-  console.log(
-    pad('TOTAL', COL_FILE) +
-    lpad(aggregate.total_handlers,   COL_TOTAL) +
-    lpad(aggregate.logged_handlers,  COL_LOGGED) +
-    lpad(aggCov, COL_COVER)
-  );
-
-  console.log('\napp.js middleware:');
-  console.log(`  Request timing middleware : ${appInfo.has_request_timing_middleware}`);
-  console.log(`  Error handling middleware : ${appInfo.has_error_handling_middleware}`);
-  console.log(`  app.use() call count      : ${appInfo.middleware_count}`);
-  console.log('');
-}
-
-run();
--- a/scripts/perf-benchmark.js
+++ b/scripts/perf-benchmark.js
@@ -0,0 +1,62 @@
+#!/usr/bin/env node
+'use strict';
+
+const BASE_URL = process.env.BENCHMARK_URL || 'http://localhost:3001';
+const ITERATIONS = 5;
+const MEAN_THRESHOLD_MS = parseInt(process.env.SLOW_THRESHOLD_MS || '500', 10);
+
+const ENDPOINTS = [
+  { label: 'GET /api/paychecks', path: `/api/paychecks?year=${new Date().getFullYear()}&month=${new Date().getMonth() + 1}` },
+  { label: 'GET /api/financing', path: '/api/financing' },
+  { label: 'GET /api/summary/annual', path: `/api/summary/annual?year=${new Date().getFullYear()}` },
+];
+
+async function measureEndpoint(endpoint) {
+  const times = [];
+  for (let i = 0; i < ITERATIONS; i++) {
+    const start = Date.now();
+    const res = await fetch(`${BASE_URL}${endpoint.path}`);
+    const duration = Date.now() - start;
+    if (!res.ok) {
+      console.warn(`  [warn] ${endpoint.label} returned HTTP ${res.status}`);
+    }
+    times.push(duration);
+  }
+  const min = Math.min(...times);
+  const max = Math.max(...times);
+  const mean = Math.round(times.reduce((a, b) => a + b, 0) / times.length);
+  return { min, mean, max };
+}
+
+(async () => {
+  console.log(`Benchmarking ${BASE_URL} (${ITERATIONS} iterations each, threshold ${MEAN_THRESHOLD_MS}ms)\n`);
+
+  let failed = false;
+
+  for (const endpoint of ENDPOINTS) {
+    let stats;
+    try {
+      stats = await measureEndpoint(endpoint);
+    } catch (err) {
+      console.error(`  [error] ${endpoint.label}: ${err.message}`);
+      failed = true;
+      continue;
+    }
+
+    const flag = stats.mean >= MEAN_THRESHOLD_MS ? ' *** SLOW ***' : '';
+    console.log(`${endpoint.label}`);
+    console.log(`  min=${stats.min}ms  mean=${stats.mean}ms  max=${stats.max}ms${flag}`);
+
+    if (stats.mean >= MEAN_THRESHOLD_MS) {
+      failed = true;
+    }
+  }
+
+  console.log('');
+  if (failed) {
+    console.error('FAIL: one or more endpoints exceeded the threshold or errored.');
+    process.exit(1);
+  } else {
+    console.log('PASS: all endpoints within threshold.');
+  }
+})();
--- a/server/package.json
+++ b/server/package.json
@@ -6,7 +6,8 @@
    "start": "node src/index.js",
    "dev": "nodemon src/index.js",
    "test": "vitest run",
-    "test:watch": "vitest"
+    "test:watch": "vitest",
+    "perf": "node ../scripts/perf-benchmark.js"
  },
  "dependencies": {
    "cors": "^2.8.5",
--- a/server/src/tests/timing.middleware.test.js
+++ b/server/src/tests/timing.middleware.test.js
@@ -0,0 +1,98 @@
+import { describe, it, expect, vi, beforeEach, afterEach } from 'vitest';
+
+const timingMiddleware = require('../middleware/timing');
+
+function makeResMock() {
+  const listeners = {};
+  return {
+    statusCode: 200,
+    on(event, cb) {
+      listeners[event] = cb;
+    },
+    emit(event) {
+      if (listeners[event]) listeners[event]();
+    },
+  };
+}
+
+describe('timingMiddleware', () => {
+  let consoleSpy;
+  let warnSpy;
+
+  beforeEach(() => {
+    consoleSpy = vi.spyOn(console, 'log').mockImplementation(() => {});
+    warnSpy = vi.spyOn(console, 'warn').mockImplementation(() => {});
+  });
+
+  afterEach(() => {
+    consoleSpy.mockRestore();
+    warnSpy.mockRestore();
+    vi.useRealTimers();
+  });
+
+  it('calls next()', () => {
+    const req = { method: 'GET', path: '/api/health' };
+    const res = makeResMock();
+    const next = vi.fn();
+
+    timingMiddleware(req, res, next);
+    expect(next).toHaveBeenCalledOnce();
+  });
+
+  it('logs timing on response finish', () => {
+    const req = { method: 'GET', path: '/api/health' };
+    const res = makeResMock();
+
+    timingMiddleware(req, res, vi.fn());
+    res.emit('finish');
+
+    expect(consoleSpy).toHaveBeenCalledOnce();
+    const msg = consoleSpy.mock.calls[0][0];
+    expect(msg).toMatch(/\[timing\] GET \/api\/health 200 \d+ms/);
+  });
+
+  it('emits SLOW warning when duration exceeds 200ms threshold', () => {
+    vi.useFakeTimers();
+
+    const req = { method: 'POST', path: '/api/paychecks' };
+    const res = makeResMock();
+
+    timingMiddleware(req, res, vi.fn());
+
+    // Advance time past the threshold
+    vi.advanceTimersByTime(250);
+    res.emit('finish');
+
+    expect(warnSpy).toHaveBeenCalledOnce();
+    const msg = warnSpy.mock.calls[0][0];
+    expect(msg).toMatch(/\[SLOW\] POST \/api\/paychecks/);
+    expect(consoleSpy).not.toHaveBeenCalled();
+  });
+
+  it('does not emit SLOW warning for fast requests', () => {
+    vi.useFakeTimers();
+
+    const req = { method: 'GET', path: '/api/financing' };
+    const res = makeResMock();
+
+    timingMiddleware(req, res, vi.fn());
+
+    vi.advanceTimersByTime(50);
+    res.emit('finish');
+
+    expect(consoleSpy).toHaveBeenCalledOnce();
+    expect(warnSpy).not.toHaveBeenCalled();
+  });
+
+  it('includes status code in the log message', () => {
+    const req = { method: 'GET', path: '/api/bills' };
+    const res = makeResMock();
+    res.statusCode = 404;
+
+    timingMiddleware(req, res, vi.fn());
+    res.emit('finish');
+
+    const msg = consoleSpy.mock.calls[0][0];
+    expect(msg).toContain('404');
+  });
+});
--- a/server/src/app.js
+++ b/server/src/app.js
@@ -9,13 +9,14 @@ const actualsRouter = require('./routes/actuals');
 const oneTimeExpensesRouter = require('./routes/one-time-expenses');
 const summaryRouter = require('./routes/summary');
 const { router: financingRouter } = require('./routes/financing');
+const timingMiddleware = require('./middleware/timing');

 const app = express();

 app.use(cors());
 app.use(express.json());
-
 // API routes
+app.use('/api', timingMiddleware);
 app.use('/api', healthRouter);
 app.use('/api', configRouter);
 app.use('/api', billsRouter);
--- a/server/src/middleware/timing.js
+++ b/server/src/middleware/timing.js
@@ -0,0 +1,21 @@
+'use strict';
+
+const SLOW_THRESHOLD_MS = 200;
+
+function timingMiddleware(req, res, next) {
+  const start = Date.now();
+
+  res.on('finish', () => {
+    const duration = Date.now() - start;
+    const msg = `${req.method} ${req.path} ${res.statusCode} ${duration}ms`;
+    if (duration >= SLOW_THRESHOLD_MS) {
+      console.warn(`[SLOW] ${msg}`);
+    } else {
+      console.log(`[timing] ${msg}`);
+    }
+  });
+
+  next();
+}
+
+module.exports = timingMiddleware;