Profiling Python Applications

Posted in Software

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()")

The next thing I did is write a simple bit of code that will print to stdout the current update rate of my application every second. It’s pretty much a Python port of the JavaScript library stats.js.

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.