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

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

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

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

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

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

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

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

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

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

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

      214 function calls (207 primitive calls) in 0.002 seconds

Ordered by: cumulative time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1    0.000    0.000    0.002    0.002 {built-in method builtins.exec}
     1    0.000    0.000    0.001    0.001 <string>:1(<module>)
     1    0.000    0.000    0.001    0.001 __init__.py:250(compile)
     1    0.000    0.000    0.001    0.001 __init__.py:289(_compile)
     1    0.000    0.000    0.000    0.000 _compiler.py:759(compile)
     1    0.000    0.000    0.000    0.000 _parser.py:937(parse)
     1    0.000    0.000    0.000    0.000 _compiler.py:598(_code)
     1    0.000    0.000    0.000    0.000 _parser.py:435(_parse_sub)

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

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 <output_file>

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

-s <sort_order>

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

-m <module>

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

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

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

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

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

p.print_callers(.5, 'init')

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

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

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

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

Справочник по модулям profile и cProfile

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

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

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

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

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

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

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

exec(command, globals, locals)

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

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

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

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

Использование класса Profile напрямую позволяет форматировать результаты профилирования, не записывая данные профиля в файл:

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

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

import cProfile

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

    pr.print_stats()

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

enable()

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

disable()

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

create_stats()

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

print_stats(sort=-1)

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

Параметр sort задаёт порядок сортировки отображаемой статистики. Он принимает один ключ или кортеж ключей для многоуровневой сортировки, как и Stats.sort_stats.

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

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'	Н/Д	суммарное время
'file'	Н/Д	имя файла
'filename'	SortKey.FILENAME	имя файла
'module'	Н/Д	имя файла
'ncalls'	Н/Д	число вызовов
'pcalls'	SortKey.PCALLS	число примитивных вызовов
'line'	SortKey.LINE	номер строки
'name'	SortKey.NAME	имя функции
'nfl'	SortKey.NFL	имя/файл/строка
'stdname'	SortKey.STDNAME	стандартное имя
'time'	SortKey.TIME	внутреннее время
'tottime'	Н/Д	внутреннее время

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

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

Добавлено в версии 3.7: Добавлено перечисление 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().

get_stats_profile()

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

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

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