Профилировщики 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>

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

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

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:

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

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

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

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

reverse_order()

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

print_stats(*restrictions)

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

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

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

print_stats(.1, 'foo:')

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

print_stats('foo:', .1)

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

print_callers(*restrictions)

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

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

print_callees(*restrictions)

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

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