Exception #08: Поиск "утечек" памяти в python-программе

Я собрался с силами и сгенерировал текстовую версию доклада, который я делал на Exception #08. Про то, как я его писал можно будет написать отдельный пост =)

Exception #08: Поиск "утечек" памяти в python-программе

Постановка задачи

Все началось с конкретной задачи, с которой я столкнулся в Яндексе. Появилась необходимость протестировать работу сложного веб-сервиса написанного на mighty-яндекс-технологиях. Единственной точкой, в которой можно было адекватно тестировать сервер, был сервер снаружи, по http-интерфейсу. Так как части логики равномерно располагались на всем стеке сервера.

В качестве инструментария для тестирования было решено использовать стандартный модуль unittest и twill.

В нашем примере весь этот фреймворк будет заменен простым сервером на cherrypy. В нашем случае сервер реализует одну единственную форму, с одним полем и кнопкой Submit, по которой выдается некий достаточно большой ответ.

server.py:

import cherrypy

class Server(object):
    @cherrypy.expose
    def index(self):
        return ('<form action="/form">'
                '<input type="text" name="q"></input>'
                '<input type="submit"></input>'
                '</form>')

    @cherrypy.expose
    def form(self, q):
        return (
            ('Your query was: %s' % q) +
            'I love your RAM! '*50000)

cherrypy.quickstart(Server())

Само описание тестов - смесь простого входного файла с описаниями и мета-программирования.

test_foo.py:

import unittest
import twill
import twill.browser

twill.browser.OUT = file('/dev/null', 'w+')

queries = [
    'hepatospenomegaly',
    'Lymphadenopathy',
    'aneurysmorrhaphy',
    'electroneuromyography',
    'esophagogastroduodenoscopy',
    'meningoencephalomyelitis',
    'Pneumonoultramicroscopicsilico',
    'volcanoconiosis',
    'Pseudopseudohypoparathyroidism',
    'Floccinaucinihilipilification',
    'Honorificabilitudinitatibus']

class TestFoo(unittest.TestCase):
    def setUp(self):
        self.browser = twill.get_browser()

    def _ensure_it_was_query(self, query):
        content = self.browser.get_html()
        self.assert_(query in content)

for (i, query) in enumerate(queries*5):
    def test_query(self, query='%s_%i' % (query, i)):
        self.browser.go('http://localhost:8080/')
        f = self.browser.get_form(1)
        f['q'] = query
        self.browser.submit()

        self._ensure_it_was_query(query)

    setattr(TestFoo, 'test_query_%s_%i' % (query, i), test_query)

if __name__ == '__main__':
    unittest.main()

Все было бы хорошо, если бы не факт, что во время работы test_foo.py "утекает" память.

  PID COMMAND      %CPU   TIME   #TH #PRTS #MREGS RPRVT  RSHRD  RSIZE  VSIZE
 5369 Python       0.0%  0:18.10   1    27    415   25M  1360K    28M    52M

То есть от итерации к итерации количество занимаемых ресурсов увеличивается. В оригинальной ситуации тестов было несколько тысяч и все стало на столько плохо, что сервер пришлось перегружать (питоний процесс занял всю память и остальные процессы ушли в свап так глубоко, что мы не смогли дождаться установки ssh-соединения).

Первая попытка

Как только обнаружилась проблема был применен метод гениальной догадки™ и код

self.browser = twill.get_browser()

был заменен на

self.browser = twill.browser.TwillBrowser()

так как метод twill.get_browser() возвращал ссылку на один и тот же глобальный объект, что само по себе располагает к ошибкам такого рода.

Тем не менее памать продолжала накапливаться, а пул гениальных догадок кончился. (Потом станет ясно, что из характера изменения скорости накапливания памяти в первом и втором случае можно было сделать некие выводы относительно причин ее накопления.)

  PID COMMAND      %CPU   TIME   #TH #PRTS #MREGS RPRVT  RSHRD  RSIZE  VSIZE
 5480 Python       0.0%  0:18.38   1    27    244   24M  1360K    43M    59M

Модуль GC

