Measure Node Event Loop Delay Before Blaming the CPU

1. Enable the built-in event loop delay histogram.

// instrument.js -- import FIRST, before anything else
import { monitorEventLoopDelay } from 'node:perf_hooks';
const h = monitorEventLoopDelay({ resolution: 20 });
h.enable();

setInterval(() => {
  const spike = h.percentile(99) / 1e6; // ms
  if (spike > 100) {
    console.error(JSON.stringify({
      evt: 'loop-lag', p99ms: Math.round(spike),
      mean: Math.round(h.mean / 1e6), at: new Date().toISOString(),
    }));
  }
  h.reset();
}, 5000).unref();

Expected output: Log lines appear only when p99 lag exceeds 100 ms, each stamped with the moment the loop was blocked.

2. Correlate lag spikes with request activity in the same window.

grep "loop-lag" /var/log/app/app.log | jq -r '"\(.at) p99=\(.p99ms)ms"' | tail -5; grep "loop-lag" /var/log/app/app.log | jq -r .at | while read t; do jq -r --arg a "$t" 'select(.at >= $a and .at <= ($a + "0.2s")) | .route' requests.json 2>/dev/null | sort | uniq -c | sort -rn | head -3; done

Expected output: Routes active during each spike window are ranked; a report-generation route appearing in every spike is the prime suspect.

3. Confirm with a CPU profile sample captured during a spike.

kill -USR1 $(pgrep -f "node dist/server") 2>/dev/null; sleep 10; node --prof-process --preprocess -j isolate-*.log 2>/dev/null | jq -r '.code[].fn' 2>/dev/null | head -8 || node --prof-process isolate-*.log | grep -A3 "[Summary]"

Expected output: The hottest frames in the sampled profile print; a single sync function such as renderReport dominating ticks confirms the blocker.

4. Move the blocking work off the loop.

// before: 900ms of synchronous JSON.stringify + template render
app.get('/report', (req, res) => {
  res.send(renderReport(buildReport(req.query)));
});

// after: chunk to the worker_threads pool, stream the result
import { Worker } from 'node:worker_threads';
app.get('/report', (req, res) => {
  const w = new Worker('./report-worker.js', { workerData: req.query });
  res.setHeader('content-type', 'text/html');
  w.on('message', (chunk) => res.write(chunk));
  w.on('exit', () => res.end());
});

Expected output: The p99 lag line disappears from the log during report requests, and request latency for other routes stops spiking alongside them.

5. Keep the histogram as a permanent guardrail metric.

// metrics endpoint addition
import { monitorEventLoopDelay } from 'node:perf_hooks';
const lag = monitorEventLoopDelay({ resolution: 20 });
lag.enable();
setInterval(() => {
  metrics.gauge('node_loop_lag_p99_ms', lag.percentile(99) / 1e6);
  metrics.gauge('node_loop_lag_max_ms', lag.max / 1e6);
  lag.reset();
}, 15000).unref();

Expected output: Loop lag appears beside CPU and memory on the dashboard, with an alert at 100 ms p99 that would have caught this incident on day one.

Problem

No lag lines appear but latency still spikes

Solution

The stall is outside the loop: GC pauses, kernel-level IO wait, or a downstream dependency; check GC timings and external request logs before chasing the loop.

Problem

Spikes occur at exact regular intervals

Solution

A scheduled job, cache sweep, or metrics scrape runs synchronously; find it by timestamp arithmetic against cron entries, then move it to a worker or its own process.

Problem

monitorEventLoopDelay shows huge values at startup

Solution

Module loading and JIT warmup legitimately block the loop; skip the first 30 seconds after boot before alerting, or raise the startup threshold.