A Tornado decorator for timing critical functions
Recently I have been working on a small pet project using the great asynchronous networking library Tornado. This project communicates with various other APIs and systems such as MySQL, Amazon SQS etc. I was keen to just have a rough idea how long my application was spending using these systems. I didn't really want to go to all the effort of either doing some application profiling, or modifying my application to add loads of timing/logging code.
I thought creating a python decorator to do the task would be the easiest/quickest. The code below creates a decorator that will record the amount of time a method takes and print the time to standard stdout.
def log_runtime(method):
def wrap(*a, **k):
arg_spec = inspect.getargspec(method)
classname = ""
if 'self' in arg_spec.args:
classname = a[0].__class__.__name__
start_time = time.time()
retval = method(*a, **k)
finish_time = time.time()
timestr = datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S.%f")
print "%s : %s" % (timestr,
"%s.%s() took %s secs." % (classname,
method.__name__,
finish_time - start_time))
return retval
return wrap
The decorator will take any method/function regardless of its parameters and wrap timing and logging logic around it.
Lets take the following code
class democlass:
def function_that_we_want_to_time:
do_some_operation_of_interest()
print "function_that_we_want_to_time() complete."
We can modify this to use our timing decorator in the following way.
class democlass:
@log_runtime
def function_that_we_want_to_time:
do_some_operation_of_interest()
print "function_that_we_want_to_time() complete."
Then when the function_that_we_want_to_time() method is called a message will be printed on stdout that looks like
2013-06-12 12:50:14:282084 : democlass.function_that_we_want_to_time() took 0.23882317543 secs. function_that_we_want_to_time() complete.
Simples.