Профилировщики Python

Введение в профилировщики

cProfile и profile предоставляют детерминированное профилирование программ на Python. Профиль — это набор статистических данных, описывающих, как часто и как долго выполнялись различные части программы. Эти статистические данные могут быть отформатированы в отчеты с помощью модуля pstats.

Стандартная библиотека Python предоставляет две разные реализации одного и того же интерфейса профилирования:

1. cProfile рекомендуется большинству пользователей; это расширение на C с приемлемой нагрузкой, что делает его подходящим для профилирования долго выполняемых программ. Основано на lsprof, предоставленных Бреттом Розеном и Тедом Чоттером.
2. profile, чистый модуль Python, интерфейс которого имитируется cProfile, но который добавляет значительную нагрузку на профилируемые программы. Если вы пытаетесь каким-либо образом расширить профилировщик, эта задача может быть проще с этим модулем. Первоначально разработан и написан Джимом Роскиндом.

Быстрый справочник пользователя

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

Для профилирования функции, принимающей один аргумент, можно выполнить:

import cProfile
import re
cProfile.run('re.compile("foo|bar")')

(Используйте profile вместо cProfile, если последний не доступен в вашей системе.)

Вышеуказанное действие запустило бы re.compile() и напечатало бы результаты профилирования, подобные следующим:

      214 function calls (207 primitive calls) in 0.002 seconds

Ordered by: cumulative time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1    0.000    0.000    0.002    0.002 {built-in method builtins.exec}
     1    0.000    0.000    0.001    0.001 <string>:1(<module>)
     1    0.000    0.000    0.001    0.001 __init__.py:250(compile)
     1    0.000    0.000    0.001    0.001 __init__.py:289(_compile)
     1    0.000    0.000    0.000    0.000 _compiler.py:759(compile)
     1    0.000    0.000    0.000    0.000 _parser.py:937(parse)
     1    0.000    0.000    0.000    0.000 _compiler.py:598(_code)
     1    0.000    0.000    0.000    0.000 _parser.py:435(_parse_sub)

Первая строка указывает, что было отслежено 214 вызовов. Из этих вызовов 207 были примитивными, что означает, что вызов не был вызван рекурсией. Следующая строка: Ordered by: cumulative time указывает, что вывод отсортирован по значениям cumtime. Заголовки столбцов включают:

ncalls

для количества вызовов.

tottime

для общего времени, затраченного в данной функции (исключая время, затраченное на вызовы подфункций)

percall

является частным от деления tottime на ncalls

cumtime

является кумулятивным временем, затраченным в данной и всех подфункциях (от вызова до выхода). Эта величина точна даже для рекурсивных функций.

percall

является частным от деления cumtime на количество примитивных вызовов

filename:lineno(function)

предоставляет соответствующие данные для каждой функции

Когда в первом столбце есть два числа (например, 3/1), это означает, что функция рекурсировала. Второе значение — количество примитивных вызовов, а первое — общее количество вызовов. Обратите внимание, что когда функция не рекурсирует, эти два значения одинаковы, и выводится только одно значение.

Вместо вывода результата в конце выполнения профилирования, вы можете сохранить результаты в файл, указав имя файла функции run():

import cProfile
import re
cProfile.run('re.compile("foo|bar")', 'restats')

Класс pstats.Stats читает результаты профилирования из файла и форматирует их различными способами.

Файлы cProfile и profile также могут быть вызваны как скрипт для профилирования другого скрипта. Например:

python -m cProfile [-o output_file] [-s sort_order] (-m module | myscript.py)

-o записывает результаты профилирования в файл вместо стандартного вывода

-s указывает одно из значений сортировки sort_stats() для сортировки вывода. Это применимо только тогда, когда не указано -o.

-m указывает, что профилируется модуль, а не скрипт.

Модуль pstats имеет различные методы для манипулирования и вывода данных, сохраненных в файле результатов профилирования:

import pstats
from pstats import SortKey
p = pstats.Stats('restats')
p.strip_dirs().sort_stats(-1).print_stats()

Метод strip_dirs() удаляет лишний путь из всех имён модулей. Метод sort_stats() сортирует все записи по стандартной строке модуля/строки/имени, которая выводится. Метод print_stats() выводит всю статистику. Вы можете попробовать следующие вызовы сортировки:

