Представьте, endpoint на Fastify иногда отвечает за секунды вместо миллисекунд. Как вы будете искать причину?

Отладка периодически медленных ответов Fastify-endpoint

Нерегулярные задержки («иногда секунды вместо миллисекунд») — одна из самых коварных ситуаций: проблема не воспроизводится на каждом запросе, поэтому нужен систематический подход с метриками и логами, а не ручное воспроизведение.

Шаг 1 — зафиксировать аномалию в логах

Fastify через pino пишет responseTime для каждого запроса. Добавьте алерт на значения выше порога, чтобы не ловить проблему вручную.

fastify.addHook('onResponse', async (request, reply) => {
  if (reply.elapsedTime > 500) {
    request.log.warn({
      url: request.url,
      method: request.method,
      responseTime: reply.elapsedTime,
      userId: request.user?.id
    }, 'slow request detected');
  }
});

Шаг 2 — добавить per-request таймеры внутри хуков

Разбейте обработку на фазы, чтобы понять, где именно уходит время: в auth/middleware, в обработчике или в сериализации ответа.

fastify.addHook('onRequest', async (req) => {
  req.timings = { start: performance.now() };
});

fastify.addHook('preHandler', async (req) => {
  req.timings.preHandler = performance.now() - req.timings.start;
});

fastify.addHook('onSend', async (req, reply, payload) => {
  req.timings.total = performance.now() - req.timings.start;
  req.log.info({ timings: req.timings }, 'request timings');
  return payload;
});

Шаг 3 — проверить event loop lag

Периодические задержки часто связаны с GC (Garbage Collector) или синхронным кодом, блокирующим event loop. Мониторьте lag через Node.js perf_hooks.

import { monitorEventLoopDelay } from 'perf_hooks';

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

fastify.get('/metrics/eventloop', async () => ({
  p50: h.percentile(50) / 1e6,
  p99: h.percentile(99) / 1e6,
  max: h.max / 1e6
}));

Шаг 4 — проверить пул соединений с базой

Самая распространённая причина периодических задержек — исчерпание пула соединений. Запрос встаёт в очередь и ждёт свободного слота. Логируйте размер пула.

// Пример для pg (node-postgres)
fastify.addHook('onRequest', async (req) => {
  const pool = fastify.pg.pool; // если используете @fastify/postgres
  req.log.debug({
    poolTotal: pool.totalCount,
    poolIdle: pool.idleCount,
    poolWaiting: pool.waitingCount
  });
});

Если waitingCount ненулевой в момент медленного запроса, увеличьте max в конфигурации пула или найдите утечку соединений (незакрытые транзакции).

Шаг 5 — проверить внешние зависимости

Если endpoint вызывает сторонний API, Redis, S3 или другой сервис, добавьте таймер вокруг каждого вызова. Периодически медленный внешний сервис будет чётко виден в метриках.

async function fetchWithTimer(label, fn, log) {
  const t = performance.now();
  try {
    return await fn();
  } finally {
    log.info({ [label + '_ms']: performance.now() - t });
  }
}

// Использование:
const data = await fetchWithTimer('redis_get', () => redis.get(key), request.log);

Шаг 6 — нагрузочный тест для воспроизведения

Если проблема проявляется только под нагрузкой, воспроизведите её с помощью autocannon (родной инструмент экосистемы Fastify).

npx autocannon -c 50 -d 30 http://localhost:3000/api/slow-endpoint
# -c 50 = 50 concurrent connections
# -d 30 = 30 seconds duration

Подводные камни

• GC-паузы: Node.js периодически запускает major GC, что может добавлять 50–200 мс — включите флаг --expose-gc и логируйте вызовы, чтобы скоррелировать с задержками.
• Утечка соединений: незакрытая транзакция или соединение постепенно опустошают пул — проблема проявляется только через часы работы под нагрузкой.
• Холодный кеш: первый запрос после деплоя или TTL-инвалидации попадает в БД — выглядит как нерегулярная медлительность, хотя это ожидаемое поведение.
• DNS TTL и re-resolve: если зависимость резолвится по имени без кеша, периодический DNS-lookup добавляет задержки, особенно при использовании внешних сервисов.
• Таймаут keep-alive: если upstream закрывает соединение раньше, чем Node.js успевает его переиспользовать, происходит повторный TCP-handshake — добавьте keepAliveTimeout или настройте agent.
• Несинхронизированный clock: если сравниваете логи нескольких сервисов по времени, расхождение NTP в несколько секунд делает корреляцию бесполезной.
• Истечение токена auth: периодическое обновление JWT или OAuth-токена внутри middleware добавляет задержку именно тогда, когда токен протухает.

• Сразу обвинять Fastify, не проверив соседние слои системы
• Чинить симптом без минимального воспроизведения и evidence
• Не учитывать версии, конфигурацию, окружение и recent changes

• Умеет локализовать проблему вокруг Fastify
• Двигается от симптома к гипотезам и проверкам
• Отличает баг инструмента от ошибки использования или окружения