Профилировщики 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() и отобразит результаты профилирования, например, следующие:

      197 function calls (192 primitive calls) in 0.002 seconds

Ordered by: standard name

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1    0.000    0.000    0.001    0.001 <string>:1(<module>)
     1    0.000    0.000    0.001    0.001 re.py:212(compile)
     1    0.000    0.000    0.001    0.001 re.py:268(_compile)
     1    0.000    0.000    0.000    0.000 sre_compile.py:172(_compile_charset)
     1    0.000    0.000    0.000    0.000 sre_compile.py:201(_optimize_charset)
     4    0.000    0.000    0.000    0.000 sre_compile.py:25(_identityfunction)
   3/1    0.000    0.000    0.000    0.000 sre_compile.py:33(_compile)

Первая строка указывает, что было отслежено 197 вызовов. Из этих вызовов 192 были примитивными, что означает, что вызов не был вызван рекурсией. Следующая строка: Ordered by: standard name, указывает, что строка текста в крайнем правом столбце использовалась для сортировки вывода. Заголовки столбцов включают:

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)

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

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 на основе текущего профиля и вывести результаты в стандартный вывод.

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