p.sort_stats(SortKey.NAME)
p.print_stats()

Первый вызов фактически отсортирует список по имени функции, а второй вызов выведет статистику. Ниже приведены некоторые интересные вызовы для экспериментов:

p.sort_stats(SortKey.CUMULATIVE).print_stats(10)

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

Если вы хотите увидеть, какие функции многократно циклились и затрачивали много времени, вы сделаете:

p.sort_stats(SortKey.TIME).print_stats(10)

для сортировки по времени, затраченному внутри каждой функции, и вывода статистики по 10 наиболее значимым функциям.

Вы также можете попробовать:

p.sort_stats(SortKey.FILENAME).print_stats('__init__')

Это отсортирует всю статистику по имени файла и выведет статистику только для методов инициализации класса (так как в них есть __init__). В качестве последнего примера вы можете попробовать:

p.sort_stats(SortKey.TIME, SortKey.CUMULATIVE).print_stats(.5, 'init')

Эта строка сортирует статистику с первичным ключом — временем и вторичным ключом — кумулятивным временем, а затем выводит часть статистики. Более конкретно, список сначала сокращается до 50% (относительно .5) от его первоначального размера, затем сохраняются только строки, содержащие init, и этот под-под-список выводится.

Если вы задались вопросом, какие функции вызвали вышеперечисленные функции, вы теперь (p всё ещё отсортированы по последним критериям) можете сделать:

p.print_callers(.5, 'init')

и вы получите список вызывающих функций для каждой из указанных функций.

Если вам нужна дополнительная функциональность, вам придётся прочитать руководство или предположить, что делают следующие функции:

p.print_callees()
p.add('restats')

Вызванный как скрипт, модуль pstats является браузером статистики для чтения и просмотра дампов профилей. Он имеет простой интерфейс с ориентированным на строки взаимодействием (реализованный с помощью cmd) и интерактивную справку.

Справочник модуля profile и cProfile

В модулях profile и cProfile представлены следующие функции:

profile.run(command, filename=None, sort=-1)

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

exec(command, __main__.__dict__, __main__.__dict__)

и собирает статистику профилирования из выполнения. Если имя файла не указано, эта функция автоматически создает экземпляр Stats и выводит простой отчёт по профилированию. Если значение сортировки указано, оно передаётся этому экземпляру Stats для управления сортировкой результатов.

profile.runctx(command, globals, locals, filename=None, sort=-1)

Эта функция похожа на run(), с добавленными аргументами для указания отображений глобальных и локальных переменных для строки command. Эта процедура выполняет:

exec(command, globals, locals)

и собирает статистику профилирования, как и в функции run() выше.

class profile.Profile(timer=None, timeunit=0.0, subcalls=True, builtins=True)

Этот класс обычно используется только в том случае, если требуется более точный контроль над профилированием, чем обеспечивает функция cProfile.run().

Для измерения времени выполнения кода можно использовать пользовательский таймер, передавая его в аргумент timer. Он должен быть функцией, возвращающей единственное число, представляющее текущее время. Если число является целым, timeunit указывает множитель, определяющий продолжительность каждой единицы времени. Например, если таймер возвращает значения, измеренные в тысячных долях секунды, единица времени будет .001.

Использование класса Profile напрямую позволяет форматировать результаты профилирования без записи данных профиля в файл:

import cProfile, pstats, io
from pstats import SortKey
pr = cProfile.Profile()
pr.enable()
# ... do something ...
pr.disable()
s = io.StringIO()
sortby = SortKey.CUMULATIVE
ps = pstats.Stats(pr, stream=s).sort_stats(sortby)
ps.print_stats()
print(s.getvalue())

Класс Profile также может использоваться как менеджер контекста (поддерживается только в модуле cProfile. см. Типы менеджеров контекста):

import cProfile

with cProfile.Profile() as pr:
    # ... do something ...

    pr.print_stats()

Изменено в версии 3.8: Добавлена поддержка менеджеров контекста.

enable()

Начать сбор данных профилирования. Только в модуле cProfile.

disable()

Остановить сбор данных профилирования. Только в модуле cProfile.

create_stats()

Остановить сбор данных профилирования и записать результаты внутри как текущий профиль.

