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

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

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

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

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

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

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

Новое в версии 2.5.
profile, чисто Python-модуль, чей интерфейс имитируется cProfile, но который добавляет значительные накладные расходы профилируемым программам. Если требуется расширить профилировщик каким-либо образом, задача может оказаться проще с этим модулем. Изначально спроектирован и написан Джимом Роскиндом.

Изменено в версии 2.4: Теперь также сообщается время, затраченное на вызовы встроенных функций и методов.
hotshot был экспериментальным модулем на C, ориентированным на минимизацию накладных расходов профилирования ценой увеличения времени последующей обработки данных. Он больше не поддерживается и может быть удалён в одной из будущих версий Python.

Изменено в версии 2.5: Результаты теперь должны быть более осмысленными, чем раньше: ядро измерения времени содержало критическую ошибку.

Модули profile и cProfile экспортируют один и тот же интерфейс, так что они в основном взаимозаменяемы; cProfile имеет гораздо меньшие накладные расходы, но является более новым и может быть недоступен во всех системах. cProfile на самом деле является уровнем совместимости поверх внутреннего модуля _lsprof. Модуль hotshot предназначен для специализированного использования.

Примечание

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

26.4.2. Краткое руководство пользователя¶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 можно также запустить как сценарий для профилирования другого сценария. Например:

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

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

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

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

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', 'cum').print_stats(.5, 'init')

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

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

p.print_callers(.5, 'init')

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

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

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

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

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

Оба модуля 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)¶

Эта функция аналогична 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, StringIO
pr = cProfile.Profile()
pr.enable()
# ... сделать что-то ...
pr.disable()
s = StringIO.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 на основе текущего профиля и вывести результаты в stdout.

dump_stats(filename)¶: Записать результаты текущего профиля в filename.

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

runctx(cmd, globals, locals)¶: Профилировать cmd с помощью exec() с указанным глобальным и локальным окружением.

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

26.4.4. Класс `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.

Новое в версии 2.3.

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

26.4.5. Что такое детерминированное профилирование?¶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.

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

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

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

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

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

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

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

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

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)

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

26.4.8. Использование пользовательского таймера¶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.

Сноски

1: До Python 2.2 необходимо было редактировать исходный код профилировщика, чтобы встроить смещение как литеральное число. Это всё ещё возможно, но этот метод больше не описывается, так как больше не нужен.