Simple profiling through decorator functions. (counting and timing of functions decorated with @count and @timeIt that have a SimPEG.utils.Counter)

e.g. output:
‘’’
Counters:
  InexactGaussNewton.doEndIteration       :        6
  InexactGaussNewton.printIter            :        7
  InexactGaussNewton.scaleSearchDirection :        6

Times:                                        mean      sum
  InexactGaussNewton.findSearchDirection  : 1.55e-02, 9.29e-02,    6x
  InexactGaussNewton.minimize             : 1.10e-01, 1.10e-01,    1x
  InexactGaussNewton.modifySearchDirection: 2.89e-04, 1.73e-03,    6x
  InexactGaussNewton.projection           : 3.69e-06, 1.11e-04,   30x
  InexactGaussNewton.stoppingCriteria     : 1.16e-04, 1.51e-03,   13x
  Inversion.dataObj                       : 6.60e-05, 8.58e-04,   13x
  Inversion.dataObj2Deriv                 : 1.03e-04, 6.20e-03,   60x
  Inversion.dataObjDeriv                  : 5.06e-05, 3.54e-04,    7x
  Inversion.evalFunction                  : 7.75e-04, 1.01e-02,   13x
  Inversion.run                           : 1.10e-01, 1.10e-01,    1x
  Regularization.modelObj                 : 3.56e-04, 4.63e-03,   13x
  Regularization.modelObj2Deriv           : 1.29e-03, 7.76e-02,   60x
  Regularization.modelObjDeriv            : 5.01e-04, 3.51e-03,    7x
‘’’
This commit is contained in:
Rowan Cockett
2013-11-20 21:59:53 -08:00
parent 514b709270
commit 2782a6fcfb
5 changed files with 160 additions and 15 deletions
+111
View File
@@ -60,3 +60,114 @@ def printStoppers(obj, stoppers, pad='', stop='STOP!', done='DONE!'):
r = stopper['right'](obj)
print pad + stopper['str'] % (l<=r,l,r)
print pad + "%s%s%s" % ('-'*25,done,'-'*25)
import time
import numpy as np
class Counter(object):
"""
Counter allows anything that calls it to record iterations and
timings in a simple way.
Also has plotting functions that allow quick recalls of data.
If you want to use this, import *count* or *timeIt* and use them as decorators on class methods.
.. ::
class MyClass(object):
def __init__(self, url):
self.counter = Counter()
@count
def MyMethod(self):
pass
@timeIt
def MySecondMethod(self):
pass
c = MyClass('blah')
for i in range(100): c.MyMethod()
for i in range(300): c.MySecondMethod()
c.counter.summary()
"""
def __init__(self):
self._countList = {}
self._timeList = {}
def count(self, prop):
"""
Increases the count of the property.
"""
assert type(prop) is str, 'The property must be a string.'
if prop not in self._countList:
self._countList[prop] = 0
self._countList[prop] += 1
def countTic(self, prop):
"""
Times a property call, this is the init call.
"""
assert type(prop) is str, 'The property must be a string.'
if prop not in self._timeList:
self._timeList[prop] = []
self._timeList[prop].append(-time.time())
def countToc(self, prop):
"""
Times a property call, this is the end call.
"""
assert type(prop) is str, 'The property must be a string.'
assert prop in self._timeList, 'The property must already be in the dictionary.'
self._timeList[prop][-1] += time.time()
def summary(self):
"""
Provides a text summary of the current counters and timers.
"""
print 'Counters:'
for prop in sorted(self._countList):
print " {0:<40}: {1:8d}".format(prop,self._countList[prop])
print '\nTimes:'+' '*40+'mean sum'
for prop in sorted(self._timeList):
l = len(self._timeList[prop])
a = np.array(self._timeList[prop])
print " {0:<40}: {1:4.2e}, {2:4.2e}, {3:4d}x".format(prop,a.mean(),a.sum(),l)
def count(f):
def wrapper(self,*args,**kwargs):
counter = getattr(self,'counter',None)
if type(counter) is Counter: counter.count(self.__class__.__name__+'.'+f.__name__)
out = f(self,*args,**kwargs)
return out
return wrapper
def timeIt(f):
def wrapper(self,*args,**kwargs):
counter = getattr(self,'counter',None)
if type(counter) is Counter: counter.countTic(self.__class__.__name__+'.'+f.__name__)
out = f(self,*args,**kwargs)
if type(counter) is Counter: counter.countToc(self.__class__.__name__+'.'+f.__name__)
return out
return wrapper
if __name__ == '__main__':
class MyClass(object):
def __init__(self, url):
self.counter = Counter()
@count
def MyMethod(self):
pass
@timeIt
def MySecondMethod(self):
pass
c = MyClass('blah')
for i in range(100): c.MyMethod()
for i in range(300): c.MySecondMethod()
c.counter.summary()