В этой статье мы рассмотрим различные профилировщики (cProfile, Pyinstrument, Eliot) и обсудим их плюсы и минусы, а также когда и где их лучше применить.

Данная статья является переводом. Ссылка на оригинал.

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

Что вы сделаете для ускорения работы программы?

Вы, вероятно, сделаете следующее:

1. Выберите подходящий инструмент (программное средство) для измерения скорости.

2. Используете инструмент для поиска «узкого места».

3. Устраните «узкое место».

В этой статье основное внимание будет уделено первому шагу: выбору правильного инструмента. И, в частности, он будет включать в себя:

• cProfile: детерминированный профайлер стандартной библиотеки Python.
• Pyinstrument: профилировщик выборки.
• Eliot: библиотека логирования.

Я не буду вдаваться в подробности о том, как использовать эти инструменты, потому что задача состоит в том, чтобы помочь вам выбрать правильный. Но я объясню, что делают эти инструменты, а также когда и почему нужно выбрать тот или иной.

Больше полезных материалов вы найдете на нашем телеграм-канале «Библиотека питониста» Интересно, перейти к каналу

1. cProfile: Детерминированный профайлер

Профилировщик cProfile встроен в Python, поэтому вы, вероятно, слышали о нем, и, возможно, это тот инструмент, который вы используете по умолчанию. Он работает, отслеживая каждый вызов функции в программе. Вот почему это детерминированный профилировщик: если вы запустите его с теми же входными данными, он даст тот же результат.

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

Хотя cProfile доступен по умолчанию в Python, у него также есть некоторые недостатки — и, как вы увидите чуть позже, вы вряд ли захотите его использовать для большинства случаев.

Использование cProfile

Использовать cProfile довольно просто. Если у вас есть скрипт, то, скорее всего, вы запустите его так:

1

         $ python benchmark.py 7855 messages/sec     

Затем вы можете просто добавить префикс python -m cProfile и запустить его с профилировщиком:

2

         $ python -m cProfile benchmark.py 1444992 function calls (1443814 primitive calls) in 1.208 seconds  Ordered by: cumulative time  ncalls  tottime  percall  cumtime  percall filename:lineno(function)      1    0.000    0.000    1.208    1.208 benchmark.py:7(<module>)      1    0.048    0.048    1.151    1.151 benchmark.py:21(run)  50000    0.031    0.000    0.657    0.000 _output.py:182(write)  50000    0.045    0.000    0.618    0.000 _output.py:73(send)  50000    0.064    0.000    0.566    0.000 _output.py:452(__call__) ... a million more lines of output ...     

Существует также профилирование для Python API, поэтому вы можете профилировать определенные функции в запросе интерпретатора Python или в Jupyter notebook.

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

Что cProfile может вам сказать

Если вы посмотрите на таблицу выше, то увидите, что:

• _output.py(__call__) вызвали 50 000 раз. У нас получилось четное число, потому что это тестовый скрипт, который запускает один и тот же код в цикле 10 000 раз. Если вы не вызывали функцию намеренно множество раз, то это может быть полезно для определения большого количества вызовов для выявления занятых внутренних циклов.
• _output.py(send) работал в течение 0.618 секунд (включая время, затраченное на вызываемые им функции) и 0.045 секунд (не считая вызываемых им функций).

Используя эту информацию, вы можете определить медленные функции, которые можно оптимизировать.

Как это работает

cProfile проводит измерение для каждого вызова функции. В частности, вызов функции во время ее выполнения выглядит следующим образом:

         start = time() try:     f() finally:     elapsed = time() - start     

Профилировщик записывает время в начале и в конце. Полученная разница является временем работы функции.

Проблемы с cProfile

Хотя cProfile всегда доступен при любой установке Python, он также имеет ряд существенных проблем.

Проблема №1: Высокие затраты вычислительных ресурсов и искаженные результаты

Как вы понимаете, выполнение дополнительной работы для каждого вызова функции требует определенных затрат:

4

         $ python benchmark.py 7855 messages/sec  $ python -m cProfile benchmark.py 5264 messages/sec ... cProfile output ...     

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

Проблема №2: Слишком много информации

Если вы помните, выходные данные cProfile, которые мы видели выше, содержат строку для каждой отдельной функции, которая была вызвана во время выполнения программы. Большинство данных вызовов функций не имеют отношения к нашей проблеме с производительностью: они выполняются быстро и только один или два раза.

Поэтому, когда вы читаете выходные данные cProfile, вы имеете дело с большим количеством шума, который мешает распознать сигнал.

Проблема № 3: Измерение результатов работы на локальном компьютере

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

