Перевод подготовлен в рамках онлайн-курса "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
