Автор оригинала: Narendra Kumar Vadapalli.
Оригинальный пост : https://www.narenvadapalli.com/blog/profiling-visualization-tools-in-python-part-1/
Что в моем коде python занимает время ?
Звучит как знакомый вопрос!
Ну, у меня этот вопрос всплывает довольно часто, особенно когда я имею дело с устаревшими кодовыми базами и незнакомым кодом. Это моя попытка помочь пролить свет на поиск ответа на этот вопрос
Установка
Рассмотрим следующий простой фрагмент кода в файле с именем test.py
def print_method():
print("hello world")
def test_print_method():
for i in xrange(2):
print_method()
for i in range(3):
test_print_method()
Когда вы выполняете код с помощью python executable, следующий вывод hello world печатается 6 раз
$ python test.py hello world hello world hello world hello world hello world hello world
Параметры зондирования
Давайте рассмотрим различные инструменты, которые мы могли бы использовать для определения
- Кодовый путь
- Количество звонков и
- Какой метод занял больше всего времени !
Оговорка
Этот блог был создан после выполнения команд в дистрибутиве Linux. Если на другой платформе, я предполагаю, что кто-то знает, как добраться до необходимых (или подобных) программных пакетов
Основа для профилирования
Мы в основном полагаемся на profile module, более конкретно cProfile module для генерации данных, необходимых для различных инструментов визуализации. ( https://docs.python.org/2/library/profile.html#module-profile ) Самый простой способ запустить cProfile в коде python-это запустить его как модуль с исполняемым файлом python , передав фактический скрипт в качестве аргумента cProfile
Пример
python -m cProfile test.py
Наряду с ожидаемым выводом строк hello world мы видим дополнительную информацию о времени ,затраченном на выполнение каждого метода.
$ python -m cProfile test.py
hello world
hello world
hello world
hello world
hello world
hello world
12 function calls in 0.000 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.000 0.000 test.py:1()
6 0.000 0.000 0.000 0.000 test.py:1(print_method)
3 0.000 0.000 0.000 0.000 test.py:5(test_print_method)
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
1 0.000 0.000 0.000 0.000 {range}
Выход может быть не очень удобоваримым мгновенно на первый взгляд. Давайте погрузимся в различные доступные инструменты визуализации, которые могут сделать информацию о времени более воспринимаемой.
Картинка стоит тысячи слов
gprof2dot
Мой любимый из всех доступных инструментов – gprof2dot https://github.com/jrfonseca/gprof2dot
Установите gprof2dot
pip install gprof2dot --user
Сгенерировать файл .pstats
Выполните команду test.py на этот раз сценарий с информацией о времени направляется во внешний выходной файл, а не в стандартный консольный вывод. Обратите внимание на флаг -o с выходным именем файла test.pstats
python -m cProfile -o test.pstats test.py
Визуализация информации профилирования
Предполагая, что у вас установлены dot и eog , выполните следующую команду в терминале, где находится выходной файл профилирования test.pstats
gprof2dot -f pstats test.pstats | dot -Tpng -o output.png && eog output.png
Бинго, вы получаете окно, которое показывает что-то вроде следующего
Анализ
Приведенный выше график показывает , что 91,67% было потрачено в test_print_method и один и тот же метод был вызван 3 раза ( 3x ), который, в свою очередь, вызывает print_method (в целом 6 раз).
Другие вызовы методов, такие как range , – это крошечное количество общего времени выполнения, но оно также видно на графике
Это был простой код на python. Этот метод одинаково хорошо работает со сложным кодом. Вставка образца изображения из gprof2dot github repo
Змеевиз
SnakeViz – это инструмент визуализации на основе браузера. Ему нужен вывод в формате .profile , а не .stats , когда вывод профилирования генерируется с помощью модуля cProfile
Установите snakeviz
pip install snakeviz --user
Сгенерировать файл .profile
Выполните команду test.py скрипт на этот раз с информацией о времени перенаправляется с помощью флага -o в выходной файл с именем test.profile
python -m cProfile -o test.profile test.py
Визуализация информации профилирования
Выполните следующую команду в терминале, где находится выходной файл профилирования test.profile
snakeviz test.profile
Анализ
При выполнении команды в консоли будет напечатана некоторая информация и появится новое окно, которое появится в сеансе браузера
$ snakeviz test.profile snakeviz web server started on 127.0.0.1:8080; enter Ctrl-C to exit http://127.0.0.1:8080/snakeviz/%2Ftmp%2Ftest.profile START /usr/bin/google-chrome-stable "http://127.0.0.1:8080/snakeviz/%2Ftmp%2Ftest.profile" Opening in existing browser session. WARNING:tornado.access:404 GET /images/sort_both.png (127.0.0.1) 1.04ms WARNING:tornado.access:404 GET /images/sort_desc.png (127.0.0.1) 0.49ms
PyCallGraph
Это, кажется, заброшенный проект, но эй ! все еще работает.
Установить pycallgraph
pip install pycallgraph --user
Создание файла визуализации png
Выполните скрипт с помощью pycallgraph executable, а не через python executable.
Оговорка
В следующих примерах указывается graphviz в качестве выводимого, поэтому он должен быть установлен
pycallgraph graphviz -- ./test.py
Визуализация информации профилирования
Приведенная выше команда генерирует изображение pycallgraph.png . Откройте изображение с помощью любого средства просмотра изображений. Использование eog в качестве примера на моем хосте
$ eog pycallgraph.png
Показывает информацию о времени и количестве звонков.
Вывод
Я все еще верю, что gprof2dot лучше справляется с выдачей % и глаз естественно отслеживает поток на графике гораздо проще, чем другие методы визуализации.