От 1 секунды до 10 миллисекунд: Сокращение задержки Prometheus в API Gateway

Запросы с задержками от 1 до 2 секунд

В сообществе APISIX пользователи сообщили о загадочном явлении: когда трафик запросов поступает в нормально развернутый кластер APISIX, небольшое количество запросов имеет исключительно длительную задержку от 1 до 2 секунд. Масштаб QPS пользователя составляет около 10 000, и такие аномальные запросы редки, появляясь всего 1–3 раза каждые несколько минут.

Пользователи предоставили свои снимки запросов с высокой задержкой в issues. Из этих скриншотов видно, что действительно существуют запросы с высокой задержкой, некоторые из которых могут достигать уровня секунд.

С этим явлением связано еще одно заметное явление: использование CPU одним из рабочих процессов достигает 100%.

Команда разработчиков выяснила условия, при которых это явление возникает:

1. Включен плагин Prometheus, и Prometheus Exporter обращается к конечной точке APISIX /apisix/prometheus/metrics для сбора метрик.
2. Количество метрик, которые учитывает плагин Prometheus, достигает определенного масштаба, обычно десятков тысяч.

Это явление в отрасли называется "длинные хвостовые запросы". Оно относится к ситуации, когда небольшой процент запросов имеет аномально длительное время выполнения, в то время как большинство запросов имеют нормальное время отклика в группе запросов. Это может быть связано с узким местом в производительности бэкенд-системы, недостатком ресурсов или другими причинами. Это не фатальная ошибка, но она серьезно влияет на опыт конечных пользователей.

Разбор проблемы

APISIX разработал плагин Prometheus на основе открытой библиотеки Lua nginx-lua-prometheus, который предоставляет функции отслеживания и сбора метрик. Когда Prometheus Exporter обращается к конечной точке метрик Prometheus, предоставляемой APISIX, APISIX вызывает функцию, предоставляемую библиотекой nginx-lua-prometheus, чтобы предоставить результаты вычисления метрик.

Команда разработчиков локализовала проблему: функция prometheus:metric_data(), используемая для предоставления метрик в nginx-lua-prometheus.

Однако это лишь предварительное предположение, и необходимы прямые доказательства, чтобы подтвердить, что длинные хвостовые запросы связаны с этим, а также необходимо прояснить следующие вопросы:

1. Что именно делает эта функция?
2. Почему эта функция вызывает длинные хвостовые запросы?

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

1. Имитация клиента, отправляющего нормальный запрос, который проксируется APISIX на вышестоящий сервер.
2. Имитация того, что Prometheus Exporter обращается к /apisix/prometheus/metrics каждые 5 секунд, вызывая функцию prometheus:metric_data() в APISIX.

Воспроизведенная среда:

При проведении теста мы наблюдали P100 и другие показатели в результатах теста wrk2, чтобы подтвердить наличие явления длинных хвостовых запросов. Мы создали flame graph APISIX, чтобы наблюдать за использованием CPU при возникновении длинных хвостовых запросов.

Результаты теста wrk2:

  Распределение задержек (HdrHistogram - Нескорректированная задержка (измеренная без учета задержек запуска))
   50.000%    1.13ms
   75.000%    2.56ms
   90.000%    4.82ms
   99.000%   14.70ms
   99.900%   27.95ms
   99.990%   74.75ms
   99.999%  102.78ms
  100.000%  102.78ms

Согласно этим результатам теста, можно сделать вывод, что во время теста 99% запросов были выполнены в течение 14.70 миллисекунд, а небольшое количество запросов заняло более 100 миллисекунд. Мы использовали количество метрик как переменную для проведения нескольких тестов и обнаружили, что количество метрик линейно увеличивается с задержкой P100. Если количество метрик достигает уровня 100 000, P100 достигает уровня секунд.

Полученный flame graph:

Как видно из стека функций flame graph, prometheus:metric_data() занимает наибольшую горизонтальную ширину, что свидетельствует о большом потреблении CPU, и прямо указывает на то, что prometheus:metric_data() вызывает длинные хвостовые запросы.

Давайте кратко проанализируем, что делает функция prometheus:metric_data().

