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

Источник: Lib/profile.py и Lib/pstats.py

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

cProfile и profile обеспечивают deterministic profiling программ на Python. profile - это набор статистических данных, описывающих, как часто и как долго выполняются различные части программы. Эта статистика может быть отформатирована в отчеты с помощью модуля 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() и выведет результаты профиля, как показано ниже:

      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 были primitive, что означает, что вызов не был вызван через рекурсию. Следующая строка: Ordered by: cumulative time указывает на то, что вывод отсортирован по значениям cumtime. Заголовки столбцов включают:

ncalls

по количеству звонков.

tottime

общее время, затраченное на выполнение данной функции (без учета времени, затраченного на обращение к подфункциям)

percall

это коэффициент tottime, деленный на ncalls.

кумтайм

это суммарное время, затраченное на выполнение данной и всех подфункций (от вызова до выхода). Эта цифра точна даже для рекурсивных функций.

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 записывает результаты профиля в файл, а не в stdout

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

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

Added in version 3.7: Добавлена опция -m к cProfile.

Added in version 3.8: Добавлена опция -m к profile.

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

Эта строка сортирует статистику с первичным ключом time и вторичным ключом cumulative time, а затем распечатывает некоторые из них. Если быть точным, то сначала список сокращается до 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 и печатает простой отчет о профилировании. Если указано значение sort, то оно передается этому экземпляру 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 на основе текущего профиля и выведите результаты в stdout.

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

Added in version 3.13: print_stats() теперь принимает кортеж ключей.

dump_stats(filename)

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

run(cmd)

Передайте команду через exec().

runctx(cmd, globals, locals)

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

runcall(func, /, *args, **kwargs)

Профиль func(*args, **kwargs)

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

The 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: file, line, name) функций автоматически накапливается в статистику одной функции.

dump_stats(filename)

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

sort_stats(*keys)

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

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

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

Ниже перечислены допустимые варианты строк и ключей SortKey:

Допустимый строковый аргумент

Допустимое перечисление Arg

Значение

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

Added in version 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: called vs was called by), аргументы и порядок следования идентичны методу print_callers().

get_stats_profile()

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

Added in version 3.9: Добавлены следующие классы данных: StatsProfile, FunctionProfile. Добавлена следующая функция: get_stats_profile.

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

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

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

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

Ограничения

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

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

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

Калибровка

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

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

Метод выполняет заданное аргументом количество вызовов Python напрямую и под профилировщиком, измеряя время на оба вызова. Затем он вычисляет скрытые накладные расходы на каждое событие профилировщика и возвращает их в виде плавающей величины. Например, на 1,8-гигагерцевом Intel Core i5 под управлением 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()). Если функция возвращает единственное число времени или список возвращаемых чисел имеет длину 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().