Python замечателен тем, что предоставляет массу способов для рефлексии. Один из самых интересных способов предлагает модуль gc.

Этот модуль предоставляет такие интересные для нас возможности, как:

• получить список всех объектов в системе,
• получить список всех объектов, ссылающихся на заданный.

Стратегия его использования будет следующей: каждую итерацию/каждые несколько итераций мы будем делать слепок всех объектов в системе, а потом сравним их, чтобы понять какие объекты добавляются и не исчезают.

Функция, которая будет записывать состояние системы:

rcount = 0
def reflect():
    global rcount
    if rcount % 50 == 0:
        objs = gc.get_objects()
        pickle.dump(objs, file('dump_%.2i.dump' % (rcount/50), 'w+'))
    rcount += 1

Добавим ее в конец функции тестирования:

def test_query(self, query='%s_%i' % (query, i)):
    self.browser.go('http://localhost:8080/')
    f = self.browser.get_form(1)
    f['q'] = query
    self.browser.submit()

    self._ensure_it_was_query(query)
    reflect()

К сожалению, именно в такой формулировке reflect не работает:

TypeError: can't pickle module objects

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

rcount = 0
def reflect():
    global rcount
    if rcount % 50 == 0:
        counts = defaultdict(int)
        for obj in gc.get_objects():
            counts[type(obj).__name__] += 1

        pickle.dump(counts,
                    file('dump_%.2i.dump' % (rcount/50), 'w+'))
    rcount += 1

Полный исходный код test_foobar.py

На этот раз успешно получены два дампа, с которыми можно поработать. Запускаем IPython:

