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

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

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

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

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

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

27.4.2. Быстрое руководство пользователя

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

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

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

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

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

      197 function calls (192 primitive calls) in 0.002 seconds

Ordered by: standard name

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1    0.000    0.000    0.001    0.001 <string>:1(<module>)
     1    0.000    0.000    0.001    0.001 re.py:212(compile)
     1    0.000    0.000    0.001    0.001 re.py:268(_compile)
     1    0.000    0.000    0.000    0.000 sre_compile.py:172(_compile_charset)
     1    0.000    0.000    0.000    0.000 sre_compile.py:201(_optimize_charset)
     4    0.000    0.000    0.000    0.000 sre_compile.py:25(_identityfunction)
   3/1    0.000    0.000    0.000    0.000 sre_compile.py:33(_compile)

Первая строка указывает, что было отслежено 197 вызовов. Из них 192 были примитивными, что означает, что вызов не был вызван рекурсией. Следующая строка: Ordered by: standard name, указывает, что строка текста в правом столбце использовалась для сортировки вывода. Заголовки столбцов включают:

ncalls

для количества вызовов.

tottime

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

percall

является частным от tottime делённое на ncalls

cumtime

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

percall

является частным от cumtime делённое на число примитивных вызовов

filename:lineno(function)

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

Когда в первом столбце присутствуют две цифры (например, 3/1), это означает, что функция рекурсировала. Второе значение — это количество примитивных вызовов, а первое — общее количество вызовов. Обратите внимание, что когда функция не рекурсирует, эти два значения совпадают и выводится только одна цифра.

Вместо вывода результатов в конце выполнения профилирования, вы можете сохранить результаты в файл, указав имя файла функции run():

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

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

Файл cProfile также может быть вызван как скрипт для профилирования другого скрипта. Например:

python -m cProfile [-o output_file] [-s sort_order] myscript.py

-o записывает результаты профилирования в файл вместо стандартного вывода.

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

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

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

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

p.sort_stats('name')
p.print_stats()

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

p.sort_stats('cumulative').print_stats(10)

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

Если вы хотели увидеть функции, которые много циклились и тратили много времени, вы бы сделали:

p.sort_stats('time').print_stats(10)

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

Вы также можете попробовать:

p.sort_stats('file').print_stats('__init__')

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

p.sort_stats('time', 'cumulative').print_stats(.5, 'init')

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

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

p.print_callers(.5, 'init')

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

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

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

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

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

exec(command, globals, locals)

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

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

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

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

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

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

enable()

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

disable()

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

create_stats()

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

print_stats(sort=-1)

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

dump_stats(filename)

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

run(cmd)

Профилировать cmd с помощью exec().

runctx(cmd, globals, locals)

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

runcall(func, *args, **kwargs)

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

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

27.4.4. Класс Stats

Анализ данных профилировщика выполняется с помощью класса Stats.

class pstats.Stats(*filenames or profile, stream=sys.stdout)

Конструктор этого класса создаёт экземпляр «объекта статистики» из имени файла (или списка имён файлов) или из объекта Profile. Вывод будет выведен в поток, указанный параметром stream.

Файл, выбранный вышеуказанным конструктором, должен был быть создан соответствующей версией profile или cProfile. Более конкретно, никакой гарантии совместимости файлов с будущими версиями этого профилировщика нет, а также нет совместимости с файлами, созданными другими профилировщиками, или тем же профилировщиком, запущенным на другой операционной системе. Если предоставлено несколько файлов, вся статистика для одинаковых функций будет объединена, так что в одном отчёте можно будет рассмотреть общий обзор нескольких процессов. Если необходимо объединить дополнительные файлы с данными в существующем объекте Stats, можно использовать метод add().

Вместо чтения данных профилирования из файла можно использовать объект cProfile.Profile или profile.Profile в качестве источника данных профилирования.

Stats объекты имеют следующие методы:

strip_dirs()

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

add(*filenames)

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

dump_stats(filename)

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

sort_stats(*keys)

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

При предоставлении нескольких ключей дополнительные ключи используются как вторичные критерии при равенстве по всем ключам, выбранным перед ними. Например, sort_stats('name', 'file') отсортирует все записи по имени функции и разрешит все ничьи (одинаковые имена функций) путём сортировки по имени файла.

Для имён ключей могут использоваться сокращения, при условии, что сокращение однозначно. Ниже приведены текущие определённые ключи:

Действительный аргумент	Значение
'calls'	число вызовов
'cumulative'	кумулятивное время
'cumtime'	кумулятивное время
'file'	имя файла
'filename'	имя файла
'module'	имя файла
'ncalls'	число вызовов
'pcalls'	число примитивных вызовов
'line'	номер строки
'name'	имя функции
'nfl'	имя/файл/строка
'stdname'	стандартное имя
'time'	внутреннее время
'tottime'	внутреннее время

Обратите внимание, что все сортировки статистики выполняются в порядке убывания (с наибольшим временем выполнения вначале), в то время как поиск по имени, файлу и номеру строки выполняется в порядке возрастания (по алфавиту). Немного отличается 'nfl' от 'stdname', так как стандартное имя - это сортировка имени при печати, что означает, что встроенные номера строк сравниваются странным образом. Например, строки 3, 20 и 40 (если имена файлов были бы одинаковыми) появились бы в строковом порядке 20, 3 и 40. В отличие от этого, 'nfl' выполняет числовое сравнение номеров строк. Фактически, sort_stats('nfl') равно sort_stats('name', 'file', 'line').

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

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

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

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

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

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

27.4.6. Ограничения

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

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

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

27.4.7. Калибровка

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

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

Метод выполняет заданное количество вызовов Python непосредственно и ещё раз под управлением профилировщика, измеряя время в обоих случаях. Затем он вычисляет скрытые накладные расходы на событие профилировщика и возвращает это значение как число с плавающей точкой. Например, на компьютере с процессором Intel Core i5 1,8 ГГц под управлением Mac OS X и с использованием функции `time.clock()` Python в качестве таймера магическое число составляет около 4,04e-6.

Цель этого упражнения — получить довольно согласованный результат. Если ваш компьютер очень быстрый или функция таймера имеет низкое разрешение, вам может потребоваться передать значение 100000 или даже 1000000, чтобы получить согласованные результаты.

Когда вы получите согласованный ответ, есть три способа его использования:

import profile

# 1. Apply computed bias to all Profile instances created hereafter.
profile.Profile.bias = your_computed_bias

# 2. Apply computed bias to a specific Profile instance.
pr = profile.Profile()
pr.bias = your_computed_bias

# 3. Specify computed bias in instance constructor.
pr = profile.Profile(bias=your_computed_bias)

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

27.4.8. Использование пользовательского таймера

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