diff --git a/graphile/graphile-cache/src/__tests__/counters.test.ts b/graphile/graphile-cache/src/__tests__/counters.test.ts new file mode 100644 index 0000000000..5b3ec01be3 --- /dev/null +++ b/graphile/graphile-cache/src/__tests__/counters.test.ts @@ -0,0 +1,120 @@ +import { + cacheCounters, + clearMatchingEntries, + getCacheConfig, + getCacheCounters, + graphileCache, + type GraphileCacheEntry +} from '../graphile-cache'; + +/** + * Counter instrumentation regression tests. The counters are process-global and + * mutable, so every assertion is a DELTA against a snapshot captured immediately + * before the action — robust to test ordering and to fire-and-forget disposals from + * other suites. The eviction and disposal increments happen synchronously inside + * graphileCache.delete() (the dispose callback and the pre-await head of disposeEntry), + * so no tick is needed except for the async drain-timeout path. + */ + +const tick = (ms = 60) => new Promise((resolve) => setTimeout(resolve, ms)); + +const makeEntry = (releaseDelayMs = 0): GraphileCacheEntry => { + const release = jest.fn( + () => new Promise((resolve) => setTimeout(resolve, releaseDelayMs)) + ); + return { + pgl: { release } as unknown as GraphileCacheEntry['pgl'], + serv: {} as GraphileCacheEntry['serv'], + handler: {} as GraphileCacheEntry['handler'], + // Never .listen()ed in production; close() invokes its callback synchronously here. + httpServer: { close: (cb: () => void) => cb() } as unknown as GraphileCacheEntry['httpServer'], + cacheKey: 'mock', + createdAt: Date.now() + }; +}; + +describe('cacheCounters increment on eviction/disposal', () => { + afterEach(async () => { + graphileCache.clear(); + await tick(); + }); + + it('counts an LRU eviction (fresh entry, plain delete) and a disposal', () => { + const before = getCacheCounters(); + const key = 'counter-lru-1'; + graphileCache.set(key, makeEntry(0)); + graphileCache.delete(key); // fresh + not manual → reason 'lru'; disposeEntry runs + + const after = getCacheCounters(); + expect(after.evictions.lru).toBe(before.evictions.lru + 1); + expect(after.disposals).toBe(before.disposals + 1); + }); + + it('counts a TTL eviction when the entry is older than the configured ttl', () => { + const before = getCacheCounters(); + const key = 'counter-ttl-1'; + const entry = makeEntry(0); + // Backdate our own createdAt beyond the idle-ttl so getEvictionReason returns 'ttl'. + entry.createdAt = Date.now() - getCacheConfig().ttl - 1_000; + graphileCache.set(key, entry); + graphileCache.delete(key); + + const after = getCacheCounters(); + expect(after.evictions.ttl).toBe(before.evictions.ttl + 1); + }); + + it('counts a manual eviction via clearMatchingEntries', () => { + const before = getCacheCounters(); + graphileCache.set('counter-manual-1', makeEntry(0)); + const cleared = clearMatchingEntries(/^counter-manual-/); + + expect(cleared).toBe(1); + const after = getCacheCounters(); + expect(after.evictions.manual).toBe(before.evictions.manual + 1); + }); +}); + +describe('cacheCounters.drainTimeouts', () => { + const prev = process.env.GRAPHILE_CACHE_DRAIN_TIMEOUT_MS; + afterEach(async () => { + if (prev === undefined) delete process.env.GRAPHILE_CACHE_DRAIN_TIMEOUT_MS; + else process.env.GRAPHILE_CACHE_DRAIN_TIMEOUT_MS = prev; + graphileCache.clear(); + await tick(); + }); + + it('increments when disposal drains past the timeout with a request still in flight', async () => { + process.env.GRAPHILE_CACHE_DRAIN_TIMEOUT_MS = '1'; // one 100ms poll cycle, then give up + const before = getCacheCounters(); + const key = 'counter-drain-1'; + const entry = makeEntry(0); + entry.inflight = 1; // never drops → drain loop hits the timeout branch + + graphileCache.set(key, entry); + graphileCache.delete(key); // fire-and-forget disposeEntry begins draining + + await tick(250); // allow the poll cycle + timeout to elapse + + const after = getCacheCounters(); + expect(after.drainTimeouts).toBe(before.drainTimeouts + 1); + // Disposal still proceeds after the drain timeout. + expect((entry.pgl as unknown as { release: jest.Mock }).release).toHaveBeenCalledTimes(1); + }); +}); + +describe('getCacheCounters snapshot isolation', () => { + it('returns a deep copy that cannot mutate the live counters', () => { + const before = getCacheCounters(); + const snapshot = getCacheCounters(); + snapshot.disposals += 1_000; + snapshot.evictions.lru += 1_000; + snapshot.drainTimeouts += 1_000; + + const after = getCacheCounters(); + expect(after.disposals).toBe(before.disposals); + expect(after.evictions.lru).toBe(before.evictions.lru); + expect(after.drainTimeouts).toBe(before.drainTimeouts); + // Sanity: the live object is the same instance across reads. + expect(cacheCounters.disposals).toBe(after.disposals); + }); +}); diff --git a/graphile/graphile-cache/src/__tests__/disposal-and-cap.test.ts b/graphile/graphile-cache/src/__tests__/disposal-and-cap.test.ts new file mode 100644 index 0000000000..f272704899 --- /dev/null +++ b/graphile/graphile-cache/src/__tests__/disposal-and-cap.test.ts @@ -0,0 +1,201 @@ +import { EventEmitter } from 'events'; +import { + ensureCacheHeadroom, + getCacheConfig, + graphileCache, + type GraphileCacheEntry, + invokeEntryHandler, +} from '../graphile-cache'; + +/** + * Regression tests for the schema-builder OOM fix. + * + * 1. Disposal guard is entry-scoped, not key-scoped. The previous string-keyed guard + * skipped pgl.release() for a rebuilt entry that shared a key with an entry still + * mid-release (the "same-key disposal race"). These tests pin the corrected behaviour: + * every distinct entry is released exactly once, while the SAME entry is never + * double-disposed. + * 2. getCacheConfig honours GRAPHILE_CACHE_MAX and otherwise returns a heap-aware default + * bounded to a sane range (a count-only default of 50 × ~0.5GB/instance was the OOM). + */ + +const tick = (ms = 60) => new Promise((resolve) => setTimeout(resolve, ms)); + +const makeEntry = (releaseDelayMs = 0): GraphileCacheEntry => { + const release = jest.fn( + () => new Promise((resolve) => setTimeout(resolve, releaseDelayMs)), + ); + return { + pgl: { release } as unknown as GraphileCacheEntry['pgl'], + serv: {} as GraphileCacheEntry['serv'], + handler: {} as GraphileCacheEntry['handler'], + // Never .listen()ed in production; close() invokes its callback synchronously here. + httpServer: { close: (cb: () => void) => cb() } as unknown as GraphileCacheEntry['httpServer'], + cacheKey: 'mock', + createdAt: Date.now(), + }; +}; + +describe('graphile-cache disposal guard (same-key race)', () => { + it('disposes a rebuilt entry on the same key while a prior entry is mid-release', async () => { + const key = 'race-key-1'; + const a = makeEntry(40); // a.release() stays pending while b is disposed + const b = makeEntry(0); + + graphileCache.set(key, a); + graphileCache.delete(key); // -> disposeEntry(a) begins, a.release() in flight + graphileCache.set(key, b); // key was free; inserts b + graphileCache.delete(key); // -> disposeEntry(b) MUST NOT be skipped by the guard + + await tick(120); + + // The bug: the old string-keyed guard left `key` parked while a.release() was pending, + // so b.release() was never called (would be 0 here). + expect((a.pgl as unknown as { release: jest.Mock }).release).toHaveBeenCalledTimes(1); + expect((b.pgl as unknown as { release: jest.Mock }).release).toHaveBeenCalledTimes(1); + }); + + it('never disposes the same entry twice', async () => { + const key = 'race-key-2'; + const a = makeEntry(0); + + graphileCache.set(key, a); + graphileCache.delete(key); // dispose a + graphileCache.set(key, a); // re-insert the SAME entry object + graphileCache.delete(key); // dispose again -> guard must skip (already disposed) + + await tick(); + + expect((a.pgl as unknown as { release: jest.Mock }).release).toHaveBeenCalledTimes(1); + }); +}); + +describe('graphile-cache heap-aware capacity', () => { + const prev = process.env.GRAPHILE_CACHE_MAX; + afterEach(() => { + if (prev === undefined) delete process.env.GRAPHILE_CACHE_MAX; + else process.env.GRAPHILE_CACHE_MAX = prev; + }); + + it('honours an explicit GRAPHILE_CACHE_MAX', () => { + process.env.GRAPHILE_CACHE_MAX = '7'; + expect(getCacheConfig().max).toBe(7); + }); + + it('falls back to a bounded heap-aware default when unset', () => { + delete process.env.GRAPHILE_CACHE_MAX; + const { max } = getCacheConfig(); + // Bounded within [1, 50]: at least one instance must be admitted, but the + // floor must never exceed what the heap budget says fits (a floor of 3 + // over-admitted 1.3GB instances on a 2GB heap and aborted the process). + expect(max).toBeGreaterThanOrEqual(1); + expect(max).toBeLessThanOrEqual(50); + }); + + it('ignores a non-numeric GRAPHILE_CACHE_MAX (falls back to heap-aware default)', () => { + process.env.GRAPHILE_CACHE_MAX = 'not-a-number'; + const { max } = getCacheConfig(); + expect(max).toBeGreaterThanOrEqual(1); + expect(max).toBeLessThanOrEqual(50); + }); + + it('admits only one instance when the per-instance estimate exceeds half the heap', () => { + delete process.env.GRAPHILE_CACHE_MAX; + const prevEstimate = process.env.GRAPHILE_CACHE_INSTANCE_HEAP_BYTES; + // Larger than any plausible test-runner heap budget => budgeted count is 0 + // and the floor of 1 must win (never the old floor of 3). + process.env.GRAPHILE_CACHE_INSTANCE_HEAP_BYTES = String(64 * 1024 * 1024 * 1024); + try { + expect(getCacheConfig().max).toBe(1); + } finally { + if (prevEstimate === undefined) delete process.env.GRAPHILE_CACHE_INSTANCE_HEAP_BYTES; + else process.env.GRAPHILE_CACHE_INSTANCE_HEAP_BYTES = prevEstimate; + } + }); +}); + +// A minimal express-like response: an EventEmitter so invokeEntryHandler can hook +// 'finish'/'close', cast to the express type it expects. +const makeRes = () => new EventEmitter() as unknown as Parameters[2]; +const fakeReq = {} as Parameters[1]; +const fakeNext = (() => undefined) as Parameters[3]; + +describe('invokeEntryHandler in-flight refcounting', () => { + it('increments while serving and releases exactly once across finish+close', () => { + const entry = makeEntry(); + const handler = jest.fn(); + entry.handler = handler as unknown as GraphileCacheEntry['handler']; + + const res = makeRes(); + expect(invokeEntryHandler(entry, fakeReq, res, fakeNext)).toBe(true); + expect(handler).toHaveBeenCalledTimes(1); + expect(entry.inflight).toBe(1); + + (res as unknown as EventEmitter).emit('finish'); + expect(entry.inflight).toBe(0); + // 'close' always follows 'finish' in Node; the release must be idempotent. + (res as unknown as EventEmitter).emit('close'); + expect(entry.inflight).toBe(0); + }); + + it('refuses a disposing entry without invoking the handler', () => { + const entry = makeEntry(); + const handler = jest.fn(); + entry.handler = handler as unknown as GraphileCacheEntry['handler']; + entry.disposing = true; + + expect(invokeEntryHandler(entry, fakeReq, makeRes(), fakeNext)).toBe(false); + expect(handler).not.toHaveBeenCalled(); + }); +}); + +describe('disposeEntry drains in-flight requests before release', () => { + it('waits for inflight to reach 0, then releases exactly once', async () => { + const key = 'drain-key-1'; + const entry = makeEntry(0); + entry.inflight = 1; // simulate a request mid-flight + + graphileCache.set(key, entry); + graphileCache.delete(key); // disposal starts; must poll instead of releasing + + await tick(120); // one poll cycle elapsed, request still in flight + expect((entry.pgl as unknown as { release: jest.Mock }).release).not.toHaveBeenCalled(); + + entry.inflight = 0; // request completes + await tick(250); // allow the next poll cycle to observe it + + expect((entry.pgl as unknown as { release: jest.Mock }).release).toHaveBeenCalledTimes(1); + }); +}); + +describe('ensureCacheHeadroom', () => { + const prevMax = process.env.GRAPHILE_CACHE_MAX; + afterEach(() => { + if (prevMax === undefined) delete process.env.GRAPHILE_CACHE_MAX; + else process.env.GRAPHILE_CACHE_MAX = prevMax; + graphileCache.clear(); + }); + + it('evicts least-recently-used entries until a build slot is free', async () => { + process.env.GRAPHILE_CACHE_MAX = '2'; + const a = makeEntry(0); + const b = makeEntry(0); + graphileCache.set('headroom-a', a); + graphileCache.set('headroom-b', b); + graphileCache.get('headroom-a'); // touch a → b becomes LRU-oldest + + const evicted = ensureCacheHeadroom(1); + + expect(evicted).toBe(1); + expect(graphileCache.has('headroom-a')).toBe(true); + expect(graphileCache.has('headroom-b')).toBe(false); + await tick(); // let the fire-and-forget disposal settle before clear() + }); + + it('no-ops when under capacity', () => { + process.env.GRAPHILE_CACHE_MAX = '5'; + graphileCache.set('headroom-c', makeEntry(0)); + expect(ensureCacheHeadroom(1)).toBe(0); + expect(graphileCache.has('headroom-c')).toBe(true); + }); +}); diff --git a/graphile/graphile-cache/src/__tests__/governor.test.ts b/graphile/graphile-cache/src/__tests__/governor.test.ts new file mode 100644 index 0000000000..19ae8df6e6 --- /dev/null +++ b/graphile/graphile-cache/src/__tests__/governor.test.ts @@ -0,0 +1,83 @@ +import { + computeCapacityFromBudget, + getCacheCounters, + getMemoryPressure, + shouldRefuseBuild +} from '../graphile-cache'; + +const MB = 1024 * 1024; + +describe('computeCapacityFromBudget (two-constraint capacity model)', () => { + it('matches the live capacity-2 proof: 3584MB heap with 1.45GB instances', () => { + // r2-div-k1: two ~1.35GB instances resident (heapMax 2750MB), rebuild safe + // because evict-before-build frees a slot ahead of the transient peak. + expect(computeCapacityFromBudget(3584 * MB, 1450 * MB, 256 * MB, 768 * MB)).toBe(2); + }); + + it('gives capacity 1 on a 2GB heap with measured 1.45GB instances', () => { + expect(computeCapacityFromBudget(2048 * MB, 1450 * MB, 256 * MB, 768 * MB)).toBe(1); + }); + + it('never returns less than 1 even when nothing fits', () => { + expect(computeCapacityFromBudget(896 * MB, 1450 * MB, 256 * MB, 768 * MB)).toBe(1); + }); + + it('caps at 50 for tiny instances on big heaps', () => { + expect(computeCapacityFromBudget(64 * 1024 * MB, 4 * MB, 256 * MB, 768 * MB)).toBe(50); + }); + + it('applies the rebuild constraint when it is the binding one', () => { + // Residency alone would allow 3 (3*1000+256 <= 3500), but a rebuild with + // 2 residents (2*1000 + 256 + 900 = 3156 <= 3500) is the binding bound: + // byResidency = floor((3500-256)/1000) = 3 + // byRebuild = floor((3500-256-900)/1000) + 1 = 2 + 1 = 3 + expect(computeCapacityFromBudget(3500 * MB, 1000 * MB, 256 * MB, 900 * MB)).toBe(3); + // Shrink the heap so the rebuild constraint bites: + // byResidency = floor((3300-256)/1000) = 3 + // byRebuild = floor((3300-256-900)/1000) + 1 = 2 + 1 = 3 -> still 3; + // push harder: + // byResidency(3256) = 3, byRebuild(3256) = floor(2100/1000)+1 = 3 + // byResidency(3200) = 2 — residency binds again. Use a bigger reserve: + expect(computeCapacityFromBudget(3300 * MB, 1000 * MB, 256 * MB, 1500 * MB)).toBe(2); + }); +}); + +describe('memory governor pressure gate', () => { + const cleanup: Array<() => void> = []; + afterEach(() => { + while (cleanup.length) cleanup.pop()!(); + }); + + const setEnv = (key: string, value: string) => { + const prev = process.env[key]; + process.env[key] = value; + cleanup.push(() => { + if (prev === undefined) delete process.env[key]; + else process.env[key] = prev; + }); + }; + + it('reports ok at normal test-process heap levels', () => { + expect(getMemoryPressure().level).toBe('ok'); + }); + + it('refuses builds and counts them at critical pressure', () => { + // Force the critical watermark below any real process usage. + setEnv('GRAPHILE_MEMORY_GOVERNOR_CRITICAL', '0.0001'); + setEnv('GRAPHILE_MEMORY_GOVERNOR_ELEVATED', '0.00005'); + const before = getCacheCounters().buildRefusals; + const verdict = shouldRefuseBuild(); + expect(verdict.level).toBe('critical'); + expect(verdict.refuseBuild).toBe(true); + expect(getCacheCounters().buildRefusals).toBe(before + 1); + }); + + it('does not refuse builds at elevated pressure', () => { + setEnv('GRAPHILE_MEMORY_GOVERNOR_ELEVATED', '0.0001'); + const before = getCacheCounters().buildRefusals; + const verdict = shouldRefuseBuild(); + expect(verdict.level).toBe('elevated'); + expect(verdict.refuseBuild).toBe(false); + expect(getCacheCounters().buildRefusals).toBe(before); + }); +}); diff --git a/graphile/graphile-cache/src/create-instance.ts b/graphile/graphile-cache/src/create-instance.ts index fc4c625ae2..5787020a5a 100644 --- a/graphile/graphile-cache/src/create-instance.ts +++ b/graphile/graphile-cache/src/create-instance.ts @@ -10,6 +10,11 @@ const log = new Logger('graphile-cache:create'); interface GraphileInstanceOptions { preset: any; cacheKey: string; + /** + * Database name backing this instance's pg pool. Stored on the entry so the + * graphile-cache pgCache cleanup callback can evict it when its pool is disposed. + */ + dbname?: string; /** * When true, a RealtimeManager is created and started alongside the * PostGraphile instance. The pool is extracted from the preset's @@ -37,7 +42,7 @@ interface GraphileInstanceOptions { export const createGraphileInstance = async ( opts: GraphileInstanceOptions ): Promise => { - const { preset, cacheKey, enableRealtime = false } = opts; + const { preset, cacheKey, dbname, enableRealtime = false } = opts; const pgl = postgraphile(preset); const serv = pgl.createServ(grafserv); @@ -53,7 +58,9 @@ export const createGraphileInstance = async ( handler, httpServer, cacheKey, + dbname, createdAt: Date.now(), + inflight: 0, }; if (enableRealtime) { diff --git a/graphile/graphile-cache/src/graphile-cache.ts b/graphile/graphile-cache/src/graphile-cache.ts index 26bbb24c0a..ef257a6c62 100644 --- a/graphile/graphile-cache/src/graphile-cache.ts +++ b/graphile/graphile-cache/src/graphile-cache.ts @@ -1,8 +1,14 @@ import { EventEmitter } from 'events'; +import { getHeapStatistics } from 'node:v8'; import { Logger } from '@pgpmjs/logger'; import { LRUCache } from 'lru-cache'; import { pgCache } from 'pg-cache'; -import type { Express } from 'express'; +import type { + Express, + NextFunction as ExpressNextFunction, + Request as ExpressRequest, + Response as ExpressResponse, +} from 'express'; import type { Server as HttpServer } from 'http'; import type { PostGraphileInstance } from 'postgraphile'; import type { GrafservBase } from 'grafserv'; @@ -12,11 +18,45 @@ const log = new Logger('graphile-cache'); // --- Time Constants --- export const ONE_HOUR_MS = 1000 * 60 * 60; export const FIVE_MINUTES_MS = 1000 * 60 * 5; -const ONE_DAY = ONE_HOUR_MS * 24; -const ONE_YEAR = ONE_DAY * 366; +const SIX_HOURS_MS = ONE_HOUR_MS * 6; // --- Eviction Types --- -export type EvictionReason = 'lru' | 'ttl' | 'manual'; +export type EvictionReason = 'lru' | 'ttl' | 'manual' | 'governor'; + +// --- Cache Counters (in-process metrics) --- +export interface CacheCounters { + evictions: { lru: number; ttl: number; manual: number; governor: number }; + disposals: number; + drainTimeouts: number; + buildRefusals: number; +} + +/** + * Cumulative in-process cache counters for the metrics sampler. Mutated in the LRU + * dispose callback (by eviction reason), in disposeEntry (each distinct disposal), and + * in the drain-timeout warning branch. Zero overhead when the sampler is disabled — the + * increments are a handful of integer bumps on paths that already do real teardown work. + * Read a stable snapshot via getCacheCounters(). + */ +export const cacheCounters: CacheCounters = { + evictions: { lru: 0, ttl: 0, manual: 0, governor: 0 }, + disposals: 0, + drainTimeouts: 0, + buildRefusals: 0 +}; + +/** + * Snapshot the cache counters. Returns a deep copy so callers cannot mutate the live + * counters through the returned object. + */ +export function getCacheCounters(): CacheCounters { + return { + evictions: { ...cacheCounters.evictions }, + disposals: cacheCounters.disposals, + drainTimeouts: cacheCounters.drainTimeouts, + buildRefusals: cacheCounters.buildRefusals + }; +} // --- Cache Event Emitter --- export interface CacheEvictionEvent { @@ -43,30 +83,128 @@ export interface CacheConfig { ttl: number; } +/** + * Empirically, a PostGraphile v5 instance that has served at least one GraphQL + * request retains ~0.5 GB of V8 heap (the fully-materialised GraphQL schema plus + * grafast's per-schema plan machinery; a build-only instance is far smaller, but + * every *cached* instance is, by definition, one that serves requests). The cache + * therefore CANNOT be bounded by entry count alone: `max` heavy instances need + * `max * ~0.5GB` of resident heap, and once that exceeds the V8 old-space limit the + * process OOMs as distinct hosts fill the cache. A fixed default of 50 implies + * ~24 GB of resident schemas — far beyond any normal heap — which is the root cause + * of the schema-builder OOM. We derive a heap-aware default that budgets a fraction + * of the heap for cached instances. Override explicitly with GRAPHILE_CACHE_MAX, and + * tune the per-instance estimate with GRAPHILE_CACHE_INSTANCE_HEAP_BYTES. + */ +// ~0.5 GB retained per query-serving instance (measured against real provisioned apps +// on a small catalog). NOTE: instance heap scales with the TOTAL pg catalog +// (~21 KB per pg_class row measured) — on large multi-tenant catalogs set +// GRAPHILE_CACHE_INSTANCE_HEAP_BYTES to a measured value (e.g. ~1.45 GB at 61k rows). +const DEFAULT_INSTANCE_HEAP_BYTES = 512 * 1024 * 1024; +// Heap reserved for the server itself: express, pools, request working set +// (~+250 MB was measured at 200 rps on top of the resident instance). +const DEFAULT_BASE_RESERVE_BYTES = 256 * 1024 * 1024; +// Heap reserved for ONE in-flight schema build's transient allocations +// (introspection payload + gather + schema construction; >700 MB measured at a +// 61k-pg_class catalog). Builds are serialized by the server's BuildSemaphore, +// and ensureCacheHeadroom evicts down to (max - 1) residents before each build, +// so exactly one transient of this size coexists with (max - 1) residents. +const DEFAULT_BUILD_RESERVE_BYTES = 768 * 1024 * 1024; +// At least one instance must be admitted or nothing can ever build — but never +// more than the heap budget says fit. A floor of 3 admitted two extra builds +// the heap could not hold and aborted the process (V8 heap-limit SIGABRT) +// before eviction ever ran. +const MIN_CACHE_MAX = 1; +const MAX_CACHE_MAX = 50; + +const parseEnvInt = (value: string | undefined, fallback: number): number => { + if (!value) return fallback; + const n = parseInt(value, 10); + return Number.isFinite(n) && n > 0 ? n : fallback; +}; + +/** + * Pure capacity math (exported for tests and diagnostics). + * + * Two constraints bound how many instances fit: + * residency: max * perInstance + baseReserve <= heapLimit + * rebuild: (max - 1) * perInstance + baseReserve + * + buildReserve <= heapLimit + * (the rebuild constraint has (max - 1) residents because evict-before-build + * frees one slot before the transient allocation peaks — validated live: a + * 3584 MB heap holds TWO ~1.35 GB instances and still rebuilds safely). + */ +export function computeCapacityFromBudget( + heapLimit: number, + perInstance: number, + baseReserve: number = DEFAULT_BASE_RESERVE_BYTES, + buildReserve: number = DEFAULT_BUILD_RESERVE_BYTES, +): number { + const byResidency = Math.floor((heapLimit - baseReserve) / perInstance); + const byRebuild = Math.floor((heapLimit - baseReserve - buildReserve) / perInstance) + 1; + const budgeted = Math.min(byResidency, byRebuild); + return Math.min(MAX_CACHE_MAX, Math.max(MIN_CACHE_MAX, budgeted)); +} + +/** + * Heap-aware default for the maximum number of cached PostGraphile instances. + * See computeCapacityFromBudget for the model. Tunables: + * GRAPHILE_CACHE_INSTANCE_HEAP_BYTES — measured per-instance retained heap + * GRAPHILE_CACHE_BASE_RESERVE_BYTES — server base + request working set + * GRAPHILE_CACHE_BUILD_RESERVE_BYTES — one build's transient peak + */ +function computeHeapAwareMax(): number { + try { + const heapLimit = getHeapStatistics().heap_size_limit; // reflects --max-old-space-size + const perInstance = parseEnvInt( + process.env.GRAPHILE_CACHE_INSTANCE_HEAP_BYTES, + DEFAULT_INSTANCE_HEAP_BYTES, + ); + const baseReserve = parseEnvInt( + process.env.GRAPHILE_CACHE_BASE_RESERVE_BYTES, + DEFAULT_BASE_RESERVE_BYTES, + ); + const buildReserve = parseEnvInt( + process.env.GRAPHILE_CACHE_BUILD_RESERVE_BYTES, + DEFAULT_BUILD_RESERVE_BYTES, + ); + return computeCapacityFromBudget(heapLimit, perInstance, baseReserve, buildReserve); + } catch { + return MIN_CACHE_MAX; + } +} + /** * Get cache configuration from environment variables * * Supports: - * - GRAPHILE_CACHE_MAX: Maximum number of entries (default: 50) - * - GRAPHILE_CACHE_TTL_MS: TTL in milliseconds - * - Production default: ONE_YEAR + * - GRAPHILE_CACHE_MAX: Maximum number of entries. Default is heap-aware + * (see computeHeapAwareMax) rather than a fixed 50, because each cached + * instance retains ~0.5 GB and a count-only cap OOMs the process. + * - GRAPHILE_CACHE_INSTANCE_HEAP_BYTES: per-instance heap estimate for the + * heap-aware default (default ~512 MB). + * - GRAPHILE_CACHE_TTL_MS: idle TTL in milliseconds (updateAgeOnGet refreshes it + * on every hit, so this is an idle-expiry, not an absolute lifetime) + * - Production default: SIX_HOURS_MS — an idle tenant's ~0.5 GB instance is + * reclaimed within hours instead of pinned for a year; a later request + * simply rebuilds it * - Development default: FIVE_MINUTES_MS * - * NOTE: This value should be <= PG_CACHE_MAX (also default: 50) so that - * every cached PostGraphile instance has a live pool backing it. + * NOTE: This value should be <= PG_CACHE_MAX so that every cached PostGraphile + * instance has a live pool backing it. */ export function getCacheConfig(): CacheConfig { const isDevelopment = process.env.NODE_ENV === 'development'; const max = process.env.GRAPHILE_CACHE_MAX - ? parseInt(process.env.GRAPHILE_CACHE_MAX, 10) - : 50; + ? parseEnvInt(process.env.GRAPHILE_CACHE_MAX, computeHeapAwareMax()) + : computeHeapAwareMax(); const ttl = process.env.GRAPHILE_CACHE_TTL_MS ? parseInt(process.env.GRAPHILE_CACHE_TTL_MS, 10) : isDevelopment ? FIVE_MINUTES_MS - : ONE_YEAR; + : SIX_HOURS_MS; return { max, ttl }; } @@ -89,16 +227,61 @@ export interface GraphileCacheEntry { httpServer: HttpServer; cacheKey: string; createdAt: number; + /** + * Database name backing this instance's pg pool. Used to evict the entry when its + * pool is disposed (see the pgCache cleanup callback). Distinct from cacheKey, which + * on the public server is the request HOST, not the database. + */ + dbname?: string; /** Optional RealtimeManager for cursor-tracked subscription delivery */ realtimeManager?: { stop(): Promise } | null; + /** + * Number of requests currently executing against this entry's handler. + * Maintained by invokeEntryHandler; disposeEntry drains to 0 (bounded by + * GRAPHILE_CACHE_DRAIN_TIMEOUT_MS) before releasing the instance so eviction + * cannot tear down a schema mid-request. + */ + inflight?: number; + /** Set at the start of disposal; routing must treat the entry as a cache miss. */ + disposing?: boolean; } -// Track disposed entries to prevent double-disposal -const disposedKeys = new Set(); +// Track disposed entries to prevent double-disposal. Keyed by ENTRY IDENTITY (a WeakSet), +// NOT by the cache key. A key-scoped guard caused a same-key disposal race: while entry A +// for key K was mid `pgl.release()` (K parked in the guard), a rebuilt entry B for the SAME +// key K could be evicted and its disposeEntry would short-circuit, silently skipping +// B.pgl.release(). Guarding by entry identity disposes every distinct entry exactly once +// while still allowing a rebuilt entry on the same key to be released. +const disposedEntries = new WeakSet(); // Track keys that are being manually evicted for accurate eviction reason const manualEvictionKeys = new Set(); +// Track keys evicted by the memory governor for accurate eviction reason +const governorEvictionKeys = new Set(); + +// Number of entries currently DRAINING (evicted from the cache but their ~GB of +// heap still live until in-flight requests finish and pgl.release() completes). +// Invisible to ensureCacheHeadroom (they are no longer cache entries), so build +// admission must consult it: a build transient stacked on undrained instances is +// what OOMed the soak (flush -> rebuild race). +let drainingCount = 0; + +export const getDrainingCount = (): number => drainingCount; + +/** + * Hold a build until evicted instances have actually released their memory — + * or heap pressure is comfortable anyway, or the bounded wait expires (drains + * are themselves bounded by GRAPHILE_CACHE_DRAIN_TIMEOUT_MS). + */ +export async function waitForDrainSettle(timeoutMs = 20_000): Promise { + const start = Date.now(); + while (drainingCount > 0 && Date.now() - start < timeoutMs) { + if (getMemoryPressure().level === 'ok') return; + await new Promise((resolve) => setTimeout(resolve, 200)); + } +} + /** * Dispose a PostGraphile v5 cache entry * @@ -106,20 +289,53 @@ const manualEvictionKeys = new Set(); * 1. Closing the HTTP server if listening * 2. Releasing the PostGraphile instance (which internally releases grafserv) * - * Uses disposedKeys set to prevent double-disposal when closeAllCaches() - * explicitly disposes entries and then clear() triggers the dispose callback. + * Uses the disposedEntries WeakSet to prevent double-disposal of the same entry when + * closeAllCaches() explicitly disposes entries and then clear() triggers the dispose + * callback for the same entry. */ const disposeEntry = async (entry: GraphileCacheEntry, key: string): Promise => { - // Prevent double-disposal - if (disposedKeys.has(key)) { + // Prevent double-disposal of the SAME entry (guard by identity, not by key — see the + // disposedEntries declaration for why). + if (disposedEntries.has(entry)) { return; } - disposedKeys.add(key); + disposedEntries.add(entry); + cacheCounters.disposals += 1; + entry.disposing = true; + drainingCount += 1; + try { + await disposeEntryInner(entry, key); + } finally { + drainingCount -= 1; + } +}; + +const disposeEntryInner = async (entry: GraphileCacheEntry, key: string): Promise => { + + // Drain in-flight requests before tearing the instance down. The entry is already + // out of the cache (dispose fires post-removal), so no NEW requests can route here — + // invokeEntryHandler also refuses entries with `disposing` set. Bounded wait: a wedged + // request must not pin ~0.5 GB forever. + const drainTimeoutMs = parseEnvInt(process.env.GRAPHILE_CACHE_DRAIN_TIMEOUT_MS, 30_000); + const drainStart = Date.now(); + while ((entry.inflight ?? 0) > 0 && Date.now() - drainStart < drainTimeoutMs) { + await new Promise((resolve) => setTimeout(resolve, 100)); + } + if ((entry.inflight ?? 0) > 0) { + cacheCounters.drainTimeouts += 1; + log.warn( + `Disposing PostGraphile[${key}] with ${entry.inflight} request(s) still in flight after ${drainTimeoutMs}ms drain timeout`, + ); + } log.debug(`Disposing PostGraphile[${key}]`); try { - // Close HTTP server if it's listening - if (entry.httpServer?.listening) { + // Close the HTTP server. create-instance builds it via createServer() but never + // .listen()s it, so `.listening` is always false — the old guard meant close() never + // ran. Closing unconditionally detaches grafserv's 'upgrade' listener; when the server + // was never listening, close() simply invokes the callback with ERR_SERVER_NOT_RUNNING + // (a harmless no-op here), so the Promise always resolves. + if (entry.httpServer) { await new Promise((resolve) => { entry.httpServer.close(() => resolve()); }); @@ -138,15 +354,18 @@ const disposeEntry = async (entry: GraphileCacheEntry, key: string): Promise { + if (governorEvictionKeys.has(key)) { + governorEvictionKeys.delete(key); + return 'governor'; + } if (manualEvictionKeys.has(key)) { manualEvictionKeys.delete(key); return 'manual'; @@ -165,6 +384,20 @@ const getEvictionReason = (key: string, entry: GraphileCacheEntry): EvictionReas // Get initial cache configuration const initialConfig = getCacheConfig(); +// Surface the resolved instance cap once at startup. Because each cached PostGraphile +// instance retains ~0.5 GB, an oversized cap (relative to the heap) is the primary cause +// of schema-builder OOM — make the chosen value visible to operators. +try { + const heapLimitMb = Math.round(getHeapStatistics().heap_size_limit / (1024 * 1024)); + const source = process.env.GRAPHILE_CACHE_MAX ? 'GRAPHILE_CACHE_MAX' : 'heap-aware default'; + log.info( + `graphileCache max=${initialConfig.max} instances (${source}); heap limit ~${heapLimitMb}MB. ` + + `Each query-serving instance retains ~0.5GB; raise --max-old-space-size or lower GRAPHILE_CACHE_MAX if memory-constrained.`, + ); +} catch { + // ignore — logging is best-effort +} + // --- Graphile Cache --- export const graphileCache = new LRUCache({ max: initialConfig.max, @@ -173,6 +406,7 @@ export const graphileCache = new LRUCache({ dispose: (entry, key) => { // Determine eviction reason before disposal const reason = getEvictionReason(key, entry); + cacheCounters.evictions[reason] += 1; // Emit eviction event cacheEvents.emitEviction({ key, reason, entry }); @@ -187,6 +421,169 @@ export const graphileCache = new LRUCache({ } }); +/** + * Invoke an entry's Express handler with in-flight refcounting. + * + * Returns false WITHOUT invoking when the entry is already being disposed — + * callers must treat that as a cache miss (rebuild) or retry. On invocation, + * the refcount is incremented and released exactly once when the response + * finishes or the connection closes, which is what disposeEntry drains on. + */ +export function invokeEntryHandler( + entry: GraphileCacheEntry, + req: ExpressRequest, + res: ExpressResponse, + next: ExpressNextFunction, +): boolean { + if (entry.disposing) { + return false; + } + entry.inflight = (entry.inflight ?? 0) + 1; + let released = false; + const release = () => { + if (!released) { + released = true; + entry.inflight = Math.max(0, (entry.inflight ?? 1) - 1); + } + }; + // 'close' fires after 'finish' and also on aborted connections; release is idempotent. + res.once('finish', release); + res.once('close', release); + entry.handler(req, res, next); + return true; +} + +/** + * Evict least-recently-used entries until there is room for `slots` new entries + * under the configured max. Called BEFORE building a new instance so the build's + * transient allocation (hundreds of MB) lands on a cache that has already shed + * an instance, instead of stacking a full cache + a build peak (the OOM shape). + */ +export function ensureCacheHeadroom(slots = 1): number { + const { max } = getCacheConfig(); + let evicted = 0; + while (graphileCache.size > Math.max(0, max - slots)) { + // rkeys() iterates least-recently-used first + const oldestKey = graphileCache.rkeys().next().value as string | undefined; + if (oldestKey === undefined) break; + graphileCache.delete(oldestKey); + evicted++; + } + if (evicted > 0) { + log.info(`Evicted ${evicted} instance(s) before build to keep heap headroom (max=${max})`); + } + return evicted; +} + +// --- Memory Governor --- +export type MemoryPressureLevel = 'ok' | 'elevated' | 'critical'; + +export interface MemoryPressure { + level: MemoryPressureLevel; + heapUsed: number; + heapLimit: number; + ratio: number; +} + +const parseEnvFloat = (value: string | undefined, fallback: number): number => { + if (!value) return fallback; + const n = parseFloat(value); + return Number.isFinite(n) && n > 0 && n < 1 ? n : fallback; +}; + +/** + * Current heap pressure against V8's actually-exhaustible headroom + * (used / (used + total_available_size)). + * + * elevated (default >=85%): proactively evict idle instances ahead of the LRU + * schedule. critical (default >=92%): additionally REFUSE to start new schema + * builds (the caller responds 503; resident instances keep serving). A build's + * transient allocations are the largest single spike the process makes — at + * critical pressure admitting one converts degraded service into a V8 + * heap-limit abort for every tenant on the box. + * Tunables: GRAPHILE_MEMORY_GOVERNOR_ELEVATED / GRAPHILE_MEMORY_GOVERNOR_CRITICAL. + */ +export function getMemoryPressure(): MemoryPressure { + const stats = getHeapStatistics(); + const heapLimit = stats.heap_size_limit; + const heapUsed = process.memoryUsage().heapUsed; + // Ratio denominator is used + V8's own remaining-allocatable estimate, NOT + // heap_size_limit: the limit includes young-generation and reserved space the + // old space can never use, so with --max-old-space-size=512 the limit reads + // ~738MB while the process aborts near ~508MB used — a 0.69 "ratio" at the + // moment of death, leaving 0.85/0.92 watermarks unreachable exactly when they + // matter. used/(used+available) approaches 1.0 as the abort nears at every + // heap size. + const available = stats.total_available_size ?? Math.max(0, heapLimit - heapUsed); + const exhaustible = heapUsed + available; + const ratio = exhaustible > 0 ? heapUsed / exhaustible : 0; + const elevated = parseEnvFloat(process.env.GRAPHILE_MEMORY_GOVERNOR_ELEVATED, 0.85); + const critical = parseEnvFloat(process.env.GRAPHILE_MEMORY_GOVERNOR_CRITICAL, 0.92); + const level: MemoryPressureLevel = ratio >= critical ? 'critical' : ratio >= elevated ? 'elevated' : 'ok'; + return { level, heapUsed, heapLimit, ratio }; +} + +/** + * Gate for new schema builds. Returns the pressure snapshot; when + * `refuseBuild` is true the caller must not start a build (respond 503 and + * count it). Cheap enough for the request path: one memoryUsage() call. + */ +export function shouldRefuseBuild(): MemoryPressure & { refuseBuild: boolean } { + const pressure = getMemoryPressure(); + const refuseBuild = pressure.level === 'critical'; + if (refuseBuild) { + cacheCounters.buildRefusals += 1; + log.warn( + `Refusing new schema build at critical heap pressure ` + + `(${Math.round(pressure.ratio * 100)}% of exhaustible headroom used; ` + + `heap limit ${Math.round(pressure.heapLimit / 1048576)}MB)`, + ); + } + return { ...pressure, refuseBuild }; +} + +let governorTimer: ReturnType | null = null; + +/** + * Periodic proactive eviction: at elevated/critical pressure, evict the + * least-recently-used instance (skipping in-flight ones) each tick until + * pressure clears. Disabled with GRAPHILE_MEMORY_GOVERNOR=0. + */ +export function startMemoryGovernor(intervalMs = 10_000): () => void { + if (process.env.GRAPHILE_MEMORY_GOVERNOR === '0') return () => {}; + if (governorTimer) return stopMemoryGovernor; + governorTimer = setInterval(() => { + const pressure = getMemoryPressure(); + if (pressure.level === 'ok') return; + // Evict ONE entry per tick, LRU first, preferring idle entries. + let victim: string | undefined; + for (const key of graphileCache.rkeys()) { + const entry = graphileCache.peek(key); + if (entry && !entry.disposing && (entry.inflight ?? 0) === 0) { + victim = key; + break; + } + if (victim === undefined) victim = key; // fall back to LRU even if busy + } + if (victim === undefined) return; + governorEvictionKeys.add(victim); + log.warn( + `Memory governor evicting PostGraphile[${victim}] at ${pressure.level} pressure ` + + `(heap ${Math.round(pressure.ratio * 100)}%)`, + ); + graphileCache.delete(victim); + }, intervalMs); + if (typeof governorTimer.unref === 'function') governorTimer.unref(); + return stopMemoryGovernor; +} + +export function stopMemoryGovernor(): void { + if (governorTimer) { + clearInterval(governorTimer); + governorTimer = null; + } +} + // --- Cache Stats --- export interface CacheStats { size: number; @@ -235,9 +632,12 @@ export function clearMatchingEntries(pattern: RegExp): number { const unregister = pgCache.registerCleanupCallback((pgPoolKey: string) => { log.debug(`pgPool[${pgPoolKey}] disposed - checking graphile entries`); - // Remove graphile entries that reference this pool key + // Remove graphile entries backed by this pool. Match on the entry's dbname (the pool is + // keyed by database name), NOT on cacheKey: on the public server cacheKey is the request + // HOST, which never contains the database name, so the old `cacheKey.includes(pgPoolKey)` + // test never matched and this safety valve was dead. graphileCache.forEach((entry, k) => { - if (entry.cacheKey.includes(pgPoolKey)) { + if (entry.dbname === pgPoolKey) { log.debug(`Removing graphileCache[${k}] due to pgPool[${pgPoolKey}] disposal`); manualEvictionKeys.add(k); graphileCache.delete(k); @@ -281,11 +681,12 @@ export const closeAllCaches = async (verbose = false): Promise => { // Wait for all disposals to complete await Promise.allSettled(disposePromises); - // Clear the cache after disposal (dispose callback will no-op due to disposedKeys) + // Clear the cache after disposal (dispose callback no-ops: each entry is already + // in the disposedEntries WeakSet from the explicit disposeEntry above). graphileCache.clear(); - // Clear disposed keys tracking after full cleanup - disposedKeys.clear(); + // The disposedEntries WeakSet needs no explicit clearing — entries are reclaimed by + // GC once the cache no longer references them. manualEvictionKeys.clear(); // Close pg pools diff --git a/graphile/graphile-cache/src/index.ts b/graphile/graphile-cache/src/index.ts index e64be532b9..3dec3e4442 100644 --- a/graphile/graphile-cache/src/index.ts +++ b/graphile/graphile-cache/src/index.ts @@ -25,6 +25,28 @@ export { CacheStats, getCacheStats, + // In-process metrics counters + CacheCounters, + cacheCounters, + getCacheCounters, + + // In-flight refcounting + pre-build headroom + invokeEntryHandler, + ensureCacheHeadroom, + + // Capacity model + memory governor + computeCapacityFromBudget, + MemoryPressure, + MemoryPressureLevel, + getMemoryPressure, + shouldRefuseBuild, + startMemoryGovernor, + stopMemoryGovernor, + + // Drain-aware build admission + getDrainingCount, + waitForDrainSettle, + // Clear matching entries clearMatchingEntries } from './graphile-cache'; diff --git a/graphql/server/src/diagnostics/__tests__/metrics-sampler.test.ts b/graphql/server/src/diagnostics/__tests__/metrics-sampler.test.ts new file mode 100644 index 0000000000..57bce236ce --- /dev/null +++ b/graphql/server/src/diagnostics/__tests__/metrics-sampler.test.ts @@ -0,0 +1,123 @@ +import fs from 'node:fs'; +import os from 'node:os'; +import path from 'node:path'; + +import { collectMetricsSample, startMetricsSampler } from '../metrics-sampler'; + +const originalEnv = { ...process.env }; + +const tmpFile = (): string => + path.join(os.tmpdir(), `metrics-sampler-${process.pid}-${Date.now()}-${Math.random().toString(16).slice(2)}.jsonl`); + +const waitForFileContent = async (file: string, timeoutMs = 2_000): Promise => { + const deadline = Date.now() + timeoutMs; + while (Date.now() < deadline) { + try { + const content = await fs.promises.readFile(file, 'utf8'); + if (content.trim().length > 0) { + return content; + } + } catch { + // file not created yet + } + await new Promise((resolve) => setTimeout(resolve, 20)); + } + throw new Error(`metrics file ${file} never received content`); +}; + +afterEach(() => { + process.env = { ...originalEnv }; +}); + +describe('collectMetricsSample', () => { + it('produces a well-formed, JSON-serializable sample', () => { + const sample = collectMetricsSample(); + + expect(typeof sample.ts).toBe('string'); + expect(Number.isNaN(Date.parse(sample.ts))).toBe(false); + expect(typeof sample.rss).toBe('number'); + expect(typeof sample.heapUsed).toBe('number'); + expect(typeof sample.heapTotal).toBe('number'); + expect(typeof sample.external).toBe('number'); + expect(typeof sample.heap_size_limit).toBe('number'); + expect(typeof sample.cache.size).toBe('number'); + expect(typeof sample.cache.keys).toBe('number'); + // counters merge cache counters + graphile counters + build queue depth + expect(typeof sample.counters.disposals).toBe('number'); + expect(typeof sample.counters.evictions.lru).toBe('number'); + expect(typeof sample.counters.builds).toBe('number'); + expect(typeof sample.counters.buildQueueDepth).toBe('number'); + expect(typeof sample.gc).toBe('object'); + + // Round-trips through JSON without loss. + expect(() => JSON.parse(JSON.stringify(sample))).not.toThrow(); + }); +}); + +describe('startMetricsSampler (disabled)', () => { + it('returns null and writes nothing when GRAPHILE_DEBUG_METRICS is unset', async () => { + delete process.env.GRAPHILE_DEBUG_METRICS; + const file = tmpFile(); + process.env.GRAPHILE_DEBUG_METRICS_FILE = file; + + const handle = startMetricsSampler(); + expect(handle).toBeNull(); + + await new Promise((resolve) => setTimeout(resolve, 60)); + expect(fs.existsSync(file)).toBe(false); + }); + + it('returns null when GRAPHILE_DEBUG_METRICS is a falsy string', () => { + process.env.GRAPHILE_DEBUG_METRICS = '0'; + expect(startMetricsSampler()).toBeNull(); + process.env.GRAPHILE_DEBUG_METRICS = 'false'; + expect(startMetricsSampler()).toBeNull(); + }); +}); + +describe('startMetricsSampler (enabled)', () => { + it("writes a parseable JSON line to the configured file when enabled ('1')", async () => { + const file = tmpFile(); + process.env.GRAPHILE_DEBUG_METRICS = '1'; + process.env.GRAPHILE_DEBUG_METRICS_FILE = file; + process.env.GRAPHILE_DEBUG_METRICS_INTERVAL_MS = '50'; + + const handle = startMetricsSampler(); + expect(handle).not.toBeNull(); + + try { + const content = await waitForFileContent(file); + const firstLine = content.trim().split('\n')[0]; + const parsed = JSON.parse(firstLine); + + expect(typeof parsed.ts).toBe('string'); + expect(typeof parsed.rss).toBe('number'); + expect(typeof parsed.heap_size_limit).toBe('number'); + expect(parsed.cache).toBeDefined(); + expect(typeof parsed.counters.disposals).toBe('number'); + expect(typeof parsed.counters.buildQueueDepth).toBe('number'); + expect(parsed.gc).toBeDefined(); + } finally { + handle?.stop(); + await fs.promises.rm(file, { force: true }); + } + }); + + it("also treats 'true' as enabled", async () => { + const file = tmpFile(); + process.env.GRAPHILE_DEBUG_METRICS = 'true'; + process.env.GRAPHILE_DEBUG_METRICS_FILE = file; + process.env.GRAPHILE_DEBUG_METRICS_INTERVAL_MS = '50'; + + const handle = startMetricsSampler(); + expect(handle).not.toBeNull(); + + try { + const content = await waitForFileContent(file); + expect(() => JSON.parse(content.trim().split('\n')[0])).not.toThrow(); + } finally { + handle?.stop(); + await fs.promises.rm(file, { force: true }); + } + }); +}); diff --git a/graphql/server/src/diagnostics/connection-error-guard.ts b/graphql/server/src/diagnostics/connection-error-guard.ts new file mode 100644 index 0000000000..2a846730ce --- /dev/null +++ b/graphql/server/src/diagnostics/connection-error-guard.ts @@ -0,0 +1,97 @@ +import { Logger } from '@pgpmjs/logger'; + +const log = new Logger('connection-guard'); + +/** + * Process-level guard for connection-class failures. + * + * A multi-tenant server holds many long-lived PostgreSQL connections (service + * pools, LISTEN/NOTIFY, introspection checkouts). When PostgreSQL restarts or + * crash-recovers (failover, OOM-killed backend, admin restart), every one of + * those sockets dies at once. Most owners handle their own errors (pg-cache + * pools, the schema listener), but a checkout that is mid-query when the + * server goes away can surface as an unhandled 'error' event on a raw pg + * Client — which kills the WHOLE process, turning a ~15s PostgreSQL recovery + * into a full outage for every tenant (observed live during scale validation: + * an introspection backend was OOM-killed, PG crash-recovered, and the node + * process exited on the orphaned client error). + * + * This guard absorbs ONLY connection-class errors (logged, counted); anything + * else preserves fatal semantics via process.exit(1). Pools reconnect on the + * next checkout, so the correct behavior after PG recovery is a brief burst + * of 5xx followed by self-healing — not process death. + * + * Disable with GRAPHILE_CONNECTION_GUARD=0. + */ +const CONN_ERROR_CODES = new Set([ + '57P01', // admin_shutdown (pg_terminate_backend / restart) + '57P02', // crash_shutdown + '57P03', // cannot_connect_now (recovery in progress) + '08006', // connection_failure + '08003', // connection_does_not_exist + '53300', // too_many_connections + 'ECONNRESET', + 'ECONNREFUSED', + 'EPIPE' +]); + +const CONN_ERROR_RE = + /connection terminated|terminating connection|server closed the connection|connection ended|client has encountered a connection error/i; + +export const isConnectionClassError = (err: unknown): boolean => { + if (!(err instanceof Error)) return false; + const code = (err as Error & { code?: string }).code; + if (code && CONN_ERROR_CODES.has(code)) return true; + return CONN_ERROR_RE.test(err.message || ''); +}; + +export interface ConnectionErrorGuardCounters { + absorbedExceptions: number; + absorbedRejections: number; +} + +const counters: ConnectionErrorGuardCounters = { + absorbedExceptions: 0, + absorbedRejections: 0 +}; + +export const getConnectionErrorGuardCounters = (): ConnectionErrorGuardCounters => ({ ...counters }); + +let installed = false; + +export function installConnectionErrorGuard(): void { + if (installed) return; + if (process.env.GRAPHILE_CONNECTION_GUARD === '0') return; + installed = true; + + process.on('uncaughtException', (err) => { + if (isConnectionClassError(err)) { + counters.absorbedExceptions++; + log.error( + `Absorbed connection-class exception (PG restart/failover?): ${(err as Error).message} ` + + `[absorbed=${counters.absorbedExceptions}] — pools reconnect on next checkout` + ); + return; + } + // Preserve fatal semantics for everything else. + // eslint-disable-next-line no-console + console.error('Uncaught exception (fatal):', err); + process.exit(1); + }); + + process.on('unhandledRejection', (reason) => { + if (isConnectionClassError(reason)) { + counters.absorbedRejections++; + log.error( + `Absorbed connection-class rejection (PG restart/failover?): ${(reason as Error).message} ` + + `[absorbed=${counters.absorbedRejections}]` + ); + return; + } + // eslint-disable-next-line no-console + console.error('Unhandled rejection (fatal):', reason); + process.exit(1); + }); + + log.info('connection-error guard installed (disable with GRAPHILE_CONNECTION_GUARD=0)'); +} diff --git a/graphql/server/src/diagnostics/metrics-sampler.ts b/graphql/server/src/diagnostics/metrics-sampler.ts new file mode 100644 index 0000000000..f16b7634fb --- /dev/null +++ b/graphql/server/src/diagnostics/metrics-sampler.ts @@ -0,0 +1,213 @@ +import fs from 'node:fs'; +import { constants as perfConstants, PerformanceObserver } from 'node:perf_hooks'; +import v8 from 'node:v8'; +import { Logger } from '@pgpmjs/logger'; +import { getCacheCounters, getCacheStats } from 'graphile-cache'; + +import { getBuildQueueDepth, getGraphileCounters } from '../middleware/graphile'; +import { getConnectionErrorGuardCounters } from './connection-error-guard'; + +const log = new Logger('metrics-sampler'); + +const DEFAULT_INTERVAL_MS = 10_000; +const DEFAULT_METRICS_FILE = './metrics.jsonl'; + +// ============================================================================= +// GC tracking (perf_hooks) +// +// A single process-global PerformanceObserver accumulates GC pause time and counts +// by kind. Registered lazily the first time the sampler starts (so there is zero +// overhead when GRAPHILE_DEBUG_METRICS is off) and torn down when the sampler stops. +// ============================================================================= + +interface GcKindStat { + count: number; + totalPauseMs: number; +} + +type GcStats = Record; + +const gcStats: GcStats = {}; +let gcObserver: PerformanceObserver | null = null; + +// Map perf_hooks GC kind flags to stable, human-readable names for the metrics line. +const GC_KIND_NAMES: Record = { + [perfConstants.NODE_PERFORMANCE_GC_MINOR]: 'minor', + [perfConstants.NODE_PERFORMANCE_GC_MAJOR]: 'major', + [perfConstants.NODE_PERFORMANCE_GC_INCREMENTAL]: 'incremental', + [perfConstants.NODE_PERFORMANCE_GC_WEAKCB]: 'weakcb' +}; + +const startGcObserver = (): void => { + if (gcObserver) { + return; + } + try { + const observer = new PerformanceObserver((list) => { + for (const entry of list.getEntries()) { + // `detail.kind` is the modern accessor; fall back to the deprecated top-level + // `kind` for older Node. Guard: unknown kinds are bucketed by their numeric flag. + const kind = + (entry as { detail?: { kind?: number } }).detail?.kind ?? + (entry as unknown as { kind?: number }).kind; + const name = + kind != null && GC_KIND_NAMES[kind] ? GC_KIND_NAMES[kind] : `kind_${kind ?? 'unknown'}`; + const stat = gcStats[name] ?? (gcStats[name] = { count: 0, totalPauseMs: 0 }); + stat.count += 1; + stat.totalPauseMs += entry.duration; + } + }); + observer.observe({ entryTypes: ['gc'] }); + gcObserver = observer; + } catch (err) { + // GC observation is best-effort; a platform without 'gc' entries just omits GC data. + gcObserver = null; + log.warn('GC PerformanceObserver unavailable; metrics will omit GC data', err); + } +}; + +const stopGcObserver = (): void => { + if (gcObserver) { + try { + gcObserver.disconnect(); + } catch { + // ignore — teardown is best-effort + } + gcObserver = null; + } +}; + +const snapshotGcStats = (): GcStats => { + const out: GcStats = {}; + for (const [name, stat] of Object.entries(gcStats)) { + out[name] = { count: stat.count, totalPauseMs: stat.totalPauseMs }; + } + return out; +}; + +// ============================================================================= +// Env parsing +// ============================================================================= + +const isEnabled = (): boolean => { + const raw = process.env.GRAPHILE_DEBUG_METRICS; + if (!raw) { + return false; + } + const normalized = raw.trim().toLowerCase(); + return normalized === '1' || normalized === 'true'; +}; + +const getIntervalMs = (): number => { + const raw = process.env.GRAPHILE_DEBUG_METRICS_INTERVAL_MS; + const parsed = raw ? Number.parseInt(raw, 10) : DEFAULT_INTERVAL_MS; + return Number.isFinite(parsed) && parsed > 0 ? parsed : DEFAULT_INTERVAL_MS; +}; + +const getMetricsFile = (): string => + process.env.GRAPHILE_DEBUG_METRICS_FILE || DEFAULT_METRICS_FILE; + +// ============================================================================= +// Sample +// ============================================================================= + +export interface MetricsSample { + ts: string; + rss: number; + heapUsed: number; + heapTotal: number; + external: number; + heap_size_limit: number; + cache: { + size: number; + keys: number; + }; + counters: ReturnType & + ReturnType & { + buildQueueDepth: number; + connGuard: ReturnType; + }; + gc: GcStats; +} + +/** + * Collect a single metrics sample. Cheap: a memoryUsage() call, a v8 heap-stats read, + * cache size/key-count, and integer counter snapshots. Exposed for tests and future + * promotion to a /metrics endpoint. + */ +export const collectMetricsSample = (): MetricsSample => { + const mem = process.memoryUsage(); + const cacheStats = getCacheStats(); + return { + ts: new Date().toISOString(), + rss: mem.rss, + heapUsed: mem.heapUsed, + heapTotal: mem.heapTotal, + external: mem.external, + heap_size_limit: v8.getHeapStatistics().heap_size_limit, + cache: { + size: cacheStats.size, + keys: cacheStats.keys.length + }, + counters: { + ...getCacheCounters(), + ...getGraphileCounters(), + buildQueueDepth: getBuildQueueDepth(), + connGuard: getConnectionErrorGuardCounters() + }, + gc: snapshotGcStats() + }; +}; + +// ============================================================================= +// Sampler +// ============================================================================= + +export interface MetricsSamplerHandle { + stop(): void; +} + +/** + * Start the in-process metrics sampler. + * + * When GRAPHILE_DEBUG_METRICS is '1' or 'true', appends one JSON line per + * GRAPHILE_DEBUG_METRICS_INTERVAL_MS (default 10000ms) to GRAPHILE_DEBUG_METRICS_FILE + * (default ./metrics.jsonl). The interval timer is unref'd so it never keeps the + * process alive, and file writes swallow errors so metrics can never affect the server. + * + * Returns null (a true no-op, zero overhead) when disabled. + */ +export const startMetricsSampler = (): MetricsSamplerHandle | null => { + if (!isEnabled()) { + return null; + } + + startGcObserver(); + + const intervalMs = getIntervalMs(); + const file = getMetricsFile(); + + const writeSample = (): void => { + const line = `${JSON.stringify(collectMetricsSample())}\n`; + // Fire-and-forget; a failed metrics write must never impact request handling. + fs.appendFile(file, line, () => { + // swallow errors + }); + }; + + // Emit an immediate baseline sample so the file has a line without waiting a full + // interval, then sample periodically. + writeSample(); + + const timer = setInterval(writeSample, intervalMs); + timer.unref(); + + log.info(`Metrics sampler writing every ${intervalMs}ms to ${file}`); + + return { + stop(): void { + clearInterval(timer); + stopGcObserver(); + } + }; +}; diff --git a/graphql/server/src/middleware/__tests__/build-timeout.test.ts b/graphql/server/src/middleware/__tests__/build-timeout.test.ts new file mode 100644 index 0000000000..742c2df013 --- /dev/null +++ b/graphql/server/src/middleware/__tests__/build-timeout.test.ts @@ -0,0 +1,57 @@ +import { BuildRefusedError, raceBuildAgainstTimeout } from '../graphile'; + +describe('BuildRefusedError', () => { + it('carries the 503 mapping contract (code + name) and the pressure ratio', () => { + const err = new BuildRefusedError(0.934); + expect(err.code).toBe('SERVICE_OVERLOADED'); + expect(err.name).toBe('BuildRefusedError'); + expect(err.message).toContain('0.93'); + expect(err).toBeInstanceOf(Error); + }); +}); + +describe('raceBuildAgainstTimeout', () => { + beforeEach(() => { + jest.useFakeTimers(); + }); + + afterEach(() => { + jest.useRealTimers(); + }); + + it('returns the built value and disarms the timer when the build wins', async () => { + const instance = { handler: 'built' }; + const result = await raceBuildAgainstTimeout(Promise.resolve(instance), 180_000); + expect(result).toBe(instance); + // The load-bearing assertion: an armed timer here retains the built instance + // through the race reaction chain for the full timeout (the evict-churn OOM). + expect(jest.getTimerCount()).toBe(0); + }); + + it('returns null when the wait expires, leaving no armed timer', async () => { + const never = new Promise(() => {}); + const race = raceBuildAgainstTimeout(never, 180_000); + jest.advanceTimersByTime(180_000); + await expect(race).resolves.toBeNull(); + expect(jest.getTimerCount()).toBe(0); + }); + + it('disarms the timer when the build rejects', async () => { + const boom = new Error('build failed'); + await expect(raceBuildAgainstTimeout(Promise.reject(boom), 180_000)).rejects.toBe(boom); + expect(jest.getTimerCount()).toBe(0); + }); + + it('propagates a late build failure to no one after a timeout (no unhandled timer state)', async () => { + let rejectBuild: (err: Error) => void; + const build = new Promise((_resolve, reject) => { + rejectBuild = reject; + }); + build.catch(() => { /* the dispatcher attaches its own handler; mirror that */ }); + const race = raceBuildAgainstTimeout(build, 1_000); + jest.advanceTimersByTime(1_000); + await expect(race).resolves.toBeNull(); + expect(jest.getTimerCount()).toBe(0); + rejectBuild!(new Error('late failure')); + }); +}); diff --git a/graphql/server/src/middleware/__tests__/graphile-recoalesce.test.ts b/graphql/server/src/middleware/__tests__/graphile-recoalesce.test.ts new file mode 100644 index 0000000000..7ea244f2f1 --- /dev/null +++ b/graphql/server/src/middleware/__tests__/graphile-recoalesce.test.ts @@ -0,0 +1,79 @@ +import type { NextFunction, Request, Response } from 'express'; +import type { GraphileCacheEntry } from 'graphile-cache'; + +import { BuildRefusedError, clearInFlightMap, graphile, setInFlightForTest } from '../graphile'; + +/** + * Regression test for the Phase C re-coalesce load-shed hole. + * + * Contract (commit 46636d4b4): BuildRefusedError maps to 503 SERVICE_OVERLOADED + + * Retry-After "for the requester and every coalesced waiter." A re-coalescing + * waiter awaits a fresh in-flight build at the Phase C re-coalesce await. Pre-fix + * that await was unguarded, so a BuildRefusedError surfacing there escaped to the + * outer catch and became a generic 500 INTERNAL_ERROR with no Retry-After — + * contradicting the contract on the exact memory-pressure path the error exists for. + * + * The re-coalesce await is reached before the request-time pressure gate, so the + * real (empty) cache naturally misses and no build machinery runs; seeding the + * in-flight map with a rejecting promise drives the path deterministically. + */ +describe('graphile dispatcher — Phase C re-coalesce refusal mapping', () => { + const key = 'svc-recoalesce-test'; + + const makeRes = () => { + const headers: Record = {}; + const res: any = { headersSent: false }; + res.setHeader = jest.fn((name: string, value: string) => { + headers[name] = value; + }); + res.status = jest.fn((code: number) => { + res.statusCode = code; + return res; + }); + res.json = jest.fn((payload: unknown) => { + res.body = payload; + return res; + }); + return { res: res as Response, headers }; + }; + + const makeReq = (): Request => + ({ + requestId: 'test-req', + svc_key: key, + api: { + dbname: 'constructive', + anonRole: 'anon', + roleName: 'authenticated', + schema: ['app-public'] + } + } as unknown as Request); + + afterEach(() => { + clearInFlightMap(); + }); + + it('maps a BuildRefusedError on the re-coalesce await to 503 SERVICE_OVERLOADED + Retry-After', async () => { + // A rejecting in-flight promise that is NOT self-deleting, so it survives from + // Phase B (which falls through on the rejection) into the Phase C re-coalesce + // read — mirroring a fresh owner's build that refuses under late heap pressure. + const refused: Promise = Promise.reject(new BuildRefusedError(0.98)); + refused.catch(() => { /* guard: both awaits inside the dispatcher handle it */ }); + setInFlightForTest(key, refused); + + const handler = graphile({} as never); + const { res, headers } = makeRes(); + const next = jest.fn() as unknown as NextFunction; + + await handler(makeReq(), res, next); + + expect((res.status as jest.Mock)).toHaveBeenCalledWith(503); + expect(headers['Retry-After']).toBe('15'); + expect((res.json as jest.Mock).mock.calls[0][0]).toEqual({ + error: { code: 'SERVICE_OVERLOADED', message: 'Server is at critical memory pressure; retry shortly' } + }); + // The pre-fix defect: a generic 500 with no Retry-After from the outer catch. + expect((res.status as jest.Mock)).not.toHaveBeenCalledWith(500); + expect(next).not.toHaveBeenCalled(); + }); +}); diff --git a/graphql/server/src/middleware/graphile.ts b/graphql/server/src/middleware/graphile.ts index 477e61288b..0fdae99cae 100644 --- a/graphql/server/src/middleware/graphile.ts +++ b/graphql/server/src/middleware/graphile.ts @@ -3,8 +3,22 @@ import { getNodeEnv } from '@pgpmjs/env'; import type { ConstructiveOptions } from '@constructive-io/graphql-types'; import { Logger } from '@pgpmjs/logger'; import type { NextFunction, Request, RequestHandler, Response } from 'express'; -import type { GraphQLError, GraphQLFormattedError } from 'grafast/graphql'; -import { createGraphileInstance, type GraphileCacheEntry, graphileCache } from 'graphile-cache'; +// Type-only import of the canonical GraphQL error types. Imported from 'graphql' +// (a direct, version-pinned dependency) rather than the 'grafast/graphql' subpath so +// the types resolve under every moduleResolution mode — including ts-jest, which type- +// checks this file transitively via the diagnostics metrics sampler. Erased at runtime. +import type { GraphQLError, GraphQLFormattedError } from 'graphql'; +import type { Pool } from 'pg'; +import { + createGraphileInstance, + ensureCacheHeadroom, + getMemoryPressure, + type GraphileCacheEntry, + graphileCache, + invokeEntryHandler, + shouldRefuseBuild, + waitForDrainSettle, +} from 'graphile-cache'; import type { GraphileConfig } from 'graphile-config'; import { createConstructivePreset, makePgService } from 'graphile-settings'; import { getPgPool } from 'pg-cache'; @@ -191,6 +205,95 @@ export function clearInFlightMap(): void { creating.clear(); } +/** + * Seeds an in-flight creation promise for a key. Used for testing purposes to + * exercise the coalescing paths (Phase B / Phase C re-coalesce) deterministically. + */ +export function setInFlightForTest(key: string, promise: Promise): void { + creating.set(key, promise); +} + +// ============================================================================= +// Build Admission Control +// ============================================================================= + +/** + * Bounds how many PostGraphile schema builds run concurrently across ALL cache + * keys (the single-flight map only dedups builds for the SAME key). Each build + * transiently allocates hundreds of MB, so concurrent builds of different + * tenants stack those peaks on top of the resident cache — the OOM shape. + * Default 1: builds queue and run serially. Override with GRAPHILE_BUILD_CONCURRENCY. + */ +class BuildSemaphore { + private active = 0; + private waiters: Array<() => void> = []; + constructor(private readonly capacity: number) {} + + async acquire(): Promise { + if (this.active < this.capacity) { + this.active++; + return; + } + await new Promise((resolve) => this.waiters.push(resolve)); + this.active++; + } + + release(): void { + this.active = Math.max(0, this.active - 1); + const wake = this.waiters.shift(); + if (wake) wake(); + } + + /** Number of builds currently queued (blocked on a free slot). */ + get queueDepth(): number { + return this.waiters.length; + } +} + +const parseBuildConcurrency = (): number => { + const raw = process.env.GRAPHILE_BUILD_CONCURRENCY; + const n = raw ? parseInt(raw, 10) : 1; + return Number.isFinite(n) && n > 0 ? n : 1; +}; + +const buildSemaphore = new BuildSemaphore(parseBuildConcurrency()); + +/** + * Returns the number of PostGraphile schema builds currently queued behind the + * build-concurrency semaphore. A persistently non-zero depth means builds are + * arriving faster than they can be serialized — a leading indicator of build + * backpressure under load. Exposed for the metrics sampler. + */ +export function getBuildQueueDepth(): number { + return buildSemaphore.queueDepth; +} + +// ============================================================================= +// In-Process Build Counters (metrics) +// ============================================================================= + +export interface GraphileCounters { + /** Total PostGraphile schema builds started (past coalescing + the semaphore). */ + builds: number; + /** Requests that gave up waiting on a build (GRAPHILE_BUILD_TIMEOUT_MS) and got 503. */ + buildWaitTimeouts: number; +} + +/** + * Cumulative in-process build counters for the metrics sampler. Mutated where a build + * starts. Zero overhead when the sampler is off — these are integer bumps on paths + * that already do real build work. + */ +const graphileCounters: GraphileCounters = { + builds: 0, + buildWaitTimeouts: 0 +}; + +/** Snapshot the build counters. Returns a copy so callers cannot mutate live state. */ +export function getGraphileCounters(): GraphileCounters { + return { ...graphileCounters }; +} + const log = new Logger('graphile'); const reqLabel = (req: Request): string => (req.requestId ? `[${req.requestId}]` : '[req]'); @@ -203,13 +306,13 @@ const reqLabel = (req: Request): string => (req.requestId ? `[${req.requestId}]` * (everything on except aggregates). */ const buildPreset = ( - pool: import('pg').Pool, + pool: Pool, schemas: string[], anonRole: string, roleName: string, databaseSettings?: DatabaseSettings, ): GraphileConfig.Preset => { - return { + const preset: GraphileConfig.Preset = { extends: [createConstructivePreset(databaseSettings)], plugins: [AuthCookiePlugin], pgServices: [ @@ -221,7 +324,9 @@ const buildPreset = ( grafserv: { graphqlPath: '/graphql', graphiqlPath: '/graphiql', - graphiql: true, + // GraphiQL (ruru) assets/handlers are per-instance overhead and an unnecessary + // prod surface — enable only in development, or explicitly via GRAPHILE_GRAPHIQL=true. + graphiql: getNodeEnv() === 'development' || process.env.GRAPHILE_GRAPHIQL === 'true', graphiqlOnGraphQLGET: false, maskError, }, @@ -299,12 +404,71 @@ const buildPreset = ( }; }, }, + }; + + return preset; }; + +/** + * Bound how long a REQUEST waits on a build, ALWAYS clearing the timeout timer. + * + * The build itself is not cancelled — makeSchema cannot be aborted — it completes + * in the background and fills the cache for retries. Resolves to the built value + * when the build wins, or `null` when the wait expires. + * + * Why the finally/clearTimeout is load-bearing: `Promise.race` subscribes reactions + * to BOTH arms. If the timeout timer is left armed after the build wins, Node's + * internal timers list keeps the timeout arm's reaction — and, transitively through + * the race result promise, the built ~15MB instance — reachable for the full + * `timeoutMs` (default 180s). Under evict-churn (GRAPHILE_CACHE_MAX=1) every built + * instance stays pinned past its cache eviction, stacking ~2 builds/s × ~15MB × 180s + * far beyond the heap ceiling and OOMing the process. `.unref()` only removes + * event-loop keepalive, NOT GC retention — the timer must be cleared. clearTimeout() + * removes the Timeout from the timers list so the whole chain is collectable the + * instant the cache evicts the entry. + */ +/** + * Thrown from inside the build critical section when heap pressure reaches + * critical between a request's admission check and the build's actual start. + * The dispatcher maps it (for the requester and every coalesced waiter) to + * 503 SERVICE_OVERLOADED instead of a generic 500. + */ +export class BuildRefusedError extends Error { + readonly code = 'SERVICE_OVERLOADED'; + constructor(ratio: number) { + super(`Schema build refused at critical heap pressure (ratio ${ratio.toFixed(2)})`); + this.name = 'BuildRefusedError'; + } +} + +export const raceBuildAgainstTimeout = async ( + buildPromise: Promise, + timeoutMs: number, +): Promise => { + let timer: ReturnType | undefined; + const timeoutPromise = new Promise((resolve) => { + timer = setTimeout(() => resolve(null), timeoutMs); + timer.unref?.(); + }); + try { + return await Promise.race([buildPromise, timeoutPromise]); + } finally { + // Disarm the timer whether the build won, timed out, or rejected — otherwise + // the armed Timeout pins the built instance via the race reaction chain. + clearTimeout(timer); + } }; export const graphile = (opts: ConstructiveOptions): RequestHandler => { const observabilityEnabled = isGraphqlObservabilityEnabled(opts.server?.host); + // Pause between build STARTS while heap pressure is elevated (ms; 0 disables). + // Bounds the allocation rate of an eviction-churn storm so GC keeps pace. + const buildPressureSpacingMs = (() => { + const n = parseInt(process.env.GRAPHILE_BUILD_PRESSURE_SPACING_MS || '', 10); + return Number.isFinite(n) && n >= 0 ? n : 250; + })(); + return async (req: Request, res: Response, next: NextFunction) => { const label = reqLabel(req); try { @@ -326,8 +490,12 @@ export const graphile = (opts: ConstructiveOptions): RequestHandler => { // ========================================================================= const cached = graphileCache.get(key); if (cached) { - log.debug(`${label} PostGraphile cache hit key=${key} db=${dbname} schemas=${schemaLabel}`); - return cached.handler(req, res, next); + if (invokeEntryHandler(cached, req, res, next)) { + log.debug(`${label} PostGraphile cache hit key=${key} db=${dbname} schemas=${schemaLabel}`); + return; + } + // Entry is mid-disposal — fall through and rebuild. + log.debug(`${label} PostGraphile cache hit on disposing entry key=${key}; rebuilding`); } log.debug(`${label} PostGraphile cache miss key=${key} db=${dbname} schemas=${schemaLabel}`); @@ -340,7 +508,11 @@ export const graphile = (opts: ConstructiveOptions): RequestHandler => { log.debug(`${label} Coalescing request for PostGraphile[${key}] - waiting for in-flight creation`); try { const instance = await inFlight; - return instance.handler(req, res, next); + if (invokeEntryHandler(instance, req, res, next)) { + return; + } + log.debug(`${label} Coalesced instance already disposing for PostGraphile[${key}], retrying`); + // Fall through to Phase C to retry creation } catch (error) { log.warn(`${label} Coalesced request failed for PostGraphile[${key}], retrying`); // Fall through to Phase C to retry creation @@ -353,17 +525,54 @@ export const graphile = (opts: ConstructiveOptions): RequestHandler => { // Re-check cache after coalesced request failure (another retry may have succeeded) const recheckedCache = graphileCache.get(key); - if (recheckedCache) { + if (recheckedCache && invokeEntryHandler(recheckedCache, req, res, next)) { log.debug(`${label} PostGraphile cache hit on re-check key=${key}`); - return recheckedCache.handler(req, res, next); + return; } // Re-check in-flight map (another retry may have started creation) const retryInFlight = creating.get(key); if (retryInFlight) { log.debug(`${label} Re-coalescing request for PostGraphile[${key}]`); - const retryInstance = await retryInFlight; - return retryInstance.handler(req, res, next); + try { + const retryInstance = await retryInFlight; + if (invokeEntryHandler(retryInstance, req, res, next)) { + return; + } + log.warn(`${label} Re-coalesced instance already disposing for PostGraphile[${key}]`); + return res.status(503).json({ + error: { code: 'SERVICE_ROTATING', message: 'Service is restarting, please retry' } + }); + } catch (error) { + // A refusal surfacing on the re-coalesce await is bound by the same + // contract as the owner path and the request-time gate below: + // 503 SERVICE_OVERLOADED + Retry-After for every coalesced waiter, never + // a generic 500. Other rejections fall through to retry the build here, + // exactly as Phase B does. + if (error instanceof BuildRefusedError) { + log.warn(`${label} ${error.message} key=${key}`); + res.setHeader('Retry-After', '15'); + return res.status(503).json({ + error: { code: 'SERVICE_OVERLOADED', message: 'Server is at critical memory pressure; retry shortly' } + }); + } + log.warn(`${label} Re-coalesced request failed for PostGraphile[${key}], retrying`); + // Fall through to build below. + } + } + + // Memory governor gate: at critical heap pressure a build's transient + // allocation (hundreds of MB to >700MB on large catalogs) would abort the + // whole process. Resident instances keep serving; only NEW builds refuse. + const pressure = shouldRefuseBuild(); + if (pressure.refuseBuild) { + res.setHeader('Retry-After', '15'); + return res.status(503).json({ + error: { + code: 'SERVICE_OVERLOADED', + message: 'Server is at critical memory pressure; retry shortly' + } + }); } log.info( @@ -381,27 +590,115 @@ export const graphile = (opts: ConstructiveOptions): RequestHandler => { // Create promise and store in in-flight map BEFORE try block const preset = buildPreset(pool, schema || [], anonRole, roleName, api.databaseSettings); - const creationPromise = observeGraphileBuild( - { - cacheKey: key, - serviceKey: key, - databaseId: api.databaseId ?? null, - }, - () => createGraphileInstance({ - preset, - cacheKey: key, - enableRealtime: api.databaseSettings?.enableRealtime, - }), - { enabled: observabilityEnabled }, - ); + const creationPromise = (async (): Promise => { + // Serialize builds process-wide: each build transiently allocates hundreds of MB, + // and only same-key builds are deduped by the single-flight map above. + await buildSemaphore.acquire(); + try { + // While queued for the slot another request may have finished this key. + const builtMeanwhile = graphileCache.get(key); + if (builtMeanwhile) { + return builtMeanwhile; + } + // Evict the LRU instance BEFORE building so the build peak lands on freed + // headroom instead of stacking on a full cache. + ensureCacheHeadroom(1); + // Evicted != freed: a draining instance's ~GB stays live until its + // in-flight requests finish and release completes. Stacking the build + // transient on undrained instances OOMed the soak — wait them out + // (bounded; returns immediately when heap pressure is already ok). + await waitForDrainSettle(); + // The request-time pressure gate can be seconds stale by the time a + // queued build reaches this point: under an eviction-churn storm the + // dispatcher sustains tens of builds/s, each retaining ~15MB until GC + // catches up, so heap can cross from ok to fatal between two request + // admissions. Re-check at the point of allocation — and under elevated + // pressure pause once (semaphore held, so this spaces GLOBAL build + // starts) to give mark-compact a window before committing the next + // transient. + let latePressure = getMemoryPressure(); + if (latePressure.level === 'elevated' && buildPressureSpacingMs > 0) { + await new Promise((resolve) => setTimeout(resolve, buildPressureSpacingMs)); + latePressure = getMemoryPressure(); + } + if (latePressure.level === 'critical') { + const refusal = shouldRefuseBuild(); + if (refusal.refuseBuild) { + throw new BuildRefusedError(refusal.ratio); + } + } + // A build genuinely starts here: past single-flight coalescing, past the + // build semaphore, and past the built-meanwhile re-check. + graphileCounters.builds += 1; + return await observeGraphileBuild( + { + cacheKey: key, + serviceKey: key, + databaseId: api.databaseId ?? null, + }, + () => createGraphileInstance({ + preset, + cacheKey: key, + dbname, + enableRealtime: api.databaseSettings?.enableRealtime, + }), + { enabled: observabilityEnabled }, + ); + } finally { + buildSemaphore.release(); + } + })(); creating.set(key, creationPromise); + // Populate the cache and clear the in-flight slot when the BUILD settles + // (not when this request finishes): a request that stops waiting + // (build-timeout below) must leave coalescing intact for followers, and + // the finished build must land in the cache for their retries. + creationPromise + .then((instance) => { + graphileCache.set(key, instance); + log.info(`${label} Cached PostGraphile v5 handler key=${key} db=${dbname}`); + }) + .catch(() => { + /* logged by the awaiting branch (or a coalesced waiter) below */ + }) + .finally(() => { + creating.delete(key); + }); + try { - const instance = await creationPromise; - graphileCache.set(key, instance); - log.info(`${label} Cached PostGraphile v5 handler key=${key} db=${dbname}`); - return instance.handler(req, res, next); + // Bound how long a REQUEST waits on a build (queue time + build time). + const timeoutMs = (() => { + const n = parseInt(process.env.GRAPHILE_BUILD_TIMEOUT_MS || '', 10); + return Number.isFinite(n) && n > 0 ? n : 180_000; + })(); + const instance = await raceBuildAgainstTimeout(creationPromise, timeoutMs); + if (instance === null) { + graphileCounters.buildWaitTimeouts += 1; + log.warn(`${label} Request timed out after ${timeoutMs}ms waiting for PostGraphile[${key}] build`); + res.setHeader('Retry-After', '15'); + return res.status(503).json({ + error: { code: 'BUILD_TIMEOUT', message: 'Schema build in progress; retry shortly' } + }); + } + if (invokeEntryHandler(instance, req, res, next)) { + return; + } + log.warn(`${label} Freshly built instance already disposing for PostGraphile[${key}]`); + return res.status(503).json({ + error: { code: 'SERVICE_ROTATING', message: 'Service is restarting, please retry' } + }); } catch (error) { + // Pressure refusal from inside the critical section: same contract as the + // request-time gate — 503 + Retry-After for the requester and every + // coalesced waiter, never a generic 500. + if (error instanceof BuildRefusedError) { + log.warn(`${label} ${error.message} key=${key}`); + res.setHeader('Retry-After', '15'); + return res.status(503).json({ + error: { code: 'SERVICE_OVERLOADED', message: 'Server is at critical memory pressure; retry shortly' } + }); + } log.error(`${label} Failed to create PostGraphile[${key}]:`, error); throw new HandlerCreationError( `Failed to create handler for ${key}: ${error instanceof Error ? error.message : String(error)}`, @@ -410,9 +707,6 @@ export const graphile = (opts: ConstructiveOptions): RequestHandler => { cause: error instanceof Error ? error.message : String(error), }, ); - } finally { - // Always clean up in-flight tracker - creating.delete(key); } } catch (e: any) { log.error(`${label} PostGraphile middleware error`, e); diff --git a/graphql/server/src/server.ts b/graphql/server/src/server.ts index a88b48d9f4..3aad1050c1 100644 --- a/graphql/server/src/server.ts +++ b/graphql/server/src/server.ts @@ -10,11 +10,12 @@ import express, { Express, NextFunction, Request, RequestHandler, Response } fro import type { Server as HttpServer } from 'http'; import graphqlUpload from 'graphql-upload'; import { Pool, PoolClient } from 'pg'; -import { graphileCache, closeAllCaches } from 'graphile-cache'; +import { closeAllCaches, getMemoryPressure, graphileCache, startMemoryGovernor } from 'graphile-cache'; import { getPgPool } from 'pg-cache'; import requestIp from 'request-ip'; import type { DebugSamplerHandle } from './diagnostics/debug-sampler'; +import { installConnectionErrorGuard } from './diagnostics/connection-error-guard'; import { closeDebugDatabasePools } from './diagnostics/debug-db-snapshot'; import { isDevelopmentObservabilityMode, @@ -40,6 +41,7 @@ import { parseCookieValue, SESSION_COOKIE_NAME } from './middleware/cookie'; import { createAgenticRouter } from 'agentic-server'; import { createContextMiddleware, requestIdMiddleware } from '@constructive-io/express-context'; import { startDebugSampler } from './diagnostics/debug-sampler'; +import { collectMetricsSample, type MetricsSamplerHandle, startMetricsSampler } from './diagnostics/metrics-sampler'; const log = new Logger('server'); @@ -80,8 +82,11 @@ class Server { private closed = false; private httpServer: HttpServer | null = null; private debugSampler: DebugSamplerHandle | null = null; + private metricsSampler: MetricsSamplerHandle | null = null; + private stopGovernor: (() => void) | null = null; constructor(opts: ConstructiveOptions) { + installConnectionErrorGuard(); this.opts = getEnvOptions(opts); const effectiveOpts = this.opts; const observabilityRequested = isGraphqlObservabilityRequested(); @@ -126,6 +131,15 @@ class Server { } healthz(app); + // Operational metrics endpoint (heap/rss, cache size, build/eviction/guard + // counters, memory pressure) — same sample shape as the JSON-line sampler. + // Env-gated and loopback-only by default; front it with internal routing in + // production if remote scrape access is needed. + if (process.env.GRAPHILE_METRICS_ENDPOINT === '1') { + app.get('/metrics', localObservabilityOnly, (_req, res) => { + res.json({ ...collectMetricsSample(), memoryPressure: getMemoryPressure() }); + }); + } if (observabilityEnabled) { app.get('/debug/memory', localObservabilityOnly, debugMemory); app.get('/debug/db', localObservabilityOnly, createDebugDatabaseMiddleware(effectiveOpts)); @@ -209,6 +223,14 @@ class Server { this.app = app; this.debugSampler = observabilityEnabled ? startDebugSampler(effectiveOpts) : null; + // Gated purely on GRAPHILE_DEBUG_METRICS (not dev-only observability): this JSON-line + // sampler is designed for long production soak analysis and is a true no-op when the + // env flag is off. + this.metricsSampler = startMetricsSampler(); + // Proactive heap-pressure eviction (85%) + critical build refusal (92%) — + // the request-path gate lives in the graphile dispatcher; this timer only + // does the background evictions. Disable with GRAPHILE_MEMORY_GOVERNOR=0. + this.stopGovernor = startMemoryGovernor(); } listen(): HttpServer { @@ -320,6 +342,14 @@ class Server { await this.debugSampler.stop(); this.debugSampler = null; } + if (this.metricsSampler) { + this.metricsSampler.stop(); + this.metricsSampler = null; + } + if (this.stopGovernor) { + this.stopGovernor(); + this.stopGovernor = null; + } if (this.httpServer?.listening) { await new Promise((resolve) => this.httpServer!.close(() => resolve())); }