From 1ebcbdda42fa58d1620c381a5c9e84af1a6ff381 Mon Sep 17 00:00:00 2001 From: Charles Bochet Date: Tue, 4 Aug 2026 16:50:50 +0200 Subject: [PATCH] feat(server): export event-loop delay and workspace-cache recompute metrics (#23751) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## 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. Review in cubic --- .../metrics/event-loop-metrics.service.ts | 72 ++++++++++++++ .../core-modules/metrics/metrics.module.ts | 3 +- .../__tests__/workspace-cache.service.spec.ts | 3 + .../services/workspace-cache.service.ts | 99 ++++++++++++++----- 4 files changed, 151 insertions(+), 26 deletions(-) create mode 100644 packages/twenty-server/src/engine/core-modules/metrics/event-loop-metrics.service.ts diff --git a/packages/twenty-server/src/engine/core-modules/metrics/event-loop-metrics.service.ts b/packages/twenty-server/src/engine/core-modules/metrics/event-loop-metrics.service.ts new file mode 100644 index 0000000000..6eaa1d4435 --- /dev/null +++ b/packages/twenty-server/src/engine/core-modules/metrics/event-loop-metrics.service.ts @@ -0,0 +1,72 @@ +import { Injectable, OnModuleDestroy, OnModuleInit } from '@nestjs/common'; + +import { type Histogram } from '@opentelemetry/api'; +import { performance, type EventLoopUtilization } from 'perf_hooks'; + +import { MetricsService } from 'src/engine/core-modules/metrics/metrics.service'; + +const SAMPLE_INTERVAL_MS = 1_000; +const MILLISECONDS_PER_SECOND = 1_000; +const DELAY_BUCKETS_SECONDS = [ + 0.001, 0.0025, 0.005, 0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1, 2.5, 5, +]; + +// Sampled as a histogram (not per-pod percentile gauges) so Grafana can +// re-aggregate a true fleet-wide quantile across pods. +@Injectable() +export class EventLoopMetricsService implements OnModuleInit, OnModuleDestroy { + private readonly delayHistogram: Histogram; + private sampler?: NodeJS.Timeout; + private lastSampleAt = performance.now(); + private lastEventLoopUtilization: EventLoopUtilization = + performance.eventLoopUtilization(); + + constructor(private readonly metricsService: MetricsService) { + this.delayHistogram = this.metricsService + .getMeter() + .createHistogram('twenty_nodejs_eventloop_delay_seconds', { + description: 'Node.js event loop lag, sampled per interval', + unit: 's', + advice: { explicitBucketBoundaries: DELAY_BUCKETS_SECONDS }, + }); + } + + onModuleInit(): void { + this.lastSampleAt = performance.now(); + + this.sampler = setInterval(() => { + const now = performance.now(); + const lagMs = Math.max(0, now - this.lastSampleAt - SAMPLE_INTERVAL_MS); + + this.lastSampleAt = now; + this.delayHistogram.record(lagMs / MILLISECONDS_PER_SECOND); + }, SAMPLE_INTERVAL_MS); + this.sampler.unref(); + + this.metricsService.createObservableGauge({ + metricName: 'twenty_nodejs_eventloop_utilization', + options: { + description: + 'Fraction of time the Node.js event loop was busy since the previous scrape', + unit: '1', + }, + callback: async () => { + const current = performance.eventLoopUtilization(); + const delta = performance.eventLoopUtilization( + current, + this.lastEventLoopUtilization, + ); + + this.lastEventLoopUtilization = current; + + return delta.utilization; + }, + }); + } + + onModuleDestroy(): void { + if (this.sampler) { + clearInterval(this.sampler); + } + } +} diff --git a/packages/twenty-server/src/engine/core-modules/metrics/metrics.module.ts b/packages/twenty-server/src/engine/core-modules/metrics/metrics.module.ts index a0afac6e14..b06aef7c91 100644 --- a/packages/twenty-server/src/engine/core-modules/metrics/metrics.module.ts +++ b/packages/twenty-server/src/engine/core-modules/metrics/metrics.module.ts @@ -1,10 +1,11 @@ import { Module } from '@nestjs/common'; +import { EventLoopMetricsService } from 'src/engine/core-modules/metrics/event-loop-metrics.service'; import { MetricsCacheService } from 'src/engine/core-modules/metrics/metrics-cache.service'; import { MetricsService } from 'src/engine/core-modules/metrics/metrics.service'; @Module({ - providers: [MetricsService, MetricsCacheService], + providers: [MetricsService, MetricsCacheService, EventLoopMetricsService], exports: [MetricsService, MetricsCacheService], }) export class MetricsModule {} diff --git a/packages/twenty-server/src/engine/workspace-cache/services/__tests__/workspace-cache.service.spec.ts b/packages/twenty-server/src/engine/workspace-cache/services/__tests__/workspace-cache.service.spec.ts index ea710bc663..7b9d3106b5 100644 --- a/packages/twenty-server/src/engine/workspace-cache/services/__tests__/workspace-cache.service.spec.ts +++ b/packages/twenty-server/src/engine/workspace-cache/services/__tests__/workspace-cache.service.spec.ts @@ -88,6 +88,9 @@ describe('WorkspaceCacheService', () => { provide: MetricsService, useValue: { incrementCounterBy: jest.fn(), + getMeter: jest.fn().mockReturnValue({ + createHistogram: jest.fn().mockReturnValue({ record: jest.fn() }), + }), }, }, { diff --git a/packages/twenty-server/src/engine/workspace-cache/services/workspace-cache.service.ts b/packages/twenty-server/src/engine/workspace-cache/services/workspace-cache.service.ts index c05f088baa..b363d7d5a6 100644 --- a/packages/twenty-server/src/engine/workspace-cache/services/workspace-cache.service.ts +++ b/packages/twenty-server/src/engine/workspace-cache/services/workspace-cache.service.ts @@ -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) {