Add ELU timings (#154022)

Co-authored-by: kibanamachine <42973632+kibanamachine@users.noreply.github.com>

packages/core/http/core-http-server-internal/src/__snapshots__/http_config.test.ts.snap

@@ -56,6 +56,16 @@ Object {
     "enabled": false,
   },
   "customResponseHeaders": Object {},
+  "eluMonitor": Object {
+    "enabled": true,
+    "logging": Object {
+      "enabled": false,
+      "threshold": Object {
+        "ela": 250,
+        "elu": 0.15,
+      },
+    },
+  },
   "host": "localhost",
   "keepaliveTimeout": 120000,
   "maxPayload": ByteSizeValue {

packages/core/http/core-http-server-internal/src/http_config.ts

@@ -16,6 +16,7 @@ import { hostname } from 'os';
 import url from 'url';
 
 import type { Duration } from 'moment';
+import { IHttpEluMonitorConfig } from '@kbn/core-http-server/src/elu_monitor';
 import { CspConfigType, CspConfig } from './csp';
 import { ExternalUrlConfig } from './external_url';
 import {
@@ -137,6 +138,21 @@ const configSchema = schema.object(
         { defaultValue: [] }
       ),
     }),
+    eluMonitor: schema.object({
+      enabled: schema.boolean({ defaultValue: true }),
+      logging: schema.object({
+        enabled: schema.conditional(
+          schema.contextRef('dist'),
+          false,
+          schema.boolean({ defaultValue: true }),
+          schema.boolean({ defaultValue: false })
+        ),
+        threshold: schema.object({
+          elu: schema.number({ defaultValue: 0.15, min: 0, max: 1 }),
+          ela: schema.number({ defaultValue: 250, min: 0 }),
+        }),
+      }),
+    }),
     requestId: schema.object(
       {
         allowFromAnyIp: schema.boolean({ defaultValue: false }),
@@ -226,6 +242,8 @@ export class HttpConfig implements IHttpConfig {
   public shutdownTimeout: Duration;
   public restrictInternalApis: boolean;
 
+  public eluMonitor: IHttpEluMonitorConfig;
+
   /**
    * @internal
    */
@@ -265,7 +283,9 @@ export class HttpConfig implements IHttpConfig {
     this.xsrf = rawHttpConfig.xsrf;
     this.requestId = rawHttpConfig.requestId;
     this.shutdownTimeout = rawHttpConfig.shutdownTimeout;
+
     this.restrictInternalApis = rawHttpConfig.restrictInternalApis;
+    this.eluMonitor = rawHttpConfig.eluMonitor;
   }
 }
 

packages/core/http/core-http-server-internal/src/http_server.ts

@@ -43,6 +43,10 @@ import type {
   HttpAuth,
   IAuthHeadersStorage,
 } from '@kbn/core-http-server';
+import { performance } from 'perf_hooks';
+import { isBoom } from '@hapi/boom';
+import { identity } from 'lodash';
+import { IHttpEluMonitorConfig } from '@kbn/core-http-server/src/elu_monitor';
 import { HttpConfig } from './http_config';
 import { adoptToHapiAuthFormat } from './lifecycle/auth';
 import { adoptToHapiOnPreAuth } from './lifecycle/on_pre_auth';
@@ -55,6 +59,62 @@ import { AuthHeadersStorage } from './auth_headers_storage';
 import { BasePath } from './base_path_service';
 import { getEcsResponseLog } from './logging';
 
+/**
+ * Adds ELU timings for the executed function to the current's context transaction
+ *
+ * @param path The request path
+ * @param log  Logger
+ */
+function startEluMeasurement<T>(
+  path: string,
+  log: Logger,
+  eluMonitorOptions: IHttpEluMonitorConfig | undefined
+): () => void {
+  if (!eluMonitorOptions?.enabled) {
+    return identity;
+  }
+
+  const startUtilization = performance.eventLoopUtilization();
+  const start = performance.now();
+
+  return function stopEluMeasurement() {
+    const { active, utilization } = performance.eventLoopUtilization(startUtilization);
+
+    apm.currentTransaction?.addLabels(
+      {
+        event_loop_utilization: utilization,
+        event_loop_active: active,
+      },
+      false
+    );
+
+    const duration = performance.now() - start;
+
+    const { elu: eluThreshold, ela: elaThreshold } = eluMonitorOptions.logging.threshold;
+
+    if (
+      eluMonitorOptions.logging.enabled &&
+      active >= eluMonitorOptions.logging.threshold.ela &&
+      utilization >= eluMonitorOptions.logging.threshold.elu
+    ) {
+      log.warn(
+        `Event loop utilization for ${path} exceeded threshold of ${elaThreshold}ms (${Math.round(
+          active
+        )}ms out of ${Math.round(duration)}ms) and ${eluThreshold * 100}% (${Math.round(
+          utilization * 100
+        )}%) `,
+        {
+          labels: {
+            request_path: path,
+            event_loop_active: active,
+            event_loop_utilization: utilization,
+          },
+        }
+      );
+    }
+  };
+}
+
 /** @internal */
 export interface HttpServerSetup {
   server: Server;
@@ -350,7 +410,27 @@ export class HttpServer {
     config: HttpConfig,
     executionContext?: InternalExecutionContextSetup
   ) {
+    this.server!.ext('onPreResponse', (request, responseToolkit) => {
+      const stop = (request.app as KibanaRequestState).measureElu;
+
+      if (!stop) {
+        return responseToolkit.continue;
+      }
+
+      if (isBoom(request.response)) {
+        stop();
+      } else {
+        request.response.events.once('finish', () => {
+          stop();
+        });
+      }
+
+      return responseToolkit.continue;
+    });
+
     this.server!.ext('onRequest', (request, responseToolkit) => {
+      const stop = startEluMeasurement(request.path, this.log, this.config?.eluMonitor);
+
       const requestId = getRequestId(request, config.requestId);
 
       const parentContext = executionContext?.getParentContextFrom(request.headers);
@@ -366,6 +446,7 @@ export class HttpServer {
         ...(request.app ?? {}),
         requestId,
         requestUuid: uuidv4(),
+        measureElu: stop,
         // Kibana stores trace.id until https://github.com/elastic/apm-agent-nodejs/issues/2353 is resolved
         // The current implementation of the APM agent ends a request transaction before "response" log is emitted.
         traceId: apm.currentTraceIds['trace.id'],

packages/core/http/core-http-server/index.ts

@@ -107,6 +107,8 @@ export type { ICspConfig } from './src/csp';
 
 export type { IExternalUrlConfig } from './src/external_url';
 
+export type { IHttpEluMonitorConfig } from './src/elu_monitor';
+
 export type { IBasePath } from './src/base_path';
 
 export type {

packages/core/http/core-http-server/src/elu_monitor.ts

@@ -0,0 +1,36 @@
+/*
+ * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+ * or more contributor license agreements. Licensed under the Elastic License
+ * 2.0 and the Server Side Public License, v 1; you may not use this file except
+ * in compliance with, at your election, the Elastic License 2.0 or the Server
+ * Side Public License, v 1.
+ */
+
+/**
+ * HTTP request ELU monitor config
+ * @public
+ */
+export interface IHttpEluMonitorConfig {
+  /**
+   * Whether the monitoring of event loop utilization for HTTP requests is enabled.
+   */
+  readonly enabled: boolean;
+
+  readonly logging: {
+    /**
+     * Whether to log ELU + ELA violations. Both `.elu` and `.ela` need to be exceeded for it to be considered a violation.
+     */
+    readonly enabled: boolean;
+
+    readonly threshold: {
+      /**
+       * The minimum percentage of the request duration that needs to be exceeded (needs to be between 0 and 1)
+       */
+      readonly elu: number;
+      /**
+       * The minimum number of milliseconds the event loop was active for the duration of the request.
+       */
+      readonly ela: number;
+    };
+  };
+}

packages/core/http/core-http-server/src/router/request.ts

@@ -30,6 +30,7 @@ export interface KibanaRequestState extends RequestApplicationState {
   requestUuid: string;
   rewrittenUrl?: URL;
   traceId?: string;
+  measureElu?: () => void;
 }
 
 /**