Диагностика медленных API Node.js: измеряйте задержку перед оптимизацией

Обработка запроса занимает почти секунду, однако загрузка CPU составляет около трети её мощности, объём памяти не вызывает нареканий, а панель управления базой данных показывает зелёный статус. Настройка тех элементов, которые, по вашим предположениям, могут быть причиной проблем, редко помогает. В этом руководстве шаг за шагом описывается процесс обработки запроса, чтобы вы могли определить, куда уходит время, а также приводятся методы отслеживания, которые позволяют проводить расследование быстро и надёжно.

Измерьте время обработки запроса, прежде чем винить среду выполнения

Используйте простой маршрут, который загружает заказ по его идентификатору и возвращает его в формате JSON.

app.get("/orders/:id", async (req, res) => {
  const order = await getOrder(req.params.id);
  res.json(order);
});

Предположим, что время ответа составляет примерно 900 мс. Вместо того чтобы винить Node.js, оберните операцию ожидания вызова функции performance.now(), чтобы узнать, какую долю от общего времени она занимает.

const start = performance.now();

const order = await getOrder(req.params.id);
console.log(
  `getOrder: ${performance.now() - start}ms`
);
res.json(order);

Числа обычно быстро разрешают вопрос:

Request:       910ms
getOrder():    870ms
Node.js:        40ms

Почти вся задержка приходится на функцию getOrder(); остальная часть JavaScript-кода потребляет примерно 40 мс. Это время тратится в ожидании ответа от какого-либо внешнего компонента.

Низкая загрузка CPU не означает нормальной работы сервиса

Панель мониторинга загрузки, похожая на приведённую ниже, создаёт впечатление стабильности:

CPU: 32%
Memory: 48%

Загрузка CPU отражает объём выполняемой работы, а запросы, находящиеся в состоянии ожидания, практически не потребляют ресурсов. Типичные причины ожидания в процессе Node.js:

• получение подключения к базе данных
• сам запрос
• другой HTTP-сервис
• общие сетевые операции ввода-вывода
• очередь сообщений
• блокировка

Медленный сервис с низкой загрузкой CPU обычно не находится в активном режиме работы; он заблокирован.

Следите не только за процентом загрузки CPU, но и за задержкой цикла событий

Каждый обратный вызов в процессе Node.js использует один и тот же цикл событий, поэтому разница между моментом, когда должен сработать таймер, и моментом его действия, является прямым показателем состояния системы. Функция monitorEventLoopDelay из модуля node:perf_hooks собирает данные об этой разнице в гистограмму; здесь используется разрешение 20 мс, и каждые пять секунд выводятся значения p95 и p99.

import { monitorEventLoopDelay } from "node:perf_hooks";

const histogram = monitorEventLoopDelay({
  resolution: 20
});
histogram.enable();
setInterval(() => {
  console.log({
    p95: histogram.percentile(95),
    p99: histogram.percentile(99)
  });
}, 5000);

Если вывод выглядит так, значит с циклом всё в порядке, и это не может объяснить задержку запроса в 900 мс:

p95 event-loop delay: 8ms
p99 event-loop delay: 14ms

Значения в несколько сотен миллисекунд говорят совершенно о другом:

p95: 180ms
p99: 650ms

Теперь что-то монополизирует цикл. Типичной причиной является синхронная функция, требующая больших вычислительных ресурсов, вызываемая непосредственно внутри обработчика:

app.get("/report", (req, res) => {
  const result = expensiveCalculation();
  res.json(result);
});

Пока выполняется функция expensiveCalculation(), никакие другие запросы в этом процессе не могут быть обработаны. На многопроцессорном сервере общая нагрузка на CPU может казаться умеренной, поскольку загруженный ядро среднится с неактивными, в связи с чем задержка цикла зачастую отражает реальную ситуацию лучше, чем процент загрузки CPU. Обычным решением является перенос такой работы в отдельный поток, очередь задач или отдельное приложение. Схожая проблема, при которой планирование микрозадач вместо выполнения вычислений приводит к замедлению цикла, рассматривается в статье как функция process.nextTick может замедлять работу цикла событий в Node.js.

Когда виноват база данных

Далее необходимо аналогичным образом отслеживать выполнение запросов.

const start = performance.now();
const result = await db.query(
  "SELECT * FROM orders WHERE customer_id = $1",
  [customerId]
);
console.log(
  `DB query: ${performance.now() - start}ms`
);

Теперь причина проблемы явно связана с базой данных:

