How to measure event loop lag

Start monitorEventLoopDelay() in the process and read its percentiles beside a latency figure from the same run. Idle here the histogram reported a mean of 16.16 ms. Under 50 connections a route that awaits 300 ms left it unchanged, and one that blocks 30 ms took p99 to 1 470 ms.

Why check this

Run this when latency rises and the handler looks innocent, and before releasing anything that parses a large payload, hashes a password or sorts a list per request. The two figures answer different questions and only locate the time together.

The failure it catches is a synchronous call added to a hot handler. Throughput falls, every route on the process slows at once, and the trace of the changed endpoint shows nothing, because the time is spent in front of it.

Prerequisites

• Node 22 or later. perf_hooks.monitorEventLoopDelay() returns a histogram (perf_hooks API).
• npx autocannon@8, which fetches autocannon on first use.
• A free port. 9753 below.
• The generator shares eight cores with the target, and loopback has no network in it. Latency here is service time plus queueing, with no transit.
• The target, eld-server.mjs, started with node eld-server.mjs &. /block burns 30 ms synchronously, /slow awaits 300 ms, the hash routes run one workload on and off the main thread, and /eld reads and resets the histogram.

// eld-server.mjs   the service under test
import { createServer } from 'node:http';
import { monitorEventLoopDelay } from 'node:perf_hooks';
import { pbkdf2, pbkdf2Sync } from 'node:crypto';

const h = monitorEventLoopDelay({ resolution: 10 });
h.enable();

const ms = (ns) => +(ns / 1e6).toFixed(2);
const read = () => ({ min: ms(h.min), mean: ms(h.mean), p50: ms(h.percentile(50)),
  p99: ms(h.percentile(99)), max: ms(h.max) });
const json = (res, o) => {
  res.writeHead(200, { 'content-type': 'application/json' });
  res.end(JSON.stringify(o));
};
const busy = (n) => { const end = Date.now() + n; while (Date.now() < end); };

let rampStart = Date.now();

createServer((req, res) => {
  const path = req.url.split('?')[0];
  if (path === '/slow') return void setTimeout(() => json(res, { ok: true }), 300);
  if (path === '/block') { busy(30); return json(res, { ok: true }); }
  if (path === '/hash-sync') { pbkdf2Sync('p', 's', 40000, 32, 'sha512'); return json(res, { ok: true }); }
  if (path === '/hash-async') return void pbkdf2('p', 's', 40000, 32, 'sha512', () => json(res, { ok: true }));
  if (path === '/ramp') { busy(Math.min(20, Math.floor((Date.now() - rampStart) / 1000))); return json(res, { ok: true }); }
  if (path === '/ramp-reset') { rampStart = Date.now(); return json(res, { ok: true }); }
  if (path === '/eld') { const r = read(); h.reset(); return json(res, r); }
  res.writeHead(404).end();
}).listen(9753, '127.0.0.1', () => console.log('listening on 9753'));

• floor.mjs, which reads one idle process at three sampling resolutions.

// floor.mjs   the idle baseline at three sampling resolutions
import { monitorEventLoopDelay } from 'node:perf_hooks';
const hs = [1, 10, 20].map((resolution) => [resolution, monitorEventLoopDelay({ resolution })]);
for (const [, h] of hs) h.enable();
const f = (n) => (n / 1e6).toFixed(2).padStart(6);
setTimeout(() => {
  console.log('resolution     min     mean      p99      max');
  for (const [r, h] of hs) {
    console.log(String(r).padEnd(10) + f(h.min) + '  ' + f(h.mean) + '  ' + f(h.percentile(99)) + '  ' + f(h.max));
  }
}, 3000);

• pair.sh, one load run and one histogram on two lines.

#!/bin/sh
# pair.sh <route> <connections>   one load run, with the loop histogram beside it
curl -s http://127.0.0.1:9753/eld > /dev/null
npx autocannon@8 -c $2 -d 5 -j http://127.0.0.1:9753/$1 > run.json 2>/dev/null
node -e "const j=require('./run.json');console.log('$1'.padEnd(11),'rps',Math.round(j.requests.average),' latency mean',j.latency.average,'ms  p99',j.latency.p99,'ms')"
echo "            loop  $(curl -s http://127.0.0.1:9753/eld)"

