Merge pull request #26 from thelastbackspace/feat/pool-and-index

Pool exhaustion, missing indexes, and query attribution under a full pool

Author: thelastbackspace

CHANGELOG.md

@@ -7,12 +7,17 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+### Fixed
+- **Queries were attributed to the wrong request when a connection pool was full.** pg-pool, mysql2 and mysql call a queued request's callback from whichever request released a connection, so its queries landed in that other request's tree, or in none. Pool callbacks, and every callback a tracked driver call takes, now keep the caller's context. With a pool of 1 and 4 concurrent requests, 3 of the 4 showed no queries before (found while adding pool-wait tracking).
+
 ### Fixed (found by the new evaluation set)
 - `run` reported each of several `Promise.all` calls as "dominant" (each spans most of the request). Parallel calls are no longer dominant, and a dominant call must take at least 50 ms (`dominantMinMs`).
 - Blocking code was reported three times: as blocking, as its own route queueing, and as the process being busy. Only the bystanders that waited behind it are listed now.
 - `traceperf/auto` wrote each request tree with its own `appendFileSync`, and under load that showed up as the app's "CPU cost" (`writeFileUtf8`). Writes are batched every 20 ms.
 
 ### Added
+- **Missing indexes:** `traceperf run` EXPLAINs (plans, never runs) the app's Postgres `SELECT`s after the load and reports full scans of tables with 10,000+ rows that an index would avoid, with the `CREATE INDEX` to add. `--no-explain` turns it off.
+- **Pool exhaustion:** `pg` and `mysql2` pools track the wait for a free connection when every connection is in use (`pg pool wait`, `mysql pool wait`); `run`/`explain` report it with the setting to change.
 - **GitHub Action** (`uses: thelastbackspace/traceperf@<tag>`): runs the baseline check, fails the job on more calls per request, and posts one pull-request comment it updates on every push. `traceperf run --markdown file.md` writes the same summary.
 - `traceperf run` reads `traceperf.config.json` (or `--config file`); command-line options win. A `login` step logs in before the traffic and sends the returned token or cookies with every request; `${NAME}` in the file is read from the environment.
 - `npm run eval` scores `traceperf run` on 20 apps in `examples/slow-apps`: 12 with a planted problem, 8 clean ones where the right answer is "no issues". CI fails on any missed problem or false alarm. Before these fixes: 17/17 found, 15 false alarms; after: 17/17, 0.

README.md