prometheus:metric_data() извлекает метрики из общей памяти, классифицирует их и обрабатывает в текстовый формат, совместимый с Prometheus. В этом процессе все метрики сортируются в лексикографическом порядке, а префиксы метрик обрабатываются с помощью регулярных выражений. Как правило, это очень ресурсоемкие операции.

Несовершенная попытка оптимизации

Как только мы локализовали код, вызывающий задержку, следующим шагом является анализ кода в сочетании с flame graph и поиск возможностей для оптимизации.

Из flame graph мы локализовали функцию fix_histogram_bucket_labels. При анализе этой функции мы обнаружили две чувствительные функции: string:match и string:gusb. Ни одна из этих функций не может быть JIT-компилирована LuaJIT. Они могут быть только интерпретированы и выполнены.

LuaJIT — это JIT-компилятор для языка программирования Lua, который может компилировать код Lua в машинный код и выполнять его. Это может обеспечить более высокую производительность по сравнению с использованием интерпретатора для выполнения кода Lua.

Одним из преимуществ использования LuaJIT для выполнения кода Lua является то, что он может значительно увеличить скорость выполнения кода. Это позволяет APISIX поддерживать низкую задержку при обработке большого количества запросов и лучше работать в условиях высокой конкуренции.

Поэтому код, который LuaJIT не может скомпилировать, становится потенциальным узким местом в производительности.

Мы собрали вышеуказанную информацию и отправили issue: оптимизация явления длинных хвостовых запросов в nginx-lua-prometheus, где мы связались с автором Knyar этого проекта и исследовали возможности для оптимизации. Knyar оперативно ответил, и мы уточнили места, которые можно оптимизировать. Затем был отправлен PR: chore: использование ngx.re.match вместо string match для повышения производительности для оптимизации.

В этом PR мы в основном выполнили:

• Использование ngx.re.match вместо string:match
• Замена string:gusb на ngx.re.gsub

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

NGINX — это многопроцессная однопоточная архитектура. Все рабочие процессы будут отслеживать TCP-соединения (Transmission Control Protocol), но как только соединение попадает в рабочий процесс, оно не может быть перенесено в другие рабочие процессы для обработки.

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

prometheus:metric_data() занимает большое количество временных срезов CPU для вычислений, вытесняя ресурсы CPU для обработки нормальных запросов. Именно поэтому вы видите рабочий процесс с использованием CPU на 100%.

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

В приведенном выше flame graph builtin#100 представляет функции библиотеки luajit/lua (например, string.find), к которым можно получить доступ через https://github.com/openresty/openresty-devel-utils/blob/master/ljff.lua в этом проекте, чтобы получить соответствующее имя функции.

Как использовать:

$ luajit ljff.lua 100
FastFunc table.sort

Поскольку вычисление метрик занимает чрезмерное количество CPU, мы рассматриваем возможность отказа от временных срезов CPU при вычислении метрик.

Для APISIX приоритет обработки нормальных запросов является наивысшим, и ресурсы CPU должны быть направлены на это. В то же время prometheus:metric_data() будет влиять только на эффективность получения метрик Prometheus Exporter.

В мире OpenResty существует скрытый способ уступить временные срезы CPU: ngx.sleep(0). Мы вводим этот метод в prometheus:metric_data(). При обработке метрик мы будем уступать временные срезы CPU после обработки определенного количества метрик (например, 200 метрик), чтобы новые входящие запросы могли быть обработаны.

Мы отправили PR для этой оптимизации: feat: оптимизация производительности.

В нашем тестовом сценарии, когда общее количество метрик достигает уровня 100 000, результаты теста с использованием wrk2 до введения этой оптимизации:

  Распределение задержек (HdrHistogram - Нескорректированная задержка (измеренная без учета задержек запуска))
 50.000%   10.21ms
 75.000%   12.03ms
 90.000%   13.25ms
 99.000%   92.80ms
 99.900%  926.72ms
 99.990%  932.86ms
 99.999%  934.40ms
100.000%  934.91ms

Результаты wrk2 после оптимизации:

  Распределение задержек (HdrHistogram - Нескорректированная задержка (измеренная без учета задержек запуска))
 50.000%    4.34ms
 75.000%   12.81ms
 90.000%   16.12ms
 99.000%   82.75ms
 99.900%  246.91ms
 99.990%  349.44ms
 99.999%  390.40ms