• ramp.mjs, which sends at a fixed rate and reads both figures each second.

// ramp.mjs <seconds> <requests per second>
const secs = +process.argv[2], rate = +process.argv[3];
const rows = [];
let t0;
const pct = (a, p) => a.slice().sort((x, y) => x - y)[Math.ceil((p / 100) * a.length) - 1];

async function fire() {
  const s = performance.now();
  try { await (await fetch('http://127.0.0.1:9753/ramp')).text(); } catch { return; }
  rows.push([Math.floor((s - t0) / 1000), performance.now() - s]);
}

await (await fetch('http://127.0.0.1:9753/ramp-reset')).text();
await (await fetch('http://127.0.0.1:9753/eld')).text();
t0 = performance.now();
const iv = setInterval(() => { for (let i = 0; i < rate / 10; i += 1) fire(); }, 100);

const eld = [];
for (let s = 0; s < secs; s += 1) {
  await new Promise((r) => setTimeout(r, 1000));
  eld.push(await (await fetch('http://127.0.0.1:9753/eld')).json());
}
clearInterval(iv);
await new Promise((r) => setTimeout(r, 1500));

console.log('sec  done   p50 ms   p99 ms   loop mean   loop p99');
for (let s = 0; s < secs; s += 1) {
  const d = rows.filter((r) => r[0] === s).map((r) => r[1]);
  const e = eld[s];
  if (!d.length) continue;
  console.log(
    String(s).padEnd(5) + String(d.length).padEnd(7) +
    pct(d, 50).toFixed(1).padStart(6) + '   ' + pct(d, 99).toFixed(1).padStart(7) +
    '   ' + String(e.mean).padStart(9) + '   ' + String(e.p99).padStart(8)
  );
}

Steps

1. 1

   Step 1.

   Read the histogram with no load at all.

   curl -s http://127.0.0.1:9753/eld
   

   {"min":10.15,"mean":16.16,"p50":15.81,"p99":27.92,"max":32.78}

   An idle process reports a mean of 16.16 ms. Later readings compare against that, not against zero.

2. 2

   Step 2.

   Read the same idle baseline at three sampling resolutions.

   node floor.mjs
   

   resolution     min     mean      p99      max
   1           0.01   15.51   24.56   25.97
   10         10.58   15.92   24.56   25.95
   20         22.12   31.19   35.09   37.75

   min follows the resolution argument: 0.01, 10.58 and 22.12 ms for 1, 10 and 20. The sampling interval sits inside the reported number, and the 15 ms left at resolution: 1 is this machine's timer granularity. An alert set at 10 ms fires here on an idle process.

3. 3

   Step 3.

   Load a route that waits without blocking.

   sh pair.sh slow 50
   

   slow        rps 160  latency mean 312.14 ms  p99 325 ms
             loop  {"min":10.34,"mean":16.14,"p50":15.75,"p99":28.8,"max":33.69}

   Latency mean 312.14 ms, loop mean 16.14 ms, the idle baseline to two decimals. A caller waiting a third of a second and a fully responsive process are the same run.

4. 4

   Step 4.

   Load a route that blocks for 30 ms in the handler.

   sh pair.sh block 50
   

   block       rps 33  latency mean 1282.45 ms  p99 1500 ms
             loop  {"min":10.44,"mean":87.03,"p50":15.74,"p99":1470.1,"max":1472.2}

   Both figures move. Loop p99 is 1 470.1 ms for a 30 ms block, because 50 connections arrive together and the loop runs all 50 handlers in one turn before reaching the sampling timer. p50 stays at the idle 15.74 ms: half the samples land between blocks.

5. 5

   Step 5.

   Run one cryptographic workload on the main thread and on the pool.

   sh pair.sh hash-sync 10; sh pair.sh hash-async 10
   

   hash-sync   rps 54  latency mean 182.49 ms  p99 205 ms
             loop  {"min":11.8,"mean":59.65,"p50":16.02,"p99":181.27,"max":187.56}
   hash-async  rps 140  latency mean 70.84 ms  p99 95 ms
             loop  {"min":9.12,"mean":14.36,"p50":14.41,"p99":23.9,"max":24.92}

   The same 40 000 PBKDF2 iterations. pbkdf2Sync put loop p99 at 181.27 ms. pbkdf2 left it at 23.9 ms, below the idle reading, at 140 requests a second against 54.

