Script Benchmarking with Decorators Example

@PGriffith showed me a python decorator script on another thread, which gave me an idea on how to use it for timing module functions. I’m sure someone else has done this and maybe better, but it has been fun to play with.

The decorator takes two arguments which determine the time units to be returned and how many times the function should be called.

import functools
from java.lang import System

class benchmark(object):
	''' decorator for benchmarking scripts'''
	
	def __init__(self,units,n):
		if units == 'seconds':
			divisor = 100000000.0
		elif units == 'nanos':
			divisor = 1.0
		else:
			units = 'millis'
			divisor = 100000.0
			
		self.n = n
		self.divisor = divisor
		self.fmt = '{:d} calls of {:s}, avg: {:.1f} %s' % units
 
	def __call__(self,fn):
		# returns the decorator itself, which accepts a function and returns another function
		# wraps ensures that the name and docstring of 'fn' is preserved in 'wrapper'
		@functools.wraps(fn)
		def wrapper(*args, **kwargs):
			# the wrapper passes all parameters to the function being decorated
			t1 = System.nanoTime()
			for _ in range(self.n):
				res = fn(*args, **kwargs)
			t2 = System.nanoTime()
			total = (t2-t1)/self.divisor/self.n
			print(self.fmt.format(self.n, fn.__name__, total))
			return res
		return wrapper

@benchmark("millis", 10)
def sayHello(a1, a2, a3, a4):
    print 'sayHello arguments:', a1, a2, a3, a4

sayHello(1,2,3,4)

output

sayHello arguments: 1 2 3 4
sayHello arguments: 1 2 3 4
sayHello arguments: 1 2 3 4
sayHello arguments: 1 2 3 4
sayHello arguments: 1 2 3 4
sayHello arguments: 1 2 3 4
sayHello arguments: 1 2 3 4
sayHello arguments: 1 2 3 4
sayHello arguments: 1 2 3 4
sayHello arguments: 1 2 3 4
10 calls of sayHello, avg: 3.1 millis

4 Likes

FormatUtil has some methods that might be useful for a ‘see how long this one execution took’ style decorator, rather than a statistical benchmark style function.

As a minor style thing:
for _ in range(self.n):
Since you’re only after a number of iterations, in Python 2 you should always prefer xrange, so that you’re not create a (useless) list in memory for no reason.

4 Likes

I wanted to try to write a generic error handling decorator, so I gave it a shot. I probably committed an unforgivable sin somewhere lol.

@pturmel 's later.py has a PythonAsJavaException class if you want to use a logger. I just did a print to test with.

from java.lang import Throwable
import traceback

class errorHandler():
	''' decorator to wrap functions with a generic error handler '''

	def handleError(self, fn, values, trace):
		fnName = fn.__name__
		args =  dict( zip( fn.func_code.co_varnames[:fn.func_code.co_argcount], values['args'] + fn.__defaults__ ) )								
		gateway = system.tag.readBlocking(["[System]Gateway/SystemName"]).value
		exception = 'Call to %s() failed with an exception \n Args: %s \n Kwargs: %s \n %s' % (fnName, args, values['kwargs'], trace)
		print exception
	
	def __call__(self, fn):
		# returns the decorator itself, which accepts a function and returns another function
		# wraps ensures that the name and docstring of 'fn' is preserved in 'wrapper'
		@functools.wraps(fn)
		def wrapper(*args, **kwargs):
			# the wrapper passes all parameters to the function being decorated		
			try:
				return fn(*args, **kwargs)
			except Exception, e:
				self.handleError(fn, locals(), traceback.format_exc()) #(later.PythonAsJavaException(e)
				return None
			except Throwable, t:
				self.handleError(fn, locals(), traceback.format_exc()) #later.PythonAsJavaException(t))
				return None
		return wrapper

Python exception example

@errorHandler()
def exceptionTest(x, y, override = 4, **kwargs):	
	z = x / y
	system.db.runNamedQuery('Unknown', {'z':z})
	
exceptionTest(4,0, test=True)

results

