Шел вторник, 25 февраля. Непростой выпуск версии в субботу, 22 февраля, был уже в прошлом. Казалось, что все худшее позади, и ничто не предвещало беды. Но все изменилось в один момент, когда от мониторинга пришла ошибка об утечке памяти на процессе-координаторе сервиса контроля доступа.
Вот откуда? Последние серьезные изменения в кодовой базе координатора были в предыдущей версии более двух месяцев назад, и после этого с памятью не происходило ничего примечательного. Но, к сожалению, графики мониторинга были непреклонны – память координатора явно стала куда-то утекать, на полу сервиса красовалась большая лужа, а значит, сантехнической бригаде предстояла серьезная работа.
Предварительно сделаем небольшое отступление. Помимо прочего, СБИС позволяет вести учет рабочего времени и осуществлять контроль доступа по модели лица, отпечатку пальца или картам доступа. При этом СБИС обменивается данными с контроллерами конечных устройств (замки, турникеты, терминалы доступа и т.д.). Общается с устройствами отдельный сервис. Он пассивный, взаимодействует с устройствами контроля доступа на основании их собственных протоколов, реализованных поверх HTTP(S). Написан на основе стандартного стека для сервисов в нашей компании: БД PostgreSQL, для бизнес-логики используется Python 3, расширенный методами на C/C++ от нашей платформы.
Типовой узел web-сервиса состоит из следующих процессов:
Монитор — первый процесс web-сервиса. Его задача — вызвать fork(), запустить дочерний процесс-координатор и следить за его работой. Координатор — основной процесс web-сервиса, именно он принимает запросы от внешних устройств, отправляет ответы и балансирует нагрузку. Координатор передает запрос рабочим процессам на исполнение, они его выполняют, передают ответ в разделяемую память и сообщают координатору о том, что задача выполнена и можно забрать результат.
Итак, координатор сервиса контроля доступа отличается от координаторов других сервисов в нашей компании наличием web-сервера. Координаторы других сервисов работали без утечек, поэтому проблему нужно было искать в нашей конфигурации. Хуже того, на тестовых стендах новая версия существовала довольно давно, и на них никто не заметил проблем с памятью. Стали смотреть более внимательно и обнаружили, что память течет только на одном из стендов, да и то с переменным успехом – значит, проблема еще и не так просто воспроизводится.
Что же делать? Как найти причину? Первым делом мы сняли дамп памяти и отдали на анализ специалистам из платформы. Результат – в дампе ничего нет: ни причины, ни наводки, в какую сторону смотреть дальше. Проверили изменения в коде координатора с предыдущей версии — вдруг мы все-таки внесли какие-то страшные правки, но просто не поняли этого сразу? Но нет — в коде координатора добавились лишь несколько комментариев, да пара методов переехала в новые файлы — в общем, ничего криминального.
Стали смотреть в сторону наших коллег – разработчиков ядра нашего сервиса. Они уверенно отрицали саму возможность причастности к нашей беде, но предложили вживить в сервис мониторинг tracemalloc. Сказано – сделано, в ближайший хотфикс дорабатываем сервис, быстро тестируем, выпускаем на бой.
И что мы видим? Теперь память у нас утекает не просто быстро, а очень быстро – рост стал экспоненциальным. Первый пик списываем на злые силы и сопутствующие им факторы, но второй пик, спустя несколько часов после первого, дает понять, что ждать выпуска следующего хотфикса с таким аварийным поведением сервиса слишком долго. Поэтому забираем результаты tracemalloc и патчим сервис, откатывая правки с мониторингом, чтобы вернуться хотя бы к линейному росту.
Казалось, что у нас есть результаты работы tracemalloc по выделенной в Python памяти, сейчас мы заглянем в них и найдем виновника утечки, но не тут-то было – в собранных данных нет пиков в 5,5ГБ, которые мы видели на графиках мониторинга. Максимум используемой памяти всего 250МБ, да и то 130МБ из них съедает сам tracemalloc. Отчасти это объяснимо – tracemalloc позволяет увидеть динамику памяти в Python, но он не знает о распределении памяти в пакетах на С и С++, которые реализованы нашей платформой. В полученных же данных найти что-то интересное не удалось, память выделяется в приемлемых объемах на обычные объекты типа потоков, строк и словарей — в общем, ничего подозрительного. Тогда решили убрать из данных все лишнее, оставив только общий расход памяти и время, и визуализировать. Хотя визуализация не помогла ответить на вопросы «что происходит» и «почему», с ее помощью мы увидели корреляцию с данными из мониторинга – значит, проблема точно у нас где-то есть, и ее нужно искать.
На тот момент у нашей бригады сантехников закончились идеи, где искать утечку. К счастью, нам птичка напела, что одно серьезное изменение от платформы все-таки произошло – изменилась версия Python с 3.4 на 3.7, а это огромное поле для поиска.
Решили поискать проблемы, связанные с утечкой памяти в Python 3.7 на просторах Интернета, ведь наверняка кто-то уже столкнулся с подобным поведением. Все-таки Python 3.7 вышел в свет довольно давно, это мы на него перешли только с текущим обновлением. К счастью, ответ на наш вопрос нашелся быстро, а также нашлись issue и pull-request на исправление проблемы, а она сама оказалась в изменениях, внесенных разработчиками Python.
Что же произошло?
Начиная с версии 3.7 изменилось поведение класса ThreadingMixIn, от которого мы наследуемся в нашем web-сервере для обработки каждого запроса в отдельном потоке. В классе ThreadingMixIn добавили занесение всех создаваемых потоков в массив. Из-за таких изменений экземпляры класса, обрабатывающие подключения устройств, не освобождаются после завершения, и сборщик мусора в Python не может очистить память по отработавшим потокам. Это-то и привело к линейному росту выделенной памяти в прямой зависимости от количества запросов на наш сервер.
Вот он, коварный код питоновского модуля с большой дырой (слева показан код в Python 3.5 до изменений, справа – в 3.7, после):
Выяснив причину, мы легко устранили утечку: в нашем классе-наследнике изменили значение флага, возвращавшего старое поведение, и все – победа! Потоки создаются как раньше, не записываясь в переменную класса, а мы наблюдаем приятную картину на графиках мониторинга – утечка устранена!
Приятно писать об этом после одержанной победы. Мы, вероятно, далеко не первые, кто столкнулся с данной проблемой после перехода на Python 3.7, но, скорей всего, и не последние. Для себя же мы сделали выводы, что нужно:
Ну и хочется выразить благодарность всем, кто помог справиться с аварийными сантехническими работами и вновь вернуть былую работоспособность нашему сервису!
Вот откуда? Последние серьезные изменения в кодовой базе координатора были в предыдущей версии более двух месяцев назад, и после этого с памятью не происходило ничего примечательного. Но, к сожалению, графики мониторинга были непреклонны – память координатора явно стала куда-то утекать, на полу сервиса красовалась большая лужа, а значит, сантехнической бригаде предстояла серьезная работа.
Предварительно сделаем небольшое отступление. Помимо прочего, СБИС позволяет вести учет рабочего времени и осуществлять контроль доступа по модели лица, отпечатку пальца или картам доступа. При этом СБИС обменивается данными с контроллерами конечных устройств (замки, турникеты, терминалы доступа и т.д.). Общается с устройствами отдельный сервис. Он пассивный, взаимодействует с устройствами контроля доступа на основании их собственных протоколов, реализованных поверх HTTP(S). Написан на основе стандартного стека для сервисов в нашей компании: БД PostgreSQL, для бизнес-логики используется Python 3, расширенный методами на C/C++ от нашей платформы.
Типовой узел web-сервиса состоит из следующих процессов:
- Монитор — корневой процесс.
- Координатор — процесс-потомок монитора.
- Рабочие процессы.
Монитор — первый процесс web-сервиса. Его задача — вызвать fork(), запустить дочерний процесс-координатор и следить за его работой. Координатор — основной процесс web-сервиса, именно он принимает запросы от внешних устройств, отправляет ответы и балансирует нагрузку. Координатор передает запрос рабочим процессам на исполнение, они его выполняют, передают ответ в разделяемую память и сообщают координатору о том, что задача выполнена и можно забрать результат.
Кто виноват, и что делать?
Итак, координатор сервиса контроля доступа отличается от координаторов других сервисов в нашей компании наличием web-сервера. Координаторы других сервисов работали без утечек, поэтому проблему нужно было искать в нашей конфигурации. Хуже того, на тестовых стендах новая версия существовала довольно давно, и на них никто не заметил проблем с памятью. Стали смотреть более внимательно и обнаружили, что память течет только на одном из стендов, да и то с переменным успехом – значит, проблема еще и не так просто воспроизводится.
Что же делать? Как найти причину? Первым делом мы сняли дамп памяти и отдали на анализ специалистам из платформы. Результат – в дампе ничего нет: ни причины, ни наводки, в какую сторону смотреть дальше. Проверили изменения в коде координатора с предыдущей версии — вдруг мы все-таки внесли какие-то страшные правки, но просто не поняли этого сразу? Но нет — в коде координатора добавились лишь несколько комментариев, да пара методов переехала в новые файлы — в общем, ничего криминального.
Стали смотреть в сторону наших коллег – разработчиков ядра нашего сервиса. Они уверенно отрицали саму возможность причастности к нашей беде, но предложили вживить в сервис мониторинг tracemalloc. Сказано – сделано, в ближайший хотфикс дорабатываем сервис, быстро тестируем, выпускаем на бой.
И что мы видим? Теперь память у нас утекает не просто быстро, а очень быстро – рост стал экспоненциальным. Первый пик списываем на злые силы и сопутствующие им факторы, но второй пик, спустя несколько часов после первого, дает понять, что ждать выпуска следующего хотфикса с таким аварийным поведением сервиса слишком долго. Поэтому забираем результаты tracemalloc и патчим сервис, откатывая правки с мониторингом, чтобы вернуться хотя бы к линейному росту.
Казалось, что у нас есть результаты работы tracemalloc по выделенной в Python памяти, сейчас мы заглянем в них и найдем виновника утечки, но не тут-то было – в собранных данных нет пиков в 5,5ГБ, которые мы видели на графиках мониторинга. Максимум используемой памяти всего 250МБ, да и то 130МБ из них съедает сам tracemalloc. Отчасти это объяснимо – tracemalloc позволяет увидеть динамику памяти в Python, но он не знает о распределении памяти в пакетах на С и С++, которые реализованы нашей платформой. В полученных же данных найти что-то интересное не удалось, память выделяется в приемлемых объемах на обычные объекты типа потоков, строк и словарей — в общем, ничего подозрительного. Тогда решили убрать из данных все лишнее, оставив только общий расход памяти и время, и визуализировать. Хотя визуализация не помогла ответить на вопросы «что происходит» и «почему», с ее помощью мы увидели корреляцию с данными из мониторинга – значит, проблема точно у нас где-то есть, и ее нужно искать.
На тот момент у нашей бригады сантехников закончились идеи, где искать утечку. К счастью, нам птичка напела, что одно серьезное изменение от платформы все-таки произошло – изменилась версия Python с 3.4 на 3.7, а это огромное поле для поиска.
Решили поискать проблемы, связанные с утечкой памяти в Python 3.7 на просторах Интернета, ведь наверняка кто-то уже столкнулся с подобным поведением. Все-таки Python 3.7 вышел в свет довольно давно, это мы на него перешли только с текущим обновлением. К счастью, ответ на наш вопрос нашелся быстро, а также нашлись issue и pull-request на исправление проблемы, а она сама оказалась в изменениях, внесенных разработчиками Python.
Что же произошло?
Начиная с версии 3.7 изменилось поведение класса ThreadingMixIn, от которого мы наследуемся в нашем web-сервере для обработки каждого запроса в отдельном потоке. В классе ThreadingMixIn добавили занесение всех создаваемых потоков в массив. Из-за таких изменений экземпляры класса, обрабатывающие подключения устройств, не освобождаются после завершения, и сборщик мусора в Python не может очистить память по отработавшим потокам. Это-то и привело к линейному росту выделенной памяти в прямой зависимости от количества запросов на наш сервер.
Вот он, коварный код питоновского модуля с большой дырой (слева показан код в Python 3.5 до изменений, справа – в 3.7, после):
Выяснив причину, мы легко устранили утечку: в нашем классе-наследнике изменили значение флага, возвращавшего старое поведение, и все – победа! Потоки создаются как раньше, не записываясь в переменную класса, а мы наблюдаем приятную картину на графиках мониторинга – утечка устранена!
Приятно писать об этом после одержанной победы. Мы, вероятно, далеко не первые, кто столкнулся с данной проблемой после перехода на Python 3.7, но, скорей всего, и не последние. Для себя же мы сделали выводы, что нужно:
- Серьезнее подходить к оценке возможных последствий при внесении серьезных изменений, особенно если от нас зависят другие прикладные решения.
- В случае глобальных изменений в платформе, как, например, смена версии Python, проверять свой код на возможные проблемы.
- Реагировать на любое подозрительное изменение в графиках мониторинга не только боевых сервисов, но и тестовых. Несмотря на действующий сборщик мусора, в Python тоже бывают утечки памяти.
- С инструментами для анализа памяти типа tracemalloc нужно быть осторожными, так как их неправильное использование может ухудшить ситуацию.
- Нужно быть готовыми к тому, что обнаружение утечек памяти потребует терпения, настойчивости и небольшой сыскной работы.
Ну и хочется выразить благодарность всем, кто помог справиться с аварийными сантехническими работами и вновь вернуть былую работоспособность нашему сервису!