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

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

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

Стандартная библиотека Python предоставляет два различных профилировщика:

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

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

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

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

Чтобы профилировать приложение с главной точкой входа foo(), вы должны добавить следующее в ваш модуль:

import cProfile
cProfile.run('foo()')

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

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

import cProfile
cProfile.run('foo()', 'fooprof')

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

python -m cProfile myscript.py

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

cProfile.py [-o output_file] [-s sort_order]

-s применяется только к стандартному выводу (если не указан -o). Обратитесь к документации Stats для получения допустимых значений сортировки.

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

import pstats
p = pstats.Stats('fooprof')

Класс Stats (приведенный выше код только что создал экземпляр этого класса) имеет множество методов для обработки и вывода данных, которые были только что прочитаны в p. Когда вы запустили cProfile.run() выше, выведенный результат представлял собой результат трех вызовов методов:

p.strip_dirs().sort_stats(-1).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('fooprof')

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

26.3.3. Что такое детерминированное профилирование?¶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.3.4. Справочное руководство – profile и cProfile¶Reference Manual – profile and cProfile

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

cProfile.run(command, filename=None, sort=-1)¶

Эта функция принимает один аргумент, который можно передать функции exec(), и необязательное имя файла. Во всех случаях эта процедура пытается выполнить exec() свой первый аргумент и собирает статистику профилирования из выполнения. Если имя файла не указано, эта функция автоматически выводит простой отчет о профилировании, отсортированный по стандартной строке имени (файл/строка/имя-функции), которая представлена в каждой строке. Ниже приведен типичный вывод такого вызова:

      2706 function calls (2004 primitive calls) in 4.504 CPU seconds

Ordered by: standard name

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     2    0.006    0.003    0.953    0.477 pobject.py:75(save_objects)
  43/3    0.533    0.012    0.749    0.250 pobject.py:99(evaluate)
 ...

Первая строка показывает, что было отслежено 2706 вызовов. Из этих вызовов 2004 были первичными. Мы определяем первичный как вызов, который не был вызван рекурсией. Следующая строка: Упорядочено по: стандартному имени, указывает, что текстовая строка в крайнем правом столбце использовалась для сортировки вывода. Заголовки столбцов включают:

ncalls

– количество вызовов,

tottime

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

percall

– результат деления tottime на ncalls

cumtime

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

percall

– результат деления cumtime на количество первичных вызовов

filename:lineno(function)

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

Если в первом столбце два числа (например, 43/3), то последнее – это количество первичных вызовов, а первое – фактическое количество вызовов. Обратите внимание, что если функция не рекурсивна, эти два значения совпадают, и выводится только одно число.

Если указан аргумент sort, он может быть одним из значений, допустимых для параметра key из pstats.Stats.sort_stats().

cProfile.runctx(command, globals, locals, filename=None)¶

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

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

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

Конструктор этого класса создает экземпляр «объекта статистики» из filename (или набора имен файлов). Объекты Stats управляются методами для вывода полезных отчетов. Можно указать альтернативный выходной поток данных, передав именованный аргумент stream.

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

26.3.5. Ограничения¶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.3.6. Калибровка¶Calibration

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

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

Метод выполняет количество вызовов Python, заданное аргументом, напрямую и снова под профилировщиком, измеряя время для обоих случаев. Затем он вычисляет скрытые накладные расходы на каждое событие профилировщика и возвращает их как число с плавающей запятой. Например, на Pentium 800 МГц под Windows 2000 с использованием time.clock() в качестве таймера это магическое число составляет около 12.5e-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)

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

26.3.7. Расширения – создание более совершенных профилировщиков¶Extensions – Deriving Better Profilers

Класс Profile обоих модулей, profile и cProfile, был написан так, чтобы можно было разрабатывать производные классы, расширяющие профилировщик. Подробности здесь не описываются, поскольку для успешного выполнения этого требуется экспертное понимание внутренней работы класса Profile. Если вы хотите этим заняться, внимательно изучите исходный код модуля.

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

pr = profile.Profile(your_time_func)

Полученный профилировщик будет вызывать your_time_func().

profile.Profile

your_time_func() должна возвращать одно число или список чисел, сумма которых даёт текущее время (как возвращает os.times()). Если функция возвращает одно число времени или список длины 2, то будет использована особенно быстрая версия диспетчера.

Имейте в виду, что следует откалибровать класс профилировщика для выбранной функции таймера. На большинстве машин таймер, возвращающий одно целое число, даёт наилучшие результаты с точки зрения низких накладных расходов при профилировании. (os.times() довольно плох, так как возвращает кортеж чисел с плавающей запятой). Если вы хотите заменить таймер наиболее чистым способом, создайте производный класс и жёстко пропишите замену метода диспетчера, который наилучшим образом обрабатывает ваш вызов таймера, вместе с соответствующей константой калибровки.

cProfile.Profile

your_time_func() должна возвращать одно число. Если она возвращает целые числа, можно также вызвать конструктор класса со вторым аргументом, указывающим реальную длительность одной единицы времени. Например, если your_integer_time_func() возвращает время, измеряемое в тысячных долях секунды, то экземпляр Profile создаётся следующим образом:

pr = profile.Profile(your_integer_time_func, 0.001)

Поскольку класс cProfile.Profile нельзя откалибровать, пользовательские функции таймера следует использовать с осторожностью, и они должны быть максимально быстрыми. Для достижения наилучших результатов с пользовательским таймером может потребоваться жёстко закодировать его в исходном коде C внутреннего модуля _lsprof.