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

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

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

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

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

1. cProfile рекомендуется для большинства пользователей; это расширение на C с приемлемой накладной, что делает его подходящим для профилирования долго выполняемых программ. Основано на lsprof, предоставленном Бреттом Розеном и Тедом Чоттером.

   Добавлен в версии 2.5.

2. profile, чистый модуль Python, чей интерфейс имитируется cProfile, но который добавляет значительную накладную к профилируемым программам. Если вы пытаетесь каким-то образом расширить профилировщик, эта задача может быть проще с этим модулем. Первоначально разработан и написан Джимом Роскиндом.

   Изменено в версии 2.4: Теперь также сообщает о времени, затраченном на вызовы встроенных функций и методов.

3. hotshot был экспериментальным модулем C, который фокусировался на минимизации накладных расходов при профилировании, за счёт более длительных времен обработки данных после профилирования. Он больше не поддерживается и может быть удалён в будущих версиях Python.

   Изменено в версии 2.5: Результаты должны быть более осмысленными, чем раньше: ядро тайминга содержало критическую ошибку.

Модули profile и cProfile экспортируют одинаковый интерфейс, поэтому они в основном взаимозаменяемы; cProfile имеет гораздо меньшую накладную, но является более новым и может быть недоступен на всех системах. cProfile — это фактически слой совместимости поверх внутреннего модуля _lsprof. Модуль hotshot предназначен для специализированного использования.

2. Быстрый справочник пользователя

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

Для профилирования функции, принимающей один аргумент, можно выполнить:

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] myscript.py

-o записывает результаты профилирования в файл вместо стандартного вывода.

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

Модуль pstats и класс Stats имеют множество методов для обработки и вывода данных, сохранённых в файле результатов профилирования:

import pstats
p = pstats.Stats('restats')
p.strip_dirs().sort_stats(-1).print_stats()

Метод strip_dirs() удалил избыточный путь из всех имён модулей. Метод sort_stats() отсортировал все записи по стандартной строке модуль/строка/имя, которая выводится. Метод print_stats() вывел все статистические данные. Вы можете попробовать следующие вызовы сортировки:

p.sort_stats('name')
p.print_stats()

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

p.sort_stats('cumulative').print_stats(10)

Это сортирует профиль по кумулятивному времени в функции и затем выводит только десять наиболее важных строк. Если вы хотите понять, какие алгоритмы занимают много времени, вышеприведённая строка — то, что вам нужно.

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

p.sort_stats('time').print_stats(10)

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

Вы также можете попробовать:

p.sort_stats('file').print_stats('__init__')

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

p.sort_stats('time', 'cum').print_stats(.5, 'init')

Эта строка сортирует статистику по первичному ключу — времени, и вторичному ключу — кумулятивному времени, а затем выводит некоторые из статистических данных. Более конкретно, список сначала сокращается до 50% (см. .5) от исходного размера, затем сохраняются только строки, содержащие init, и выводится этот подсписок.

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

p.print_callers(.5, 'init')

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

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

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

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

3. Справочник по модулям 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)

Эта функция похожа на 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, StringIO
pr = cProfile.Profile()
pr.enable()
# ... do something ...
pr.disable()
s = StringIO.StringIO()
sortby = '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)

4. Класс 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.

New in version 2.3.

sort_stats(*keys)

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

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

Можно использовать сокращения для имён ключей, если сокращение однозначно. Вот текущие определенные ключи:

Допустимый аргумент	Значение
'calls'	количество вызовов
'cumulative'	накопленное время
'cumtime'	накопленное время
'file'	имя файла
'filename'	имя файла
'module'	имя файла
'ncalls'	количество вызовов
'pcalls'	количество вызовов функций первого уровня
'line'	номер строки
'name'	имя функции
'nfl'	имя/файл/строка
'stdname'	стандартное имя
'time'	внутреннее время
'tottime'	внутреннее время

Обратите внимание, что все сортировки по статистике выполняются в порядке убывания (сначала самые длительные операции), а сортировка по имени, файлу и номеру строки — в порядке возрастания (по алфавиту). Существенное различие между 'nfl' и 'stdname' заключается в том, что стандартное имя — это сортировка имени, как оно выводится, а это означает, что встроенные номера строк сравниваются странным образом. Например, строки 3, 20 и 40 (если имена файлов одинаковые) будут выведены в порядке 20, 3 и 40. В отличие от этого, 'nfl' выполняет числовое сравнение номеров строк. На самом деле, sort_stats('nfl') эквивалентно sort_stats('name', 'file', 'line').

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

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

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

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

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

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

6. Ограничения

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

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

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

7. Калибровка

Профилировщик модуля 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.clock()` Python в качестве таймера, это магическое число составляет около 4,04e-6.

Цель этого упражнения состоит в получении достаточно согласованного результата. Если ваш компьютер очень быстрый или функция таймера имеет низкое разрешение, вам может потребоваться передать значение 100000 или даже 1000000, чтобы получить согласованные результаты.

Когда вы получите согласованный ответ, у вас есть три способа его использования: 1

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)

Если есть выбор, лучше выбрать меньшую константу, тогда результаты «менее часто» будут отображаться как отрицательные в статистике профиля.

8. Использование пользовательского таймера

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

Примечания

1

До Python 2.2 было необходимо изменить исходный код профилировщика, чтобы встроить смещение в виде литерального числа. Вы всё ещё можете это сделать, но этот метод больше не описан, потому что он больше не нужен.