Профилирование Nginx: где теряются миллисекунды

Если Nginx отдаёт 502, а пользователи жалуются на медленные страницы, одного среднего времени ответа недостаточно. Запрос мог потратить миллисекунды на подключение к upstream, секунды — на ожидание заголовков приложения, а оставшееся время — на передачу большого тела ответа. Ниже — практический способ профилировать Nginx 1.25–1.27 без догадок: добавить временные метки в access log, сопоставить их с этапами запроса и проверить гипотезу на нагрузке.

Что именно измеряет Nginx

Начните с разделения полного времени запроса и времени общения с upstream. Для этого в формате access log нужны встроенные переменные Nginx:

• $request_time — время обработки запроса от чтения первой строки клиента до завершения отправки ответа;
• $upstream_connect_time — время подключения к серверу upstream;
• $upstream_header_time — время от установления соединения до получения первых заголовков от upstream;
• $upstream_response_time — время от передачи запроса upstream до получения последнего байта ответа;
• $status, $request_length, $bytes_sent — статус, размер входящего запроса и объём ответа.

Эти значения записываются в секундах с миллисекундной точностью. Если запрос проходил через несколько upstream, некоторые переменные могут содержать несколько значений, разделённых запятыми, а этапы внутри одного upstream — двоеточиями. Поэтому лог лучше делать структурированным, например в JSON, либо хотя бы использовать однозначный разделитель.

Профилирование Nginx начинается не с увеличения worker_connections. Сначала нужно узнать, на каком переходе запроса появляется задержка.

Сноска. Upstream — сервер или группа серверов, куда Nginx передаёт запрос: приложение, FastCGI, gRPC-сервис или другой HTTP-сервер.

Добавляем временные метки в access log

В конфигурации Nginx 1.25–1.27 создайте отдельный формат для диагностики. Синтаксис поддерживается модулем логирования HTTP:

http {
    log_format timing '$remote_addr [$time_iso8601] '
                      '"$request" status=$status '
                      'request_time=$request_time '
                      'upstream_connect=$upstream_connect_time '
                      'upstream_header=$upstream_header_time '
                      'upstream_response=$upstream_response_time '
                      'request_length=$request_length '
                      'bytes_sent=$bytes_sent '
                      'upstream_addr=$upstream_addr';

    access_log /var/log/nginx/access_timing.log timing;

    # Остальные настройки блока http остаются без изменений.
}

Не включайте такой лог бездумно на каждом вспомогательном location. На высоком трафике диагностический файл сам создаёт нагрузку на диск и усложняет агрегацию. Обычно достаточно временно включить формат для нужного виртуального хоста или отдельного endpoint.

После изменения проверьте конфигурацию и перечитайте её без остановки процесса:

nginx -t
nginx -s reload

Проверка результата: команда nginx -t должна завершиться сообщением об успешной проверке, а в новом access log должны появиться поля request_time и upstream_response. Если Nginx установлен не из системного пакета, путь к бинарному файлу может отличаться.

Как читать одну строку лога

Представим запись:

203.0.113.10 [2025-02-14T12:00:00+00:00] "GET /catalog HTTP/1.1" status=200 request_time=0.842 upstream_connect=0.001 upstream_header=0.801 upstream_response=0.805 request_length=512 bytes_sent=18432 upstream_addr=127.0.0.1:8000

Соединение с приложением заняло 1 мс. Первые заголовки пришли через 801 мс, а весь ответ — через 805 мс. Значит, искать причину нужно в приложении, базе данных или внешнем сервисе, а не в сетевом стеке Nginx. Разница между $request_time и $upstream_response_time составила 37 мс. Это время могло уйти на получение запроса от клиента, буферизацию и передачу ответа.

Другой профиль выглядит иначе: request_time=0.430, upstream_connect=0.210, upstream_header=0.218, upstream_response=0.225. Здесь приложение отвечает быстро после соединения, но само подключение к upstream занимает значительную долю запроса. Причины — исчерпание пула соединений, проблемы маршрутизации, DNS, сетевой фильтр или перегруженный сервер назначения.

Четыре источника задержки

Таблица задаёт направление, но не доказывает причину. Например, большое время передачи ответа может быть следствием медленного клиента, а может — слишком тяжёлого тела ответа. Эти сценарии различаются по размеру ответа, типу ресурса и наблюдениям на сетевом интерфейсе.

Когда одного access log недостаточно

Запросы к приложению

Если задержка появляется между подключением к upstream и первыми заголовками, Nginx уже выполнил свою основную работу. Сопоставьте время запроса с логом приложения по идентификатору запроса. Для этого можно передать собственный заголовок через конфигурацию, но формат и имя идентификатора должны совпадать с тем, что понимает ваше приложение. Не полагайтесь только на секунду в timestamp: несколько запросов могут иметь одинаковое время до миллисекунды.

Статические файлы

Для статики upstream-переменные будут пустыми, поэтому смотрите на $request_time, $bytes_sent, статус и путь. Большое время при небольшом файле указывает на проблему вокруг запроса: TLS, диск, сеть, лимиты файловых дескрипторов или очередь worker-процесса. Большое время при крупном файле может быть нормальным для медленного клиента, но это нужно проверить отдельно.

TLS и сеть

Встроенные переменные access log не дают полной разбивки TLS handshake. Для этой части нужны метрики балансировщика, данные клиента и системные наблюдения. Если задержка возникает до того, как Nginx начал проксировать запрос, анализ только $upstream_response_time ничего не покажет.

Что часто ломает диагностику

• Смотрят только среднее. Среднее скрывает хвост распределения. Соберите как минимум медиану и высокие перцентили, например p95 и p99, по endpoint и статусу.
• Смешивают кэш и динамику. Ответ из proxy cache и ответ приложения нельзя сравнивать в одной группе. Добавьте в лог признак cache status, если он уже настроен в вашей конфигурации.
• Принимают 499 за медленный Nginx. Такой статус означает, что клиент закрыл соединение до завершения ответа. Причина может быть в таймауте клиента, мобильной сети или слишком долгом upstream.
• Включают debug log на постоянной основе. Подробный error log увеличивает объём записи и может изменить поведение системы под нагрузкой. Используйте его короткими сеансами и на ограниченном наборе запросов.
• Меняют таймауты вместо поиска причины. Увеличение proxy_read_timeout не ускоряет приложение. Оно лишь позволяет дольше ждать его ответ.

Как подтвердить гипотезу

Сначала выберите один endpoint и один сценарий: например, GET без кэша или POST с типичным телом. Снимите логи до изменения конфигурации, затем повторите измерение после изменения только одного параметра. Укажите версию Nginx, число worker-процессов, тип upstream, размер ответа и уровень параллельности. Без этих условий числа нельзя честно сравнивать.

Для внешней проверки используйте клиент, который показывает время DNS, TCP, TLS, ожидания и загрузки ответа. Такой замер должен идти отдельно от access log: клиент видит путь от своей машины до сервера, а Nginx — обработку запроса внутри сервера. Если клиентское время велико, а $request_time мало, узкое место находится за пределами Nginx.

Что делать дальше

Оставьте диагностический формат как отдельный шаблон, но не включайте его навсегда без оценки объёма логов. Настройте агрегацию по URI, статусу и перцентилям, затем сравните динамические запросы, кэшированные ответы и статику. Следующий практический шаг — связать access log Nginx с логом приложения по единому идентификатору запроса. Тогда задержка перестанет быть общей цифрой и превратится в цепочку конкретных этапов.