[Logging]metrics ops logs include event loop delay histogram data (#1…

…20451)
elastic · Dec 13, 2021 · de777f7 · de777f7
1 parent a820dda
commit de777f7
Show file tree

Hide file tree

Showing 3 changed files with 63 additions and 32 deletions.
diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.test.ts b/src/core/server/metrics/logging/get_ops_metrics_log.test.ts
@@ -42,6 +42,7 @@ const testMetrics = {
     memory: { heap: { used_in_bytes: 100 } },
     uptime_in_millis: 1500,
     event_loop_delay: 50,
+    event_loop_delay_histogram: { percentiles: { '50': 50, '75': 75, '95': 95, '99': 99 } },
   },
   os: {
     load: {
@@ -56,7 +57,7 @@ describe('getEcsOpsMetricsLog', () => {
   it('provides correctly formatted message', () => {
     const result = getEcsOpsMetricsLog(createMockOpsMetrics(testMetrics));
     expect(result.message).toMatchInlineSnapshot(
-      `"memory: 100.0B uptime: 0:00:01 load: [10.00,20.00,30.00] delay: 50.000"`
+      `"memory: 100.0B uptime: 0:00:01 load: [10.00,20.00,30.00] mean delay: 50.000 delay histogram: { 50: 50.000; 95: 95.000; 99: 99.000 }"`
     );
   });
 
@@ -70,46 +71,49 @@ describe('getEcsOpsMetricsLog', () => {
     const missingMetrics = {
       ...baseMetrics,
       process: {},
+      processes: [],
       os: {},
     } as unknown as OpsMetrics;
     const logMeta = getEcsOpsMetricsLog(missingMetrics);
     expect(logMeta.message).toMatchInlineSnapshot(`""`);
   });
 
   it('provides an ECS-compatible response', () => {
-    const logMeta = getEcsOpsMetricsLog(createBaseOpsMetrics());
-    expect(logMeta).toMatchInlineSnapshot(`
+    const logMeta = getEcsOpsMetricsLog(createMockOpsMetrics(testMetrics));
+    expect(logMeta.meta).toMatchInlineSnapshot(`
       Object {
-        "message": "memory: 1.0B load: [1.00,1.00,1.00] delay: 1.000",
-        "meta": Object {
-          "event": Object {
-            "category": Array [
-              "process",
-              "host",
-            ],
-            "kind": "metric",
-            "type": Array [
-              "info",
-            ],
-          },
-          "host": Object {
-            "os": Object {
-              "load": Object {
-                "15m": 1,
-                "1m": 1,
-                "5m": 1,
-              },
+        "event": Object {
+          "category": Array [
+            "process",
+            "host",
+          ],
+          "kind": "metric",
+          "type": Array [
+            "info",
+          ],
+        },
+        "host": Object {
+          "os": Object {
+            "load": Object {
+              "15m": 30,
+              "1m": 10,
+              "5m": 20,
             },
           },
-          "process": Object {
-            "eventLoopDelay": 1,
-            "memory": Object {
-              "heap": Object {
-                "usedInBytes": 1,
-              },
+        },
+        "process": Object {
+          "eventLoopDelay": 50,
+          "eventLoopDelayHistogram": Object {
+            "50": 50,
+            "95": 95,
+            "99": 99,
+          },
+          "memory": Object {
+            "heap": Object {
+              "usedInBytes": 100,
             },
-            "uptime": 0,
           },
+          "uptime": 1,
         },
       }
     `);

diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.ts b/src/core/server/metrics/logging/get_ops_metrics_log.ts
@@ -30,10 +30,29 @@ export function getEcsOpsMetricsLog(metrics: OpsMetrics) {
   // HH:mm:ss message format for backward compatibility
   const uptimeValMsg = uptimeVal ? `uptime: ${numeral(uptimeVal).format('00:00:00')} ` : '';
 
-  // Event loop delay is in ms
+  // Event loop delay metrics are in ms
   const eventLoopDelayVal = process?.event_loop_delay;
   const eventLoopDelayValMsg = eventLoopDelayVal
-    ? `delay: ${numeral(process?.event_loop_delay).format('0.000')}`
+    ? `mean delay: ${numeral(process?.event_loop_delay).format('0.000')}`
+    : '';
+
+  const eventLoopDelayPercentiles = process?.event_loop_delay_histogram?.percentiles;
+
+  // Extract 50th, 95th and 99th percentiles for log meta
+  const eventLoopDelayHistVals = eventLoopDelayPercentiles
+    ? {
+        50: eventLoopDelayPercentiles[50],
+        95: eventLoopDelayPercentiles[95],
+        99: eventLoopDelayPercentiles[99],
+      }
+    : undefined;
+  // Format message from 50th, 95th and 99th percentiles
+  const eventLoopDelayHistMsg = eventLoopDelayPercentiles
+    ? ` delay histogram: { 50: ${numeral(eventLoopDelayPercentiles['50']).format(
+        '0.000'
+      )}; 95: ${numeral(eventLoopDelayPercentiles['95']).format('0.000')}; 99: ${numeral(
+        eventLoopDelayPercentiles['99']
+      ).format('0.000')} }`
     : '';
 
   const loadEntries = {
@@ -65,6 +84,7 @@ export function getEcsOpsMetricsLog(metrics: OpsMetrics) {
         },
       },
       eventLoopDelay: eventLoopDelayVal,
+      eventLoopDelayHistogram: eventLoopDelayHistVals,
     },
     host: {
       os: {
@@ -75,7 +95,13 @@ export function getEcsOpsMetricsLog(metrics: OpsMetrics) {
   };
 
   return {
-    message: `${processMemoryUsedInBytesMsg}${uptimeValMsg}${loadValsMsg}${eventLoopDelayValMsg}`,
+    message: [
+      processMemoryUsedInBytesMsg,
+      uptimeValMsg,
+      loadValsMsg,
+      eventLoopDelayValMsg,
+      eventLoopDelayHistMsg,
+    ].join(''),
     meta,
   };
 }
diff --git a/src/core/server/metrics/metrics_service.test.ts b/src/core/server/metrics/metrics_service.test.ts
@@ -203,6 +203,7 @@ describe('MetricsService', () => {
             },
             "process": Object {
               "eventLoopDelay": undefined,
+              "eventLoopDelayHistogram": undefined,
               "memory": Object {
                 "heap": Object {
                   "usedInBytes": undefined,