Профайлери Python

Вихідний код: Lib/profile.py і Lib/pstats.py

Знайомство з профайлерами

cProfile і profile забезпечують детермінізоване профілювання програм Python. profile — це набір статистичних даних, який описує, як часто та як довго виконуються різні частини програми. Цю статистику можна форматувати у звіти за допомогою модуля pstats.

Стандартна бібліотека Python надає дві різні реалізації одного інтерфейсу профілювання:

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

  2. profile, чистий модуль Python, інтерфейс якого імітується cProfile, але який додає значні накладні витрати на профільовані програми. Якщо ви намагаєтеся якимось чином розширити профайлер, завдання може бути легшим із цим модулем. Спочатку розроблений і написаний Джимом Роскіндом.

Примітка

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

Посібник користувача Instant

Цей розділ призначений для користувачів, які «не хочуть читати посібник». Він надає дуже короткий огляд і дозволяє користувачеві швидко виконувати профілювання існуючої програми.

Для профілювання функції, яка приймає один аргумент, ви можете зробити:

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)

The first line indicates that 197 calls were monitored. Of those calls, 192 were primitive, meaning that the call was not induced via recursion. The next line: Ordered by: standard name, indicates that the text string in the far right column was used to sort the output. The column headings include:

виклики

за кількість дзвінків.

tottime

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

percall

це частка tottime, поділена на ncalls

cumtime

це сукупний час, витрачений на цю та всі підфункції (від виклику до виходу). Ця цифра точна навіть для рекурсивних функцій.

percall

це частка cumtime, поділена на примітивні виклики

ім’я файлу: lineno(функція)

надає відповідні дані кожної функції

Якщо в першому стовпці є два числа (наприклад, 3/1), це означає, що функція рекурсувала. Друге значення — це кількість первинних викликів, а перше — загальна кількість викликів. Зауважте, що коли функція не рекурсує, ці два значення однакові, і друкується лише одна цифра.

Замість того, щоб друкувати вихідні дані в кінці запуску профілю, ви можете зберегти результати у файлі, вказавши ім’я файлу у функції run():

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

Клас pstats.Stats читає результати профілю з файлу та форматує їх різними способами.

Файли cProfile і profile також можна викликати як сценарій для профілювання іншого сценарію. Наприклад:

python -m cProfile [-o output_file] [-s sort_order] (-m module | myscript.py)

-o записує результати профілю у файл замість stdout

-s вказує одне зі значень сортування sort_stats() для сортування виводу. Це стосується лише випадків, коли -o не вказано.

-m вказує, що профільується модуль замість сценарію.

Нове в версії 3.7: Додано опцію -m до cProfile.

Нове в версії 3.8: Додано опцію -m до profile.

Клас Stats модуля pstats має різноманітні методи для обробки та друку даних, збережених у файлі результатів профілю:

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

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

p.sort_stats(SortKey.NAME)
p.print_stats()

Перший виклик фактично відсортує список за назвою функції, а другий виклик роздрукує статистику. Нижче наведено кілька цікавих викликів для експериментів:

p.sort_stats(SortKey.CUMULATIVE).print_stats(10)

Це сортує профіль за сукупним часом у функції, а потім друкує лише десять найважливіших рядків. Якщо ви хочете зрозуміти, які алгоритми потребують часу, ви б використали рядок вище.

Якби ви хотіли побачити, які функції часто зациклюються та займають багато часу, ви б зробили:

p.sort_stats(SortKey.TIME).print_stats(10)

щоб відсортувати відповідно до часу, витраченого на виконання кожної функції, а потім надрукувати статистику для перших десяти функцій.

Ви також можете спробувати:

p.sort_stats(SortKey.FILENAME).print_stats('__init__')

Це відсортує всю статистику за назвою файлу, а потім роздрукує статистику лише для методів ініціалізації класу (оскільки в них пишеться __init__). Як останній приклад, ви можете спробувати:

p.sort_stats(SortKey.TIME, SortKey.CUMULATIVE).print_stats(.5, 'init')

Цей рядок сортує статистичні дані за первинним ключем часу та вторинним ключем сукупного часу, а потім роздруковує деякі статистичні дані. Щоб бути конкретним, список спочатку відбирається до 50% (re: .5) від його початкового розміру, потім зберігаються лише рядки, що містять init, і цей підпідсписок друкується.

Якщо вам було цікаво, які функції називають наведені вище функції, ви можете тепер (p все ще сортується за останнім критерієм) зробити:

p.print_callers(.5, 'init')

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

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

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

Викликаний як скрипт, модуль pstats є браузером статистики для читання та вивчення дампів профілю. Він має простий рядково-орієнтований інтерфейс (реалізований за допомогою cmd) та інтерактивну довідку.

Довідка про модуль 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)

This function is similar to run(), with added arguments to supply the globals and locals dictionaries for the command string. This routine executes:

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
from pstats import SortKey
pr = cProfile.Profile()
pr.enable()
# ... do something ...
pr.disable()
s = io.StringIO()
sortby = SortKey.CUMULATIVE
ps = pstats.Stats(pr, stream=s).sort_stats(sortby)
ps.print_stats()
print(s.getvalue())

