cprofile python 3

Python obtiene resultados significativos de cProfile

Question

Tengo un script de Python en un archivo que tarda unos 30 segundos en ejecutarse. Estoy tratando de perfilarlo ya que me gustaría reducirlo dramáticamente.

Estoy tratando de perfilar el script utilizando cProfile , pero básicamente todo lo que parece decirme es que sí, el script principal tardó mucho tiempo en ejecutarse, pero no da el tipo de desglose que esperaba. En la terminal, escribo algo como:

cat my_script_input.txt | python -m cProfile -s time my_script.py

Los resultados que obtengo son:

<my_script_output>
             683121 function calls (682169 primitive calls) in 32.133 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1   31.980   31.980   32.133   32.133 my_script.py:18(<module>)
   121089    0.050    0.000    0.050    0.000 {method ''split'' of ''str'' objects}
   121090    0.038    0.000    0.049    0.000 fileinput.py:243(next)
        2    0.027    0.014    0.036    0.018 {method ''sort'' of ''list'' objects}
   121089    0.009    0.000    0.009    0.000 {method ''strip'' of ''str'' objects}
   201534    0.009    0.000    0.009    0.000 {method ''append'' of ''list'' objects}
   100858    0.009    0.000    0.009    0.000 my_script.py:51(<lambda>)
      952    0.008    0.000    0.008    0.000 {method ''readlines'' of ''file'' objects}
 1904/952    0.003    0.000    0.011    0.000 fileinput.py:292(readline)
    14412    0.001    0.000    0.001    0.000 {method ''add'' of ''set'' objects}
      182    0.000    0.000    0.000    0.000 {method ''join'' of ''str'' objects}
        1    0.000    0.000    0.000    0.000 fileinput.py:80(<module>)
        1    0.000    0.000    0.000    0.000 fileinput.py:197(__init__)
        1    0.000    0.000    0.000    0.000 fileinput.py:266(nextfile)
        1    0.000    0.000    0.000    0.000 {isinstance}
        1    0.000    0.000    0.000    0.000 fileinput.py:91(input)
        1    0.000    0.000    0.000    0.000 fileinput.py:184(FileInput)
        1    0.000    0.000    0.000    0.000 fileinput.py:240(__iter__)
        1    0.000    0.000    0.000    0.000 {method ''disable'' of ''_lsprof.Profiler'' objects}

Esto no parece que me esté diciendo nada útil. La gran mayoría de las veces se enumera simplemente como:

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1   31.980   31.980   32.133   32.133 my_script.py:18(<module>)

