Как правильно использовать cProfile с асинхронным кодом?
Я пытаюсь определить, как правильно использовать cProfile и pstats с асинхронным кодом. Я профилирую свой сценарий, запустив cProfile.run('loop.run_until_complete(main())', 'profile.stats'),
После использования pstats сортировать по SortKeys.TIMEЯ получаю следующий вывод:
In [9]: sorted_stats.print_stats()
Fri Feb 15 14:40:18 2019 profile.txt
67411199 function calls (67230882 primitive calls) in 305.899 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
3617 273.162 0.076 273.162 0.076 {method 'poll' of 'select.epoll' objects}
14094092/14093931 1.527 0.000 1.904 0.000 {built-in method builtins.isinstance}
44901 1.166 0.000 1.166 0.000 {built-in method posix.stat}
784052 1.028 0.000 1.479 0.000 /usr/lib/python3/dist-packages/soupsieve/util.py:41(lower)
32070 0.887 0.000 1.565 0.000 /usr/lib/python3/dist-packages/bs4/element.py:620(<genexpr>)
4554545 0.729 0.000 0.756 0.000 /usr/lib/python3/dist-packages/bs4/element.py:1331(descendants)
1026560 0.726 0.000 3.358 0.000 /usr/lib/python3/dist-packages/bs4/element.py:1502(search)
448385 0.716 0.000 1.411 0.000 /usr/lib/python3/dist-packages/bs4/element.py:1528(_matches)
104 0.689 0.007 4.771 0.046 /usr/lib/python3/dist-packages/bs4/builder/_lxml.py:283(feed)
255143 0.655 0.000 1.575 0.000 /usr/lib/python3/dist-packages/bs4/__init__.py:391(endData)
137377 0.520 0.000 3.692 0.000 /usr/lib/python3/dist-packages/html5lib/_tokenizer.py:49(__iter__)
8574 0.510 0.000 2.392 0.000 /usr/lib/python3.7/traceback.py:318(extract)
167700 0.494 0.000 1.061 0.000 /usr/lib/python3/dist-packages/bleach/html5lib_shim.py:199(charsUntil)
53607 0.487 0.000 0.589 0.000 /usr/lib/python3/dist-packages/bs4/builder/__init__.py:158(_replace_cdata_list_attribute_values)
299357 0.485 0.000 0.485 0.000 /usr/lib/python3/dist-packages/bs4/element.py:258(setup)
22253 0.467 0.000 5.928 0.000 /usr/lib/python3/dist-packages/bs4/element.py:592(_find_all)
448385 0.437 0.000 2.225 0.000 /usr/lib/python3/dist-packages/bs4/element.py:1461(search_tag)
83147 0.424 0.000 2.365 0.000 /usr/lib/python3/dist-packages/bs4/builder/_lxml.py:176(start)
1293015 0.418 0.000 0.556 0.000 /usr/lib/python3/dist-packages/soupsieve/css_match.py:94(is_tag)
4824419 0.409 0.000 0.409 0.000 {method 'append' of 'list' objects}
73068 0.404 0.000 0.634 0.000 /home/jess/.local/lib/python3.7/site-packages/rfc3986/normalizers.py:127(encode_component)
868978 0.403 0.000 0.773 0.000 /usr/lib/python3/dist-packages/bleach/html5lib_shim.py:192(char)
454702 0.385 0.000 0.385 0.000 {method 'match' of 're.Pattern' objects}
2326981 0.374 0.000 0.415 0.000 {built-in method builtins.hasattr}
52 0.334 0.006 5.732 0.110 /usr/lib/python3/dist-packages/html5lib/html5parser.py:196(mainLoop)
... ... ... ... ... ...
Как вы можете видеть, почти все время выполнения отображается как {method 'poll' of 'select.epoll' objects},
У меня недостаточно опыта cProfile или же asyncio знать, как интерпретировать этот результат. Я не могу сказать, показывает ли статистика, что моя программа тратит большую часть времени выполнения в poll() потому что (а) cProfile не работает с asyncio и не дает правильную статистику, (б) это нормальное поведение, и я должен просто игнорировать первую строку или (в) это индикатор какой-то ошибки в моей программе (которая действительно ужасно медленная сейчас по причинам Я еще не определился) ...
Это нормально для асинхронных процессов тратить столько времени на выполнение poll()? Есть ли лучший способ профилировать асинхронный код с помощью cProfile или чего-то еще, что даст мне более точные результаты? Или это признак того, что в моем коде есть какая-то ошибка, вызывающая это?
ПРИМЕЧАНИЕ: для контекста код, который я профилировал, в основном выбирает 50 страниц, обрабатывает HTML, а затем выполняет некоторую обработку текста / языка. fetch() часть может объяснить большую часть времени в poll(), Но это при быстром интернет-соединении (> 5 МБ / с), поэтому я не думаю, что нужно тратить% времени на получение всего нескольких десятков text/html страницы. Кажется, что-то еще происходит, или статистика не верна...
1 ответ
TL;DR используйте лучшие инструменты
Я обнаружил, что более практично профилировать что-либо, когда оно воспроизводимо, потому что тогда любое изменение кода может быть подтверждено (если оно улучшает производительность или нет).
Если вы можете преобразовать свой код в тестовый пример, используя
pytest, то рассмотрите возможность использования https://pypi.org/project/pytest-profiling/ , его легко настроить, а визуальный вывод [относительно] легко понять.
Другой вариант - использовать статистический профилировщик , например https://pypi.org/project/pprofile/
Еще один вариант, если вам нравится профилирование в производственной среде, - это использовать службу, например https://docs.datadoghq.com/tracing/profiler/.
Наконец, четко определите, что вы измеряете .
Профилировщик Most / many позволяет собирать как время настенных часов, так и время использования процессора.
Наивный
asyncioПрограмма является однопоточной и при достаточном количестве ресурсов ЦП находится в одном из двух состояний в любой момент времени: либо перерабатывает , либо ожидает . Если ваша «проблема» слишком сложна, то ответом будет профилировщик, и часто время процессора и время стены примерно одинаковы. Если «проблема» на самом деле ждет, то вы, вероятно, захотите посмотреть, «кто чего ждет». Бесстыдный плагин: используйте мой https://pypi.org/project/awaitwhat/ для Python 3.7~3.9.