100.000%  397.31ms

Индекс P100 составляет примерно 1/3–1/2 от того, что было до оптимизации.

Однако это не решает проблему идеально. Анализируя оптимизированный flame graph:

Можно увидеть, что builtin#100 (table.sort) и builtin#92 (string.format) все еще занимают значительную ширину горизонтальной оси, потому что:

1. prometheus:metric_data() сначала вызывает table.sort для сортировки всех метрик. Когда количество метрик достигает уровня 100 000, это эквивалентно сортировке 100 000 строк, и table.sort не может быть прерван ngx.sleep(0).
2. Места, где используются string.format и fix_histogram_bucket_labels, не могут быть оптимизированы. После общения с knyar я узнал, что эти шаги необходимы для того, чтобы prometheus:metric_data() могла предоставлять метрики в правильном формате.

На данный момент методы оптимизации на уровне кода исчерпаны, но, к сожалению, проблема все еще не решена идеально. В метриках P100 все еще заметна задержка.

Что делать?

Вернемся к основной проблеме: prometheus:metric_data() занимает большое количество временных срезов CPU для вычислений, вытесняя ресурсы CPU для обработки нормальных запросов.

В системе Linux временные срезы CPU выделяются потоку или процессу? Точнее, потоку, и поток является фактической единицей работы. Однако NGINX — это многопроцессная однопоточная архитектура, в каждом процессе только один поток.

На этом этапе мы подумали о направлении оптимизации: переместить prometheus:metric_data() в другие потоки (или, точнее, процессы). Поэтому мы исследовали два направления:

1. Использовать ngx.run_worker_thread для выполнения задач вычисления prometheus:metric_data(), что эквивалентно передаче задач, интенсивно использующих CPU, в пул потоков.
2. Использовать отдельный процесс для обработки задач вычисления prometheus:metric_data(), этот процесс не будет обрабатывать нормальные запросы.

После PoC (proof of concept) мы отвергли вариант 1 и приняли вариант 2. Вариант 1 отвергнут, потому что ngx.run_worker_thread подходит только для выполнения задач вычисления, не связанных с запросами, в то время как prometheus:metric_data() связана с запросами.

Реализация варианта 2: Пусть privileged agent (привилегированный процесс) обрабатывает prometheus:metric_data(). Но привилегированный процесс не прослушивает никакие порты и не обрабатывает никакие запросы. Поэтому нам нужно изменить привилегированный процесс, чтобы он мог прослушивать порт.

В итоге мы использовали feat: разрешить привилегированному агенту прослушивать порт и feat(prometheus): поддержка сбора метрик в привилегированном агенте для реализации варианта 2.

Мы протестировали APISIX с этой оптимизацией и обнаружили, что задержка индекса P100 снизилась до разумного диапазона, и проблема длинных хвостовых запросов больше не существует.

  Распределение задержек (HdrHistogram - Нескорректированная задержка (измеренная без учета задержек запуска))
 50.000%    3.74ms
 75.000%    4.66ms
 90.000%    5.77ms
 99.000%    9.99ms
 99.900%   13.41ms
 99.990%   16.77ms
 99.999%   18.38ms
100.000%   18.40ms

Это изящное решение, которое решает основную проблему. Мы наблюдали и проверяли это решение в производственной среде. Оно устранило явление длинных хвостовых запросов и не вызвало дополнительных исключений.

Итог

Когда мы исправляли эту проблему, возникла новая мысль: подходит ли открытая библиотека nginx-lua-prometheus для APISIX?

Мы решили проблему prometheus:metric_data() на стороне APISIX. В то же время мы также обнаружили другие проблемы в nginx-lua-prometheus и исправили их. Например, исправление утечки памяти и LRU-кэширование.

nginx-lua-prometheus изначально разрабатывалась для NGINX, а не для OpenResty и приложений на основе OpenResty. Однако в экосистеме OpenResty нет более зрелого открытого проекта, который бы подключался к экосистеме Prometheus, чем nginx-lua-prometheus. Поэтому nginx-lua-prometheus постоянно продвигается сообществом для экосистемы OpenResty.

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