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

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

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

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

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

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

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

-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) и интерактивную справку.

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

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

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

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

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

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

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

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

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

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

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 и с использованием функции времени Python time.clock() магическое число составляет примерно 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)

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

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