Total request: 850ms
Node.js:        15ms
DB query:      810ms
Serialization:  25ms

Перед переписыванием SQL проверьте, была ли запроса медленной или запрос ожидал подключения.

Исчерпание пула, маскирующееся под медленный запрос

Рассмотрим пул такого размера:

API instances:        10
Connections/instance: 20

Total connections:   200

Затем поступает всплеск трафика:

Requests:          500
Active DB queries:  20
Waiting requests: 480

По одному экземпляру можно выполнять только 20 запросов, поэтому остальные ожидают в очереди внутри пула. Один запрос может занять 30 мс, но запрос в конце очереди будет ждать сотни миллисекунд, прежде чем дойти до базы данных. Таймер приложения показывает:

DB call = 500ms

Сама база данных сообщает:

Query = 30ms

Медленный запрос требует использования индексов или более эффективного плана выполнения; длительное ожидание требует увеличения размера пула, сокращения длительности транзакций или уменьшения количества обращений к базе данных. Измеряйте отдельные этапы, а не единую величину «задержки базы данных»:

Connection wait
      +
Query execution
      +
Result processing

Большинство библиотек пулов предоставляют информацию о количестве свободных, общем и ожидающих операций; экспорт этих данных — самый быстрый способ различить эти случаи.

Службы нижнего уровня и последовательные операции await

Многие конечные точки формируют ответ из нескольких зависимостей поочередно:

const customer = await customerService.get(id);

const payment = await paymentApi.get(
  customer.paymentId
);
const orders = await orderService.get(id);

Отслеживание времени выполнения каждого вызова отдельно позволяет выявить аномалии:

Customer API:    40ms
Payment API:    700ms  ← 🚨
Orders DB:       35ms
Node.js:         15ms

Служба оплаты доминирует, и поскольку каждая операция await ожидает предыдущей, задержки накапливаются:

40ms + 700ms + 35ms + 15ms
≈ 790ms

Независимые вызовы могут начинаться одновременно. Для поиска информации о клиенте и заказе требуется только id, поэтому Promise.all выполняет их одновременно:

const [customer, orders] = await Promise.all([
  customerService.get(id),
  orderService.get(id)
]);

Вызов для оплаты всё ещё ожидает, поскольку ему нужен customer.paymentId. Не стоит автоматически параллелизовать такие операции: дополнительная конкурентность увеличивает нагрузку на пулы, API и память, а при высокой нагрузке может ухудшить ситуацию.

Перцентили показывают то, что скрывает среднее значение

Панель управления, отображающая эту информацию, кажется приемлемой:

Average latency: 120ms

Вид перцентилей для того же трафика выглядит менее обнадеживающим:

p50:  80ms
p95: 180ms
p99: 2.8s

Среднее значение описывает обычный запрос; информация о «хвосте» распределения показывает пользователей, сталкивающихся с перегруженными ресурсами или медленными зависимостями. Необходимо отслеживать распределение:

p50
p95
p99

Инструменты, которые помогают, а не мешают

Измерения потребляют процессорные ресурсы, место хранения и внимание. Несколько привычек помогают сохранять их полезность.

Измеряйте на границах, а не в каждом вспомогательном модуле

Отслеживание времени выполнения каждой функции таким образом создает больше шума, чем полезной информации:

const start = performance.now();
// ...
console.log(performance.now() - start);

Измеряйте моменты, когда запрос переходит в другую систему, именно там происходит ожидание:

HTTP request
   ↓
Database
   ↓
External API
   ↓
Queue
   ↓
Response

Контролируйте логирование по запросу

Запись одной строки в лог для каждого запроса становится дорогостоящей при высокой пропускной способности:

console.log({
  path: req.path,
  duration,
  userId: req.user.id
});

Используйте структурированную логгеринговую систему с уровнями и выборкой, и полностью исключите из логов следующее:

passwords
tokens
authorization headers
payment information

Время выполнения — не диагноз

Наличие такой цифры не доказывает, что SQL-запрос занял именно столько времени:

DB: 700ms

Этот промежуток времени может включать несколько разных факторов, влияющих на его длительность:

Connection acquisition
+
Query execution
+
Network
+
Result transfer
+
Client-side processing

Когда число вас удивляет, разделите его на составные части перед тем, как принимать по нему решения.

Избегайте меток с высокой кардинальностью

Присвоение метки показателю задержки пользовательскому ID кажется безвредным:

http_request_duration{user_id="123456"}