print_stats(sort=-1)

Создать объект Stats на основе текущего профиля и вывести результаты в stdout.

Параметр sort определяет порядок сортировки отображаемой статистики. Он принимает один ключ или кортеж ключей для многоуровневой сортировки, как в Stats.sort_stats.

Добавлена в версии 3.13: print_stats() теперь принимает кортеж ключей.

dump_stats(filename)

Записать результаты текущего профиля в файл filename.

run(cmd)

Профилировать cmd через exec().

runctx(cmd, globals, locals)

Профилировать cmd через exec() со заданной средой глобальных и локальных переменных.

runcall(func, /, *args, **kwargs)

Профилировать func(*args, **kwargs)

Обратите внимание, что профилирование будет работать только в том случае, если вызываемая команда/функция фактически возвращает значение. Если интерпретатор завершается (например, через вызов sys.exit() во время выполнения вызываемой команды/функции), результаты профилирования не будут выведены.

Класс Stats

Анализ данных профилировщика выполняется с помощью класса Stats.

class pstats.Stats(*filenames or profile, stream=sys.stdout)

Этот конструктор класса создаёт экземпляр «объекта статистики» из имени файла (или списка имён файлов) или из объекта Profile. Вывод будет выведен в поток, указанный параметром stream.

Файл, выбранный в конструкторе выше, должен быть создан соответствующей версией profile или cProfile. То есть, нет гарантии совместимости файлов с будущими версиями профилировщика, а также нет совместимости с файлами, созданными другими профилировщиками или тем же профилировщиком, запущенным на другой операционной системе. Если предоставлено несколько файлов, вся статистика для идентичных функций будет объединёна, так что общий обзор нескольких процессов может быть рассмотрен в одном отчёте. Если необходимо объединить дополнительные файлы с данными в существующем объекте Stats, можно использовать метод add().

Вместо чтения данных профиля из файла можно использовать объект cProfile.Profile или profile.Profile в качестве источника данных профиля.

Stats объекты имеют следующие методы:

strip_dirs()

Этот метод класса Stats удаляет всю информацию о пути из имён файлов. Это очень полезно для уменьшения объёма вывода, чтобы он помещался (почти) в 80 колонок. Этот метод изменяет объект, и удалённая информация теряется. После выполнения операции удаления объект считается имеющим записи в «случайном» порядке, как сразу после инициализации и загрузки объекта. Если strip_dirs() приводит к тому, что два имени функций становятся неразличимыми (они находятся в одной строке одного файла и имеют одинаковое имя функции), то статистика для этих двух записей накапливается в одну запись.

add(*filenames)

Этот метод класса Stats накапливает дополнительную информацию о профилировании в текущий объект профилирования. Его аргументы должны ссылаться на имена файлов, созданные соответствующей версией profile.run() или cProfile.run(). Статистика для функций с одинаковыми именами (по файлу, строке и имени) автоматически накапливается в статистику одной функции.

dump_stats(filename)

Сохраняет данные, загруженные в объект Stats, в файл с именем filename. Файл создаётся, если он не существует, и перезаписывается, если он уже существует. Это эквивалентно методу с тем же именем для классов profile.Profile и cProfile.Profile.

sort_stats(*keys)

Этот метод изменяет объект Stats, сортируя его по заданному критерию. Аргумент может быть строкой или перечислением SortKey, определяющим основу сортировки (например: 'time', 'name', SortKey.TIME или SortKey.NAME). Аргументы SortKey более надёжны и менее подвержены ошибкам, чем строковые аргументы.

Если указано более одного ключа, дополнительные ключи используются как вторичные критерии при равенстве всех выбранных перед ними ключей. Например, sort_stats(SortKey.NAME, SortKey.FILE) отсортирует все записи по имени функции и разрешит все ничьи (идентичные имена функций) путём сортировки по имени файла.

Для строкового аргумента могут использоваться сокращения для имён ключей, если сокращение однозначно.

Следующие являются допустимыми строковыми и SortKey аргументами:

