Ich habe ein kleines Paket erstellt mit dem man sehr einfach Funktionen profilen kann. Man kann sehr schnell erkennen, wie oft Funktionen durchlaufen werden und wie viel Zeit dafür benötigt wird. Eine feine Sache um seinen Code zu optimieren Verwendet wird der hotshot Profiler.

Als Beispiel möchte ich wissen was in der Funktion buildEpgEntry() meines Plugins vor sich geht. Zunächst muss ich dazu einen Import machen:

from merlin.tools import hotshotit

Außerdem setze ich einen Funktionsdekorator für meine Funktion buildEpgEntry():

@hotshotit
def buildEpgEntry(self, ignoreMe, eventid, sRef, begin, duration, title, short, desc):

Anschliessend starte ich mein Plugin und sorge dafür, daß die gewünschte Funktion natürlich auch mal aufgerufen wird. Dadurch wird eine Datei /tmp/Funktionsname.prof (also /tmp/buildEpgEntry.prof) angelegt.

Zum Schluß gehe ich mit telnet auf meine Box und lasse mir das Ergebnis anzeigen (Aufruf ohne die Dateiendung .prof):

profistats.sh buildEpgEntry

Hier das Ergebnis:

root@bastelbox:~# profistats.sh buildEpgEntry
     	2346 function calls in 0.263 CPU seconds


   Ordered by: internal time, call count


   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
   	34	0.184	0.005	0.263	0.008 EpgCenterList.py:179(buildEpgEntry)
 	1581	0.030	0.000	0.030	0.000 config.py:1567(__getattr__)
   	34	0.027	0.001	0.027	0.001 LoadPixmap.py:5(LoadPixmap)
   	17	0.006	0.000	0.009	0.001 HelperFunctions.py:255(findPicon)
   	34	0.005	0.000	0.013	0.000 HelperFunctions.py:232(getPiconFilename)
  	306	0.003	0.000	0.003	0.000 config.py:65(getValue)
  	221	0.002	0.000	0.002	0.000 config.py:307(getValue)
   	34	0.002	0.000	0.043	0.001 HelperFunctions.py:252(getPicon)
   	17	0.002	0.000	0.002	0.000 Directories.py:181(fileExists)
   	34	0.001	0.000	0.001	0.000 EpgCenterList.py:736(getTimerPixmapsForEntry)
   	34	0.001	0.000	0.001	0.000 HelperFunctions.py:379(updateEntry)
    	0	0.000         	0.000      	profile:0(profiler)

Die Bedeutung der einzelnen Spalten:

Zitat

ncalls
for the number of calls,

tottime
for the total time spent in the given function (and excluding time made in calls to sub-functions),

percall
is the quotient of tottime divided by ncalls

cumtime
is the total time spent in this and all subfunctions (from invocation till exit). This figure is accurate even for recursive functions.

percall
is the quotient of cumtime divided by primitive calls

filename:lineno(function)
provides the respective data of each function

Alles anzeigen

Dieses Paket basiert auf code von Trent Mick und befindet sich im Anhang