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

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

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

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

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

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

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

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

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 имеет класс Stats, который предоставляет различные методы для обработки и вывода данных, сохранённых в файле результатов профилирования:

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% (re: .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.

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

• С помощью 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 как напрямую, так и под управлением профилировщика, измеряя время в обоих случаях. Затем он вычисляет скрытые накладные расходы на каждое событие профилировщика и возвращает это значение как число с плавающей точкой. Например, на компьютере с процессором Intel Core i5 1.8 ГГц под macOS и таймером time.process_time() Python магическое число составляет примерно 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().