From 99f65d3c7c8d529484ca1ff412fb54a797106a4e Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Mon, 17 Jun 2019 18:24:00 +0300 Subject: [PATCH 01/10] feat: implement GC metrics collection without native(C++) modules --- CHANGELOG.md | 2 ++ example/server.js | 13 +++++++ lib/defaultMetrics.js | 4 ++- lib/metrics/gc.js | 78 ++++++++++++++++++++++++++++++++++++++++++ test/metrics/gcTest.js | 49 ++++++++++++++++++++++++++ 5 files changed, 145 insertions(+), 1 deletion(-) create mode 100644 lib/metrics/gc.js create mode 100644 test/metrics/gcTest.js diff --git a/CHANGELOG.md b/CHANGELOG.md index 1fc8df70..e6e3cc64 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,8 @@ project adheres to [Semantic Versioning](http://semver.org/). ### Changed ### Added +- `nodejs_gc_runs` metric to the `collectDefaultMetrics()`. It counts number of GC runs with split by GC type. +- `nodejs_gc_duration_summary` metric to the `collectDefaultMetrics()`. It counts 0.5, 0.75, 0.9, 0.99 percentiles of GC duration (in seconds). ## [11.5.3] - 2019-06-27 diff --git a/example/server.js b/example/server.js index 890be2a1..28036672 100644 --- a/example/server.js +++ b/example/server.js @@ -56,6 +56,19 @@ if (cluster.isWorker) { }, 2000); } +// Generate some garbage +const t = []; +setInterval(() => { + for (let i = 0; i < 100; i++) { + t.push(new Date()); + } +}, 10); +setInterval(() => { + while (t.length > 0) { + t.pop(); + } +}); + server.get('/metrics', (req, res) => { res.set('Content-Type', register.contentType); res.end(register.metrics()); diff --git a/lib/defaultMetrics.js b/lib/defaultMetrics.js index 1972b3c8..553ed24c 100644 --- a/lib/defaultMetrics.js +++ b/lib/defaultMetrics.js @@ -11,6 +11,7 @@ const processRequests = require('./metrics/processRequests'); const heapSizeAndUsed = require('./metrics/heapSizeAndUsed'); const heapSpacesSizeAndUsed = require('./metrics/heapSpacesSizeAndUsed'); const version = require('./metrics/version'); +const gc = require('./metrics/gc'); const { globalRegistry } = require('./registry'); const { printDeprecationCollectDefaultMetricsNumber } = require('./util'); @@ -25,7 +26,8 @@ const metrics = { processRequests, heapSizeAndUsed, heapSpacesSizeAndUsed, - version + version, + gc }; const metricsList = Object.keys(metrics); diff --git a/lib/metrics/gc.js b/lib/metrics/gc.js new file mode 100644 index 00000000..b7cd71bd --- /dev/null +++ b/lib/metrics/gc.js @@ -0,0 +1,78 @@ +'use strict'; +const Counter = require('../counter'); +const Summary = require('../summary'); + +let perf_hooks; + +try { + // eslint-disable-next-line + perf_hooks = require('perf_hooks'); +} catch (e) { + // node version is too old +} + +const NODEJS_GC_RUNS = 'nodejs_gc_runs'; +const NODEJS_GC_DURATION_SUMMARY = 'nodejs_gc_duration_summary'; + +function gcKindToString(gcKind) { + let gcKindName = ''; + switch (gcKind) { + case perf_hooks.constants.NODE_PERFORMANCE_GC_MAJOR: + gcKindName = 'major'; + break; + case perf_hooks.constants.NODE_PERFORMANCE_GC_MINOR: + gcKindName = 'minor'; + break; + case perf_hooks.constants.NODE_PERFORMANCE_GC_INCREMENTAL: + gcKindName = 'incremental'; + break; + case perf_hooks.constants.NODE_PERFORMANCE_GC_WEAKCB: + gcKindName = 'weakcb'; + break; + default: + gcKindName = 'unknown'; + break; + } + return gcKindName; +} + +module.exports = (registry, config = {}) => { + if (!perf_hooks) { + return () => {}; + } + + const namePrefix = config.prefix ? config.prefix : ''; + const gcCount = new Counter({ + name: namePrefix + NODEJS_GC_RUNS, + help: + 'Count of garbage collections. gc_type label is one of major, minor, incremental or weakcb.', + labelNames: ['gc_type'], + registers: registry ? [registry] : undefined + }); + const gcSummary = new Summary({ + name: namePrefix + NODEJS_GC_DURATION_SUMMARY, + help: + 'Summary of garbage collections. gc_type label is one of major, minor, incremental or weakcb.', + labelNames: ['gc_type'], + maxAgeSeconds: 600, + ageBuckets: 5, + percentiles: [0.5, 0.75, 0.9, 0.99], + registers: registry ? [registry] : undefined + }); + + const obs = new perf_hooks.PerformanceObserver(list => { + const entry = list.getEntries()[0]; + const labels = { gc_type: gcKindToString(entry.kind) }; + + gcCount.inc(labels, 1); + // Convert duration from milliseconds to seconds + gcSummary.observe(labels, entry.duration / 1000); + }); + + // We do not expect too many gc events per second, so we do not use buffering + obs.observe({ entryTypes: ['gc'], buffered: false }); + + return () => {}; +}; + +module.exports.metricNames = [NODEJS_GC_RUNS, NODEJS_GC_DURATION_SUMMARY]; diff --git a/test/metrics/gcTest.js b/test/metrics/gcTest.js new file mode 100644 index 00000000..d0bd4a77 --- /dev/null +++ b/test/metrics/gcTest.js @@ -0,0 +1,49 @@ +'use strict'; + +describe('gc', () => { + const register = require('../../index').register; + const processHandles = require('../../lib/metrics/gc'); + + beforeAll(() => { + register.clear(); + }); + + afterEach(() => { + register.clear(); + }); + + it('should add metric to the registry', () => { + expect(register.getMetricsAsJSON()).toHaveLength(0); + + processHandles()(); + + const metrics = register.getMetricsAsJSON(); + + // 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 + } + + if (perf_hooks) { + expect(metrics).toHaveLength(2); + + expect(metrics[0].help).toEqual( + 'Count of garbage collections. gc_type label is one of major, minor, incremental or weakcb.' + ); + expect(metrics[0].type).toEqual('counter'); + expect(metrics[0].name).toEqual('nodejs_gc_runs'); + + expect(metrics[1].help).toEqual( + 'Summary of garbage collections. gc_type label is one of major, minor, incremental or weakcb.' + ); + expect(metrics[1].type).toEqual('summary'); + expect(metrics[1].name).toEqual('nodejs_gc_duration_summary'); + } else { + expect(metrics).toHaveLength(0); + } + }); +}); From 75849017e50cc746c4318b78bb27e68a2f11ea78 Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Tue, 18 Jun 2019 14:51:01 +0300 Subject: [PATCH 02/10] feat: collect bootstrap timing metrics --- CHANGELOG.md | 7 +++ lib/defaultMetrics.js | 2 + lib/metrics/bootstrapTime.js | 84 +++++++++++++++++++++++++++++++ test/metrics/bootstrapTimeTest.js | 62 +++++++++++++++++++++++ 4 files changed, 155 insertions(+) create mode 100644 lib/metrics/bootstrapTime.js create mode 100644 test/metrics/bootstrapTimeTest.js diff --git a/CHANGELOG.md b/CHANGELOG.md index e6e3cc64..0d3d9a06 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -34,6 +34,13 @@ project adheres to [Semantic Versioning](http://semver.org/). - fix: guard against missing constructor +- Following bootstap timing metrics collection implemented: + - `nodejs_node_start` - Node process start time + - `nodejs_v8_start` - V8 start time + - `nodejs_environment_initialized` - Node.js environment initialization complete time + - `nodejs_bootstrap_complete` - Node.js bootstrap complete time + - `nodejs_loop_start` - Node.js event loop start time + ## [11.5.0] - 2019-06-04 ### Added diff --git a/lib/defaultMetrics.js b/lib/defaultMetrics.js index 553ed24c..70e2deb9 100644 --- a/lib/defaultMetrics.js +++ b/lib/defaultMetrics.js @@ -12,11 +12,13 @@ const heapSizeAndUsed = require('./metrics/heapSizeAndUsed'); const heapSpacesSizeAndUsed = require('./metrics/heapSpacesSizeAndUsed'); const version = require('./metrics/version'); const gc = require('./metrics/gc'); +const bootstrapTime = require('./metrics/bootstrapTime'); const { globalRegistry } = require('./registry'); const { printDeprecationCollectDefaultMetricsNumber } = require('./util'); const metrics = { processCpuTotal, + bootstrapTime, processStartTime, osMemoryHeap, processOpenFileDescriptors, diff --git a/lib/metrics/bootstrapTime.js b/lib/metrics/bootstrapTime.js new file mode 100644 index 00000000..94b3bf43 --- /dev/null +++ b/lib/metrics/bootstrapTime.js @@ -0,0 +1,84 @@ +'use strict'; +const Gauge = require('../gauge'); + +let perf_hooks; + +try { + // eslint-disable-next-line + perf_hooks = require('perf_hooks'); +} catch (e) { + // node version is too old +} + +// Constants ordered accordingly with order of events +const NODEJS_NODE_START = 'nodejs_node_start'; +const NODEJS_V8_START = 'nodejs_v8_start'; +const NODEJS_ENVIRONMENT_INITIALIZED = 'nodejs_environment_initialized'; +const NODEJS_BOOTSTRAP_COMPLETE = 'nodejs_bootstrap_complete'; +const NODEJS_LOOP_START = 'nodejs_loop_start'; + +module.exports = (registry, config = {}) => { + if (!perf_hooks) { + return () => {}; + } + + const namePrefix = config.prefix ? config.prefix : ''; + const nodeStart = new Gauge({ + name: namePrefix + NODEJS_NODE_START, + help: 'Node process start time(in seconds).', + registers: registry ? [registry] : undefined + }); + const v8Start = new Gauge({ + name: namePrefix + NODEJS_V8_START, + help: 'V8 start time (in seconds).', + registers: registry ? [registry] : undefined + }); + const environmentInitialized = new Gauge({ + name: namePrefix + NODEJS_ENVIRONMENT_INITIALIZED, + help: 'Node.js environment initialization complete time (in seconds).', + registers: registry ? [registry] : undefined + }); + const bootstrapComplete = new Gauge({ + name: namePrefix + NODEJS_BOOTSTRAP_COMPLETE, + help: 'Node.js bootstrap complete time (in seconds).', + registers: registry ? [registry] : undefined + }); + const loopStart = new Gauge({ + name: namePrefix + NODEJS_LOOP_START, + help: 'Node.js event loop start time (in seconds).', + registers: registry ? [registry] : undefined + }); + + return () => { + const entry = perf_hooks.performance.nodeTiming; + const now = Date.now(); + + if (entry.nodeStart !== -1) { + nodeStart.set({}, entry.nodeStart, now); + } + + if (entry.v8Start !== -1) { + v8Start.set({}, entry.v8Start, now); + } + + if (entry.environment !== -1) { + environmentInitialized.set({}, entry.environment, now); + } + + if (entry.loopStart !== -1) { + loopStart.set({}, entry.loopStart, now); + } + + if (entry.bootstrapComplete !== -1) { + bootstrapComplete.set({}, entry.bootstrapComplete, now); + } + }; +}; + +module.exports.metricNames = [ + NODEJS_NODE_START, + NODEJS_V8_START, + NODEJS_ENVIRONMENT_INITIALIZED, + NODEJS_BOOTSTRAP_COMPLETE, + NODEJS_LOOP_START +]; diff --git a/test/metrics/bootstrapTimeTest.js b/test/metrics/bootstrapTimeTest.js new file mode 100644 index 00000000..6e2a8f59 --- /dev/null +++ b/test/metrics/bootstrapTimeTest.js @@ -0,0 +1,62 @@ +'use strict'; + +describe('bootstrapTime', () => { + const register = require('../../index').register; + const processHandles = require('../../lib/metrics/bootstrapTime'); + + beforeAll(() => { + register.clear(); + }); + + afterEach(() => { + register.clear(); + }); + + it('should add metric to the registry', () => { + expect(register.getMetricsAsJSON()).toHaveLength(0); + + processHandles()(); + + const metrics = register.getMetricsAsJSON(); + + // 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 + } + + if (perf_hooks) { + expect(metrics).toHaveLength(5); + expect(metrics[0].help).toEqual('Node process start time(in seconds).'); + expect(metrics[0].type).toEqual('gauge'); + expect(metrics[0].name).toEqual('nodejs_node_start'); + + expect(metrics[1].help).toEqual('V8 start time (in seconds).'); + expect(metrics[1].type).toEqual('gauge'); + expect(metrics[1].name).toEqual('nodejs_v8_start'); + + expect(metrics[2].help).toEqual( + 'Node.js environment initialization complete time (in seconds).' + ); + expect(metrics[2].type).toEqual('gauge'); + expect(metrics[2].name).toEqual('nodejs_environment_initialized'); + + expect(metrics[3].help).toEqual( + 'Node.js bootstrap complete time (in seconds).' + ); + expect(metrics[3].type).toEqual('gauge'); + expect(metrics[3].name).toEqual('nodejs_bootstrap_complete'); + + expect(metrics[4].help).toEqual( + 'Node.js event loop start time (in seconds).' + ); + expect(metrics[4].type).toEqual('gauge'); + expect(metrics[4].name).toEqual('nodejs_loop_start'); + } else { + expect(metrics).toHaveLength(0); + } + }); +}); From 6febd2d3331756b1d594b34173498519cfa2fcd5 Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Fri, 21 Jun 2019 17:49:23 +0300 Subject: [PATCH 03/10] fix: add support for timestamp option --- lib/metrics/bootstrapTime.js | 32 +++++++++++++++++++++++++------ test/metrics/bootstrapTimeTest.js | 2 +- 2 files changed, 27 insertions(+), 7 deletions(-) diff --git a/lib/metrics/bootstrapTime.js b/lib/metrics/bootstrapTime.js index 94b3bf43..1b85e5ff 100644 --- a/lib/metrics/bootstrapTime.js +++ b/lib/metrics/bootstrapTime.js @@ -4,7 +4,7 @@ const Gauge = require('../gauge'); let perf_hooks; try { - // eslint-disable-next-line + // eslint-disable-next-line node/no-unsupported-features/node-builtins perf_hooks = require('perf_hooks'); } catch (e) { // node version is too old @@ -54,23 +54,43 @@ module.exports = (registry, config = {}) => { const now = Date.now(); if (entry.nodeStart !== -1) { - nodeStart.set({}, entry.nodeStart, now); + if (config.timestamps) { + nodeStart.set({}, entry.nodeStart, now); + } else { + nodeStart.set({}, entry.nodeStart); + } } if (entry.v8Start !== -1) { - v8Start.set({}, entry.v8Start, now); + if (config.timestamps) { + v8Start.set({}, entry.v8Start, now); + } else { + v8Start.set({}, entry.v8Start); + } } if (entry.environment !== -1) { - environmentInitialized.set({}, entry.environment, now); + if (config.timestamps) { + environmentInitialized.set({}, entry.environment, now); + } else { + environmentInitialized.set({}, entry.environment); + } } if (entry.loopStart !== -1) { - loopStart.set({}, entry.loopStart, now); + if (config.timestamps) { + loopStart.set({}, entry.loopStart, now); + } else { + loopStart.set({}, entry.loopStart); + } } if (entry.bootstrapComplete !== -1) { - bootstrapComplete.set({}, entry.bootstrapComplete, now); + if (config.timestamps) { + bootstrapComplete.set({}, entry.bootstrapComplete, now); + } else { + bootstrapComplete.set({}, entry.bootstrapComplete); + } } }; }; diff --git a/test/metrics/bootstrapTimeTest.js b/test/metrics/bootstrapTimeTest.js index 6e2a8f59..7563497e 100644 --- a/test/metrics/bootstrapTimeTest.js +++ b/test/metrics/bootstrapTimeTest.js @@ -22,7 +22,7 @@ describe('bootstrapTime', () => { // Check if perf_hooks module is available let perf_hooks; try { - // eslint-disable-next-line + // eslint-disable-next-line node/no-unsupported-features/node-builtins perf_hooks = require('perf_hooks'); } catch (e) { // node version is too old From 833ee3955c53aba89687e80e3aa320f6cd8e821b Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Fri, 21 Jun 2019 18:48:44 +0300 Subject: [PATCH 04/10] fix eslint issue --- lib/metrics/bootstrapTime.js | 2 +- test/metrics/bootstrapTimeTest.js | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/metrics/bootstrapTime.js b/lib/metrics/bootstrapTime.js index 1b85e5ff..b77c4d55 100644 --- a/lib/metrics/bootstrapTime.js +++ b/lib/metrics/bootstrapTime.js @@ -4,7 +4,7 @@ const Gauge = require('../gauge'); let perf_hooks; try { - // eslint-disable-next-line node/no-unsupported-features/node-builtins + // eslint-disable-next-line perf_hooks = require('perf_hooks'); } catch (e) { // node version is too old diff --git a/test/metrics/bootstrapTimeTest.js b/test/metrics/bootstrapTimeTest.js index 7563497e..6e2a8f59 100644 --- a/test/metrics/bootstrapTimeTest.js +++ b/test/metrics/bootstrapTimeTest.js @@ -22,7 +22,7 @@ describe('bootstrapTime', () => { // Check if perf_hooks module is available let perf_hooks; try { - // eslint-disable-next-line node/no-unsupported-features/node-builtins + // eslint-disable-next-line perf_hooks = require('perf_hooks'); } catch (e) { // node version is too old From 46daca9923f5830c7e7b446ed7d946c8c0d16e83 Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Mon, 2 Sep 2019 17:25:40 +0300 Subject: [PATCH 05/10] Fix CHANGELOG --- CHANGELOG.md | 16 +++++++++------- 1 file changed, 9 insertions(+), 7 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 0d3d9a06..85c5c076 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,9 +12,17 @@ project adheres to [Semantic Versioning](http://semver.org/). ### Changed ### Added + - `nodejs_gc_runs` metric to the `collectDefaultMetrics()`. It counts number of GC runs with split by GC type. - `nodejs_gc_duration_summary` metric to the `collectDefaultMetrics()`. It counts 0.5, 0.75, 0.9, 0.99 percentiles of GC duration (in seconds). +- Following bootstap timing metrics collection implemented: + - `nodejs_node_start` - Node process start time + - `nodejs_v8_start` - V8 start time + - `nodejs_environment_initialized` - Node.js environment initialization complete time + - `nodejs_bootstrap_complete` - Node.js bootstrap complete time + - `nodejs_loop_start` - Node.js event loop start time + ## [11.5.3] - 2019-06-27 ### Changed @@ -34,13 +42,6 @@ project adheres to [Semantic Versioning](http://semver.org/). - fix: guard against missing constructor -- Following bootstap timing metrics collection implemented: - - `nodejs_node_start` - Node process start time - - `nodejs_v8_start` - V8 start time - - `nodejs_environment_initialized` - Node.js environment initialization complete time - - `nodejs_bootstrap_complete` - Node.js bootstrap complete time - - `nodejs_loop_start` - Node.js event loop start time - ## [11.5.0] - 2019-06-04 ### Added @@ -63,6 +64,7 @@ project adheres to [Semantic Versioning](http://semver.org/). metrics. (#244) ### Added + - Added a `remove()` method on each metric type, based on [Prometheus "Writing Client Libraries" section on labels](https://prometheus.io/docs/instrumenting/writing_clientlibs/#labels) ## [11.2.1] From 0e447ec9b6714e8337725cc0c6a906b0650b2f9a Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Tue, 25 Jun 2019 16:10:06 +0300 Subject: [PATCH 06/10] feat: implement advanced event loop monitoring --- lib/defaultMetrics.js | 1 + lib/metrics/eventLoopLag.js | 109 +++++++++++++++++++++++++++++-- test/metrics/eventLoopLagTest.js | 40 +++++++++++- 3 files changed, 143 insertions(+), 7 deletions(-) diff --git a/lib/defaultMetrics.js b/lib/defaultMetrics.js index 70e2deb9..c96505f6 100644 --- a/lib/defaultMetrics.js +++ b/lib/defaultMetrics.js @@ -49,6 +49,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 c11f59f790c25bc72c975cc2a5bae729e1e0244c Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Mon, 2 Sep 2019 19:12:30 +0300 Subject: [PATCH 07/10] Add notes to CHANGELOG. Change how event loop lag is being calculated --- CHANGELOG.md | 12 ++++++++++++ lib/metrics/eventLoopLag.js | 9 ++++++--- 2 files changed, 18 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 85c5c076..ba5800c1 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -11,18 +11,30 @@ project adheres to [Semantic Versioning](http://semver.org/). ### Changed +- `nodejs_eventloop_lag_seconds` - perf_hooks is available then this metric is calculate as mean event loop lag. Previous calculation was misleading + ### Added - `nodejs_gc_runs` metric to the `collectDefaultMetrics()`. It counts number of GC runs with split by GC type. - `nodejs_gc_duration_summary` metric to the `collectDefaultMetrics()`. It counts 0.5, 0.75, 0.9, 0.99 percentiles of GC duration (in seconds). - Following bootstap timing metrics collection implemented: + - `nodejs_node_start` - Node process start time - `nodejs_v8_start` - V8 start time - `nodejs_environment_initialized` - Node.js environment initialization complete time - `nodejs_bootstrap_complete` - Node.js bootstrap complete time - `nodejs_loop_start` - Node.js event loop start time +- Following event loop metrics collection implemented: + - `nodejs_eventloop_lag_min_seconds` - event loop minimum lag + - `nodejs_eventloop_lag_max_seconds` - event loop maximum lag + - `nodejs_eventloop_lag_mean_seconds` - event loop mean lag + - `nodejs_eventloop_lag_stddev_seconds` - standard deviation of event loop lag + - `nodejs_eventloop_lag_p50_seconds` - 50 percentile of event loop lag + - `nodejs_eventloop_lag_p90_seconds` - 90 percentile of event loop lag + - `nodejs_eventloop_lag_p99_seconds` - 99 percentile of event loop lag + ## [11.5.3] - 2019-06-27 ### Changed diff --git a/lib/metrics/eventLoopLag.js b/lib/metrics/eventLoopLag.js index b04c92f8..239213c0 100644 --- a/lib/metrics/eventLoopLag.js +++ b/lib/metrics/eventLoopLag.js @@ -91,12 +91,12 @@ module.exports = (registry, config = {}) => { histogram.enable(); return () => { - const start = process.hrtime(); - setImmediate(reportEventloopLag, start, lag, config.timestamps); - if (config.timestamps) { const now = Date.now(); + //event loop lag now reported as mean event loop lag + lag.set(histogram.mean / 1e9, now); + lagMin.set(histogram.min / 1e9, now); lagMax.set(histogram.max / 1e9, now); lagMean.set(histogram.mean / 1e9, now); @@ -105,6 +105,9 @@ module.exports = (registry, config = {}) => { lagP90.set(histogram.percentile(90) / 1e9, now); lagP99.set(histogram.percentile(99) / 1e9, now); } else { + //event loop lag now reported as mean event loop lag + lag.set(histogram.mean / 1e9); + lagMin.set(histogram.min / 1e9); lagMax.set(histogram.max / 1e9); lagMean.set(histogram.mean / 1e9); From 2acd3537ea0e96cc12e50cb2f5088f3692787a7c Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Wed, 19 Jun 2019 18:21:17 +0300 Subject: [PATCH 08/10] feat: implement monitoring of callbacks executed by process.nextTick() --- CHANGELOG.md | 3 ++ example/server.js | 4 ++ lib/defaultMetrics.js | 2 + lib/metrics/tick.js | 86 ++++++++++++++++++++++++++++++++++++++++ test/metrics/tickTest.js | 52 ++++++++++++++++++++++++ 5 files changed, 147 insertions(+) create mode 100644 lib/metrics/tick.js create mode 100644 test/metrics/tickTest.js diff --git a/CHANGELOG.md b/CHANGELOG.md index ba5800c1..1935e3ef 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -14,6 +14,9 @@ project adheres to [Semantic Versioning](http://semver.org/). - `nodejs_eventloop_lag_seconds` - perf_hooks is available then this metric is calculate as mean event loop lag. Previous calculation was misleading ### Added +- `monitorNextTick` option to the `collectDefaultMetrics()` config. It enables collection of two metrics listed below +- `nodejs_tick_count` counts number of ticks executed by process.nextTick(). +- `nodejs_tick_duration_summary` counts 0.5, 0.75, 0.9, 0.99 percentiles of tick execution time (in seconds). - `nodejs_gc_runs` metric to the `collectDefaultMetrics()`. It counts number of GC runs with split by GC type. - `nodejs_gc_duration_summary` metric to the `collectDefaultMetrics()`. It counts 0.5, 0.75, 0.9, 0.99 percentiles of GC duration (in seconds). diff --git a/example/server.js b/example/server.js index 28036672..3fd77e32 100644 --- a/example/server.js +++ b/example/server.js @@ -41,6 +41,10 @@ setInterval(() => { setInterval(() => { c.inc(); + function exampleNextTick() { + c.inc(); + } + process.nextTick(exampleNextTick); }, 2000); setInterval(() => { diff --git a/lib/defaultMetrics.js b/lib/defaultMetrics.js index c96505f6..f0976ae2 100644 --- a/lib/defaultMetrics.js +++ b/lib/defaultMetrics.js @@ -2,6 +2,7 @@ const processCpuTotal = require('./metrics/processCpuTotal'); const processStartTime = require('./metrics/processStartTime'); +const tick = require('./metrics/tick'); const osMemoryHeap = require('./metrics/osMemoryHeap'); const processOpenFileDescriptors = require('./metrics/processOpenFileDescriptors'); const processMaxFileDescriptors = require('./metrics/processMaxFileDescriptors'); @@ -20,6 +21,7 @@ const metrics = { processCpuTotal, bootstrapTime, processStartTime, + tick, osMemoryHeap, processOpenFileDescriptors, processMaxFileDescriptors, diff --git a/lib/metrics/tick.js b/lib/metrics/tick.js new file mode 100644 index 00000000..741ddae6 --- /dev/null +++ b/lib/metrics/tick.js @@ -0,0 +1,86 @@ +'use strict'; +const Counter = require('../counter'); +const Summary = require('../summary'); + +let perf_hooks; +let async_hooks; + +try { + // eslint-disable-next-line + perf_hooks = require('perf_hooks'); + // eslint-disable-next-line + async_hooks = require('async_hooks'); +} catch (e) { + // node version is too old +} + +const NODEJS_TICK_COUNT = 'nodejs_tick_count'; +const NODEJS_TICK_DURATION_SUMMARY = 'nodejs_tick_duration_summary'; + +module.exports = (registry, config = {}) => { + if (!perf_hooks || !async_hooks) { + return () => {}; + } + + const namePrefix = config.prefix ? config.prefix : ''; + const tickCount = new Counter({ + name: namePrefix + NODEJS_TICK_COUNT, + help: 'NO callbacks executed by procecc.nextTick()', + registers: registry ? [registry] : undefined + }); + const tickDurationSummary = new Summary({ + name: namePrefix + NODEJS_TICK_DURATION_SUMMARY, + help: 'Summary of callbacks executed by procecc.nextTick()', + maxAgeSeconds: 600, + ageBuckets: 5, + percentiles: [0.5, 0.75, 0.9, 0.99], + registers: registry ? [registry] : undefined + }); + + const obs = new perf_hooks.PerformanceObserver(list => { + const entries = list.getEntries(); + for (let i = 0; i < entries.length; i++) { + tickCount.inc({}, 1); + tickDurationSummary.observe({}, entries[i].duration / 1000); + } + }); + obs.observe({ entryTypes: ['measure'], buffered: true }); + + const idToCallbackName = new Map(); + // eslint-disable-next-line + const hook = async_hooks.createHook({ + init(id, type, triggerAsyncId, resource) { + if (type === 'TickObject') { + idToCallbackName[id] = resource.callback.name + ? resource.callback.name + : `Tick-${id}`; + } + }, + before(id) { + if (typeof idToCallbackName[id] !== 'undefined') { + perf_hooks.performance.mark(`Tick-${id}-Before`); + } + }, + after(id) { + if (typeof idToCallbackName[id] !== 'undefined') { + perf_hooks.performance.mark(`Tick-${id}-After`); + } + }, + destroy(id) { + if (typeof idToCallbackName[id] !== 'undefined') { + perf_hooks.performance.measure( + idToCallbackName[id], + `Tick-${id}-Before`, + `Tick-${id}-After` + ); + + idToCallbackName.delete(id); + } + } + }); + hook.enable(); + + return () => {}; +}; + +module.exports.metricNames = [NODEJS_TICK_COUNT, NODEJS_TICK_DURATION_SUMMARY]; diff --git a/test/metrics/tickTest.js b/test/metrics/tickTest.js new file mode 100644 index 00000000..6b912723 --- /dev/null +++ b/test/metrics/tickTest.js @@ -0,0 +1,52 @@ +'use strict'; + +describe('tick', () => { + const register = require('../../index').register; + const tick = require('../../lib/metrics/tick'); + + beforeAll(() => { + register.clear(); + }); + + afterEach(() => { + register.clear(); + }); + + it('should add metric to the registry', () => { + expect(register.getMetricsAsJSON()).toHaveLength(0); + + tick()(); + + const metrics = register.getMetricsAsJSON(); + + // Check if perf_hooks module is available + let perf_hooks; + let async_hooks; + try { + // eslint-disable-next-line + perf_hooks = require('perf_hooks'); + // eslint-disable-next-line + async_hooks = require('async_hooks'); + } catch (e) { + // node version is too old + } + + if (perf_hooks && async_hooks) { + expect(metrics).toHaveLength(2); + + expect(metrics[0].help).toEqual( + 'NO callbacks executed by procecc.nextTick()' + ); + expect(metrics[0].type).toEqual('counter'); + expect(metrics[0].name).toEqual('nodejs_tick_count'); + + expect(metrics[1].help).toEqual( + 'Summary of callbacks executed by procecc.nextTick()' + ); + expect(metrics[1].type).toEqual('summary'); + expect(metrics[1].name).toEqual('nodejs_tick_duration_summary'); + } else { + expect(metrics).toHaveLength(0); + } + }); +}); From bc0bdfdf751ff421aaaf843a4ee092163ba97837 Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Mon, 24 Jun 2019 13:03:55 +0300 Subject: [PATCH 09/10] feat: support for timestamp option --- lib/metrics/tick.js | 15 ++++++++++++--- test/metrics/tickTest.js | 2 +- 2 files changed, 13 insertions(+), 4 deletions(-) diff --git a/lib/metrics/tick.js b/lib/metrics/tick.js index 741ddae6..569ca0ea 100644 --- a/lib/metrics/tick.js +++ b/lib/metrics/tick.js @@ -18,7 +18,7 @@ const NODEJS_TICK_COUNT = 'nodejs_tick_count'; const NODEJS_TICK_DURATION_SUMMARY = 'nodejs_tick_duration_summary'; module.exports = (registry, config = {}) => { - if (!perf_hooks || !async_hooks) { + if (!perf_hooks || !async_hooks || !config.monitorNextTick) { return () => {}; } @@ -40,8 +40,17 @@ module.exports = (registry, config = {}) => { const obs = new perf_hooks.PerformanceObserver(list => { const entries = list.getEntries(); for (let i = 0; i < entries.length; i++) { - tickCount.inc({}, 1); - tickDurationSummary.observe({}, entries[i].duration / 1000); + if (config.timestamps) { + tickCount.inc({}, 1, entries[i].startTime); + tickDurationSummary.observe( + {}, + entries[i].duration / 1000, + entries[i].startTime + ); + } else { + tickCount.inc({}, 1); + tickDurationSummary.observe({}, entries[i].duration / 1000); + } } }); obs.observe({ entryTypes: ['measure'], buffered: true }); diff --git a/test/metrics/tickTest.js b/test/metrics/tickTest.js index 6b912723..38f4e3bc 100644 --- a/test/metrics/tickTest.js +++ b/test/metrics/tickTest.js @@ -15,7 +15,7 @@ describe('tick', () => { it('should add metric to the registry', () => { expect(register.getMetricsAsJSON()).toHaveLength(0); - tick()(); + tick(register, { monitorNextTick: true })(); const metrics = register.getMetricsAsJSON(); From 7b883387f00cf9824859cea935457179a407b6db Mon Sep 17 00:00:00 2001 From: Yuriy Vasiyarov Date: Mon, 24 Jun 2019 13:23:39 +0300 Subject: [PATCH 10/10] feat: make tick monitoring opt-in, disabled by default --- lib/defaultMetrics.js | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/lib/defaultMetrics.js b/lib/defaultMetrics.js index f0976ae2..5e5e1805 100644 --- a/lib/defaultMetrics.js +++ b/lib/defaultMetrics.js @@ -52,7 +52,8 @@ module.exports = function startDefaultMetrics(config) { { timestamps: true, eventLoopMonitoringPrecision: 10, - timeout: 10000 + timeout: 10000, + monitorNextTick: false }, normalizedConfig );