Режим мачете: теги для фреймов

Перевод подготовлен в рамках онлайн-курса «Python Developer. Professional«.

Также приглашаем всех желающих на открытый демо-урок «Что нового в Python 3.10». На этом вебинаре мы поговорим о том, какие самые важные PEPы включены в ближайший релиз Python 3.10. В частности о том, как изменится работа с типами.

Сегодня мне пришлось разгадывать загадку выполнения кода на Python, и воспользовался фокусом с отладкой в режиме мачете, чтобы понять, в чем дело. Если раньше вы никогда не слышали этот термин, то поясню, режим «мачете» — это когда вы используете грубый временный код для получения информации любым способом. 

Вот как это было. Я добавил новый параметризованный тест к тестовому набору coverage.py. Работало все очень медленно, поэтому я запустил его с отображением таймингов:

Что ж, странно: два теста вызываются, но вызываются еще и четыре вызова моей функции настройки теста и четыре для прерывания. Я только недавно преобразовал этот набор из unittest.TestCase, и у меня есть несколько странных «прокладок» для уменьшения оттока кода. Думая о повторной настройке, я подумал о том, что либо мои прокладки были какими-то не такими, либо я наткнулся на краевой сценарий того, как pytest запускает тесты.

Но как понять, почему настройка вызывается дважды при каждом запуске теста? Я решил воспользоваться инструментом, к которому часто обращался в прошлом и записать куда-нибудь информацию, полученную из стека.

def setup_test(self):     import inspect     project_home = "/Users/ned/coverage"     site_packages = ".tox/py39/lib/python3.9/site-packages/"     with open("/tmp/foo.txt", "a") as foo:         print("setup_test", file=foo)         for t in inspect.stack()[::-1]:             # t is (frame, filename, lineno, function, code_context, index)             frame, filename, lineno, function = t[:4]             filename = os.path.relpath(filename, project_home)             filename = filename.replace(site_packages, "")             show = "%30s : %s:%d" % (function, filename, lineno)             print(show, file=foo)

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

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

setup_test                       <module> : igor.py:424                           main : igor.py:416            do_test_with_tracer : igor.py:216                      run_tests : igor.py:133                           main : _pytest/config/__init__.py:84                       __call__ : pluggy/hooks.py:286                      _hookexec : pluggy/manager.py:93                       <lambda> : pluggy/manager.py:84                     _multicall : pluggy/callers.py:187            pytest_cmdline_main : _pytest/main.py:243                   wrap_session : _pytest/main.py:206                          _main : _pytest/main.py:250                       __call__ : pluggy/hooks.py:286                      _hookexec : pluggy/manager.py:93                       <lambda> : pluggy/manager.py:84                     _multicall : pluggy/callers.py:187             pytest_runtestloop : _pytest/main.py:271                       __call__ : pluggy/hooks.py:286                      _hookexec : pluggy/manager.py:93                       <lambda> : pluggy/manager.py:84                     _multicall : pluggy/callers.py:187        pytest_runtest_protocol : flaky/flaky_pytest_plugin.py:94        pytest_runtest_protocol : _pytest/runner.py:78                runtestprotocol : _pytest/runner.py:87                call_and_report : flaky/flaky_pytest_plugin.py:138              call_runtest_hook : _pytest/runner.py:197                      from_call : _pytest/runner.py:226                       <lambda> : _pytest/runner.py:198                       __call__ : pluggy/hooks.py:286                      _hookexec : pluggy/manager.py:93                       <lambda> : pluggy/manager.py:84                     _multicall : pluggy/callers.py:187           pytest_runtest_setup : _pytest/runner.py:116                        prepare : _pytest/runner.py:362                          setup : _pytest/python.py:1468                   fillfixtures : _pytest/fixtures.py:296                  _fillfixtures : _pytest/fixtures.py:469                getfixturevalue : _pytest/fixtures.py:479         _get_active_fixturedef : _pytest/fixtures.py:502         _compute_fixture_value : _pytest/fixtures.py:587                        execute : _pytest/fixtures.py:894                       __call__ : pluggy/hooks.py:286                      _hookexec : pluggy/manager.py:93                       <lambda> : pluggy/manager.py:84                     _multicall : pluggy/callers.py:187           pytest_fixture_setup : _pytest/fixtures.py:936              call_fixture_func : _pytest/fixtures.py:795              connect_to_pytest : tests/mixins.py:33                     setup_test : tests/test_process.py:1651

Я надеялся, что для первого и второго вызовов будут немного разные трассировки, и эта разница даст мне подсказку. Поскольку в стеке все идентично, то дело должно быть в циклах. Но как достать их из стека?

