¿Dónde está mi script en Python, pasando el tiempo? ¿Hay “tiempo perdido” en mi rastro cprofile / pstats?
-
03-10-2019 - |
Pregunta
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?
Solución
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.
Otros consejos
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.
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.
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.