Профилировщики 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 имеет класс 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% (относительно .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(), с добавлением аргументов для предоставления словарей глобальных и локальных переменных для строки команды. Эта процедура выполняет:

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