>>> import pickle
>>> d0 = pickle.load(file('dump_00.dump'))
>>> d0
defaultdict(<type 'int'>, {'Regex': 10, 'function': 2768,
'MemoryError': 1, 'set': 6, 'Group': 3, 'NotAny': 4, 'CodecInfo':
# ... еще много непонятного
>>> d1 = pickle.load(file('dump_01.dump'))
>>> d1
defaultdict(<type 'int'>, {'Regex': 10, 'function': 2798,
'MemoryError': 1, 'NavigableString': 169, 'Group': 3, 'NotAny': 4,
# ... и еще

Много и непонятно, попробуем поискать то что нам будет интересно:

>>> [(i, d1[i] - d0[i]) for i in d1 if d1[i] > d0[i]]
[('function', 150), ('NavigableString', 510), ('set', 300),
('member_descriptor', 22), ('method_descriptor', 1), ('instance',
3308), ('dict', 5182), ('_fileobject', 154), ('method-wrapper',
100), ('tuple', 276), ('SplitResult', 12), ('instancemethod',
804), ('TwillBrowser', 50), ('getset_descriptor', 15),
('builtin_function_or_method', 155), ('classobj', 50), ('list',
2836), ('weakref', 14), ('wrapper_descriptor', 131)]

Из этого списка нам пока не интересны классы типа set, list или weakref, так как они не являются самостоятельными и не занимают много ресурсов сами по себе. С другой стороны интереснее всего классы TwillBrowser и NavigableString. Поиск быстро показывает, что NavigableString растет из пакета mechanize - на нем основывается twill. Остается TwillBrowser, попробуем выяснить, почему их так много в памяти.

PDB

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

Вызовем pdb на 50-й итерации тестирования:

rcount = 0
def reflect():
    global rcount
    if rcount % 50 == 0:
        counts = defaultdict(int)
        for obj in gc.get_objects():
            counts[type(obj).__name__] += 1

        pickle.dump(counts,
                    file('dump_%.2i.dump' % (rcount/50), 'w+'))

    if rcount == 50:
        import pdb
        pdb.set_trace()

    rcount += 1

В результате, после запуска тестов мы попадем в интерактивную консоль:

elephantum-macbook:exception elephantum$ python test_foobar_pdb.py 
..................................................> 
/Users/elephantum/exception/test_foobar_pdb.py(39)reflect()
-> rcount += 1
(Pdb)

Найдем все объекты типа TwillBrowser на текущий момент в памяти.

(Pdb) objs = gc.get_objects()
(Pdb) typ = lambda t: lambda x, t=t: type(x).__name__ == t
(Pdb) bb = filter(typ('TwillBrowser'), objs)
(Pdb) len(bb)
52

Все объекты, которые ссылаются на любой из найденных браузеров:

(Pdb) ref = lambda l: gc.get_referrers(*l)
(Pdb) rr = ref(bb)
(Pdb) len(rr)
55
(Pdb) set(map(type, rr))
set([<type 'list'>, <type 'tuple'>, <type 'dict'>])

Не очень интересно. Попробуем пройтись дальше обратно по ссылкам.

(Pdb) rr_ = ref(rr)
(Pdb) set(map(type, rr_))
set([<type 'dict'>, <type 'list'>, <type 'function'>, <type
'tuple'>, <type 'module'>, <class '__main__.TestFoo'>])

Этот результат очевиден. На TwillBrowser ссылаются объекты класса TestFoo. Так написано в исходном коде test_foobar.py.

(Pdb) tt = filter(typ('TestFoo'), rr_)
(Pdb) len(tt)
51

А вот это уже интереснее. Почему-то объектов класса TestFoo гораздо больше чем мы могли ожидать. Интуитивно их должно быть не больше одного в каждый момент времени. Кто же их держит? Несколько итераций разыменования сделано в уме, вот интересный результат:

(Pdb) set(map(type, ref(ref(ref(tt)))))
set([<type 'dict'>, <type 'tuple'>, <type 'frame'>, <class
'unittest.TestSuite'>, <type 'list'>])

TestSuite. При чем в единственном экземпляре. Как же у него это получается?

(Pdb) len(filter(typ('TestSuite'), ref(ref(ref(tt)))))
1
(Pdb) ts = filter(typ('TestSuite'), ref(ref(ref(tt))))[0]
(Pdb) dir(ts)
['__call__', '__class__', '__delattr__', '__dict__', '__doc__',
'__getattribute__', '__hash__', '__init__', '__iter__',
'__module__', '__new__', '__reduce__', '__reduce_ex__',
'__repr__', '__setattr__', '__str__', '__weakref__', '_tests',
'addTest', 'addTests', 'countTestCases', 'debug', 'run']
(Pdb) ts._tests
[<__main__.TestFoo
testMethod=test_query_Floccinaucinihilipilification_20>,
<__main__.TestFoo
testMethod=test_query_Floccinaucinihilipilification_31>,
<__main__.TestFoo
testMethod=test_query_Floccinaucinihilipilification_42>,
# ...
(Pdb) len(ts._tests)
55

Итого

Оказывается, все это время мы пытались бороться с архитектурной особенностью модуля unittest. До начала тестирования создается набор объектов класса TestCase по количеству test*-методов в тесте, и ни один из не удаляется до окончания тестирования. Поэтому не сработал ход с локализацией TwillBrowser-а в TestCase-е. Для того чтобы браузер удалился должен удалиться TestCase, но этого не происходило в тот момент, когда мы ожидали.

Для того что бы убедиться, что эта гипотеза верна добавим метод tearDown в TestCase. Файл test_foobarbaz.py:

def tearDown(self):
    del self.browser

Действительно:

  PID COMMAND      %CPU   TIME   #TH #PRTS #MREGS RPRVT  RSHRD  RSIZE  VSIZE
 5676 Python       0.0%  0:18.32   1    27    165   13M  1400K    15M    30M

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

Выводы

Память не "утекает" в python просто так. Если в программе есть рост используемых ресурсов, то практически всегда это обозначает плохую архитектуру с необоснованно долгим сроком жизни каких либо объектов.

Python - динамический язык с богатыми возможностями для рефлексии, которые могут помогать в разных непростых ситуациях:

• gc - рефлексия по памяти в процессе исполнения, все объекты в этот момент, кто ссылается на этот объект,
• pdb - интерактивный дебаггер, который можно инициировать в любой момент из программного кода,
• pickle - способ сериализовать практически любую python-структуру и потом восстановить.