Dove si trova il mio script python passare il tempo? C'è “missing time” nella mia traccia Cprofile / pstats?

Question

Sto tentando di profilo di uno script python lunga corsa. Lo script esegue alcune analisi spaziale sul set di dati raster GIS usando l' gdal modulo . Lo script utilizza attualmente tre file, lo script principale che loop nel corso dei pixel raster chiamati find_pixel_pairs.py, una semplice cache in lrucache.py e alcune classi misc in utils.py. Ho profilato il codice su un set di dati di dimensioni moderate. ritorna 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__)

I primi due chiamate contiene il ciclo principale - l'intero analyis. I restanti chiamate sommano a meno di 625 dei 11644 secondi. Dove sono spesi i restanti 11.000 secondi? È tutto all'interno del ciclo principale di find_pixel_pairs.py? Se è così, posso sapere quali linee di codice stanno prendendo la maggior parte del tempo?

Answer 1

Hai ragione che la maggior parte del tempo viene speso nella funzione phes on line 49 del find_pixel_pairs.py. Per saperne di più, è necessario spezzare phes in più parziali, e poi reprofile.

Answer 2

Dimenticate le funzioni e di misurazione. Utilizzare questa tecnica. basta eseguirlo in modalità debug, e fare ctrl-C un paio di volte. Lo stack di chiamate ti mostrerà esattamente quali linee di codice sono responsabili per il tempo.

Aggiunto: Per esempio, mettere in pausa per 10 volte. Se, come dice EOL, 10400 secondi su 11000 vengono spesi direttamente phes, poi su circa 9 di quelle pause, si fermerà proprio lì . Se, d'altra parte, si sta spendendo una grande frazione di tempo in qualche subroutine chiamata da phes, allora si avrà non solo vedere dove si trova in quel subroutine, ma potrete vedere le linee che lo chiamano, che sono anche responsabili il tempo, e così via, lo stack di chiamate.

Non misurare. Cattura.

Answer 3

Il tempo trascorso nell'esecuzione del codice di ciascuna funzione o metodo è nella colonna tottime. Il metodo è cumtime tottime + il tempo trascorso in funzioni chiamate.

Nel vostro profilo, si vede che i 11.000 secondi che sono alla ricerca di sono spesi direttamente dalla funzione phes stesso. Quello che definisce vogliono solo circa 600 secondi.

In questo modo, si vuole trovare ciò che richiede tempo in phes, rompendo in su in parziali e riprofilatura, come ~ unutbu suggerito.

Answer 4

Se avete il potenziale identificato per i colli di bottiglia nella funzione phes / metodo find_pixel_pairs.py, è possibile utilizzare line_profiler per ottenere la linea per linea numeri di spettacolo nel profilo di esecuzione come questi (copiato da un'altra domanda 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 queste informazioni, si fa non necessità di rompere phes up in più parziali, perché si poteva vedere esattamente quali linee hanno il più alto tempo di esecuzione.

Dato che si parla che lo script è in esecuzione lungo, mi consiglia di utilizzare line_profiler come numero limitato di metodi il più possibile, perché mentre profiling aggiunge un ulteriore sovraccarico, linea di profilatura può aggiungere di più.