Мониторинг задержки event loop

Почему одна медленная задача замораживает всё

Node гонит твой JavaScript в одном потоке. Event loop — это цикл, который берёт следующий готовый колбэк (истёкший таймер, завершённый I/O, зарезолвленный промис), выполняет его до конца, и только потом ищет следующий. Вытеснения нет: пока твой колбэк выполняется, ничто другое в процессе бежать не может. Поэтому один синхронный CPU-всплеск или блокирующий вызов — zlib.gzipSync, crypto.pbkdf2Sync, JSON.parse на 5МБ, fs.readFileSync по холодному диску — не просто замедляет эту одну операцию. Он держит поток, и каждый таймер, каждое чтение сокета, каждый колбэк HTTP в очереди ждут за ним. Это время ожидания — задержка event loop (event-loop lag): разрыв между тем, когда колбэк должен был выполниться, и когда loop до него реально добрался.

Под конкурентностью этот сбой жесток. С одним запросом в полёте блок на 250мс стоит этому одному запросу 250мс. С 200 запросами в полёте блок падает в середину очереди и добавляет до 250мс латентности целому куску этих 200 — ни один из которых не сделал ничего плохого. Вот почему дашборды по маршрутам из хука врали: собственная латентность маршрута экспорта выглядела нормальной, но он травил tail latency (задержки на хвосте распределения — p99 и выше) всего остального. Медленный код и медленный симптом были на разных графиках.

import http from "node:http";
import zlib from "node:zlib";

http.createServer((req, res) => {
  // ❌ блокирует единственный поток на всё сжатие — колбэк каждого
  // другого запроса в полёте ждёт за этим.
  const body = zlib.gzipSync(bigPayload);   // ~250мс чистого CPU
  res.setHeader("content-encoding", "gzip");
  res.end(body);
}).listen(3000);

Фазы loop (и где копится задержка)

Loop бежит фиксированными фазами, каждая сливает свою очередь колбэков перед переходом дальше: timers (колбэки setTimeout/setInterval, чьё время вышло) → pending callbacks (часть отложенных системных колбэков) → poll (где забираются завершения I/O и где loop блокируется в ожидании I/O, если больше ничего не готово) → check (колбэки setImmediate) → close (например, socket.on('close')). Между каждым колбэком Node сливает очереди микротасков: сначала process.nextTick, потом зарезолвленные промисы.

Практическое следствие: задержка копится везде, где колбэк засиделся. Тяжёлое тело setTimeout задержит следующий таймер; тяжёлый .then промиса задержит следующий I/O, который фаза poll хотела доставить. А process.nextTick — острый край: поскольку он сливается перед промисами и до того, как loop сменит фазу, рекурсивный nextTick может полностью заморить loop, навсегда блокируя I/O, делая «крошечную» работу на каждом тике.

// process.nextTick сливается до того, как loop продолжит — рекурсия здесь
// полностью морит I/O, хотя каждый вызов выглядит тривиально.
function spin() { process.nextTick(spin); }
spin();              // ❌ фаза poll больше никогда не выполнится

Измерение задержки: monitorEventLoopDelay

Правильный инструмент в ядре: perf_hooks.monitorEventLoopDelay. Он семплит loop по таймеру с фиксированным resolution (по умолчанию 10мс) и пишет в высокоточную гистограмму, насколько поздно был каждый семпл. Ты читаешь с неё перцентили — и перцентили это весь смысл, потому что задержка взрывная: среднее в 2мс может прятать p99 в 400мс во время компакции или GC-паузы. Следи за хвостом (p99/max), не за средним. Все значения в наносекундах.

import { monitorEventLoopDelay } from "node:perf_hooks";

const h = monitorEventLoopDelay({ resolution: 20 }); // семплить каждые 20мс
h.enable();

setInterval(() => {
  console.log({
    meanMs: (h.mean / 1e6).toFixed(2),       // здоровое: меньше миллисекунды
    p99Ms:  (h.percentile(99) / 1e6).toFixed(2),
    maxMs:  (h.max / 1e6).toFixed(2),
  });
  h.reset();                                  // начать свежее окно
}, 1000).unref();

Наивная альтернатива — дрейф таймера: запланируй setInterval(fn, 100) и измерь, насколько позже 100мс реально срабатывает каждый тик; перебор и есть задержка. Это дёшево и без зависимостей, но грубо — он семплит только с твоим интервалом и не даёт гистограммы, так что упускает всплески внутри интервала и не скажет тебе p99. Для прода monitorEventLoopDelay строго лучше. Дальше библиотеки вроде toobusy-js непрерывно опрашивают задержку и дают сбрасывать нагрузку (shed load): когда задержка пересекает порог, сразу отклоняй новые запросы с 503 вместо того, чтобы брать работу, которую не сможешь обслужить, держа уже принятые запросы быстрыми.

Хронометраж подозреваемого: performance.mark, measure, observe

Когда задержка высока, всё равно надо найти, какой вызов блокирует. perf_hooks.performance даёт высокоточные часы и структурный способ мерить спаны без арифметики Date.now(). Используй performance.mark(name), чтобы ставить отметки времени, performance.measure(name, start, end), чтобы записать длительность между двумя отметками, и PerformanceObserver, чтобы получать эти записи по мере их выпуска — так хронометраж развязан с горячим путём.

import { performance, PerformanceObserver } from "node:perf_hooks";

const obs = new PerformanceObserver((list) => {
  for (const e of list.getEntries()) {
    if (e.duration > 50) console.warn(`SLOW ${e.name}: ${e.duration.toFixed(1)}ms`);
  }
});
obs.observe({ entryTypes: ["measure"] });

performance.mark("gzip:start");
const body = zlib.gzipSync(bigPayload);
performance.mark("gzip:end");
performance.measure("gzip", "gzip:start", "gzip:end"); // появится в observer

Для разовых проверок performance.now() — это монотонный, субмиллисекундный таймер (не зависит от смены настенного времени): const t = performance.now(); …; performance.now() - t — правильный способ микро-замерить подозрительный вызов.