¿Aumentando la profundidad de cProfiler en Python para reportar más funciones?

Question

Estoy tratando de perfilar una función que llame a otras funciones. Me llamo el generador de perfiles de la siguiente manera:

from mymodule import foo 
def start(): 
    # ... 
    foo() 

import cProfile as profile 
profile.run('start()', output_file) 
p = pstats.Stats(output_file) 
print "name: " 
print p.sort_stats('name') 
print "all stats: " 
p.print_stats() 
print "cumulative (top 10): " 
p.sort_stats('cumulative').print_stats(10) 

Me parece que el perfilador dice todo el tiempo se gasta en la función "foo()" de mimodulo, en lugar de brekaing abajo en el foo subfunciones() llama, que es lo que quiero ver ¿Cómo puedo hacer que el generador de perfiles informe el rendimiento de estas funciones?

gracias.

Answer 1

Tal vez se enfrentó con un problema similar, así que voy a describir aquí mi problema. Mi código de perfiles se veía así:

def foobar(): 
    import cProfile 
    pr = cProfile.Profile() 
    pr.enable() 
    for event in reader.events(): 
     baz() 
     # and other things 

    pr.disable() 
    pr.dump_stats('result.prof') 

Y la salida de perfiles final contenía solamente events() llamada. Y pasé no tan poco tiempo para darme cuenta de que tenía un perfil de bucle vacío. Por supuesto, hubo más de una llamada de foobar() desde un código de cliente, pero los resultados significativos de creación de perfiles se sobrescribieron con la última llamada con bucle vacío.

Answer 2

Necesita p.print_callees() para obtener un desglose jerárquico de las llamadas a métodos. El resultado es bastante explicativo: en la columna de la izquierda puede encontrar su función de interés, p. foo(), luego ir a la columna del lado derecho muestra todas las subfunciones llamadas y sus tiempos totales y acumulativos del alcance. Las averías para estas sub-llamadas también están incluidas, etc.

Answer 3

Primero, quiero decir que no he podido replicar el problema del Asker. El generador de perfiles (en py2.7) definitivamente desciende a las funciones y métodos llamados. (Los documentos para py3.6 parecen idénticos, pero no los he probado en py3.) Supongo que al limitarlo a los 10 retornos principales, ordenados por tiempo acumulativo, los primeros N de esos fueron funciones de muy alto nivel llamadas un mínimo de tiempo, y las funciones llamadas por foo() cayeron en la parte inferior de la lista.

Decidí jugar con algunos números grandes para probar. Aquí está mi código de prueba:

# file: mymodule.py 
import math 

def foo(n = 5): 
    for i in xrange(1,n): 
     baz(i) 
     bar(i ** i) 

def bar(n): 
    for i in xrange(1,n): 
     e = exp200(i) 
     print "len e: ", len("{}".format(e)) 

def exp200(n): 
    result = 1 
    for i in xrange(200): 
     result *= n 
    return result 

def baz(n): 
    print "{}".format(n) 

y el archivo que incluye (muy similar al autor de la pregunta de):

# file: test.py 

from mymodule import foo 

def start(): 
    # ... 
    foo(8) 

OUTPUT_FILE = 'test.profile_info' 

import pstats 
import cProfile as profile 

profile.run('start()', OUTPUT_FILE) 
p = pstats.Stats(OUTPUT_FILE) 
print "name: " 
print p.sort_stats('name') 
print "all stats: " 
p.print_stats() 
print "cumulative (top 10): " 
p.sort_stats('cumulative').print_stats(10) 
print "time (top 10): " 
p.sort_stats('time').print_stats(10) 

Aviso de la última línea. Agregué una vista ordenada por time, que es el tiempo total empleado en la función "excluding time made in calls to sub-functions". Encuentro esta vista mucho más útil, ya que tiende a favorecer las funciones que están haciendo un trabajo real, y puede necesitar una optimización.

Aquí es la parte de los resultados que el autor de la pregunta estaba trabajando a partir de (cumulative -sorted):

cumulative (top 10): 
Thu Mar 24 21:26:32 2016 test.profile_info 

     2620840 function calls in 76.039 seconds 

    Ordered by: cumulative time 

    ncalls tottime percall cumtime percall filename:lineno(function) 
     1 0.000 0.000 76.039 76.039 <string>:1(<module>) 
     1 0.000 0.000 76.039 76.039 test.py:5(start) 
     1 0.000 0.000 76.039 76.039 /Users/jhazen/mymodule.py:4(foo) 
     7 10.784 1.541 76.039 10.863 /Users/jhazen/mymodule.py:10(bar) 
    873605 49.503 0.000 49.503 0.000 /Users/jhazen/mymodule.py:15(exp200) 
    873612 15.634 0.000 15.634 0.000 {method 'format' of 'str' objects} 
    873605 0.118 0.000 0.118 0.000 {len} 
     7 0.000 0.000 0.000 0.000 /Users/jhazen/mymodule.py:21(baz) 
     1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 

ver cómo los 3 mejores funciones de esta pantalla sólo se llama una vez. Veamos la vista time -sorted:

