From ebb5f1d8aacbf2b2bcd12cf5d46741ee20f0035d Mon Sep 17 00:00:00 2001 From: doswalt Date: Fri, 23 Oct 2026 10:08:58 -0400 Subject: [PATCH] add a custom event record that new relic can pick up instead of logging --- .../backend/src/api/services/CacheService.ts | 2 +- packages/backend/src/env.ts | 2 +- packages/backend/src/lib/newrelic.ts | 22 +- packages/backend/src/lib/perfDiagnostics.ts | 188 +++++++++++------- .../test/unit/lib/perfDiagnostics.test.ts | 119 ++++++++++- 5 files changed, 253 insertions(+), 80 deletions(-) diff --git a/packages/backend/src/api/services/CacheService.ts b/packages/backend/src/api/services/CacheService.ts index 7f095ab3b..a54f084ab 100644 --- a/packages/backend/src/api/services/CacheService.ts +++ b/packages/backend/src/api/services/CacheService.ts @@ -88,7 +88,7 @@ export class CacheService { } if (this.cache !== noopStore) { this.warnOnBucketsWithoutRefresh(); - // Temporary: see src/lib/perfDiagnostics.ts + // Times every store write — see src/lib/perfDiagnostics.ts if (env.perfDiagnostics?.enabled) { instrumentCacheStore(this.cache.store); } diff --git a/packages/backend/src/env.ts b/packages/backend/src/env.ts index a36c66f1c..0690204f0 100644 --- a/packages/backend/src/env.ts +++ b/packages/backend/src/env.ts @@ -123,7 +123,7 @@ export const env = { ttlSettings: toNumber(getOsEnvOptional('CACHING_TTL_SETTINGS')), refreshThreshold: toNumber(getOsEnvOptional('CACHING_REFRESH_THRESHOLD')), }, - // Temporary: see src/lib/perfDiagnostics.ts + // See src/lib/perfDiagnostics.ts perfDiagnostics: { enabled: toBool(getOsEnvOptional('PERF_DIAG_ENABLED')) || false, }, diff --git a/packages/backend/src/lib/newrelic.ts b/packages/backend/src/lib/newrelic.ts index 311f2029c..143ec0c8c 100644 --- a/packages/backend/src/lib/newrelic.ts +++ b/packages/backend/src/lib/newrelic.ts @@ -1,7 +1,7 @@ import { env } from '../env'; /** - * Thin wrapper over the New Relic agent's custom-attribute API. + * Thin wrapper over the New Relic agent's custom-attribute and custom-event APIs. * * The agent itself is started in `src/app.ts` when USE_NEW_RELIC is set. We resolve it here * once at module load — not per request — so the hot path costs a null check and a property @@ -10,8 +10,11 @@ import { env } from '../env'; * * When USE_NEW_RELIC is false the agent is never loaded and every call below is a no-op. */ +export type CustomEventAttributes = Record; + interface NewRelicAgent { addCustomAttribute(key: string, value: string | number | boolean): void; + recordCustomEvent(eventType: string, attributes: CustomEventAttributes): void; } let agent: NewRelicAgent | null = null; @@ -41,6 +44,23 @@ export function addCustomAttribute(key: string, value: string | number | boolean } } +/** + * Record a custom event, queryable in NRQL as `FROM `. Unlike addCustomAttribute it + * needs no active transaction, so it can be called from a timer. Synchronous and in-process — the + * agent buffers the event and sends it on its own harvest cycle. Attribute values must be flat + * primitives; the agent drops any that aren't. Never throws. + */ +export function recordCustomEvent(eventType: string, attributes: CustomEventAttributes): void { + if (!agent) { + return; + } + try { + agent.recordCustomEvent(eventType, attributes); + } catch { + // no-op — telemetry must never fail the caller + } +} + // New Relic silently truncates custom attribute values at 255 chars, so cap here too — // otherwise the same request shows a truncated value in NR but the untruncated one in logs. const MAX_CUSTOM_ATTRIBUTE_LENGTH = 255; diff --git a/packages/backend/src/lib/perfDiagnostics.ts b/packages/backend/src/lib/perfDiagnostics.ts index 992f9388b..f1b0ac646 100644 --- a/packages/backend/src/lib/perfDiagnostics.ts +++ b/packages/backend/src/lib/perfDiagnostics.ts @@ -1,40 +1,61 @@ import { constants, monitorEventLoopDelay, performance, PerformanceObserver } from 'perf_hooks'; import type { DataSource } from 'typeorm'; import { getInstanceId } from './instanceIdentity'; +import { CustomEventAttributes, recordCustomEvent } from './newrelic'; /** - * TEMPORARY production diagnostics for the /assign + /mark tail-latency investigation. - * Remove once that investigation is closed. + * Runtime performance diagnostics for the backend: event loop, garbage collection, the pg connection + * pool, and in-memory cache writes. Enabled only when PERF_DIAG_ENABLED=true; otherwise nothing here + * is started or installed. * - * Everything here runs off the request path (timers and perf_hooks observers only), so it cannot - * change how a request is handled. Every `reportMs` it writes one JSON line tagged `perfdiag` to - * stdout — deliberately not through UpgradeLogger, so the production `error` log level does not - * suppress it. Each line answers, for that window: was the event loop busy (CPU), did it stall - * (event-loop delay, GC pauses), and did requests queue for a DB connection (pg pool waiters). + * Every 10 seconds it writes one JSON line tagged `perfdiag` to stdout — deliberately not through + * UpgradeLogger, so the production `error` log level does not suppress it. Each line answers, for the + * window since the previous line: was the event loop busy (CPU), did it stall (event-loop delay, GC + * pauses), and did queries queue for a DB connection (pg pool waiters). The timers and perf_hooks + * observers behind it run off the request path, so they cannot change how a request is handled. * * Fields, per reporting window: + * - instanceId: which server process wrote the line — see instanceIdentity. * - eventLoopBusyPct: % of wall time the main JS thread was running code rather than idle-waiting on I/O. * Near 100 means it's saturated and every ready callback (including every request) queues behind it. - * - eventLoopDelayMs: how late a timer fired beyond its schedule — how long ready work sat waiting for the thread. - * - garbageCollection.major/minor: GC pauses (count, total, longest). Major pauses block the thread. - * - dbPool.maxWaitingForConnection: most queries queued for a free pg connection at any sample. Above 0 = pool exhausted. + * - eventLoopDelayMs (p50/p99/max): how late a timer fired beyond its schedule — how long ready work sat + * waiting for the thread. The 10ms sampling interval is subtracted, so an idle loop reads ~0. + * - garbageCollection.major/minor: GC pauses (count, total, longest) — major is mark-compact, minor is + * scavenge. Both stop the main thread; major pauses are the long ones. Incremental-marking and + * weak-callback steps aren't counted. + * - dbPool.maxWaitingForConnection: most queries queued for a free pg connection at any 100ms sample. + * Above 0 = pool exhausted. * - dbPool.maxConnectionsInUse: peak checked-out connections at any sample (compare to dbPoolConfig.maxPoolSize). * - dbPool.currentPoolSize: connections open (in use + idle) at report time. Drops as idle ones time out or expire. * - dbPoolConfig: the pool settings as pg-pool resolved them (after its defaults), to confirm the TYPEORM_* env - * vars took. Static for the life of the process. keepAliveInitialDelayMillis is null when unset, and has no - * effect unless keepAlive is true. - * - cacheWrites: in-memory cache writes in the window (count, total/longest time blocked, and the key of - * the longest). The memory store deep-clones every value on write, synchronously, so this is time the - * event loop was blocked copying cache values — see instrumentCacheStore. + * vars took. Static for the life of the process. keepAlive and keepAliveInitialDelayMillis have no pg-pool + * default, so they're null when unset; the delay has no effect unless keepAlive is true. + * dbPool and dbPoolConfig are both null if the TypeORM driver exposes no pg pool. + * - cacheWrites: every in-memory cache write in the window, whatever its duration (count, total/longest time + * blocked, and the key of the longest). The memory store deep-clones every value on write, synchronously, + * so this is time the event loop was blocked copying cache values — see instrumentCacheStore. + * - heapUsedMb: V8 heap in use at report time. * - * Any single cache write at or above CACHE_WRITE_LOG_THRESHOLD_MS also gets its own `perfdiag-cache` - * line: the key, whether it was a first load (`miss`) or a refresh of an existing entry, how long the - * write blocked, and how long the source load took (DB round trip plus TypeORM hydration). + * Any single cache write at or above CACHE_WRITE_LOG_THRESHOLD_MS also gets its own `perfdiag-cache` line: + * - instanceId: as above. + * - key: the cache key, cut to its first 120 characters. + * - kind: `miss` if the key held no live entry before the write (first load, or after it expired), + * `refresh` if the write replaced one. + * - writeMs: how long the write blocked the event loop. + * - loadMs: how long the source load took (DB round trip plus TypeORM hydration). Only CacheService.wrap's + * loader is timed, so it's null for writes from anywhere else, such as setCache or the batch-load path. + * - items: the value's array length or object key count; null for anything else. * - * Unlike the timers above, the cache instrumentation does sit on the request path — it wraps the cache - * store's `set` and CacheService.wrap's loader — but only adds a timestamp read per call. + * Unlike the timers, the cache instrumentation can sit on the request path — it wraps the cache store's + * `set` and CacheService.wrap's loader — but adds only a few timestamp reads and one extra store lookup + * per write. * - * Enabled only when PERF_DIAG_ENABLED=true. + * Every line also carries `tag` and an ISO-8601 `ts`. When New Relic is on (USE_NEW_RELIC=true), each line + * is also recorded as a New Relic custom event — `PerfDiag` for the window reports, `PerfDiagCacheWrite` + * for the slow cache writes — so they can be charted next to transaction data. Same fields, minus `tag` + * and `ts` (the event's own type and timestamp stand in for them). Event attributes must be flat, so + * nested fields become dotted names: `eventLoopDelayMs.p99` reads the same in NRQL as in the log line. + * Null fields are left off. */ interface GcStats { @@ -57,12 +78,18 @@ interface PgPoolLike { }; } +type RecordEvent = (eventType: string, attributes: CustomEventAttributes) => void; + export interface PerfDiagnosticsOptions { sampleMs?: number; reportMs?: number; write?: (line: string) => void; + recordEvent?: RecordEvent; } +export const PERFDIAG_EVENT_TYPE = 'PerfDiag'; +export const PERFDIAG_CACHE_EVENT_TYPE = 'PerfDiagCacheWrite'; + // monitorEventLoopDelay samples on a timer of this resolution, and its recorded values include that // interval — an idle loop reads ~10ms. Reported delays subtract it, so an idle loop reads ~0. const LOOP_DELAY_RESOLUTION_MS = 10; @@ -74,6 +101,22 @@ const defaultWrite = (line: string): void => { process.stdout.write(line + '\n'); }; +/** + * Flattens a log-line payload into New Relic event attributes: nested objects become dotted names + * (`{ dbPool: { currentPoolSize: 4 } }` → `dbPool.currentPoolSize: 4`) and null fields are dropped. + */ +export function toEventAttributes(fields: object, prefix = '', out: CustomEventAttributes = {}): CustomEventAttributes { + for (const [key, value] of Object.entries(fields)) { + const name = prefix ? `${prefix}.${key}` : key; + if (value !== null && typeof value === 'object') { + toEventAttributes(value, name, out); + } else if (typeof value === 'string' || typeof value === 'number' || typeof value === 'boolean') { + out[name] = value; + } + } + return out; +} + // ─── Cache write timing ─────────────────────────────────────────────────────── export const CACHE_WRITE_LOG_THRESHOLD_MS = 5; @@ -125,7 +168,8 @@ export function timeCacheLoad(key: string, load: () => Promise): () => Pro export function instrumentCacheStore( store: CacheStoreLike, write: (line: string) => void = defaultWrite, - logThresholdMs = CACHE_WRITE_LOG_THRESHOLD_MS + logThresholdMs = CACHE_WRITE_LOG_THRESHOLD_MS, + recordEvent: RecordEvent = recordCustomEvent ): void { const originalSet = store.set.bind(store); store.set = (key: string, value: unknown, ttl?: number) => { @@ -147,18 +191,16 @@ export function instrumentCacheStore( if (writeMs >= logThresholdMs) { void previous.then((prior) => { try { - write( - JSON.stringify({ - tag: 'perfdiag-cache', - ts: new Date().toISOString(), - instanceId: getInstanceId(), - key: key.slice(0, MAX_LOGGED_KEY_LENGTH), - kind: prior === undefined ? 'miss' : 'refresh', - writeMs: round1(writeMs), - loadMs: loadMs === undefined ? null : round1(loadMs), - items: countItems(value), - }) - ); + const fields = { + instanceId: getInstanceId(), + key: key.slice(0, MAX_LOGGED_KEY_LENGTH), + kind: prior === undefined ? 'miss' : 'refresh', + writeMs: round1(writeMs), + loadMs: loadMs === undefined ? null : round1(loadMs), + items: countItems(value), + }; + write(JSON.stringify({ tag: 'perfdiag-cache', ts: new Date().toISOString(), ...fields })); + recordEvent(PERFDIAG_CACHE_EVENT_TYPE, toEventAttributes(fields)); } catch { // Diagnostics must never take the process down. } @@ -170,7 +212,7 @@ export function instrumentCacheStore( export function startPerfDiagnostics(dataSource: DataSource, options: PerfDiagnosticsOptions = {}): () => void { // Pool counts are point-in-time, so they're sampled often enough to catch sub-second bursts. - const { sampleMs = 100, reportMs = 10000, write = defaultWrite } = options; + const { sampleMs = 100, reportMs = 10000, write = defaultWrite, recordEvent = recordCustomEvent } = options; const loopDelay = monitorEventLoopDelay({ resolution: LOOP_DELAY_RESOLUTION_MS }); loopDelay.enable(); @@ -195,7 +237,7 @@ export function startPerfDiagnostics(dataSource: DataSource, options: PerfDiagno }); gcObserver.observe({ entryTypes: ['gc'] }); - // TypeORM's postgres driver exposes the underlying pg Pool as `master` when using replication config. + // TypeORM's postgres driver keeps its pg Pool on `master` (with replication configured, the primary's pool). const pool: PgPoolLike | undefined = (dataSource?.driver as unknown as { master?: PgPoolLike })?.master; let maxWaiting = 0; let maxInUse = 0; @@ -216,44 +258,42 @@ export function startPerfDiagnostics(dataSource: DataSource, options: PerfDiagno maxMs: round1(stats.maxMs), }); - write( - JSON.stringify({ - tag: 'perfdiag', - ts: new Date().toISOString(), - instanceId: getInstanceId(), - eventLoopBusyPct: round1(elu.utilization * 100), - eventLoopDelayMs: { - p50: excessDelayMs(loopDelay.percentile(50)), - p99: excessDelayMs(loopDelay.percentile(99)), - max: excessDelayMs(loopDelay.max), - }, - garbageCollection: { major: formatGc(gcMajor), minor: formatGc(gcMinor) }, - dbPool: pool - ? { - maxWaitingForConnection: maxWaiting, - maxConnectionsInUse: maxInUse, - currentPoolSize: pool.totalCount, - } - : null, - dbPoolConfig: pool - ? { - maxPoolSize: pool.options?.max ?? null, - minPoolSize: pool.options?.min ?? null, - idleTimeoutMillis: pool.options?.idleTimeoutMillis ?? null, - maxLifetimeSeconds: pool.options?.maxLifetimeSeconds ?? null, - keepAlive: pool.options?.keepAlive ?? null, - keepAliveInitialDelayMillis: pool.options?.keepAliveInitialDelayMillis ?? null, - } - : null, - cacheWrites: { - count: cacheWrites.count, - totalMs: round1(cacheWrites.totalMs), - maxMs: round1(cacheWrites.maxMs), - maxKey: cacheWrites.maxKey, - }, - heapUsedMb: Math.round(process.memoryUsage().heapUsed / 1048576), - }) - ); + const fields = { + instanceId: getInstanceId(), + eventLoopBusyPct: round1(elu.utilization * 100), + eventLoopDelayMs: { + p50: excessDelayMs(loopDelay.percentile(50)), + p99: excessDelayMs(loopDelay.percentile(99)), + max: excessDelayMs(loopDelay.max), + }, + garbageCollection: { major: formatGc(gcMajor), minor: formatGc(gcMinor) }, + dbPool: pool + ? { + maxWaitingForConnection: maxWaiting, + maxConnectionsInUse: maxInUse, + currentPoolSize: pool.totalCount, + } + : null, + dbPoolConfig: pool + ? { + maxPoolSize: pool.options?.max ?? null, + minPoolSize: pool.options?.min ?? null, + idleTimeoutMillis: pool.options?.idleTimeoutMillis ?? null, + maxLifetimeSeconds: pool.options?.maxLifetimeSeconds ?? null, + keepAlive: pool.options?.keepAlive ?? null, + keepAliveInitialDelayMillis: pool.options?.keepAliveInitialDelayMillis ?? null, + } + : null, + cacheWrites: { + count: cacheWrites.count, + totalMs: round1(cacheWrites.totalMs), + maxMs: round1(cacheWrites.maxMs), + maxKey: cacheWrites.maxKey, + }, + heapUsedMb: Math.round(process.memoryUsage().heapUsed / 1048576), + }; + write(JSON.stringify({ tag: 'perfdiag', ts: new Date().toISOString(), ...fields })); + recordEvent(PERFDIAG_EVENT_TYPE, toEventAttributes(fields)); } catch { // Diagnostics must never take the process down. } finally { diff --git a/packages/backend/test/unit/lib/perfDiagnostics.test.ts b/packages/backend/test/unit/lib/perfDiagnostics.test.ts index 38f6316f0..eceeedfe7 100644 --- a/packages/backend/test/unit/lib/perfDiagnostics.test.ts +++ b/packages/backend/test/unit/lib/perfDiagnostics.test.ts @@ -1,5 +1,14 @@ import { caching } from 'cache-manager'; -import { instrumentCacheStore, startPerfDiagnostics, timeCacheLoad } from '../../../src/lib/perfDiagnostics'; +import { + instrumentCacheStore, + PERFDIAG_CACHE_EVENT_TYPE, + PERFDIAG_EVENT_TYPE, + startPerfDiagnostics, + timeCacheLoad, + toEventAttributes, +} from '../../../src/lib/perfDiagnostics'; + +type RecordedEvent = [string, Record]; describe('startPerfDiagnostics', () => { const waitFor = (ms: number) => new Promise((resolve) => setTimeout(resolve, ms)); @@ -54,12 +63,53 @@ describe('startPerfDiagnostics', () => { expect(typeof parsed.heapUsedMb).toBe('number'); }); + it('records each report as a PerfDiag event with the log line fields, flattened', async () => { + const pool = { + totalCount: 4, + idleCount: 1, + waitingCount: 2, + options: { max: 10, min: 0, idleTimeoutMillis: 10000, maxLifetimeSeconds: 0, keepAlive: false }, + }; + const lines: string[] = []; + const events: RecordedEvent[] = []; + const stop = startPerfDiagnostics({ driver: { master: pool } } as any, { + sampleMs: 10, + reportMs: 100, + write: (line) => lines.push(line), + recordEvent: (eventType, attributes) => events.push([eventType, attributes]), + }); + + await waitFor(250); + stop(); + + expect(events.length).toBe(lines.length); + const [eventType, attributes] = events[0]; + const logged = JSON.parse(lines[0]); + delete logged.tag; + delete logged.ts; + expect(eventType).toBe(PERFDIAG_EVENT_TYPE); + expect(attributes).toEqual(toEventAttributes(logged)); + expect(attributes).toMatchObject({ + instanceId: expect.any(String), + 'eventLoopDelayMs.p99': expect.any(Number), + 'garbageCollection.major.maxMs': expect.any(Number), + 'dbPool.maxWaitingForConnection': 2, + 'dbPool.maxConnectionsInUse': 3, + 'dbPoolConfig.maxPoolSize': 10, + 'dbPoolConfig.keepAlive': false, + }); + expect(Object.keys(attributes)).not.toContain('dbPoolConfig.keepAliveInitialDelayMillis'); + expect(Object.keys(attributes)).not.toContain('cacheWrites.maxKey'); + }); + it('reports a null pool instead of throwing when the driver has no pg pool', async () => { const lines: string[] = []; + const events: RecordedEvent[] = []; const stop = startPerfDiagnostics({ driver: {} } as any, { sampleMs: 10, reportMs: 50, write: (l) => lines.push(l), + recordEvent: (eventType, attributes) => events.push([eventType, attributes]), }); await waitFor(120); @@ -67,6 +117,7 @@ describe('startPerfDiagnostics', () => { expect(JSON.parse(lines[0]).dbPool).toBeNull(); expect(JSON.parse(lines[0]).dbPoolConfig).toBeNull(); + expect(Object.keys(events[0][1]).filter((name) => name.startsWith('dbPool'))).toEqual([]); }); it('stops writing after the returned stop function is called', async () => { @@ -92,7 +143,12 @@ describe('cache write instrumentation', () => { it('logs slow writes to the real memory store with key, kind, load time, and item count', async () => { const cache = await caching('memory', { max: 10, ttl: 60000 }); const lines: string[] = []; - instrumentCacheStore(cache.store as any, (line) => lines.push(line), 0); + instrumentCacheStore( + cache.store as any, + (line) => lines.push(line), + 0, + () => undefined + ); const load = timeCacheLoad('experiments:assign-prog', async () => bigValue()); await cache.wrap('experiments:assign-prog', load); @@ -112,15 +168,72 @@ describe('cache write instrumentation', () => { ]); }); + it('records each slow write as a PerfDiagCacheWrite event, leaving off a missing load time', async () => { + const cache = await caching('memory', { max: 10, ttl: 60000 }); + const events: RecordedEvent[] = []; + instrumentCacheStore( + cache.store as any, + () => undefined, + 0, + (eventType, attributes) => events.push([eventType, attributes]) + ); + + const load = timeCacheLoad('experiments:assign-prog', async () => bigValue()); + await cache.wrap('experiments:assign-prog', load); + await cache.set('experiments:assign-prog', bigValue()); + await flush(); + + expect(events).toEqual([ + [ + PERFDIAG_CACHE_EVENT_TYPE, + { + instanceId: expect.any(String), + key: 'experiments:assign-prog', + kind: 'miss', + writeMs: expect.any(Number), + loadMs: expect.any(Number), + items: 20000, + }, + ], + [ + PERFDIAG_CACHE_EVENT_TYPE, + { + instanceId: expect.any(String), + key: 'experiments:assign-prog', + kind: 'refresh', + writeMs: expect.any(Number), + items: 20000, + }, + ], + ]); + }); + it('still stores the value and skips the per-write line below the threshold', async () => { const cache = await caching('memory', { max: 10, ttl: 60000 }); const lines: string[] = []; - instrumentCacheStore(cache.store as any, (line) => lines.push(line), 10000); + const events: RecordedEvent[] = []; + instrumentCacheStore( + cache.store as any, + (line) => lines.push(line), + 10000, + (eventType, attributes) => events.push([eventType, attributes]) + ); await cache.set('small', { a: 1 }); await flush(); expect(await cache.get('small')).toEqual({ a: 1 }); expect(lines).toHaveLength(0); + expect(events).toHaveLength(0); + }); +}); + +describe('toEventAttributes', () => { + it('flattens nested fields to dotted names and drops nulls', () => { + expect(toEventAttributes({ a: 1, b: { c: 'x', d: null, e: { f: true } }, g: null })).toEqual({ + a: 1, + 'b.c': 'x', + 'b.e.f': true, + }); }); });