One of our services (our integration engine) at Luma Health has recently been encountering odd timeouts when making outbound connections to another service it depends on. The receiving service has plenty of resources to spare, so we’ve been working through the theory that the event loop in Node might be starved before the callbacks and timers loops cycles are able to be hit.
To test this, we’ve been playing with monitoring timer performance putting the data in to InfluxDB in order to aggregate and monitor it. To do that, we simply set up a setInterval and use a high resolution timer to watch the results and write the delta of when we expected to be called versus when the interval was actually called.
const Influx = require('influx'); // snapshot the package's name const packageName = require(process.cwd() + '/package.json').name; const measurement = 'event_loop_interval_delay'; const fs = require('fs'); const influx = new Influx.InfluxDB(process.env.INFLUXDB); const { exec } = require('child_process'); let serviceVersion = null; // snap out the gitsha exec('git rev-parse HEAD', (err, version) => { serviceVersion = version.toString().trim(); }); // and the docker container ID const hostname = fs.existsSync('/etc/hostname') ? fs.readFileSync('/etc/hostname').toString().trim() : 'localhost'; let startAt = process.hrtime(); const intervalDelay = 500; // set up an interval to run every 500ms setInterval(() => { const calledAt = process.hrtime(startAt); const nanoseconds = calledAt[0] * 1e9 + calledAt[1]; const milliseconds = nanoseconds / 1e6; influx .writePoints([{ measurement, tags: { service: packageName, serviceVersion, hostname }, fields: { delayTime: (milliseconds - intervalDelay).toFixed(4) }, }]) .then(() => {}) .catch(() => {}); startAt = process.hrtime(); }, intervalDelay);
I thought it’d be fun to share how we’re using Influx to monitor Node internals. We’ve been monitoring the data and generally seeing Node able to keep up but there are times when the integration engine is under high load and the intervals come anywhere from 500ms to multiple seconds (!!!) late.