From 00f0fde9ff1baec03c8deed4656ce1e580427fc4 Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Sun, 2 Feb 2020 18:15:27 +0300 Subject: [PATCH 1/8] feat: implement advanced event loop monitoring --- CHANGELOG.md | 1 + README.md | 13 ++-- index.d.ts | 1 + lib/defaultMetrics.js | 1 + lib/metrics/eventLoopLag.js | 109 +++++++++++++++++++++++++++++-- test/metrics/eventLoopLagTest.js | 40 +++++++++++- 6 files changed, 153 insertions(+), 12 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index c0037886..e16bb8b6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -28,6 +28,7 @@ project adheres to [Semantic Versioning](http://semver.org/). ### Added - feat: implement GC metrics collection without native(C++) modules. +- faet: implement advanced event loop monitoring ## [11.5.3] - 2019-06-27 diff --git a/README.md b/README.md index eeba8f87..b017d1e4 100644 --- a/README.md +++ b/README.md @@ -51,11 +51,14 @@ In addition, some Node-specific metrics are included, such as event loop lag, active handles, GC and Node.js version. See what metrics there are in [lib/metrics](lib/metrics). -`collectDefaultMetrics` takes 1 options object with up to 4 entries, a timeout for how -often the probe should be fired, an optional prefix for metric names, -a registry to which metrics should be registered and -`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). +`collectDefaultMetrics` takes 1 options object with following entries: + +- `timeout` for how often the probe should be fired. Default: 10 seconds. +- `prefix` an optional prefix for metric names. +- `registry` to which metrics should be registered. +- `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. + By default probes are launched every 10 seconds, but this can be modified like this: ```js diff --git a/index.d.ts b/index.d.ts index e66b1d11..57f650cd 100644 --- a/index.d.ts +++ b/index.d.ts @@ -651,6 +651,7 @@ export interface DefaultMetricsCollectorConfiguration { register?: Registry; prefix?: string; gcDurationBuckets?: number[]; + eventLoopMonitoringPrecision?: number; } /** diff --git a/lib/defaultMetrics.js b/lib/defaultMetrics.js index 553ed24c..6deb90b1 100644 --- a/lib/defaultMetrics.js +++ b/lib/defaultMetrics.js @@ -47,6 +47,7 @@ module.exports = function startDefaultMetrics(config) { normalizedConfig = Object.assign( { timestamps: true, + eventLoopMonitoringPrecision: 10, timeout: 10000 }, normalizedConfig diff --git a/lib/metrics/eventLoopLag.js b/lib/metrics/eventLoopLag.js index 56aff27a..b04c92f8 100644 --- a/lib/metrics/eventLoopLag.js +++ b/lib/metrics/eventLoopLag.js @@ -1,31 +1,128 @@ 'use strict'; - const Gauge = require('../gauge'); +// Check if perf_hooks module is available +let perf_hooks; +try { + // eslint-disable-next-line + perf_hooks = require('perf_hooks'); +} catch (e) { + // node version is too old +} + const NODEJS_EVENTLOOP_LAG = 'nodejs_eventloop_lag_seconds'; +const NODEJS_EVENTLOOP_LAG_MIN = 'nodejs_eventloop_lag_min_seconds'; +const NODEJS_EVENTLOOP_LAG_MAX = 'nodejs_eventloop_lag_max_seconds'; +const NODEJS_EVENTLOOP_LAG_MEAN = 'nodejs_eventloop_lag_mean_seconds'; +const NODEJS_EVENTLOOP_LAG_STDDEV = 'nodejs_eventloop_lag_stddev_seconds'; +const NODEJS_EVENTLOOP_LAG_P50 = 'nodejs_eventloop_lag_p50_seconds'; +const NODEJS_EVENTLOOP_LAG_P90 = 'nodejs_eventloop_lag_p90_seconds'; +const NODEJS_EVENTLOOP_LAG_P99 = 'nodejs_eventloop_lag_p99_seconds'; -function reportEventloopLag(start, gauge) { +function reportEventloopLag(start, gauge, timestamps) { const delta = process.hrtime(start); const nanosec = delta[0] * 1e9 + delta[1]; const seconds = nanosec / 1e9; - gauge.set(seconds, Date.now()); + if (timestamps) { + gauge.set(seconds, Date.now()); + } else { + gauge.set(seconds); + } } module.exports = (registry, config = {}) => { const namePrefix = config.prefix ? config.prefix : ''; - const gauge = new Gauge({ + const lag = new Gauge({ name: namePrefix + NODEJS_EVENTLOOP_LAG, help: 'Lag of event loop in seconds.', registers: registry ? [registry] : undefined, aggregator: 'average' }); + const lagMin = new Gauge({ + name: namePrefix + NODEJS_EVENTLOOP_LAG_MIN, + help: 'The minimum recorded event loop delay.', + registers: registry ? [registry] : undefined + }); + const lagMax = new Gauge({ + name: namePrefix + NODEJS_EVENTLOOP_LAG_MAX, + help: 'The maximum recorded event loop delay.', + registers: registry ? [registry] : undefined + }); + const lagMean = new Gauge({ + name: namePrefix + NODEJS_EVENTLOOP_LAG_MEAN, + help: 'The mean of the recorded event loop delays.', + registers: registry ? [registry] : undefined + }); + const lagStddev = new Gauge({ + name: namePrefix + NODEJS_EVENTLOOP_LAG_STDDEV, + help: 'The standard deviation of the recorded event loop delays.', + registers: registry ? [registry] : undefined + }); + const lagP50 = new Gauge({ + name: namePrefix + NODEJS_EVENTLOOP_LAG_P50, + help: 'The 50 percentile of the recorded event loop delays.', + registers: registry ? [registry] : undefined + }); + const lagP90 = new Gauge({ + name: namePrefix + NODEJS_EVENTLOOP_LAG_P90, + help: 'The 90 percentile of the recorded event loop delays.', + registers: registry ? [registry] : undefined + }); + const lagP99 = new Gauge({ + name: namePrefix + NODEJS_EVENTLOOP_LAG_P99, + help: 'The 99 percentile of the recorded event loop delays.', + registers: registry ? [registry] : undefined + }); + + // eslint-disable-next-line + if (!perf_hooks || !perf_hooks.monitorEventLoopDelay) { + return () => { + const start = process.hrtime(); + setImmediate(reportEventloopLag, start, lag, config.timestamps); + }; + } + + // eslint-disable-next-line + const histogram = perf_hooks.monitorEventLoopDelay({ + resolution: config.eventLoopMonitoringPrecision + }); + histogram.enable(); return () => { const start = process.hrtime(); - setImmediate(reportEventloopLag, start, gauge); + setImmediate(reportEventloopLag, start, lag, config.timestamps); + + if (config.timestamps) { + const now = Date.now(); + + lagMin.set(histogram.min / 1e9, now); + lagMax.set(histogram.max / 1e9, now); + lagMean.set(histogram.mean / 1e9, now); + lagStddev.set(histogram.stddev / 1e9, now); + lagP50.set(histogram.percentile(50) / 1e9, now); + lagP90.set(histogram.percentile(90) / 1e9, now); + lagP99.set(histogram.percentile(99) / 1e9, now); + } else { + lagMin.set(histogram.min / 1e9); + lagMax.set(histogram.max / 1e9); + lagMean.set(histogram.mean / 1e9); + lagStddev.set(histogram.stddev / 1e9); + lagP50.set(histogram.percentile(50) / 1e9); + lagP90.set(histogram.percentile(90) / 1e9); + lagP99.set(histogram.percentile(99) / 1e9); + } }; }; -module.exports.metricNames = [NODEJS_EVENTLOOP_LAG]; +module.exports.metricNames = [ + NODEJS_EVENTLOOP_LAG, + NODEJS_EVENTLOOP_LAG_MIN, + NODEJS_EVENTLOOP_LAG_MAX, + NODEJS_EVENTLOOP_LAG_MEAN, + NODEJS_EVENTLOOP_LAG_STDDEV, + NODEJS_EVENTLOOP_LAG_P50, + NODEJS_EVENTLOOP_LAG_P90, + NODEJS_EVENTLOOP_LAG_P99 +]; diff --git a/test/metrics/eventLoopLagTest.js b/test/metrics/eventLoopLagTest.js index d9bfd6e9..dcea0ff3 100644 --- a/test/metrics/eventLoopLagTest.js +++ b/test/metrics/eventLoopLagTest.js @@ -18,12 +18,50 @@ describe('eventLoopLag', () => { setTimeout(() => { const metrics = register.getMetricsAsJSON(); - expect(metrics).toHaveLength(1); + expect(metrics).toHaveLength(8); expect(metrics[0].help).toEqual('Lag of event loop in seconds.'); expect(metrics[0].type).toEqual('gauge'); expect(metrics[0].name).toEqual('nodejs_eventloop_lag_seconds'); + expect(metrics[1].help).toEqual('The minimum recorded event loop delay.'); + expect(metrics[1].type).toEqual('gauge'); + expect(metrics[1].name).toEqual('nodejs_eventloop_lag_min_seconds'); + + expect(metrics[2].help).toEqual('The maximum recorded event loop delay.'); + expect(metrics[2].type).toEqual('gauge'); + expect(metrics[2].name).toEqual('nodejs_eventloop_lag_max_seconds'); + + expect(metrics[3].help).toEqual( + 'The mean of the recorded event loop delays.' + ); + expect(metrics[3].type).toEqual('gauge'); + expect(metrics[3].name).toEqual('nodejs_eventloop_lag_mean_seconds'); + + expect(metrics[4].help).toEqual( + 'The standard deviation of the recorded event loop delays.' + ); + expect(metrics[4].type).toEqual('gauge'); + expect(metrics[4].name).toEqual('nodejs_eventloop_lag_stddev_seconds'); + + expect(metrics[5].help).toEqual( + 'The 50 percentile of the recorded event loop delays.' + ); + expect(metrics[5].type).toEqual('gauge'); + expect(metrics[5].name).toEqual('nodejs_eventloop_lag_p50_seconds'); + + expect(metrics[6].help).toEqual( + 'The 90 percentile of the recorded event loop delays.' + ); + expect(metrics[6].type).toEqual('gauge'); + expect(metrics[6].name).toEqual('nodejs_eventloop_lag_p90_seconds'); + + expect(metrics[7].help).toEqual( + 'The 99 percentile of the recorded event loop delays.' + ); + expect(metrics[7].type).toEqual('gauge'); + expect(metrics[7].name).toEqual('nodejs_eventloop_lag_p99_seconds'); + done(); }, 5); }); From 648ccc70637024db8f189e0a364f5fa0a28a5af5 Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Sun, 9 Feb 2020 22:48:27 +0300 Subject: [PATCH 2/8] Update lib/metrics/eventLoopLag.js Co-Authored-By: Sam Roberts --- lib/metrics/eventLoopLag.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/metrics/eventLoopLag.js b/lib/metrics/eventLoopLag.js index b04c92f8..dad7709a 100644 --- a/lib/metrics/eventLoopLag.js +++ b/lib/metrics/eventLoopLag.js @@ -72,7 +72,7 @@ module.exports = (registry, config = {}) => { }); const lagP99 = new Gauge({ name: namePrefix + NODEJS_EVENTLOOP_LAG_P99, - help: 'The 99 percentile of the recorded event loop delays.', + help: 'The 99th percentile of the recorded event loop delays.', registers: registry ? [registry] : undefined }); From 474aa24e0d8dbf65c14df803a6af80c0b3649db8 Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Sun, 9 Feb 2020 22:48:41 +0300 Subject: [PATCH 3/8] Update lib/metrics/eventLoopLag.js Co-Authored-By: Sam Roberts --- lib/metrics/eventLoopLag.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/metrics/eventLoopLag.js b/lib/metrics/eventLoopLag.js index dad7709a..1ee72b2d 100644 --- a/lib/metrics/eventLoopLag.js +++ b/lib/metrics/eventLoopLag.js @@ -67,7 +67,7 @@ module.exports = (registry, config = {}) => { }); const lagP90 = new Gauge({ name: namePrefix + NODEJS_EVENTLOOP_LAG_P90, - help: 'The 90 percentile of the recorded event loop delays.', + help: 'The 90th percentile of the recorded event loop delays.', registers: registry ? [registry] : undefined }); const lagP99 = new Gauge({ From f81831e39c9a72f6d99e7c8b60a5bc0fbc2e5151 Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Sun, 9 Feb 2020 22:48:52 +0300 Subject: [PATCH 4/8] Update lib/metrics/eventLoopLag.js Co-Authored-By: Sam Roberts --- lib/metrics/eventLoopLag.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/metrics/eventLoopLag.js b/lib/metrics/eventLoopLag.js index 1ee72b2d..96a43eea 100644 --- a/lib/metrics/eventLoopLag.js +++ b/lib/metrics/eventLoopLag.js @@ -62,7 +62,7 @@ module.exports = (registry, config = {}) => { }); const lagP50 = new Gauge({ name: namePrefix + NODEJS_EVENTLOOP_LAG_P50, - help: 'The 50 percentile of the recorded event loop delays.', + help: 'The 50th percentile of the recorded event loop delays.', registers: registry ? [registry] : undefined }); const lagP90 = new Gauge({ From 73083f542c3f4b78a3c7121c5378b289ccdf5a4d Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Sun, 9 Feb 2020 23:11:43 +0300 Subject: [PATCH 5/8] fix: remove timestamp support, fix tests --- lib/metrics/eventLoopLag.js | 38 +++++++++----------------------- test/metrics/eventLoopLagTest.js | 6 ++--- 2 files changed, 14 insertions(+), 30 deletions(-) diff --git a/lib/metrics/eventLoopLag.js b/lib/metrics/eventLoopLag.js index 96a43eea..2cfabf46 100644 --- a/lib/metrics/eventLoopLag.js +++ b/lib/metrics/eventLoopLag.js @@ -19,16 +19,12 @@ const NODEJS_EVENTLOOP_LAG_P50 = 'nodejs_eventloop_lag_p50_seconds'; const NODEJS_EVENTLOOP_LAG_P90 = 'nodejs_eventloop_lag_p90_seconds'; const NODEJS_EVENTLOOP_LAG_P99 = 'nodejs_eventloop_lag_p99_seconds'; -function reportEventloopLag(start, gauge, timestamps) { +function reportEventloopLag(start, gauge) { const delta = process.hrtime(start); const nanosec = delta[0] * 1e9 + delta[1]; const seconds = nanosec / 1e9; - if (timestamps) { - gauge.set(seconds, Date.now()); - } else { - gauge.set(seconds); - } + gauge.set(seconds); } module.exports = (registry, config = {}) => { @@ -80,7 +76,7 @@ module.exports = (registry, config = {}) => { if (!perf_hooks || !perf_hooks.monitorEventLoopDelay) { return () => { const start = process.hrtime(); - setImmediate(reportEventloopLag, start, lag, config.timestamps); + setImmediate(reportEventloopLag, start, lag); }; } @@ -92,27 +88,15 @@ module.exports = (registry, config = {}) => { return () => { const start = process.hrtime(); - setImmediate(reportEventloopLag, start, lag, config.timestamps); - - if (config.timestamps) { - const now = Date.now(); + setImmediate(reportEventloopLag, start, lag); - lagMin.set(histogram.min / 1e9, now); - lagMax.set(histogram.max / 1e9, now); - lagMean.set(histogram.mean / 1e9, now); - lagStddev.set(histogram.stddev / 1e9, now); - lagP50.set(histogram.percentile(50) / 1e9, now); - lagP90.set(histogram.percentile(90) / 1e9, now); - lagP99.set(histogram.percentile(99) / 1e9, now); - } else { - lagMin.set(histogram.min / 1e9); - lagMax.set(histogram.max / 1e9); - lagMean.set(histogram.mean / 1e9); - lagStddev.set(histogram.stddev / 1e9); - lagP50.set(histogram.percentile(50) / 1e9); - lagP90.set(histogram.percentile(90) / 1e9); - lagP99.set(histogram.percentile(99) / 1e9); - } + lagMin.set(histogram.min / 1e9); + lagMax.set(histogram.max / 1e9); + lagMean.set(histogram.mean / 1e9); + lagStddev.set(histogram.stddev / 1e9); + lagP50.set(histogram.percentile(50) / 1e9); + lagP90.set(histogram.percentile(90) / 1e9); + lagP99.set(histogram.percentile(99) / 1e9); }; }; diff --git a/test/metrics/eventLoopLagTest.js b/test/metrics/eventLoopLagTest.js index dcea0ff3..0dd6dcc3 100644 --- a/test/metrics/eventLoopLagTest.js +++ b/test/metrics/eventLoopLagTest.js @@ -45,19 +45,19 @@ describe('eventLoopLag', () => { expect(metrics[4].name).toEqual('nodejs_eventloop_lag_stddev_seconds'); expect(metrics[5].help).toEqual( - 'The 50 percentile of the recorded event loop delays.' + 'The 50th percentile of the recorded event loop delays.' ); expect(metrics[5].type).toEqual('gauge'); expect(metrics[5].name).toEqual('nodejs_eventloop_lag_p50_seconds'); expect(metrics[6].help).toEqual( - 'The 90 percentile of the recorded event loop delays.' + 'The 90th percentile of the recorded event loop delays.' ); expect(metrics[6].type).toEqual('gauge'); expect(metrics[6].name).toEqual('nodejs_eventloop_lag_p90_seconds'); expect(metrics[7].help).toEqual( - 'The 99 percentile of the recorded event loop delays.' + 'The 99th percentile of the recorded event loop delays.' ); expect(metrics[7].type).toEqual('gauge'); expect(metrics[7].name).toEqual('nodejs_eventloop_lag_p99_seconds'); From fa467caaea10ed24906d8d0c849cfbb23683d10e Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Tue, 11 Feb 2020 13:02:18 +0300 Subject: [PATCH 6/8] Update lib/metrics/eventLoopLag.js Co-Authored-By: Sam Roberts --- lib/metrics/eventLoopLag.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/metrics/eventLoopLag.js b/lib/metrics/eventLoopLag.js index 2cfabf46..7b1258c4 100644 --- a/lib/metrics/eventLoopLag.js +++ b/lib/metrics/eventLoopLag.js @@ -4,7 +4,7 @@ const Gauge = require('../gauge'); // Check if perf_hooks module is available let perf_hooks; try { - // eslint-disable-next-line + /* eslint-disable node/no-unsupported-features/node-builtins */ perf_hooks = require('perf_hooks'); } catch (e) { // node version is too old From e4bcfced7bf11eb87c422ce4cb726d9e0a1d0a01 Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Tue, 11 Feb 2020 13:03:21 +0300 Subject: [PATCH 7/8] Update lib/metrics/eventLoopLag.js Co-Authored-By: Sam Roberts --- lib/metrics/eventLoopLag.js | 1 - 1 file changed, 1 deletion(-) diff --git a/lib/metrics/eventLoopLag.js b/lib/metrics/eventLoopLag.js index 7b1258c4..35da96d3 100644 --- a/lib/metrics/eventLoopLag.js +++ b/lib/metrics/eventLoopLag.js @@ -72,7 +72,6 @@ module.exports = (registry, config = {}) => { registers: registry ? [registry] : undefined }); - // eslint-disable-next-line if (!perf_hooks || !perf_hooks.monitorEventLoopDelay) { return () => { const start = process.hrtime(); From ac3e673e5ad6b67535a2f55f70eb907493d85ec3 Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Tue, 11 Feb 2020 13:03:33 +0300 Subject: [PATCH 8/8] Update lib/metrics/eventLoopLag.js Co-Authored-By: Sam Roberts --- lib/metrics/eventLoopLag.js | 1 - 1 file changed, 1 deletion(-) diff --git a/lib/metrics/eventLoopLag.js b/lib/metrics/eventLoopLag.js index 35da96d3..07f73e0f 100644 --- a/lib/metrics/eventLoopLag.js +++ b/lib/metrics/eventLoopLag.js @@ -79,7 +79,6 @@ module.exports = (registry, config = {}) => { }; } - // eslint-disable-next-line const histogram = perf_hooks.monitorEventLoopDelay({ resolution: config.eventLoopMonitoringPrecision });