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

Знакомство с профилировщиками¶

cProfile и profile предоставляют deterministic profiling программ Python. profile - это набор статистических данных, описывающих, как часто и как долго выполнялись различные части программы. Эта статистика может быть отформатирована в отчеты с помощью модуля 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 были primitive, что означает, что вызов не был вызван через рекурсию. Следующая строка: Ordered by: standard name, указывает на то, что текстовая строка в крайнем правом столбце была использована для сортировки вывода. Заголовки столбцов включают:

ncalls

по количеству звонков.

tottime

для общего времени, проведенного в данной функции (исключая время, затраченное на вызовы подфункций)

percall

это коэффициент tottime, деленный на ncalls.

кумтайм

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

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 записывает результаты профиля в файл, а не в stdout

-s задает одно из значений сортировки sort_stats() для сортировки вывода. Это применимо только в том случае, если не указано -o.

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

Добавлено в версии 3.7: Добавлена опция -m к cProfile.

Добавлено в версии 3.8: Добавлена опция -m к profile.

Класс 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')

Эта строка сортирует статистику с первичным ключом time и вторичным ключом cumulative time, а затем распечатывает некоторые статистические данные. Если быть точным, список сначала сокращается до 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 и печатает простой отчет о профилировании. Если указано значение sort, то оно передается этому экземпляру Stats для управления сортировкой результатов.

profile.runctx(command, globals, locals, filename=None, sort=- 1)¶

Эта функция аналогична run(), с добавленными аргументами, чтобы предоставить словари globals и locals для строки команда. Эта процедура выполняет:

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)¶

Профилируйте команду через exec().

runctx(cmd, globals, locals)¶

Профиль команды cmd через exec() с указанным глобальным и локальным окружением.

runcall(func, /, *args, **kwargs)¶

Профиль func(*args, **kwargs)

Обратите внимание, что профилирование будет работать только в том случае, если вызванная команда/функция действительно возвращается. Если интерпретатор завершается (например, через вызов sys.exit() во время выполнения вызванной команды/функции), результаты профилирования не будут выведены.

Класс Stats¶

Анализ данных профилировщика выполняется с помощью класса Stats.

class pstats.Stats(*filenames or profile, stream=sys.stdout)¶

Этот конструктор класса создает экземпляр «объекта статистики» из filename (или списка имен файлов) или из экземпляра Profile. Вывод будет напечатан в поток, указанный stream.

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

Вместо чтения данных профиля из файла в качестве источника данных профиля можно использовать объект cProfile.Profile или profile.Profile.

Объекты Stats имеют следующие методы:

strip_dirs()¶

Этот метод для класса Stats удаляет всю ведущую информацию о пути из имен файлов. Это очень полезно для уменьшения размера распечатки, чтобы она помещалась в 80 столбцов (почти). Этот метод модифицирует объект, и удаленная информация теряется. После выполнения операции зачистки считается, что записи в объекте расположены в «случайном» порядке, как это было сразу после инициализации и загрузки объекта. Если в результате операции strip_dirs() два имени функций становятся неразличимыми (находятся в одной строке одного и того же файла и имеют одинаковое имя функции), то статистика для этих двух записей накапливается в одной записи.

add(*filenames)¶

Этот метод класса Stats накапливает дополнительную информацию о профилировании в текущем объекте профилирования. Его аргументы должны ссылаться на имена файлов, созданных соответствующей версией profile.run() или cProfile.run(). Статистика для одинаково названных (re: file, line, name) функций автоматически накапливается в статистику одной функции.

dump_stats(filename)¶

Сохранить данные, загруженные в объект Stats, в файл с именем filename. Файл создается, если он не существует, и перезаписывается, если он уже существует. Это эквивалентно одноименному методу классов profile.Profile и cProfile.Profile.

sort_stats(*keys)¶

Этот метод изменяет объект Stats, сортируя его в соответствии с заданными критериями. Аргументом может быть либо строка, либо перечисление SortKey, определяющее основу сортировки (пример: 'time', 'name', SortKey.TIME или SortKey.NAME). Аргумент SortKey enum имеет преимущество перед строковым аргументом в том, что он более надежен и менее подвержен ошибкам.

Если указано более одного ключа, то дополнительные ключи используются в качестве вторичных критериев при равенстве всех ключей, выбранных до них. Например, sort_stats(SortKey.NAME, SortKey.FILE) отсортирует все записи по имени функции и устранит все связи (одинаковые имена функций) путем сортировки по имени файла.

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

Ниже перечислены допустимые строки и SortKey:

Допустимый строковый аргумент	Действительное перечисление Arg	Значение
'calls'	SortKey.CALLS	количество звонков
'cumulative'	SortKey.CUMULATIVE	суммарное время
'cumtime'	Н/Д	суммарное время
'file'	Н/Д	имя файла
'filename'	SortKey.FILENAME	имя файла
'module'	Н/Д	имя файла
'ncalls'	Н/Д	количество звонков
'pcalls'	SortKey.PCALLS	количество примитивных вызовов
'line'	SortKey.LINE	номер строки
'name'	SortKey.NAME	название функции
'nfl'	SortKey.NFL	имя/файл/строка
'stdname'	SortKey.STDNAME	стандартное название
'time'	SortKey.TIME	внутреннее время
'tottime'	Н/Д	внутреннее время

Обратите внимание, что все виды статистики расположены в порядке убывания (сначала размещаются наиболее трудоемкие элементы), в то время как поиск по имени, файлу и номеру строки - в порядке возрастания (по алфавиту). Тонкое различие между 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 выводит список всех функций, которые были вызваны указанной функцией. За исключением обратного направления вызовов (re: called vs was called by), аргументы и порядок идентичны методу print_callers().

get_stats_profile()¶

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

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

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

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

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

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

Ограничения¶

Одно из ограничений связано с точностью временной информации. Существует фундаментальная проблема с детерминированными профилировщиками, связанная с точностью. Наиболее очевидным ограничением является то, что базовые «часы» тикают со скоростью (обычно) около .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 под управлением macOS и с использованием Python’s 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().