Допустимый строковый аргумент	Допустимый аргумент перечисления	Значение
'calls'	SortKey.CALLS	количество вызовов
'cumulative'	SortKey.CUMULATIVE	накопленное время
'cumtime'	N/A	накопленное время
'file'	N/A	имя файла
'filename'	SortKey.FILENAME	имя файла
'module'	N/A	имя файла
'ncalls'	N/A	количество вызовов
'pcalls'	SortKey.PCALLS	количество примитивных вызовов
'line'	SortKey.LINE	номер строки
'name'	SortKey.NAME	имя функции
'nfl'	SortKey.NFL	имя/файл/строка
'stdname'	SortKey.STDNAME	стандартное имя
'time'	SortKey.TIME	внутреннее время
'tottime'	N/A	внутреннее время

Обратите внимание, что все сортировки статистики выполняются в порядке убывания (более затратные по времени элементы выводятся первыми), а поиск по имени, файлу и номеру строки выполняется в порядке возрастания (в алфавитном порядке). Незначительное различие между SortKey.NFL и SortKey.STDNAME заключается в том, что стандартное имя - это своего рода отсортированное имя, выводимое на печать, что означает, что вложенные номера строк сравниваются необычным образом. Например, строки 3, 20 и 40 (если имена файлов одинаковые) будут выводиться в порядке строк 20, 3 и 40. В противоположность этому, SortKey.NFL выполняет числовое сравнение номеров строк. На самом деле, sort_stats(SortKey.NFL) эквивалентно sort_stats(SortKey.NAME, SortKey.FILENAME, SortKey.LINE).

По причинам обратной совместимости допускаются числовые аргументы -1, 0, 1, и 2. Они интерпретируются как 'stdname', 'calls', 'time', и 'cumulative' соответственно. Если используется этот старый формат (числовой), будет использован только один ключ сортировки (числовой ключ), и дополнительные аргументы будут проигнорированы.

Добавлен в версии 3.7: Добавлена перечисление SortKey.

reverse_order()

Этот метод класса Stats изменяет порядок элементов в списке объекта. Обратите внимание, что по умолчанию порядок (возрастания или убывания) правильно выбирается в зависимости от выбранного ключа сортировки.

print_stats(*restrictions)

Этот метод класса Stats выводит отчёт, как описано в определении profile.run().

Порядок вывода основан на последней операции sort_stats(), выполненной над объектом (с учётом оговорок в методах add() и strip_dirs()).

Предоставленные аргументы (если таковые имеются) могут использоваться для ограничения списка до значимых записей. Изначально список рассматривается как полный набор профилируемых функций. Каждое ограничение – это либо целое число (для выбора количества строк), либо десятичная дробь от 0,0 до 1,0 включительно (для выбора процента строк), либо строка, которая будет интерпретирована как регулярное выражение (для сопоставления с шаблоном стандартного имени, выводимого на печать). Если предоставлено несколько ограничений, то они применяются последовательно. Например:

print_stats(.1, 'foo:')

сначала ограничит вывод первыми 10% элементов списка, а затем выведет только функции, которые были частью файла .*foo:. В отличие от команды:

print_stats('foo:', .1)

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

print_callers(*restrictions)

Этот метод класса Stats выводит список всех функций, которые вызывали каждую функцию в базе данных профилирования. Порядок такой же, как и у print_stats(), и определение ограничивающего аргумента тоже идентично. Каждый вызывающий объект отображается в отдельной строке. Формат немного отличается в зависимости от профилировщика, который создал stats:

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

print_callees(*restrictions)

Этот метод класса Stats выводит список всех функций, которые были вызваны указанной функцией. Помимо этого изменения направления вызовов (вызвала/была вызвана), аргументы и порядок идентичны методу print_callers().

get_stats_profile()

Этот метод возвращает экземпляр StatsProfile, который содержит отображение имён функций на экземпляры FunctionProfile. Каждый экземпляр FunctionProfile содержит информацию о профиле функции, такую как время выполнения функции, количество вызовов и т. д…

Добавлен в версии 3.9: Добавлены следующие классы данных: StatsProfile, FunctionProfile. Добавлена функция: get_stats_profile.

Что такое детерминированное профилирование?

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

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

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

Ограничения

