Node 3680 rwb enhancements (#26)

* don't replace defaults with empty env vars
* invoke interval handler on SIGINT
* fix always-on loads
* add tests for 'load' events
* version 2.0.0

.github/workflows/on-new-code.yml

@@ -2,7 +2,7 @@ name: on-new-code
 on:
   push:
     branches:
-      - master
+      - main
   pull_request:
     branches: '*'
 jobs:
@@ -25,11 +25,3 @@ jobs:
       run: npm install
     - name: Run tests
       run: npm test
-#    - if: matrix.node-version == 14
-#      name: generate code coverage
-#      run: npm run test:ci
-#    - if: matrix.node-version == 14
-#      name: send coverage to codecov
-#      uses: codecov/codecov-action@v1
-#      with:
-#        token: ${{ secrets.CODECOV_TOKEN}}

README.md

@@ -34,6 +34,20 @@ This allows server performance, exclusive of network time, to be compared
 with and without other packages installed. `route-metrics` writes a json
 log file, `route-metrics.log` by default.
 
+### benchmarking
+
+A primary use case for `route-metrics` is benchmark performance of different
+configurations. Because the time-series data is written on intervals, it's
+possible that the last `proc`, `eventloop`, and `gc` entries will be before
+the last of the `route` entries in the log file, so they won't encompass the
+entire set of requests in the benchmark.
+
+Send a `SIGINT` signal to the node process and `route-metrics` will write the
+time-series data. It only listens for `SIGINT` once, but should get the signal
+before the application process does. This has been tested on Linux, not Macs.
+It does not work on Windows - the program gets the `SIGINT` on `^C`, but not
+when signaled via `childprocess.kill('SIGINT')`.
+
 ## processing the log file
 
 Once the `route-metrics` agent has been used to generate a log file, it's

lib/config/common-config.js

@@ -84,7 +84,10 @@ function get({defs}) {
           errors.invalid.push(`${k} must be a number, not ${n}`);
         }
       } else if (defaultType === 'string') {
-        config[key] = process.env[k];
+        // only replace if it's set to a non-empty string
+        if (process.env[k]) {
+          config[key] = process.env[k];
+        }
       } else if (key in config) {
         throw new Error(`silly programmer, ${defaultType} is not yet valid for options: ${k}`);
       }

lib/esm-hooks/hooks.mjs

