Archive for July, 2016

Thu, Jul 21st, 2016
posted by jjburton 02:07 PM

As I was prepping Morpheus Rig for public dev release I found some pretty awful slowdowns in our code base. As I’m also working on an Intro to Meta course for Rigging Dojo, it seemed like a good time to resolve some of those issues.

So that was most of this week.

Before digging in,  a little foundation. Our code base is a meta data system that relies heavily on red9’s MetaClass and caching in order to function. So when I dug into issues I needed to find if they were on our end or optimizations that could happen in red9 itself.

How does one start to analyze where the slow downs are and fixing them? I’m sure there are more intelligent and efficient ways but being mostly a self taught coder I decided to lean on my junior high science lesson of using the scientific method – namely devising questions and seeking to answer them with simple direct tests. So to start I came up with some questions I wanted to answer.


  • Does scene size have an effect on certain calls?
  • Does cache size have an effect?
  • Are there things that when iterated on increase the speed at which the next exact same call happen?
  • Are there ways to make failed metaclass nodes fail sooner, with fewer errors and clearer ones to boot?


  • Unit tests in our code base made speed checking and function breaking much easier than not having that
  • Simple setup for iteration tests where I could easily change what was being called and then being able to check speed differentials between functions based on a given scene size of objects or iterating new objects every round

Here’s a sample test call (warning – it’s a bit messy):

