feat: implement monitoring of callbacks executed by process.nextTick()

CHANGELOG.md

@@ -11,7 +11,32 @@ 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
+- `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).
+
+- 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
 
@@ -54,6 +79,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]

example/server.js

@@ -41,6 +41,10 @@ setInterval(() => {
 
 setInterval(() => {
 	c.inc();
+	function exampleNextTick() {
+		c.inc();
+	}
+	process.nextTick(exampleNextTick);
 }, 2000);
 
 setInterval(() => {
@@ -56,6 +60,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());

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');
@@ -11,12 +12,16 @@ 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,
+	tick,
 	osMemoryHeap,
 	processOpenFileDescriptors,
 	processMaxFileDescriptors,
@@ -25,7 +30,8 @@ const metrics = {
 	processRequests,
 	heapSizeAndUsed,
 	heapSpacesSizeAndUsed,
-	version
+	version,
+	gc
 };
 const metricsList = Object.keys(metrics);
 
@@ -45,7 +51,9 @@ module.exports = function startDefaultMetrics(config) {
 	normalizedConfig = Object.assign(
 		{
 			timestamps: true,
-			timeout: 10000
+			eventLoopMonitoringPrecision: 10,
+			timeout: 10000,
+			monitorNextTick: false
 		},
 		normalizedConfig
 	);

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
+];

lib/metrics/eventLoopLag.js

@@ -1,31 +1,131 @@
 '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);
+		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);
+			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 {
+			//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);
+			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
+];