6. 6

   Step 6.

   Send 200 requests a second at a route whose blocking work grows 1 ms a second.

   node ramp.mjs 14 200
   

   sec  done   p50 ms   p99 ms   loop mean   loop p99
   0    180      17.5      33.9       16.01      23.49
   1    180      23.4      40.7       16.27      25.02
   2    180      35.2      60.8       21.43      48.82
   3    180      45.9      76.7       29.28      80.22
   4    180      56.0      95.7       41.56      100.2
   5    200      69.4     126.5      106.89     120.06
   6    200     172.3     397.7      234.19     420.22
   7    200     516.5    1116.4      800.33     800.59
   8    180     908.7    2486.4      1308.1    1308.62
   9    200    1717.7   10634.7     1797.26    1905.26
   10   200    2286.7   26810.4     2446.33    2447.38
   11   143    2397.0   37635.1     2550.14    2560.62
   12   89     2736.0    2922.0     2239.76    2321.55
   13   79     3443.8    3631.7     2296.63    2520.78

   Loop mean leaves the 16 ms baseline at second 2 and is six times it by second 5, while p99 latency is still 126.5 ms. From second 7 the two loop figures agree to the decimal, 800.33 against 800.59: every sample late by the same amount.

   Then they separate. At second 11 p99 latency is 37 635.1 ms and loop p99 2 560.62 ms, fourteen times smaller. Loop delay is bounded by the longest synchronous span; the queue in front is not. done falling to 143, 89 and 79 says those rows no longer measure 200 a second.

7. 7

   Step 7.

   Stop the target and confirm the port is clear.

   netstat -ano | grep "127.0.0.1:9753 " | grep LISTENING; powershell -Command "Stop-Process -Id 36244 -Force"; netstat -ano | grep -c ":9753 .*LISTENING"
   

     TCP    127.0.0.1:9753         0.0.0.0:0              LISTENING       36244
   0

   Read the process id from the last column and stop that alone.

How to read the result

| What you see | What it means | What to do | | --- | --- | --- | | Loop p99 at the idle baseline, latency high | Work waiting, not blocking | Look downstream. The handler is not holding the loop. | | Loop p99 many times the baseline | Something synchronous runs per request | Find the longest synchronous span in the handler. | | Loop mean and loop p99 equal | Every sample equally late, so the loop never drains | Lower the load. Readings above this point describe the queue. | | p50 at the idle floor, p99 far above | A block that is rarer than the sampling interval | Count occurrences. A mean will never show this. | | min close to the resolution argument | The sampling interval is inside the figure | Compare against a measured idle baseline, never against zero. | | Latency tail far above loop p99 | Requests queued in front of the loop | Cut the arrival rate or add processes. |

Common mistakes

What to check next

• How to check p95 latency: the latency half of the pair.
• How to test concurrent users: where queueing starts.
• How to check memory growth under load: collection pauses arrive as delay.
• How to run a soak test: counts that climb while the loop stays clean.
• How to stress test an api: the same ramp, read for capacity.

FAQ

What is event loop lag in Node.js?

The time between when the loop was due to run a scheduled callback and when it did. A sampling timer records the difference into a histogram. It says whether the process can pick up new work, not how long a request took.

How do I measure event loop lag?

Call monitorEventLoopDelay(), enable it, read mean and percentile(99). The values are nanoseconds. Expose them on an endpoint, reset after each read, and record a load figure alongside.

What is a good event loop lag metric to alert on?

A high percentile against a measured idle baseline on the same platform. Mean and p50 miss rare blocks: step 4 held p50 at 15.74 ms while p99 reached 1 470.1 ms.

What blocks the Node event loop?

Anything synchronous in a handler: pbkdf2Sync, JSON.parse of a large body, readFileSync, a sort over a long array, a backtracking regular expression. Step 5 cost 181.27 ms of loop p99 on the main thread and 23.9 ms on the pool.

Verified