Шел вторник, 25 февраля. Непростой выпуск версии в субботу, 22 февраля, был уже в прошлом. Казалось, что все худшее позади, и ничто не предвещало беды. Но все изменилось в один момент, когда от мониторинга пришла ошибка об утечке памяти на процессе-координаторе сервиса контроля доступа.
Вот откуда? Последние серьезные изменения в кодовой базе координатора были в предыдущей версии более двух месяцев назад, и после этого с памятью не происходило ничего примечательного. Но, к сожалению, графики мониторинга были непреклонны – память координатора явно стала куда-то утекать, на полу сервиса красовалась большая лужа, а значит, сантехнической бригаде предстояла серьезная работа.
![](https://habrastorage.org/webt/sz/a5/nc/sza5ncpnbgd9jxdzckmeu1bztsi.png)
Предварительно сделаем небольшое отступление. Помимо прочего, СБИС позволяет вести учет рабочего времени и осуществлять контроль доступа по модели лица, отпечатку пальца или картам доступа. При этом СБИС обменивается данными с контроллерами конечных устройств (замки, турникеты, терминалы доступа и т.д.). Общается с устройствами отдельный сервис. Он пассивный, взаимодействует с устройствами контроля доступа на основании их собственных протоколов, реализованных поверх HTTP(S). Написан на основе стандартного стека для сервисов в нашей компании: БД PostgreSQL, для бизнес-логики используется Python 3, расширенный методами на C/C++ от нашей платформы.
Типовой узел web-сервиса состоит из следующих процессов:
Монитор — первый процесс web-сервиса. Его задача — вызвать fork(), запустить дочерний процесс-координатор и следить за его работой. Координатор — основной процесс web-сервиса, именно он принимает запросы от внешних устройств, отправляет ответы и балансирует нагрузку. Координатор передает запрос рабочим процессам на исполнение, они его выполняют, передают ответ в разделяемую память и сообщают координатору о том, что задача выполнена и можно забрать результат.
Итак, координатор сервиса контроля доступа отличается от координаторов других сервисов в нашей компании наличием web-сервера. Координаторы других сервисов работали без утечек, поэтому проблему нужно было искать в нашей конфигурации. Хуже того, на тестовых стендах новая версия существовала довольно давно, и на них никто не заметил проблем с памятью. Стали смотреть более внимательно и обнаружили, что память течет только на одном из стендов, да и то с переменным успехом – значит, проблема еще и не так просто воспроизводится.
![](https://habrastorage.org/webt/c_/lg/_k/c_lg_kswgcknpdyc8k2h7bd22d8.png)
Что же делать? Как найти причину? Первым делом мы сняли дамп памяти и отдали на анализ специалистам из платформы. Результат – в дампе ничего нет: ни причины, ни наводки, в какую сторону смотреть дальше. Проверили изменения в коде координатора с предыдущей версии — вдруг мы все-таки внесли какие-то страшные правки, но просто не поняли этого сразу? Но нет — в коде координатора добавились лишь несколько комментариев, да пара методов переехала в новые файлы — в общем, ничего криминального.
Стали смотреть в сторону наших коллег – разработчиков ядра нашего сервиса. Они уверенно отрицали саму возможность причастности к нашей беде, но предложили вживить в сервис мониторинг tracemalloc. Сказано – сделано, в ближайший хотфикс дорабатываем сервис, быстро тестируем, выпускаем на бой.
И что мы видим? Теперь память у нас утекает не просто быстро, а очень быстро – рост стал экспоненциальным. Первый пик списываем на злые силы и сопутствующие им факторы, но второй пик, спустя несколько часов после первого, дает понять, что ждать выпуска следующего хотфикса с таким аварийным поведением сервиса слишком долго. Поэтому забираем результаты tracemalloc и патчим сервис, откатывая правки с мониторингом, чтобы вернуться хотя бы к линейному росту.
![](https://habrastorage.org/webt/zl/yh/w7/zlyhw7-3oq-9wxxwkvwvsl8gd08.png)
Казалось, что у нас есть результаты работы tracemalloc по выделенной в Python памяти, сейчас мы заглянем в них и найдем виновника утечки, но не тут-то было – в собранных данных нет пиков в 5,5ГБ, которые мы видели на графиках мониторинга. Максимум используемой памяти всего 250МБ, да и то 130МБ из них съедает сам tracemalloc. Отчасти это объяснимо – tracemalloc позволяет увидеть динамику памяти в Python, но он не знает о распределении памяти в пакетах на С и С++, которые реализованы нашей платформой. В полученных же данных найти что-то интересное не удалось, память выделяется в приемлемых объемах на обычные объекты типа потоков, строк и словарей — в общем, ничего подозрительного. Тогда решили убрать из данных все лишнее, оставив только общий расход памяти и время, и визуализировать. Хотя визуализация не помогла ответить на вопросы «что происходит» и «почему», с ее помощью мы увидели корреляцию с данными из мониторинга – значит, проблема точно у нас где-то есть, и ее нужно искать.
![](https://habrastorage.org/webt/yr/es/gp/yresgpdyry0i_dr88dbtswqr8k8.png)
На тот момент у нашей бригады сантехников закончились идеи, где искать утечку. К счастью, нам птичка напела, что одно серьезное изменение от платформы все-таки произошло – изменилась версия 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, после):
![](https://habrastorage.org/webt/0m/pp/87/0mpp87t9snuuoadbahwaoxw2jj8.png)
Выяснив причину, мы легко устранили утечку: в нашем классе-наследнике изменили значение флага, возвращавшего старое поведение, и все – победа! Потоки создаются как раньше, не записываясь в переменную класса, а мы наблюдаем приятную картину на графиках мониторинга – утечка устранена!
![](https://habrastorage.org/webt/1o/ja/ss/1ojassz9esw-378romz5kexysde.png)
Приятно писать об этом после одержанной победы. Мы, вероятно, далеко не первые, кто столкнулся с данной проблемой после перехода на Python 3.7, но, скорей всего, и не последние. Для себя же мы сделали выводы, что нужно:
Ну и хочется выразить благодарность всем, кто помог справиться с аварийными сантехническими работами и вновь вернуть былую работоспособность нашему сервису!
Вот откуда? Последние серьезные изменения в кодовой базе координатора были в предыдущей версии более двух месяцев назад, и после этого с памятью не происходило ничего примечательного. Но, к сожалению, графики мониторинга были непреклонны – память координатора явно стала куда-то утекать, на полу сервиса красовалась большая лужа, а значит, сантехнической бригаде предстояла серьезная работа.
![](https://habrastorage.org/webt/sz/a5/nc/sza5ncpnbgd9jxdzckmeu1bztsi.png)
Предварительно сделаем небольшое отступление. Помимо прочего, СБИС позволяет вести учет рабочего времени и осуществлять контроль доступа по модели лица, отпечатку пальца или картам доступа. При этом СБИС обменивается данными с контроллерами конечных устройств (замки, турникеты, терминалы доступа и т.д.). Общается с устройствами отдельный сервис. Он пассивный, взаимодействует с устройствами контроля доступа на основании их собственных протоколов, реализованных поверх HTTP(S). Написан на основе стандартного стека для сервисов в нашей компании: БД PostgreSQL, для бизнес-логики используется Python 3, расширенный методами на C/C++ от нашей платформы.
Типовой узел web-сервиса состоит из следующих процессов:
- Монитор — корневой процесс.
- Координатор — процесс-потомок монитора.
- Рабочие процессы.
Монитор — первый процесс web-сервиса. Его задача — вызвать fork(), запустить дочерний процесс-координатор и следить за его работой. Координатор — основной процесс web-сервиса, именно он принимает запросы от внешних устройств, отправляет ответы и балансирует нагрузку. Координатор передает запрос рабочим процессам на исполнение, они его выполняют, передают ответ в разделяемую память и сообщают координатору о том, что задача выполнена и можно забрать результат.
Кто виноват, и что делать?
Итак, координатор сервиса контроля доступа отличается от координаторов других сервисов в нашей компании наличием web-сервера. Координаторы других сервисов работали без утечек, поэтому проблему нужно было искать в нашей конфигурации. Хуже того, на тестовых стендах новая версия существовала довольно давно, и на них никто не заметил проблем с памятью. Стали смотреть более внимательно и обнаружили, что память течет только на одном из стендов, да и то с переменным успехом – значит, проблема еще и не так просто воспроизводится.
![](https://habrastorage.org/webt/c_/lg/_k/c_lg_kswgcknpdyc8k2h7bd22d8.png)
Что же делать? Как найти причину? Первым делом мы сняли дамп памяти и отдали на анализ специалистам из платформы. Результат – в дампе ничего нет: ни причины, ни наводки, в какую сторону смотреть дальше. Проверили изменения в коде координатора с предыдущей версии — вдруг мы все-таки внесли какие-то страшные правки, но просто не поняли этого сразу? Но нет — в коде координатора добавились лишь несколько комментариев, да пара методов переехала в новые файлы — в общем, ничего криминального.
Стали смотреть в сторону наших коллег – разработчиков ядра нашего сервиса. Они уверенно отрицали саму возможность причастности к нашей беде, но предложили вживить в сервис мониторинг tracemalloc. Сказано – сделано, в ближайший хотфикс дорабатываем сервис, быстро тестируем, выпускаем на бой.
И что мы видим? Теперь память у нас утекает не просто быстро, а очень быстро – рост стал экспоненциальным. Первый пик списываем на злые силы и сопутствующие им факторы, но второй пик, спустя несколько часов после первого, дает понять, что ждать выпуска следующего хотфикса с таким аварийным поведением сервиса слишком долго. Поэтому забираем результаты tracemalloc и патчим сервис, откатывая правки с мониторингом, чтобы вернуться хотя бы к линейному росту.
![](https://habrastorage.org/webt/zl/yh/w7/zlyhw7-3oq-9wxxwkvwvsl8gd08.png)
Казалось, что у нас есть результаты работы tracemalloc по выделенной в Python памяти, сейчас мы заглянем в них и найдем виновника утечки, но не тут-то было – в собранных данных нет пиков в 5,5ГБ, которые мы видели на графиках мониторинга. Максимум используемой памяти всего 250МБ, да и то 130МБ из них съедает сам tracemalloc. Отчасти это объяснимо – tracemalloc позволяет увидеть динамику памяти в Python, но он не знает о распределении памяти в пакетах на С и С++, которые реализованы нашей платформой. В полученных же данных найти что-то интересное не удалось, память выделяется в приемлемых объемах на обычные объекты типа потоков, строк и словарей — в общем, ничего подозрительного. Тогда решили убрать из данных все лишнее, оставив только общий расход памяти и время, и визуализировать. Хотя визуализация не помогла ответить на вопросы «что происходит» и «почему», с ее помощью мы увидели корреляцию с данными из мониторинга – значит, проблема точно у нас где-то есть, и ее нужно искать.
![](https://habrastorage.org/webt/yr/es/gp/yresgpdyry0i_dr88dbtswqr8k8.png)
На тот момент у нашей бригады сантехников закончились идеи, где искать утечку. К счастью, нам птичка напела, что одно серьезное изменение от платформы все-таки произошло – изменилась версия 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, после):
![](https://habrastorage.org/webt/0m/pp/87/0mpp87t9snuuoadbahwaoxw2jj8.png)
Выяснив причину, мы легко устранили утечку: в нашем классе-наследнике изменили значение флага, возвращавшего старое поведение, и все – победа! Потоки создаются как раньше, не записываясь в переменную класса, а мы наблюдаем приятную картину на графиках мониторинга – утечка устранена!
![](https://habrastorage.org/webt/1o/ja/ss/1ojassz9esw-378romz5kexysde.png)
Приятно писать об этом после одержанной победы. Мы, вероятно, далеко не первые, кто столкнулся с данной проблемой после перехода на Python 3.7, но, скорей всего, и не последние. Для себя же мы сделали выводы, что нужно:
- Серьезнее подходить к оценке возможных последствий при внесении серьезных изменений, особенно если от нас зависят другие прикладные решения.
- В случае глобальных изменений в платформе, как, например, смена версии Python, проверять свой код на возможные проблемы.
- Реагировать на любое подозрительное изменение в графиках мониторинга не только боевых сервисов, но и тестовых. Несмотря на действующий сборщик мусора, в Python тоже бывают утечки памяти.
- С инструментами для анализа памяти типа tracemalloc нужно быть осторожными, так как их неправильное использование может ухудшить ситуацию.
- Нужно быть готовыми к тому, что обнаружение утечек памяти потребует терпения, настойчивости и небольшой сыскной работы.
Ну и хочется выразить благодарность всем, кто помог справиться с аварийными сантехническими работами и вновь вернуть былую работоспособность нашему сервису!
Ghool
Спасибо, это очень интересно.
Непонятно вот что: почему в дампе памяти этой проблемы не было видно?
Ведь массив-то этот в памяти хранится.
Некоторое время назад я столкнулся с похожей проблемой на веблоджике — тоже память растёт, дамп снимаешь, смотришь — ничего интересного в нём нет, объём дампа 10 гигов, а в EclipseMemoryAnalyser анализируется 700 метров.
Так и не разобрался.
И на .Net недавно похожая заморочка была — тоже утечка, размер дампа соответствует памяти, а в dotMemory откроешь — а внутри виден один гиг и в нём гигантской утечки не видать. Увидели малкнькую утечку, исправили её — большая тоже ушла.
GrimRanger Автор
В дампе массив с потоками был, но дамп большой, информации в нем много, а массив не особо выделялся на фоне остальных данных, поэтому мы и не заметили проблемы.
Насчет EclipseMemoryAnalyser и dotMemory, вероятно, проблема из той же серии, что и в случае с tracemalloc, который показывает только память, выделенную самим Python, но ничего не знает о распределении памяти в С и С++.
Ghool
Ттак а у вас разве не этот массив всю память пожирал?
Про c-шный код верно.
GrimRanger Автор
Да, по сути он, но при анализе дампа его не заметили.
Не заметили из-за того, что массив состоит из объектов, которые содержат в себе кучу сишной начинки, которая занимает память. Поэтому сам массив относительно небольшой по сравнению с остальными структурами, а память была съедена теми объектами, ссылки на которые он содержал.