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