feat(server): export event-loop delay and workspace-cache recompute metrics (#23751)

## What Exports three sets of metrics to Prometheus to diagnose the recurring "Slow DB Query" Sentry issues on `POST /graphql` (e.g. the `fieldMetadata` select): - `twenty_nodejs_eventloop_delay_seconds` (mean/p50/p99/max) + `twenty_nodejs_eventloop_utilization` - `twenty_workspace_cache_recompute_duration_seconds{cache_key}` — wall time per provider `computeForCache` - `twenty_workspace_cache_redis_write_duration_seconds` — serialize + Redis write time for recomputed entries ## Why Investigation of these issues showed: - The flagged query executes in ~1ms (prod EXPLAIN), so it is not a query/index problem. - Event counts do **not** correlate with connection-pool acquire latency (Pearson ~0 against both p99 and the direct count of >1s acquires), so it is not pool contention. - Event counts **do** correlate with pod CPU (Pearson +0.40). The leading explanation is that the slow `db` span is inflated by event-loop saturation during the workspace metadata cache recompute: `Promise.all` parallelizes the I/O, but the synchronous work it cannot parallelize (TypeORM entity hydration of JSONB-heavy result sets, then `JSON.stringify` of the flat-map payloads into Redis) blocks the single event-loop thread, so an awaiting query resolves ~1.3s late. Node event-loop delay was only being collected by Sentry's `nodeRuntimeMetricsIntegration`, never exported to Prometheus, so it could not be graphed or correlated in Grafana. These metrics confirm (or refute) the mechanism and give a before/after baseline for the fix. Grafana panels land in a companion twenty-infra PR. ## Notes - Metric-only change; no behavioral change to the cache. - Uses the same OTel `MetricsService` / meter as the existing DB pool metrics.  <a href="https://cubic.dev/pr/twentyhq/twenty/pull/23751?utm_source=github" target="_blank" rel="noopener noreferrer" data-no-image-dialog="true"><picture><source media="(prefers-color-scheme: dark)" srcset="https://www.cubic.dev/buttons/review-in-cubic-dark.svg"><source media="(prefers-color-scheme: light)" srcset="https://www.cubic.dev/buttons/review-in-cubic-light.svg"><img alt="Review in cubic" src="https://www.cubic.dev/buttons/review-in-cubic-dark.svg"></picture></a>
2026-08-04 16:50:50 +02:00
parent 6e1c710a7d
commit 1ebcbdda42
4 changed files with 151 additions and 26 deletions
@@ -1,6 +1,7 @@
 import { Injectable, Logger, OnModuleInit } from '@nestjs/common';
 import { DiscoveryService, Reflector } from '@nestjs/core';

+import { type Histogram } from '@opentelemetry/api';
 import * as Sentry from '@sentry/node';
 import crypto from 'crypto';

@@ -43,6 +44,9 @@ const MAX_LOCAL_STALE_VERSIONS = 5; // 5 stale versions
 // Sized against 4 GiB pods (--max-old-space-size=3500): 7,500 sat at the heap ceiling
 const MAX_LOCAL_CACHE_ENTRIES = 6_000;
 const MIN_EVICT_KEYS = 100;
+const CACHE_DURATION_BUCKETS_SECONDS = [
+  0.001, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, 10,
+];

 type CacheDataType = WorkspaceCacheDataMap[WorkspaceCacheKeyName];

@@ -76,6 +80,9 @@ export class WorkspaceCacheService implements OnModuleInit {

  private readonly logger = new Logger(WorkspaceCacheService.name);

+  private readonly recomputeDurationHistogram: Histogram;
+  private readonly redisWriteDurationHistogram: Histogram;
+
  constructor(
    @InjectCacheStorage(CacheStorageNamespace.EngineWorkspace)
    private readonly cacheStorage: CacheStorageService,
@@ -83,7 +90,32 @@ export class WorkspaceCacheService implements OnModuleInit {
    private readonly reflector: Reflector,
    private readonly metricsService: MetricsService,
    private readonly twentyConfigService: TwentyConfigService,
-  ) {}
+  ) {
+    const meter = this.metricsService.getMeter();
+
+    this.recomputeDurationHistogram = meter.createHistogram(
+      'twenty_workspace_cache_recompute_duration_seconds',
+      {
+        description:
+          'Wall-clock time to compute one workspace metadata cache entry from its provider',
+        unit: 's',
+        advice: {
+          explicitBucketBoundaries: CACHE_DURATION_BUCKETS_SECONDS,
+        },
+      },
+    );
+    this.redisWriteDurationHistogram = meter.createHistogram(
+      'twenty_workspace_cache_redis_write_duration_seconds',
+      {
+        description:
+          'Wall-clock time to serialize and write recomputed cache entries to Redis',
+        unit: 's',
+        advice: {
+          explicitBucketBoundaries: CACHE_DURATION_BUCKETS_SECONDS,
+        },
+      },
+    );
+  }

  async onModuleInit() {
    const providers = this.discoveryService.getProviders();
@@ -442,32 +474,41 @@ export class WorkspaceCacheService implements OnModuleInit {
    const computePromises = cacheKeyNames.map(async (keyName) => {
      const provider = this.getProviderOrThrow(keyName);
      const isLocalDataOnly = this.localDataOnlyKeys.has(keyName);
-      const data = await Sentry.startSpan(
-        {
-          name: 'compute workspace metadata cache entry from provider',
-          op: 'cache.recompute',
-          onlyIfParent: true,
-          attributes: {
-            'cache.key_name': keyName,
-            'cache.recompute.strategy': hashResolution.strategy,
-            'cache.local_data_only': isLocalDataOnly,
+      const computeStartedAt = performance.now();
+
+      try {
+        const data = await Sentry.startSpan(
+          {
+            name: 'compute workspace metadata cache entry from provider',
+            op: 'cache.recompute',
+            onlyIfParent: true,
+            attributes: {
+              'cache.key_name': keyName,
+              'cache.recompute.strategy': hashResolution.strategy,
+              'cache.local_data_only': isLocalDataOnly,
+            },
          },
-        },
-        () => provider.computeForCache(workspaceId),
-      );
+          () => provider.computeForCache(workspaceId),
+        );

-      if (hashResolution.strategy === 'mint') {
-        return { keyName, data, hash: crypto.randomUUID(), isAdopted: false };
+        if (hashResolution.strategy === 'mint') {
+          return { keyName, data, hash: crypto.randomUUID(), isAdopted: false };
+        }
+
+        const adoptableHash = hashResolution.adoptableHashes[keyName];
+
+        return {
+          keyName,
+          data,
+          hash: adoptableHash ?? crypto.randomUUID(),
+          isAdopted: isDefined(adoptableHash),
+        };
+      } finally {
+        this.recomputeDurationHistogram.record(
+          (performance.now() - computeStartedAt) / 1000,
+          { cache_key: keyName },
+        );
      }
-
-      const adoptableHash = hashResolution.adoptableHashes[keyName];
-
-      return {
-        keyName,
-        data,
-        hash: adoptableHash ?? crypto.randomUUID(),
-        isAdopted: isDefined(adoptableHash),
-      };
    });

    const computed = await Promise.all(computePromises);
@@ -498,7 +539,15 @@ export class WorkspaceCacheService implements OnModuleInit {
    }

    if (redisEntries.length > 0) {
-      await this.cacheStorage.mset(redisEntries);
+      const redisWriteStartedAt = performance.now();
+
+      try {
+        await this.cacheStorage.mset(redisEntries);
+      } finally {
+        this.redisWriteDurationHistogram.record(
+          (performance.now() - redisWriteStartedAt) / 1000,
+        );
+      }
    }

    if (bootstrapHashEntries.length > 0) {