Einfaches profiling von Python-Code

Dear visitor, welcome to Dreamboard. If this is your first visit here, please read the Help. It explains in detail how this page works. To use all features of this page, you should consider registering. Please use the registration form, to register here or read more information about the registration process. If you are already registered, please login here.

Shaderman

Dreamer

Posts: 74

Sunday, November 6th 2011, 10:03am

Einfaches profiling von Python-Code

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:

	Source code
1	from merlin.tools import hotshotit

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

	Source code
1 2	@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):

	Source code
1	profistats.sh buildEpgEntry

Hier das Ergebnis:

Source code

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:

Quoted

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