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

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

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

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

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

Ограничения

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

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

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

Калибровка

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

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

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