Профилирование и отладка Python, инструменты

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

Сегодня мы познакомимся с основной и самой многочисленной группой инструментов — событийными профайлерами.

— зачем вообще нужно профилирование, различные подходы, инструменты и отличия между ними — переходим к практике
• Событийное профилирование — инструменты и их применение — что делать, когда ничего не работает

Задача для тренировки

Помним, что код не идеален, и многие вещи можно сделать проще, лучше, быстрее. Именно в этом заключается цель данной статьи =)

В прошлой статье я оконфузился и не сделал самого важного: тестов. На самом деле поломать программу в процессе рефакторинга или оптимизации легче простого, и каждый цикл профилирования и переписывания кода должен в обязательном порядке сопровождаться тестированием функционала (как непосредственно затронутого изменениями, так и всего остального, ведь сайд-эффекты такие сайд-эффекты). Попробуем исправиться и добавим тесты в нашу программу. Самый простой и подходящий для такого простого скрипта вариант — использовать модуль doctest. Добавляем тесты и запускаем их:

Давайте посмотрим, насколько быстрый у нас получился код:

Да, небыстро, есть что пооптимизировать =)

Инструменты

• cProfile — относительно новый (с версии 2.5) модуль, написанный на C и оттого быстрый
• profile — нативная реализация профайлера (написан на чистом питоне), медленный, и поэтому не рекомендуется к использованию
• hotshot — экспериментальный модуль на си, очень быстрый, но больше не поддерживается и в любой момент может быть удалён из стандартных библиотек

Какой разговор о профилировании питона обходится без описания cProfile — одного из стандартных модулей Python? Уверен, каждый программист Python хоть раз пробовал запустить cProfile:

Сразу заметим разницу во времени выполнения программы: без профайлера: 1.27 секунды, с профайлером: 1.55 секунд, то есть на 20% медленнее в нашем конкретном случае. И это ещё очень хороший результат!

Итак, мы видим, что самая долгая (по суммарному времени) операция — функция is_prime. Практически всё время программа проводит в этой функции. Следующий по «тяжести» вызов — функция range, которая как раз вызывается из функции is_prime. Читаем документацию и понимаем, что при вызове range в памяти создаётся список со всеми числами из заданного диапазона. С учётом того, что функция range вызывается 104741 раз, а верхняя граница диапазона при каждом вызове инкрементируется (перебираем числа последовательно), можно сделать вывод, что длина списка, создаваемого функцией range достигает сотни тысяч элементов к концу работы программы и список создаётся больше ста тысяч раз. Почитав ещё документацию мы узнаём, что нам следует использовать функцию xrange в этом цикле (внимательный читатель должен почувствовать сарказм в этом месте, ведь любой питонист знает про range VS xrange). Плюсом замены range на xrange будет так же явная экономия памяти (эту теорию мы проверим позже). Заменяем, запускаем тесты: всё ок, запускаем профайлер:

1.010 секунды вместо 1.552, то есть в полтора раза быстрее! Нормально. Теперь самое узкое место в программе — функция is_prime сама по себе. Оптимизируем её позже, с использованием других инструментов.

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

или можно воспользоваться простейшим декоратором:

И тогда при каждом вызове функции foo будет сохранён файл с результатами профилирования («get_prime_numbers.prof» в нашем случае).

hotshot — ещё один стандартный модуль Python, на данный момент не поддерживается и в любое время может быть удалён из стандартных библиотек. Но пока он есть, можно использовать его, ведь он очень быстрый и даёт минимальный оверхед при запуске программы под профайлером. Использовать его очень просто:

Или в виде декоратора:

Анализ результатов профилирования

Редко когда получается вывести результаты профилирования на экран сразу после запуска программы. Да и смысла в таких результатах немного: только простейшие скрипты и удастся изучить. Для просмотра и анализа данных лучше воспользоваться встроенным в Python модулем pstats (удобнее в сочетании с замечательной консолью iPython):

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

Начну, пожалуй, с такого известного инструмента, как kcachegrind, который, на самом деле, предназначен для визуализации результатов утилиты Callgrind, но переконвертировав результаты Python-профалера, их можно открыть в kcachegrind. Конвертирование выполняется с помощью утилиты pyprof2calltree:

Можно сразу открыть результаты в kcachegrind, без сохранения в файл:

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

Ещё одна программа для визуализации результатов профайлинга RunSnakeRun была изначально написана для работы с профайлером питона (это видно из её названия). Похожа на kcachegrind, но, как говорят авторы, выгодно отличается более простым интерфейсом и функционалом. Установка не вызовет сложностей:

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

RunSnakeRun позволяет так же визуализировать результат профилирования потребления памяти с помощью утилиты Meliae:

Утилита gprof2dot генерирует картинку с деревом вызовов функций и информацией о времени их выполнения. В большинстве случаев этого достаточно для поиска узких мест в программе. Ставим и генерируем картинку:

Профилирование Django

Для профилирования Django удобно использовать модуль django-extensions, который, помимо кучи разных полезных вещей, имеет полезную команду «runprofileserver». Использовать его просто. Ставим:

Добавляем application в settings.py:

В директории /tmp/prof/ будет создан файл с результатами профилирования для каждого запроса в приложение:

Дальнейший анализ можно выполнить с помощью любого из инструментов, перечисленных выше: pstats, kcachegrind, RunSnakeRun или gprof2dot. Или любого другого =)

Помимо встроенного в Python профайлера имеется так же масса сторонних программ, простых и сложных, полезных и не очень.

pycallgraph

pycallgraph позволяет строить дерево вызовов программы Python. Ставим:

Запускаем и смотрим результат:

line_profiler

line_profiler, как следует из его названия, позволяет построчно отпрофилировать нужные участки кода. Ставим:

Добавляем в нужные места декоратор «profile» (я временно убрал докстринги для более компактного вывода результатов):

Сразу замечаем огромный оверхед: программа выполнялась больше 30 секунд, при том, что без профайлера она отрабатывает быстрее, чем за секунду.

Анализируя результаты можно сделать вывод, что наибольшее время программа тратит в строках 9 и 10, проверяя делители числа для определения его «простоты». И для каждого последующего числа происходят все те же самые проверки. Логичной оптимизацией программы является проверка в качестве делителей только тех чисел, которые ранее были определены как простые:

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

Ускорили работу почти в три раза, неплохо. Запустим ещё разок профилирование:

Как видим, программа стала выполняться гораздо быстрее.

memory_profiler

Для профилирования памяти можно использовать memory_profiler. Использовать его так же просто, как line_profiler. Ставим:

Как видим, никаких особых проблем с памятью у нас нет. Всё в пределах нормы.

Ещё инструменты

— отличнейший инструмент для профилирования памяти — ещё одна программа для профилирования памяти — уже упоминавшийся ранее инструмент для профилирования памяти, которую можно использовать вместе с RunSnakeRun — обнаружение утечек памяти — снова профилирование памяти — интересный инструмент для исследования объектов

Мы познакомились с инструментами для профилирования кода на Python. Множество из них осталось за кадром, надеюсь, мои коллеги дополнят меня в комментариях.

В следующей статье мы познакомимся с методами и инструментами для отладки Python-программ. Оставайтесь на связи!

Минутка статистики: в трёх статьях про профилирование питона я использовал слово «профилирование» больше ста раз.