Выявили долгий ответ сервиса и начали тесты
В какой-то момент мониторинг стал показывать, что быстрые запросы иногда получают ошибки из-за долгого ответа сервиса. Попытки воспроизвести проблему на тестовых стендах не дали стабильного результата.
Мы провели мозговой штурм, проанализировали возможные причины и выбрали наиболее вероятную гипотезу. Из-за ограниченного числа worker’ов Django короткие запросы не успевают получить ответ, так как перед ними в очереди стоят долгие запросы. Среди других причин рассматривались нехватка ресурсов для базы данных, слишком большое число одновременно входящих запросов, плохо настроенная пагинация (выдача результатов частями).
Для подтверждения этой гипотезы мы провели два типа тестов. В первых делались только быстрые запросы. Во вторых основную часть запросов составляли долгие. В результате была собрана статистика. При выполнении только быстрых запросов сервис предоставляет ответ за привычные 1–3 секунды. При добавлении к ним параллельно долгих запросов время ответа на быстрые начинало расти. Чем больше становилась доля долгих запросов в общем числе, тем сильнее росло время ответа на быстрые. Но эта зависимость не была линейной. Часть быстрых запросов обрабатывалась как обычно, а часть не успевала обработаться в критичные 30 секунд (время таймаута прокси-сервера). На основании этих результатов стало понятно, что ситуация наблюдается только при втором сценарии.
Следующим шагом мы проанализировали, зависит ли время ответа на долгие запросы от типа и объема запрашиваемых данных. На основании результатов были созданы задачи в таск-трекере для разработчиков на анализ и оптимизацию кода, отвечающего за обработку этих запросов.
Анализ запросов к БД не решил проблему
До этого момента мы в основном использовали инструмент locust, предназначенный для анализа производительности веб-сервисов по протоколу HTTP.
При анализе каждой созданной задачи основная гипотеза была в том, что запросы к базе данных составлены через Django ORM и они не оптимальны. Это могло приводить к лишней нагрузке на базу данных, из-за которой она не справлялась с потоком запросов к ней от сервиса. Что, в свою очередь, увеличивало время ожидания и ответа клиенту.
Мы проанализировали все запросы к базе данных. Часть из них была переписана несколько раз, вплоть до перехода на прямые SQL-запросы вместо Django ORM. Это дало определенный прирост скорости, но не решило проблему в целом.
Следующим шагом мы стали анализировать данные, которые отправлялись клиенту. Здесь удалось выяснить, что часть этих данных формируется сложными запросами из базы данных, но при этом результат всегда одинаков для каждого набора входных параметров. На этом основании мы реализовали кеширующую таблицу в базе данных для хранения готовых ответов на каждый запрошенный набор данных. Это дало хороший прирост скорости. Но только до определенного размера запрашиваемых данных. Затем ситуация повторилась.
Все-таки обнаружили причину
Тогда мы решили проанализировать ресурсы, потребляемые сервисом в различных режимах нагрузки. В первом приближении использовали ручной мониторинг потребления оперативной памяти и нагрузки процессора.
Потребление оперативной памяти всегда оставалось в допустимых пределах — не более 12 из 16 ГБ, доступных системе. А вот нагрузка процессора в отдельные моменты доходила до значений около 100%.
Для дальнейшего анализа мы закрепили отдельные сервисы системы за определенными ядрами процессора. Но так как ядер было меньше, чем сервисов, и некоторым сервисам требовалось более одного ядра, то анализ занял несколько дней кропотливой работы.
Во время перебора комбинаций сервисов по ядрам были получены интересные результаты. Ресурсов процессора для базы данных и worker’ов Celery хватало с запасом. В то время как worker’ы Django на долгих запросах нагружали ядра на полную мощность. Это было достаточно странно, так как никакой сложной логики в этой части кода просто не было.
Для анализа этой ситуации и поиска места в коде, где наблюдаются повышенные нагрузки на процессор, добавили логи с отметками основных этапов в коде. При постепенном сужении и локализации искомой части кода мы обнаружили, что проблема возникает в сериализаторе, который готовит ответ нужной структуры из данных, полученных из базы данных.
И устранили ее
Анализ этого сериализатора показал, что у него сложная вложенная структура, но при этом отсутствует дополнительная логика внутри. Поиски методов оптимизации особого результата не дали, так как единственным действенным решением была замена валидатора на ручное создание структуры ответа из полученных данных. Это бы сильно усложнило читаемость кода и его обслуживание, а также добавило бы возможные места для ошибок в будущем.
Дальнейший анализ ситуации показал, что реальным решением в этой ситуации может быть следующее.
Количество ядер процессора нужно было увеличить. Разделить сервис Django на два: один для обслуживания быстрых запросов, второй для обслуживания долгих запросов. За вторым из них закрепить конкретные ядра процессора в количестве, которое подбирается экспериментально. Запросы на адреса быстрых и медленных запросов разделить на уровне прокси-сервера nginx.
Еще какое-то время у нас ушло на балансировку количества ядер между Django для долгих запросов и остальными сервисами. Но в результате мы получили работающее решение.
Эта ситуация позволила глубоко изучить внутреннюю структуру многих компонентов, используемых в системе, а также еще раз убедиться, что проблема оптимизации и ее решение не всегда очевидны.
