Profiling Python Applications
I’ve been working on a project that’s written in Python, it continuously communicates with some external industrial equipment. It will poll the status of this equipment 4 times per second and also sends commands to them when requested to. My job this week was to raise the update rate to 5Hz…. I needed to make sure I had enough time to do this!
I decided before doing anything I should profile the code to find out how much time the main loop needs to run and what methods take the longest time. That way I’d know if the code can support 5Hz and if not what I can do about it.
Once again the Python standard library comes to the rescue, the cProfile module will monitor the execution of your program and generate a report. Below is an example of how to use it.
import cProfile cProfile.run("main()")
from __future__ import division import time class stats(object): def __init__(self): self.msMin = 1000 self.msMax = 0 self.msTime = 0 self.fpsMin = 1000 self.fpsMax = 0 self.fps = 0; self.updates = 0 self.startTime = int((time.time()+0.5)*1000) self.prevTime = int((time.time()+0.5)*1000) def begin(self): """Calling the method signifies the start of a frame """ self.startTime = int((time.time()+0.5)*1000) def end(self): """Calling this method signifies the end of a frame """ now = int((time.time()+0.5)*1000) self.msTime = now-self.startTime self.msMax = max(self.msMax, self.msTime) self.msMin = min(self.msMin, self.msTime) #print "ms: %i (%i - %i)" % (self.msTime, self.msMin, self.msMax) self.updates = self.updates + 1 if now > (self.prevTime + 1000.0): self.fps = round((self.updates*1000.0)/float(now-self.prevTime)) self.fpsMax = max(self.fpsMax, self.fps) self.fpsMin = min(self.fpsMin, self.fps) print "stats: %i fps (%.i fps - %i fps)" % (self.fps, self.fpsMin, self.fpsMax) self.prevTime = now self.updates = 0 return now def update(self): self.startTime = self.end()
Simply add a call to begin() to the start of your loop and a corresponding call to end() at the end of your loop. Now I get a nice counter that tells me how the code is performing. As I work on the code I can see how this affects the main loop performance.