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