Archive for September, 2013

First off, sorry for the big break in posts here. We’ve just been swamped working on Morpheus and haven’t posted much. This sounded like a good topic.

As we’re getting close to finishing up Morpheus 2, I’ve been trying to do some optimization in the code to make the build processes faster and other things. One of the questions I had was if log.debug was causing speed hits and what other affects prints or log.infos were having on our main code speeds.

What does one do when trying to solve something? Well, we make some hypotheses and tests for those hypotheses. Go, go 8th grade science!

So I wrote a test this morning and the results are rather interesting. I wrote a series of timed functions that do a pow calculation on an enumerated range. I gave the tester a single kw arg of setting the maxTest which sets the range end. I’ll post the tester code below.

The results on a 3000 range test are as follows:

logger >> Time >> = 46.289 seconds

debug >> Time >> = 24.752 seconds

if debug >> Time >> = 0.000 seconds

print >> Time >> = 150.508 seconds

calc >> Time >> = 0.569 seconds

The raw calc is obviously the fastest. What was curious to me was that debugs take a hit even when not printing. What was most crazy was how slow print statements are and concluded that you should pretty much never ever use them in maya tools.

For the purposes of our own debugging, using an if/debug gate on that info seemed like it was going to make the most sense. So with that in mind I tried a way to find the level of the logger. The only call I could initially find was log.getEffectiveLevel(). That seems to be the most intuitive method to get a if/debug check for free. Need to do more research to figure out if a level of 10 – which seems to be debug’s default integer value is a usable check.

On a whim I pulled all the log.debugs from our core code and the time savings was considerable on our unit tests. Blrgh…yet another item for the ever growing to do pile.

In the end these are my initial conclusions:

Never use ‘print’ calls in maya python. Use logger – log.info

Only raw log.debugs in when no calculations have to happen to form that report. I.e – they’ve already been done.

I need to begin working to pull out as many debugs as possible and/or level-gate those calls for speed’s sake.