@@ -28,8 +28,12 @@ async function initialize(data = {}) {
   function patchListener(m) {
     port.postMessage({type: 'patch', ts: Date.now(), tid, m});
   }
-  function loadListener(m) {
-    port.postMessage({type: 'load', ts: Date.now(), tid, m});
+  let loadListener;
+  if (env.CSI_RM_LOG_ALL_LOADS) {
+    // listen for load events and forward them to main thread for logging.
+    loadListener = (m) => {
+      port.postMessage({type: 'load', ts: Date.now(), tid, m});
+    };
   }
   setupPatcher(patchListener, loadListener);
 

lib/init-route-metrics.js

@@ -122,6 +122,7 @@ module.exports = function initRouteMetrics({type}) {
   interval = Number(interval);
 
   const TimeSeries = require('./time-series');
+  // eslint-disable-next-line no-unused-vars
   const timeSeries = new TimeSeries(interval, timeSeriesOptions);
 
   for (const agent of agentsToBeEmitted) {
@@ -153,14 +154,16 @@ module.exports = function initRouteMetrics({type}) {
     writer.write({type: 'patch'}, m);
   };
 
-  // listen for load events and write them to the log. a file being
-  // loaded will emit either a load or a patch event, not both. packages
-  // preloaded by node, whether using --require or --import, will emit
-  // a patch event (currently only @contrast/agent is checked).
-  const loadListener = (m) => {
-    writer.write({type: 'load'}, m);
-  };
-
+  let loadListener;
+  if (config.LOG_ALL_LOADS) {
+    // listen for load events and write them to the log. a file being
+    // loaded will emit either a load or a patch event, not both. packages
+    // preloaded by node, whether using --require or --import, will emit
+    // a patch event (currently only @contrast/agent is checked).
+    loadListener = (m) => {
+      writer.write({type: 'load'}, m);
+    };
+  }
   const setupPatcher = require('./setup-patcher');
   setupPatcher(patchListener, loadListener);
 
@@ -191,8 +194,10 @@ module.exports = function initRouteMetrics({type}) {
         app_dir: header.app_dir,
         // this probably should pass the entire config to the loader thread but
         // at this time, this is the only item needed. it's used by patcher.
+        // N.B. it's used as an integer in the loader thread even though it does
+        // get assigned to process.env too.
         env: {
-          CSI_RM_LOG_ALL_LOADS: process.env.CSI_RM_LOG_ALL_LOADS
+          CSI_RM_LOG_ALL_LOADS: Number(process.env.CSI_RM_LOG_ALL_LOADS) || 0,
         },
       };
       const registerHooks = (await import('./esm-hooks/index.mjs')).default;

lib/patcher.js

@@ -5,13 +5,14 @@ const fs = require('node:fs');
 const path = require('node:path');
 const M = require('node:module');
 
-const logAllLoads = !!process.env.CSI_RM_LOG_ALL_LOADS;
-
 const Require = module.constructor.prototype.require;
 
 const patchmap = new Map();
 const emitter = new Emitter();
 
+// this is set when enable() is called
+let logAllLoads = false;
+
 // build the library of patchers at startup. it's only http code, but this is
 // extensible if ever needed.
 const patchers = fs.readdirSync(`${__dirname}/patchers`);
@@ -81,7 +82,10 @@ function patcher(name) {
   return m;
 }
 
-patcher.enable = function() {
+patcher.enable = function(options = {}) {
+  if (options.logAllLoads) {
+    logAllLoads = true;
+  }
   module.constructor.prototype.require = patcher;
 };
 

lib/setup-patcher.js

@@ -3,7 +3,11 @@
 module.exports = function patcherSetup(patchListener, loadListener) {
   // the require patcher gets setup for both types: esm and cjs
   const {patcher, emitter: patchEmitter} = require('./patcher');
-  patcher.enable();
+  // the presence of the loadListener is used as a flag so that 'load' events
+  // won't be emitted when they are not enabled.
+  patcher.enable({logAllLoads: !!loadListener});
   patchEmitter.on('patch', patchListener);
-  patchEmitter.on('load', loadListener);
+  if (loadListener) {
+    patchEmitter.on('load', loadListener);
+  }
 };

lib/time-series/index.js

@@ -92,15 +92,16 @@ class TimeSeries {
         this.elCallback(percents);
       }
 
-      // get cpu usage and calculate weighted moving averages.
+      // get cpu usage for the interval and calculate weighted moving averages.
+      // these are microsecond values.
       const cpu = process.cpuUsage();
       const cpuUser = cpu.user - this.prevCpu.user;
       const cpuSystem = cpu.system - this.prevCpu.system;
       const cpuUserAvg = this.cpuUserEMA.update(cpuUser);
       const cpuSystemAvg = this.cpuSystemEMA.update(cpuSystem);
       this.prevCpu = cpu;
 
-      // get memory usage
+      // get memory usage. these values are in bytes.
       // this should not be called very often as it's expensive.
       // https://nodejs.org/api/process.html#processmemoryusagerss
       // it's also not particularly useful except 1) to compare with/without
@@ -122,11 +123,27 @@ class TimeSeries {
       this.tsCallback(cpuAndMem);
     };
 
-    // run one interval immediately so there is no windows without data.
+    // run one interval immediately so there is no window without data.
     intervalHandler();
 
     this.interval = setInterval(intervalHandler, this.ms);
     this.interval.unref();
+
+    // finally, if we get a SIGINT, write one more set of stats. we don't
+    // actually exit on SIGINT (expecting a SIGKILL or something else to
+    // finish off the process). this is primarily for benchmarking to assure
+    // that timeseries entries can be written at the end of a run.
+    //
+    // N.B. this doesn't get called on Windows 11 (and maybe other windows) so
+    // another solution will be required if we need a windows equivalent.
+    process.once('SIGINT', () => {
+      // we don't want to generate additional timeseries entries after this.
+      // should we write status entry that we received SIGINT? probably, but
+      // not doing now to avoid it possibly preventing one of the time-series
+      // writes from completing.
+      clearInterval(this.interval);
+      intervalHandler();
+    });
   }
 
   setupPerfObserver() {

package.json

@@ -1,6 +1,6 @@
 {
   "name": "@contrast/route-metrics",
-  "version": "2.0.0-beta.4",
+  "version": "2.0.0",
   "description": "",
   "main": "lib/index.js",
   "bin": {
@@ -37,6 +37,7 @@
   },
   "license": "MIT",
   "dependencies": {
+    "@contrast/find-package-json": "^1.2.0",
     "shimmer": "^1.2.1"
   },
   "devDependencies": {

test-integration/_helpers.js

@@ -217,7 +217,7 @@ if (!module.parent) {
     // eslint-disable-next-line no-console
     console.log(c.reduce((consol, single) => Object.assign(consol, single), {}));
   }
-  function getEnv() {return [{bruce: 'wenxin'}]}
+  function getEnv() {return [{bruce: 'heihei'}, {bruce: 'yinyin'}]}
 
   const g = makeTestGenerator({getEnv, addPatchLogEntries: true});
   for (const t of g()) {

test-integration/checks/index.js

@@ -135,6 +135,7 @@ module.exports = {
   Checkers,
   HeaderChecker: require('./header'),
   PatchChecker: require('./patch'),
+  LoadChecker: require('./load'),
   RouteChecker: require('./route'),
   ProcChecker: require('./proc'),
   GcChecker: require('./gc'),

test-integration/checks/load.js

@@ -0,0 +1,11 @@
+'use strict';
+
+const BaseChecker = require('./_base');
+
+class LoadChecker extends BaseChecker {
+  constructor(options = {}) {
+    super(Object.assign({}, options, {type: 'load'}));
+  }
+}
+
+module.exports = LoadChecker;

test-integration/servers-log.test.js

@@ -11,12 +11,15 @@ const {
   HeaderChecker,
   PatchChecker,
   RouteChecker,
+  LoadChecker
 } = require('./checks');
 
 const pdj = require('../test/servers/package.json');
 const app_dir = path.resolve(__dirname, '../test/servers');
 
-const tests = makeTestGenerator({});
+const getEnv = (env) => [{CSI_RM_LOG_ALL_LOADS: 1}, {CSI_RM_LOG_ALL_LOADS: 0}].map(ev => Object.assign({}, env, ev));
+
+const tests = makeTestGenerator({getEnv});
 
 // for some reason v18 takes longer for the simple tests
 const v18 = semver.satisfies(process.version, '>=18.0.0 <19.0.0');
@@ -73,7 +76,11 @@ describe('server log tests', function() {
       });
 
       beforeEach(function() {
-        const overrides = {execArgv: t.nodeArgs, app_dir};
+        const overrides = {
+          execArgv: t.nodeArgs,
+          app_dir,
+          config: {LOG_ALL_LOADS: t.env.CSI_RM_LOG_ALL_LOADS},
+        };
         const requiredPatches = PatchChecker.getMinimalPatchEntries(t);
 
         // all tests check for the header and patch entries
@@ -126,6 +133,10 @@ describe('server log tests', function() {
         const routeChecker = new RouteChecker(routeCheckerOptions);
         checkers.add(routeChecker);
 
+        const requiredEntries = t.env.CSI_RM_LOG_ALL_LOADS == '0' ? 0 : 1;
+        const loadChecker = new LoadChecker({requiredEntries});
+        checkers.add(loadChecker);
+
         const obj = {cat: 'tuna', dog: 'beef', snake: 'mouse'};
         await testServer.post('/echo', obj);
         await testServer.post('/meta', obj);
@@ -144,6 +155,13 @@ describe('server log tests', function() {
 
         checkers.check(logObjects);
         expect(routeChecker.getCount()).equal(3);
+
+        // cheating, but all we care about is how it's set
+        if (t.env.CSI_RM_LOG_ALL_LOADS == '0') {
+          expect(loadChecker.getCount()).equal(0, 'no load entries should be present');
+        } else {
+          expect(loadChecker.getCount()).greaterThan(0, 'load entries should be present');
+        }
       });
 
       it('do not write a record if end() is not called', async function() {