diff --git a/CHANGELOG.md b/CHANGELOG.md index 1fc8df70..85c5c076 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,6 +13,16 @@ project adheres to [Semantic Versioning](http://semver.org/). ### 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 @@ -54,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] 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..70e2deb9 100644 --- a/lib/defaultMetrics.js +++ b/lib/defaultMetrics.js @@ -11,11 +11,14 @@ 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 bootstrapTime = require('./metrics/bootstrapTime'); const { globalRegistry } = require('./registry'); const { printDeprecationCollectDefaultMetricsNumber } = require('./util'); const metrics = { processCpuTotal, + bootstrapTime, processStartTime, osMemoryHeap, processOpenFileDescriptors, @@ -25,7 +28,8 @@ const metrics = { processRequests, heapSizeAndUsed, heapSpacesSizeAndUsed, - version + version, + gc }; const metricsList = Object.keys(metrics); diff --git a/lib/metrics/bootstrapTime.js b/lib/metrics/bootstrapTime.js new file mode 100644 index 00000000..b77c4d55 --- /dev/null +++ b/lib/metrics/bootstrapTime.js @@ -0,0 +1,104 @@ +'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) { + if (config.timestamps) { + nodeStart.set({}, entry.nodeStart, now); + } else { + nodeStart.set({}, entry.nodeStart); + } + } + + if (entry.v8Start !== -1) { + if (config.timestamps) { + v8Start.set({}, entry.v8Start, now); + } else { + v8Start.set({}, entry.v8Start); + } + } + + if (entry.environment !== -1) { + if (config.timestamps) { + environmentInitialized.set({}, entry.environment, now); + } else { + environmentInitialized.set({}, entry.environment); + } + } + + if (entry.loopStart !== -1) { + if (config.timestamps) { + loopStart.set({}, entry.loopStart, now); + } else { + loopStart.set({}, entry.loopStart); + } + } + + if (entry.bootstrapComplete !== -1) { + if (config.timestamps) { + bootstrapComplete.set({}, entry.bootstrapComplete, now); + } else { + bootstrapComplete.set({}, entry.bootstrapComplete); + } + } + }; +}; + +module.exports.metricNames = [ + NODEJS_NODE_START, + NODEJS_V8_START, + NODEJS_ENVIRONMENT_INITIALIZED, + NODEJS_BOOTSTRAP_COMPLETE, + NODEJS_LOOP_START +]; 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/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); + } + }); +}); 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); + } + }); +});