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

Исходный код: Lib/profile.py и Lib/pstats.py

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

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

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

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

Примечание

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

Краткое руководство пользователя

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

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

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

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

Приведённая выше команда выполнит 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 <output_file>: Записывает результаты профилирования в файл, а не в stdout.

-s <sort_order>: Задаёт одно из значений сортировки sort_stats(), по которому будет отсортирован вывод. Применяется только в том случае, если не задан параметр -o.

-m <module>: Указывает, что профилируется модуль, а не сценарий.

Добавлено в версии 3.7: В cProfile добавлен параметр -m.

Добавлено в версии 3.8: В profile добавлен параметр -m.

Класс Stats модуля 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)

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

Можно также попробовать:

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)

Конструктор этого класса создаёт экземпляр «объекта статистики» из filename (или списка имён файлов) либо из экземпляра 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(), а определение аргумента ограничения также совпадает. Каждый вызывающий объект выводится в отдельной строке. Формат немного различается в зависимости от профилировщика, создавшего статистику:

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

print_callees(*restrictions): Этот метод класса Stats выводит список всех функций, вызванных указанной функцией. Помимо изменения направления вызовов (вызываемые функции вместо вызывающих), аргументы и порядок вывода совпадают с методом print_callers().

get_stats_profile(): Этот метод возвращает экземпляр StatsProfile, содержащий отображение имён функций на экземпляры FunctionProfile. Каждый экземпляр FunctionProfile хранит сведения о профиле функции, например, сколько времени заняло её выполнение, сколько раз она была вызвана и т. д.

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

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

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

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

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

Ограничения

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

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

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

Калибровка

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

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

Этот метод выполняет указанное в аргументе число вызовов Python напрямую, а затем повторяет их под профилировщиком, измеряя время в обоих случаях. После этого он вычисляет скрытые накладные расходы на одно событие профилировщика и возвращает результат в виде числа с плавающей точкой. Например, на компьютере с Intel Core i5 1,8 ГГц под управлением 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().