Клас Profile також можна використовувати як менеджер контексту (підтримується лише в модулі cProfile. Див. Типи менеджера контексту):

import cProfile

with cProfile.Profile() as pr:
    # ... do something ...

pr.print_stats()

Змінено в версії 3.8: Додано підтримку менеджера контексту.

enable()

Почніть збирати дані профілювання. Тільки в cProfile.

disable()

Припиніть збір даних профілювання. Тільки в cProfile.

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)

Зауважте, що профілювання працюватиме, лише якщо викликана команда/функція дійсно повернеться. Якщо інтерпретатор завершується (наприклад, через виклик sys.exit() під час виконання викликаної команди/функції), результати профілювання не друкуються.

Клас 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(). Статистика для функцій з ідентичними назвами (re: файл, рядок, ім’я) автоматично накопичується в одній статистиці функції.

dump_stats(filename)

Збережіть дані, завантажені в об’єкт Stats, у файл з назвою filename. Файл створюється, якщо він не існує, і перезаписується, якщо він уже існує. Це еквівалентно однойменному методу в класах profile.Profile і cProfile.Profile.

sort_stats(*keys)

Цей метод змінює об’єкт Stats, сортуючи його відповідно до наданих критеріїв. Аргументом може бути рядок або перелік SortKey, що визначає основу сортування (приклад: 'time', 'name', SortKey.TIME або SortKey.NAME). Аргумент переліку SortKey має перевагу над рядковим аргументом у тому, що він більш надійний і менш схильний до помилок.

Якщо надається більше одного ключа, то додаткові ключі використовуються як вторинні критерії, якщо є рівність у всіх ключах, вибраних перед ними. Наприклад, sort_stats(SortKey.NAME, SortKey.FILE) відсортує всі записи відповідно до їхньої назви функції та розв’яже всі зв’язки (ідентичні назви функції) шляхом сортування за назвою файлу.

Для рядкового аргументу можна використовувати абревіатури для будь-яких імен ключів, за умови, що скорочення є однозначним.

Нижче наведено дійсний рядок і SortKey:

Дійсний рядковий аргумент

Дійсний перелік Arg

Значення

'дзвінки'

SortKey.CALLS

кількість дзвінків

'кумулятивний''

SortKey.CUMULATIVE

кумулятивний час

'cumtime''

N/A

кумулятивний час

''файл'

N/A

ім’я файлу

'ім'я файлу'

SortKey.FILENAME

ім’я файлу

''модуль'

N/A

ім’я файлу

'calls''

N/A

кількість дзвінків

'pcalls'

SortKey.PCALLS

примітивний підрахунок викликів

''рядок'

SortKey.LINE

номер рядка

''ім'я'

SortKey.NAME

назва функції

'nfl'

SortKey.NFL

ім’я/файл/рядок

'stdname'

SortKey.STDNAME

стандартна назва

'час''

SortKey.TIME

внутрішній час

'tottime'

N/A

внутрішній час

Зауважте, що всі сортування в статистиці виконуються в порядку спадання (першими розміщуються елементи, що вимагають більше часу), а пошук імені, файлу та номера рядка здійснюється в порядку зростання (за алфавітом). Тонка різниця між SortKey.NFL і SortKey.STDNAME полягає в тому, що стандартна назва є різновидом назви, як надруковано, що означає, що вбудовані номери рядків порівнюються дивним чином. Наприклад, рядки 3, 20 і 40 (якби імена файлів були однаковими) відображалися б у порядку рядків 20, 3 і 40. На відміну від цього, SortKey.NFL виконує числове порівняння номерів рядків. Фактично, sort_stats(SortKey.NFL) те саме, що sort_stats(SortKey.NAME, SortKey.FILENAME, SortKey.LINE).

З міркувань зворотної сумісності дозволені числові аргументи -1, 0, 1 і 2. Вони інтерпретуються як 'stdname', 'calls', 'time' і 'cumulative' відповідно. Якщо використовується цей формат старого стилю (числовий), використовуватиметься лише один ключ сортування (числовий ключ), а додаткові аргументи мовчки ігноруватимуться.

Нове в версії 3.7: Додано перелік SortKey.

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 друкує список усіх функцій, викликаних зазначеною функцією. Окрім зміни напрямку викликів (re: called проти was called by), аргументи та порядок ідентичні методу print_callers().

get_stats_profile()

Цей метод повертає екземпляр StatsProfile, який містить зіставлення імен функцій з екземплярами FunctionProfile. Кожен екземпляр FunctionProfile містить інформацію, пов’язану з профілем функції, наприклад, скільки часу знадобилося для виконання функції, скільки разів її викликали тощо…

Нове в версії 3.9: Додано такі класи даних: StatsProfile, FunctionProfile. Додано таку функцію: get_stats_profile.

Що таке детерміноване профілювання?

