From 3474216ec7ee2c0c3526e6abbccd315d9d9a45a2 Mon Sep 17 00:00:00 2001 From: "Christiane (Tina) Heiligers" Date: Thu, 16 Dec 2021 11:23:58 -0700 Subject: [PATCH] [Logging]metrics ops logs include event loop delay histogram data (#120451) (#121430) --- .../logging/get_ops_metrics_log.test.ts | 62 ++++++++++--------- .../metrics/logging/get_ops_metrics_log.ts | 32 +++++++++- .../server/metrics/metrics_service.test.ts | 1 + 3 files changed, 63 insertions(+), 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 index cba188c94c74e..3fd3c4a7a24d6 100644 --- 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,6 +71,7 @@ describe('getEcsOpsMetricsLog', () => { const missingMetrics = { ...baseMetrics, process: {}, + processes: [], os: {}, } as unknown as OpsMetrics; const logMeta = getEcsOpsMetricsLog(missingMetrics); @@ -77,39 +79,41 @@ describe('getEcsOpsMetricsLog', () => { }); 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 index 7e13f35889ec7..6211407ae86f0 100644 --- 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 index d7de41fd7ccf7..27043b8fa2c8a 100644 --- 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,