Verfolgen Sie die Ursache für eine langsame Funktion in Python

Question

In einem großen Projekt stieß ich auf eine Funktion, die ziemlich langsam ist (gesprochen von Sekunden bis Minuten Ausführungszeit). Die Funktion macht viele Dinge und hat einen sehr tiefen Stacktrace. Obwohl nur wenige Klassen an der Ausführung dieser Funktion beteiligt sind, ist es nicht so offensichtlich, woher die lange Laufzeit kommt.

Ich fing an, die Funktion zu debuggen, Anrufe usw. zu verfolgen und fand das trace Paket ziemlich nützlich. Damit konnte ich einige Funktionen identifizieren, die immer wieder Listen bilden würden, die beim Speichern der Listen nach der ersten Ausführung tatsächlich zu einer Beschleunigung von etwa 3x führen.

Aber jetzt kann ich wirklich keine offensichtlichen Teile mehr sehen, wo die Funktion optimiert werden kann, da das Trace-Paket mehrere Megabyte Text produziert und ich nichts erkennen kann, was mir verdächtig erscheint.

Ich dachte über die Timing-Option der Ablaufverfolgung, um mir einen Überblick über die Laufzeit zu geben, um zu sehen, welche Funktionen langsam sein könnten - aber die Menge der Daten ist einfach zu groß, so dass eine Zusammenfassung wäre schön Die Gesamtausführungszeit jedes Aufrufs wird aufgelistet, aber es scheint, dass dies vom Ablaufverfolgungspaket nicht unterstützt wird.

Noch eine Frage ist, auf welcher Ebene möchte ich die Ausführungszeiten bekommen. Es ist eher nicht der Fall, dass eine einzelne Anweisung langsam ist, aber eine ganze Funktion oft aufgerufen wird oder die Daten nicht gespeichert werden. Also was ich irgendwann brauchen würde ist die durchschnittliche Ausführungszeit pro Anweisung multipliziert mit der Anzahl. Der spätere kann vom Trace-Paket generiert werden.

Gibt es irgendwann noch ein anderes Tool außer pdb und Trace, die ich verwenden könnte?

Answer 1

Haben Sie versucht, den Code zu profilieren? Hier ist ein Beispiel, das cProfile verwendet, um zusammengefasste Statistiken über zu sammeln, wie lange verschiedene Funktionen ausgeführt:

import cProfile, pstats, StringIO 
import time 

# simulate a delay 
def delay(ms): 
    startms = int(round(time.time() * 1000)) 
    while (int(round(time.time() * 1000)) - startms <= ms): 
     pass 

def foo1(): 
    delay(100) 

def foo2(): 
    for x in range(10): 
     foo1() 

def foo3(): 
    for x in range(20): 
     foo1() 

def foo4(): 
    foo2() 
    foo3() 

if __name__ == '__main__': 
    pr = cProfile.Profile() 
    pr.enable() # start profiling 

    foo4() 

    pr.disable() # end profiling 
    s = StringIO.StringIO() 
    sortby = 'cumulative' 
    ps = pstats.Stats(pr, stream=s).sort_stats(sortby) 
    ps.print_stats() 
    print s.getvalue() 

Und hier ist der Ausgang:

  4680454 function calls in 3.029 seconds 

    Ordered by: cumulative time 

    ncalls tottime percall cumtime percall filename:lineno(function) 
     1 0.000 0.000 3.029 3.029 C:\Temp\test.py:21(foo4) 
     30 0.000 0.000 3.029 0.101 C:\Temp\test.py:10(foo1) 
     30 2.458 0.082 3.029 0.101 C:\Temp\test.py:5(delay) 
     1 0.000 0.000 2.020 2.020 C:\Temp\test.py:17(foo3) 
     1 0.000 0.000 1.010 1.010 C:\Temp\test.py:13(foo2) 
    2340194 0.308 0.000 0.308 0.000 {round} 
    2340194 0.263 0.000 0.263 0.000 {time.time} 
     2 0.000 0.000 0.000 0.000 {range} 
     1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}