Но cProfile, как мы видели, немного замедляет вашу программу, и поэтому вы, вероятно, не захотите запускать его в своем рабочем проекте. Таким образом, в то время как низкая скорость работы появляется только при работе с реальными проектами, cProfile может быть полезен только на стадии разработки.

Проблема № 4: Производительность измеряется только для функций

cProfile может сообщить вам о том, что «slowfunc() работает медленно», когда он усредняет все входные данные для этой функции. И это нормально, если функция сама по себе всегда медленная.

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

• slowfunc(100) выполняется быстро.
• slowfunc(0) выполняется медленно.

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

cProfile: Его, как правило, недостаточно

Обобщая все недостатки, cProfile не должен быть вашим предпочтительным инструментом для повышения производительности. Поэтому далее мы поговорим о его двух альтернативах:

• Pyinstrument решает проблемы №1 и №2.
• Eliot решает проблемы №3 и №4.

2. Pyinstrument: Профилировщик выборки

Pyinstrument решает две проблемы, которые мы рассмотрели выше, а именно:

• Затраты вычислительных ресурсов меньше, чем у cProfile, при этом результаты не искажаются.
• Он отфильтровывает ненужные вызовы функций, поэтому шума становится меньше.

Pyinstrument измеряет системное время, а не процессорное, поэтому он также может фиксировать замедление, вызванное сетевыми запросами, записью на диск, конфликтом блокировок и т. д.

Как вы можете его использовать

Использование Pyinstrument аналогично cProfile — просто добавьте префикс к вашему скрипту:

7

         $ python benchmark.py 7561 messages/sec  $ python -m pyinstrument benchmark.py 6760 messages/sec ... pyinstrument output ...     

Обратите внимание, что у него есть некоторые накладные расходы, но не такие большие, как у cProfile, при этом затраты вычислительных ресурсов распределены равномерно.

Pyinstrument также поддерживает API Python, так что вы можете использовать его для профилирования определенных фрагментов кода в интерактивном интерпретаторе Python или блокноте Jupyter.

Выходные данные

На выходе Pyinstrument представляет собой дерево вызовов, измеряющее системное время:

8

         1.506 <module>  benchmark.py:7 ├─ 1.477 run  benchmark.py:21 │  ├─ 0.604 attach  myapp/_code.py:52 │  │  └─ 0.598 write  myapp/_code.py:130 │  │     ├─ 0.557 final_write  myapp/_foo.py:181 ...     

В отличие от построчной функции cProfile, Pyinstrument дает вам дерево вызовов функций, поэтому вы можете получить информацию о скорости работы. Функция может появляться несколько раз, если низкая скорость работы вызвана несколькими путями выполнения кода.

В результате вывод Pyinstrument намного проще интерпретировать, ведь он предоставляет более подробное понимание структуры производительности вашей программы, чем вывод cProfile по умолчанию.

Как это работает (кошачья версия)

Представьте, что у вас есть кошка. Вы хотите знать, как эта кошка проводит свое время.

Вы могли бы непрерывно шпионить за ней, но это был бы весьма трудоемкий процесс. Поэтому вместо этого вы решаете периодически делать «замеры»: каждые 5 минут вы заглядываете в комнату, где находится кошка, и записываете, что она делает.

Например:

• 12:00: Спит 💤
• 12:05: Спит 💤
• 12:10: Ест 🍲
• 12:15: Использует лоток 💩
• 12:20: Спит 💤
• 12:25: Спит 💤
• 12:30: Спит 💤

Через несколько дней можно подвести итоги своих наблюдений:

• 80%: Спит 💤
• 10%: Ест 🍲
• 9%: Использует лоток 💩
• 1%: С тоской смотрит в окно на птиц 🐦

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

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

Как это работает (программная версия)

Как и наш кот, Pyinstrument периодически наблюдает за поведением Python-программы: каждую 1 мс он проверяет, какая функция запущена в данный момент. Это означает:

• Если функция кумулятивно медленная, она будет появляться часто.
• Если функция кумулятивно быстрая, мы, как правило, ее вообще не увидим.

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

3. Eliot: Библиотека логирования

Последним инструментом, который мы подробно рассмотрим, является Eliot, написанная мной библиотека логирования. Она решает оставшиеся две проблемы, которые мы видели в cProfile:

• Логирование можно использовать в продакшене.
• Логирование может записывать аргументы для функций.

Как вы видите, Eliot предоставляет некоторые уникальные возможности, которые делают лучше его запись производительности, чем у обычных библиотек логирования. При этом, проделав некоторую дополнительную работу, вы можете получить те же преимущества и от других библиотек ведения логов.

Добавление логирования в существующий код

Рассмотрим следующий набросок программы:

