feat: collect bootstrap timing metrics

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]

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());

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);
 

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

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);
+		}
+	});
+});

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);
+		}
+	});
+});