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.

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()')

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.

profile_fibonacci_memoized.py
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().

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},
    )

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:

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()

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.

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')

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.

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')

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