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

Исходный код: Lib/profile.py и Lib/pstats.py

Введение в профилировщики

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

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

enable()

Начать сбор данных профилирования.

disable()

Остановить сбор данных профилирования.

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 enums имеют преимущество перед строковым аргументом, так как они более надёжны и менее подвержены ошибкам.

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

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

Следующие являются допустимыми строковыми и SortKey значениями:

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

Обратите внимание, что все сортировки статистики выполняются в порядке убывания (наиболее ресурсоёмкие элементы ставятся первыми), в то время как поиск по имени, файлу и номеру строки выполняется в порядке возрастания (в алфавитном порядке). Небольшое различие между SortKey.NFL и SortKey.STDNAME заключается в том, что стандартное имя представляет собой сортировку имени, как оно отображается, что означает, что встроенные номера строк сравниваются странным образом. Например, строки 3, 20 и 40 (если имена файлов одинаковы) будут появляться в строчном порядке 20, 3 и 40. В отличие от этого, SortKey.NFL выполняет числовое сравнение номеров строк. Фактически, sort_stats(SortKey.NFL) эквивалентно sort_stats(SortKey.NAME, SortKey.FILENAME, SortKey.LINE).

В целях обратной совместимости допускаются числовые аргументы -1, 0, 1, и 2 . Они интерпретируются как 'stdname', 'calls', 'time', и 'cumulative' соответственно. Если используется этот старый формат (числовой), будет использован только один ключ сортировки (числовой ключ), и дополнительные аргументы будут проигнорированы.

В версии 3.7: Добавлен перечисление SortKey.

reverse_order()

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

print_stats(*restrictions)

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

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

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

print_stats(.1, 'foo:')

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

print_stats('foo:', .1)

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

print_callers(*restrictions)

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

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

print_callees(*restrictions)

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

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

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

В 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 ГГц под управлением Mac OS X и с использованием таймера `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().