Будь я знаком с кодом, о котором идет речь, одна трассировка могла бы указать на нужно место. Но pytest для меня не прозрачный, и я не хотел начинать копаться в нем. У меня несколько функций pytest, так что, похоже, дело сложное.

Трассировки стека были одинаковыми, поскольку они показывают только статические аспекты вызовов: кто что вызывает и откуда. Но для конкретных экземпляров вызовов функции стеки различаются. Самый верхний кадр один и тот же (одно выполнение основной программы), а самый нижний кадр варьируется (четыре выполнения функции настройки теста). Если мы найдем самый верхний кадр, который отличается от стека к стеку, то узнаем, какой цикл дважды вызывает функцию настройки.

Первым, что пришло мне в голову, было выводить id объекта фрейма, но id переиспользуются, поскольку сами объекты переиспользуются из списков свободной памяти. Вместо этого, почему бы не назначить им теги? У каждого фрейма есть свой набор локальных переменных, который хранится в словаре, привязанном к фрейму.  В каждый кадр я пишу целое число, то есть то количество раз, сколько мы видели этот кадр.

Теперь цикл по кадрам будет проверять локальные переменные каждого фрейма. Если наших посещений нет, то они инициализируется нулем, а если есть, то увеличиваются на единицу. Количество посещений добавляется к отображению стека, и мы можем работать:

def setup_test(self):     import inspect     project_home = "/Users/ned/coverage"     site_packages = ".tox/py39/lib/python3.9/site-packages/"     with open("/tmp/foo.txt", "a") as foo:         print("setup_test", file=foo)         for t in inspect.stack()[::-1]:             # t is (frame, filename, lineno, function, code_context, index)             frame, filename, lineno, function = t[:4]             visits = frame.f_locals.get("$visits", 0)       ## new             frame.f_locals["$visits"] = visits + 1          ## new             filename = os.path.relpath(filename, project_home)             filename = filename.replace(site_packages, "")             show = "%30s :  %d  %s:%d" % (function, visits, filename, lineno)             print(show, file=foo)

Теперь стеки все еще одинаковые, но количество посещений различается. Вот стек второго вызова настройки теста:

setup_test                       <module> :  1  igor.py:424                           main :  1  igor.py:416            do_test_with_tracer :  1  igor.py:216                      run_tests :  1  igor.py:133                           main :  1  _pytest/config/__init__.py:84                       __call__ :  1  pluggy/hooks.py:286                      _hookexec :  1  pluggy/manager.py:93                       <lambda> :  1  pluggy/manager.py:84                     _multicall :  1  pluggy/callers.py:187            pytest_cmdline_main :  1  _pytest/main.py:243                   wrap_session :  1  _pytest/main.py:206                          _main :  1  _pytest/main.py:250                       __call__ :  1  pluggy/hooks.py:286                      _hookexec :  1  pluggy/manager.py:93                       <lambda> :  1  pluggy/manager.py:84                     _multicall :  1  pluggy/callers.py:187             pytest_runtestloop :  1  _pytest/main.py:271                       __call__ :  1  pluggy/hooks.py:286                      _hookexec :  1  pluggy/manager.py:93                       <lambda> :  1  pluggy/manager.py:84                     _multicall :  1  pluggy/callers.py:187        pytest_runtest_protocol :  1  flaky/flaky_pytest_plugin.py:94        pytest_runtest_protocol :  0  _pytest/runner.py:78                runtestprotocol :  0  _pytest/runner.py:87                call_and_report :  0  flaky/flaky_pytest_plugin.py:138              call_runtest_hook :  0  _pytest/runner.py:197                      from_call :  0  _pytest/runner.py:226                       <lambda> :  0  _pytest/runner.py:198                       __call__ :  0  pluggy/hooks.py:286                      _hookexec :  0  pluggy/manager.py:93                       <lambda> :  0  pluggy/manager.py:84                     _multicall :  0  pluggy/callers.py:187           pytest_runtest_setup :  0  _pytest/runner.py:116                        prepare :  0  _pytest/runner.py:362                          setup :  0  _pytest/python.py:1468                   fillfixtures :  0  _pytest/fixtures.py:296                  _fillfixtures :  0  _pytest/fixtures.py:469                getfixturevalue :  0  _pytest/fixtures.py:479         _get_active_fixturedef :  0  _pytest/fixtures.py:502         _compute_fixture_value :  0  _pytest/fixtures.py:587                        execute :  0  _pytest/fixtures.py:894                       __call__ :  0  pluggy/hooks.py:286                      _hookexec :  0  pluggy/manager.py:93                       <lambda> :  0  pluggy/manager.py:84                     _multicall :  0  pluggy/callers.py:187           pytest_fixture_setup :  0  _pytest/fixtures.py:936              call_fixture_func :  0  _pytest/fixtures.py:795              connect_to_pytest :  0  tests/mixins.py:33                     setup_test :  0  tests/test_process.py:1651

