Où est mon temps passe script python? Y at-il « temps manquant » dans ma trace cprofile / pstats?

Question

J'essaie de profiler un script python à long en cours d'exécution. Le script fait une analyse spatiale sur le jeu de données SIG raster à l'aide du gdal Module . Le script utilise actuellement trois fichiers, le script principal qui passe en boucle sur les pixels de trame appelés find_pixel_pairs.py, un cache simple lrucache.py et certaines classes de Rigolo utils.py. Je profilé le code sur un ensemble de données de taille moyenne. retourne 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__)

Les deux premiers appels contiennent la boucle principale - l'ensemble analyis. Les autres appels totalisent moins de 625 des 11644 secondes. Où sont les 11.000 secondes restantes passé? Est-ce tout dans la boucle principale de find_pixel_pairs.py? Si oui, puis-je savoir quelles lignes de code prennent la plupart du temps?

Answer 1

Vous avez raison que la plupart du temps est consacré à la fonction phes sur la ligne 49 du find_pixel_pairs.py. Pour en savoir plus, vous devez briser phes en plus sous-fonctions, et puis remodelez.

Answer 2

Oublier les fonctions et mesure. utiliser cette technique. il suffit de l'exécuter en mode débogage et faire Ctrl-C quelques fois. La pile d'appel va vous montrer exactement quelles lignes de code sont responsables du temps.

Ajout: Par exemple, mettre en pause 10 fois. Si, comme le dit EOL, 10400 secondes sur onze mille sont dépensés directement dans phes, puis environ 9 de ces pauses, il arrêtera là . Si, d'autre part, il dépense une grande partie du temps dans certains sous-programme appelé à partir phes, alors vous verrez non seulement où il est dans ce sous-programme, mais vous verrez les lignes qui appellent, qui sont également responsables de la le temps, et ainsi de suite, la pile d'appel.

Ne pas mesurer. Capture.

Answer 3

Le temps passé dans le exécution de code de chaque fonction ou méthode se trouve dans la colonne de tottime. La méthode est cumtime tottime + le temps passé dans les fonctions appelées.

Dans votre liste, vous voyez que les 11.000 secondes que vous cherchez sont dépensés directement par la fonction phes lui-même. Ce qu'il appelle prend seulement environ 600 secondes.

Ainsi, vous voulez trouver ce qui prend du temps à phes, en divisant en sous-fonctions et reprofilage, comme ~ unutbu suggéré.

Answer 4

Si vous avez identifié le potentiel pour les goulots d'étranglement dans la fonction phes / méthode find_pixel_pairs.py, vous pouvez utiliser line_profiler pour obtenir l'exécution ligne par ligne les numéros de performance de profil comme celles-ci (copié à partir d'une autre question 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))]

Avec ces informations, vous faites pas nécessité de briser phes en de multiples sous-fonctions, parce que vous pouvez voir précisément quelles lignes ont le plus de temps d'exécution.

Puisque vous mentionnez que votre script est en cours d'exécution à long, je vous recommande d'utiliser line_profiler en tant que nombre limité de méthodes que possible, car si le profilage ajoute une charge supplémentaire, le profilage de ligne peut ajouter plus.