::easy profiling::

September 16th, 2010 by hamish download the zooToolBox

We all write slow code at some point. And figuring out why things are running slow isn’t always obvious.

Naturally python is awesome and has the solution to this largely covered. It has a profile module which can help narrow down where slow downs are coming from, but by itself its a bit of a pain to use.  Anyway, I personally figured the way to go was to write a profile decorator.  If you’re not familiar with decorators I highly recommend learning about them – they’re pretty useful.

Anyway I’m not going to go into what decorators are here, but I’ll give you a super quick demo on how to use em.  So lets say you have a slow function thisFunctionIsSlow.

import profileDecorators
@profileDecorators.d_profile
def thisFunctionIsSlow():
   for n in range( 10000000 ):
      n ** 2

If you’re unfamiliar with decorators – the @profileDecorators.d_profile is where the business is happening. This magic line (which can be commented out or simply removed when you’re done profiling) is all you need to add and you get a bunch of useful profiling information which will look something like this:

ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  1    0.115    0.115    0.117    0.117 C:\maya\scripts\profileDecorators.py:60(thisFunctionIsSlow)
  1    0.002    0.002    0.002    0.002 {range}
  1    0.000    0.000    0.117    0.117 C:\maya\scripts\profileDecorators.py:13(run)

So this is a table that breaks down what functions get called, how many times they’re called (ncalls) how long is spent making those calls (tottime) and the time taken per call (percall).  Its super useful for figuring out where the time is being spent.

Anyway next time you’re trying to figure out why something is slow, try out this profile decorator.  The only bad thing about it is that you can’t decorate a function that returns a value – the decorator eats the return value (in general this can be dealt with, but the profile module doesn’t store/return the return value of the function being profiled).

Share

This post is public domain

This entry was posted on Thursday, September 16th, 2010 at 19:54 and is filed under main. You can follow any responses to this entry through the RSS 2.0 feed. You can leave a response, or trackback from your own site.

  • floppyDJ

    Hey Hamish,

    Used this today to determine why populating my UI was being a dog.

    so easy to implement!

    Quite ironic, I implemented a simple timer decorator and was reading up on cProfile and how I would implement that, then remembered this post :)

    Nice.
    BTW the biggest delay in my UI population was checking the perforce status. damn.

  • hamish

    oh yeah the profile is so awesome. has saved me countless hours of tracking down perf issues.

    regarding perforce – are you using the P4File class in filesystem? It is known to be way slower than it should be. I’m not sure why (I’ve not investigated yet), but usually when I have lots of p4 queries to do I try to batch them and use a really simple function to broker the data exchange.

    I found out about a year ago that I’ve done the p4 classes really wrong – the p4 cmd line app has this -G flag which will return encoded python data structures, so I have a function that I pass the queued up requests to and get back a list of dicts.

    It can make a HUGE difference.

  • floppyDJ

    profile = win!

    Yeah I am using P4File from the filesystem.

    I did a test today with the Perforce P4 one, and it was very fast I think because it keeps a connection open to P4..(haven’t looked too deep)

    Is that function in the current filesystem? I’ll investigate tomorrow, kind of want to keep the right click menu’s having perforce functionality.

    Thanks for the heads up!
    Dave

  • hamish

    I still use P4File for UI and a lot of things actually, but when I know a piece of code is likely to perform many operations at once, I’ll batch them up and do it differently…

    I moved away from perforce’s module for various reasons – but I think the big one was that they didn’t have compiled versions for 2.6 when I needed it, and I couldn’t figure out how to compile it myself.

    And they also didn’t support a timeout period either. We had a period where the p4 server would stall for ages (long story) which was really annoying if a tool was trying to query the p4 state of a file, it would hang. So anyway, thats why I wrote the P4File class – to handle the stalls, and make it version agnostic.

  • floppyDJ

    I will experiment with the -G flag and get me some python data back to work on.

    Your tools have saved me hours of fumbling working out or own modules, much appreciated.

    Dave