def speedTest_substantiation(*args, **kws):
    Test for seeing how substantiation speeds are affected
    _d_build = {'network':'network'}    
    class fncWrap(cgmGeneral.cgmFuncCls):
        def __init__(self,*args, **kws):
            super(fncWrap, self).__init__(*args, **kws)
	    self._str_funcName = 'speedTest_substantiation'
            self._b_reportTimes = 1 #..we always want this on so we're gonna set it on
            self._b_autoProgressBar = True
            self._l_ARGS_KWS_DEFAULTS = [{'kw':'targetCount',"default":10,"argType":'int','help':"How many objects to create"},
                                         {'kw':'build',"default":'network',"argType":'string','help':"What kind of base node to build to test"},
            self.__dataBind__(*args, **kws)
            #Now we're gonna register some steps for our function...
            self.l_funcSteps = [{'step':'Validating Args','call':self._validate_},
                                {'step':'Build stuffs','call':self._buildStuff_},

        def _validate_(self):
            #self.int_iterations = int(cgmValid.valueArg(self.d_kws['iterations'],noneValid=False))
            self.int_targetCount = int(cgmValid.valueArg(self.d_kws['targetCount'],noneValid=False))
	    self.str_nodeType = self.d_kws['build']
            #self.l_valueBuffer = [i for i in range(self.int_iterations)]
            #self.log_debug("Debug in _validate_")
            #For each of our test values, we're gonna create a transform and store it
            #self.md_rootToChildren = {}
            self.l_times_1 = []
	    self.l_times_2 = []
	    self.l_times_3 = []
	    self.l_times_4 = []
	    self.l_roots_1  = []
	    self.l_roots_2 = []
	    self.l_roots_3 = []
	    self.l_roots_4 = []
	    self.l_objects = []
	def test1_func(self,string):
	    return r9Meta.MetaClass(string)          
	def test2_func(self,string):
	    #return cgmMeta_optimize.cgmNode2(string)
	    #return cgmMeta.cgmNode(string)
	    #return cgmMeta.validateObjArgOLD(string,'cgmObject',setClass = True)	
	    return cgmMeta.cgmNode(string)	    
	def test22_func(self,string):
	    #return cgmMeta.cgmObject(string)
	def call2_func(self):pass
	def test3_func(self,string):
	    #return string
	    #return string
	    #return cgmMeta.cgmObject(string)
	    #return cgmMeta_optimize.cgmNode2(string)
	    return cgmMeta.validateObjArg(string,'cgmNode',setClass = False)	    	    
	    #return cgmMeta.validateObjArg(string)
        def _buildStuff_(self):
            for i in range(self.int_targetCount):
                self.progressBar_set(status = ("Creating obj %i"%i), progress = i, maxValue = self.int_targetCount)
                #self.l_objects.append(mc.createNode( self.str_nodeType, n = "obj_{0}".format(i) ))
		_jnt = mc.joint(n = "obj_{0}".format(i) )
        def _iterate_(self):
	    self.call2_func = self.test2_func
	    """if self.str_nodeType == 'network':
		self.call2_func = self.test2_func
		self.call2_func = self.test22_func"""
            for i in range(self.int_targetCount):
                self.progressBar_set(status = ("Pass 1: Substantiating Call %i"%i), progress = i, maxValue = self.int_targetCount)		
		t1 = time.clock()	
		t2 = time.clock()
		t1 = time.clock()	
		t2 = time.clock()
		t1 = time.clock()	
		t2 = time.clock()
	def _reportHowMayaIsStupid_(self):
	    _m1_time = sum(self.l_times_1)
	    _m2_time = sum(self.l_times_2)
	    _m3_time = sum(self.l_times_3)
	    for i,t in enumerate(self.l_times_1):
                self.progressBar_set(status = ("Pass 1: Reporting %i"%i), progress = i, maxValue = len(self.l_times_1))				
		_dif1 = t - self.l_times_2[i]
		_dif2 = t - self.l_times_3[i]
		self.log_info("Step {0} | MetaClass: {1}| cgmNode: {2}(d{4}) | validate: {3}(d{5})".format(i,"%0.4f"%t,
	    self.log_info(cgmGeneral._str_headerDiv + " Times " + cgmGeneral._str_headerDiv + cgmGeneral._str_subLine)	
	    self.log_info("Count: {0} | MetaClass: {1} | cgmNode: {2} | validate: {3}".format(self.int_targetCount,
	    self.log_info("Method 1 | Start: {0} | End: {1} | Difference: {2} | Total: {3} ".format("%0.4f"%self.l_times_1[0],
	                                                                                            "%0.4f"%(self.l_times_1[-1] - self.l_times_1[0]),
	    self.log_info("Method 2 | Start: {0} | End: {1} | Difference: {2} | Total: {3} ".format("%0.4f"%self.l_times_2[0],
                                                                                                    "%0.4f"%(self.l_times_2[-1] - self.l_times_2[0]),
	    self.log_info("Method 3 | Start: {0} | End: {1} | Difference: {2} | Total: {3} ".format("%0.4f"%self.l_times_3[0],
	                                                                                            "%0.4f"%(self.l_times_3[-1] - self.l_times_3[0]),
	    self.log_info("Compare 2:1| Dif: {0} | Dif: {1} |                    Total: {2} ".format("%0.4f"%(self.l_times_1[0] - self.l_times_2[0]),
                                                                                                    "%0.4f"%(self.l_times_1[-1] - self.l_times_2[-1]),
                                                                                                    "%0.4f"%(_m1_time - _m2_time)))  
	    self.log_info("Compare 3:1| Dif: {0} | Dif: {1} |                    Total: {2} ".format("%0.4f"%(self.l_times_1[0] - self.l_times_3[0]),
	                                                                                             "%0.4f"%(self.l_times_1[-1] - self.l_times_3[-1]),
	                                                                                             "%0.4f"%(_m1_time - _m3_time)))   	    	    
    return fncWrap(*args, **kws).go()

Here’s the output…

speedTest_substantiation >> Step 998 | MetaClass: 0.0019| cgmNode: 0.0008(d0.0011) | validate: 0.0015(d0.0004)
speedTest_substantiation >> Step 999 | MetaClass: 0.0019| cgmNode: 0.0008(d0.0011) | validate: 0.0013(d0.0006)
speedTest_substantiation >> /// Times ///----------------------------------------------------------------------------------------------------
speedTest_substantiation >> Count: 1000 | MetaClass: 2.0867 | cgmNode: 0.8801 | validate: 1.5791
speedTest_substantiation >> Method 1 | Start: 0.0022 | End: 0.0019 | Difference: -0.0003 | Total: 2.0867 
speedTest_substantiation >> Method 2 | Start: 0.0010 | End: 0.0008 | Difference: -0.0002 | Total: 0.8801 
speedTest_substantiation >> Method 3 | Start: 0.0017 | End: 0.0013 | Difference: -0.0003 | Total: 1.5791 
speedTest_substantiation >> Compare 2:1| Dif: 0.0012 | Dif: 0.0011 |                    Total: 1.2066 
speedTest_substantiation >> Compare 3:1| Dif: 0.0006 | Dif: 0.0006 |                    Total: 0.5076 
speedTest_substantiation >>  [TIME] -- Step: 'Report' >>  5.392 
speedTest_substantiation >> /// Times ///----------------------------------------------------------------------------------------------------
# Warning: cgm.core.cgm_General :  speedTest_substantiation >> /// Total : 10.829 sec ///---------------------------------------------------------------------------------------------------- # 

Issues and Solutions

  • General
    • It doesn’t appear to be the iterating itself that is causing the slowdown but some other process
    • Reloading meta resets the slowdown to base (after the file new/open fix)
  •  cgm
    • cgmNode was much slower than a MetaClass node
      • Short version – I had a list.extend() when I should have had a if a not in list:list.append()
      • Long Version – Tracked down an issue where everytime cgmNode was called ( a lot), it was micrscopically increasing the speed of the next call. On a subclass to r9Meta.MetaClass I was extending the UNMANAGED class list with some attributes on my root subclass’s __init__ doing so was adding duplicate attributes to that list any time my subclass was substantiated after initial reload of Meta. That fact caused some of the subfunctions to add that number of steps everytime they called. So long story short, every time my subclass substantiated after a meta reload it got minisculely slower. However, when that call happens tens/hundreds of thousands of times, it added up.
      • Also was curious if having properties or too many functions would cause a slow down in substantiation speeds and the answer is, not really.
      • I was was also concerned that use of a function class I’d been experimenting with was causing slow down and I didn’t come to a full answer on this one yet.
      • autofill flag – There is a flag in MetaClass for autofilling attrs for auto completion to work. Turns out it’s a pretty big hit. Changed our autofill to off and it’s considerably faster than MetaClass.
        • 1000 joint test – red9.MetaClass(autofilldefault) – 2.0699s | cgmNode – .8944s  | validateObjArg – 1.5777s
        • 1000 joint test – red9.MetaClass(autofill – False) – 1.s | cgmNode – .8944s | validateObjArg – 1.5777s
    • validateObjArg was dog slow
      • Completely rewrote this
      • Decided to go at it a different way and found some nice savings
      • for meta node conversion  — Post rewrite – 1000 node conversion test – red9 – 238.129s | cgm – 8.965s
  • red9
    • Reloading red9 introduced an appended file new/open check everytime. This a growing list of errors in the script editor and increased file new/open times.
      • Code change suggested to red9
    • 3 issues in one – 1) A single meta node that had been deleted generated up to 6 errors on an empty scene. This of course grows the bigger the scene is. and 2)error messages were non specific in nature providing no insight to what errors were happening . 3) a corrupted node can made the cache break when called
      • Proposed two additional MetaClass attrs to store _LastDagPath and _lastUUID – these are displayed when a node fails to know what failed
      • Proposed allowing failed nodes to attempt to auto remove themselves from the cache when they fail
      • Proposed some changes that immediately raise an exception rather than keeping processing to get to a failed node state as quickly as possible
    • convertMClassType gets slower the denser the scene
      • rewrote cgmMeta.valiateObjArg. Will talk to Mark on this one.
    • Hierarchical depth has a direct influence on substantiation speeds
      • Created test where for each iteration a new joint is created and parented to the last so at the end you have a 1000 joint chain
      • Base results- red9.MetaClass – start :.001s | end: .018s | total: 8.837s
      • Oddly enough, if you pass shortNames of the children joints on call instead of the .mNode strings (long name), it cuts the end per time from .018 to .010 for a total of 5.571s
      • Talking to Mark on this one.

Why should you care?

The end result of this pass is that a crazy 5 hour rig build anomaly for Morpheus was parred down to 40 minutes after the cgmNode fixes and 31 minutes after the cgmValidateObjArg rewrite. This is in 2011. Never versions of maya are more efficient and it will get better still as we more through optimizing more.

Note, none my optimizations are in red9’s core yet. Mark is on vacation and most of those fixes wouldn’t help anyone but a coder.