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.__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.