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

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

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

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

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

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

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

Примечание

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

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

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

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

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

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

Приведённая команда выполнит 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()

The strip_dirs() method removed the extraneous path from all the module names. The sort_stats() method sorted all the entries according to the standard module/line/name string that is printed. The print_stats() method printed out all the statistics. You might try the following sort calls:

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

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

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

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

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

runcall(func, *args, **kwargs)¶: Профилирует func(*args, **kwargs)

27.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.

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

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

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

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

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

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, чтобы получить стабильные результаты.

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

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)

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

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

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

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