Поиск утекающих ресурсов в Java приложении
Привет, сообщество! Меня зовут Данила, я ведущий разработчик в БФТ-Холдинге.
Я расскажу вам о нашем опыте борьбы с утечкой памяти в сервисе авторизации. Как наша команда столкнулась с критической проблемой, которая приводила к сбоям сервиса, и нам пришлось провести исследование, чтобы найти и устранить причину утечки ресурсов.
Как все начиналось: из бэклога прилетела задача с формулировкой — при эксплуатации authz-server на контуре PROD наблюдается активная утечка памяти, которая приводит к прекращению работы сервиса по причине достижения лимитов по RAM.
Контур PROD уже звучит грозно, приоритет критический, надо разбираться. После недолгого анализа исходников выяснено: обычный Spring Boot сервис c gRPC библиотекой, который выполняет 2 функции — поход в базу за данными пользователей (ФИО и роли) и проверку наличия доступа к конкретному ресурсу для конкретного пользователя. Первая функция тривиальная — «дай по id такого-то пользователя, если нет, то скажи, что его нет». Вторая функция немного сложнее: нужно вызвать метод сторонней библиотеки и передать в него 5 параметров. И всё, но на PROD график использования heap вот такой:
На промежутке в 10 секунд сервис успевает из состояния 1 скакнуть в состояние 2 и «съесть» больше 4 гигабайт heap, вернуться обратно и повторить цикл. Не была и исключительной ситуация, когда такой скачок потребления был выше установленного лимита в 9 (!!!) гигабайт и сервис ругался на ООМ, уходя в рестарт. Но у сервиса всего 2 функции, откуда такой зверский аппетит?
Проблема есть, надо решать. Графики входящих запросов в grafana:
DDOS-а нет, в сумме около 100 rps — это очень маленькое число, но heap куда-то улетает… В топе вызываемого API ожидаемые лидеры — это запрос на конкретного пользователя и проверка доступа к ресурсам:
Первая мысль — снять дамп и заглянуть внутрь, чтобы понять, кто же всё-таки потребляет heap в таких количествах, но для этого нужно было выкатить соответствующие настройки запуска приложения в PROD-контур. Дело небыстрое, задача на девопса заведена, но пока дампа нет, снова нужен анализ исходников.
Первый метод — getUserInfo. Вроде бы всё хорошо: в вызываемом классе есть корень cache, значит, тут точно нет проблем. Все пользователи выгружены в кэш приложения, и здесь проблем не будет.
Но наивные мысли о наличии кэша были разрушены при переходе в реализацию самого метода:
Оказалось, что никакого кэша-то и нет, по крайней мере для этого метода: на каждый запрос идёт обращение в базу, тратятся драгоценные миллисекунды на передачу информации с последующей сериализацией/десериализацией. Вроде бы это не должно потреблять много памяти, но выглядит подозрительно. Далее возник интерес:, а все ли методы внутри этого класса ходят в tarantool по каждому запросу? И, как оказалось, да! Но при чём тут кэш в названии? Далее внутри проекта был найден интересный каталог:
Так кэш все-таки есть, а какова реализация интерфейса?
Всего 1 метод? Не густо. А как это работает?
То есть, существует некая коллекция users со следующим заполнением:
На этапе запуска приложения выполняется метод cacheUsers () и потом по crone обновляется cache. Тут можно призадуматься: существует класс доступа к ресурсам, который имеет в своем названии cache и при том нагло обманывает и никакого кэша нет и каждый запрос — это поход в БД. Но, одновременно с этим, буквально в соседнем каталоге — кэш есть! Непонятно, почему так было сделано; у автора репозитория узнать уже невозможно. Ладно, какой хоть таймаут обновления данных?
То есть, два соседних метода API будут выдавать противоречивые данные? По id пользователя получить можно, а вот по фильтрам он, в худшем случае, появится через полчаса? После проведения замеров было выяснено, что все выгруженные в память пользователи весят примерно 300–400 Mb, то есть ответ на причину потребления памяти не найден, да и обновление кэша происходит раз в 30 минут. Было решено проверить, насколько много памяти расходуется при вызове самого популярного метода — getUserInfo. Для этого был создан дополнительный метод для эмулирования нагрузки, при помощи которого, уже на DEV-контуре, была осуществлена проверка: как будет вести себя heap при 100 rps в течение 1 минуты. Как результат, heap почти не растет, нет никаких скачков, еле-еле съедено 100 Mb.
Значит, псевдо-кэш не виноват, и множественные запросы в тарантул здесь ни при чём. После консультации с непосредственными пользователями было установлено, что задержка в 1 минуту не является критичной. Время обновления кэша было выставлено в 1 минуту, и осуществлён перевод всех методов API на его использование.
Настала очередь на проверку второго самого популярного метода hasAccessBatch. Из логов был найден пример получаемого сообщения. По сути, это список из неких объектов batch внутри которых передан userId и тот ресурс к которому проверяется доступ. Это 100% вторая функция сервиса, при которой идет обращение к сторонней библиотеке jcasbin.
Из документации к сервису стало понятно, что пользователи системы имеют репозиторий, где в файл формата csv они кладут строчки вида Домен-Роль-Ресурс-Действие. Задача библиотеки jcasbin состоит в том, чтобы загрузить в себя этот файл с политиками и, далее проверять — есть ли у конкретного пользователя доступ для действий над ресурсом.
Создан еще один тестовый метод, по аналогу с предыдущим, только воспроизводящим вызовы hasAccessBatch. Дана нагрузка 50 rps и… бинго!
Та самая пила, в меньших масштабах, но поведение одинаковое. Из реализации видно, что на вход hasAccessBatch поступает список из ресурсов, к которым проверяем доступ.
Далее тело метода, в котором нужно понять, что же вызывается в конце концов.
Прошерстив логи за прошедший день, не было найдено ни одного запроса, в котором бы передавались специфичные политики. Поэтому анализируется ветка, где политики в запросе отсутствуют:
Что тут происходит? Для каждой из ролей выполняется запрос в библиотеку jcasbin для определения доступа к действию над ресурсом. Если хотя бы один ответ положительный, то доступ есть. Вроде бы ничего странного, но… А если у пользователя сто ролей или тысяча? А если список из ресурсов во входящем запросе длинный?
Налицо отсутствие хоть какой бы то ни было оптимизации со стороны приложения. Как это было исправлено — будет описано ниже. Но главный вопрос остался без ответа: зачем простому методу с 4 параметрами столько памяти?
В исходниках метода enforce нет ясности о происходящем процессе, в результате чего было потрачено еще какое-то время на анализ и найдено вот это место:
В п.1 идет очевидная проверка, что список загруженных политик не пуст, а затем, в п.2 идет итерация по ВСЕМ политикам с созданием HashMap (п.3) для каждой итерации. В heapdump скорее всего будет очень большое количество объектов-внутренностей HashMap в виде Node
Таким образом, каждый раз, чтобы проверить, есть ли доступ к одному ресурсу, нужно перебрать весь файл с политиками. Отсюда следует грустная математика: размер входящего списка ролей у пользователя умноженный на количество строк в файле политик — и есть та нагрузка, которая генерирует такое потребление памяти. Был задан вопрос разработчику библиотеки по поводу потребления ресурсов, на что разработчик посоветовал использовать последнюю версию. Но ирония в том, что на картинке выше, с «пилой» при локальных тестах, версия уже была актуальна.
Примерно в это время подоспел дамп. VisualVM выдает предполагаемую картину, весь heap забит внутренностями HashMap:
Но детализации не хватает. Непонятно, кто же создает такое большое количество объектов. Анализаторы посерьезнее, с автоматической аналитикой, говорят следующее: J-xray (платный, но на одном компьютере можно запустить 3 анализа в течение 30 дней), некий googlecode.aviator.utils.Env и jcasbin, скорее всего googlecode.aviator часть библиотеки jcasbin, построенное дерево зависимостей проекта это подтверждают.
IBM heap analyzer говорит то же самое, jcasbin потребляет очень много heap.
Причина установлена со стопроцентной надежностью, но отказаться от использования библиотеки нельзя. Следовательно, ее нужно вызывать как можно реже. Можно начинать оптимизацию! Первым под нож пошел метод hasAccess, про который было написано выше. Теперь понятно, зачем там была нужна локальная хэшмапа: так как не было нормального кэша, то для исключения повторных походов в БД все найденные пользователи клались в «промежуточный» кэш на время выполнения метода. Сейчас это всё не нужно, кэш был исправлен, и лишнее можно убрать.
Вложенный метод hasAccess уже некуда оптимизировать (картинка с ним выше), поэтому следующий hasAccessRbac. В нем-то и произошли основные изменения. Как можно снизить количество вызовов метода на проверку доступа к ресурсу? Правильно, вызывать метод только для тех ролей, у которых есть гипотетический доступ к ресурсу. Узнать это можно, проанализировав файл политик. Так как файлы политик можно обновить только через редеплой сервиса (особенности эксплуатации), то можно спокойно их загрузить в кэш приложения и построить Map
А метод getEnforcerInfo так:
Сначала идёт проверка, что роли вообще есть, затем получаем ключ из переданных аргументов. Если такой ключ в политиках не упомянут (то есть раньше нас могли просто заддосить, посылая на проверку несуществующие роли и ресурсы с доменами), то сразу выходим; далее фильтр по ролям пользователя, опять сразу выход, если ролей подходящих нет. И только в конце, если что-то нашлось, то идёт проверка доступа через jcasbin.
Но ведь можно же ещё сильнее сократить количество обращений в jcasbin. Почему бы не составлять похожий строковый ключ, как это было сделано для кэширования политик, и при отсутствии этого ключа в кэше не провести расчёт, положить результат в кэш и дальше его переиспользовать? Этот шаг выглядит очень простым: добавляется Caffeine внутри отдельного класса для нового кэша (избегание проблемы с нагенерированными спрингом прокси-классами, см. nested @Transactional)
Собирается новый артефакт, все тесты зеленые, деплой в контур, при появлении нагрузки наблюдается следующая картина:
График ровный, память освобождается. Пики по ЦПУ — это начитка информации по пользователям из БД. Никаких панических прыжков до 8 гигабайт нет. Но всё равно, 3–4 гигабайта приложение ест. Что ещё может быть источником дополнительного потребления heap? В реализации внешнего API найдено следующее:
Не очень информативно выходит, каждый запрос логгируется вместе со входящим дто, плюс не несёт в себе практически никакой полезной информации. Замена info на debug, артефакт доставляется на PROD через стандартный процесс, и ситуация сильно меняется!
Вот так гораздо лучше! Приложение едва-едва переползает за 2 гига heap и это в самый пик нагрузки!
Выводы:
1.Сторонние библиотеки могут при неожиданно простых операциях потреблять очень много памяти, что может приводить к целым расследованиям по поиску проблемного места или поиску обходных путей, для минимизации использования такой библиотеки.
2. Простое отсечение заведомо ложных веток исполнения кода может высвобождать значительное количество ресурсов.
3.Рефакторинг кода иногда приносит пользу, особенно когда он направлен на устранение избыточных операций, оптимизацию алгоритмов и упрощение структуры. При этом важно учитывать, что изменения должны быть хорошо протестированы перед внедрением в продакшн.:)
4.Излишнее логгирование тоже потребляет ресурсы. Даже на первый взгляд безобидные логгируемые операции могут привести к значительному увеличению нагрузки на систему, особенно при высокой частоте запросов.:(
