Why you should never use ‘print’ in your Maya tools and other optimization thoughts…

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.
import time
import logging
log = logging.getLogger(__name__)

def testDebugCalls(maxTest = 500):
    ifDebug = False
    def logTest():
        _str_funcName = 'logger'
        time_start = time.clock()
        for i,n in enumerate(range(1,maxTest)):
            log.info("log >>> %s"%(pow(n,i)))
        return "%s >> Time >> = %0.3f seconds " % (_str_funcName,(time.clock()-time_start))
    def debugTest():
        _str_funcName = 'debug'
        time_start = time.clock()
        for i,n in enumerate(range(1,maxTest)):
            log.debug("debug >>> %s"%(pow(n,i)))
        return "%s >> Time >> = %0.3f seconds " % (_str_funcName,(time.clock()-time_start))
    def ifDebugTest():
        _str_funcName = 'if debug'
        time_start = time.clock()
        for i,n in enumerate(range(1,maxTest)):
            if log.getEffectiveLevel() == 10:log.debug("debug EFFECTIVELEVEL >>> %s"%(pow(n,i)))
        return "%s >> Time >> = %0.3f seconds " % (_str_funcName,(time.clock()-time_start))
    def printTest():
        _str_funcName = 'print'
        time_start = time.clock()
        for i,n in enumerate(range(1,maxTest)):
            print("print >>> %s"%(pow(n,i)))
        return "%s >> Time >> = %0.3f seconds " % (_str_funcName,(time.clock()-time_start))  
    def calcTest():
        _str_funcName = 'calc'
        time_start = time.clock()
        for i,n in enumerate(range(1,maxTest)):
            x = (pow(n,i))
        return "%s >> Time >> = %0.3f seconds " % (_str_funcName,(time.clock()-time_start))

    time_log = logTest()
    time_debug = debugTest()
    time_ifDebug = ifDebugTest()    
    time_print = printTest()
    time_calc = calcTest()

    for l in [time_log,time_debug,time_ifDebug,time_print,time_calc]:
        print l

Comments are closed.