From f9243e1346ec2005272d1671f1461a8d4b6a0e1b Mon Sep 17 00:00:00 2001 From: ivan-tymoshenko Date: Tue, 4 Oct 2022 16:01:03 +0300 Subject: [PATCH 1/5] feat: add eventloop utilization default metric --- README.md | 1 + index.d.ts | 1 + lib/metrics/eventLoopUtilization.js | 52 ++++++++++++++++++++++ test/metrics/eventLoopUtilizationTest.js | 55 ++++++++++++++++++++++++ 4 files changed, 109 insertions(+) create mode 100644 lib/metrics/eventLoopUtilization.js create mode 100644 test/metrics/eventLoopUtilizationTest.js diff --git a/README.md b/README.md index b0484861..251b4fc2 100644 --- a/README.md +++ b/README.md @@ -54,6 +54,7 @@ available on Linux. - `register` to which metrics should be registered. Default: the global default registry. - `gcDurationBuckets` with custom buckets for GC duration histogram. Default buckets of GC duration histogram are `[0.001, 0.01, 0.1, 1, 2, 5]` (in seconds). - `eventLoopMonitoringPrecision` with sampling rate in milliseconds. Must be greater than zero. Default: 10. +- `eventLoopUtilizationTimeout` measurement duration in milliseconds. Must be greater than zero. Default: 100. To register metrics to another registry, pass it in as `register`: diff --git a/index.d.ts b/index.d.ts index a99bcd0c..399b6371 100644 --- a/index.d.ts +++ b/index.d.ts @@ -636,6 +636,7 @@ export interface DefaultMetricsCollectorConfiguration { prefix?: string; gcDurationBuckets?: number[]; eventLoopMonitoringPrecision?: number; + eventLoopUtilizationTimeout?: number; labels?: Object; } diff --git a/lib/metrics/eventLoopUtilization.js b/lib/metrics/eventLoopUtilization.js new file mode 100644 index 00000000..8b80bac3 --- /dev/null +++ b/lib/metrics/eventLoopUtilization.js @@ -0,0 +1,52 @@ +'use strict'; + +const Gauge = require('../gauge'); + +// Check if perf_hooks module is available +let perf_hooks; +try { + /* eslint-disable node/no-unsupported-features/node-builtins */ + perf_hooks = require('perf_hooks'); +} catch { + // node version is too old +} + +// Reported always. +const NODEJS_EVENTLOOP_UTILIZATION = 'nodejs_eventloop_utilization'; + +module.exports = (registry, config = {}) => { + if ( + !perf_hooks || + !perf_hooks.performance || + !perf_hooks.performance.eventLoopUtilization + ) { + return; + } + + const eventLoopUtilization = perf_hooks.performance.eventLoopUtilization; + + const namePrefix = config.prefix ? config.prefix : ''; + const labels = config.labels ? config.labels : {}; + const labelNames = Object.keys(labels); + const registers = registry ? [registry] : undefined; + + new Gauge({ + name: namePrefix + NODEJS_EVENTLOOP_UTILIZATION, + help: 'Ratio of time the event loop is not idling in the event provider to the total time the event loop is running.', + registers, + labelNames, + async collect() { + const start = eventLoopUtilization(); + + return new Promise(resolve => { + setTimeout(() => { + const end = eventLoopUtilization(); + this.set(labels, eventLoopUtilization(end, start).utilization); + resolve(); + }, config.eventLoopUtilizationTimeout || 100); + }); + }, + }); +}; + +module.exports.metricNames = [NODEJS_EVENTLOOP_UTILIZATION]; diff --git a/test/metrics/eventLoopUtilizationTest.js b/test/metrics/eventLoopUtilizationTest.js new file mode 100644 index 00000000..873f5ca3 --- /dev/null +++ b/test/metrics/eventLoopUtilizationTest.js @@ -0,0 +1,55 @@ +'use strict'; + +describe('eventLoopUtilization', () => { + const register = require('../../index').register; + const elu = require('../../lib/metrics/eventLoopUtilization'); + const { eventLoopUtilization } = require('perf_hooks').performance; + + beforeAll(() => { + register.clear(); + }); + + afterEach(() => { + register.clear(); + }); + + it('should add metric to the registry', async () => { + expect(await register.getMetricsAsJSON()).toHaveLength(0); + + elu(register, { eventLoopUtilizationTimeout: 1000 }); + + const eluStart = eventLoopUtilization(); + const metricsPromise = register.getMetricsAsJSON(); + + setImmediate(() => blockEventLoop(500)); + + const metrics = await metricsPromise; + const eluEnd = eventLoopUtilization(); + + expect(metrics).toHaveLength(1); + + const eluMetric = metrics[0]; + expect(eluMetric.help).toEqual( + 'Ratio of time the event loop is not idling in the event provider to the total time the event loop is running.', + ); + expect(eluMetric.type).toEqual('gauge'); + expect(eluMetric.name).toEqual('nodejs_eventloop_utilization'); + expect(eluMetric.values).toHaveLength(1); + + const eluValue = eluMetric.values[0].value; + expect(eluValue).toBeGreaterThanOrEqual(0); + expect(eluValue).toBeLessThanOrEqual(1); + + const expectedELU = eventLoopUtilization(eluEnd, eluStart).utilization; + expect(eluValue).toBeCloseTo(expectedELU, 2); + + console.log(eluValue, eventLoopUtilization(eluEnd, eluStart)); + }); +}); + +function blockEventLoop(ms) { + const start = Date.now(); + while (Date.now() - start < ms) { + // heavy operations + } +} From 0f099d0715a523dbafef50f7c020b40778c79489 Mon Sep 17 00:00:00 2001 From: ivan-tymoshenko Date: Wed, 5 Oct 2022 20:16:22 +0300 Subject: [PATCH 2/5] docs: add eventloop utilization to CHANGELOG.md --- CHANGELOG.md | 2 ++ 1 file changed, 2 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index a48e0e91..b116a085 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,6 +13,8 @@ project adheres to [Semantic Versioning](http://semver.org/). ### Added +- Added: `nodejs_eventloop_utilization` metric to 'collectDefaultMetrics()`. + ## [14.1.0] - 2022-08-23 ### Changed From 1806a70fcd47987ef81c3bad4996db157f41393e Mon Sep 17 00:00:00 2001 From: ivan-tymoshenko Date: Wed, 5 Oct 2022 20:32:40 +0300 Subject: [PATCH 3/5] test: skip eventloop utilization test for nodejs v10 --- test/metrics/eventLoopUtilizationTest.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/test/metrics/eventLoopUtilizationTest.js b/test/metrics/eventLoopUtilizationTest.js index 873f5ca3..d5560be0 100644 --- a/test/metrics/eventLoopUtilizationTest.js +++ b/test/metrics/eventLoopUtilizationTest.js @@ -16,6 +16,8 @@ describe('eventLoopUtilization', () => { it('should add metric to the registry', async () => { expect(await register.getMetricsAsJSON()).toHaveLength(0); + if (!eventLoopUtilization) return; + elu(register, { eventLoopUtilizationTimeout: 1000 }); const eluStart = eventLoopUtilization(); @@ -42,8 +44,6 @@ describe('eventLoopUtilization', () => { const expectedELU = eventLoopUtilization(eluEnd, eluStart).utilization; expect(eluValue).toBeCloseTo(expectedELU, 2); - - console.log(eluValue, eventLoopUtilization(eluEnd, eluStart)); }); }); From b619eff000d6a94eb024bad19795e606c2bc447f Mon Sep 17 00:00:00 2001 From: Ivan Tymoshenko Date: Mon, 8 Jan 2024 00:17:56 +0100 Subject: [PATCH 4/5] feat: add elu metric to the default metric list --- CHANGELOG.md | 1 + lib/defaultMetrics.js | 2 ++ 2 files changed, 3 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index e17ee5e2..b2d5484e 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,7 @@ project adheres to [Semantic Versioning](http://semver.org/). ### Added - Added: `nodejs_eventloop_utilization` metric to 'collectDefaultMetrics()`. + ## [15.1.0] - 2023-12-15 ### Changed diff --git a/lib/defaultMetrics.js b/lib/defaultMetrics.js index f285981a..c4421ac9 100644 --- a/lib/defaultMetrics.js +++ b/lib/defaultMetrics.js @@ -9,6 +9,7 @@ const osMemoryHeap = require('./metrics/osMemoryHeap'); const processOpenFileDescriptors = require('./metrics/processOpenFileDescriptors'); const processMaxFileDescriptors = require('./metrics/processMaxFileDescriptors'); const eventLoopLag = require('./metrics/eventLoopLag'); +const eventLoopUtilization = require('./metrics/eventLoopUtilization'); const processHandles = require('./metrics/processHandles'); const processRequests = require('./metrics/processRequests'); const processResources = require('./metrics/processResources'); @@ -24,6 +25,7 @@ const metrics = { processOpenFileDescriptors, processMaxFileDescriptors, eventLoopLag, + eventLoopUtilization, ...(typeof process.getActiveResourcesInfo === 'function' ? { processResources } : {}), From f4fac17292c86f0b08dc45196c2479768f298509 Mon Sep 17 00:00:00 2001 From: Ivan Tymoshenko Date: Wed, 10 Jan 2024 13:58:27 +0100 Subject: [PATCH 5/5] feat: use histogram and summary for elu calculation --- README.md | 6 +- index.d.ts | 4 + lib/metrics/eventLoopUtilization.js | 86 ++++++++++++++---- test/metrics/eventLoopUtilizationTest.js | 109 +++++++++++++++++------ 4 files changed, 160 insertions(+), 45 deletions(-) diff --git a/README.md b/README.md index 0e00696d..dcc83f8b 100644 --- a/README.md +++ b/README.md @@ -54,7 +54,11 @@ available on Linux. - `register` to which registry the metrics should be registered. Default: the global default registry. - `gcDurationBuckets` with custom buckets for GC duration histogram. Default buckets of GC duration histogram are `[0.001, 0.01, 0.1, 1, 2, 5]` (in seconds). - `eventLoopMonitoringPrecision` with sampling rate in milliseconds. Must be greater than zero. Default: 10. -- `eventLoopUtilizationTimeout` measurement duration in milliseconds. Must be greater than zero. Default: 100. +- `eventLoopUtilizationTimeout` interval in milliseconds to calculate event loop utilization. Must be greater than zero. Default: 100. +- `eventLoopUtilizationBuckets` with custom buckets for event loop utilization histogram. Default buckets of event loop utilization histogram are `[0.01, 0.05, 0.1, 0.25, 0.5, 0.6, 0.7, 0.75, 0.8, 0.9, 0.95, 0.99, 1]` (in seconds). +- `eventLoopUtilizationPercentiles` with custom percentiles for event loop utilization summary. Default percentiles of event loop utilization summary are `[0.01, 0.05, 0.5, 0.9, 0.95, 0.99, 0.999]`. +- `eventLoopUtilizationMaxAgeSeconds` summary sliding window time in seconds. Must be greater than zero. Default: 60. +- `eventLoopUtilizationAgeBuckets` summary sliding window buckets. Must be greater than zero. Default: 5. To register metrics to another registry, pass it in as `register`: diff --git a/index.d.ts b/index.d.ts index 54156e73..544bfab2 100644 --- a/index.d.ts +++ b/index.d.ts @@ -761,6 +761,10 @@ export interface DefaultMetricsCollectorConfiguration< gcDurationBuckets?: number[]; eventLoopMonitoringPrecision?: number; eventLoopUtilizationTimeout?: number; + eventLoopUtilizationBuckets?: number[]; + eventLoopUtilizationPercentiles?: number[]; + eventLoopUtilizationAgeBuckets: number; + eventLoopUtilizationMaxAgeSeconds: number; labels?: Object; } diff --git a/lib/metrics/eventLoopUtilization.js b/lib/metrics/eventLoopUtilization.js index 8b80bac3..e17a8cad 100644 --- a/lib/metrics/eventLoopUtilization.js +++ b/lib/metrics/eventLoopUtilization.js @@ -1,6 +1,7 @@ 'use strict'; -const Gauge = require('../gauge'); +const Summary = require('../summary'); +const Histogram = require('../histogram'); // Check if perf_hooks module is available let perf_hooks; @@ -12,7 +13,19 @@ try { } // Reported always. -const NODEJS_EVENTLOOP_UTILIZATION = 'nodejs_eventloop_utilization'; +const NODEJS_EVENTLOOP_UTILIZATION_SUMMARY = + 'nodejs_eventloop_utilization_summary'; + +const NODEJS_EVENTLOOP_UTILIZATION_HISTOGRAM = + 'nodejs_eventloop_utilization_histogram'; + +const DEFAULT_ELU_HISTOGRAM_BUCKETS = [ + 0.01, 0.05, 0.1, 0.25, 0.5, 0.6, 0.7, 0.75, 0.8, 0.9, 0.95, 0.99, 1, +]; + +const DEFAULT_ELU_SUMMARY_PERCENTILES = [ + 0.01, 0.05, 0.5, 0.9, 0.95, 0.99, 0.999, +]; module.exports = (registry, config = {}) => { if ( @@ -30,23 +43,64 @@ module.exports = (registry, config = {}) => { const labelNames = Object.keys(labels); const registers = registry ? [registry] : undefined; - new Gauge({ - name: namePrefix + NODEJS_EVENTLOOP_UTILIZATION, + const ageBuckets = config.eventLoopUtilizationAgeBuckets + ? config.eventLoopUtilizationAgeBuckets + : 5; + + const maxAgeSeconds = config.eventLoopUtilizationMaxAgeSeconds + ? config.eventLoopUtilizationMaxAgeSeconds + : 60; + + const percentiles = config.eventLoopUtilizationSummaryPercentiles + ? config.eventLoopUtilizationSummaryPercentiles + : DEFAULT_ELU_SUMMARY_PERCENTILES; + + const summary = new Summary({ + name: namePrefix + NODEJS_EVENTLOOP_UTILIZATION_SUMMARY, + help: 'Ratio of time the event loop is not idling in the event provider to the total time the event loop is running.', + maxAgeSeconds, + ageBuckets, + percentiles, + registers, + labelNames, + }); + + const buckets = config.eventLoopUtilizationBuckets + ? config.eventLoopUtilizationBuckets + : DEFAULT_ELU_HISTOGRAM_BUCKETS; + + const histogram = new Histogram({ + name: namePrefix + NODEJS_EVENTLOOP_UTILIZATION_HISTOGRAM, help: 'Ratio of time the event loop is not idling in the event provider to the total time the event loop is running.', + buckets, registers, labelNames, - async collect() { - const start = eventLoopUtilization(); - - return new Promise(resolve => { - setTimeout(() => { - const end = eventLoopUtilization(); - this.set(labels, eventLoopUtilization(end, start).utilization); - resolve(); - }, config.eventLoopUtilizationTimeout || 100); - }); - }, }); + + const intervalTimeout = config.eventLoopUtilizationTimeout || 100; + + let elu1 = eventLoopUtilization(); + let start = process.hrtime(); + + setInterval(() => { + const elu2 = eventLoopUtilization(); + const end = process.hrtime(); + + const timeMs = (end[0] - start[0]) * 1000 + (end[1] - start[1]) / 1e6; + const value = eventLoopUtilization(elu2, elu1).utilization; + + const blockedIntervalsNumber = Math.round(timeMs / intervalTimeout); + for (let i = 0; i < blockedIntervalsNumber; i++) { + summary.observe(value); + histogram.observe(value); + } + + elu1 = elu2; + start = end; + }, intervalTimeout).unref(); }; -module.exports.metricNames = [NODEJS_EVENTLOOP_UTILIZATION]; +module.exports.metricNames = [ + NODEJS_EVENTLOOP_UTILIZATION_SUMMARY, + NODEJS_EVENTLOOP_UTILIZATION_HISTOGRAM, +]; diff --git a/test/metrics/eventLoopUtilizationTest.js b/test/metrics/eventLoopUtilizationTest.js index d5560be0..96e5da60 100644 --- a/test/metrics/eventLoopUtilizationTest.js +++ b/test/metrics/eventLoopUtilizationTest.js @@ -1,10 +1,11 @@ 'use strict'; -describe('eventLoopUtilization', () => { - const register = require('../../index').register; - const elu = require('../../lib/metrics/eventLoopUtilization'); - const { eventLoopUtilization } = require('perf_hooks').performance; +const { setTimeout: sleep } = require('timers/promises'); +const register = require('../../index').register; +const elu = require('../../lib/metrics/eventLoopUtilization'); +const { eventLoopUtilization } = require('perf_hooks').performance; +describe('eventLoopUtilization', () => { beforeAll(() => { register.clear(); }); @@ -14,42 +15,94 @@ describe('eventLoopUtilization', () => { }); it('should add metric to the registry', async () => { + if (!eventLoopUtilization) return; + expect(await register.getMetricsAsJSON()).toHaveLength(0); - if (!eventLoopUtilization) return; + elu(register, { eventLoopUtilizationTimeout: 50 }); + + const expectedELU = Math.random(); + await blockEventLoop(expectedELU, 3000); - elu(register, { eventLoopUtilizationTimeout: 1000 }); + const metrics = await register.getMetricsAsJSON(); + expect(metrics).toHaveLength(2); - const eluStart = eventLoopUtilization(); - const metricsPromise = register.getMetricsAsJSON(); + { + const percentilesCount = 7; - setImmediate(() => blockEventLoop(500)); + const eluSummaryMetric = metrics[0]; + expect(eluSummaryMetric.type).toEqual('summary'); + expect(eluSummaryMetric.name).toEqual( + 'nodejs_eventloop_utilization_summary', + ); + expect(eluSummaryMetric.help).toEqual( + 'Ratio of time the event loop is not idling in the event provider to the total time the event loop is running.', + ); + expect(eluSummaryMetric.values).toHaveLength(percentilesCount + 2); - const metrics = await metricsPromise; - const eluEnd = eventLoopUtilization(); + const sum = eluSummaryMetric.values[percentilesCount]; + const count = eluSummaryMetric.values[percentilesCount + 1]; - expect(metrics).toHaveLength(1); + expect(sum.metricName).toEqual( + 'nodejs_eventloop_utilization_summary_sum', + ); + expect(count.metricName).toEqual( + 'nodejs_eventloop_utilization_summary_count', + ); + const calculatedELU = sum.value / count.value; + const delta = Math.abs(calculatedELU - expectedELU); + expect(delta).toBeLessThanOrEqual(0.05); + } - const eluMetric = metrics[0]; - expect(eluMetric.help).toEqual( - 'Ratio of time the event loop is not idling in the event provider to the total time the event loop is running.', - ); - expect(eluMetric.type).toEqual('gauge'); - expect(eluMetric.name).toEqual('nodejs_eventloop_utilization'); - expect(eluMetric.values).toHaveLength(1); + { + const bucketsCount = 14; - const eluValue = eluMetric.values[0].value; - expect(eluValue).toBeGreaterThanOrEqual(0); - expect(eluValue).toBeLessThanOrEqual(1); + const eluHistogramMetric = metrics[1]; + expect(eluHistogramMetric.type).toEqual('histogram'); + expect(eluHistogramMetric.name).toEqual( + 'nodejs_eventloop_utilization_histogram', + ); + expect(eluHistogramMetric.help).toEqual( + 'Ratio of time the event loop is not idling in the event provider to the total time the event loop is running.', + ); + expect(eluHistogramMetric.values).toHaveLength(bucketsCount + 2); - const expectedELU = eventLoopUtilization(eluEnd, eluStart).utilization; - expect(eluValue).toBeCloseTo(expectedELU, 2); + const sum = eluHistogramMetric.values[bucketsCount]; + const count = eluHistogramMetric.values[bucketsCount + 1]; + + expect(sum.metricName).toEqual( + 'nodejs_eventloop_utilization_histogram_sum', + ); + expect(count.metricName).toEqual( + 'nodejs_eventloop_utilization_histogram_count', + ); + const calculatedELU = sum.value / count.value; + const delta = Math.abs(calculatedELU - expectedELU); + expect(delta).toBeLessThanOrEqual(0.05); + + const infBucket = eluHistogramMetric.values[bucketsCount - 1]; + expect(infBucket.labels.le).toEqual('+Inf'); + expect(infBucket.value).toEqual(count.value); + + const le1Bucket = eluHistogramMetric.values[bucketsCount - 2]; + expect(le1Bucket.labels.le).toEqual(1); + expect(le1Bucket.value).toEqual(count.value); + } }); }); -function blockEventLoop(ms) { - const start = Date.now(); - while (Date.now() - start < ms) { - // heavy operations +async function blockEventLoop(ratio, ms) { + const frameMs = 1000; + const framesNumber = Math.round(ms / frameMs); + + const blockedFrameTime = ratio * frameMs; + const freeFrameTime = frameMs - blockedFrameTime; + + for (let i = 0; i < framesNumber; i++) { + const endBlockedTime = Date.now() + blockedFrameTime; + while (Date.now() < endBlockedTime) { + // heavy operations + } + await sleep(freeFrameTime); } }