Was ist der Unterschied zwischen Tottime und Cumtime bei der cProfile-Ausgabe?

70

Ich profiliere ein Python-Skript main.pymit cProfile mit dem folgenden Befehl:

python -m cProfile -s tottime main.py

Die Ausgabe, die ich erhalte, ist (nur die obersten Zeilen der Ausgabe kopieren):

10184337 function calls (10181667 primitive calls) in 13.597 seconds

Ordered by: internal time

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    1    4.674    4.674   13.598   13.598 main.py:2(<module>)
 2142    2.964    0.001    4.663    0.002 load_aerdat3.py:61(getPacket)
  459    2.381    0.005    2.381    0.005 {waitKey}
1667989    1.170    0.000    1.170    0.000 {numpy.core.multiarray.array}

...

Wie kann sich die tottime(4.674) von der cumtime(13.598) unterscheiden main.py, da diese Funktion (dh das gesamte Skript) nur einmal aufgerufen wird?

Takahashi
quelle

Antworten:

92

tottimeist die Gesamtzeit, die allein in der Funktion verbracht wird . cumtimeist die Gesamtzeit, die in der Funktion verbracht wurde, plus alle Funktionen, die diese Funktion aufgerufen hat.

Die beiden Werte sind gleich, wenn eine Funktion niemals etwas anderes aufruft. Zum Beispiel {waitKey}scheint nichts anderes aufzurufen:

  459    2.381    0.005    2.381    0.005 {waitKey}

sondern getPacket()ruft andere Funktionen, so dass es die cumtimeSpalte , um die Zeit für die Anrufe beinhaltet:

 2142    2.964    0.001    4.663    0.002 load_aerdat3.py:61(getPacket)

Die main.pyZeile deckt den gesamten Code ab, der außerhalb von Funktionen ausgeführt wird, den globalen Code. Nur die Anweisungen auf dieser Ebene dauerten 4,674 Sekunden. Da diese Anweisungen jedoch andere Funktionen aufriefen, beträgt die kumulative Gesamtzeit des main.pyCodes plus aller durchgeführten Funktionsaufrufe 13,598 Sekunden.

Aus der Dokumentation :

Gesamtzeit
für die Gesamtzeit, die in der angegebenen Funktion verbracht wurde (und ohne die Zeit, die beim Aufrufen von Unterfunktionen benötigt wurde)

[...]

cumtime
ist die kumulierte Zeit, die für diese und alle Unterfunktionen aufgewendet wird (vom Aufruf bis zum Beenden). Diese Zahl ist auch für rekursive Funktionen genau.

Martijn Pieters
quelle
toll, jetzt verstehe ich! Irgendwie habe ich vermisst, dass tottimedie Unterfunktionen nicht enthalten sind. Danke!
Takahashi
Was zählt als Unterfunktion und was nicht? Wenn ich zum Beispiel einen Teil einer Zeichenfolge nehme, zählt dies als Aufruf einer Unterfunktion? Oder zählt es als eingebaute Elementaroperation innerhalb der Hauptfunktion?
John Smith Optional
1
@JohnSmithOptional: Alles, was in Python-Code implementiert ist, kann instrumentiert werden. String Slicing kann nicht instrumentiert werden, da es in nativem Maschinencode implementiert ist, der aus C. kompiliert wurde.
Martijn Pieters
Danke Martijn, jetzt verstehe ich, warum das Profilmodul solche Ergebnisse zurückgibt.
John Smith Optional