¿Dónde está mi script en Python, pasando el tiempo? ¿Hay “tiempo perdido” en mi rastro cprofile / pstats?

Question

Estoy intentando perfilar un script en Python larga duración. El script hace un análisis espacial de conjunto de datos raster SIG utilizando el gdal módulo . La secuencia de comandos utiliza actualmente tres archivos, el guión principal, que los bucles sobre los píxeles de mapa de bits llamados find_pixel_pairs.py, un simple caché en lrucache.py y algunas clases misceláneos en utils.py. He perfilado el código en un conjunto de datos de tamaño moderado. vuelve pstats:

   p.sort_stats('cumulative').print_stats(20)
   Thu May  6 19:16:50 2010    phes.profile

   355483738 function calls in 11644.421 CPU seconds

   Ordered by: cumulative time
   List reduced from 86 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.008    0.008 11644.421 11644.421 <string>:1(<module>)
        1 11064.926 11064.926 11644.413 11644.413 find_pixel_pairs.py:49(phes)
340135349  544.143    0.000  572.481    0.000 utils.py:173(extent_iterator)
  8831020   18.492    0.000   18.492    0.000 {range}
   231922    3.414    0.000    8.128    0.000 utils.py:152(get_block_in_bands)
   142739    1.303    0.000    4.173    0.000 utils.py:97(search_extent_rect)
   745181    1.936    0.000    2.500    0.000 find_pixel_pairs.py:40(is_no_data)
   285478    1.801    0.000    2.271    0.000 utils.py:98(intify)
   231922    1.198    0.000    2.013    0.000 utils.py:116(block_to_pixel_extent)
   695766    1.990    0.000    1.990    0.000 lrucache.py:42(get)
  1213166    1.265    0.000    1.265    0.000 {min}
  1031737    1.034    0.000    1.034    0.000 {isinstance}
   142740    0.563    0.000    0.909    0.000 utils.py:122(find_block_extent)
   463844    0.611    0.000    0.611    0.000 utils.py:112(block_to_pixel_coord)
   745274    0.565    0.000    0.565    0.000 {method 'append' of 'list' objects}
   285478    0.346    0.000    0.346    0.000 {max}
   285480    0.346    0.000    0.346    0.000 utils.py:109(pixel_coord_to_block_coord)
      324    0.002    0.000    0.188    0.001 utils.py:27(__init__)
      324    0.016    0.000    0.186    0.001 gdal.py:848(ReadAsArray)
        1    0.000    0.000    0.160    0.160 utils.py:50(__init__)

Los dos principales llamadas contiene el bucle principal - todo el analyis. Las llamadas restantes suman menos de 625 de los 11644 segundos. Cuando se gastan los restantes 11.000 segundos? ¿Es todo dentro del bucle principal de find_pixel_pairs.py? Si es así, ¿puedo saber qué líneas de código están tomando la mayor parte del tiempo?

Answer 1

Tienes razón en que la mayor parte del tiempo se gasta en la función phes en la línea 49 de find_pixel_pairs.py. Para obtener más información, lo que necesita para romper phes en más subfunciones, y después de modificación del perfil.

Answer 2

Forget funciones y de medición. uso de esta técnica. Sólo tiene que ejecutar en modo de depuración, y hacer ctrl-C un par de veces. La pila de llamadas le mostrará exactamente qué líneas de código son responsables del tiempo.

Agregado: Por ejemplo, hacer una pausa en 10 veces. Si, como dice EOL, 10400 segundos de cada 11.000 se gastan directamente en phes, a continuación, en aproximadamente el 9 de esas pausas, se detendrá allí mismo . Si, por el contrario, se está gastando una gran parte del tiempo en alguna subrutina llamada desde phes, entonces no sólo se ve donde está en dicha subrutina, pero verá las líneas que llaman, que también son responsables de el tiempo, y así sucesivamente, hasta la pila de llamadas.

No mida. Captura.

Answer 3

El tiempo empleado en el ejecución de código de cada función o método está en la columna de la tottime. El método cumtime es el tiempo de permanencia en tottime + funciones llamadas.

En su perfil, se ve que los 11.000 segundos que están buscando son gastados directamente por la propia función phes. Lo que llama sólo se tarda unos 600 segundos.

Por lo tanto, usted quiere encontrar lo que lleva tiempo en phes, por dividirlo en subfunciones y reperfilado, como sugirió ~ unutbu.

Answer 4

Si usted ha identificado potencial para los cuellos de botella en la función phes / método en el find_pixel_pairs.py, puede utilizar line_profiler para obtener el perfil de ejecución números de rendimiento de línea por línea como estos (copiado de otra pregunta here ):

Timer unit: 1e-06 s

Total time: 9e-06 s
File: <ipython-input-4-dae73707787c>
Function: do_other_stuff at line 4

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     4                                           def do_other_stuff(numbers):
     5         1            9      9.0    100.0      s = sum(numbers)

Total time: 0.000694 s
File: <ipython-input-4-dae73707787c>
Function: do_stuff at line 7

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================
     7                                           def do_stuff(numbers):
     8         1           12     12.0      1.7      do_other_stuff(numbers)
     9         1          208    208.0     30.0      l = [numbers[i]/43 for i in range(len(numbers))]
    10         1          474    474.0     68.3      m = ['hello'+str(numbers[i]) for i in range(len(numbers))]

Con esta información, lo hace no necesidad de romper phes en múltiples funciones parciales, porque se podía ver exactamente qué líneas tienen el mayor tiempo de ejecución.

Desde que usted menciona que la secuencia de comandos se ejecuta siempre, me gustaría recomendar el uso de line_profiler como el número limitado de métodos como sea posible, porque si bien perfilado implica una sobrecarga adicional, línea de perfilado puede añadir más.