feat: start monitoring total time to update cache (#6517)

src/lib/features/frontend-api/frontend-api-service.ts

@@ -16,7 +16,7 @@ import {
 import { validateOrigins } from '../../util';
 import { BadDataError, InvalidTokenError } from '../../error';
 import {
-    OPERATION_TIME,
+    FUNCTION_TIME,
     FRONTEND_API_REPOSITORY_CREATED,
     PROXY_REPOSITORY_CREATED,
 } from '../../metric-events';
@@ -77,9 +77,10 @@ export class FrontendApiService {
         this.services = services;
         this.globalFrontendApiCache = globalFrontendApiCache;
 
-        this.timer = (operationId) =>
-            metricsHelper.wrapTimer(config.eventBus, OPERATION_TIME, {
-                operationId,
+        this.timer = (functionName) =>
+            metricsHelper.wrapTimer(config.eventBus, FUNCTION_TIME, {
+                className: 'FrontendApiService',
+                functionName,
             });
     }
 

src/lib/features/frontend-api/global-frontend-api-cache.test.ts

@@ -48,7 +48,11 @@ const createCache = (
     segment: ISegment = defaultSegment,
     features: Record<string, Record<string, IFeatureToggleClient>> = {},
 ) => {
-    const config = { getLogger: noLogger, flagResolver: alwaysOnFlagResolver };
+    const config = {
+        getLogger: noLogger,
+        flagResolver: alwaysOnFlagResolver,
+        eventBus: <any>{ emit: jest.fn() },
+    };
     const segmentReadModel = new FakeSegmentReadModel([segment as ISegment]);
     const clientFeatureToggleReadModel = new FakeClientFeatureToggleReadModel(
         features,

src/lib/features/frontend-api/global-frontend-api-cache.ts

@@ -15,8 +15,10 @@ import { ALL_ENVS } from '../../util/constants';
 import { Logger } from '../../logger';
 import { UPDATE_REVISION } from '../feature-toggle/configuration-revision-service';
 import { IClientFeatureToggleReadModel } from './client-feature-toggle-read-model-type';
+import metricsHelper from '../../util/metrics-helper';
+import { FUNCTION_TIME } from '../../metric-events';
 
-type Config = Pick<IUnleashConfig, 'getLogger' | 'flagResolver'>;
+type Config = Pick<IUnleashConfig, 'getLogger' | 'flagResolver' | 'eventBus'>;
 
 type FrontendApiFeatureCache = Record<string, Record<string, FeatureInterface>>;
 
@@ -39,6 +41,8 @@ export class GlobalFrontendApiCache extends EventEmitter {
 
     private status: GlobalFrontendApiCacheState = 'starting';
 
+    private timer: Function;
+
     constructor(
         config: Config,
         segmentReadModel: ISegmentReadModel,
@@ -52,6 +56,12 @@ export class GlobalFrontendApiCache extends EventEmitter {
         this.configurationRevisionService = configurationRevisionService;
         this.segmentReadModel = segmentReadModel;
         this.onUpdateRevisionEvent = this.onUpdateRevisionEvent.bind(this);
+        this.timer = (functionName) =>
+            metricsHelper.wrapTimer(config.eventBus, FUNCTION_TIME, {
+                className: 'GlobalFrontendApiCache',
+                functionName,
+            });
+
         this.refreshData();
         this.configurationRevisionService.on(
             UPDATE_REVISION,
@@ -103,6 +113,7 @@ export class GlobalFrontendApiCache extends EventEmitter {
     // TODO: also consider not fetching disabled features, because those are not returned by frontend API
     private async refreshData() {
         try {
+            const stopTimer = this.timer('refreshData');
             this.featuresByEnvironment = await this.getAllFeatures();
             this.segments = await this.getAllSegments();
             if (this.status === 'starting') {
@@ -112,6 +123,7 @@ export class GlobalFrontendApiCache extends EventEmitter {
                 this.status = 'updated';
                 this.emit('updated');
             }
+            stopTimer();
         } catch (e) {
             this.logger.error('Cannot load data for token', e);
         }

src/lib/features/frontend-api/proxy-repository.ts

@@ -17,7 +17,11 @@ import { Logger } from '../../logger';
 import ConfigurationRevisionService, {
     UPDATE_REVISION,
 } from '../feature-toggle/configuration-revision-service';
-import { PROXY_FEATURES_FOR_TOKEN_TIME } from '../../metric-events';
+import {
+    FUNCTION_TIME,
+    PROXY_FEATURES_FOR_TOKEN_TIME,
+} from '../../metric-events';
+import metricsHelper from '../../util/metrics-helper';
 
 type Config = Pick<IUnleashConfig, 'getLogger' | 'frontendApi' | 'eventBus'>;
 
@@ -55,6 +59,8 @@ export class ProxyRepository
 
     private running: boolean;
 
+    private methodTimer: Function;
+
     constructor(
         config: Config,
         stores: Stores,
@@ -71,6 +77,12 @@ export class ProxyRepository
         this.token = token;
         this.onUpdateRevisionEvent = this.onUpdateRevisionEvent.bind(this);
         this.interval = config.frontendApi.refreshIntervalInMs;
+
+        this.methodTimer = (functionName) =>
+            metricsHelper.wrapTimer(config.eventBus, FUNCTION_TIME, {
+                className: 'ProxyRepository',
+                functionName,
+            });
     }
 
     getTogglesWithSegmentData(): EnhancedFeatureInterface[] {
@@ -135,8 +147,10 @@ export class ProxyRepository
 
     private async loadDataForToken() {
         try {
+            const stopTimer = this.methodTimer('loadDataForToken');
             this.features = await this.featuresForToken();
             this.segments = await this.segmentsForToken();
+            stopTimer();
         } catch (e) {
             this.logger.error('Cannot load data for token', e);
         }

src/lib/metric-events.ts

@@ -1,6 +1,6 @@
 const REQUEST_TIME = 'request_time';
 const DB_TIME = 'db_time';
-const OPERATION_TIME = 'operation_time';
+const FUNCTION_TIME = 'function_time';
 const SCHEDULER_JOB_TIME = 'scheduler_job_time';
 const FEATURES_CREATED_BY_PROCESSED = 'features_created_by_processed';
 const EVENTS_CREATED_BY_PROCESSED = 'events_created_by_processed';
@@ -12,7 +12,7 @@ export {
     REQUEST_TIME,
     DB_TIME,
     SCHEDULER_JOB_TIME,
-    OPERATION_TIME,
+    FUNCTION_TIME,
     FEATURES_CREATED_BY_PROCESSED,
     EVENTS_CREATED_BY_PROCESSED,
     FRONTEND_API_REPOSITORY_CREATED,

src/lib/metrics.test.ts

@@ -2,7 +2,7 @@ import { register } from 'prom-client';
 import EventEmitter from 'events';
 import { IEventStore } from './types/stores/event-store';
 import { createTestConfig } from '../test/config/test-config';
-import { DB_TIME, OPERATION_TIME, REQUEST_TIME } from './metric-events';
+import { DB_TIME, FUNCTION_TIME, REQUEST_TIME } from './metric-events';
 import {
     CLIENT_METRICS,
     CLIENT_REGISTER,
@@ -172,15 +172,16 @@ test('should collect metrics for db query timings', async () => {
     );
 });
 
-test('should collect metrics for operation timings', async () => {
-    eventBus.emit(OPERATION_TIME, {
-        operationId: 'getToggles',
+test('should collect metrics for function timings', async () => {
+    eventBus.emit(FUNCTION_TIME, {
+        functionName: 'getToggles',
+        className: 'ToggleService',
         time: 0.1337,
     });
 
     const metrics = await prometheusRegister.metrics();
     expect(metrics).toMatch(
-        /operation_duration_seconds\{quantile="0\.99",operationId="getToggles"\} 0.1337/,
+        /function_duration_seconds\{quantile="0\.99",functionName="getToggles",className="ToggleService"\} 0.1337/,
     );
 });
 

src/lib/metrics.ts

@@ -85,10 +85,10 @@ export default class MetricsMonitor {
             maxAgeSeconds: 600,
             ageBuckets: 5,
         });
-        const operationDuration = createSummary({
-            name: 'operation_duration_seconds',
-            help: 'Operation duration time',
-            labelNames: ['operationId'],
+        const functionDuration = createSummary({
+            name: 'function_duration_seconds',
+            help: 'Function duration time',
+            labelNames: ['functionName', 'className'],
             percentiles: [0.1, 0.5, 0.9, 0.95, 0.99],
             maxAgeSeconds: 600,
             ageBuckets: 5,
@@ -413,9 +413,14 @@ export default class MetricsMonitor {
             schedulerDuration.labels(jobId).observe(time);
         });
 
-        eventBus.on(events.OPERATION_TIME, ({ operationId, time }) => {
-            operationDuration.labels(operationId).observe(time);
-        });
+        eventBus.on(
+            events.FUNCTION_TIME,
+            ({ functionName, className, time }) => {
+                functionDuration
+                    .labels({ functionName, className })
+                    .observe(time);
+            },
+        );
 
         eventBus.on(events.EVENTS_CREATED_BY_PROCESSED, ({ updated }) => {
             eventCreatedByMigration.inc(updated);