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

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

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 и 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% (относительно .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())

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

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

Когда предоставлено более одного ключа, дополнительные ключи используются в качестве вторичных критериев при равенстве по всем выбранным ранее ключам. Например, 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 печатает список всех функций, которые были вызваны указанной функцией. Помимо этого изменения направления вызовов (вызываемая vs. вызывающая), аргументы и порядок идентичны методу print_callers().

get_stats_profile()

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

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

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

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

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