8

         def add(a, b):     # ... implementation ...      def multiply(a, b):     # ... implementation ...  def multiplysum(a, b, c):     return multiply(add(a, b), c)  print(multiplysum(1, 2, 4))     

Мы можем взять этот код и добавить к нему логирование:

         from eliot import log_call, to_file to_file(open("out.log", "w"))  @log_call def add(a, b):     # ... implementation ...  @log_call def multiply(a, b):     # ... implementation ... # etc. Specifically, we do two     

В частности, мы делаем две вещи:

1. Сообщаем Eliot куда выводить сообщения журнала (в данном случае это файл с именем out.log).
2. Добавляем декоратор функции @log_call. Это позволяет зарегистрировать факт вызова функции, ее аргументы и возвращаемое значение (или возникшее исключение).

У Eliot есть другие, более детализированные API, но @log_call достаточно для демонстрации преимуществ ведения журнала логов.

Выходные данные Eliot

Как только мы запустим программу, мы сможем просмотреть журналы с помощью инструмента под названием eliot-tree:

9

         $ python calc.py 12 $ eliot-tree out.log ─── multiplysum (inputs a=1 b=2 c=4) ⧖ 10.0s     ├── add (inputs a=1 b=2) ⧖ 1.0s     │   └── result: 3     ├── multiply (inputs a=3 b=4) ⧖ 9.0s     │   └── result: 12     └── result: 12     

Обратите внимание на сходство с Pyinstrument – дерево действий. Я немного упростил вывод — изначально так, чтобы он поместился на слайде, который я использовал в статье для доклада, — но даже в этой версии этого достаточно, чтобы оценить производительность.

У Eliot каждое действие имеет начало и конец и может запускать другие действия, в результате чего получается дерево. Поскольку мы знаем, когда начинается и заканчивается каждое зарегистрированное действие, мы также знаем, сколько времени оно заняло.

В этом случае каждое действие сопоставляется с вызовом функции в отношении один к одному. И есть некоторые отличия от вывода Pyinstrument:

1. Вместо объединения нескольких вызовов функций вы видите каждый вызов отдельно от других.
2. Вы можете видеть аргументы и возвращаемый результат каждого вызова.
3. Вы можете увидеть прошедшее системное время для каждого действия.

Например, вы можете видеть, что multiplysum() заняло 10 секунд, но больше всего времени было потрачено на multiply(), с входными данными 3 и 4. Таким образом, вы сразу знаете, что для оптимизации производительности нужно сосредоточиться на multiply(), и у вас есть некоторые начальные входные данные (3 и 4), чтобы поиграть ими и посмотреть на изменения.

Ограничения ведения журнала

Логирование само по себе не является достаточным источником информации о производительности.

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

Если вы не добавили код ведения журнала, вы не получите никакой информации. Eliot делает это немного лучше, поскольку структура дерева действий дает вам некоторое представление о том, где было потрачено время, но этого все же недостаточно, если логирование слишком редкое.

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

4. Правильный выбор инструментов

Итак, когда вы должны использовать каждый инструмент?

Всегда добавляйте ведение журнала

Любая нетривиальная программа, вероятно, нуждается в некотором логировании, хотя бы для того, чтобы отлавливать баги и ошибки. И если вы уже добавляете ведение журнала, вы также можете позаботиться о том, чтобы регистрировать информацию, необходимую для отладки производительности.

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

После этого используйте профилировщик выборки, такой как Pyinstrument.

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

• Имеет низкие накладные расходы и, что более важно, не искажает результаты.
• Измеряет системное время, поэтому можете не беспокоиться, что CPU является «узким местом».
• Выводит только медленные функции, опуская нерелевантные быстрые функции.

Используйте cProfile, если вам нужна индивидуальная метрика затрат

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

Вы можете измерить:

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

5. TL;DR

В качестве хорошей отправной точки для работы с инструментами оптимизации производительности я предлагаю вам следующий алгоритм:

1. Зарегистрируйте ключевые входы и выходы, а также прошедшее время ключевых действий, используя Eliot или какую-либо другую библиотеку регистрации.
2. Используйте Pyinstrument или другой профилировщик выборки в качестве профилировщика по умолчанию.
3. Используйте cProfile, если вам нужен собственный профайлер.

***

Из этой статьи мы узнали:

1. Что собой представляют cProfile, Pyinstrument и Eliot.
2. Обсудили их плюсы и минусы.
3. Узнали как лучше комбинировать работу профилировщиков.

Материалы по теме

• Медлительность Python: причины проблем со скоростью
• Сравниваем скорость С++ и Python на примере стереозрения в OpenCV на Raspberry Pi