En my_script.py , la línea 18 no es más que el """ cierre del comentario del bloque de encabezado del archivo, por lo que no es que haya una carga completa de trabajo concentrada en la línea 18. La secuencia de comandos en su totalidad está compuesta principalmente por líneas Procesamiento basado en la mayoría con algunas tareas de división, clasificación y trabajo de conjuntos, por lo que esperaba encontrar la mayor parte del tiempo en una o más de estas actividades. Tal como está, ver todo el tiempo agrupado en los resultados de cProfile como resultado de un comentario la línea no tiene ningún sentido o al menos no arroja ninguna luz sobre lo que realmente está consumiendo todo el tiempo.

EDITAR: He construido un ejemplo de trabajo mínimo similar a mi caso anterior para demostrar el mismo comportamiento:

mwe.py

import fileinput

for line in fileinput.input():
    for i in range(10):
        y = int(line.strip()) + int(line.strip())

Y llámalo con:

perl -e ''for(1..1000000){print "$_/n"}'' | python -m cProfile -s time mwe.py

Para obtener el resultado:

         22002536 function calls (22001694 primitive calls) in 9.433 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    8.004    8.004    9.433    9.433 mwe.py:1(<module>)
 20000000    1.021    0.000    1.021    0.000 {method ''strip'' of ''str'' objects}
  1000001    0.270    0.000    0.301    0.000 fileinput.py:243(next)
  1000000    0.107    0.000    0.107    0.000 {range}
      842    0.024    0.000    0.024    0.000 {method ''readlines'' of ''file'' objects}
 1684/842    0.007    0.000    0.032    0.000 fileinput.py:292(readline)
        1    0.000    0.000    0.000    0.000 fileinput.py:80(<module>)
        1    0.000    0.000    0.000    0.000 fileinput.py:91(input)
        1    0.000    0.000    0.000    0.000 fileinput.py:197(__init__)
        1    0.000    0.000    0.000    0.000 fileinput.py:184(FileInput)
        1    0.000    0.000    0.000    0.000 fileinput.py:266(nextfile)
        1    0.000    0.000    0.000    0.000 {isinstance}
        1    0.000    0.000    0.000    0.000 fileinput.py:240(__iter__)
        1    0.000    0.000    0.000    0.000 {method ''disable'' of ''_lsprof.Profiler'' objects}

¿Estoy usando cProfile incorrectamente de alguna manera?

Answer 1

Como mencioné en un comentario, cuando no puede hacer que cProfile funcione externamente, a menudo puede usarlo internamente. No es tan dificil.

Por ejemplo, cuando ejecuto con -m cProfile en mi Python 2.7, obtengo efectivamente los mismos resultados que obtuviste. Pero cuando instalo manualmente su programa de ejemplo:

import fileinput
import cProfile

pr = cProfile.Profile()
pr.enable()
for line in fileinput.input():
    for i in range(10):
        y = int(line.strip()) + int(line.strip())
pr.disable()
pr.print_stats(sort=''time'')

... esto es lo que obtengo:

         22002533 function calls (22001691 primitive calls) in 3.352 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
 20000000    2.326    0.000    2.326    0.000 {method ''strip'' of ''str'' objects}
  1000001    0.646    0.000    0.700    0.000 fileinput.py:243(next)
  1000000    0.325    0.000    0.325    0.000 {range}
      842    0.042    0.000    0.042    0.000 {method ''readlines'' of ''file'' objects}
 1684/842    0.013    0.000    0.055    0.000 fileinput.py:292(readline)
        1    0.000    0.000    0.000    0.000 fileinput.py:197(__init__)
        1    0.000    0.000    0.000    0.000 fileinput.py:91(input)
        1    0.000    0.000    0.000    0.000 {isinstance}
        1    0.000    0.000    0.000    0.000 fileinput.py:266(nextfile)
        1    0.000    0.000    0.000    0.000 fileinput.py:240(__iter__)
        1    0.000    0.000    0.000    0.000 {method ''disable'' of ''_lsprof.Profiler'' objects}

Eso es mucho más útil: le dice lo que probablemente ya esperaba, que se gasta más de la mitad de su tiempo en llamar a str.strip() .

Además, tenga en cuenta que si no puede editar el archivo que contiene el código que desea perfilar ( mwe.py ), siempre puede hacer esto:

import cProfile
pr = cProfile.Profile()
pr.enable()
import mwe
pr.disable()
pr.print_stats(sort=''time'')

Incluso eso no siempre funciona. Si su programa llama a exit() , por ejemplo, tendrá que usar try: / finally: wrapper y / o atexit . Y se llama os._exit() , o segfaults, probablemente estás completamente perdido. Pero eso no es muy común.

Sin embargo, algo que descubrí más tarde: si mueve todo el código fuera del alcance global, -m cProfile parece funcionar, al menos para este caso. Por ejemplo:

import fileinput

def f():
    for line in fileinput.input():
        for i in range(10):
            y = int(line.strip()) + int(line.strip())
f()

Ahora la salida de -m cProfile incluye, entre otras cosas:

2000000 4.819 0.000 4.819 0.000: 0 (tira) 100001 0.288 0.000 0.295 0.000 fileinput.py:243 (siguiente)

No tengo idea de por qué esto también lo hizo el doble de lento ... o tal vez eso es solo un efecto de caché; han pasado unos minutos desde la última vez que lo ejecuté, y he hecho un montón de navegación web entre ellos. Pero eso no es importante, lo importante es que la mayoría del tiempo se está cargando en lugares razonables.

Pero si cambio esto para mover el bucle externo al nivel global, y solo su cuerpo en una función, la mayoría del tiempo desaparece de nuevo.

Otra alternativa, que no sugeriría excepto como último recurso ...

Observo que si uso el perfil en lugar de cProfile, funciona tanto interna como externamente, cobrando el tiempo a las llamadas correctas. Sin embargo, esas llamadas son también 5 veces más lentas. Y parece que hay 10 segundos adicionales de sobrecarga constante (que se carga para import profile si se usa internamente, lo que esté en la línea 1 si se usa externamente). Entonces, para saber que la split está usando el 70% de mi tiempo, en lugar de esperar 4 segundos y hacer 2.326 / 3.352, tengo que esperar 27 segundos y hacer 10.93 / (26.34 - 10.01). No es muy divertido ...

Una última cosa: obtengo los mismos resultados con una compilación de desarrollo de CPython 3.4: resultados correctos cuando se usan internamente, todo se carga en la primera línea de código cuando se usa externamente. Pero PyPy 2.2 / 2.7.3 y PyPy3 2.1b1 / 3.2.3 parecen darme resultados correctos con -m cProfile . Esto puede significar que el profile de PyPy se falsifica en la parte superior del profile porque el código de Python puro es lo suficientemente rápido.

De todos modos, si alguien puede averiguar / explicar por qué -m cProfile no está funcionando, sería genial ... pero de lo contrario, esta es una solución perfecta.