Содержание страницы

Профилировщики Python¶The Python Profilers

Исходный код: Lib/profile.py и Lib/pstats.py

Введение в профилировщики¶Introduction to the profilers

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

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

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

Примечание

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

Краткое руководство пользователя¶Instant User’s Manual

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

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

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

(Use profile instead of cProfile if the latter is not available on your system.)

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

function calls (192 primitive calls) in 0.002 seconds

Ordered by: standard name

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  0.000    0.000    0.001    0.001 <string>:1(<module>)
  0.000    0.000    0.001    0.001 re.py:212(compile)
  0.000    0.000    0.001    0.001 re.py:268(_compile)
  0.000    0.000    0.000    0.000 sre_compile.py:172(_compile_charset)
  0.000    0.000    0.000    0.000 sre_compile.py:201(_optimize_charset)
  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 записывает результаты профилирования в файл, а не в stdout

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

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

Новое в версии 3.7: Добавлена опция -m в cProfile.

Новое в версии 3.8: Добавлена опция -m в profile.

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

import pstats
from pstats import SortKey
p = pstats.Stats('restats')
p.strip_dirs().sort_stats(-1).print_stats()

Метод strip_dirs() удаляет лишние пути из всех имён модулей. Метод sort_stats() сортирует все записи по стандартной строке модуль/строка/имя, которая выводится. Метод print_stats() выводит всю статистику. Можно попробовать следующие вызовы сортировки:

p.sort_stats(SortKey.NAME)
p.print_stats()

Первый вызов сортирует список по имени функции, а второй вызов выводит статистику. Вот несколько интересных вызовов для экспериментов:

p.sort_stats(SortKey.CUMULATIVE).print_stats(10)

Это сортирует профиль по суммарному времени в функции и затем выводит только десять наиболее значимых строк. Чтобы понять, какие алгоритмы занимают время, следует использовать приведённую выше строку.

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

p.sort_stats(SortKey.TIME).print_stats(10)

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

Можно также попробовать:

p.sort_stats(SortKey.FILENAME).print_stats('__init__')

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

p.sort_stats(SortKey.TIME, SortKey.CUMULATIVE).print_stats(.5, 'init')

Эта строка сортирует статистику сначала по времени, затем по суммарному времени, и выводит часть статистики. Если точнее, список сначала сокращается до 50% (отн. .5) от исходного размера, затем оставляются только строки, содержащие init, и выводится этот под-под-список.

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

p.print_callers(.5, 'init')

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

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

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

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

`profile` и `cProfile` Справочник по модулям¶profile and cProfile Module Reference

Оба модуля 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(), но с дополнительными аргументами для передачи словарей globals и locals для строки command. Данная процедура выполняет:

exec(command, globals, locals)

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

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

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

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

Непосредственное использование класса Profile позволяет форматировать результаты профилирования без записи данных профиля в файл:

import cProfile, pstats, io
from pstats import SortKey
pr = cProfile.Profile()
pr.enable()
# ... сделать что-то ...
pr.disable()
s = io.StringIO()
sortby = SortKey.CUMULATIVE
ps = pstats.Stats(pr, stream=s).sort_stats(sortby)
ps.print_stats()
print(s.getvalue())

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

import cProfile

with cProfile.Profile() as pr:
    # ... сделать что-то ...

    pr.print_stats()

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

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

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

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

print_stats(sort=- 1)¶: Создать объект Stats на основе текущего профиля и вывести результаты в 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`¶The Stats Class

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

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

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

Что такое детерминированное профилирование?¶What Is Deterministic Profiling?

Deterministic profiling is meant to reflect the fact that all function call, function return, and exception events are monitored, and precise timings are made for the intervals between these events (during which time the user’s code is executing). In contrast, statistical profiling (which is not done by this module) randomly samples the effective instruction pointer, and deduces where time is being spent. The latter technique traditionally involves less overhead (as the code does not need to be instrumented), but provides only relative indications of where time is being spent.

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

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

Ограничения¶Limitations

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

The second problem is that it “takes a while” from when an event is dispatched until the profiler’s call to get the time actually gets the state of the clock. Similarly, there is a certain lag when exiting the profiler event handler from the time that the clock’s value was obtained (and then squirreled away), until the user’s code is once again executing. As a result, functions that are called many times, or call many functions, will typically accumulate this error. The error that accumulates in this fashion is typically less than the accuracy of the clock (less than one clock tick), but it can accumulate and become very significant.

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

Калибровка¶Calibration

Профилировщик модуля 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. Применить вычисленное смещение ко всем экземплярам Profile, создаваемым в дальнейшем.
profile.Profile.bias = your_computed_bias

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

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

Если есть выбор, лучше выбрать меньшую константу – тогда результаты будут «реже» отображаться как отрицательные в статистике профилирования.

Использование пользовательского таймера¶Using a custom timer

Если требуется изменить способ определения текущего времени (например, принудительно использовать wall-clock time или время процесса), передайте нужную функцию таймера в конструктор класса 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().