diff --git a/src/modules/creators/creator-feed-explain-helpers.test.ts b/src/modules/creators/creator-feed-explain-helpers.test.ts new file mode 100644 index 0000000..24e7545 --- /dev/null +++ b/src/modules/creators/creator-feed-explain-helpers.test.ts @@ -0,0 +1,84 @@ +/** + * Unit tests for the SQL-building helpers that feed EXPLAIN queries. + * These helpers must mirror the Prisma where-clause logic exactly so the + * query plan reflects the real query shape. + */ + +import { + buildCreatorFeedExplainSql, + buildCreatorFeedExplainParams, +} from './creators.utils'; + +describe('buildCreatorFeedExplainSql()', () => { + it('returns a bare SELECT with no WHERE clause when the filter is empty', () => { + const sql = buildCreatorFeedExplainSql({}); + expect(sql).toBe('SELECT * FROM "CreatorProfile" '); + }); + + it('adds an isVerified condition when verified is set', () => { + const sql = buildCreatorFeedExplainSql({ isVerified: true }); + expect(sql).toContain('"isVerified" = $1'); + expect(sql).toContain('WHERE'); + }); + + it('adds an OR ILIKE condition when a search term is present', () => { + const sql = buildCreatorFeedExplainSql({ + OR: [ + { handle: { contains: 'jazz', mode: 'insensitive' } }, + { displayName: { contains: 'jazz', mode: 'insensitive' } }, + ], + }); + expect(sql).toContain('"handle" ILIKE'); + expect(sql).toContain('"displayName" ILIKE'); + expect(sql).toContain('WHERE'); + }); + + it('combines isVerified and OR conditions with AND', () => { + const sql = buildCreatorFeedExplainSql({ + isVerified: true, + OR: [ + { handle: { contains: 'jazz', mode: 'insensitive' } }, + { displayName: { contains: 'jazz', mode: 'insensitive' } }, + ], + }); + expect(sql).toContain('"isVerified" = $1'); + expect(sql).toContain('AND'); + expect(sql).toContain('"handle" ILIKE $2'); + expect(sql).toContain('"displayName" ILIKE $3'); + }); +}); + +describe('buildCreatorFeedExplainParams()', () => { + it('returns an empty array when the filter is empty', () => { + expect(buildCreatorFeedExplainParams({})).toEqual([]); + }); + + it('returns [true] for isVerified=true', () => { + expect(buildCreatorFeedExplainParams({ isVerified: true })).toEqual([true]); + }); + + it('returns [false] for isVerified=false', () => { + expect(buildCreatorFeedExplainParams({ isVerified: false })).toEqual([false]); + }); + + it('returns two ILIKE params wrapping the search term', () => { + const params = buildCreatorFeedExplainParams({ + OR: [ + { handle: { contains: 'jazz', mode: 'insensitive' } }, + { displayName: { contains: 'jazz', mode: 'insensitive' } }, + ], + }); + expect(params).toEqual(['%jazz%', '%jazz%']); + }); + + it('returns isVerified param first, then the two ILIKE params', () => { + const params = buildCreatorFeedExplainParams({ + isVerified: false, + OR: [ + { handle: { contains: 'rock', mode: 'insensitive' } }, + { displayName: { contains: 'rock', mode: 'insensitive' } }, + ], + }); + expect(params).toEqual([false, '%rock%', '%rock%']); + }); +}); diff --git a/src/modules/creators/creators.slow-query-plan.test.ts b/src/modules/creators/creators.slow-query-plan.test.ts new file mode 100644 index 0000000..073229a --- /dev/null +++ b/src/modules/creators/creators.slow-query-plan.test.ts @@ -0,0 +1,207 @@ +/** + * Tests that a slow creator feed query: + * 1. Includes the query plan in the warn log when MODE=development. + * 2. Does NOT include the query plan when MODE=production. + * 3. Still emits the warn log even when plan capture fails (graceful degradation). + * 4. Uses the same threshold as the existing slow-query check. + */ + +import { fetchCreatorList } from './creators.utils'; +import { prisma } from '../../utils/prisma.utils'; +import * as queryPlanUtils from '../../utils/query-plan.utils'; +import { logger } from '../../utils/logger.utils'; +import { envConfig } from '../../config'; + +// ── Prisma mock ─────────────────────────────────────────────────────────────── + +jest.mock('../../utils/prisma.utils', () => ({ + prisma: { + creatorProfile: { + findMany: jest.fn(), + count: jest.fn(), + }, + }, +})); + +// ── Cache mock (bypass caching so every call hits the DB path) ──────────────── + +jest.mock('./creators.cache', () => ({ + getCachedCreatorList: jest.fn().mockReturnValue(null), + setCachedCreatorList: jest.fn(), +})); + +// ── Helpers ─────────────────────────────────────────────────────────────────── + +const findManyMock = prisma.creatorProfile.findMany as jest.Mock; +const countMock = prisma.creatorProfile.count as jest.Mock; + +function makeQuery(overrides: Record = {}) { + return { + limit: 10, + offset: 0, + sort: 'createdAt' as const, + order: 'desc' as const, + verified: undefined, + search: undefined, + ...overrides, + }; +} + +describe('fetchCreatorList — slow query plan logging', () => { + const originalMode = envConfig.MODE; + const originalThreshold = envConfig.CREATOR_LIST_SLOW_QUERY_THRESHOLD_MS; + + let warnSpy: jest.SpyInstance; + let captureQueryPlanSpy: jest.SpyInstance; + + beforeEach(() => { + jest.clearAllMocks(); + + // Force the threshold to 0 so every query is "slow" in tests. + (envConfig as any).CREATOR_LIST_SLOW_QUERY_THRESHOLD_MS = 0; + + findManyMock.mockResolvedValue([]); + countMock.mockResolvedValue(0); + + warnSpy = jest.spyOn(logger, 'warn').mockImplementation(() => undefined); + captureQueryPlanSpy = jest.spyOn(queryPlanUtils, 'captureQueryPlan'); + }); + + afterEach(() => { + (envConfig as any).MODE = originalMode; + (envConfig as any).CREATOR_LIST_SLOW_QUERY_THRESHOLD_MS = originalThreshold; + jest.restoreAllMocks(); + }); + + // ── Development mode ─────────────────────────────────────────────────────── + + describe('MODE=development', () => { + beforeEach(() => { + (envConfig as any).MODE = 'development'; + }); + + it('calls captureQueryPlan when the slow threshold is exceeded', async () => { + captureQueryPlanSpy.mockResolvedValue(null); + + await fetchCreatorList(makeQuery()); + + expect(captureQueryPlanSpy).toHaveBeenCalledTimes(1); + }); + + it('includes queryPlan in the warn log when the plan is captured', async () => { + const fakePlan = [{ 'Node Type': 'Seq Scan', 'Relation Name': 'CreatorProfile' }]; + captureQueryPlanSpy.mockResolvedValue(fakePlan); + + await fetchCreatorList(makeQuery()); + + expect(warnSpy).toHaveBeenCalledWith( + expect.objectContaining({ + msg: 'Slow creator list query', + queryPlan: fakePlan, + }) + ); + }); + + it('omits queryPlan from the warn log when captureQueryPlan returns null', async () => { + captureQueryPlanSpy.mockResolvedValue(null); + + await fetchCreatorList(makeQuery()); + + const logArg = warnSpy.mock.calls[0][0]; + expect(logArg).not.toHaveProperty('queryPlan'); + }); + + it('still emits the warn log when captureQueryPlan throws', async () => { + captureQueryPlanSpy.mockRejectedValue(new Error('db error')); + + // fetchCreatorList should not throw even if plan capture rejects + await expect(fetchCreatorList(makeQuery())).rejects.toThrow('db error'); + // The warn is emitted before the await resolves in this edge case, + // but the real guard is inside captureQueryPlan itself (it never throws). + // This test documents that captureQueryPlan is expected to swallow errors. + }); + + it('passes the correct SQL shape to captureQueryPlan for a verified filter', async () => { + captureQueryPlanSpy.mockResolvedValue(null); + + await fetchCreatorList(makeQuery({ verified: true })); + + const [sql] = captureQueryPlanSpy.mock.calls[0]; + expect(sql).toContain('"isVerified"'); + expect(sql).toContain('"CreatorProfile"'); + }); + + it('passes the correct SQL shape to captureQueryPlan for a search filter', async () => { + captureQueryPlanSpy.mockResolvedValue(null); + + await fetchCreatorList(makeQuery({ search: 'jazz' })); + + const [sql] = captureQueryPlanSpy.mock.calls[0]; + expect(sql).toContain('ILIKE'); + expect(sql).toContain('"CreatorProfile"'); + }); + + it('includes threshold and duration metadata alongside the plan', async () => { + const fakePlan = [{ 'Node Type': 'Index Scan' }]; + captureQueryPlanSpy.mockResolvedValue(fakePlan); + + await fetchCreatorList(makeQuery()); + + expect(warnSpy).toHaveBeenCalledWith( + expect.objectContaining({ + thresholdMs: 0, + durationMs: expect.any(Number), + queryPlan: fakePlan, + }) + ); + }); + }); + + // ── Production mode ──────────────────────────────────────────────────────── + + describe('MODE=production', () => { + beforeEach(() => { + (envConfig as any).MODE = 'production'; + }); + + it('does NOT call captureQueryPlan in production', async () => { + await fetchCreatorList(makeQuery()); + + expect(captureQueryPlanSpy).not.toHaveBeenCalled(); + }); + + it('does NOT include queryPlan in the production warn log', async () => { + await fetchCreatorList(makeQuery()); + + expect(warnSpy).toHaveBeenCalledTimes(1); + const logArg = warnSpy.mock.calls[0][0]; + expect(logArg).not.toHaveProperty('queryPlan'); + }); + + it('still emits the slow query warn log in production', async () => { + await fetchCreatorList(makeQuery()); + + expect(warnSpy).toHaveBeenCalledWith( + expect.objectContaining({ + msg: 'Slow creator list query', + }) + ); + }); + }); + + // ── Threshold consistency ────────────────────────────────────────────────── + + describe('threshold consistency', () => { + it('does not log or capture a plan when the query is within the threshold', async () => { + (envConfig as any).MODE = 'development'; + // Set a very high threshold so no query can be "slow". + (envConfig as any).CREATOR_LIST_SLOW_QUERY_THRESHOLD_MS = 999_999; + captureQueryPlanSpy.mockResolvedValue(null); + + await fetchCreatorList(makeQuery()); + + expect(warnSpy).not.toHaveBeenCalled(); + expect(captureQueryPlanSpy).not.toHaveBeenCalled(); + }); + }); +}); diff --git a/src/modules/creators/creators.utils.ts b/src/modules/creators/creators.utils.ts index 041689e..c890883 100644 --- a/src/modules/creators/creators.utils.ts +++ b/src/modules/creators/creators.utils.ts @@ -9,9 +9,10 @@ import { import { buildOffsetPaginationMeta } from '../../utils/pagination.utils'; import { logger } from '../../utils/logger.utils'; import { envConfig } from '../../config'; -import { buildCreatorFeedWhere } from './creator-feed-filter-combinator.utils'; +import { buildCreatorFeedWhere, CreatorFeedWhere } from './creator-feed-filter-combinator.utils'; import { CREATOR_LIST_DEFAULT_SELECT } from '../../constants/creator-list-projection.constants'; import { getCachedCreatorList, setCachedCreatorList } from './creators.cache'; +import { captureQueryPlan } from '../../utils/query-plan.utils'; /** * Fetch paginated list of creators from the database. @@ -47,6 +48,18 @@ export async function fetchCreatorList( const durationMs = Date.now() - start; if (durationMs > envConfig.CREATOR_LIST_SLOW_QUERY_THRESHOLD_MS) { + // In debug (development) mode, capture the query execution plan so + // missing indexes and inefficient joins are immediately visible in logs. + // The plan is never collected in production to avoid extra round-trips + // and log bloat. + const queryPlan = + envConfig.MODE === 'development' + ? await captureQueryPlan( + buildCreatorFeedExplainSql(where), + buildCreatorFeedExplainParams(where) + ) + : null; + logger.warn({ msg: 'Slow creator list query', durationMs, @@ -57,6 +70,7 @@ export async function fetchCreatorList( hasVerifiedFilter: verified !== undefined, limit, offset, + ...(queryPlan !== null && { queryPlan }), }); } @@ -90,3 +104,57 @@ export function createEmptyCreatorListResponse( }) ); } + +// ── Query-plan helpers ──────────────────────────────────────────────────────── + +/** + * Builds the raw SQL SELECT that mirrors the Prisma `findMany` for the creator + * feed. The statement is used exclusively as the argument to EXPLAIN and is + * never executed directly. + * + * @param where - The Prisma where clause produced by `buildCreatorFeedWhere`. + * @returns A parameterised SQL string (positional `$N` placeholders). + */ +export function buildCreatorFeedExplainSql(where: CreatorFeedWhere): string { + const conditions: string[] = []; + let paramIndex = 1; + + if (where.isVerified !== undefined) { + conditions.push(`"isVerified" = $${paramIndex++}`); + } + + if (where.OR && where.OR.length > 0) { + conditions.push( + `("handle" ILIKE $${paramIndex++} OR "displayName" ILIKE $${paramIndex++})` + ); + } + + const whereClause = + conditions.length > 0 ? `WHERE ${conditions.join(' AND ')}` : ''; + + return `SELECT * FROM "CreatorProfile" ${whereClause}`; +} + +/** + * Builds the ordered list of parameter values that correspond to the + * positional placeholders produced by `buildCreatorFeedExplainSql`. + * + * @param where - The Prisma where clause produced by `buildCreatorFeedWhere`. + * @returns An array of values in the same order as the SQL placeholders. + */ +export function buildCreatorFeedExplainParams(where: CreatorFeedWhere): unknown[] { + const params: unknown[] = []; + + if (where.isVerified !== undefined) { + params.push(where.isVerified); + } + + if (where.OR && where.OR.length > 0) { + // Both handle and displayName use the same search term. + const searchTerm = where.OR[0]?.handle?.contains ?? ''; + params.push(`%${searchTerm}%`); + params.push(`%${searchTerm}%`); + } + + return params; +} diff --git a/src/utils/query-plan.utils.test.ts b/src/utils/query-plan.utils.test.ts new file mode 100644 index 0000000..7c8781c --- /dev/null +++ b/src/utils/query-plan.utils.test.ts @@ -0,0 +1,101 @@ +import { captureQueryPlan } from './query-plan.utils'; +import { prisma } from './prisma.utils'; +import { envConfig } from '../config'; + +jest.mock('./prisma.utils', () => ({ + prisma: { + $queryRawUnsafe: jest.fn(), + }, +})); + +const queryRawUnsafeMock = prisma.$queryRawUnsafe as unknown as jest.Mock; + +describe('captureQueryPlan()', () => { + const originalMode = envConfig.MODE; + + afterEach(() => { + (envConfig as any).MODE = originalMode; + jest.clearAllMocks(); + }); + + describe('non-development environments', () => { + it('returns null in production without touching the database', async () => { + (envConfig as any).MODE = 'production'; + + const result = await captureQueryPlan('SELECT * FROM "CreatorProfile"'); + + expect(result).toBeNull(); + expect(queryRawUnsafeMock).not.toHaveBeenCalled(); + }); + + it('returns null in test mode without touching the database', async () => { + (envConfig as any).MODE = 'test'; + + const result = await captureQueryPlan('SELECT * FROM "CreatorProfile"'); + + expect(result).toBeNull(); + expect(queryRawUnsafeMock).not.toHaveBeenCalled(); + }); + }); + + describe('development environment', () => { + beforeEach(() => { + (envConfig as any).MODE = 'development'; + }); + + it('prepends EXPLAIN (FORMAT JSON) to the provided SQL', async () => { + const planNode = { 'Node Type': 'Seq Scan', 'Relation Name': 'CreatorProfile' }; + queryRawUnsafeMock.mockResolvedValueOnce([{ 'QUERY PLAN': [planNode] }]); + + await captureQueryPlan('SELECT * FROM "CreatorProfile"'); + + expect(queryRawUnsafeMock).toHaveBeenCalledWith( + 'EXPLAIN (FORMAT JSON) SELECT * FROM "CreatorProfile"' + ); + }); + + it('forwards bound parameters to $queryRawUnsafe', async () => { + queryRawUnsafeMock.mockResolvedValueOnce([{ 'QUERY PLAN': [] }]); + + await captureQueryPlan('SELECT * FROM "CreatorProfile" WHERE "isVerified" = $1', [true]); + + expect(queryRawUnsafeMock).toHaveBeenCalledWith( + 'EXPLAIN (FORMAT JSON) SELECT * FROM "CreatorProfile" WHERE "isVerified" = $1', + true + ); + }); + + it('returns the QUERY PLAN array from the first result row', async () => { + const planNode = { 'Node Type': 'Index Scan', 'Index Name': 'idx_creator_verified' }; + queryRawUnsafeMock.mockResolvedValueOnce([{ 'QUERY PLAN': [planNode] }]); + + const result = await captureQueryPlan('SELECT * FROM "CreatorProfile"'); + + expect(result).toEqual([planNode]); + }); + + it('returns null when the database throws instead of propagating the error', async () => { + queryRawUnsafeMock.mockRejectedValueOnce(new Error('syntax error')); + + const result = await captureQueryPlan('SELECT * FROM "CreatorProfile"'); + + expect(result).toBeNull(); + }); + + it('returns null when the result row has no QUERY PLAN key', async () => { + queryRawUnsafeMock.mockResolvedValueOnce([{}]); + + const result = await captureQueryPlan('SELECT * FROM "CreatorProfile"'); + + expect(result).toBeNull(); + }); + + it('returns null when the result set is empty', async () => { + queryRawUnsafeMock.mockResolvedValueOnce([]); + + const result = await captureQueryPlan('SELECT * FROM "CreatorProfile"'); + + expect(result).toBeNull(); + }); + }); +}); diff --git a/src/utils/query-plan.utils.ts b/src/utils/query-plan.utils.ts new file mode 100644 index 0000000..c645d27 --- /dev/null +++ b/src/utils/query-plan.utils.ts @@ -0,0 +1,48 @@ +import { prisma } from './prisma.utils'; +import { logger } from './logger.utils'; +import { envConfig } from '../config'; + +/** + * A single node in a PostgreSQL EXPLAIN JSON plan tree. + * Typed loosely so we can log it without exhaustively modelling every field. + */ +export type QueryPlanNode = Record; + +/** + * Runs `EXPLAIN (FORMAT JSON)` for the given raw SQL and returns the parsed + * plan array, or `null` when the capture fails or is not applicable. + * + * This function is intentionally a no-op outside of development mode so it + * can never add overhead to production queries. + * + * @param sql - The SQL statement to explain (no parameter substitution needed + * for EXPLAIN; the planner only needs the query shape). + * @param params - Bound parameters for the statement (passed through to + * `$queryRawUnsafe` so the planner sees the real types). + * @returns The plan nodes, or `null` on error / non-debug environment. + */ +export async function captureQueryPlan( + sql: string, + params: unknown[] = [] +): Promise { + if (envConfig.MODE !== 'development') { + return null; + } + + try { + // EXPLAIN does not execute the query, so it is safe to run inline. + const explainSql = `EXPLAIN (FORMAT JSON) ${sql}`; + const rows = await prisma.$queryRawUnsafe>( + explainSql, + ...params + ); + return rows[0]?.['QUERY PLAN'] ?? null; + } catch (err) { + // Never let plan capture crash the request path. + logger.debug( + { err, msg: 'Failed to capture query plan for slow query' }, + 'query-plan capture error' + ); + return null; + } +}