PyMOTW: profile, cProfile, pstats
3 Septiembre 2008
Traducción de PyMOTW: profile, cProfile, pstats los módulos profile y cProfilede la columna semanal de Doug Hellmann.
Los módulos profile y cProfile proporcionan interfaces de programación para
coleccionar y analizar estadísticas sobre cómo código Python consume recursos de
procesamiento.
| Módulo: | profile |
|---|---|
| Propósito: | Análisis de de rendimiento de programas en Python |
| Versiones de Python: | 1.4 y posterior, estos ejemplos son para Python 2.5 |
run():
El punto más básico de inicio en el módulo profile es run(). Acepta una
cadena como argumento, y crea un reporte del tiempo empleado ejecutando diversas
líneas de código mientras ejecuta la instrucción.
import profile
def fib(n):
# de http://en.literateprograms.org/Fibonacci_numbers_(Python)
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
print 'RUDIMENTARIO'
print '=' * 80
profile.run('print fib_seq(20); print')
Esta versión recursiva de un calculador de una secuencia Fibonacci es
especialmente útil para demostrar el módulo profile porque podemos tanto
mejorar el rendimiento. El formato estándar del reporte muestra un sumario y
detalles de cada función ejecutada.
$ python profile_fibonacci_raw.py
RUDIMENTARIO
================================================================================
[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
57356 function calls (66 primitive calls) in 0.584 CPU seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
21 0.000 0.000 0.000 0.000 :0(append)
20 0.000 0.000 0.000 0.000 :0(extend)
1 0.000 0.000 0.000 0.000 :0(setprofile)
1 0.000 0.000 0.580 0.580 <string>:1(<module>)
1 0.004 0.004 0.584 0.584 profile:0(print fib_seq(20); print)
0 0.000 0.000 profile:0(profiler)
57291/21 0.580 0.000 0.580 0.028 profile_fibonacci_raw.py:13(fib)
21/1 0.000 0.000 0.580 0.580 profile_fibonacci_raw.py:22(fib_seq)
Como puedes ver, la ejecución requiere de 57356 invocaciones de función y toma
1/2 segundo. Ya que hay tan solo 66 invocaciones primitivas, sabemos que
la gran mayoría de las 57 mil invocaciones fueron recursivas. Los detalles
sobre donde se pasó el tiempo están separados por función en el listado que
muestra el numero de invocaciones, el tiempo total transcurrido en la función,
el tiempo por invocación (tottime/ncalls), tiempo acumulado transcurrido en
una función y la relación de tiempo acumulado a invocaciones primitivas.
No es sorprendente que la mayoría del tiempo aquí transcurre invocando fib()
en repetidas ocasiones. Podemos añadir un decorador memoize para reducir el
número de invocaciones recursivas y obtener un impacto importante en el
rendimiento de esta función.
import profile
class memoize:
# de http://avinashv.net/2008/04/python-decorators-syntactic-sugar/
def __init__(self, function):
self.function = function
self.memoized = {}
def __call__(self, *args):
try:
return self.memoized[args]
except KeyError:
self.memoized[args] = self.function(*args)
return self.memoized[args]
@memoize
def fib(n):
# de http://en.literateprograms.org/Fibonacci_numbers_(Python)
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__':
print 'MEMOIZADO'
print '=' * 80
profile.run('print fib_seq(20); print')
Recordando el valor de (la serie) Fibonacci podemos evitar la mayoría de la
recursión y reducir a 145 las invocaciones que tan sólo toman 0.008 segundos.
También nota que el contador ncalls para fib() muestra que nunca entra
en recursión.
$ python profile_fibonacci_memoized.py
MEMOIZADO
================================================================================
[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
145 function calls (87 primitive calls) in 0.008 CPU seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
21 0.000 0.000 0.000 0.000 :0(append)
20 0.000 0.000 0.000 0.000 :0(extend)
1 0.004 0.004 0.004 0.004 :0(setprofile)
1 0.000 0.000 0.004 0.004 <string>:1(<module>)
1 0.000 0.000 0.008 0.008 profile:0(print fib_seq(20); 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:26(fib)
21/1 0.004 0.000 0.004 0.004 profile_fibonacci_memoized.py:36(fib_seq)
runctx():
Obviamente, no siempre es fácil construir la expresión para pasar a run().
Algunas veces es más fácil construir una expresión simple y ejecutarla en un
contexto con (variables) globales y locales, 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" es pasado mediante el contexto de variables
locales en lugar de estar embebido directamente en la instrucción que se pasa a
runctx().
$ python profile_runctx.py
[0, 1, 1, 2, 3, 5, 8, 13, 21, 34, 55, 89, 144, 233, 377, 610, 987, 1597, 2584, 4181, 6765]
145 function calls (87 primitive calls) in 0.004 CPU seconds
Ordered by: standard name
ncalls tottime percall cumtime percall filename:lineno(function)
21 0.000 0.000 0.000 0.000 :0(append)
20 0.000 0.000 0.000 0.000 :0(extend)
1 0.000 0.000 0.000 0.000 :0(setprofile)
1 0.000 0.000 0.004 0.004 <string>:1(<module>)
1 0.000 0.000 0.004 0.004 profile:0(print fib_seq(n); print)
0 0.000 0.000 profile:0(profiler)
59/21 0.000 0.000 0.004 0.000 profile_fibonacci_memoized.py:19(__call__)
21 0.004 0.000 0.004 0.000 profile_fibonacci_memoized.py:26(fib)
21/1 0.000 0.000 0.004 0.004 profile_fibonacci_memoized.py:36(fib_seq)
pstats: Guardando y trabajando con estadíticas:
Si el reporte estándar no está formateado de la manera que lo necesitas, ambos
run() y runctx() aceptan un nombre de archivo como argumento para guardar
los datos en un archivo en lugar de mostrar el reporte. La clase Stats del
módulo pstats sabe cómo leer el archivo y puede ser usada para manipular los
datos.
Por ejemplo, para ejecutar varias veces el mismo test y combinar los resultados, puede hacer algo como esto:
import profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq
# Crea 5 conjuntos de estadística
filenames = []
for i in range(5):
filename = 'profile_stats_%d.stats' % i
profile.run('print %d, fib_seq(20)' % i, filename)
# Lee los 5 archivos con estadísticas en un solo objeto
stats = pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
stats.add('profile_stats_%d.stats' % i)
# Limpia nombres de archivos para el reporte
stats.strip_dirs()
# Ordena las estadísticas por el tiempo acumulado en la función
stats.sort_stats('cumulative')
stats.print_stats()
El reporte resultante está ordenado en orden descendiente de tiempo acumulado transcurrido en la función y los nombres de directorios son eliminados de los archivos mostrados para ahorra espacio horizontal.
$ python 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]
Wed Sep 3 21:22:27 2008 profile_stats_0.stats
Wed Sep 3 21:22:27 2008 profile_stats_1.stats
Wed Sep 3 21:22:27 2008 profile_stats_2.stats
Wed Sep 3 21:22:27 2008 profile_stats_3.stats
Wed Sep 3 21:22:27 2008 profile_stats_4.stats
489 function calls (351 primitive calls) in 0.032 CPU seconds
Ordered by: cumulative time
ncalls tottime percall cumtime percall filename:lineno(function)
5 0.004 0.001 0.024 0.005 <string>:1(<module>)
105/5 0.012 0.000 0.020 0.004 profile_fibonacci_memoized.py:36(fib_seq)
1 0.000 0.000 0.012 0.012 profile:0(print 0, fib_seq(20))
143/105 0.004 0.000 0.008 0.000 profile_fibonacci_memoized.py:19(__call__)
1 0.004 0.004 0.008 0.008 profile:0(print 3, fib_seq(20))
1 0.004 0.004 0.008 0.008 profile:0(print 1, fib_seq(20))
21 0.004 0.000 0.004 0.000 profile_fibonacci_memoized.py:26(fib)
1 0.000 0.000 0.004 0.004 profile:0(print 4, fib_seq(20))
105 0.000 0.000 0.000 0.000 :0(append)
5 0.000 0.000 0.000 0.000 :0(setprofile)
100 0.000 0.000 0.000 0.000 :0(extend)
1 0.000 0.000 0.000 0.000 profile:0(print 2, fib_seq(20))
0 0.000 0.000 profile:0(profiler)
Limitando el contenido del reporte:
Ya que estamos estudiando el rendimiento de fib() y fib_seq(), podemos
también restringir la salida del reporte para incluir estas funciones usando
una expresión regular que coincida con los valores de
archivo:línea(función) que queremos.
import profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq
# Lee los 5 archivos con estadísticas en un solo objeto
stats = pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
stats.add('profile_stats_%d.stats' % i)
stats.strip_dirs()
stats.sort_stats('cumulative')
# Limita el resulato a líneas con "(fib"
stats.print_stats('\(fib')
La expresión regular incluye un paréntesis izquierdo literal (() para coincidir
con la parte del nombre de la función del valor location.
$ python profile_stats_restricted.py
Wed Sep 3 21:22:27 2008 profile_stats_0.stats
Wed Sep 3 21:22:27 2008 profile_stats_1.stats
Wed Sep 3 21:22:27 2008 profile_stats_2.stats
Wed Sep 3 21:22:27 2008 profile_stats_3.stats
Wed Sep 3 21:22:27 2008 profile_stats_4.stats
489 function calls (351 primitive calls) in 0.032 CPU seconds
Ordered by: cumulative time
List reduced from 13 to 2 due to restriction <'\\(fib'>
ncalls tottime percall cumtime percall filename:lineno(function)
105/5 0.012 0.000 0.020 0.004 profile_fibonacci_memoized.py:36(fib_seq)
21 0.004 0.000 0.004 0.000 profile_fibonacci_memoized.py:26(fib)
Grafos de funciones invocadas e invocadoras (caller/callee):
Stats también incluye métodos para mostrar las funciones invocadas y quienes
las invocan.
import profile
import pstats
from profile_fibonacci_memoized import fib, fib_seq
# Lee los 5 archivos con estadísticas en un solo objeto
stats = pstats.Stats('profile_stats_0.stats')
for i in range(1, 5):
stats.add('profile_stats_%d.stats' % i)
stats.strip_dirs()
stats.sort_stats('cumulative')
print 'INVOCACIONES ENTRANTES:'
stats.print_callers('\(fib')
print 'INVOCACIONES SALIENTES:'
stats.print_callees('\(fib')
Los argumentos de print_callers() y print_callees() funciona de la misma
manera que los argumentos de restricción de print_stats(). El resultado
muestra en invocador (caller), el invocado (callee) y el tiempo acumulado.
$ python profile_stats_callers.py
INVOCACIONES ENTRANTES:
Ordered by: cumulative time
List reduced from 13 to 2 due to restriction <'\\(fib'>
Function was called by...
profile_fibonacci_memoized.py:36(fib_seq) <- <string>:1(<module>)(5) 0.024
profile_fibonacci_memoized.py:36(fib_seq)(100) 0.020
profile_fibonacci_memoized.py:26(fib) <- profile_fibonacci_memoized.py:19(__call__)(21) 0.008
INVOCACIONES SALIENTES:
Ordered by: cumulative time
List reduced from 13 to 2 due to restriction <'\\(fib'>
Function called...
profile_fibonacci_memoized.py:36(fib_seq) -> :0(append)(105) 0.000
:0(extend)(100) 0.000
profile_fibonacci_memoized.py:19(__call__)(105) 0.008
profile_fibonacci_memoized.py:36(fib_seq)(100) 0.020
profile_fibonacci_memoized.py:26(fib) -> profile_fibonacci_memoized.py:19(__call__)(38) 0.008
Referencias:
Python Module of the Week Home
Descarga el código
profile y cProfile
pstats
La implementación del ejemplo Fibonacci es de Fibonacci numbers (Python) - LiteratePrograms).
El decorador memoize es de Python Decorators: Syntactic Sugar | avinash.vora.
Copyright 2008 Doug Hellmann.
blog comments powered by Disqus