Call to exceptionTest() failed with an exception 
 Args: {'x': 4, 'y': 0, 'override': 4} 
 Kwargs: {'test': True} 
 Traceback (most recent call last):
  File "<module:util>", line 175, in wrapper
  File "<input>", line 3, in exceptionTest
ZeroDivisionError: integer division or modulo by zero

Java throwable example

@errorHandler()
def exceptionTest(x, y, override = 4, **kwargs):	
	z = x / y
	system.db.runNamedQuery('Unknown', {'z':z})
	
exceptionTest(4,1, test=True)

results

Call to exceptionTest() failed with an exception 
 Args: {'x': 4, 'y': 1, 'override': 4} 
 Kwargs: {'test': True} 
 Traceback (most recent call last):
  File "<module:util>", line 175, in wrapper
  File "<input>", line 4, in exceptionTest
Exception: java.lang.Exception: Did not find query Unknown in project resources.
3 Likes

I made something similar to what you are aiming for but its also made for managing database transactions and errors in a standard way by creating a Response object that then I inspect after.

import functools
import timeit
import traceback
from forms2.structs import Response
import java.lang.Throwable

class handleTransaction(object):
	def __init__(self, logger):
		self.logger = logger

	def __call__(self, inner_func):
		"""
		We do 'tx' not in kwargs a few times here.  If a fucntion has tx=None and is decorated with this, we generate the transatction.
		However, sometimes we want to string together multiple transactions into one larger transcation.  So by passing it in directly and checking for
		'tx' not in kwargs, we only close it for a self contained decorated function.  If tx is passed, then the transaction lives on.  However,
		then you must manually close it.
		Look to forsm2.tests.runAllTest for an example of this.		
		"""
		@functools.wraps(inner_func)
		def wrapped_func(*args, **kwargs): 
			start_time = timeit.default_timer()
			# A transaction was not provided, we create one
			if 'tx' not in kwargs:
				transaction_config = forms2.common.TRANSACTION_CONFIG
				tx = system.db.beginNamedQueryTransaction(**transaction_config)
				kwargs['tx'] = tx
				self.logger.info("Starting transaction %s"%(tx))
			self.logger.info("Proceeding using transaction %s"%(kwargs['tx']))
			try:
				result = inner_func(*args, **kwargs)
				response = Response(success=True, result=result, error=None,errorType=None)
			except Exception, e:
				self.logger.error("Python error occured")
				self.logger.error(str(e))
				self.logger.error(traceback.format_exc())
				response = Response(success=False, result=None, error=str(e), errorType='Python')
			except java.lang.Throwable, e:
				self.logger.error("Java Error Occured")
				self.logger.error(str(e.cause))
				self.logger.error(traceback.format_exc())
				response = Response(success=False, result=None, error=str(e.cause), errorType='Java')
			finally:
				if response.success:
					self.logger.info("Committing transaction %s"%(str(kwargs['tx'])))
					system.db.commitTransaction(kwargs['tx'])
				else:
					self.logger.info("Rolling back transaction %s"%(str(kwargs['tx'])))
					system.db.rollbackTransaction(kwargs['tx'])
				self.logger.info("Closing Transaciton %s"%(str(kwargs['tx'])))
				system.db.closeTransaction(kwargs['tx'])
				# At this point we would parse the result object and return an appropraite?  Or return entire result
				elapsed = timeit.default_timer() - start_time
				self.logger.info("Finished transaction in %f seconds"%(elapsed))
				return response
		return wrapped_func

and response

class Response(object):
	def __init__(self, success=False, result=None, error=None, errorType=None):
		self.success = success
		self.result = result
		self.error = error
		self.errorType = errorType
	
	def __str__(self):
		if self.success:
			return "Success: True, Result: %s"%(str(self.result))
		elif self.errorType and self.error:
			return "Error Type %s Error Text: %s"%(self.errorType, self.error)
		else:
			return "Success: False, Result: None, Error Type: None, Error Text: None"

Let's me write my functions that only deal with the actual database actions and let this decorator handle all committing/reverting/closing the transaction. Works pretty well in my experience so far.

3 Likes

No reason to nest your imports. Put them in the outermost level of the script module. Save a little execution time.

3 Likes