При наличии миллионов пользователей это означает миллионы временных рядов. Вместо этого используйте ограниченные размерности:

route
method
status_code
service

Хорошо пронумерованный временной ряд будет выглядеть так:

http_request_duration{
  route="/orders/:id",
  method="GET",
  status="200"
}

Детали по каждому запросу должны храниться в логах и трейсах.

Целенаправленно используйте выборку

Обычная политика отслеживает лишь часть обычного трафика и всё значимое:

Normal traffic → sample a percentage
Errors         → capture aggressively
Slow requests  → capture aggressively

Соотношение зависит от объёма трафика, инструментов и бюджета; цель — иметь достаточно доказательств для объяснения сбоев, а не полную информацию.

Сравнивайте до и после, используя несколько показателей

Фраза «Кажется, быстрее» не является доказательством. Запишите процентиль до внесения изменений:

Before:
p95 = 820ms

И снова после них:

After:
p95 = 410ms

Затем убедитесь, что ничего другого не изменилось в неправильном направлении:

error rate
CPU
memory
DB load
connection pool usage

Более быстрый запрос, удваивающий использование пула ресурсов или нагрузку на базу данных, просто смещает проблему.

Отслеживайте отдельный запрос

Показатель на уровне маршрута сообщает только общую картину:

GET /orders = 980ms

Распределённое отслеживание разбивает один и тот же запрос на этапы, поэтому стоимость каждого из них видна с первого взгляда:

GET /orders
│
├── Node.js processing       15ms
├── DB connection wait      120ms
├── PostgreSQL query         40ms
├── Payment API             700ms
├── JSON serialization       20ms
└── Network                   5ms
                              ───
                              900ms

Стоит запомнить этот принцип разделения труда: метрики сообщают о наличии проблем, а трейсы показывают, где именно она возникла.

Чек-лист для анализа пути запроса

Когда увеличивается задержка, не спешите сразу добавлять серверы или процессоры. Проследите путь, который проходит запрос, и измерьте каждый этап:

Request
   ↓
Queue / Load Balancer
   ↓
Node.js
   ↓
Event Loop
   ↓
Connection Pool
   ↓
Database
   ↓
External APIs
   ↓
Network
   ↓
Response

На каждом этапе задавайте конкретный вопрос:

Is the event loop blocked?

Are requests waiting for connections?

Are database queries slow?

Are downstream APIs slow?

Are we waiting on network I/O?

Is the queue growing?

Is garbage collection causing pauses?

Is the response itself expensive to serialize?

На все эти вопросы можно ответить с помощью данных, поэтому нет необходимости догадываться.

Что обычно показывают доказательства

Вернемся к исходной ситуации:

API latency: 900ms
CPU: 35%
Memory: 48%

После измерения каждого этапа картина совершенно иная:

Event loop:          12ms
DB query:            35ms
Connection wait:    120ms
Payment API:        700ms
Serialization:       20ms
Network:              5ms

Отсутствие перезаписи во время выполнения; поможет увеличение размера экземпляра или дополнительная память. Основные проблемы — задержка обработки оплаты в 700 мс (использование кэша, настройка таймаута с альтернативой или перемещение этого процесса вне пути запроса) и задержка подключения в 120 мс (регулировка размера пула соединений или объема запросов).

Основные выводы

Инстинктивный вариант реализации выглядит так:

Slow API
   ↓
Add more servers

Эффективный вариант реализации выглядит так:

Slow API
   ↓
Measure
   ↓
Break down latency
   ↓
Find the bottleneck
   ↓
Fix the bottleneck
   ↓
Measure again

• Сначала измерьте общее время выполнения запроса, затем разделите его на этапы в местах выхода из процесса.
• Считайте задержку цикла событий основным показателем работоспособности Node.js; процент использования CPU может скрывать наличие заблокированного ядра.
• Отделите время ожидания подключения от выполнения запроса перед обращением к SQL.
• Оценивайте задержку по значениям p95 и p99, а не по средним значениям.
• Сохраняйте метрики с низкой кардинальностью, используйте выборочные логи без конфиденциальной информации, а детали каждого запроса храните в трейсах.

Проверяйте каждое исправление с учётом тех же процентилов и соседних сигналов, на которые оно могло повлиять.

Медленную систему можно управлять, как только она становится видимой; до этого момента каждая изменение представляет собой лишь догадку. Чтобы узнать, какие исправления следует отдать в приоритет после выявления узкого места, ознакомьтесь с рамкой для определения приоритетов в работе с производительностью API Node.js.