profile y pstats — Análisis de rendimiento¶
Propósito: | Análisis de rendimiento de programas Python. |
---|
El módulo profile
proporciona una interfaz de programación para recopilar y
analizar estadísticas sobre cómo la fuente Python consume recursos del
procesador.
Nota
Los informes de esta salida en esta sección se han reformateado para
ajustarse a la página. Las líneas que terminan con la barra diagonal
inversa (\
) continúan en la línea siguiente.
Ejecutando el Profiler¶
El punto de partida más básico en el módulo profile
es run()
. Toma una
declaración de cadena como argumento y crea un informe del tiempo dedicado a
ejecutar diferentes líneas de código mientras se ejecuta la declaración.
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()')
Esta versión recursiva de una calculadora de secuencia de Fibonacci es especialmente útil para demostrar el perfil porque el rendimiento se puede mejorar significativamente. El formato de informe estándar muestra un resumen y luego detalles para cada función ejecutada.
$ 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 <string>:1(<module\
>)
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)
La versión sin procesar tarda 57359 llamadas a funciones separadas y 0.127 segundos para ejecutarse. El hecho de que solo haya 69 llamadas primitivas dice que la gran mayoría de esas 57k llamadas fueron recursivas. Los detalles sobre dónde se gastó el tiempo se desglosan por función en la lista que muestra el número de llamadas, el tiempo total gastado en la función, el tiempo por llamada (tottime/ncalls), el tiempo acumulado gastado en una función y la relación del tiempo acumulado a llamadas primitivas.
No es sorprendente que la mayor parte del tiempo aquí se gaste llamando
repetidamente a fib()
. Agregar un decorador de caché reduce la cantidad de
llamadas recursivas y tiene un gran impacto en el rendimiento de esta función.
import functools
import profile
@functools.lru_cache(maxsize=None)
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()')
Al recordar el valor de Fibonacci en cada nivel, se evita la mayor parte de la
recursión y la ejecución se reduce a 89 llamadas que solo toman 0.001 segundos.
El recuento de ncalls
para fib()
muestra que nunca se repite.
$ 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 <string>:1(<module\
>)
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)
Ejecutando en un contexto¶
A veces, en lugar de construir una expresión compleja para run()
, es más
fácil construir una expresión simple y pasarle parámetros a través de un
contexto, usando runctx()
.
import profile
from profile_fibonacci_memoized import fib, fib_seq
if __name__ == '__main__':
profile.runctx(
'print(fib_seq(n)); print()',
globals(),
{'n': 20},
)
En este ejemplo, el valor de n
se pasa a través del contexto de la variable
local en lugar de incrustarse directamente en la declaración pasada a
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 <string>:1(<module\
>)
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: guardar y trabajar con estadísticas¶
El informe estándar creado por las funciones de profile
no es muy flexible.
Sin embargo, se pueden generar informes personalizados guardando los datos de
perfiles sin procesar de run()
y runctx()
y procesándolos por separado
con la clase pstats.Stats
.
Este ejemplo ejecuta varias iteraciones de la misma prueba y combina los resultados:
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()
El informe de salida se ordena en orden descendente de tiempo acumulado en la función y los nombres de directorio se eliminan de los nombres de archivo impresos para conservar el espacio horizontal en la página.
$ 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 <string>:1(<module\
>)
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}
Limitar el contenido del informe¶
La salida se puede restringir por función. Esta versión solo muestra
información sobre el rendimiento de fib()
y fib_seq()
mediante el uso
de una expresión regular para que coincida con los valores
filename:lineno(function)
deseados.
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')
La expresión regular incluye un paréntesis izquierdo literal ((
) para que
coincida con la parte del nombre de la función del valor de ubicación.
$ 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)
Gráficos de llamador y llamado¶
Stats
también incluye métodos para imprimir las personas que llaman y las
llamadas de funciones.
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')
Los argumentos para print_callers()
y print_callees()
funcionan igual
que los argumentos de restricción para print_stats()
. La salida muestra la
persona que llama, la persona que llama, el número de llamadas y el tiempo
acumulado.
$ 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 <string>:1(<module>)
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) ->
Ver también
- Documentación de la biblioteca estándar para profile
- functools.lru_cache() – El decorador de caché utilizado para mejorar el rendimiento en este ejemplo.
- The Stats class –
Documentación de la biblioteca estándar para
pstats.Stats
. - Gprof2Dot – Herramienta de visualización para datos de salida de profile.
- Python Decorators: Syntactic Sugar | avinash.vora – Otro generador de secuencias de Fibonacci memorable en Python.
- Smiley – Rastreador de aplicaciones Python