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

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

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

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

1. cProfile рекомендуется для большинства пользователей; это расширение для языка Си с разумными затратами, что делает его подходящим для профилирования длительно работающих программ. Основано на 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 были primitive, что означает, что вызов не был вызван с помощью рекурсии. Следующая строка: Ordered by: cumulative time указывает, что выходные данные отсортированы по значениям cumtime. Заголовки столбцов включают:

вызовы ncalls

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

общее время

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

перколл

это частное от tottime, деленное на ncalls

время кончать

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

перколл

это частное от cumtime, деленное на примитивные вызовы

имя файла:lineno(функция)

предоставляет соответствующие данные для каждой функции

Когда в первом столбце есть два числа (например, 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% (re: .5) от его первоначального размера, затем сохраняются только строки, содержащие init, и этот подсписок печатается.

Если вам интересно, какие функции вызывают указанные выше функции, вы могли бы сейчас (p по-прежнему сортируется в соответствии с последним критерием) сделать:

p.print_callers(.5, 'init')

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

Если вы хотите получить больше функциональности, вам придется прочитать руководство или догадаться, что делают следующие функции:

p.print_callees()
p.add('restats')

Вызываемый в виде скрипта, модуль pstats представляет собой браузер статистики для чтения и проверки дампов профилей. Он имеет простой интерфейс, ориентированный на строки (реализован с использованием cmd) и интерактивную справку.

profile и cProfile Ссылка на модуль¶

Оба модуля profile и cProfile предоставляют следующие функции:

profile.run(command, filename=None, sort=-1)¶

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

exec(command, __main__.__dict__, __main__.__dict__)

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

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

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

exec(command, globals, locals)

и собирает статистику профилирования, как в функции run(), описанной выше.

class profile.Profile(timer=None, timeunit=0.0, subcalls=True, builtins=True)¶

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

Пользовательский таймер может быть установлен для измерения продолжительности выполнения кода с помощью аргумента timer. Это должна быть функция, которая возвращает единственное число, представляющее текущее время. Если число является целым, то timeunit указывает множитель, который определяет продолжительность каждой единицы времени. Например, если таймер возвращает время, измеренное в тысячах секунд, единицей измерения времени будет .001.

Прямое использование класса Profile позволяет форматировать результаты профилирования без записи данных профиля в файл:

import cProfile, pstats, io
from pstats import SortKey
pr = cProfile.Profile()
pr.enable()
# ... do something ...
pr.disable()
s = io.StringIO()
sortby = SortKey.CUMULATIVE
ps = pstats.Stats(pr, stream=s).sort_stats(sortby)
ps.print_stats()
print(s.getvalue())

Класс Profile также может использоваться в качестве контекстного менеджера (поддерживается только в модуле cProfile. смотрите Типы контекстных менеджеров):

import cProfile

with cProfile.Profile() as pr:
    # ... do something ...

    pr.print_stats()

Изменено в версии 3.8: Добавлена поддержка контекстного менеджера.

enable()¶

Начните собирать данные для профилирования. Только в cProfile.

disable()¶

Прекратите сбор данных для профилирования. Только в cProfile.

create_stats()¶

Прекратите сбор данных для профилирования и запишите результаты внутри системы в качестве текущего профиля.

print_stats(sort=-1)¶

Создайте объект Stats на основе текущего профиля и выведите результаты в стандартный вывод.

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

Этот конструктор класса создает экземпляр «статистического объекта» из 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(). Статистика для функций с одинаковыми именами (например, файл, строка, имя) автоматически накапливается в статистике одной функции.

dump_stats(filename)¶

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

sort_stats(*keys)¶

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

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

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

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

Допустимый аргумент строки	Допустимый аргумент перечисления	Значение
'calls'	Программная клавиша.звонки	количество звонков
'cumulative'	Ключ сортировки.совокупный	совокупное время
'cumtime'	Н/Д	совокупное время
'file'	Н/Д	имя файла
'filename'	Ключ сортировки.имя файла	имя файла
'module'	Н/Д	имя файла
'ncalls'	Н/Д	количество звонков
'pcalls'	Ключ сортировки.PCALLS	примитивное количество вызовов
'line'	Ключ сортировки.линия	номер строки
'name'	SortKey.NAME	название функции
'nfl'	Сортировочный ключ.NFL	имя/файл/строка
'stdname'	Ключ сортировки.СТАНДАРТНОЕ ИМЯ	стандартное название
'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: Добавлено перечисление ключа сортировки.

reverse_order()¶

Этот метод для класса Stats изменяет порядок расположения базового списка в объекте на противоположный. Обратите внимание, что по умолчанию порядок сортировки выбирается по возрастанию или по убыванию в зависимости от выбранного ключа сортировки.

print_stats(*restrictions)¶

Этот метод для класса Stats выводит отчет, как описано в определении profile.run().

Порядок печати основан на последней sort_stats() операции, выполненной над объектом (с учетом предостережений, приведенных в add() и strip_dirs()).

Приведенные аргументы (если таковые имеются) могут быть использованы для ограничения списка значимыми элементами. Изначально предполагается, что список представляет собой полный набор профилированных функций. Каждое ограничение представляет собой либо целое число (для выбора количества строк), либо десятичную дробь от 0,0 до 1,0 включительно (для выбора процента строк), либо строку, которая будет интерпретироваться как регулярное выражение (чтобы шаблон соответствовал стандартному имени, которое выводится на печать). Если предусмотрено несколько ограничений, то они применяются последовательно. Например:

print_stats(.1, 'foo:')

сначала можно было бы ограничить печать первыми 10% списка, а затем печатать только те функции, которые были частью filename .*foo:. В отличие от этого, команда:

print_stats('foo:', .1)

ограничил бы список всеми функциями, имеющими имена файлов .*foo:, а затем приступил бы к печати только первых 10% из них.

print_callers(*restrictions)¶

Этот метод для класса Stats выводит список всех функций, которые вызывали каждую функцию в профилированной базе данных. Порядок выполнения идентичен порядку, указанному в print_stats(), и определение ограничивающего аргумента также идентично. О каждом звонящем сообщается в отдельной строке. Формат немного отличается в зависимости от профилировщика, который создал статистику:

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

• При cProfile перед каждым вызывающим абонентом указываются три цифры: количество раз, когда был выполнен этот конкретный вызов, и общее и кумулятивное время, затраченное на текущую функцию, пока она была вызвана этим конкретным вызывающим абонентом.

print_callees(*restrictions)¶

Этот метод для класса Stats выводит список всех функций, которые были вызваны указанной функцией. За исключением изменения направления вызовов (re: called vs был вызван by), аргументы и порядок следования идентичны методу print_callers().

get_stats_profile()¶

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

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

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

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

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

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

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

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

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

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

Калибровка¶

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

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

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

Имейте в виду, что вам следует откалибровать класс profiler для выбранной вами функции timer (см. Калибровка). Для большинства машин таймер, который возвращает единственное целое значение, обеспечит наилучшие результаты с точки зрения снижения затрат на профилирование. (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().