Единицы – это кадры, которые не менялись от первого ко второму вызову, а нули – новые кадры. И теперь мы видим, что в flaky_pytest_plugin.py есть цикл, который второй раз вызывает настройку. 

Стандартная ситуация: как только вы находите ответ, все становится очевидно. Я использую плагин pytest-flaky для автоматического повторения тестов, которые завершаются неудачно. Мой новый медленный тест не просто медленный, он еще и не проходит (на текущий момент), поэтому pytest-flaky запускает его еще раз.

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

Когда тест завершился успешно, выполнение по два раза исчезло, поскольку pytest-flaky не запускал его заново.

Вот вам и классическая история отладки в режиме мачете, то есть проблемы было легче отловить с помощью динамических инструментов, а не статических. Я сломал какой-то грубый код, чтобы получить нужную информацию, не зная, сработает ли это, но оно сработало.

Кстати, в отображение этот столбец может быть и глупо ставить, но это простой способ увидеть циклическую природу выполнения тестов. Вот вам четвертый стек вызовов:

setup_test                       <module> :  3  igor.py:424                           main :  3  igor.py:416            do_test_with_tracer :  3  igor.py:216                      run_tests :  3  igor.py:133                           main :  3  _pytest/config/__init__.py:84                       __call__ :  3  pluggy/hooks.py:286                      _hookexec :  3  pluggy/manager.py:93                       <lambda> :  3  pluggy/manager.py:84                     _multicall :  3  pluggy/callers.py:187            pytest_cmdline_main :  3  _pytest/main.py:243                   wrap_session :  3  _pytest/main.py:206                          _main :  3  _pytest/main.py:250                       __call__ :  3  pluggy/hooks.py:286                      _hookexec :  3  pluggy/manager.py:93                       <lambda> :  3  pluggy/manager.py:84                     _multicall :  3  pluggy/callers.py:187             pytest_runtestloop :  3  _pytest/main.py:271                       __call__ :  1  pluggy/hooks.py:286                      _hookexec :  1  pluggy/manager.py:93                       <lambda> :  1  pluggy/manager.py:84                     _multicall :  1  pluggy/callers.py:187        pytest_runtest_protocol :  1  flaky/flaky_pytest_plugin.py:94        pytest_runtest_protocol :  0  _pytest/runner.py:78                runtestprotocol :  0  _pytest/runner.py:87                call_and_report :  0  flaky/flaky_pytest_plugin.py:138              call_runtest_hook :  0  _pytest/runner.py:197                      from_call :  0  _pytest/runner.py:226                       <lambda> :  0  _pytest/runner.py:198                       __call__ :  0  pluggy/hooks.py:286                      _hookexec :  0  pluggy/manager.py:93                       <lambda> :  0  pluggy/manager.py:84                     _multicall :  0  pluggy/callers.py:187           pytest_runtest_setup :  0  _pytest/runner.py:116                        prepare :  0  _pytest/runner.py:362                          setup :  0  _pytest/python.py:1468                   fillfixtures :  0  _pytest/fixtures.py:296                  _fillfixtures :  0  _pytest/fixtures.py:469                getfixturevalue :  0  _pytest/fixtures.py:479         _get_active_fixturedef :  0  _pytest/fixtures.py:502         _compute_fixture_value :  0  _pytest/fixtures.py:587                        execute :  0  _pytest/fixtures.py:894                       __call__ :  0  pluggy/hooks.py:286                      _hookexec :  0  pluggy/manager.py:93                       <lambda> :  0  pluggy/manager.py:84                     _multicall :  0  pluggy/callers.py:187           pytest_fixture_setup :  0  _pytest/fixtures.py:936              call_fixture_func :  0  _pytest/fixtures.py:795              connect_to_pytest :  0  tests/mixins.py:33                     setup_test :  0  tests/test_process.py:1651

Тройки меняются на единицы в _pytest/main.py:271, то есть в цикле выполнения тестов, и это круто!

Узнать подробнее о курсе «Python Developer. Professional«

Смотреть вебинар «Что нового в Python 3.10»