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


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

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

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

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

Примечание

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

Быстрое руководство пользователя

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

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

import cProfile
import re
cProfile.run('re.compile("foo|bar")')

(Используйте profile вместо cProfile, если последний недоступен в вашей системе.)

Приведённое выше действие будет запускать re.compile() и печатать результаты профиля, как показано ниже:

      197 function calls (192 primitive calls) in 0.002 seconds

Ordered by: standard name

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1    0.000    0.000    0.001    0.001 <string>:1(<module>)
     1    0.000    0.000    0.001    0.001 re.py:212(compile)
     1    0.000    0.000    0.001    0.001 re.py:268(_compile)
     1    0.000    0.000    0.000    0.000 sre_compile.py:172(_compile_charset)
     1    0.000    0.000    0.000    0.000 sre_compile.py:201(_optimize_charset)
     4    0.000    0.000    0.000    0.000 sre_compile.py:25(_identityfunction)
   3/1    0.000    0.000    0.000    0.000 sre_compile.py:33(_compile)

В первой строке указано, что было отслежено 197 вызовов. Из данных вызовов 192 были примитивными, что означает, что вызов не был вызван рекурсией. Следующая строка: Ordered by: standard name указывает, что текстовая строка в крайнем правом столбце использовалась для сортировки вывода. Заголовки столбцов включают:

ncalls
на количество вызовов.
tottime
за общее время, проведенное в данной функции (без учета времени, проведенного в вызовы подфункций)
percall
представляет собой частное tottime, делённое на ncalls
cumtime
это совокупное время, затраченное на эту и все подфункции (с момента вызова до выхода). Данный рисунок точен даже для рекурсивных функций.
percall
является частным cumtime, разделённым на примитивные вызовы
filename:lineno(function)
предоставляет соответствующие данные каждой функции

Когда в первом столбце два числа (например, 3/1), это означает, что функция рекурсивна. Второе значение — это количество примитивных вызовов, а первое — общее количество вызовов. Обратите внимание, что когда функция не рекурсивна, данные два значения совпадают, и печатается только одна цифра.

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

import cProfile
import re
cProfile.run('re.compile("foo|bar")', 'restats')

Класс pstats.Stats считывает результаты профиля из файла и форматирует их различными способами.

Файлы cProfile и profile также можно вызывать как сценарий для профилирования другого сценария. Например:

python -m cProfile [-o output_file] [-s sort_order] (-m module | myscript.py)

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

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

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

Добавлено в версии 3.7: Добавлен параметр -m в cProfile.

Добавлено в версии 3.8: Добавлен параметр -m в profile.

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

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()
# ... сделать что-нибудь ...
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:
    # ... сделать что-нибудь ...

pr.print_stats()

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

enable()

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

disable()

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

create_stats()

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

print_stats(sort=-1)

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

dump_stats(filename)

Записать результаты текущего профиля в filename.

run(cmd)

Профилировать cmd через exec().

runctx(cmd, globals, locals)

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

runcall(func, *args, **kwargs)

Профилирование func(*args, **kwargs)

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

Класс Stats

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

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

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

dump_stats(filename)

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

sort_stats(*keys)

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

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

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

Ниже приведены допустимая строка и SortKey:

Правильная строка Arg Правильный enum Arg Смысл
'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 и 1. Напротив, 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: вызванный vs был вызван), аргументы и порядок идентичны методу print_callers().

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

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

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

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

Ограничения

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

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

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

Калибровка

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

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

Код выполняет количество вызовов Python, заданное аргументом, напрямую и снова под профилировщиком, измеряя время для обоих. Затем он вычисляет скрытые служебные данные для каждого события профилировщика и возвращает его в виде числа с плавающей запятой. Например, на процессоре Intel Core i5 с тактовой частотой 1,8 ГГц под управлением Mac OS X и использовании в качестве таймера Python time.process_time() магическое число составляет около 4,04e-6.

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

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

import profile

# 1. Применить вычисленное смещение ко всем экземплярам Profile, созданным ниже.
profile.Profile.bias = your_computed_bias

# 2. Применить вычисленное смещение к экземпляру Profile.
pr = profile.Profile()
pr.bias = your_computed_bias

# 3. Указать вычисленное смещение в конструкторе экземпляра.
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 должен возвращать один номер или список номеров, чьи sum — это текущее время (например, то, что возвращает 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().