Автор оригинала: Doug Hellmann.
Цель:
Анализ производительности программ Python.
Модуль profile предоставляет API для сбора и анализа статистики о том, как исходный код Python потребляет ресурсы процессора.
Примечание
Эти выходные отчеты в этом разделе были переформатированы, чтобы поместиться на странице. Строки, оканчивающиеся обратной косой чертой ( \ ), продолжаются на следующей строке.
Запуск профилировщика
Самая основная отправная точка в модуле profile – это run () . Он принимает строковый оператор в качестве аргумента и создает отчет о времени, затраченном на выполнение разных строк кода во время выполнения оператора.
profile_fibonacci_raw.py
import profile
def fib(n):
# from literateprograms.org
# http://bit.ly/hlOQ5m
if n 0:
return 0
elif n 1:
return 1
else:
return fib(n - 1) + fib(n - 2)
def fib_seq(n):
seq []
if n > 0:
seq.extend(fib_seq(n - 1))
seq.append(fib(n))
return seq
profile.run('print(fib_seq(20)); print()')Эта рекурсивная версия калькулятора последовательности Фибоначчи особенно полезна для демонстрации профиля, поскольку производительность может быть значительно улучшена. Стандартный формат отчета показывает сводку, а затем подробные сведения по каждой выполненной функции.
$ python3 profile_fibonacci_raw.py
[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 98\
7, 1597, 2584, 4181, 6765]
57359 function calls (69 primitive calls) in 0.127 seco\
nds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(fu\
nction)
21 0.000 0.000 0.000 0.000 :0(append)
1 0.000 0.000 0.127 0.127 :0(exec)
20 0.000 0.000 0.000 0.000 :0(extend)
2 0.000 0.000 0.000 0.000 :0(print)
1 0.001 0.001 0.001 0.001 :0(setprofile)
1 0.000 0.000 0.127 0.127 :1()
1 0.000 0.000 0.127 0.127 profile:0(print(fi\
b_seq(20)); print())
0 0.000 0.000 profile:0(profiler\
)
57291/21 0.126 0.000 0.126 0.006 profile_fibonacci_\
raw.py:11(fib)
21/1 0.000 0.000 0.127 0.127 profile_fibonacci_\
raw.py:22(fib_seq) Необработанная версия требует 57359 отдельных вызовов функций и 0,127 секунды на выполнение. Тот факт, что существует только 69 примитивных вызовов, говорит о том, что подавляющее большинство из этих 57k вызовов были рекурсивными. Подробная информация о том, где было потрачено время, разбита по функциям в листинге, показывающем количество вызовов, общее время, проведенное в функции, время на вызов (tottime/ncalls), совокупное время, проведенное в функции, и соотношение совокупного времени на примитивные звонки.
Неудивительно, что здесь большую часть времени тратится на многократные вызовы fib () . Добавление декоратора кеша снижает количество рекурсивных вызовов и оказывает большое влияние на производительность этой функции.
profile_fibonacci_memoized.py
import functools
import profile
@functools.lru_cache(maxsizeNone)
def fib(n):
# from literateprograms.org
# http://bit.ly/hlOQ5m
if n 0:
return 0
elif n 1:
return 1
else:
return fib(n - 1) + fib(n - 2)
def fib_seq(n):
seq []
if n > 0:
seq.extend(fib_seq(n - 1))
seq.append(fib(n))
return seq
if __name__ '__main__':
profile.run('print(fib_seq(20)); print()')Запоминая значение Фибоначчи на каждом уровне, можно избежать большей части рекурсии, и выполнение сокращается до 89 вызовов, которые занимают всего 0,001 секунды. Счетчик ncalls для fib () показывает, что он никогда не повторяется.
$ python3 profile_fibonacci_memoized.py
[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 98\
7, 1597, 2584, 4181, 6765]
89 function calls (69 primitive calls) in 0.001 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(fu\
nction)
21 0.000 0.000 0.000 0.000 :0(append)
1 0.000 0.000 0.000 0.000 :0(exec)
20 0.000 0.000 0.000 0.000 :0(extend)
2 0.000 0.000 0.000 0.000 :0(print)
1 0.001 0.001 0.001 0.001 :0(setprofile)
1 0.000 0.000 0.000 0.000 :1()
1 0.000 0.000 0.001 0.001 profile:0(print(fi\
b_seq(20)); print())
0 0.000 0.000 profile:0(profiler\
)
21 0.000 0.000 0.000 0.000 profile_fibonacci_\
memoized.py:12(fib)
21/1 0.000 0.000 0.000 0.000 profile_fibonacci_\
memoized.py:24(fib_seq) Запуск в контексте
Иногда вместо создания сложного выражения для run () проще создать простое выражение и передать его параметры через контекст с помощью runctx () .
profile_runctx.py
import profile
from profile_fibonacci_memoized import fib, fib_seq
if __name__ '__main__':
profile.runctx(
'print(fib_seq(n)); print()',
globals(),
{'n': 20},
)В этом примере значение n передается через контекст локальной переменной вместо того, чтобы быть встроенным непосредственно в оператор, переданный в runctx () .
$ python3 profile_runctx.py
[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610,
987, 1597, 2584, 4181, 6765]
148 function calls (90 primitive calls) in 0.002 seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(\
function)
21 0.000 0.000 0.000 0.000 :0(append)
1 0.000 0.000 0.001 0.001 :0(exec)
20 0.000 0.000 0.000 0.000 :0(extend)
2 0.000 0.000 0.000 0.000 :0(print)
1 0.001 0.001 0.001 0.001 :0(setprofile)
1 0.000 0.000 0.001 0.001 :1()
1 0.000 0.000 0.002 0.002 profile:0(print(fi\
b_seq(n)); print())
0 0.000 0.000 profile:0(profiler\
)
59/21 0.000 0.000 0.000 0.000 profile_fibonacci_\
memoized.py:19(__call__)
21 0.000 0.000 0.000 0.000 profile_fibonacci_\
memoized.py:27(fib)
21/1 0.000 0.000 0.001 0.001 profile_fibonacci_\
memoized.py:39(fib_seq) pstats: сохранение и работа со статистикой
Стандартный отчет, созданный функциями profile , не очень гибкий. Однако пользовательские отчеты можно создавать, сохраняя необработанные данные профилирования из run () и runctx () и обрабатывая их отдельно с помощью pstats.Stats класс.
В этом примере выполняется несколько итераций одного и того же теста и объединяются результаты:
profile_stats.py
import cProfile as profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq
# Create 5 set of stats
for i in range(5):
filename 'profile_stats_{}.stats'.format(i)
profile.run('print({}, fib_seq(20))'.format(i), filename)
# Read all 5 stats files into a single object
stats pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
stats.add('profile_stats_{}.stats'.format(i))
# Clean up filenames for the report
stats.strip_dirs()
# Sort the statistics by the cumulative time spent
# in the function
stats.sort_stats('cumulative')
stats.print_stats()Выходной отчет сортируется в порядке убывания совокупного времени, проведенного в функции, и имена каталогов удаляются из напечатанных имен файлов, чтобы сохранить горизонтальное пространство на странице.
$ python3 profile_stats.py
0 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, \
987, 1597, 2584, 4181, 6765]
1 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, \
987, 1597, 2584, 4181, 6765]
2 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, \
987, 1597, 2584, 4181, 6765]
3 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, \
987, 1597, 2584, 4181, 6765]
4 [0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, \
987, 1597, 2584, 4181, 6765]
Sat Dec 31 07:46:22 2016 profile_stats_0.stats
Sat Dec 31 07:46:22 2016 profile_stats_1.stats
Sat Dec 31 07:46:22 2016 profile_stats_2.stats
Sat Dec 31 07:46:22 2016 profile_stats_3.stats
Sat Dec 31 07:46:22 2016 profile_stats_4.stats
351 function calls (251 primitive calls) in 0.000 secon\
ds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(fu\
nction)
5 0.000 0.000 0.000 0.000 {built-in method b\
uiltins.exec}
5 0.000 0.000 0.000 0.000 :1()
105/5 0.000 0.000 0.000 0.000 profile_fibonacci_\
memoized.py:24(fib_seq)
5 0.000 0.000 0.000 0.000 {built-in method b\
uiltins.print}
100 0.000 0.000 0.000 0.000 {method 'extend' o\
f 'list' objects}
21 0.000 0.000 0.000 0.000 profile_fibonacci_\
memoized.py:12(fib)
105 0.000 0.000 0.000 0.000 {method 'append' o\
f 'list' objects}
5 0.000 0.000 0.000 0.000 {method 'disable' \
of '_lsprof.Profiler' objects} Ограничение содержания отчета
Выход может быть ограничен функцией. Эта версия показывает только информацию о производительности fib () и fib_seq () , используя регулярное выражение, соответствующее желаемому filename: lnine (function) значения.
profile_stats_restricted.py
import profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq
# Read all 5 stats files into a single object
stats pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
stats.add('profile_stats_{}.stats'.format(i))
stats.strip_dirs()
stats.sort_stats('cumulative')
# limit output to lines with "(fib" in them
stats.print_stats('\(fib')Регулярное выражение включает буквальную левую круглую скобку ( () для сопоставления с частью имени функции значения местоположения.
$ python3 profile_stats_restricted.py
Sat Dec 31 07:46:22 2016 profile_stats_0.stats
Sat Dec 31 07:46:22 2016 profile_stats_1.stats
Sat Dec 31 07:46:22 2016 profile_stats_2.stats
Sat Dec 31 07:46:22 2016 profile_stats_3.stats
Sat Dec 31 07:46:22 2016 profile_stats_4.stats
351 function calls (251 primitive calls) in 0.000 secon\
ds
Ordered by: cumulative time
List reduced from 8 to 2 due to restriction <'\\(fib'>
ncalls tottime percall cumtime percall filename:lineno(fu\
nction)
105/5 0.000 0.000 0.000 0.000 profile_fibonacci_\
memoized.py:24(fib_seq)
21 0.000 0.000 0.000 0.000 profile_fibonacci_\
memoized.py:12(fib)Графики вызывающих/вызывающих абонентов
Статистика также включает методы для печати вызывающих и вызываемых функций.
profile_stats_callers.py
import cProfile as profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq
# Read all 5 stats files into a single object
stats pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
stats.add('profile_stats_{}.stats'.format(i))
stats.strip_dirs()
stats.sort_stats('cumulative')
print('INCOMING CALLERS:')
stats.print_callers('\(fib')
print('OUTGOING CALLEES:')
stats.print_callees('\(fib')Аргументы для print_callers () и print_callees () работают так же, как аргументы ограничения для print_stats () . В выходных данных отображается вызывающий, вызываемый, количество вызовов и общее время.
$ python3 profile_stats_callers.py
INCOMING CALLERS:
Ordered by: cumulative time
List reduced from 8 to 2 due to restriction <'\\(fib'>
Function was called by...
ncalls tottime \
cumtime
profile_fibonacci_memoized.py:24(fib_seq) <- 5 0.000 \
0.000 :1()
100/5 0.000 \
0.000 profile_fibonacci_memoized.py:24(fib_seq)
profile_fibonacci_memoized.py:12(fib) <- 21 0.000 \
0.000 profile_fibonacci_memoized.py:24(fib_seq)
OUTGOING CALLEES:
Ordered by: cumulative time
List reduced from 8 to 2 due to restriction <'\\(fib'>
Function called...
ncalls tottime \
cumtime
profile_fibonacci_memoized.py:24(fib_seq) -> 21 0.000 \
0.000 profile_fibonacci_memoized.py:12(fib)
100/5 0.000 \
0.000 profile_fibonacci_memoized.py:24(fib_seq)
105 0.000 \
0.000 {method 'append' of 'list' objects}
100 0.000 \
0.000 {method 'extend' of 'list' objects}
profile_fibonacci_memoized.py:12(fib) -> Смотрите также
- стандартная библиотечная документация для профиля
- functools.lru_cache () – декоратор кеша, используемый для повышения производительности в этом примере.
- Класс Stats – стандартная библиотека документации для
pstats.Stats . - Gprof2Dot – инструмент визуализации выходных данных профиля.
- Декораторы Python: синтаксический сахар | avinash.vora – еще один запоминающийся генератор последовательности Фибоначчи на Python.
- Smiley – средство отслеживания приложений Python