Wo ist mein Python-Skript viel Zeit? Gibt es „fehlende Zeit“ in meinem Cprofile / pstats Spur?

Question

Ich versuche, eine lange laufenden Python-Skript zu profilieren. Das Skript hat einige räumliche Analyse auf Raster GIS Datensatz unter Verwendung der gdal Modul . Das Skript verwendet derzeit drei Dateien, die Haupt-Skript, das über die Raster Pixel genannt find_pixel_pairs.py Schleifen, einem einfachen Cache in lrucache.py und einige misc Klassen in utils.py. Ich habe den Code auf einem moderaten Größe Dataset profiliert. pstats kehrt:

   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__)

Die beiden Top-Anrufe enthalten die Hauptschleife - den gesamten Analyis. Die übrigen Anrufe Summe auf weniger als 625 der 11.644 Sekunden. Wo sind die restlichen 11.000 Sekunden ausgegeben? Ist es in der Hauptschleife von find_pixel_pairs.py? Wenn ja, kann ich herausfinden, welche Codezeilen nehmen die meiste Zeit?

Answer 1

Sie haben Recht, dass die meiste Zeit in der phes Funktion auf der Leitung 49 von find_pixel_pairs.py ausgegeben wird. Um mehr zu erfahren, müssen Sie phes in mehr Unterfunktionen aufzubrechen, und dann profilieren.

Answer 2

Vergessen Funktionen und Messen. Mit dieser Technik. führen sie es nur im Debug-Modus, und drücken sie Strg-C ein paar mal. Der Call-Stack zeigt Ihnen genau, welche Codezeilen sind für die Zeit verantwortlich.

Hinzugefügt: Zum Beispiel pausiert es 10-mal. Wenn, wie EOL sagt, 10.400 Sekunden aus 11000 direkt in phes ausgegeben werden, dann auf etwa 9 diese Pausen, wird es aufhören genau dort . Wenn auf der anderen Seite wird es einen großen Teil der Zeit in einem gewissen Unterprogramm von phes genannt zu verbringen, dann werden Sie nicht nur sehen, wo es in diesem Unterprogramm ist, aber Sie werden die Linien sehen, dass es nennen, die auch für die verantwortlich sind die Zeit, und so weiter, bis der Call-Stack.

Messen Sie nicht. Capture.

Answer 3

Die Zeit, in der Code-Ausführung jede Funktion oder Methode ist in der tottime Spalte. Die cumtime Methode ist tottime + Zeit in Funktionen ausgegeben genannt.

In Ihren Eintrag, sehen Sie, dass die 11.000 Sekunden, dass Sie suchen, sich direkt von der phes Funktion ausgegeben werden. Was es nennt dauert nur etwa 600 Sekunden.

So wollen Sie finden, was Zeit in phes nimmt, indem es Zerschlagung in Teilfunktionen und Reprofilierung, wie ~ unutbu vorgeschlagen.

Answer 4

Wenn Sie mögliche Engpässe in der phes Funktion / Methode in find_pixel_pairs.py identifiziert haben, können Sie line_profiler verwenden können, wie diese Zeile-für-Zeile Ausführungsprofil Performance-Zahlen zu erhalten (von einer anderen Frage kopiert 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))]

Mit diesen Informationen Sie tun nicht Notwendigkeit phes bricht in mehrere Teilfunktionen, weil Sie genau sehen können, welche Linien die höchste Ausführungszeit haben.

Da Sie erwähnen, dass Ihr Skript lange läuft, würde ich mit line_profiler auf als begrenzte Anzahl von Methoden wie möglich empfehlen, da während Profilierung zusätzliche Overhead hinzufügt, Linienprofilierung mehr hinzufügen können.