Deterministic profiling призначене для відображення того факту, що всі події виклику функції, повернення функції та виключення відстежуються, а також точні часові інтервали між цими подіями (протягом часу, протягом якого користувач код виконується). На відміну від цього, statistical profiling (яке не виконується цим модулем) випадково відбирає ефективний вказівник інструкції та визначає, де витрачається час. Останній метод традиційно передбачає менше накладних витрат (оскільки код не потребує інструментарію), але забезпечує лише відносні показники того, де витрачається час.

У Python, оскільки під час виконання активний інтерпретатор, наявність інструментального коду не потрібна для виконання детермінованого профілювання. Python автоматично надає hook (додатковий зворотний виклик) для кожної події. Крім того, інтерпретована природа Python має тенденцію додавати стільки накладних витрат на виконання, що детерміноване профілювання має тенденцію лише додавати невеликі накладні витрати на обробку в типових програмах. Результатом є те, що детерміноване профілювання не таке вже й дороге, але забезпечує розширену статистику часу виконання про виконання програми Python.

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

Обмеження

Одне обмеження пов’язане з точністю інформації про час. Існує фундаментальна проблема з детермінованим профайлером, пов’язана з точністю. Найбільш очевидним обмеженням є те, що основний «годинник» цокає лише зі швидкістю (зазвичай) приблизно 0,001 секунди. Тому жодні вимірювання не будуть точнішими, ніж базовий годинник. Якщо проведено достатньо вимірювань, «похибка» матиме тенденцію до усереднення. На жаль, видалення цієї першої помилки спричиняє друге джерело помилки.

Друга проблема полягає в тому, що «потрібен деякий час» від моменту надсилання події до моменту, коли виклик профайлера для отримання часу фактично отримує стан годинника. Подібним чином існує певна затримка під час виходу з обробника подій профайлера з моменту, коли було отримано значення годинника (і потім вилучено), до моменту, коли код користувача знову виконується. У результаті функції, які викликаються багато разів або викликають багато функцій, зазвичай накопичуватимуть цю помилку. Похибка, яка накопичується таким чином, зазвичай менша, ніж точність годинника (менше одного такту), але вона може накопичуватися і стати дуже значною.

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

Калібрування

Профайлер модуля profile віднімає константу від часу обробки кожної події, щоб компенсувати накладні витрати на виклик функції часу та накопичення результатів. За замовчуванням константа дорівнює 0. Наступну процедуру можна використати, щоб отримати кращу константу для даної платформи (див. Обмеження).

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

Метод виконує кількість викликів Python, заданих аргументом, безпосередньо та знову під профайлером, вимірюючи час для обох. Потім він обчислює приховані накладні витрати на кожну подію профілювача та повертає їх як число з плаваючою точкою. Наприклад, на процесорі Intel Core i5 з тактовою частотою 1,8 ГГц, який працює під керуванням macOS і використовує Python time.process_time() як таймер, магічне число становить приблизно 4,04e-6.

Мета цієї вправи — отримати досить послідовний результат. Якщо ваш комп’ютер дуже швидкий або ваша функція таймера має низьку роздільну здатність, вам, можливо, доведеться передати 100 000 або навіть 1000 000, щоб отримати стабільні результати.

Якщо у вас є послідовна відповідь, ви можете використовувати її трьома способами:

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)

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

Використання спеціального таймера

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

pr = profile.Profile(your_time_func)

Потім отриманий профайлер викличе your_time_func. Залежно від того, чи використовуєте ви profile.Profile чи cProfile.Profile, значення, що повертається your_time_func, буде інтерпретуватися по-різному:

профіль.Профіль

your_time_func має повертати одне число або список чисел, сума яких є поточним часом (як те, що повертає os.times()). Якщо функція повертає єдине число часу або список повернутих чисел має довжину 2, тоді ви отримаєте особливо швидку версію процедури відправки.

Be warned that you should calibrate the profiler class for the timer function that you choose (see Калібрування). For most machines, a timer that returns a lone integer value will provide the best results in terms of low overhead during profiling. (os.times() is pretty bad, as it returns a tuple of floating point values). If you want to substitute a better timer in the cleanest fashion, derive a class and hardwire a replacement dispatch method that best handles your timer call, along with the appropriate calibration constant.

cProfile.Profile

your_time_func має повертати одне число. Якщо він повертає цілі числа, ви також можете викликати конструктор класу з другим аргументом, який визначає реальну тривалість однієї одиниці часу. Наприклад, якщо your_integer_time_func повертає час, виміряний у тисячах секунд, ви повинні створити екземпляр Profile наступним чином:

pr = cProfile.Profile(your_integer_time_func, 0.001)

As the cProfile.Profile class cannot be calibrated, custom timer functions should be used with care and should be as fast as possible. For the best results with a custom timer, it might be necessary to hard-code it in the C source of the internal _lsprof module.

Python 3.3 додає кілька нових функцій у time, які можна використовувати для точного вимірювання часу процесу або настінного годинника. Наприклад, перегляньте time.perf_counter().