Одно из ограничений связано с точностью информации о времени. Существует фундаментальная проблема с детерминированными профилировщиками, связанная с точностью. Наиболее очевидное ограничение состоит в том, что базовый «часовой механизм» тикает только с частотой (как правило) около 0,001 секунды. Следовательно, никакие измерения не будут более точными, чем базовый часовой механизм. Если будет выполнено достаточно измерений, то «ошибка» будет, в среднем, компенсироваться. К сожалению, устранение этой первой ошибки приводит ко второй ошибке.

Вторая проблема заключается в том, что «проходит некоторое время» с момента отправки события до фактического получения значения состояния часового механизма вызовом профилировщика. Аналогично, существует определённая задержка при выходе из обработчика событий профилировщика от момента получения значения часового механизма (а затем его сохранения), до момента повторного выполнения кода пользователя. В результате функции, которые вызываются много раз или вызывают много функций, обычно накапливают эту ошибку. Ошибка, которая накапливается таким образом, обычно меньше, чем точность часового механизма (менее одной тика), но она может накапливаться и становиться очень значительной.

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

Калибровка

Профилировщик модуля profile вычитает константу из времени обработки каждого события, чтобы компенсировать накладные расходы на вызов функции времени и сохранение результатов. По умолчанию константа равна 0. Следующая процедура может быть использована для получения лучшей константы для данной платформы (см. Ограничения).

import profile
pr = profile.Profile()
for i in range(5):
    print(pr.calibrate(10000))

Метод выполняет указанное количество вызовов Python напрямую и снова под управлением профилировщика, измеряя время для обоих случаев. Затем он вычисляет скрытые накладные расходы на каждое событие профилировщика и возвращает это значение как число с плавающей точкой. Например, на 1,8-ГГц процессоре Intel Core i5 под macOS и с использованием функции Python time.process_time() в качестве таймера, магическое число составляет примерно 4,04e-6.

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

Когда вы получите согласованный ответ, есть три способа его использования:

import profile

# 1. Apply computed bias to all Profile instances created hereafter.
profile.Profile.bias = your_computed_bias

# 2. Apply computed bias to a specific Profile instance.
pr = profile.Profile()
pr.bias = your_computed_bias

# 3. Specify computed bias in instance constructor.
pr = profile.Profile(bias=your_computed_bias)

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

Использование пользовательского таймера

Если вы хотите изменить способ определения текущего времени (например, для принудительного использования времени работы программы или затраченного времени процесса), передайте желаемую функцию времени конструктору класса Profile:

pr = profile.Profile(your_time_func)

Полученный профилировщик затем вызовет your_time_func. В зависимости от того, используете ли вы profile.Profile или cProfile.Profile, возвращаемое значение your_time_func будет интерпретироваться по-разному:

profile.Profile

your_time_func должно возвращать одно число или список чисел, сумма которых равна текущему времени (как возвращает os.times()). Если функция возвращает одно число времени или список возвращаемых чисел имеет длину 2, то вы получите особенно быструю версию процедуры обработки.

Будьте предупреждены, что вам следует откалибровать класс профилировщика для выбранной функции таймера (см. Калибровка). Для большинства машин таймер, возвращающий одиночное целое значение, обеспечит лучшие результаты с точки зрения низких накладных расходов во время профилирования. (os.times() очень плох, так как он возвращает кортеж значений с плавающей точкой). Если вы хотите заменить лучший таймер самым чистым способом, создайте класс-наследник и жёстко закодируйте заменяющий метод обработки, который лучше всего обрабатывает ваш вызов таймера, вместе с соответствующей константой калибровки.

cProfile.Profile

your_time_func должно возвращать одно число. Если оно возвращает целые числа, вы также можете вызвать конструктор класса со вторым аргументом, определяющим реальную продолжительность единицы времени. Например, если your_integer_time_func возвращает время, измеряемое в тысячах секунд, вы бы создали экземпляр Profile следующим образом:

pr = cProfile.Profile(your_integer_time_func, 0.001)

Так как класс cProfile.Profile не может быть откалиброван, пользовательские функции таймера должны использоваться с осторожностью и быть максимально быстрыми. Для достижения наилучших результатов с пользовательским таймером может потребоваться жёсткая кодировка в исходном коде C внутреннего модуля _lsprof.

Python 3.3 добавляет несколько новых функций в time, которые можно использовать для точного измерения времени работы процесса или времени настенных часов. Например, см. time.perf_counter().