add a custom event record that new relic can pick up instead of logging

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);
       }

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,
   },

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<string, string | number | boolean>;
+
 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 <eventType>`. 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;

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<T>(key: string, load: () => Promise<T>): () => 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 {