time (top 10): 
Thu Mar 24 21:26:32 2016 test.profile_info 

     2620840 function calls in 76.039 seconds 

    Ordered by: internal time 

    ncalls tottime percall cumtime percall filename:lineno(function) 
    873605 49.503 0.000 49.503 0.000 /Users/jhazen/mymodule.py:15(exp200) 
    873612 15.634 0.000 15.634 0.000 {method 'format' of 'str' objects} 
     7 10.784 1.541 76.039 10.863 /Users/jhazen/mymodule.py:10(bar) 
    873605 0.118 0.000 0.118 0.000 {len} 
     7 0.000 0.000 0.000 0.000 /Users/jhazen/mymodule.py:21(baz) 
     1 0.000 0.000 76.039 76.039 /Users/jhazen/mymodule.py:4(foo) 
     1 0.000 0.000 76.039 76.039 test.py:5(start) 
     1 0.000 0.000 76.039 76.039 <string>:1(<module>) 
     1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 

Ahora la entrada número uno tiene sentido. Obviamente elevar algo a la potencia número 200 por multiplicación repetida es una estrategia "ingenua".Vamos a reemplazarlo:

def exp200(n): 
    return n ** 200 

Y los resultados:

time (top 10): 
Thu Mar 24 21:32:18 2016 test.profile_info 

     2620840 function calls in 30.646 seconds 

    Ordered by: internal time 

    ncalls tottime percall cumtime percall filename:lineno(function) 
    873612 15.722 0.000 15.722 0.000 {method 'format' of 'str' objects} 
     7 9.760 1.394 30.646 4.378 /Users/jhazen/mymodule.py:10(bar) 
    873605 5.056 0.000 5.056 0.000 /Users/jhazen/mymodule.py:15(exp200) 
    873605 0.108 0.000 0.108 0.000 {len} 
     7 0.000 0.000 0.000 0.000 /Users/jhazen/mymodule.py:18(baz) 
     1 0.000 0.000 30.646 30.646 /Users/jhazen/mymodule.py:4(foo) 
     1 0.000 0.000 30.646 30.646 test.py:5(start) 
     1 0.000 0.000 30.646 30.646 <string>:1(<module>) 
     1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 

Esa es una buena mejora en el tiempo. Ahora str.format() es nuestro peor ofensor. Agregué la línea en bar() para imprimir la longitud del número, porque mi primer intento (solo computar el número y no hacer nada con él) se optimizó, y mi intento de evitar eso (imprimiendo el número, que realmente se puso muy rápido)) parecía que podría estar bloqueando en E/S, por lo que me comprometí a imprimir la longitud del número. Oye, ese es el registro de base 10. Vamos a tratar de que:

def bar(n): 
    for i in xrange(1,n): 
     e = exp200(i) 
     print "log e: ", math.log10(e) 

Y los resultados:

time (top 10): 
Thu Mar 24 21:40:16 2016 test.profile_info 

     1747235 function calls in 11.279 seconds 

    Ordered by: internal time 

    ncalls tottime percall cumtime percall filename:lineno(function) 
     7 6.082 0.869 11.279 1.611 /Users/jhazen/mymodule.py:10(bar) 
    873605 4.996 0.000 4.996 0.000 /Users/jhazen/mymodule.py:15(exp200) 
    873605 0.201 0.000 0.201 0.000 {math.log10} 
     7 0.000 0.000 0.000 0.000 /Users/jhazen/mymodule.py:18(baz) 
     1 0.000 0.000 11.279 11.279 /Users/jhazen/mymodule.py:4(foo) 
     7 0.000 0.000 0.000 0.000 {method 'format' of 'str' objects} 
     1 0.000 0.000 11.279 11.279 test.py:5(start) 
     1 0.000 0.000 11.279 11.279 <string>:1(<module>) 
     1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 

Hmm, sigue siendo una buena cantidad de tiempo invertido en bar(), incluso sin la str.format(). Vamos a deshacernos de esa impresión:

def bar(n): 
    z = 0 
    for i in xrange(1,n): 
     e = exp200(i) 
     z += math.log10(e) 
    return z 

Y los resultados:

time (top 10): 
Thu Mar 24 21:45:24 2016 test.profile_info 

     1747235 function calls in 5.031 seconds 

    Ordered by: internal time 

    ncalls tottime percall cumtime percall filename:lineno(function) 
    873605 4.487 0.000 4.487 0.000 /Users/jhazen/mymodule.py:17(exp200) 
     7 0.440 0.063 5.031 0.719 /Users/jhazen/mymodule.py:10(bar) 
    873605 0.104 0.000 0.104 0.000 {math.log10} 
     7 0.000 0.000 0.000 0.000 /Users/jhazen/mymodule.py:20(baz) 
     1 0.000 0.000 5.031 5.031 /Users/jhazen/mymodule.py:4(foo) 
     7 0.000 0.000 0.000 0.000 {method 'format' of 'str' objects} 
     1 0.000 0.000 5.031 5.031 test.py:5(start) 
     1 0.000 0.000 5.031 5.031 <string>:1(<module>) 
     1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects} 

Ahora parece que las cosas haciendo el trabajo real es la función más ocupado, así que creo que hemos terminado de optimización.

Espero que ayude!