@@ -93,6 +93,14 @@ The database was fast; `buildReport` was blocking it. That only shows up when re
      fix: Mongoose is building full documents: add .lean() to read-only queries … and .select() only the fields you send
   ```
 - **Timings you can trust:** after the warm-up, `run` sends a few requests one at a time (`--probe`) and takes the per-request findings (a call taking most of a request, sequential awaits, N+1) from those. Under concurrent load every `await` also waits for the busy event loop, which makes fast queries look slow.
+- **Missing indexes (Postgres):** after the load, the app runs plain `EXPLAIN` (the query is planned, not executed) on the `SELECT`s it made and reports full scans of big tables that an index would avoid:
+
+  ```
+  🔍 SELECT * FROM orders WHERE customer_id = $1 (run 1219 times) reads all ~60,000 rows of orders to return ~12 (Seq Scan, Filter: (customer_id = 0))
+     fix: add an index: CREATE INDEX ON orders (customer_id)
+  ```
+  Postgres scans small tables on purpose, so a test database with little data rarely shows one: point the run at realistic data. Tables under 10,000 rows are ignored. `--no-explain` turns it off.
+- **Pool exhaustion:** with `pg` and `mysql2`, the time a request waits for a free connection from a full pool is tracked (`pg pool wait`) and reported, with the pool setting to change: "GET /report waited 65 ms for a free pg connection (79% of the request): every connection in the pool was in use".
 - **Wrong setup is said first:** "2117 of 2117 responses failed (most: 401 Unauthorized)…" instead of timings of error pages.
 
 Checked on real apps, not only on the planted ones: Prisma's REST example, the RealWorld API (Express + Prisma), an Express + Mongoose boilerplate and a NestJS + TypeORM app.

examples/slow-apps/cases.json

@@ -214,5 +214,43 @@
       "/flags"
     ],
     "expect": []
+  },
+  "pool-exhaustion": {
+    "paths": [
+      "/report"
+    ],
+    "requires": "pg",
+    "expect": [
+      {
+        "kind": "pool",
+        "includes": "for a free pg connection"
+      }
+    ]
+  },
+  "missing-index": {
+    "paths": [
+      "/orders"
+    ],
+    "requires": "pg",
+    "expect": [
+      {
+        "kind": "index",
+        "includes": "traceperf_eval_orders"
+      }
+    ]
+  },
+  "clean-indexed": {
+    "paths": [
+      "/orders"
+    ],
+    "requires": "pg",
+    "expect": []
+  },
+  "clean-pool": {
+    "paths": [
+      "/report"
+    ],
+    "requires": "pg",
+    "expect": []
   }
 }

examples/slow-apps/clean-indexed/server.js

@@ -0,0 +1,10 @@
+// Clean: the fixed version of missing-index (customer_id is indexed). Needs TRACEPERF_PG_URL.
+const serve = require('../serve');
+const setup = require('../missing-index/setup');
+
+setup('traceperf_eval_orders_indexed', true).then(pool => {
+  let n = 0;
+  serve({
+    '/orders': async () => (await pool.query('SELECT * FROM traceperf_eval_orders_indexed WHERE customer_id = $1', [n++ % 5000])).rows,
+  });
+});

examples/slow-apps/clean-pool/server.js

@@ -0,0 +1,9 @@
+// Clean: the fixed version of pool-exhaustion (pool of 20 for 10 concurrent requests). Needs TRACEPERF_PG_URL.
+const pg = require('pg');
+const serve = require('../serve');
+
+const pool = new pg.Pool({ connectionString: process.env.TRACEPERF_PG_URL, max: 20 });
+
+serve({
+  '/report': async () => (await pool.query('SELECT pg_sleep(0.015), now() AS at')).rows,
+});

examples/slow-apps/missing-index/server.js

@@ -0,0 +1,11 @@
+// Planted cause: orders are looked up by customer_id, which has no index:
+// every request makes Postgres read all 60,000 rows. Needs TRACEPERF_PG_URL.
+const serve = require('../serve');
+const setup = require('./setup');
+
+setup('traceperf_eval_orders', false).then(pool => {
+  let n = 0;
+  serve({
+    '/orders': async () => (await pool.query('SELECT * FROM traceperf_eval_orders WHERE customer_id = $1', [n++ % 5000])).rows,
+  });
+});

examples/slow-apps/missing-index/setup.js

@@ -0,0 +1,14 @@
+// A 60,000-row orders table (created once), with or without an index on customer_id
+const pg = require('pg');
+
+module.exports = async function setup(table, indexed) {
+  const pool = new pg.Pool({ connectionString: process.env.TRACEPERF_PG_URL, max: 10 });
+  await pool.query(`CREATE TABLE IF NOT EXISTS ${table} (id int PRIMARY KEY, customer_id int, total numeric, created_at timestamptz)`);
+  const { rows } = await pool.query(`SELECT count(*)::int AS n FROM ${table}`);
+  if (rows[0].n === 0) {
+    await pool.query(`INSERT INTO ${table} SELECT g, g % 5000, g * 1.5, now() - g * interval '1 minute' FROM generate_series(1, 60000) g`);
+  }
+  if (indexed) await pool.query(`CREATE INDEX IF NOT EXISTS ${table}_customer ON ${table} (customer_id)`);
+  await pool.query(`ANALYZE ${table}`);
+  return pool;
+};

examples/slow-apps/pool-exhaustion/server.js

@@ -0,0 +1,11 @@
+// Planted cause: a pg pool of 2 connections serving 10 concurrent requests,
+// each holding its connection for a ~15 ms query: most of every request is
+// waiting for a free connection, not querying. Needs TRACEPERF_PG_URL.
+const pg = require('pg');
+const serve = require('../serve');
+
+const pool = new pg.Pool({ connectionString: process.env.TRACEPERF_PG_URL, max: 2 });
+
+serve({
+  '/report': async () => (await pool.query('SELECT pg_sleep(0.015), now() AS at')).rows,
+});

src/__tests__/drivers.test.ts

@@ -25,6 +25,7 @@ import {
   instrumentRedis,
   sqlLabel,
 } from '../index';
+import { observeSql, ObservedSql } from '../drivers';
 
 function setup() {
   const roots: ExecutionRecord[] = [];
@@ -477,3 +478,81 @@ describe('instrumentBetterSqlite3 (database shaped like better-sqlite3: Statemen
     expect(labels(roots[0])).toEqual([]);
   });
 });
+
+describe('pg pools without a server (fake pg)', () => {
+  // Shaped like pg: Client.query(text, values, cb) and pg-pool's counters and callback queue
+  function fakePg() {
+    class Client {
+      query(text: string, values: unknown, cb?: (e: unknown, r: unknown) => void) {
+        const done = typeof values === 'function' ? values as typeof cb : cb;
+        const result = { rows: [{ 'QUERY PLAN': [{ Plan: { 'Node Type': 'Seq Scan' } }] }] };
+        if (done) { setTimeout(() => done(null, result), 2); return undefined; }
+        return new Promise(r => setTimeout(() => r(result), 2));
+      }
+    }
+    class Pool {
+      options = { max: 1 };
+      totalCount = 0;
+      idleCount = 0;
+      private queue: Array<(e: unknown, c: Client, release: () => void) => void> = [];
+      private client = new Client();
+      connect(cb: (e: unknown, c: Client, release: () => void) => void) {
+        const release = () => {
+          const next = this.queue.shift();
+          // The next waiter is called from inside this release: another request's context
+          if (next) next(null, this.client, release);
+          else this.idleCount = 1;
+        };
+        if (this.totalCount < this.options.max) { this.totalCount++; setTimeout(() => cb(null, this.client, release), 1); return; }
+        if (this.idleCount > 0) { this.idleCount = 0; setTimeout(() => cb(null, this.client, release), 1); return; }
+        this.queue.push(cb);
+      }
+      query(text: string, values?: unknown[]) {
+        return new Promise((resolve, reject) => this.connect((e, c, release) => {
+          if (e) return reject(e);
+          (c.query(text, values) as Promise<unknown>).then(r => { release(); resolve(r); }, reject);
+        }));
+      }
+    }
+    return { Client, Pool };
+  }
+
+  test('a full pool: each request keeps its own queries, and the wait is tracked', async () => {
+    const pg = fakePg();
+    const { tp, roots } = setup();
+    const uninstall = instrumentPg(tp, pg);
+    const pool = new pg.Pool();
+    try {
+      await Promise.all([1, 2, 3].map(i => tp.track(async () => {
+        await pool.query(`SELECT ${i}`);
+      }, { label: `req${i}` })));
+    } finally {
+      uninstall();
+    }
+    const requests = roots.filter(r => r.label.startsWith('req'));
+    expect(requests).toHaveLength(3);
+    for (const r of requests) expect(labels(r).filter(l => l !== 'pg pool wait')).toEqual(['pg SELECT']);
+    expect(requests.filter(r => labels(r).includes('pg pool wait')).length).toBeGreaterThanOrEqual(1);
+  });
+
+  test('observeSql sees statements and runs its own on the same pool, untracked', async () => {
+    const pg = fakePg();
+    const { tp, roots } = setup();
+    const uninstall = instrumentPg(tp, pg);
+    const seen: ObservedSql[] = [];
+    observeSql(q => seen.push(q));
+    const pool = new pg.Pool();
+    try {
+      await tp.track(() => pool.query('SELECT * FROM users WHERE id = $1', [7]), { label: 'job' });
+      expect(seen.map(q => [q.text, q.values])).toEqual([['SELECT * FROM users WHERE id = $1', [7]]]);
+      const rows = await seen[0].run('EXPLAIN (FORMAT JSON) SELECT 1');
+      expect(rows[0]['QUERY PLAN']).toBeDefined();
+      // The EXPLAIN was neither observed again nor tracked as the app's query
+      expect(seen).toHaveLength(1);
+    } finally {
+      observeSql(undefined);
+      uninstall();
+    }
+    expect(roots.map(r => r.label)).toEqual(['job']);
+  });
+});

src/__tests__/run.test.ts

@@ -137,7 +137,9 @@ const cases: Record<string, { paths: string[]; expect: Array<{ kind: string | st
   JSON.parse(fs.readFileSync(path.join(APPS, 'cases.json'), 'utf8'));
 
 describe('known-slow example apps: explain names the planted cause', () => {
-  it.each(Object.keys(cases))('%s', async name => {
+  // Cases that need a real database run where CI provides one (TRACEPERF_PG_URL)
+  const runnable = Object.keys(cases).filter(name => !(cases[name] as { requires?: string }).requires || !!process.env.TRACEPERF_PG_URL);
+  it.each(runnable)('%s', async name => {
     const c = cases[name];
     const out: string[] = [];
     const argv = [path.join(APPS, name, 'server.js'), ...c.paths.flatMap(p => ['--path', p]), '-d', '1s', '--json'];
@@ -430,3 +432,24 @@ describe('markdownReport', () => {
     expect(markdownReport({ trees: 5, findings: [] })).toMatch(/^### traceperf: no issues found/);
   });
 });
+
+describe('indexFindings', () => {
+  const { indexFindings } = jest.requireActual('../run');
+  const scan = (over: object) => ({ table: 'orders', filter: '(customer_id = 5)', rows: 12, columns: ['customer_id'], tableRows: 60000, ...over });
+  it('reports selective full scans of big tables, once per index', () => {
+    const [f, ...rest] = indexFindings([
+      { driver: 'pg', text: 'SELECT * FROM orders WHERE customer_id = $1', count: 500, scans: [scan({})] },
+      { driver: 'pg', text: 'SELECT id FROM orders WHERE customer_id = $1', count: 20, scans: [scan({})] },
+    ]);
+    expect(rest).toEqual([]);
+    expect(f.kind).toBe('index');
+    expect(f.message).toMatch(/\(run 500 times\) reads all ~60,000 rows of orders to return ~12/);
+    expect(f.fix).toMatch(/^add an index: CREATE INDEX ON orders \(customer_id\)/);
+  });
+  it('small tables, unselective filters and filters without usable columns are fine', () => {
+    expect(indexFindings([{ driver: 'pg', text: 'q', count: 9, scans: [scan({ tableRows: 500 })] }])).toEqual([]);
+    expect(indexFindings([{ driver: 'pg', text: 'q', count: 9, scans: [scan({ rows: 30000 })] }])).toEqual([]);
+    expect(indexFindings([{ driver: 'pg', text: 'q', count: 9, scans: [scan({ columns: [] })] }])).toEqual([]);
+    expect(indexFindings([{ driver: 'pg', text: 'q', count: 9, scans: [scan({ tableRows: 500 })] }], 100)).toHaveLength(1);
+  });
+});